Fix panic in debug message (#1687)

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
 			}

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 <nil> 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"

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
 		}

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 <nil> 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) {

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
 		}

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 <nil> 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

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
 		}

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<protocol_version>[0-9\\.]+)$"
     source:     "protocol"
 `
+var testRegexYamlSourceWithMissingKey = `
+pipeline_stages:
+- json:
+    expressions:
+      time:
+- regex:
+    expression: "^(?P<year>\\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 <nil> 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"`
 

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
 		}

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 <nil> 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

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 ""
 	}