Task 8: standardize scanner and handler logging

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
 }
 
@@ -43,9 +45,29 @@ func NewServer(
 	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