Logging: Introduce API for contextual logging (#55198)

Introduces a FromContext method on the log.Logger interface that 
allows contextual key/value pairs to be attached, e.g. per request, 
so that any logger using this API will automatically get the per request 
context attached. The proposal makes the traceID available for 
contextual logger , if available, and would allow logs originating from 
a certain HTTP request to be correlated with traceID.
In addition, when tracing not enabled, skip adding
traceID=00000000000000000000000000000000
to logs.

pkg/infra/log/interface.go

@@ -1,5 +1,7 @@
 package log
 
+import "context"
+
 type Lvl int
 
 const (
@@ -16,9 +18,18 @@ type Logger interface {
 
 	Log(keyvals ...interface{}) error
 
-	// Log a message at the given level with context key/value pairs
+	// Debug logs a message with debug level and key/value pairs, if any.
 	Debug(msg string, ctx ...interface{})
+
+	// Info logs a message with info level and key/value pairs, if any.
 	Info(msg string, ctx ...interface{})
+
+	// Warn logs a message with warning level and key/value pairs, if any.
 	Warn(msg string, ctx ...interface{})
+
+	// Error logs a message with error level and key/value pairs, if any.
 	Error(msg string, ctx ...interface{})
+
+	// FromContext returns a new contextual Logger that has this logger's context plus the given context.
+	FromContext(ctx context.Context) Logger
 }

pkg/infra/log/log.go

@@ -5,6 +5,7 @@
 package log
 
 import (
+	"context"
 	"fmt"
 	"io"
 	"os"
@@ -31,6 +32,7 @@ var (
 	root            *logManager
 	now             = time.Now
 	logTimeFormat   = time.RFC3339Nano
+	ctxLogProviders = []ContextualLogProviderFunc{}
 )
 
 const (
@@ -190,6 +192,22 @@ func (cl *ConcreteLogger) log(msg string, logLevel level.Value, args ...interfac
 	return cl.Log(append([]interface{}{level.Key(), logLevel, "msg", msg}, args...)...)
 }
 
+func (cl *ConcreteLogger) FromContext(ctx context.Context) Logger {
+	args := []interface{}{}
+
+	for _, p := range ctxLogProviders {
+		if pArgs, exists := p(ctx); exists {
+			args = append(args, pArgs...)
+		}
+	}
+
+	if len(args) > 0 {
+		return cl.New(args...)
+	}
+
+	return cl
+}
+
 func (cl *ConcreteLogger) New(ctx ...interface{}) *ConcreteLogger {
 	if len(ctx) == 0 {
 		root.New()
@@ -243,6 +261,15 @@ func WithSuffix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger {
 	return with(ctxLogger, gokitlog.WithSuffix, ctx)
 }
 
+// ContextualLogProviderFunc contextual log provider function definition.
+type ContextualLogProviderFunc func(ctx context.Context) ([]interface{}, bool)
+
+// RegisterContextualLogProvider registers a ContextualLogProviderFunc
+// that will be used to provide context when Logger.FromContext is called.
+func RegisterContextualLogProvider(mw ContextualLogProviderFunc) {
+	ctxLogProviders = append(ctxLogProviders, mw)
+}
+
 var logLevels = map[string]level.Option{
 	"trace":    level.AllowDebug(),
 	"debug":    level.AllowDebug(),

pkg/infra/log/log_test.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"context"
 	"fmt"
 	"testing"
 	"time"
@@ -109,6 +110,79 @@ func TestLogger(t *testing.T) {
 			require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger")
 		})
 	})
+
+	newLoggerScenario(t, "Logger with contextual arguments", func(t *testing.T, sCtx *scenarioContext) {
+		ctx := context.Background()
+		rootLogger := New("root")
+		rootLoggerCtx := rootLogger.FromContext(ctx)
+		rootLoggerCtx.Debug("hello root")
+		childLogger := rootLogger.New("childKey", "childValue")
+		childLoggerCtx := childLogger.FromContext(ctx)
+		childLoggerCtx.Error("hello child")
+
+		RegisterContextualLogProvider(func(ctx context.Context) ([]interface{}, bool) {
+			return []interface{}{"ctxKey", "ctxValue"}, true
+		})
+
+		rootLoggerCtx = rootLogger.FromContext(ctx)
+		rootLoggerCtx.Debug("hello contextual root")
+		childLoggerCtx = childLogger.FromContext(ctx)
+		childLoggerCtx.Error("hello contextual child")
+
+		newRootLogger := New("root")
+		newRootLogger.Debug("hello root")
+
+		require.Len(t, sCtx.loggedArgs, 5)
+		require.Len(t, sCtx.loggedArgs[0], 8)
+		require.Equal(t, "logger", sCtx.loggedArgs[0][0].(string))
+		require.Equal(t, "root", sCtx.loggedArgs[0][1].(string))
+		require.Equal(t, "t", sCtx.loggedArgs[0][2].(string))
+		require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[0][3].(fmt.Stringer).String())
+		require.Equal(t, level.Key().(string), sCtx.loggedArgs[0][4].(string))
+		require.Equal(t, level.DebugValue(), sCtx.loggedArgs[0][5].(level.Value))
+		require.Equal(t, "msg", sCtx.loggedArgs[0][6].(string))
+		require.Equal(t, "hello root", sCtx.loggedArgs[0][7].(string))
+
+		require.Len(t, sCtx.loggedArgs[1], 10)
+		require.Equal(t, "logger", sCtx.loggedArgs[1][0].(string))
+		require.Equal(t, "root", sCtx.loggedArgs[1][1].(string))
+		require.Equal(t, "childKey", sCtx.loggedArgs[1][2].(string))
+		require.Equal(t, "childValue", sCtx.loggedArgs[1][3].(string))
+		require.Equal(t, "t", sCtx.loggedArgs[1][4].(string))
+		require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[1][5].(fmt.Stringer).String())
+		require.Equal(t, level.Key().(string), sCtx.loggedArgs[1][6].(string))
+		require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[1][7].(level.Value))
+		require.Equal(t, "msg", sCtx.loggedArgs[1][8].(string))
+		require.Equal(t, "hello child", sCtx.loggedArgs[1][9].(string))
+
+		require.Len(t, sCtx.loggedArgs[2], 10)
+		require.Equal(t, "logger", sCtx.loggedArgs[2][0].(string))
+		require.Equal(t, "root", sCtx.loggedArgs[2][1].(string))
+		require.Equal(t, "ctxKey", sCtx.loggedArgs[2][2].(string))
+		require.Equal(t, "ctxValue", sCtx.loggedArgs[2][3].(string))
+		require.Equal(t, "t", sCtx.loggedArgs[2][4].(string))
+		require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[2][5].(fmt.Stringer).String())
+		require.Equal(t, level.Key().(string), sCtx.loggedArgs[2][6].(string))
+		require.Equal(t, level.DebugValue(), sCtx.loggedArgs[2][7].(level.Value))
+		require.Equal(t, "msg", sCtx.loggedArgs[2][8].(string))
+		require.Equal(t, "hello contextual root", sCtx.loggedArgs[2][9].(string))
+
+		require.Len(t, sCtx.loggedArgs[3], 12)
+		require.Equal(t, "logger", sCtx.loggedArgs[3][0].(string))
+		require.Equal(t, "root", sCtx.loggedArgs[3][1].(string))
+		require.Equal(t, "childKey", sCtx.loggedArgs[3][2].(string))
+		require.Equal(t, "childValue", sCtx.loggedArgs[3][3].(string))
+		require.Equal(t, "ctxKey", sCtx.loggedArgs[3][4].(string))
+		require.Equal(t, "ctxValue", sCtx.loggedArgs[3][5].(string))
+		require.Equal(t, "t", sCtx.loggedArgs[3][6].(string))
+		require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[3][7].(fmt.Stringer).String())
+		require.Equal(t, level.Key().(string), sCtx.loggedArgs[3][8].(string))
+		require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[3][9].(level.Value))
+		require.Equal(t, "msg", sCtx.loggedArgs[3][10].(string))
+		require.Equal(t, "hello contextual child", sCtx.loggedArgs[3][11].(string))
+
+		require.Len(t, sCtx.loggedArgs[4], 8)
+	})
 }
 
 func TestWithPrefix(t *testing.T) {

pkg/infra/log/logtest/fake.go

@@ -1,6 +1,8 @@
 package logtest
 
 import (
+	"context"
+
 	"github.com/grafana/grafana/pkg/infra/log"
 )
 
@@ -48,3 +50,19 @@ func (f *Fake) Error(msg string, ctx ...interface{}) {
 	f.ErrorLogs.Message = msg
 	f.ErrorLogs.Ctx = ctx
 }
+
+func (f *Fake) DebugCtx(_ context.Context, msg string, args ...interface{}) {
+	f.Debug(msg, args...)
+}
+
+func (f *Fake) InfoCtx(_ context.Context, msg string, args ...interface{}) {
+	f.Info(msg, args...)
+}
+
+func (f *Fake) WarnCtx(_ context.Context, msg string, args ...interface{}) {
+	f.Warn(msg, args...)
+}
+
+func (f *Fake) FromContext(_ context.Context) log.Logger {
+	return f.New()
+}