grafana/pkg/infra/log/log_test.go

package log

import (
	"context"
	"fmt"
	"testing"
	"time"

	gokitlog "github.com/go-kit/log"
	"github.com/go-kit/log/level"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"

	"github.com/grafana/grafana/pkg/util"
)

func TestLogger(t *testing.T) {
	t.Run("Root logger should be initialized", func(t *testing.T) {
		require.NotNil(t, root)
		err := root.Log("msg", "hello")
		require.NoError(t, err)
	})
}

func TestNew(t *testing.T) {
	scenario := newLoggerScenario(t)

	log1 := New("one")
	err := log1.Log("msg", "hello 1")
	require.NoError(t, err)
	log2 := New("two")
	err = log2.Log("msg", "hello 2")
	require.NoError(t, err)
	log3 := New("three")
	log3.Error("hello 3")
	log4 := log3.New("key", "value")
	err = log4.Log("msg", "hello 4")
	require.NoError(t, err)
	log3.Error("hello 3 again")

	require.Len(t, scenario.loggedArgs, 5, "lines logged")
	scenario.ValidateLineEquality(t, 0, []any{
		"logger", "one",
		"t", scenario.mockedTime,
		"msg", "hello 1",
	})

	scenario.ValidateLineEquality(t, 1, []any{
		"logger", "two",
		"t", scenario.mockedTime,
		"msg", "hello 2",
	})

	scenario.ValidateLineEquality(t, 2, []any{
		"logger", "three",
		"t", scenario.mockedTime,
		level.Key(), level.ErrorValue(),
		"msg", "hello 3",
	})

	scenario.ValidateLineEquality(t, 3, []any{
		"logger", "three",
		"key", "value",
		"t", scenario.mockedTime,
		"msg", "hello 4",
	})

	scenario.ValidateLineEquality(t, 4, []any{
		"logger", "three",
		"t", scenario.mockedTime,
		level.Key(), level.ErrorValue(),
		"msg", "hello 3 again",
	})

	t.Run("When initializing root logger should swap loggers as expected", func(t *testing.T) {
		swappedLoggedArgs := [][]any{}
		swapLogger := gokitlog.LoggerFunc(func(i ...any) error {
			swappedLoggedArgs = append(swappedLoggedArgs, i)
			return nil
		})

		root.initialize([]logWithFilters{
			{
				val:      swapLogger,
				maxLevel: level.AllowInfo(),
			},
			{
				val:      swapLogger,
				maxLevel: level.AllowAll(),
			},
		})

		err := log1.Log("msg", "hello 1")
		require.NoError(t, err)
		err = log2.Log("msg", "hello 2")
		require.NoError(t, err)
		log3.Error("hello 3")
		log3.Debug("debug")

		require.Len(t, scenario.loggedArgs, 5, "lines logged before swapping logger")
		require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger")
	})
}

