From 0da8bef69edd987cd7135f75252c942bd61e6046 Mon Sep 17 00:00:00 2001 From: Googol Lee Date: Sat, 7 Jun 2025 17:11:50 +0200 Subject: [PATCH] Update log for passing attrs with context. (#1216) * Update log for passing attrs with context. * Check type-casting * add tests. * Use t.Cleanup() to restore the global value. * Fix error. * Update tests. * Add comments. * Remove cover.cov * Update doc. * Update git ignore. --- .gitignore | 1 + api/log/context.go | 41 ++++++++ api/log/context_test.go | 98 +++++++++++++++++++ api/log/default.go | 56 +++-------- .../executable_worker/executable_worker.go | 4 +- .../executable_worker/ffmpeg_cli.go | 8 +- .../executable_worker/magickwand.go | 2 +- api/scanner/media_type/magic.go | 6 +- 8 files changed, 162 insertions(+), 54 deletions(-) create mode 100644 api/log/context.go create mode 100644 api/log/context_test.go diff --git a/.gitignore b/.gitignore index a3ecfa14..2165aee3 100644 --- a/.gitignore +++ b/.gitignore @@ -23,6 +23,7 @@ node_modules/ /ui/coverage /api/coverage.txt /api/test-*-report.xml +*.cov # building .cache/ diff --git a/api/log/context.go b/api/log/context.go new file mode 100644 index 00000000..a6c24ec7 --- /dev/null +++ b/api/log/context.go @@ -0,0 +1,41 @@ +package log + +import ( + "context" + "log/slog" +) + +var defaultLogger *slog.Logger + +func init() { + defaultLogger = slog.Default() +} + +type loggerKeyType string + +const loggerKey loggerKeyType = "logger" + +func getLogger(ctx context.Context) *slog.Logger { + if ctx == nil { + return defaultLogger + } + + logger := ctx.Value(loggerKey) + if logger == nil { + return defaultLogger + } + + ret, ok := logger.(*slog.Logger) + if !ok { + return defaultLogger + } + + return ret +} + +// WithAttrs creates a new context containing a new logger with [args] as logging attributes. +func WithAttrs(ctx context.Context, args ...any) context.Context { + old := getLogger(ctx) + new := old.With(args...) + return context.WithValue(ctx, loggerKey, new) +} diff --git a/api/log/context_test.go b/api/log/context_test.go new file mode 100644 index 00000000..05e769ca --- /dev/null +++ b/api/log/context_test.go @@ -0,0 +1,98 @@ +package log + +import ( + "bytes" + "context" + "flag" + "log/slog" + "testing" + + "github.com/google/go-cmp/cmp" +) + +func init() { + // Avoid panic with providing flags in `test_utils/integration_setup.go`. + flag.CommandLine.Init("executable_worker", flag.ContinueOnError) +} + +func mockDefaultLogger(t *testing.T) *bytes.Buffer { + t.Helper() + + var output bytes.Buffer + handler := slog.NewJSONHandler(&output, &slog.HandlerOptions{ + AddSource: false, + Level: slog.LevelInfo, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + // Remove time from the output for predictable test output. + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }) + + logger := slog.New(handler) + oldLogger := defaultLogger + defaultLogger = logger + + t.Cleanup(func() { + defaultLogger = oldLogger + }) + + return &output +} + +func TestLogger(t *testing.T) { + output := mockDefaultLogger(t) + + Debug(nil, "no_context") + Info(nil, "no_context") + Warn(nil, "no_context") + Error(nil, "no_context") + + bg := context.Background() + + Debug(bg, "bg_context") + Info(bg, "bg_context") + Warn(bg, "bg_context") + Error(bg, "bg_context") + + ctx1 := WithAttrs(context.Background(), "arg1", "value") + Debug(ctx1, "with_context_1") + Info(ctx1, "with_context_1") + Warn(ctx1, "with_context_1") + Error(ctx1, "with_context_1") + + ctx2 := WithAttrs(ctx1, "arg2", "value") + Debug(ctx2, "with_context_2") + Info(ctx2, "with_context_2") + Warn(ctx2, "with_context_2") + Error(ctx2, "with_context_2") + + Debug(ctx1, "with_context_1") + Info(ctx1, "with_context_1") + Warn(ctx1, "with_context_1") + Error(ctx1, "with_context_1") + + // Debug messages are filtered out due to slog.LevelInfo in mock logger + want := `{"level":"INFO","msg":"no_context"} +{"level":"WARN","msg":"no_context"} +{"level":"ERROR","msg":"no_context"} +{"level":"INFO","msg":"bg_context"} +{"level":"WARN","msg":"bg_context"} +{"level":"ERROR","msg":"bg_context"} +{"level":"INFO","msg":"with_context_1","arg1":"value"} +{"level":"WARN","msg":"with_context_1","arg1":"value"} +{"level":"ERROR","msg":"with_context_1","arg1":"value"} +{"level":"INFO","msg":"with_context_2","arg1":"value","arg2":"value"} +{"level":"WARN","msg":"with_context_2","arg1":"value","arg2":"value"} +{"level":"ERROR","msg":"with_context_2","arg1":"value","arg2":"value"} +{"level":"INFO","msg":"with_context_1","arg1":"value"} +{"level":"WARN","msg":"with_context_1","arg1":"value"} +{"level":"ERROR","msg":"with_context_1","arg1":"value"} +` + if diff := cmp.Diff(output.String(), want); diff != "" { + t.Errorf("diff: (-got, +want)\n%s", diff) + } + +} diff --git a/api/log/default.go b/api/log/default.go index 1810f087..b19f9bfb 100644 --- a/api/log/default.go +++ b/api/log/default.go @@ -2,56 +2,24 @@ package log import ( "context" - "log/slog" ) -var defaultLogger *slog.Logger - -func init() { - defaultLogger = slog.Default() +// Debug logs debug messages. +func Debug(ctx context.Context, msg string, args ...any) { + getLogger(ctx).DebugContext(ctx, msg, args...) } -// Debug calls [Logger.Debug] on the default logger. -func Debug(msg string, args ...any) { - defaultLogger.Debug(msg, args...) +// Info logs info messages. +func Info(ctx context.Context, msg string, args ...any) { + getLogger(ctx).InfoContext(ctx, msg, args...) } -// DebugContext calls [Logger.DebugContext] on the default logger. -func DebugContext(ctx context.Context, msg string, args ...any) { - defaultLogger.DebugContext(ctx, msg, args...) +// Warn logs warning messages. +func Warn(ctx context.Context, msg string, args ...any) { + getLogger(ctx).WarnContext(ctx, msg, args...) } -// Info calls [Logger.Info] on the default logger. -func Info(msg string, args ...any) { - defaultLogger.Info(msg, args...) -} - -// InfoContext calls [Logger.InfoContext] on the default logger. -func InfoContext(ctx context.Context, msg string, args ...any) { - defaultLogger.InfoContext(ctx, msg, args...) -} - -// Warn calls [Logger.Warn] on the default logger. -func Warn(msg string, args ...any) { - defaultLogger.Warn(msg, args...) -} - -// WarnContext calls [Logger.WarnContext] on the default logger. -func WarnContext(ctx context.Context, msg string, args ...any) { - defaultLogger.WarnContext(ctx, msg, args...) -} - -// Error calls [Logger.Error] on the default logger. -func Error(msg string, args ...any) { - defaultLogger.Error(msg, args...) -} - -// ErrorContext calls [Logger.ErrorContext] on the default logger. -func ErrorContext(ctx context.Context, msg string, args ...any) { - defaultLogger.ErrorContext(ctx, msg, args...) -} - -// With calls [Logger.With] on the default logger. -func With(args ...any) *slog.Logger { - return defaultLogger.With(args...) +// Error logs error messages. +func Error(ctx context.Context, msg string, args ...any) { + getLogger(ctx).ErrorContext(ctx, msg, args...) } diff --git a/api/scanner/media_encoding/executable_worker/executable_worker.go b/api/scanner/media_encoding/executable_worker/executable_worker.go index b390cec7..e1241e4f 100644 --- a/api/scanner/media_encoding/executable_worker/executable_worker.go +++ b/api/scanner/media_encoding/executable_worker/executable_worker.go @@ -19,7 +19,7 @@ func Initialize() func() { Ffmpeg = newFfmpegCli() if err := SetFfprobePath(); err != nil { - log.Error("Init ffprobe fail.", "error", err) + log.Error(nil, "Init ffprobe fail.", "error", err) } return func() { @@ -46,7 +46,7 @@ func SetFfprobePath() error { return fmt.Errorf("Executable ffprobe(%q) not executable: %w", path, err) } - log.Info("Found ffprobe", "path", path, "version", strings.Split(string(version), "\n")[0]) + log.Info(nil, "Found ffprobe", "path", path, "version", strings.Split(string(version), "\n")[0]) ffprobe.SetFFProbeBinPath(path) return nil diff --git a/api/scanner/media_encoding/executable_worker/ffmpeg_cli.go b/api/scanner/media_encoding/executable_worker/ffmpeg_cli.go index b08ee2ea..8ad3c77e 100644 --- a/api/scanner/media_encoding/executable_worker/ffmpeg_cli.go +++ b/api/scanner/media_encoding/executable_worker/ffmpeg_cli.go @@ -26,7 +26,7 @@ type FfmpegCli struct { func newFfmpegCli() *FfmpegCli { if utils.EnvDisableVideoEncoding.GetBool() { - log.Warn("Executable ffmpeg worker disabled", utils.EnvDisableVideoEncoding.GetName(), utils.EnvDisableVideoEncoding.GetValue()) + log.Warn(nil, "Executable ffmpeg worker disabled", utils.EnvDisableVideoEncoding.GetName(), utils.EnvDisableVideoEncoding.GetValue()) return &FfmpegCli{ err: ErrDisabledFunction, } @@ -34,7 +34,7 @@ func newFfmpegCli() *FfmpegCli { path, err := exec.LookPath("ffmpeg") if err != nil { - log.Error("Executable ffmpeg worker not found") + log.Error(nil, "Executable ffmpeg worker not found") return &FfmpegCli{ err: ErrNoDependency, } @@ -42,7 +42,7 @@ func newFfmpegCli() *FfmpegCli { version, err := exec.Command(path, "-version").Output() if err != nil { - log.Error("Executable ffmpeg worker getting version error", "error", err) + log.Error(nil, "Executable ffmpeg worker getting version error", "error", err) return &FfmpegCli{ err: ErrNoDependency, } @@ -59,7 +59,7 @@ func newFfmpegCli() *FfmpegCli { } } - log.Info("Found executable worker: ffmpeg", "version", strings.Split(string(version), "\n")[0], "codec", codec) + log.Info(nil, "Found executable worker: ffmpeg", "version", strings.Split(string(version), "\n")[0], "codec", codec) return &FfmpegCli{ path: path, diff --git a/api/scanner/media_encoding/executable_worker/magickwand.go b/api/scanner/media_encoding/executable_worker/magickwand.go index 8624c1a8..249b4ef3 100644 --- a/api/scanner/media_encoding/executable_worker/magickwand.go +++ b/api/scanner/media_encoding/executable_worker/magickwand.go @@ -16,7 +16,7 @@ func newMagickWand() *MagickWand { verstr, vernum := imagick.GetVersion() - log.Info("Found magickwand worker: "+verstr, "version", vernum) + log.Info(nil, "Found magickwand worker: "+verstr, "version", vernum) return &MagickWand{ initialized: true, diff --git a/api/scanner/media_type/magic.go b/api/scanner/media_type/magic.go index 191fded0..925b685c 100644 --- a/api/scanner/media_type/magic.go +++ b/api/scanner/media_type/magic.go @@ -18,7 +18,7 @@ func init() { libmagic.libmagic, libmagic.err = newLibMagic() if libmagic.err != nil { libmagic.libmagic = nil - log.Error("Init libmagic error.", "error", libmagic.err) + log.Error(nil, "Init libmagic error.", "error", libmagic.err) } } @@ -29,13 +29,13 @@ func GetMediaType(f string) MediaType { defer libmagic.mu.Unlock() if libmagic.err != nil { - log.Warn("GetMediaType() error.", "error", libmagic.err, "file", f) + log.Warn(nil, "GetMediaType() error.", "error", libmagic.err, "file", f) return TypeUnknown } mime, err := libmagic.libmagic.Type(f) if err != nil { - log.Warn("GetMediaType() error.", "error", err, "file", f) + log.Warn(nil, "GetMediaType() error.", "error", err, "file", f) return TypeUnknown }