diff --git a/pkg/log/core.go b/pkg/log/core.go new file mode 100644 index 000000000..49a961c8c --- /dev/null +++ b/pkg/log/core.go @@ -0,0 +1,41 @@ +package log + +import ( + "go.uber.org/zap/zapcore" +) + +type levelFilterCore struct { + core zapcore.Core + level zapcore.LevelEnabler +} + +// NewLevelCore creates a core that can be used to independently control the +// level of an existing Core. This is essentially a filter that will only log +// if both the parent and the wrapper cores are enabled. +func NewLevelCore(core zapcore.Core, level zapcore.LevelEnabler) zapcore.Core { + return &levelFilterCore{core, level} +} + +func (c *levelFilterCore) Enabled(lvl zapcore.Level) bool { + return c.level.Enabled(lvl) +} + +func (c *levelFilterCore) With(fields []zapcore.Field) zapcore.Core { + return &levelFilterCore{c.core.With(fields), c.level} +} + +func (c *levelFilterCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if !c.Enabled(ent.Level) { + return ce + } + + return c.core.Check(ent, ce) +} + +func (c *levelFilterCore) Write(ent zapcore.Entry, fields []zapcore.Field) error { + return c.core.Write(ent, fields) +} + +func (c *levelFilterCore) Sync() error { + return c.core.Sync() +} diff --git a/pkg/log/level.go b/pkg/log/level.go new file mode 100644 index 000000000..cc8f8d433 --- /dev/null +++ b/pkg/log/level.go @@ -0,0 +1,114 @@ +package log + +import ( + "sort" + "sync" + + "github.com/go-logr/logr" + "github.com/go-logr/zapr" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// TODO: Use a struct to make testing easier. +var ( + // Global, default log level control. + globalLogLevel levelSetter = zap.NewAtomicLevel() + + // Map of name -> level control for independently setting log levels. A new + // control is registered via WithNamedLevel. This map is never cleaned up + // and new entries will overwrite previous values. Currently, this is + // acceptable behavior because WithNamedLevel is used sparingly. + globalControls map[string]levelSetter = make(map[string]levelSetter, 16) + // globalControls is protected (both read and write) by a mutex to make it + // thread safe. Access is low frequency, so performance is not a concern. + globalControlsLock sync.Mutex +) + +type levelSetter interface { + zapcore.LevelEnabler + SetLevel(zapcore.Level) + Level() zapcore.Level +} + +// SetLevel sets the log level for loggers created with the default level +// controller. +func SetLevel(level int8) { + SetLevelForControl(globalLogLevel, level) +} + +// SetLevelForControl sets the log level for a given control. +func SetLevelForControl(control levelSetter, level int8) { + // Zap's levels get more verbose as the number gets smaller, as explained + // by zapr here: https://github.com/go-logr/zapr#increasing-verbosity + // For example setting the level to -2 below, means log.V(2) will be enabled. + control.SetLevel(zapcore.Level(-level)) +} + +// SetLevelFor sets the log level for a given named control. +func SetLevelFor(name string, level int8) { + globalControlsLock.Lock() + defer globalControlsLock.Unlock() + if control, ok := globalControls[name]; ok { + SetLevelForControl(control, level) + return + } + // Create a new control so registering a control with the same name will + // inherit the existing level. + globalControls[name] = newAtomicLevelAt(level) +} + +// AddLeveler adds a log level control to a logr.Logger. +func AddLeveler(l logr.Logger, control levelSetter) (logr.Logger, error) { + zapLogger, err := getZapLogger(l) + if err != nil { + return l, err + } + + zapLogger = zapLogger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { + return NewLevelCore(core, control) + })) + return zapr.NewLogger(zapLogger), nil +} + +// WithNamedLevel creates a child logger with a new name and independent log +// level control (see SetLevelFor). NOTE: if name already exists, the existing +// controller will be used, otherwise a new controller is created with level +// matching the parent's log level. +func WithNamedLevel(logger logr.Logger, name string) logr.Logger { + logger = logger.WithName(name) + + globalControlsLock.Lock() + defer globalControlsLock.Unlock() + + var leveler levelSetter + if currentControl, ok := globalControls[name]; ok { + leveler = currentControl + } else { + leveler = newAtomicLevelAt(findLevel(logger)) + globalControls[name] = leveler + } + newLogger, err := AddLeveler(logger, leveler) + if err != nil { + return logger + } + return newLogger +} + +// newAtomicLevelAt is a helper function to create a zap.AtomicLevel +// initialized with a level. We cannot use zap.NewAtomicLevelAt here because of +// a quirk with logr levels (see SetLevelForControl). +func newAtomicLevelAt(level int8) zap.AtomicLevel { + control := zap.NewAtomicLevel() + SetLevelForControl(control, level) + return control +} + +// findLevel probes a logr.Logger to figure out what level it is at via binary +// search. We only search [0, 128), so worst case is ~7 checks. +func findLevel(logger logr.Logger) int8 { + sink := logger.GetSink() + return int8(sort.Search(128, func(i int) bool { + return !sink.Enabled(i) + }) - 1) +} diff --git a/pkg/log/log.go b/pkg/log/log.go index 93fd4e4b3..41fbcae08 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -2,6 +2,7 @@ package log import ( "errors" + "fmt" "io" "time" @@ -13,11 +14,6 @@ import ( "go.uber.org/zap/zapcore" ) -var ( - // global log level control (see SetLevel) - logLevel zap.AtomicLevel = zap.NewAtomicLevel() -) - type logConfig struct { core zapcore.Core cleanup func() error @@ -56,15 +52,6 @@ func New(service string, configs ...logConfig) (logr.Logger, func() error) { return logger, firstErrorFunc(cleanupFuncs...) } -// SetLevel sets the log level for all loggers created with WithJSONSink and -// WithConsoleSink. -func SetLevel(level int8) { - // Zap's levels get more verbose as the number gets smaller, as explained - // by zapr here: https://github.com/go-logr/zapr#increasing-verbosity - // For example setting the level to -2 below, means log.V(2) will be enabled. - logLevel.SetLevel(zapcore.Level(-level)) -} - // WithSentry adds sentry integration to the logger. This configuration may // fail, in which case, sentry will not be added and execution will continue // normally. @@ -95,36 +82,43 @@ func WithSentry(opts sentry.ClientOptions, tags map[string]string) logConfig { } } +type sinkConfig struct { + encoder zapcore.Encoder + sink zapcore.WriteSyncer + level levelSetter +} + // WithJSONSink adds a JSON encoded output to the logger. -func WithJSONSink(sink io.Writer) logConfig { - return logConfig{ - core: zapcore.NewCore( - zapcore.NewJSONEncoder(defaultEncoderConfig()), - zapcore.Lock( - zapcore.AddSync(sink), - ), - logLevel, - ), - } +func WithJSONSink(sink io.Writer, opts ...func(*sinkConfig)) logConfig { + return newCoreConfig( + zapcore.NewJSONEncoder(defaultEncoderConfig()), + zapcore.Lock(zapcore.AddSync(sink)), + globalLogLevel, + opts..., + ) } // WithConsoleSink adds a console-style output to the logger. -func WithConsoleSink(sink io.Writer) logConfig { - return logConfig{ - core: zapcore.NewCore( - zapcore.NewConsoleEncoder(defaultEncoderConfig()), - zapcore.Lock( - zapcore.AddSync(sink), - ), - logLevel, - ), - } +func WithConsoleSink(sink io.Writer, opts ...func(*sinkConfig)) logConfig { + return newCoreConfig( + zapcore.NewConsoleEncoder(defaultEncoderConfig()), + zapcore.Lock(zapcore.AddSync(sink)), + globalLogLevel, + opts..., + ) } func defaultEncoderConfig() zapcore.EncoderConfig { conf := zap.NewProductionEncoderConfig() // Use more human-readable time format. conf.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339) + conf.EncodeLevel = func(level zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { + if level == zapcore.ErrorLevel { + enc.AppendString("error") + return + } + enc.AppendString(fmt.Sprintf("info-%d", -int8(level))) + } return conf } @@ -136,16 +130,15 @@ func WithCore(core zapcore.Core) logConfig { // AddSentry initializes a sentry client and extends an existing // logr.Logger with the hook. func AddSentry(l logr.Logger, opts sentry.ClientOptions, tags map[string]string) (logr.Logger, func() error, error) { - conf := WithSentry(opts, tags) - if conf.err != nil { - return l, nil, conf.err - } - return AddSink(l, conf) + return AddSink(l, WithSentry(opts, tags)) } // AddSink extends an existing logr.Logger with a new sink. It returns the new // logr.Logger, a cleanup function, and an error. func AddSink(l logr.Logger, sink logConfig) (logr.Logger, func() error, error) { + if sink.err != nil { + return l, nil, sink.err + } zapLogger, err := getZapLogger(l) if err != nil { return l, nil, errors.New("unsupported logr implementation") @@ -165,6 +158,24 @@ func getZapLogger(l logr.Logger) (*zap.Logger, error) { return nil, errors.New("not a zapr logger") } +// WithLevel sets the sink's level to a static level. This option prevents +// changing the log level for this sink later on. +func WithLevel(level int8) func(*sinkConfig) { + return WithLeveler( + // Zap's levels get more verbose as the number gets smaller, as explained + // by zapr here: https://github.com/go-logr/zapr#increasing-verbosity + // For example setting the level to -2 below, means log.V(2) will be enabled. + zap.NewAtomicLevelAt(zapcore.Level(-level)), + ) +} + +// WithLeveler sets the sink's level enabler to leveler. +func WithLeveler(leveler levelSetter) func(*sinkConfig) { + return func(conf *sinkConfig) { + conf.level = leveler + } +} + // firstErrorFunc is a helper function that returns a function that executes // all provided args and returns the first error, if any. func firstErrorFunc(fs ...func() error) func() error { @@ -181,3 +192,28 @@ func firstErrorFunc(fs ...func() error) func() error { return firstErr } } + +// newCoreConfig is a helper function that creates a default sinkConfig, +// applies the options, then creates a zapcore.Core. +func newCoreConfig( + defaultEncoder zapcore.Encoder, + defaultSink zapcore.WriteSyncer, + defaultLevel levelSetter, + opts ...func(*sinkConfig), +) logConfig { + conf := sinkConfig{ + encoder: defaultEncoder, + sink: defaultSink, + level: defaultLevel, + } + for _, f := range opts { + f(&conf) + } + return logConfig{ + core: zapcore.NewCore( + conf.encoder, + conf.sink, + conf.level, + ), + } +} diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index f5a356314..65593b789 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -2,33 +2,52 @@ package log import ( "bytes" + "encoding/json" + "fmt" + "io" + "sort" "strings" + "sync" "testing" "time" "github.com/getsentry/sentry-go" + "github.com/go-logr/logr" "github.com/stretchr/testify/assert" + "go.uber.org/zap" ) func TestNew(t *testing.T) { var jsonBuffer, consoleBuffer bytes.Buffer - logger, sync := New("service-name", + logger, flush := New("service-name", WithJSONSink(&jsonBuffer), WithConsoleSink(&consoleBuffer), ) logger.Info("yay") - assert.Nil(t, sync()) + assert.Nil(t, flush()) - assert.Contains(t, jsonBuffer.String(), `"logger":"service-name"`) - assert.Contains(t, jsonBuffer.String(), `"msg":"yay"`) - assert.Contains(t, consoleBuffer.String(), "info\tservice-name\tyay") + var parsedJSON map[string]any + assert.Nil(t, json.Unmarshal(jsonBuffer.Bytes(), &parsedJSON)) + assert.NotEmpty(t, parsedJSON["ts"]) + delete(parsedJSON, "ts") + assert.Equal(t, + map[string]any{ + "level": "info-0", + "logger": "service-name", + "msg": "yay", + }, + parsedJSON, + ) + assert.Equal(t, + []string{"info-0\tservice-name\tyay"}, + splitLines(consoleBuffer.String()), + ) } func TestSetLevel(t *testing.T) { var buffer bytes.Buffer - logger, _ := New("service-name", - WithConsoleSink(&buffer), - ) + defer SetLevel(0) + logger, _ := New("service-name", WithConsoleSink(&buffer)) assert.Equal(t, true, logger.GetSink().Enabled(0)) assert.Equal(t, false, logger.GetSink().Enabled(1)) @@ -47,12 +66,12 @@ func TestSetLevel(t *testing.T) { func TestWithSentryFailure(t *testing.T) { var buffer bytes.Buffer - logger, sync := New("service-name", + logger, flush := New("service-name", WithSentry(sentry.ClientOptions{Dsn: "fail"}, nil), WithConsoleSink(&buffer), ) logger.Info("yay") - assert.Nil(t, sync()) + assert.Nil(t, flush()) assert.Contains(t, buffer.String(), "error configuring logger") assert.Contains(t, buffer.String(), "yay") @@ -60,15 +79,13 @@ func TestWithSentryFailure(t *testing.T) { func TestAddSentryFailure(t *testing.T) { var buffer bytes.Buffer - logger, sync := New("service-name", - WithConsoleSink(&buffer), - ) + logger, flush := New("service-name", WithConsoleSink(&buffer)) logger, _, err := AddSentry(logger, sentry.ClientOptions{Dsn: "fail"}, nil) assert.NotNil(t, err) assert.NotContains(t, err.Error(), "unsupported") logger.Info("yay") - assert.Nil(t, sync()) + assert.Nil(t, flush()) assert.Contains(t, buffer.String(), "yay") } @@ -76,10 +93,8 @@ func TestAddSentryFailure(t *testing.T) { func TestAddSentry(t *testing.T) { var buffer bytes.Buffer var sentryMessage string - logger, _ := New("service-name", - WithConsoleSink(&buffer), - ) - logger, sync, err := AddSentry(logger, sentry.ClientOptions{ + logger, _ := New("service-name", WithConsoleSink(&buffer)) + logger, flush, err := AddSentry(logger, sentry.ClientOptions{ BeforeSend: func(event *sentry.Event, hint *sentry.EventHint) *sentry.Event { sentryMessage = event.Message return nil @@ -87,19 +102,19 @@ func TestAddSentry(t *testing.T) { }, nil) assert.Nil(t, err) - logger.Info("yay") logger.Error(nil, "oops") - assert.Nil(t, sync()) + logger.Info("yay") + assert.Nil(t, flush()) - assert.Contains(t, buffer.String(), "yay") assert.Contains(t, buffer.String(), "oops") + assert.Contains(t, buffer.String(), "yay") assert.Equal(t, "oops", sentryMessage) } func TestWithSentry(t *testing.T) { var buffer bytes.Buffer var sentryMessage string - logger, sync := New("service-name", + logger, flush := New("service-name", WithConsoleSink(&buffer), WithSentry(sentry.ClientOptions{ BeforeSend: func(event *sentry.Event, hint *sentry.EventHint) *sentry.Event { @@ -110,7 +125,7 @@ func TestWithSentry(t *testing.T) { ) logger.Info("yay") logger.Error(nil, "oops") - assert.Nil(t, sync()) + assert.Nil(t, flush()) assert.Contains(t, buffer.String(), "yay") assert.Contains(t, buffer.String(), "oops") @@ -119,11 +134,11 @@ func TestWithSentry(t *testing.T) { func TestHumanReadableTimestamp(t *testing.T) { var buffer bytes.Buffer - logger, sync := New("service-name", + logger, flush := New("service-name", WithConsoleSink(&buffer), ) logger.Info("yay") - assert.Nil(t, sync()) + assert.Nil(t, flush()) ts := strings.Split(buffer.String(), "\t")[0] assert.NotContains(t, ts, "e+09") @@ -139,10 +154,10 @@ func TestAddSink(t *testing.T) { WithConsoleSink(&buf1), ) logger.Info("line 1") - logger, sync, err := AddSink(logger, WithConsoleSink(&buf2)) + logger, flush, err := AddSink(logger, WithConsoleSink(&buf2)) assert.Nil(t, err) logger.Info("line 2") - assert.Nil(t, sync()) + assert.Nil(t, flush()) assert.Contains(t, buf1.String(), "line 1") assert.Contains(t, buf1.String(), "line 2") @@ -150,3 +165,384 @@ func TestAddSink(t *testing.T) { assert.NotContains(t, buf2.String(), "line 1") assert.Contains(t, buf2.String(), "line 2") } + +func TestStaticLevelSink(t *testing.T) { + var buf1, buf2 bytes.Buffer + l1 := zap.NewAtomicLevel() + logger, flush := New( + "service-name", + WithConsoleSink(&buf1, WithLeveler(l1)), + WithConsoleSink(&buf2, WithLevel(0)), + ) + + logger.Info("line 1") + SetLevelForControl(l1, 1) + logger.V(1).Info("line 2") + assert.Nil(t, flush()) + + // buf1 should have both lines + assert.Contains(t, buf1.String(), "line 1") + assert.Contains(t, buf1.String(), "line 2") + + // buf2 should only have "line 1" + assert.Contains(t, buf2.String(), "line 1") + assert.NotContains(t, buf2.String(), "line 2") +} + +func TestWithLeveler(t *testing.T) { + var buf1, buf2 bytes.Buffer + l1, l2 := zap.NewAtomicLevel(), zap.NewAtomicLevel() + logger, flush := New( + "service-name", + WithConsoleSink(&buf1, WithLeveler(l1)), + WithConsoleSink(&buf2, WithLeveler(l2)), + ) + + SetLevelForControl(l1, 1) + SetLevelForControl(l2, 2) + + logger.V(0).Info("line 1") + logger.V(1).Info("line 2") + logger.V(2).Info("line 3") + assert.Nil(t, flush()) + + // buf1 should have lines 1 and 2 + assert.Contains(t, buf1.String(), "line 1") + assert.Contains(t, buf1.String(), "line 2") + assert.NotContains(t, buf1.String(), "line 3") + + // buf2 should have all lines + assert.Contains(t, buf2.String(), "line 1") + assert.Contains(t, buf2.String(), "line 2") + assert.Contains(t, buf2.String(), "line 3") +} + +func TestWithNamedLevelMoreVerbose(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + l1 := zap.NewAtomicLevel() + logger, flush := New( + "service-name", + WithConsoleSink(&buf, WithLeveler(l1)), + ) + + childLogger := WithNamedLevel(logger, "child") + + SetLevelForControl(l1, 1) + SetLevelFor("child", 2) + + logger.V(0).Info("line 1") + logger.V(1).Info("line 2") + logger.V(2).Info("line 3") + childLogger.V(0).Info("line A") + childLogger.V(1).Info("line B") + childLogger.V(2).Info("line C") + assert.Nil(t, flush()) + + // output should contain up to verbosity 1 + assert.Equal(t, []string{ + "info-0\tservice-name\tline 1", + "info-1\tservice-name\tline 2", + "info-0\tservice-name.child\tline A", + "info-1\tservice-name.child\tline B", + }, splitLines(buf.String())) +} + +func TestWithNamedLevelLessVerbose(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + l1 := zap.NewAtomicLevel() + logger, flush := New( + "service-name", + WithConsoleSink(&buf, WithLeveler(l1)), + ) + + childLogger := WithNamedLevel(logger, "child") + + SetLevelForControl(l1, 1) + SetLevelFor("child", 0) + + logger.V(0).Info("line 1") + logger.V(1).Info("line 2") + logger.V(2).Info("line 3") + childLogger.V(0).Info("line A") + childLogger.V(1).Info("line B") + childLogger.V(2).Info("line C") + assert.Nil(t, flush()) + + // output should contain up to verbosity 1 for parent + // and verbosity 0 for child + assert.Equal(t, []string{ + "info-0\tservice-name\tline 1", + "info-1\tservice-name\tline 2", + "info-0\tservice-name.child\tline A", + }, splitLines(buf.String())) +} + +func TestNestedWithNamedLevel(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + grandParent, flush := New("grandParent", WithConsoleSink(&buf, WithLevel(1))) + parent := WithNamedLevel(grandParent, "parent") + child := WithNamedLevel(parent, "child") + + SetLevelFor("parent", 0) + SetLevelFor("child", 2) + + grandParent.V(0).Info("line 1") + parent.V(0).Info("line 2") + child.V(0).Info("line 3") + + grandParent.V(1).Info("line 4") + parent.V(1).Info("line 5") + child.V(1).Info("line 6") + + grandParent.V(2).Info("line 7") + parent.V(2).Info("line 8") + child.V(2).Info("line 9") + + assert.Nil(t, flush()) + + lines := splitLines(buf.String()) + assert.Equal(t, 4, len(lines)) + + assert.Equal(t, `info-0 grandParent line 1`, lines[0]) + assert.Equal(t, `info-0 grandParent.parent line 2`, lines[1]) + assert.Equal(t, `info-0 grandParent.parent.child line 3`, lines[2]) + assert.Equal(t, `info-1 grandParent line 4`, lines[3]) +} + +func TestSiblingsWithNamedLevel(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New("parent", WithConsoleSink(&buf, WithLevel(1))) + alice := WithNamedLevel(parent, "alice") + bob := WithNamedLevel(parent, "bob") + + SetLevelFor("alice", 0) + SetLevelFor("bob", 2) + + parent.V(0).Info("line 1") + alice.V(0).Info("line 2") + bob.V(0).Info("line 3") + + parent.V(1).Info("line 4") + alice.V(1).Info("line 5") + bob.V(1).Info("line 6") + + parent.V(2).Info("line 7") + alice.V(2).Info("line 8") + bob.V(2).Info("line 9") + + assert.Nil(t, flush()) + lines := splitLines(buf.String()) + assert.Equal(t, 5, len(lines)) + + assert.Equal(t, `info-0 parent line 1`, lines[0]) + assert.Equal(t, `info-0 parent.alice line 2`, lines[1]) + assert.Equal(t, `info-0 parent.bob line 3`, lines[2]) + assert.Equal(t, `info-1 parent line 4`, lines[3]) + assert.Equal(t, `info-1 parent.bob line 6`, lines[4]) +} + +func TestWithNamedLevelConcurrency(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New("parent", WithConsoleSink(&buf)) + + alice := WithNamedLevel(parent, "alice") + bob := WithNamedLevel(parent, "bob") + + var wg sync.WaitGroup + f := func(logger logr.Logger) { + defer wg.Done() + for i := 0; i < 100_000; i++ { + logger.Info(fmt.Sprintf("%06d", i)) + } + } + wg.Add(3) + go f(parent) + go f(alice) + go f(bob) + wg.Wait() + + assert.Nil(t, flush()) + logLines := splitLines(buf.String()) + assert.Equal(t, 300_000, len(logLines)) + sort.Slice(logLines, func(i, j int) bool { + return logLines[i] < logLines[j] + }) + + for i := 0; i < 100_000; i++ { + assert.Equal(t, fmt.Sprintf("info-0\tparent\t%06d", i), logLines[i]) + assert.Equal(t, fmt.Sprintf("info-0\tparent.alice\t%06d", i), logLines[i+100_000]) + assert.Equal(t, fmt.Sprintf("info-0\tparent.bob\t%06d", i), logLines[i+200_000]) + } +} + +func TestWithNamedLevelInheritance(t *testing.T) { + t.Run("child inherits parent level", func(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New("parent", WithConsoleSink(&buf, WithLevel(2))) + parent = parent.WithValues("key", "value") + // child will inherit parent's log level 2 + child := WithNamedLevel(parent, "child") + + parent.V(2).Info("yay") + child.V(2).Info("yay again") + assert.Nil(t, flush()) + + logLines := splitLines(buf.String()) + assert.Equal(t, []string{ + `info-2 parent yay {"key": "value"}`, + `info-2 parent.child yay again {"key": "value"}`, + }, logLines) + }) + + t.Run("child inherits existing named level", func(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New("parent", WithConsoleSink(&buf, WithLevel(2))) + parent = parent.WithValues("key", "value") + SetLevelFor("child", 0) + // child will inherit existing named level 0 + child := WithNamedLevel(parent, "child") + + parent.V(2).Info("yay") + child.V(2).Info("yay again") + assert.Nil(t, flush()) + + logLines := splitLines(buf.String()) + assert.Equal(t, []string{`info-2 parent yay {"key": "value"}`}, logLines) + }) +} + +func TestExistingChildLevel(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New("parent", WithConsoleSink(&buf, WithLevel(2))) + + SetLevelFor("child", 2) + // child should start with a level of 2 due to SetLevelFor above + child := WithNamedLevel(parent, "child") + + parent.V(2).Info("yay") + child.V(2).Info("yay again") + assert.Nil(t, flush()) + + assert.Contains(t, buf.String(), "info-2\tparent\tyay") + assert.Contains(t, buf.String(), "info-2\tparent.child\tyay again") +} + +func TestSinkWithNamedLevel(t *testing.T) { + var buf1, buf2 bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New( + "parent", + WithConsoleSink(&buf1, WithLevel(0)), + WithConsoleSink(&buf2, WithLevel(2)), + ) + child := WithNamedLevel(parent, "child") + + for level := 0; level < 3; level++ { + SetLevelFor("child", int8(level)) + child.Info("") + child.V(1).Info("") + child.V(2).Info("") + } + assert.Nil(t, flush()) + + // buf1 should get only level 0 logs + assert.Equal(t, []string{ + "info-0\tparent.child", + "info-0\tparent.child", + "info-0\tparent.child", + }, splitLines(buf1.String())) + + assert.Equal(t, []string{ + // child level 0 + "info-0\tparent.child", + // child level 1 + "info-0\tparent.child", + "info-1\tparent.child", + // child level 2 + "info-0\tparent.child", + "info-1\tparent.child", + "info-2\tparent.child", + }, splitLines(buf2.String())) +} + +func TestAddLeveler(t *testing.T) { + l1, l2 := zap.NewAtomicLevel(), zap.NewAtomicLevel() + logger, _ := New("parent", WithConsoleSink(io.Discard, WithLeveler(l1))) + + t.Run("child level more verbose", func(t *testing.T) { + l1.SetLevel(0) + l2.SetLevel(1) + _, err := AddLeveler(logger, l2) + assert.Nil(t, err) + }) + + t.Run("child level less verbose", func(t *testing.T) { + l1.SetLevel(1) + l2.SetLevel(0) + _, err := AddLeveler(logger, l2) + assert.Nil(t, err) + }) +} + +func splitLines(s string) []string { + lines := strings.Split(strings.TrimSpace(s), "\n") + logLines := make([]string, len(lines)) + for i, logLine := range lines { + // remove timestamp + logLines[i] = strings.TrimSpace(logLine[strings.Index(logLine, "\t")+1:]) + } + return logLines +} + +func TestFindLevel(t *testing.T) { + lvl := zap.NewAtomicLevel() + logger, _ := New("parent", WithConsoleSink(io.Discard, WithLeveler(lvl))) + + for i := 0; i < 128; i++ { + i8 := int8(i) + SetLevelForControl(lvl, i8) + assert.Equal(t, i8, findLevel(logger)) + } +} + +func TestOverwriteWithNamedLevel(t *testing.T) { + var buf bytes.Buffer + globalControls = make(map[string]levelSetter, 16) + + parent, flush := New( + "parent", + WithConsoleSink(&buf, WithLevel(2)), + ) + SetLevelFor("child", 0) + child1 := WithNamedLevel(parent, "child") + child2 := WithNamedLevel(parent, "child") + SetLevelFor("child", 2) + + child1.V(2).Info("") + child2.V(2).Info("") + + assert.Nil(t, flush()) + + // buf1 should get only level 0 logs + assert.Equal(t, []string{ + "info-2\tparent.child", + "info-2\tparent.child", + }, splitLines(buf.String())) +}