Add ability to label inputs for logging (#6207)

internal/models/log.go

@@ -0,0 +1,87 @@
+package models
+
+import (
+	"log"
+	"reflect"
+
+	"github.com/influxdata/telegraf"
+	"github.com/influxdata/telegraf/selfstat"
+)
+
+// Logger defines a logging structure for plugins.
+type Logger struct {
+	Errs selfstat.Stat
+	Name string // Name is the plugin name, will be printed in the `[]`.
+}
+
+// Errorf logs an error message, patterned after log.Printf.
+func (l *Logger) Errorf(format string, args ...interface{}) {
+	l.Errs.Incr(1)
+	log.Printf("E! ["+l.Name+"] "+format, args...)
+}
+
+// Error logs an error message, patterned after log.Print.
+func (l *Logger) Error(args ...interface{}) {
+	l.Errs.Incr(1)
+	log.Print(append([]interface{}{"E! [" + l.Name + "] "}, args...)...)
+}
+
+// Debugf logs a debug message, patterned after log.Printf.
+func (l *Logger) Debugf(format string, args ...interface{}) {
+	log.Printf("D! ["+l.Name+"] "+format, args...)
+}
+
+// Debug logs a debug message, patterned after log.Print.
+func (l *Logger) Debug(args ...interface{}) {
+	log.Print(append([]interface{}{"D! [" + l.Name + "] "}, args...)...)
+}
+
+// Warnf logs a warning message, patterned after log.Printf.
+func (l *Logger) Warnf(format string, args ...interface{}) {
+	log.Printf("W! ["+l.Name+"] "+format, args...)
+}
+
+// Warn logs a warning message, patterned after log.Print.
+func (l *Logger) Warn(args ...interface{}) {
+	log.Print(append([]interface{}{"W! [" + l.Name + "] "}, args...)...)
+}
+
+// Infof logs an information message, patterned after log.Printf.
+func (l *Logger) Infof(format string, args ...interface{}) {
+	log.Printf("I! ["+l.Name+"] "+format, args...)
+}
+
+// Info logs an information message, patterned after log.Print.
+func (l *Logger) Info(args ...interface{}) {
+	log.Print(append([]interface{}{"I! [" + l.Name + "] "}, args...)...)
+}
+
+// logName returns the log-friendly name/type.
+func logName(pluginType, name, alias string) string {
+	if alias == "" {
+		return pluginType + "." + name
+	}
+	return pluginType + "." + name + "::" + alias
+}
+
+func setLogIfExist(i interface{}, log telegraf.Logger) {
+	valI := reflect.ValueOf(i)
+
+	if valI.Type().Kind() != reflect.Ptr {
+		valI = reflect.New(reflect.TypeOf(i))
+	}
+
+	field := valI.Elem().FieldByName("Log")
+	if !field.IsValid() {
+		return
+	}
+
+	switch field.Type().String() {
+	case "telegraf.Logger":
+		if field.CanSet() {
+			field.Set(reflect.ValueOf(log))
+		}
+	}
+
+	return
+}

internal/models/log_test.go

@@ -0,0 +1,70 @@
+package models
+
+import (
+	"testing"
+
+	"github.com/influxdata/telegraf/selfstat"
+	"github.com/stretchr/testify/require"
+)
+
+func TestErrorCounting(t *testing.T) {
+	iLog := Logger{Name: "inputs.test", Errs: selfstat.Register(
+		"gather",
+		"errors",
+		map[string]string{"input": "test"},
+	)}
+	iLog.Error("something went wrong")
+	iLog.Errorf("something went wrong")
+
+	aLog := Logger{Name: "aggregators.test", Errs: selfstat.Register(
+		"aggregate",
+		"errors",
+		map[string]string{"aggregator": "test"},
+	)}
+	aLog.Name = "aggregators.test"
+	aLog.Error("another thing happened")
+
+	oLog := Logger{Name: "outputs.test", Errs: selfstat.Register(
+		"write",
+		"errors",
+		map[string]string{"output": "test"},
+	)}
+	oLog.Error("another thing happened")
+
+	pLog := Logger{Name: "processors.test", Errs: selfstat.Register(
+		"process",
+		"errors",
+		map[string]string{"processor": "test"},
+	)}
+	pLog.Error("another thing happened")
+
+	require.Equal(t, int64(2), iLog.Errs.Get())
+	require.Equal(t, int64(1), aLog.Errs.Get())
+	require.Equal(t, int64(1), oLog.Errs.Get())
+	require.Equal(t, int64(1), pLog.Errs.Get())
+}
+
+func TestLogging(t *testing.T) {
+	log := Logger{Name: "inputs.test", Errs: selfstat.Register(
+		"gather",
+		"errors",
+		map[string]string{"input": "test"},
+	)}
+
+	log.Errs.Set(0)
+
+	log.Debugf("something happened")
+	log.Debug("something happened")
+
+	log.Warnf("something happened")
+	log.Warn("something happened")
+	require.Equal(t, int64(0), log.Errs.Get())
+
+	log.Infof("something happened")
+	log.Info("something happened")
+	require.Equal(t, int64(0), log.Errs.Get())
+
+	log.Errorf("something happened")
+	log.Error("something happened")
+	require.Equal(t, int64(2), log.Errs.Get())
+}

internal/models/running_aggregator.go

@@ -1,7 +1,6 @@
 package models
 
 import (
-	"log"
 	"sync"
 	"time"
 
@@ -16,6 +15,7 @@ type RunningAggregator struct {
 	Config      *AggregatorConfig
 	periodStart time.Time
 	periodEnd   time.Time
+	log         telegraf.Logger
 
 	MetricsPushed   selfstat.Stat
 	MetricsFiltered selfstat.Stat
@@ -23,39 +23,46 @@ type RunningAggregator struct {
 	PushTime        selfstat.Stat
 }
 
-func NewRunningAggregator(
-	aggregator telegraf.Aggregator,
-	config *AggregatorConfig,
-) *RunningAggregator {
+func NewRunningAggregator(aggregator telegraf.Aggregator, config *AggregatorConfig) *RunningAggregator {
+	logger := &Logger{
+		Name: logName("aggregators", config.Name, config.Alias),
+		Errs: selfstat.Register("aggregate", "errors",
+			map[string]string{"input": config.Name, "alias": config.Alias}),
+	}
+
+	setLogIfExist(aggregator, logger)
+
 	return &RunningAggregator{
 		Aggregator: aggregator,
 		Config:     config,
 		MetricsPushed: selfstat.Register(
 			"aggregate",
 			"metrics_pushed",
-			map[string]string{"aggregator": config.Name},
+			map[string]string{"aggregator": config.Name, "alias": config.Alias},
 		),
 		MetricsFiltered: selfstat.Register(
 			"aggregate",
 			"metrics_filtered",
-			map[string]string{"aggregator": config.Name},
+			map[string]string{"aggregator": config.Name, "alias": config.Alias},
 		),
 		MetricsDropped: selfstat.Register(
 			"aggregate",
 			"metrics_dropped",
-			map[string]string{"aggregator": config.Name},
+			map[string]string{"aggregator": config.Name, "alias": config.Alias},
 		),
 		PushTime: selfstat.Register(
 			"aggregate",
 			"push_time_ns",
-			map[string]string{"aggregator": config.Name},
+			map[string]string{"aggregator": config.Name, "alias": config.Alias},
 		),
+		log: logger,
 	}
 }
 
 // AggregatorConfig is the common config for all aggregators.
 type AggregatorConfig struct {
 	Name         string
+	Alias        string
 	DropOriginal bool
 	Period       time.Duration
 	Delay        time.Duration
@@ -68,8 +75,8 @@ type AggregatorConfig struct {
 	Filter            Filter
 }
 
-func (r *RunningAggregator) Name() string {
-	return "aggregators." + r.Config.Name
+func (r *RunningAggregator) LogName() string {
+	return logName("aggregators", r.Config.Name, r.Config.Alias)
 }
 
 func (r *RunningAggregator) Init() error {
@@ -93,7 +100,7 @@ func (r *RunningAggregator) EndPeriod() time.Time {
 func (r *RunningAggregator) UpdateWindow(start, until time.Time) {
 	r.periodStart = start
 	r.periodEnd = until
-	log.Printf("D! [%s] Updated aggregation range [%s, %s]", r.Name(), start, until)
+	r.log.Debugf("Updated aggregation range [%s, %s]", start, until)
 }
 
 func (r *RunningAggregator) MakeMetric(metric telegraf.Metric) telegraf.Metric {
@@ -137,8 +144,8 @@ func (r *RunningAggregator) Add(m telegraf.Metric) bool {
 	defer r.Unlock()
 
 	if m.Time().Before(r.periodStart.Add(-r.Config.Grace)) || m.Time().After(r.periodEnd.Add(r.Config.Delay)) {
-		log.Printf("D! [%s] metric is outside aggregation window; discarding. %s: m: %s e: %s g: %s",
-			r.Name(), m.Time(), r.periodStart, r.periodEnd, r.Config.Grace)
+		r.log.Debugf("metric is outside aggregation window; discarding. %s: m: %s e: %s g: %s",
+			m.Time(), r.periodStart, r.periodEnd, r.Config.Grace)
 		r.MetricsDropped.Incr(1)
 		return r.Config.DropOriginal
 	}

internal/models/running_input.go

@@ -13,6 +13,7 @@ type RunningInput struct {
 	Input  telegraf.Input
 	Config *InputConfig
 
+	log         telegraf.Logger
 	defaultTags map[string]string
 
 	MetricsGathered selfstat.Stat
@@ -20,25 +21,35 @@ type RunningInput struct {
 }
 
 func NewRunningInput(input telegraf.Input, config *InputConfig) *RunningInput {
+	logger := &Logger{
+		Name: logName("inputs", config.Name, config.Alias),
+		Errs: selfstat.Register("gather", "errors",
+			map[string]string{"input": config.Name, "alias": config.Alias}),
+	}
+
+	setLogIfExist(input, logger)
+
 	return &RunningInput{
 		Input:  input,
 		Config: config,
 		MetricsGathered: selfstat.Register(
 			"gather",
 			"metrics_gathered",
-			map[string]string{"input": config.Name},
+			map[string]string{"input": config.Name, "alias": config.Alias},
 		),
 		GatherTime: selfstat.RegisterTiming(
 			"gather",
 			"gather_time_ns",
-			map[string]string{"input": config.Name},
+			map[string]string{"input": config.Name, "alias": config.Alias},
 		),
+		log: logger,
 	}
 }
 
 // InputConfig is the common config for all inputs.
 type InputConfig struct {
 	Name     string
+	Alias    string
 	Interval time.Duration
 
 	NameOverride      string
@@ -48,14 +59,14 @@ type InputConfig struct {
 	Filter            Filter
 }
 
-func (r *RunningInput) Name() string {
-	return "inputs." + r.Config.Name
-}
-
 func (r *RunningInput) metricFiltered(metric telegraf.Metric) {
 	metric.Drop()
 }
 
+func (r *RunningInput) LogName() string {
+	return logName("inputs", r.Config.Name, r.Config.Alias)
+}
+
 func (r *RunningInput) Init() error {
 	if p, ok := r.Input.(telegraf.Initializer); ok {
 		err := p.Init()

internal/models/running_output.go

@@ -1,7 +1,6 @@
 package models
 
 import (
-	"log"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -21,6 +20,7 @@ const (
 // OutputConfig containing name and filter
 type OutputConfig struct {
 	Name   string
+	Alias  string
 	Filter Filter
 
 	FlushInterval     time.Duration
@@ -34,7 +34,6 @@ type RunningOutput struct {
 	newMetricsCount int64
 	droppedMetrics  int64
 
-	Name              string
 	Output            telegraf.Output
 	Config            *OutputConfig
 	MetricBufferLimit int
@@ -46,6 +45,7 @@ type RunningOutput struct {
 	BatchReady chan time.Time
 
 	buffer *Buffer
+	log    telegraf.Logger
 
 	aggMutex sync.Mutex
 }
@@ -53,56 +53,77 @@ type RunningOutput struct {
 func NewRunningOutput(
 	name string,
 	output telegraf.Output,
-	conf *OutputConfig,
+	config *OutputConfig,
 	batchSize int,
 	bufferLimit int,
 ) *RunningOutput {
-	if conf.MetricBufferLimit > 0 {
-		bufferLimit = conf.MetricBufferLimit
+	logger := &Logger{
+		Name: logName("outputs", config.Name, config.Alias),
+		Errs: selfstat.Register("gather", "errors",
+			map[string]string{"output": config.Name, "alias": config.Alias}),
+	}
+
+	setLogIfExist(output, logger)
+
+	if config.MetricBufferLimit > 0 {
+		bufferLimit = config.MetricBufferLimit
 	}
 	if bufferLimit == 0 {
 		bufferLimit = DEFAULT_METRIC_BUFFER_LIMIT
 	}
-	if conf.MetricBatchSize > 0 {
-		batchSize = conf.MetricBatchSize
+	if config.MetricBatchSize > 0 {
+		batchSize = config.MetricBatchSize
 	}
 	if batchSize == 0 {
 		batchSize = DEFAULT_METRIC_BATCH_SIZE
 	}
+
 	ro := &RunningOutput{
-		Name:              name,
-		buffer:            NewBuffer(name, bufferLimit),
+		buffer:            NewBuffer(config.LogName(), bufferLimit),
 		BatchReady:        make(chan time.Time, 1),
 		Output:            output,
-		Config:            conf,
+		Config:            config,
 		MetricBufferLimit: bufferLimit,
 		MetricBatchSize:   batchSize,
 		MetricsFiltered: selfstat.Register(
 			"write",
 			"metrics_filtered",
-			map[string]string{"output": name},
+			map[string]string{"output": config.Name, "alias": config.Alias},
 		),
 		WriteTime: selfstat.RegisterTiming(
 			"write",
 			"write_time_ns",
-			map[string]string{"output": name},
+			map[string]string{"output": config.Name, "alias": config.Alias},
 		),
+		log: logger,
 	}
 
 	return ro
 }
 
+func (c *OutputConfig) LogName() string {
+	if c.Alias == "" {
+		return c.Name
+	}
+	return c.Name + "::" + c.Alias
+}
+
+func (r *RunningOutput) LogName() string {
+	return logName("outputs", r.Config.Name, r.Config.Alias)
+}
+
 func (ro *RunningOutput) metricFiltered(metric telegraf.Metric) {
 	ro.MetricsFiltered.Incr(1)
 	metric.Drop()
 }
 
-func (ro *RunningOutput) Init() error {
-	if p, ok := ro.Output.(telegraf.Initializer); ok {
+func (r *RunningOutput) Init() error {
+	if p, ok := r.Output.(telegraf.Initializer); ok {
 		err := p.Init()
 		if err != nil {
 			return err
 		}
+
 	}
 	return nil
 }
@@ -192,35 +213,32 @@ func (ro *RunningOutput) WriteBatch() error {
 	return nil
 }
 
-func (ro *RunningOutput) Close() {
-	err := ro.Output.Close()
+func (r *RunningOutput) Close() {
+	err := r.Output.Close()
 	if err != nil {
-		log.Printf("E! [outputs.%s] Error closing output: %v", ro.Name, err)
+		r.log.Errorf("Error closing output: %v", err)
 	}
 }
 
-func (ro *RunningOutput) write(metrics []telegraf.Metric) error {
-	dropped := atomic.LoadInt64(&ro.droppedMetrics)
+func (r *RunningOutput) write(metrics []telegraf.Metric) error {
+	dropped := atomic.LoadInt64(&r.droppedMetrics)
 	if dropped > 0 {
-		log.Printf("W! [outputs.%s] Metric buffer overflow; %d metrics have been dropped",
-			ro.Name, dropped)
-		atomic.StoreInt64(&ro.droppedMetrics, 0)
+		r.log.Warnf("Metric buffer overflow; %d metrics have been dropped", dropped)
+		atomic.StoreInt64(&r.droppedMetrics, 0)
 	}
 
 	start := time.Now()
-	err := ro.Output.Write(metrics)
+	err := r.Output.Write(metrics)
 	elapsed := time.Since(start)
-	ro.WriteTime.Incr(elapsed.Nanoseconds())
+	r.WriteTime.Incr(elapsed.Nanoseconds())
 
 	if err == nil {
-		log.Printf("D! [outputs.%s] wrote batch of %d metrics in %s\n",
-			ro.Name, len(metrics), elapsed)
+		r.log.Debugf("Wrote batch of %d metrics in %s", len(metrics), elapsed)
 	}
 	return err
 }
 
-func (ro *RunningOutput) LogBufferStatus() {
-	nBuffer := ro.buffer.Len()
-	log.Printf("D! [outputs.%s] buffer fullness: %d / %d metrics. ",
-		ro.Name, nBuffer, ro.MetricBufferLimit)
+func (r *RunningOutput) LogBufferStatus() {
+	nBuffer := r.buffer.Len()
+	r.log.Debugf("Buffer fullness: %d / %d metrics", nBuffer, r.MetricBufferLimit)
 }

internal/models/running_processor.go

@@ -4,12 +4,12 @@ import (
 	"sync"
 
 	"github.com/influxdata/telegraf"
+	"github.com/influxdata/telegraf/selfstat"
 )
 
 type RunningProcessor struct {
-	Name string
-
 	sync.Mutex
+	log       telegraf.Logger
 	Processor telegraf.Processor
 	Config    *ProcessorConfig
 }
@@ -23,10 +23,27 @@ func (rp RunningProcessors) Less(i, j int) bool { return rp[i].Config.Order < rp
 // FilterConfig containing a name and filter
 type ProcessorConfig struct {
 	Name   string
+	Alias  string
 	Order  int64
 	Filter Filter
 }
 
+func NewRunningProcessor(processor telegraf.Processor, config *ProcessorConfig) *RunningProcessor {
+	logger := &Logger{
+		Name: logName("processors", config.Name, config.Alias),
+		Errs: selfstat.Register("process", "errors",
+			map[string]string{"input": config.Name, "alias": config.Alias}),
+	}
+
+	setLogIfExist(processor, logger)
+
+	return &RunningProcessor{
+		Processor: processor,
+		Config:    config,
+		log:       logger,
+	}
+}
+
 func (rp *RunningProcessor) metricFiltered(metric telegraf.Metric) {
 	metric.Drop()
 }
@@ -40,8 +57,8 @@ func containsMetric(item telegraf.Metric, metrics []telegraf.Metric) bool {
 	return false
 }
 
-func (rp *RunningProcessor) Init() error {
-	if p, ok := rp.Processor.(telegraf.Initializer); ok {
+func (r *RunningProcessor) Init() error {
+	if p, ok := r.Processor.(telegraf.Initializer); ok {
 		err := p.Init()
 		if err != nil {
 			return err