gitlab.com/gitlab-org/labkit@v1.21.0/log/initialization_test.go

package log

import (
	"bytes"
	"fmt"
	"os"
	"regexp"
	"testing"
	"time"

	logrus "github.com/sirupsen/logrus"
	"github.com/stretchr/testify/require"
)

func TestInitialize(t *testing.T) {
	rfc3339baseTimestampPattern := "\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}"
	iso8601baseTimestampPattern := "\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}.\\d{3}"

	tests := []struct {
		name         string
		opts         []LoggerOption
		envVars      map[string]string
		wantErr      bool
		regexps      []*regexp.Regexp
		infoMessage  string
		debugMessage string
	}{
		{
			name: "trivial",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^$`),
			},
		},
		{
			name:        "simple",
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=Hello`),
			},
		},
		{
			name: "simple-json",
			opts: []LoggerOption{
				WithFormatter("json"),
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^{"level":"info","msg":"Hello"`),
			},
		},
		{
			name: "simple-text",
			opts: []LoggerOption{
				WithFormatter("text"),
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=Hello`),
			},
		},
		{
			name: "invalid-formatter",
			opts: []LoggerOption{
				WithFormatter("rubbish"),
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=warning.*msg="unknown logging format rubbish, ignoring option"`),
				regexp.MustCompile(`(?m)^time=.*level=info.*msg=Hello`),
			},
		},
		{
			name: "loglevel-below-threshold",
			opts: []LoggerOption{
				WithLogLevel("info"),
			},
			debugMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^$`),
			},
		},
		{
			name: "loglevel-at-threshold",
			opts: []LoggerOption{
				WithLogLevel("info"),
			},
			infoMessage:  "InfoHello",
			debugMessage: "DebugHello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=InfoHello\n$`),
			},
		},
		{
			name: "invalid-threshold",
			opts: []LoggerOption{
				WithLogLevel("garbage"),
			},
			infoMessage:  "InfoHello",
			debugMessage: "DebugHello",

			regexps: []*regexp.Regexp{
				regexp.MustCompile(`level=warning msg="unknown log level, ignoring option`),
				regexp.MustCompile(`(?m)^time=.*level=info.*msg=InfoHello\n$`),
			},
		},
		{
			name: "invalid-threshold-json-format",
			opts: []LoggerOption{
				WithFormatter("json"),
				WithLogLevel("garbage"),
			},
			infoMessage:  "InfoHello",
			debugMessage: "DebugHello",

			regexps: []*regexp.Regexp{
				regexp.MustCompile(`"msg":"unknown log level, ignoring option: not a valid logrus Level`),
				regexp.MustCompile(`"msg":"InfoHello"`),
			},
		},
		{
			name: "emit-to-stderr",
			opts: []LoggerOption{
				WithOutputName("stderr"),
			},
			infoMessage: "InfoHello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=InfoHello\n$`),
			},
		},
		{
			name: "emit-to-stdout",
			opts: []LoggerOption{
				WithOutputName("stdout"),
			},
			infoMessage: "InfoHello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=InfoHello\n$`),
			},
		},
		{
			name: "emit-to-file",
			opts: []LoggerOption{
				WithOutputName("/tmp/test.log"),
			},
			infoMessage: "InfoHello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=.*level=info.*msg=InfoHello\n$`),
			},
		},
		{
			name: "color",
			opts: []LoggerOption{
				WithFormatter("color"),
			},
			infoMessage: "It's starting to look like a triple rainbow.",
			regexps: []*regexp.Regexp{
				regexp.MustCompile("^\x1b\\[36mINFO\x1b\\[0m\\[0000\\] It's starting to look like a triple rainbow."),
			},
		},
		{
			name: "timezone-utc-plus-12",
			opts: []LoggerOption{
				WithTimezone(time.FixedZone("UTC+12", 12*60*60)),
			},
			infoMessage: "test",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=[^ ]+\+12:00.*level=info.*msg=test\n$`),
			},
		},
		{
			name: "timezone-utc-plus-zero",
			opts: []LoggerOption{
				WithTimezone(time.UTC),
			},
			infoMessage: "test",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`^time=[^ ]+Z.*level=info.*msg=test\n$`),
			},
		},
		{
			name: "two-formatters",
			opts: []LoggerOption{
				WithTimezone(time.FixedZone("UTC-12", -12*60*60)),
				WithFormatter("json"),
			},
			infoMessage: "test",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(`"time":"[^"]+-12:00"`),
				regexp.MustCompile(`"msg":"test"`),
			},
		},
		{
			name: "timestamp-format-default-formatter-and-default-layout",
			opts: []LoggerOption{
				WithTimezone(time.UTC), // using a fixed timezone for portable/reproducible tests
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("^time=\"%sZ\"", rfc3339baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-default-formatter-and-iso8601-layout",
			opts: []LoggerOption{
				WithTimezone(time.UTC),
			},
			envVars:     map[string]string{iso8601TimestampEnvKey: ""},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("^time=\"%sZ\"", iso8601baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-json-formatter-and-default-layout",
			opts: []LoggerOption{
				WithFormatter("json"),
				WithTimezone(time.UTC),
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("\"time\":\"%sZ\"", rfc3339baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-json-formatter-and-iso8601-layout",
			opts: []LoggerOption{
				WithFormatter("json"),
				WithTimezone(time.UTC),
			},
			envVars:     map[string]string{iso8601TimestampEnvKey: ""},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("\"time\":\"%sZ\"", iso8601baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-text-formatter-and-default-layout",
			opts: []LoggerOption{
				WithFormatter("text"),
				WithTimezone(time.UTC),
			},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("^time=\"%sZ\"", rfc3339baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-text-formatter-and-iso8601-layout",
			opts: []LoggerOption{
				WithFormatter("text"),
				WithTimezone(time.UTC),
			},
			envVars:     map[string]string{iso8601TimestampEnvKey: ""},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("^time=\"%sZ\"", iso8601baseTimestampPattern)),
			},
		},
		{
			name: "timestamp-format-iso8601-layout-and-timezone-offset",
			opts: []LoggerOption{
				WithTimezone(time.FixedZone("UTC+12", 12*60*60)),
			},
			envVars:     map[string]string{iso8601TimestampEnvKey: ""},
			infoMessage: "Hello",
			regexps: []*regexp.Regexp{
				regexp.MustCompile(fmt.Sprintf("^time=\"%s\\+12:00\"", iso8601baseTimestampPattern)),
			},
		},
	}

	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			var buf bytes.Buffer

			opts := append([]LoggerOption{}, tt.opts...)
			opts = append(opts, WithWriter(&buf))

			backupAndSetEnvVars(t, tt.envVars)

			closer, err := Initialize(opts...)
			defer closer.Close()

			if tt.infoMessage != "" {
				logrus.Info(tt.infoMessage)
			}

			if tt.debugMessage != "" {
				logrus.Debug(tt.debugMessage)
			}

			if tt.wantErr {
				require.Error(t, err)
			} else {
				require.NoError(t, err)
			}

			bytes := buf.Bytes()
			for _, re := range tt.regexps {
				require.Regexp(t, re, string(bytes))
			}
		})
	}
}

func backupAndSetEnvVars(t *testing.T, vars map[string]string) {
	t.Helper()

	// backup any env vars and override them for the duration of t
	bkpSetEnvVars := make(map[string]string)
	var bkpUnsetEnvVars []string
	for k := range vars {
		v, exists := os.LookupEnv(k)
		if exists {
			bkpSetEnvVars[k] = v
		} else {
			bkpUnsetEnvVars = append(bkpUnsetEnvVars, k)
		}
		require.NoError(t, os.Setenv(k, v))
	}

	// restore any env vars at the end of t
	t.Cleanup(func() {
		for k, v := range bkpSetEnvVars {
			require.NoError(t, os.Setenv(k, v))
		}
		for _, k := range bkpUnsetEnvVars {
			require.NoError(t, os.Unsetenv(k))
		}
	})
}