diff --git a/cmd/promtail/main.go b/cmd/promtail/main.go index fac17045e319..d37278c24fb9 100644 --- a/cmd/promtail/main.go +++ b/cmd/promtail/main.go @@ -13,6 +13,7 @@ import ( "github.com/weaveworks/common/logging" "github.com/grafana/loki/pkg/helpers" + "github.com/grafana/loki/pkg/logentry/stages" "github.com/grafana/loki/pkg/promtail" "github.com/grafana/loki/pkg/promtail/config" ) @@ -46,6 +47,12 @@ func main() { } util.InitLogger(&config.ServerConfig.Config) + // Set the global debug variable in the stages package which is used to conditionally log + // debug messages which otherwise cause huge allocations processing log lines for log messages never printed + if config.ServerConfig.Config.LogLevel.String() == "debug" { + stages.Debug = true + } + p, err := promtail.New(config) if err != nil { level.Error(util.Logger).Log("msg", "error creating promtail", "error", err) diff --git a/pkg/logentry/stages/json.go b/pkg/logentry/stages/json.go index c0aeedccd453..c57abc57a9e9 100644 --- a/pkg/logentry/stages/json.go +++ b/pkg/logentry/stages/json.go @@ -101,13 +101,17 @@ func (j *jsonStage) Process(labels model.LabelSet, extracted map[string]interfac if j.cfg.Source != nil { if _, ok := extracted[*j.cfg.Source]; !ok { - level.Debug(j.logger).Log("msg", "source does not exist in the set of extracted values", "source", *j.cfg.Source) + if Debug { + level.Debug(j.logger).Log("msg", "source does not exist in the set of extracted values", "source", *j.cfg.Source) + } return } value, err := getString(extracted[*j.cfg.Source]) if err != nil { - level.Debug(j.logger).Log("msg", "failed to convert source value to string", "source", *j.cfg.Source, "err", err, "type", reflect.TypeOf(extracted[*j.cfg.Source]).String()) + if Debug { + level.Debug(j.logger).Log("msg", "failed to convert source value to string", "source", *j.cfg.Source, "err", err, "type", reflect.TypeOf(extracted[*j.cfg.Source]).String()) + } return } @@ -115,21 +119,27 @@ func (j *jsonStage) Process(labels model.LabelSet, extracted map[string]interfac } if input == nil { - level.Debug(j.logger).Log("msg", "cannot parse a nil entry") + if Debug { + level.Debug(j.logger).Log("msg", "cannot parse a nil entry") + } return } var data map[string]interface{} if err := json.Unmarshal([]byte(*input), &data); err != nil { - level.Debug(j.logger).Log("msg", "failed to unmarshal log line", "err", err) + if Debug { + level.Debug(j.logger).Log("msg", "failed to unmarshal log line", "err", err) + } return } for n, e := range j.expressions { r, err := e.Search(data) if err != nil { - level.Debug(j.logger).Log("msg", "failed to search JMES expression", "err", err) + if Debug { + level.Debug(j.logger).Log("msg", "failed to search JMES expression", "err", err) + } continue } @@ -145,7 +155,9 @@ func (j *jsonStage) Process(labels model.LabelSet, extracted map[string]interfac // If the value wasn't a string or a number, marshal it back to json jm, err := json.Marshal(r) if err != nil { - level.Debug(j.logger).Log("msg", "failed to marshal complex type back to string", "err", err) + if Debug { + level.Debug(j.logger).Log("msg", "failed to marshal complex type back to string", "err", err) + } continue } extracted[n] = string(jm) diff --git a/pkg/logentry/stages/labels.go b/pkg/logentry/stages/labels.go index 98f18395f649..a556cafc4dfb 100644 --- a/pkg/logentry/stages/labels.go +++ b/pkg/logentry/stages/labels.go @@ -68,12 +68,16 @@ func (l *labelStage) Process(labels model.LabelSet, extracted map[string]interfa lValue := extracted[*lSrc] s, err := getString(lValue) if err != nil { - level.Debug(l.logger).Log("msg", "failed to convert extracted label value to string", "err", err, "type", reflect.TypeOf(lValue).String()) + if Debug { + level.Debug(l.logger).Log("msg", "failed to convert extracted label value to string", "err", err, "type", reflect.TypeOf(lValue).String()) + } continue } labelValue := model.LabelValue(s) if !labelValue.IsValid() { - level.Debug(l.logger).Log("msg", "invalid label value parsed", "value", labelValue) + if Debug { + level.Debug(l.logger).Log("msg", "invalid label value parsed", "value", labelValue) + } continue } labels[model.LabelName(lName)] = labelValue diff --git a/pkg/logentry/stages/metrics.go b/pkg/logentry/stages/metrics.go index b839afd32516..d831083c0726 100644 --- a/pkg/logentry/stages/metrics.go +++ b/pkg/logentry/stages/metrics.go @@ -141,9 +141,11 @@ func (m *metricStage) recordCounter(name string, counter *metric.Counters, label if counter.Cfg.Value != nil { stringVal, err := getString(v) if err != nil { - 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())) + 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())) + } return } if *counter.Cfg.Value != stringVal { @@ -157,7 +159,9 @@ func (m *metricStage) recordCounter(name string, counter *metric.Counters, label case metric.CounterAdd: f, err := getFloat(v) if err != nil || f < 0 { - level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + if Debug { + level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + } return } counter.With(labels).Add(f) @@ -170,9 +174,11 @@ func (m *metricStage) recordGauge(name string, gauge *metric.Gauges, labels mode if gauge.Cfg.Value != nil { stringVal, err := getString(v) if err != nil { - 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())) + 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())) + } return } if *gauge.Cfg.Value != stringVal { @@ -184,7 +190,9 @@ func (m *metricStage) recordGauge(name string, gauge *metric.Gauges, labels mode case metric.GaugeSet: f, err := getFloat(v) if err != nil || f < 0 { - level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + if Debug { + level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + } return } gauge.With(labels).Set(f) @@ -195,14 +203,18 @@ func (m *metricStage) recordGauge(name string, gauge *metric.Gauges, labels mode case metric.GaugeAdd: f, err := getFloat(v) if err != nil || f < 0 { - level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + if Debug { + level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + } return } gauge.With(labels).Add(f) case metric.GaugeSub: f, err := getFloat(v) if err != nil || f < 0 { - level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + if Debug { + level.Debug(m.logger).Log("msg", "failed to convert extracted value to positive float", "metric", name, "err", err) + } return } gauge.With(labels).Sub(f) @@ -215,9 +227,11 @@ func (m *metricStage) recordHistogram(name string, histogram *metric.Histograms, if histogram.Cfg.Value != nil { stringVal, err := getString(v) if err != nil { - 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())) + 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())) + } return } if *histogram.Cfg.Value != stringVal { @@ -226,7 +240,9 @@ func (m *metricStage) recordHistogram(name string, histogram *metric.Histograms, } f, err := getFloat(v) if err != nil { - level.Debug(m.logger).Log("msg", "failed to convert extracted value to float", "metric", name, "err", err) + if Debug { + level.Debug(m.logger).Log("msg", "failed to convert extracted value to float", "metric", name, "err", err) + } return } histogram.With(labels).Observe(f) diff --git a/pkg/logentry/stages/output.go b/pkg/logentry/stages/output.go index 76f0c6b05323..d7bb9259106f 100644 --- a/pkg/logentry/stages/output.go +++ b/pkg/logentry/stages/output.go @@ -64,12 +64,16 @@ func (o *outputStage) Process(labels model.LabelSet, extracted map[string]interf if v, ok := extracted[o.cfgs.Source]; ok { s, err := getString(v) if err != nil { - level.Debug(o.logger).Log("msg", "extracted output could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + if Debug { + level.Debug(o.logger).Log("msg", "extracted output could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + } return } *entry = s } else { - level.Debug(o.logger).Log("msg", "extracted data did not contain output source") + if Debug { + level.Debug(o.logger).Log("msg", "extracted data did not contain output source") + } } } diff --git a/pkg/logentry/stages/pipeline.go b/pkg/logentry/stages/pipeline.go index da891535ebb1..608bdb3c7fd1 100644 --- a/pkg/logentry/stages/pipeline.go +++ b/pkg/logentry/stages/pipeline.go @@ -78,11 +78,15 @@ func NewPipeline(logger log.Logger, stgs PipelineStages, jobName *string, regist func (p *Pipeline) Process(labels model.LabelSet, extracted map[string]interface{}, ts *time.Time, entry *string) { start := time.Now() for i, stage := range p.stages { - level.Debug(p.logger).Log("msg", "processing pipeline", "stage", i, "name", stage.Name(), "labels", labels, "time", ts, "entry", entry) + if Debug { + level.Debug(p.logger).Log("msg", "processing pipeline", "stage", i, "name", stage.Name(), "labels", labels, "time", ts, "entry", entry) + } stage.Process(labels, extracted, ts, entry) } dur := time.Since(start).Seconds() - level.Debug(p.logger).Log("msg", "finished processing log line", "labels", labels, "time", ts, "entry", entry, "duration_s", dur) + if Debug { + level.Debug(p.logger).Log("msg", "finished processing log line", "labels", labels, "time", ts, "entry", entry, "duration_s", dur) + } if p.jobName != nil { p.plDuration.WithLabelValues(*p.jobName).Observe(dur) } diff --git a/pkg/logentry/stages/regex.go b/pkg/logentry/stages/regex.go index fd6e7134e196..6b9b0dfc8c44 100644 --- a/pkg/logentry/stages/regex.go +++ b/pkg/logentry/stages/regex.go @@ -90,13 +90,17 @@ func (r *regexStage) Process(labels model.LabelSet, extracted map[string]interfa if r.cfg.Source != nil { if _, ok := extracted[*r.cfg.Source]; !ok { - level.Debug(r.logger).Log("msg", "source does not exist in the set of extracted values", "source", *r.cfg.Source) + if Debug { + level.Debug(r.logger).Log("msg", "source does not exist in the set of extracted values", "source", *r.cfg.Source) + } return } value, err := getString(extracted[*r.cfg.Source]) if err != nil { - 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()) + 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()) + } return } @@ -104,13 +108,17 @@ func (r *regexStage) Process(labels model.LabelSet, extracted map[string]interfa } if input == nil { - level.Debug(r.logger).Log("msg", "cannot parse a nil entry") + if Debug { + level.Debug(r.logger).Log("msg", "cannot parse a nil entry") + } return } match := r.expression.FindStringSubmatch(*input) if match == nil { - level.Debug(r.logger).Log("msg", "regex did not match") + if Debug { + level.Debug(r.logger).Log("msg", "regex did not match") + } return } diff --git a/pkg/logentry/stages/template.go b/pkg/logentry/stages/template.go index afea97a75f15..315d49f2ee54 100644 --- a/pkg/logentry/stages/template.go +++ b/pkg/logentry/stages/template.go @@ -90,14 +90,18 @@ func (o *templateStage) Process(labels model.LabelSet, extracted map[string]inte if v, ok := extracted[o.cfgs.Source]; ok { s, err := getString(v) if err != nil { - level.Debug(o.logger).Log("msg", "extracted template could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + if Debug { + level.Debug(o.logger).Log("msg", "extracted template could not be converted to a string", "err", err, "type", reflect.TypeOf(v).String()) + } return } td := templateData{s} buf := &bytes.Buffer{} err = o.template.Execute(buf, td) if err != nil { - level.Debug(o.logger).Log("msg", "failed to execute template on extracted value", "err", err, "value", v) + if Debug { + level.Debug(o.logger).Log("msg", "failed to execute template on extracted value", "err", err, "value", v) + } return } st := buf.String() @@ -113,7 +117,9 @@ func (o *templateStage) Process(labels model.LabelSet, extracted map[string]inte buf := &bytes.Buffer{} err := o.template.Execute(buf, td) if err != nil { - level.Debug(o.logger).Log("msg", "failed to execute template on extracted value", "err", err, "value", v) + if Debug { + level.Debug(o.logger).Log("msg", "failed to execute template on extracted value", "err", err, "value", v) + } return } st := buf.String() diff --git a/pkg/logentry/stages/timestamp.go b/pkg/logentry/stages/timestamp.go index 368ffd63be77..1f115dd60989 100644 --- a/pkg/logentry/stages/timestamp.go +++ b/pkg/logentry/stages/timestamp.go @@ -89,17 +89,23 @@ func (ts *timestampStage) Process(labels model.LabelSet, extracted map[string]in if v, ok := extracted[ts.cfgs.Source]; ok { s, err := getString(v) if err != nil { - level.Debug(ts.logger).Log("msg", "failed to convert extracted time to string", "err", err, "type", reflect.TypeOf(v).String()) + if Debug { + level.Debug(ts.logger).Log("msg", "failed to convert extracted time to string", "err", err, "type", reflect.TypeOf(v).String()) + } } parsedTs, err := ts.parser(s) if err != nil { - level.Debug(ts.logger).Log("msg", "failed to parse time", "err", err, "format", ts.cfgs.Format, "value", s) + if Debug { + level.Debug(ts.logger).Log("msg", "failed to parse time", "err", err, "format", ts.cfgs.Format, "value", s) + } } else { *t = parsedTs } } else { - level.Debug(ts.logger).Log("msg", "extracted data did not contain a timestamp") + if Debug { + level.Debug(ts.logger).Log("msg", "extracted data did not contain a timestamp") + } } } diff --git a/pkg/logentry/stages/util.go b/pkg/logentry/stages/util.go index 3efb369fe75c..14d474abc609 100644 --- a/pkg/logentry/stages/util.go +++ b/pkg/logentry/stages/util.go @@ -7,6 +7,14 @@ import ( "time" ) +var ( + // Debug is used to wrap debug log statements, the go-kit logger won't let us introspect the current log level + // so this global is used for that purpose. This allows us to skip allocations of log messages at the + // debug level when debug level logging is not enabled. Log level allocations can become very expensive + // as we log numerous log entries per log line at debug level. + Debug = false +) + const ( ErrTimestampContainsYear = "timestamp '%s' is expected to not contain the year date component" )