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

@@ -23,6 +23,7 @@ node_modules/
 /ui/coverage
 /api/coverage.txt
 /api/test-*-report.xml
+*.cov
 
 # building
 .cache/

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

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

api/log/default.go

@@ -2,56 +2,24 @@ package log
 
 import (
 	"context"
-	"log/slog"
 )
 
-var defaultLogger *slog.Logger
+// Debug logs debug messages.
-
+func Debug(ctx context.Context, msg string, args ...any) {
-func init() {
+	getLogger(ctx).DebugContext(ctx, msg, args...)
-	defaultLogger = slog.Default()
 }
 
-// Debug calls [Logger.Debug] on the default logger.
+// Info logs info messages.
-func Debug(msg string, args ...any) {
+func Info(ctx context.Context, msg string, args ...any) {
-	defaultLogger.Debug(msg, args...)
+	getLogger(ctx).InfoContext(ctx, msg, args...)
 }
 
-// DebugContext calls [Logger.DebugContext] on the default logger.
+// Warn logs warning messages.
-func DebugContext(ctx context.Context, msg string, args ...any) {
+func Warn(ctx context.Context, msg string, args ...any) {
-	defaultLogger.DebugContext(ctx, msg, args...)
+	getLogger(ctx).WarnContext(ctx, msg, args...)
 }
 
-// Info calls [Logger.Info] on the default logger.
+// Error logs error messages.
-func Info(msg string, args ...any) {
+func Error(ctx context.Context, msg string, args ...any) {
-	defaultLogger.Info(msg, args...)
+	getLogger(ctx).ErrorContext(ctx, 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...)
 }

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

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,

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,

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
 	}