From 730c939b501a83c2cf7a4cd6e30eb94c13ea7e5f Mon Sep 17 00:00:00 2001 From: Aditya C S Date: Thu, 13 Feb 2020 10:03:52 +0530 Subject: [PATCH] Fix panic in debug message --- pkg/logentry/stages/labels.go | 2 +- pkg/logentry/stages/labels_test.go | 30 +++++++++++++++++++ pkg/logentry/stages/metrics.go | 6 ++-- pkg/logentry/stages/metrics_test.go | 30 +++++++++++++++++++ pkg/logentry/stages/output.go | 2 +- pkg/logentry/stages/output_test.go | 32 ++++++++++++++++++++ pkg/logentry/stages/regex.go | 2 +- pkg/logentry/stages/regex_test.go | 40 +++++++++++++++++++++++++ pkg/logentry/stages/template.go | 2 +- pkg/logentry/stages/template_test.go | 32 ++++++++++++++++++++ pkg/logentry/stages/tenant.go | 2 +- pkg/logentry/stages/tenant_test.go | 42 +++++++++++++++++++++++++++ pkg/logentry/stages/timestamp.go | 2 +- pkg/logentry/stages/timestamp_test.go | 30 +++++++++++++++++++ 14 files changed, 245 insertions(+), 9 deletions(-) diff --git a/pkg/logentry/stages/labels.go b/pkg/logentry/stages/labels.go index f7dd828fbc55..a2d364ff81a2 100644 --- a/pkg/logentry/stages/labels.go +++ b/pkg/logentry/stages/labels.go @@ -68,7 +68,7 @@ func (l *labelStage) Process(labels model.LabelSet, extracted map[string]interfa s, err := getString(lValue) if err != nil { if Debug { - level.Debug(l.logger).Log("msg", "failed to convert extracted label value to string", "err", err, "type", reflect.TypeOf(lValue).String()) + level.Debug(l.logger).Log("msg", "failed to convert extracted label value to string", "err", err, "type", reflect.TypeOf(lValue)) } continue } diff --git a/pkg/logentry/stages/labels_test.go b/pkg/logentry/stages/labels_test.go index 88781331c935..0191a4b79977 100644 --- a/pkg/logentry/stages/labels_test.go +++ b/pkg/logentry/stages/labels_test.go @@ -1,12 +1,15 @@ package stages import ( + "bytes" "errors" "fmt" + "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" "github.com/stretchr/testify/assert" @@ -31,6 +34,13 @@ var testLabelsLogLine = ` "level" : "WARN" } ` +var testLabelsLogLineWithMissingKey = ` +{ + "time":"2012-11-01T22:08:41+00:00", + "app":"loki", + "component": ["parser","type"] +} +` func TestLabelsPipeline_Labels(t *testing.T) { pl, err := NewPipeline(util.Logger, loadConfig(testLabelsYaml), nil, prometheus.DefaultRegisterer) @@ -49,6 +59,26 @@ func TestLabelsPipeline_Labels(t *testing.T) { assert.Equal(t, expectedLbls, lbls) } +func TestLabelsPipelineWithMissingKey_Labels(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testLabelsYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testLabelsLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug msg=\"failed to convert extracted label value to string\" err=\"Can't convert to string\" type=null" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + var ( lv1 = "lv1" lv2c = "l2" diff --git a/pkg/logentry/stages/metrics.go b/pkg/logentry/stages/metrics.go index 9eb9091bdbd6..577d8c101659 100644 --- a/pkg/logentry/stages/metrics.go +++ b/pkg/logentry/stages/metrics.go @@ -179,7 +179,7 @@ func (m *metricStage) recordCounter(name string, counter *metric.Counters, label if Debug { level.Debug(m.logger).Log("msg", "failed to convert extracted value to string, "+ "can't perform value comparison", "metric", name, "err", - fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v).String())) + fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v))) } return } @@ -212,7 +212,7 @@ func (m *metricStage) recordGauge(name string, gauge *metric.Gauges, labels mode if Debug { level.Debug(m.logger).Log("msg", "failed to convert extracted value to string, "+ "can't perform value comparison", "metric", name, "err", - fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v).String())) + fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v))) } return } @@ -265,7 +265,7 @@ func (m *metricStage) recordHistogram(name string, histogram *metric.Histograms, if Debug { level.Debug(m.logger).Log("msg", "failed to convert extracted value to string, "+ "can't perform value comparison", "metric", name, "err", - fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v).String())) + fmt.Sprintf("can't convert %v to string", reflect.TypeOf(v))) } return } diff --git a/pkg/logentry/stages/metrics_test.go b/pkg/logentry/stages/metrics_test.go index 9ea7eccafbae..db5ee46ed2d6 100644 --- a/pkg/logentry/stages/metrics_test.go +++ b/pkg/logentry/stages/metrics_test.go @@ -1,11 +1,13 @@ package stages import ( + "bytes" "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/pkg/errors" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/testutil" @@ -69,6 +71,14 @@ var testMetricLogLine2 = ` "level" : "WARN" } ` +var testMetricLogLineWithMissingKey = ` +{ + "time":"2012-11-01T22:08:41+00:00", + "payload": 20, + "component": ["parser","type"], + "level" : "WARN" +} +` const expectedMetrics = `# HELP my_promtail_custom_loki_count uhhhhhhh # TYPE my_promtail_custom_loki_count counter @@ -109,6 +119,26 @@ func TestMetricsPipeline(t *testing.T) { } } +func TestPipelineWithMissingKey_Metrics(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testMetricYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testMetricLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug msg=\"failed to convert extracted value to string, can't perform value comparison\" metric=bloki_count err=\"can't convert to string\"" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + var metricTestInvalidIdle = "10f" func Test(t *testing.T) { diff --git a/pkg/logentry/stages/output.go b/pkg/logentry/stages/output.go index d7bb9259106f..2201f50241a4 100644 --- a/pkg/logentry/stages/output.go +++ b/pkg/logentry/stages/output.go @@ -65,7 +65,7 @@ func (o *outputStage) Process(labels model.LabelSet, extracted map[string]interf s, err := getString(v) if err != nil { if Debug { - level.Debug(o.logger).Log("msg", "extracted output could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + level.Debug(o.logger).Log("msg", "extracted output could not be converted to a string", "err", err, "type", reflect.TypeOf(v)) } return } diff --git a/pkg/logentry/stages/output_test.go b/pkg/logentry/stages/output_test.go index 8429dc7e18d7..351eed90b3fb 100644 --- a/pkg/logentry/stages/output_test.go +++ b/pkg/logentry/stages/output_test.go @@ -1,10 +1,13 @@ package stages import ( + "bytes" + "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/pkg/errors" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" @@ -30,6 +33,15 @@ var testOutputLogLine = ` "message" : "this is a log line" } ` +var testOutputLogLineWithMissingKey = ` +{ + "time":"2012-11-01T22:08:41+00:00", + "app":"loki", + "component": ["parser","type"], + "level" : "WARN", + "nested" : {"child":"value"} +} +` func TestPipeline_Output(t *testing.T) { pl, err := NewPipeline(util.Logger, loadConfig(testOutputYaml), nil, prometheus.DefaultRegisterer) @@ -44,6 +56,26 @@ func TestPipeline_Output(t *testing.T) { assert.Equal(t, "this is a log line", entry) } +func TestPipelineWithMissingKey_Output(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testOutputYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testOutputLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug msg=\"extracted output could not be converted to a string\" err=\"Can't convert to string\" type=null" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + func TestOutputValidation(t *testing.T) { tests := map[string]struct { config *OutputConfig diff --git a/pkg/logentry/stages/regex.go b/pkg/logentry/stages/regex.go index 05aa5f440648..c53a4ade8507 100644 --- a/pkg/logentry/stages/regex.go +++ b/pkg/logentry/stages/regex.go @@ -99,7 +99,7 @@ func (r *regexStage) Process(labels model.LabelSet, extracted map[string]interfa value, err := getString(extracted[*r.cfg.Source]) if err != nil { if Debug { - level.Debug(r.logger).Log("msg", "failed to convert source value to string", "source", *r.cfg.Source, "err", err, "type", reflect.TypeOf(extracted[*r.cfg.Source]).String()) + level.Debug(r.logger).Log("msg", "failed to convert source value to string", "source", *r.cfg.Source, "err", err, "type", reflect.TypeOf(extracted[*r.cfg.Source])) } return } diff --git a/pkg/logentry/stages/regex_test.go b/pkg/logentry/stages/regex_test.go index 49b65fdb1a40..70f8c028ef2c 100644 --- a/pkg/logentry/stages/regex_test.go +++ b/pkg/logentry/stages/regex_test.go @@ -1,11 +1,14 @@ package stages import ( + "bytes" "reflect" + "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/pkg/errors" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" @@ -27,6 +30,23 @@ pipeline_stages: expression: "^HTTP\\/(?P[0-9\\.]+)$" source: "protocol" ` +var testRegexYamlSourceWithMissingKey = ` +pipeline_stages: +- json: + expressions: + time: +- regex: + expression: "^(?P\\d+)" + source: "time" +` + +var testRegexLogLineWithMissingKey = ` +{ + "app":"loki", + "component": ["parser","type"], + "level": "WARN" +} +` var testRegexLogLine = `11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"` @@ -96,6 +116,26 @@ func TestPipeline_Regex(t *testing.T) { } } +func TestPipelineWithMissingKey_Regex(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testRegexYamlSourceWithMissingKey), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testRegexLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug component=stage type=regex msg=\"failed to convert source value to string\" source=time err=\"Can't convert to string\" type=null" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + var regexCfg = `regex: expression: "regexexpression"` diff --git a/pkg/logentry/stages/template.go b/pkg/logentry/stages/template.go index af6cf978df8f..fd5f136693f5 100644 --- a/pkg/logentry/stages/template.go +++ b/pkg/logentry/stages/template.go @@ -88,7 +88,7 @@ func (o *templateStage) Process(labels model.LabelSet, extracted map[string]inte s, err := getString(v) if err != nil { if Debug { - level.Debug(o.logger).Log("msg", "extracted template could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + level.Debug(o.logger).Log("msg", "extracted template could not be converted to a string", "err", err, "type", reflect.TypeOf(v)) } return } diff --git a/pkg/logentry/stages/template_test.go b/pkg/logentry/stages/template_test.go index 8360ad20b7ea..6dd4b9a60939 100644 --- a/pkg/logentry/stages/template_test.go +++ b/pkg/logentry/stages/template_test.go @@ -1,11 +1,14 @@ package stages import ( + "bytes" "errors" + "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" "github.com/stretchr/testify/assert" @@ -42,6 +45,15 @@ var testTemplateLogLine = ` "message" : "this is a log line" } ` +var testTemplateLogLineWithMissingKey = ` +{ + "time":"2012-11-01T22:08:41+00:00", + "component": ["parser","type"], + "level" : "WARN", + "nested" : {"child":"value"}, + "message" : "this is a log line" +} +` func TestPipeline_Template(t *testing.T) { pl, err := NewPipeline(util.Logger, loadConfig(testTemplateYaml), nil, prometheus.DefaultRegisterer) @@ -61,6 +73,26 @@ func TestPipeline_Template(t *testing.T) { assert.Equal(t, expectedLbls, lbls) } +func TestPipelineWithMissingKey_Temaplate(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testTemplateYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testTemplateLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug msg=\"extracted template could not be converted to a string\" err=\"Can't convert to string\" type=null" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + func TestTemplateValidation(t *testing.T) { tests := map[string]struct { config *TemplateConfig diff --git a/pkg/logentry/stages/tenant.go b/pkg/logentry/stages/tenant.go index 24c05807c4ac..2fdf41a64c9e 100644 --- a/pkg/logentry/stages/tenant.go +++ b/pkg/logentry/stages/tenant.go @@ -97,7 +97,7 @@ func (s *tenantStage) getTenantFromSourceField(extracted map[string]interface{}) tenantID, err := getString(value) if err != nil { if Debug { - level.Debug(s.logger).Log("msg", "failed to convert value to string", "err", err, "type", reflect.TypeOf(value).String()) + level.Debug(s.logger).Log("msg", "failed to convert value to string", "err", err, "type", reflect.TypeOf(value)) } return "" } diff --git a/pkg/logentry/stages/tenant_test.go b/pkg/logentry/stages/tenant_test.go index 60feaece70df..b07b0ff26ef5 100644 --- a/pkg/logentry/stages/tenant_test.go +++ b/pkg/logentry/stages/tenant_test.go @@ -1,17 +1,59 @@ package stages import ( + "bytes" + "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" "github.com/grafana/loki/pkg/promtail/client" lokiutil "github.com/grafana/loki/pkg/util" + "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) +var testTenantYaml = ` +pipeline_stages: +- json: + expressions: + customer_id: +- tenant: + source: customer_id +` + +var testTenantLogLineWithMissingKey = ` +{ + "time":"2012-11-01T22:08:41+00:00", + "app":"loki", + "component": ["parser","type"], + "level" : "WARN" +} +` + +func TestPipelineWithMissingKey_Tenant(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testTenantYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testTenantLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := "level=debug msg=\"failed to convert value to string\" err=\"Can't convert to string\" type=null" + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + func TestTenantStage_Validation(t *testing.T) { t.Parallel() diff --git a/pkg/logentry/stages/timestamp.go b/pkg/logentry/stages/timestamp.go index e77b82a7aa41..0c652224cc3c 100644 --- a/pkg/logentry/stages/timestamp.go +++ b/pkg/logentry/stages/timestamp.go @@ -165,7 +165,7 @@ func (ts *timestampStage) parseTimestampFromSource(extracted map[string]interfac s, err := getString(v) if err != nil { if Debug { - level.Debug(ts.logger).Log("msg", ErrTimestampConversionFailed, "err", err, "type", reflect.TypeOf(v).String()) + level.Debug(ts.logger).Log("msg", ErrTimestampConversionFailed, "err", err, "type", reflect.TypeOf(v)) } return nil, errors.New(ErrTimestampConversionFailed) diff --git a/pkg/logentry/stages/timestamp_test.go b/pkg/logentry/stages/timestamp_test.go index cc30d5206227..c58fd4b9067d 100644 --- a/pkg/logentry/stages/timestamp_test.go +++ b/pkg/logentry/stages/timestamp_test.go @@ -1,12 +1,14 @@ package stages import ( + "bytes" "fmt" "strings" "testing" "time" "github.com/cortexproject/cortex/pkg/util" + "github.com/go-kit/kit/log" lokiutil "github.com/grafana/loki/pkg/util" "github.com/pkg/errors" "github.com/prometheus/client_golang/prometheus" @@ -34,6 +36,14 @@ var testTimestampLogLine = ` } ` +var testTimestampLogLineWithMissingKey = ` +{ + "app":"loki", + "component": ["parser","type"], + "level" : "WARN" +} +` + func TestTimestampPipeline(t *testing.T) { pl, err := NewPipeline(util.Logger, loadConfig(testTimestampYaml), nil, prometheus.DefaultRegisterer) if err != nil { @@ -53,6 +63,26 @@ var ( validLocation, _ = time.LoadLocation(validLocationString) ) +func TestPipelineWithMissingKey_Timestamp(t *testing.T) { + var buf bytes.Buffer + w := log.NewSyncWriter(&buf) + logger := log.NewLogfmtLogger(w) + pl, err := NewPipeline(logger, loadConfig(testTimestampYaml), nil, prometheus.DefaultRegisterer) + if err != nil { + t.Fatal(err) + } + lbls := model.LabelSet{} + Debug = true + ts := time.Now() + entry := testTimestampLogLineWithMissingKey + extracted := map[string]interface{}{} + pl.Process(lbls, extracted, &ts, &entry) + expectedLog := fmt.Sprintf("level=debug msg=\"%s\" err=\"Can't convert to string\" type=null", ErrTimestampConversionFailed) + if !(strings.Contains(buf.String(), expectedLog)) { + t.Errorf("\nexpected: %s\n+actual: %s", expectedLog, buf.String()) + } +} + func TestTimestampValidation(t *testing.T) { tests := map[string]struct { config *TimestampConfig