From 600f50dac5f33eac14bfbcd15addaf210a260879 Mon Sep 17 00:00:00 2001 From: Paul Buetow Date: Sun, 3 May 2026 21:14:09 +0300 Subject: Task 8: standardize scanner and handler logging --- cmd/mediaplayer/main.go | 26 +++++++------- internal/api/handlers.go | 10 +++--- internal/api/handlers_media.go | 5 ++- internal/api/server.go | 23 +++++++++++++ internal/scanner/scanner.go | 78 ++++++++++++++++++++++++++---------------- internal/service/admin.go | 15 ++++++-- 6 files changed, 104 insertions(+), 53 deletions(-) diff --git a/cmd/mediaplayer/main.go b/cmd/mediaplayer/main.go index 7ecf052..f560551 100644 --- a/cmd/mediaplayer/main.go +++ b/cmd/mediaplayer/main.go @@ -4,7 +4,6 @@ import ( "context" "flag" "fmt" - "log" "log/slog" "net/http" "os" @@ -25,7 +24,8 @@ import ( func main() { if err := run(os.Args[1:]); err != nil { - log.Fatal(err) + slog.Error("fatal", "err", err) + os.Exit(1) } } @@ -54,11 +54,6 @@ func runWithSignal(args []string, sigCh <-chan os.Signal) error { if err != nil { return fmt.Errorf("failed to open database: %w", err) } - defer func() { - if err := store.Close(); err != nil { - log.Printf("failed to close database: %v", err) - } - }() // Build logger aligned with the configured log level. var level slog.Level @@ -75,6 +70,11 @@ func runWithSignal(args []string, sigCh <-chan os.Signal) error { level = slog.LevelInfo } logger := slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: level})) + defer func() { + if err := store.Close(); err != nil { + logger.Error("failed to close database", "err", err) + } + }() clk := clock.RealClock{} hasher := auth.NewBCryptHasher(12) @@ -84,8 +84,8 @@ func runWithSignal(args []string, sigCh <-chan os.Signal) error { thumbGen := thumb.NewFFmpegGenerator() mediaSvc := service.NewMediaService(store, clk, cfg.MediaRoot, thumbGen, prober) - fsScanner := scanner.NewFSScanner(store, prober, thumbGen, clk, cfg.MediaRoot) - adminSvc := service.NewAdminService(store, clk, hasher, fsScanner, cfg.MediaRoot) + fsScanner := scanner.NewFSScannerWithLogger(store, prober, thumbGen, clk, cfg.MediaRoot, logger) + adminSvc := service.NewAdminServiceWithLogger(store, clk, hasher, fsScanner, cfg.MediaRoot, logger) progressSvc := service.NewProgressService(store, clk) authSvc := service.NewAuthService(store, clk, hasher, sm) @@ -97,11 +97,11 @@ func runWithSignal(args []string, sigCh <-chan os.Signal) error { staticFS := http.Dir("web") remuxer := probe.NewFFRemuxer() - server := api.NewServer(store, hasher, sm, cfg, mediaSvc, adminSvc, progressSvc, authSvc, staticFS, remuxer) + server := api.NewServerWithLogger(store, hasher, sm, cfg, mediaSvc, adminSvc, progressSvc, authSvc, staticFS, remuxer, logger) gs := api.NewGracefulServer(server, cfg) - log.Printf("player %s starting on %s", internal.Version, gs.Server.Addr) + logger.Info("player starting", "version", internal.Version, "addr", gs.Server.Addr) errCh := make(chan error, 1) go func() { @@ -124,12 +124,12 @@ func runWithSignal(args []string, sigCh <-chan os.Signal) error { } } - log.Println("shutting down server...") + logger.Info("shutting down server") shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := gs.Server.Shutdown(shutdownCtx); err != nil { return fmt.Errorf("failed to shutdown server: %w", err) } - log.Println("server stopped") + logger.Info("server stopped") return nil } diff --git a/internal/api/handlers.go b/internal/api/handlers.go index 911b694..8da7a9f 100644 --- a/internal/api/handlers.go +++ b/internal/api/handlers.go @@ -111,7 +111,7 @@ func (s *Server) serveDetach(w http.ResponseWriter, r *http.Request) { func (s *Server) serveFileResult(w http.ResponseWriter, r *http.Request, res *service.FileResult, attachment bool) { f, err := os.Open(res.Path) if err != nil { - fmt.Printf("[api] stream file=%s error=open_failed\n", res.FileName) + s.logger.Warn("api stream open failed", "file", res.FileName, "err", err) http.Error(w, "not found", http.StatusNotFound) return } @@ -119,7 +119,7 @@ func (s *Server) serveFileResult(w http.ResponseWriter, r *http.Request, res *se stat, err := f.Stat() if err != nil { - fmt.Printf("[api] stream file=%s error=stat_failed\n", res.FileName) + s.logger.Warn("api stream stat failed", "file", res.FileName, "err", err) http.Error(w, "not found", http.StatusNotFound) return } @@ -137,15 +137,15 @@ func (s *Server) serveFileResult(w http.ResponseWriter, r *http.Request, res *se // needing to sniff, which avoids buffering delays during streaming. w.Header().Set("Content-Type", probe.MimeTypeForFilename(res.FileName)) w.Header().Set("Accept-Ranges", "bytes") - fmt.Printf("[api] stream file=%s size=%d bytes range=%s\n", res.FileName, stat.Size(), r.Header.Get("Range")) + s.logger.Info("api stream file", "file", res.FileName, "size", stat.Size(), "range", r.Header.Get("Range")) http.ServeContent(w, r, res.FileName, stat.ModTime(), f) } func (s *Server) serveRemuxedMP4(w http.ResponseWriter, r *http.Request, res *service.FileResult, size int64) { w.Header().Set("Content-Type", "video/mp4") w.Header().Set("Cache-Control", "no-store") - fmt.Printf("[api] remux stream file=%s size=%d bytes range=%s\n", res.FileName, size, r.Header.Get("Range")) + s.logger.Info("api remux stream file", "file", res.FileName, "size", size, "range", r.Header.Get("Range")) if err := s.remuxer.Remux(r.Context(), res.Path, w); err != nil { - slog.Error("remux media", "file", res.FileName, "err", err) + s.logger.Error("remux media", "file", res.FileName, "err", err) } } diff --git a/internal/api/handlers_media.go b/internal/api/handlers_media.go index afb9685..20e44ab 100644 --- a/internal/api/handlers_media.go +++ b/internal/api/handlers_media.go @@ -2,7 +2,6 @@ package api import ( "errors" - "fmt" "net/http" "net/url" "strconv" @@ -240,11 +239,11 @@ func (s *Server) handleListMedia(w http.ResponseWriter, r *http.Request) { media, err := s.mediaSvc.ListMedia(r.Context(), userIDFromContext(r), filter) dur := time.Since(start) if err != nil { - fmt.Printf("[api] %s set_id=%s set_ids=%s search=%q type=%s fav=%s min=%s max=%s error=%v (took %s)\n", path, setID, setIDs, search, typ, fav, minDur, maxDur, err, dur) + s.logger.Error("api list media failed", "path", path, "set_id", setID, "set_ids", setIDs, "search", search, "type", typ, "favorites", fav, "min_duration", minDur, "max_duration", maxDur, "duration", dur, "err", err) writeJSON(w, http.StatusInternalServerError, map[string]string{"error": err.Error()}) return } - fmt.Printf("[api] %s set_id=%s set_ids=%s search=%q type=%s fav=%s min=%s max=%s returned=%d (took %s)\n", path, setID, setIDs, search, typ, fav, minDur, maxDur, len(media), dur) + s.logger.Info("api list media", "path", path, "set_id", setID, "set_ids", setIDs, "search", search, "type", typ, "favorites", fav, "min_duration", minDur, "max_duration", maxDur, "returned", len(media), "duration", dur) writeJSON(w, http.StatusOK, media) } diff --git a/internal/api/server.go b/internal/api/server.go index e5fdd8d..f934a56 100644 --- a/internal/api/server.go +++ b/internal/api/server.go @@ -2,6 +2,7 @@ package api import ( "context" + "log/slog" "net/http" "strconv" "time" @@ -26,6 +27,7 @@ type Server struct { authSvc service.AuthService staticFS http.FileSystem remuxer probe.Remuxer + logger *slog.Logger mw *Middleware } @@ -42,10 +44,30 @@ func NewServer( authSvc service.AuthService, staticFS http.FileSystem, remuxer probe.Remuxer, +) *Server { + return NewServerWithLogger(store, hasher, sm, cfg, mediaSvc, adminSvc, progressSvc, authSvc, staticFS, remuxer, slog.Default()) +} + +// NewServerWithLogger creates a Server with routes and an injected logger. +func NewServerWithLogger( + store repository.Store, + hasher auth.Hasher, + sm *auth.SessionManager, + cfg *internal.Config, + mediaSvc service.MediaService, + adminSvc service.AdminService, + progressSvc service.ProgressService, + authSvc service.AuthService, + staticFS http.FileSystem, + remuxer probe.Remuxer, + logger *slog.Logger, ) *Server { if staticFS == nil { staticFS = http.Dir("web") } + if logger == nil { + logger = slog.Default() + } s := &Server{ store: store, hasher: hasher, @@ -58,6 +80,7 @@ func NewServer( authSvc: authSvc, staticFS: staticFS, remuxer: remuxer, + logger: logger, mw: NewMiddleware(store, sm), } s.routes() diff --git a/internal/scanner/scanner.go b/internal/scanner/scanner.go index bb2ea55..117f99b 100644 --- a/internal/scanner/scanner.go +++ b/internal/scanner/scanner.go @@ -5,6 +5,7 @@ import ( "context" "fmt" "io/fs" + "log/slog" "path/filepath" "strings" @@ -28,10 +29,19 @@ type FSScanner struct { clock clock.Clock mediaRoot string fs FS + logger *slog.Logger } // NewFSScanner creates a filesystem scanner with injected dependencies. func NewFSScanner(store repository.ScannerStore, prober probe.Prober, thumbGen thumb.Generator, clk clock.Clock, mediaRoot string) Scanner { + return NewFSScannerWithLogger(store, prober, thumbGen, clk, mediaRoot, slog.Default()) +} + +// NewFSScannerWithLogger creates a filesystem scanner with an injected logger. +func NewFSScannerWithLogger(store repository.ScannerStore, prober probe.Prober, thumbGen thumb.Generator, clk clock.Clock, mediaRoot string, logger *slog.Logger) Scanner { + if logger == nil { + logger = slog.Default() + } return &FSScanner{ store: store, prober: prober, @@ -39,7 +49,15 @@ func NewFSScanner(store repository.ScannerStore, prober probe.Prober, thumbGen t clock: clk, mediaRoot: mediaRoot, fs: osFS{}, + logger: logger, + } +} + +func (s *FSScanner) log() *slog.Logger { + if s.logger != nil { + return s.logger } + return slog.Default() } // Scan walks immediate subdirectories of root, treating each as a set. @@ -59,7 +77,7 @@ func (s *FSScanner) Scan(ctx context.Context, root string, progress *model.ScanP if progress != nil { progress.Start(setCount) } - fmt.Printf("[scanner] scan started root=%q sets=%d\n", root, setCount) + s.log().Info("scanner scan started", "root", root, "sets", setCount) for _, entry := range entries { if !entry.IsDir() { @@ -73,13 +91,13 @@ func (s *FSScanner) Scan(ctx context.Context, root string, progress *model.ScanP progress.IncrementSet() } } - fmt.Printf("[scanner] scan finished root=%q sets=%d\n", root, setCount) + s.log().Info("scanner scan finished", "root", root, "sets", setCount) return nil } func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress *model.ScanProgress) error { setName := filepath.Base(setPath) - fmt.Printf("[scanner] set started name=%q path=%q\n", setName, setPath) + s.log().Info("scanner set started", "name", setName, "path", setPath) if progress != nil { progress.SetCurrentSet(setName) } @@ -164,7 +182,7 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress } relPath = filepath.ToSlash(relPath) _, alreadyExists := existing[relPath] - fmt.Printf("[scanner] file set=%q path=%q existing=%t\n", setName, relPath, alreadyExists) + s.log().Debug("scanner file checked", "set", setName, "path", relPath, "existing", alreadyExists) if progress != nil { progress.IncrementFile() } @@ -179,7 +197,7 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress meta, err := s.prober.Probe(ctx, path) if err != nil { - fmt.Printf("[scanner] skipping unprobeable file %q: %v\n", path, err) + s.log().Warn("scanner skipping unprobeable file", "path", path, "err", err) return nil } meta.FileSizeBytes = info.Size() @@ -194,7 +212,7 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress thumbName := strings.TrimSuffix(filepath.Base(path), filepath.Ext(path)) + ".jpg" thumbnailPath = filepath.Join(thumbDir, thumbName) if err := s.thumbGen.Generate(ctx, path, thumbnailPath, meta.Duration); err != nil { - fmt.Printf("[scanner] skipping thumbnail for %q: %v\n", path, err) + s.log().Warn("scanner skipping thumbnail", "path", path, "err", err) thumbnailPath = "" } } else if mediaType == model.MediaTypeAudio { @@ -211,34 +229,34 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress thumbName := strings.TrimSuffix(filepath.Base(path), filepath.Ext(path)) + ".jpg" thumbnailPath = filepath.Join(thumbDir, thumbName) if err := s.thumbGen.Generate(ctx, path, thumbnailPath, 0); err != nil { - fmt.Printf("[scanner] skipping thumbnail for %q: %v\n", path, err) + s.log().Warn("scanner skipping thumbnail", "path", path, "err", err) thumbnailPath = "" } } } media := &model.Media{ - SetID: setID, - RelPath: relPath, - FileName: filepath.Base(path), - AbsPath: path, - Type: mediaType, - Duration: meta.Duration, - Codec: meta.Codec, - Resolution: meta.Resolution, - Bitrate: meta.Bitrate, - FileSizeBytes: meta.FileSizeBytes, - Width: meta.Width, - Height: meta.Height, - EXIFCamera: meta.EXIFCamera, - EXIFLens: meta.EXIFLens, - EXIFDate: meta.EXIFDate, - EXIFISO: meta.EXIFISO, - EXIFFNumber: meta.EXIFFNumber, - EXIFExposure: meta.EXIFExposure, + SetID: setID, + RelPath: relPath, + FileName: filepath.Base(path), + AbsPath: path, + Type: mediaType, + Duration: meta.Duration, + Codec: meta.Codec, + Resolution: meta.Resolution, + Bitrate: meta.Bitrate, + FileSizeBytes: meta.FileSizeBytes, + Width: meta.Width, + Height: meta.Height, + EXIFCamera: meta.EXIFCamera, + EXIFLens: meta.EXIFLens, + EXIFDate: meta.EXIFDate, + EXIFISO: meta.EXIFISO, + EXIFFNumber: meta.EXIFFNumber, + EXIFExposure: meta.EXIFExposure, EXIFFocalLength: meta.EXIFFocalLength, - ThumbnailPath: thumbnailPath, - CreatedAt: s.clock.Now(), + ThumbnailPath: thumbnailPath, + CreatedAt: s.clock.Now(), } if _, err := s.store.CreateMedia(ctx, media); err != nil { @@ -246,7 +264,7 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress } newFiles++ if newFiles == 1 || newFiles%25 == 0 { - fmt.Printf("[scanner] set progress name=%q new_media=%d latest=%q\n", setName, newFiles, relPath) + s.log().Info("scanner set progress", "name", setName, "new_media", newFiles, "latest", relPath) } return nil }) @@ -262,12 +280,12 @@ func (s *FSScanner) scanSet(ctx context.Context, root, setPath string, progress candidate := findCoverImage(m.AbsPath, coverImages, setPath) if candidate != "" && candidate != m.ThumbnailPath { if err := s.store.UpdateMediaThumbnail(ctx, m.ID, candidate); err != nil { - fmt.Printf("[scanner] failed to update thumbnail for %q: %v\n", m.FileName, err) + s.log().Warn("scanner failed to update thumbnail", "file", m.FileName, "err", err) } } } - fmt.Printf("[scanner] set completed name=%q existing_media=%d new_media=%d\n", setName, len(existing), newFiles) + s.log().Info("scanner set completed", "name", setName, "existing_media", len(existing), "new_media", newFiles) return nil } diff --git a/internal/service/admin.go b/internal/service/admin.go index fb35631..bd745af 100644 --- a/internal/service/admin.go +++ b/internal/service/admin.go @@ -3,6 +3,7 @@ package service import ( "context" "fmt" + "log/slog" "sync" "time" @@ -20,6 +21,7 @@ type adminService struct { hasher auth.Hasher scanner scanner.Scanner mediaRoot string + logger *slog.Logger mu sync.Mutex scanCancel context.CancelFunc progress *model.ScanProgress @@ -27,12 +29,21 @@ type adminService struct { // NewAdminService creates a concrete AdminService. func NewAdminService(store repository.AdminServiceStore, clk clock.Clock, hasher auth.Hasher, sc scanner.Scanner, mediaRoot string) AdminService { + return NewAdminServiceWithLogger(store, clk, hasher, sc, mediaRoot, slog.Default()) +} + +// NewAdminServiceWithLogger creates a concrete AdminService with an injected logger. +func NewAdminServiceWithLogger(store repository.AdminServiceStore, clk clock.Clock, hasher auth.Hasher, sc scanner.Scanner, mediaRoot string, logger *slog.Logger) AdminService { + if logger == nil { + logger = slog.Default() + } return &adminService{ store: store, clock: clk, hasher: hasher, scanner: sc, mediaRoot: mediaRoot, + logger: logger, } } @@ -61,10 +72,10 @@ func (s *adminService) TriggerRescan(ctx context.Context) error { defer cancel() if err := s.scanner.Scan(scanCtx, s.mediaRoot, progress); err != nil { progress.Done(err) - fmt.Printf("[rescan] scan failed: %v\n", err) + s.logger.Error("rescan failed", "err", err) } else { progress.Done(nil) - fmt.Printf("[rescan] scan completed\n") + s.logger.Info("rescan completed") } }() return nil -- cgit v1.2.3