func TestContextualArguments(t *testing.T) {
	scenario := newLoggerScenario(t)
	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) ([]any, bool) {
		return []any{"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, scenario.loggedArgs, 5)

	baseLog := []any{
		"logger", "root",
		"t", scenario.mockedTime,
		level.Key(), level.DebugValue(),
		"msg", "hello root",
	}
	scenario.ValidateLineEquality(t, 0, baseLog)

	scenario.ValidateLineEquality(t, 1, []any{
		"logger", "root",
		"childKey", "childValue",
		"t", scenario.mockedTime,
		level.Key(), level.ErrorValue(),
		"msg", "hello child",
	})

	require.Len(t, scenario.loggedArgs, 5)
	scenario.ValidateLineEquality(t, 2, []any{
		"logger", "root",
		"ctxKey", "ctxValue",
		"t", scenario.mockedTime,
		level.Key(), level.DebugValue(),
		"msg", "hello contextual root",
	})

	scenario.ValidateLineEquality(t, 3, []any{
		"logger", "root",
		"childKey", "childValue",
		"ctxKey", "ctxValue",
		"t", scenario.mockedTime,
		level.Key(), level.ErrorValue(),
		"msg", "hello contextual child",
	})

	scenario.ValidateLineEquality(t, 4, baseLog)
}

func TestWithPrefix_prependsContext(t *testing.T) {
	scenario := newLoggerScenario(t)
	ls := WithPrefix(New("test"), "k1", "v1")
	ls.Info("hello", "k2", "v2")

	require.Len(t, scenario.loggedArgs, 1)
	scenario.ValidateLineEquality(t, 0, []any{
		"logger", "test",
		"k1", "v1",
		"t", scenario.mockedTime,
		level.Key(), level.InfoValue(),
		"msg", "hello",
		"k2", "v2",
	})
}

func TestWithSuffix_appendsContext(t *testing.T) {
	scenario := newLoggerScenario(t)

	ls := WithSuffix(New("test"), "k1", "v1")
	ls.Info("hello", "k2", "v2")

	require.Len(t, scenario.loggedArgs, 1)
	scenario.ValidateLineEquality(t, 0, []any{
		"logger", "test",
		"t", scenario.mockedTime,
		level.Key(), level.InfoValue(),
		"msg", "hello",
		"k2", "v2",
		"k1", "v1",
	})
}

func TestGetFilters(t *testing.T) {
	t.Run("Parsing filters on single line with only space should return expected result", func(t *testing.T) {
		filter := `   `
		filters := getFilters(util.SplitString(filter))
		require.Len(t, filters, 0)
	})

	t.Run("Parsing filters on single line with should return expected result", func(t *testing.T) {
		filter := `rendering:debug oauth.generic_oauth:debug testwithoutlevel provisioning.dashboard:debug`
		filters := getFilters(util.SplitString(filter))
		keys := []string{}
		for k := range filters {
			keys = append(keys, k)
		}

		require.ElementsMatch(t, []string{
			"rendering",
			"oauth.generic_oauth",
			"provisioning.dashboard",
		}, keys)
	})

	t.Run("Parsing filters spread over multiple lines with comments should return expected result", func(t *testing.T) {
		filter := `rendering:debug \
          ; alerting.notifier:debug \
          oauth.generic_oauth:debug \
          ; oauth.okta:debug \
          ; tsdb.postgres:debug \
          ;tsdb.mssql:debug \
          #provisioning.plugins:debug \
          provisioning.dashboard:debug \
          data-proxy-log:debug \
          ;oauthtoken:debug \
          plugins.backend:debug \
          tsdb.elasticsearch.client:debug \
          server:debug \
          tsdb.graphite:debug \
          auth:debug \
          plugin.manager:debug \
          plugin.initializer:debug \
          plugin.loader:debug \
          plugin.finder:debug \
          plugin.installer:debug \
          plugin.signature.validator:debug`
		filters := getFilters(util.SplitString(filter))
		keys := []string{}
		for k := range filters {
			keys = append(keys, k)
		}

		require.ElementsMatch(t, []string{
			"rendering",
			"oauth.generic_oauth",
			"provisioning.dashboard",
			"data-proxy-log",
			"plugins.backend",
			"tsdb.elasticsearch.client",
			"server",
			"tsdb.graphite",
			"auth",
			"plugin.manager",
			"plugin.initializer",
			"plugin.loader",
			"plugin.finder",
			"plugin.installer",
			"plugin.signature.validator",
		}, keys)
	})
}

func TestWithContextualAttributes_appendsContext(t *testing.T) {
	t.Run("Logs arguments from context", func(t *testing.T) {
		scenario := newLoggerScenario(t, false)

		// logs `"k1", "v1"` with the first context
		ctx := context.Background()
		ctx = WithContextualAttributes(ctx, []any{"k1", "v1"})
		ls := New("test").FromContext(ctx)

		ls.Info("hello", "k2", "v2")

		require.Len(t, scenario.loggedArgs, 1)
		scenario.ValidateLineEquality(t, 0, []any{
			"logger", "test",
			"k1", "v1",
			"t", scenario.mockedTime,
			level.Key(), level.InfoValue(),
			"msg", "hello",
			"k2", "v2",
		})
	})
	t.Run("Does not log arguments from different context", func(t *testing.T) {
		scenario := newLoggerScenario(t, false)

		// logs `"k1", "v1"` with the first context
		ctx := context.Background()
		ctx = WithContextualAttributes(ctx, []any{"k1", "v1"})
		ls := New("test").FromContext(ctx)

		ls.Info("hello", "k2", "v2")

		require.Len(t, scenario.loggedArgs, 1)
		scenario.ValidateLineEquality(t, 0, []any{
			"logger", "test",
			"k1", "v1",
			"t", scenario.mockedTime,
			level.Key(), level.InfoValue(),
			"msg", "hello",
			"k2", "v2",
		})
		// does not log `"k1", "v1"` with the new context
		ctx = context.Background()
		ls = New("test").FromContext(ctx)

		ls.Info("hello", "k2", "v2")

		require.Len(t, scenario.loggedArgs, 2)
		scenario.ValidateLineEquality(t, 1, []any{
			"logger", "test",
			"t", scenario.mockedTime,
			level.Key(), level.InfoValue(),
			"msg", "hello",
			"k2", "v2",
		})
	})
	t.Run("Appends arguments set previously", func(t *testing.T) {
		scenario := newLoggerScenario(t, false)

		ctx := context.Background()
		ctx = WithContextualAttributes(ctx, []any{"k1", "v1"})
		ctx = WithContextualAttributes(ctx, []any{"k2", "v2"})
		ls := New("test").FromContext(ctx)

		ls.Info("hello", "k3", "v3")

		require.Len(t, scenario.loggedArgs, 1)
		scenario.ValidateLineEquality(t, 0, []any{
			"logger", "test",
			"k1", "v1",
			"k2", "v2",
			"t", scenario.mockedTime,
			level.Key(), level.InfoValue(),
			"msg", "hello",
			"k3", "v3",
		})
	})
}

type scenarioContext struct {
	loggedArgs [][]any
	mockedTime time.Time
}

func (s *scenarioContext) ValidateLineEquality(t testing.TB, n int, expected []any) {
	t.Helper()

	actual := s.loggedArgs[n]
	require.Len(t, actual, len(expected))
	for i := range expected {
		switch ex := expected[i].(type) {
		case time.Time:
			assert.Equal(t, ex.Format(time.RFC3339Nano), actual[i].(fmt.Stringer).String())
		default:
			assert.Equalf(t, ex, actual[i], "line %d argument %d does not match expected value.", n, i)
		}
	}
}

func newLoggerScenario(t testing.TB, resetCtxLogProviders ...bool) *scenarioContext {
	clearProviders := true
	if len(resetCtxLogProviders) > 0 {
		clearProviders = resetCtxLogProviders[0]
	}

	t.Helper()

	scenario := &scenarioContext{
		loggedArgs: [][]any{},
		mockedTime: time.Now(),
	}

	l := gokitlog.LoggerFunc(func(i ...any) error {
		scenario.loggedArgs = append(scenario.loggedArgs, i)
		return nil
	})

	origNow := now
	now = func() time.Time {
		return scenario.mockedTime
	}
	t.Cleanup(func() {
		now = origNow
	})

	if clearProviders {
		origContextHandlers := ctxLogProviders
		ctxLogProviders = []ContextualLogProviderFunc{}
		t.Cleanup(func() {
			ctxLogProviders = origContextHandlers
		})
	}

	root = newManager(l)
	return scenario
}