grafana/pkg/infra/log/log_test.go

package log

import (
	"fmt"
	"testing"
	"time"

	gokitlog "github.com/go-kit/log"
	"github.com/grafana/grafana/pkg/infra/log/level"
	"github.com/grafana/grafana/pkg/util"
	"github.com/stretchr/testify/require"
)

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

	t.Run("When creating root logger should log as expected", func(t *testing.T) {
		loggedArgs := [][]interface{}{}
		l := gokitlog.LoggerFunc(func(i ...interface{}) error {
			loggedArgs = append(loggedArgs, i)
			return nil
		})

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

		root = newManager(l)
		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)

		require.Len(t, loggedArgs, 4)
		require.Len(t, loggedArgs[0], 4)
		require.Equal(t, "logger", loggedArgs[0][0].(string))
		require.Equal(t, "one", loggedArgs[0][1].(string))
		require.Equal(t, "msg", loggedArgs[0][2].(string))
		require.Equal(t, "hello 1", loggedArgs[0][3].(string))

		require.Len(t, loggedArgs[1], 4)
		require.Equal(t, "logger", loggedArgs[1][0].(string))
		require.Equal(t, "two", loggedArgs[1][1].(string))
		require.Equal(t, "msg", loggedArgs[1][2].(string))
		require.Equal(t, "hello 2", loggedArgs[1][3].(string))

		require.Len(t, loggedArgs[2], 8)
		require.Equal(t, "logger", loggedArgs[2][0].(string))
		require.Equal(t, "three", loggedArgs[2][1].(string))
		require.Equal(t, "t", loggedArgs[2][2].(string))
		require.Equal(t, mockedTime.Format("2006-01-02T15:04:05.99-0700"), loggedArgs[2][3].(fmt.Stringer).String())
		require.Equal(t, "lvl", loggedArgs[2][4].(string))
		require.Equal(t, level.ErrorValue(), loggedArgs[2][5].(level.Value))
		require.Equal(t, "msg", loggedArgs[2][6].(string))
		require.Equal(t, "hello 3", loggedArgs[2][7].(string))

		require.Len(t, loggedArgs[3], 6)
		require.Equal(t, "logger", loggedArgs[3][0].(string))
		require.Equal(t, "three", loggedArgs[3][1].(string))
		require.Equal(t, "key", loggedArgs[3][2].(string))
		require.Equal(t, "value", loggedArgs[3][3].(string))
		require.Equal(t, "msg", loggedArgs[3][4].(string))
		require.Equal(t, "hello 4", loggedArgs[3][5].(string))

		t.Run("When initializing root logger should swap loggers as expected", func(t *testing.T) {
			swappedLoggedArgs := [][]interface{}{}
			swapLogger := gokitlog.LoggerFunc(func(i ...interface{}) 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, loggedArgs, 4)
			require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger")
		})
	})
}

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