chore: expand debug logging + embeddable version

cmd/api/main.go

@@ -7,10 +7,13 @@ import (
 	"github.com/gabehf/koito/engine"
 )
 
+var Version = "dev"
+
 func main() {
 	if err := engine.Run(
 		os.Getenv,
 		os.Stdout,
+		Version,
 	); err != nil {
 		fmt.Fprintf(os.Stderr, "%s\n", err)
 		os.Exit(1)

engine/engine.go

@@ -29,26 +29,28 @@ import (
 	"github.com/rs/zerolog"
 )
 
-const Version = "dev"
-
 func Run(
 	getenv func(string) string,
 	w io.Writer,
+	version string,
 ) error {
 	err := cfg.Load(getenv)
 	if err != nil {
-		return fmt.Errorf("failed to load configuration: %v", err)
+		panic("Engine: Failed to load configuration")
 	}
+
 	l := logger.Get()
+
+	l.Debug().Msg("Engine: Starting application initialization")
+
 	if cfg.StructuredLogging() {
+		l.Debug().Msg("Engine: Enabling structured logging")
 		*l = l.Output(w)
 	} else {
+		l.Debug().Msg("Engine: Enabling console logging")
 		*l = l.Output(zerolog.ConsoleWriter{
 			Out:        w,
 			TimeFormat: time.RFC3339,
-			// FormatLevel: func(i interface{}) string {
-			// 	return strings.ToUpper(fmt.Sprintf("[%s]", i))
-			// },
 			FormatMessage: func(i interface{}) string {
 				return fmt.Sprintf("\u001b[30;1m>\u001b[0m %s |", i)
 			},
@@ -57,64 +59,75 @@ func Run(
 
 	ctx := logger.NewContext(l)
 
-	l.Info().Msgf("Koito %s", Version)
+	l.Info().Msgf("Koito %s", version)
 
+	l.Debug().Msgf("Engine: Checking config directory: %s", cfg.ConfigDir())
 	_, err = os.Stat(cfg.ConfigDir())
 	if err != nil {
-		l.Info().Msgf("Creating config dir: %s", cfg.ConfigDir())
+		l.Info().Msgf("Engine: Creating config directory: %s", cfg.ConfigDir())
 		err = os.MkdirAll(cfg.ConfigDir(), 0744)
 		if err != nil {
-			l.Error().Err(err).Msg("Failed to create config directory")
+			l.Fatal().Err(err).Msg("Engine: Failed to create config directory")
 			return err
 		}
 	}
-	l.Info().Msgf("Using config dir: %s", cfg.ConfigDir())
+	l.Info().Msgf("Engine: Using config directory: %s", cfg.ConfigDir())
+
+	l.Debug().Msgf("Engine: Checking import directory: %s", path.Join(cfg.ConfigDir(), "import"))
 	_, err = os.Stat(path.Join(cfg.ConfigDir(), "import"))
 	if err != nil {
-		l.Debug().Msgf("Creating import dir: %s", path.Join(cfg.ConfigDir(), "import"))
+		l.Info().Msgf("Engine: Creating import directory: %s", path.Join(cfg.ConfigDir(), "import"))
 		err = os.Mkdir(path.Join(cfg.ConfigDir(), "import"), 0744)
 		if err != nil {
-			l.Error().Err(err).Msg("Failed to create import directory")
+			l.Fatal().Err(err).Msg("Engine: Failed to create import directory")
 			return err
 		}
 	}
 
+	l.Debug().Msg("Engine: Initializing database connection")
 	var store *psql.Psql
 	store, err = psql.New()
 	for err != nil {
-		l.Error().Err(err).Msg("Failed to connect to database; retrying in 5 seconds")
+		l.Error().Err(err).Msg("Engine: Failed to connect to database; retrying in 5 seconds")
 		time.Sleep(5 * time.Second)
 		store, err = psql.New()
 	}
 	defer store.Close(ctx)
+	l.Info().Msg("Engine: Database connection established")
 
+	l.Debug().Msg("Engine: Initializing MusicBrainz client")
 	var mbzC mbz.MusicBrainzCaller
 	if !cfg.MusicBrainzDisabled() {
 		mbzC = mbz.NewMusicBrainzClient()
+		l.Info().Msg("Engine: MusicBrainz client initialized")
 	} else {
 		mbzC = &mbz.MbzErrorCaller{}
+		l.Warn().Msg("Engine: MusicBrainz client disabled")
 	}
 
+	l.Debug().Msg("Engine: Initializing image sources")
 	images.Initialize(images.ImageSourceOpts{
 		UserAgent:    cfg.UserAgent(),
 		EnableCAA:    !cfg.CoverArtArchiveDisabled(),
 		EnableDeezer: !cfg.DeezerDisabled(),
 	})
+	l.Info().Msg("Engine: Image sources initialized")
 
+	l.Debug().Msg("Engine: Checking for default user")
 	userCount, _ := store.CountUsers(ctx)
 	if userCount < 1 {
-		l.Debug().Msg("Creating default user...")
+		l.Info().Msg("Engine: Creating default user")
 		user, err := store.SaveUser(ctx, db.SaveUserOpts{
 			Username: cfg.DefaultUsername(),
 			Password: cfg.DefaultPassword(),
 			Role:     models.UserRoleAdmin,
 		})
 		if err != nil {
-			l.Fatal().AnErr("error", err).Msg("Failed to save default user in database")
+			l.Fatal().Err(err).Msg("Engine: Failed to save default user in database")
 		}
 		apikey, err := utils.GenerateRandomString(48)
 		if err != nil {
-			l.Fatal().AnErr("error", err).Msg("Failed to generate default api key")
+			l.Fatal().Err(err).Msg("Engine: Failed to generate default API key")
 		}
 		label := "Default"
 		_, err = store.SaveApiKey(ctx, db.SaveApiKeyOpts{
@@ -123,28 +136,27 @@ func Run(
 			Label:  label,
 		})
 		if err != nil {
-			l.Fatal().AnErr("error", err).Msg("Failed to save default api key in database")
+			l.Fatal().Err(err).Msg("Engine: Failed to save default API key in database")
 		}
-		l.Info().Msgf("Default user has been created. Login: %s : %s", cfg.DefaultUsername(), cfg.DefaultPassword())
+		l.Info().Msgf("Engine: Default user created. Login: %s : %s", cfg.DefaultUsername(), cfg.DefaultPassword())
 	}
 
+	l.Debug().Msg("Engine: Checking allowed hosts configuration")
 	if cfg.AllowAllHosts() {
-		l.Warn().Msg("Your configuration allows requests from all hosts. This is a potential security risk!")
+		l.Warn().Msg("Engine: Configuration allows requests from all hosts. This is a potential security risk!")
 	} else if len(cfg.AllowedHosts()) == 0 || cfg.AllowedHosts()[0] == "" {
-		l.Warn().Msgf("You are currently not allowing any hosts! Did you forget to set the %s variable?", cfg.ALLOWED_HOSTS_ENV)
+		l.Warn().Msgf("Engine: No hosts allowed! Did you forget to set the %s variable?", cfg.ALLOWED_HOSTS_ENV)
 	} else {
-		l.Debug().Msgf("Allowing hosts: %v", cfg.AllowedHosts())
+		l.Info().Msgf("Engine: Allowing hosts: %v", cfg.AllowedHosts())
 	}
 
+	l.Debug().Msg("Engine: Setting up HTTP server")
 	var ready atomic.Bool
-
 	mux := chi.NewRouter()
-	// bind general middleware to mux
 	mux.Use(middleware.WithRequestID)
 	mux.Use(middleware.Logger(l))
 	mux.Use(chimiddleware.Recoverer)
 	mux.Use(chimiddleware.RealIP)
-	// call router binds on mux
 	bindRoutes(mux, &ready, store, mbzC)
 
 	httpServer := &http.Server{
@@ -153,36 +165,38 @@ func Run(
 	}
 
 	go func() {
-		ready.Store(true) // signal readiness
+		ready.Store(true)
-		l.Info().Msg("listening on " + cfg.ListenAddr())
+		l.Info().Msgf("Engine: Listening on %s", cfg.ListenAddr())
 		if err := httpServer.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-			l.Fatal().AnErr("error", err).Msg("Error when running ListenAndServe")
+			l.Fatal().Err(err).Msg("Engine: Error when running ListenAndServe")
 		}
 	}()
 
-	// Import
+	l.Debug().Msg("Engine: Checking import configuration")
 	if !cfg.SkipImport() {
 		go func() {
 			RunImporter(l, store, mbzC)
 		}()
 	}
 
-	l.Info().Msg("Pruning orphaned images...")
+	l.Info().Msg("Engine: Pruning orphaned images")
 	go catalog.PruneOrphanedImages(logger.NewContext(l), store)
-	// Wait for interrupt signal to gracefully shutdown the server with a timeout of 10 seconds.
+
-	// Use a buffered channel to avoid missing signals as recommended for signal.Notify
+	l.Info().Msg("Engine: Initialization finished")
 	quit := make(chan os.Signal, 1)
 	signal.Notify(quit, os.Interrupt, syscall.SIGINT, syscall.SIGTERM)
 	<-quit
-	l.Info().Msg("Received server shutdown notice")
+	l.Info().Msg("Engine: Received server shutdown notice")
+
 	ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
 	defer cancel()
-	l.Info().Msg("waiting for all processes to finish...")
+	l.Info().Msg("Engine: Waiting for all processes to finish")
 	mbzC.Shutdown()
 	if err := httpServer.Shutdown(ctx); err != nil {
+		l.Fatal().Err(err).Msg("Engine: Error during server shutdown")
 		return err
 	}
-	l.Info().Msg("shutdown successful")
+	l.Info().Msg("Engine: Shutdown successful")
 	return nil
 }
 

engine/engine_test.go

@@ -98,7 +98,7 @@ func TestMain(m *testing.M) {
 		log.Fatalf("Could not connect to database: %s", err)
 	}
 
-	go engine.Run(getenv, os.Stdout)
+	go engine.Run(getenv, os.Stdout, "vTest")
 
 	// Wait until the web server is reachable
 	for i := 0; i < 20; i++ {

engine/handlers/alias.go

@@ -1,6 +1,7 @@
 package handlers
 
 import (
+	"fmt"
 	"net/http"
 	"strconv"
 
@@ -16,51 +17,62 @@ func GetAliasesHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("GetAliasesHandler: Got request with params: '%s'", r.URL.Query().Encode())
+
 		// Parse query parameters
 		artistIDStr := r.URL.Query().Get("artist_id")
 		albumIDStr := r.URL.Query().Get("album_id")
 		trackIDStr := r.URL.Query().Get("track_id")
 
 		if artistIDStr == "" && albumIDStr == "" && trackIDStr == "" {
+			l.Debug().Msgf("Request is missing required parameters")
 			utils.WriteError(w, "artist_id, album_id, or track_id must be provided", http.StatusBadRequest)
 			return
 		}
+		if utils.MoreThanOneString(artistIDStr, albumIDStr, trackIDStr) {
+			l.Debug().Msgf("Request is has more than one of artist_id, album_id, and track_id")
+			utils.WriteError(w, "only one of artist_id, album_id, or track_id can be provided at a time", http.StatusBadRequest)
+			return
+		}
 
 		var aliases []models.Alias
 
 		if artistIDStr != "" {
 			artistID, err := strconv.Atoi(artistIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Invalid artist id")
 				utils.WriteError(w, "invalid artist_id", http.StatusBadRequest)
 				return
 			}
 			aliases, err = store.GetAllArtistAliases(ctx, int32(artistID))
 			if err != nil {
-				l.Err(err).Msg("Failed to get artist aliases")
+				l.Err(fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Failed to get artist aliases")
 				utils.WriteError(w, "failed to retrieve aliases", http.StatusInternalServerError)
 				return
 			}
 		} else if albumIDStr != "" {
 			albumID, err := strconv.Atoi(albumIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Invalid album id")
 				utils.WriteError(w, "invalid album_id", http.StatusBadRequest)
 				return
 			}
 			aliases, err = store.GetAllAlbumAliases(ctx, int32(albumID))
 			if err != nil {
-				l.Err(err).Msg("Failed to get artist aliases")
+				l.Err(fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Failed to get album aliases")
 				utils.WriteError(w, "failed to retrieve aliases", http.StatusInternalServerError)
 				return
 			}
 		} else if trackIDStr != "" {
 			trackID, err := strconv.Atoi(trackIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Invalid track id")
 				utils.WriteError(w, "invalid track_id", http.StatusBadRequest)
 				return
 			}
 			aliases, err = store.GetAllTrackAliases(ctx, int32(trackID))
 			if err != nil {
-				l.Err(err).Msg("Failed to get artist aliases")
+				l.Err(fmt.Errorf("GetAliasesHandler: %w", err)).Msg("Failed to get track aliases")
 				utils.WriteError(w, "failed to retrieve aliases", http.StatusInternalServerError)
 				return
 			}
@@ -76,6 +88,8 @@ func DeleteAliasHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("DeleteAliasHandler: Got request with params: '%s'", r.URL.Query().Encode())
+
 		// Parse query parameters
 		artistIDStr := r.URL.Query().Get("artist_id")
 		albumIDStr := r.URL.Query().Get("album_id")
@@ -83,10 +97,12 @@ func DeleteAliasHandler(store db.DB) http.HandlerFunc {
 		alias := r.URL.Query().Get("alias")
 
 		if alias == "" || (artistIDStr == "" && albumIDStr == "" && trackIDStr == "") {
+			l.Debug().Msgf("Request is missing required parameters")
 			utils.WriteError(w, "alias and artist_id, album_id, or track_id must be provided", http.StatusBadRequest)
 			return
 		}
 		if utils.MoreThanOneString(artistIDStr, albumIDStr, trackIDStr) {
+			l.Debug().Msgf("Request is has more than one of artist_id, album_id, and track_id")
 			utils.WriteError(w, "only one of artist_id, album_id, or track_id can be provided at a time", http.StatusBadRequest)
 			return
 		}
@@ -94,36 +110,39 @@ func DeleteAliasHandler(store db.DB) http.HandlerFunc {
 		if artistIDStr != "" {
 			artistID, err := strconv.Atoi(artistIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Invalid artist id")
 				utils.WriteError(w, "invalid artist_id", http.StatusBadRequest)
 				return
 			}
 			err = store.DeleteArtistAlias(ctx, int32(artistID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to delete alias")
+				l.Err(fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Failed to delete artist alias")
 				utils.WriteError(w, "failed to delete alias", http.StatusInternalServerError)
 				return
 			}
 		} else if albumIDStr != "" {
 			albumID, err := strconv.Atoi(albumIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Invalid album id")
 				utils.WriteError(w, "invalid album_id", http.StatusBadRequest)
 				return
 			}
 			err = store.DeleteAlbumAlias(ctx, int32(albumID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to delete alias")
+				l.Err(fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Failed to delete album alias")
 				utils.WriteError(w, "failed to delete alias", http.StatusInternalServerError)
 				return
 			}
 		} else if trackIDStr != "" {
 			trackID, err := strconv.Atoi(trackIDStr)
 			if err != nil {
-				utils.WriteError(w, "invalid album_id", http.StatusBadRequest)
+				l.Debug().AnErr("error", fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Invalid track id")
+				utils.WriteError(w, "invalid track_id", http.StatusBadRequest)
 				return
 			}
 			err = store.DeleteTrackAlias(ctx, int32(trackID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to delete alias")
+				l.Err(fmt.Errorf("DeleteAliasHandler: %w", err)).Msg("Failed to delete track alias")
 				utils.WriteError(w, "failed to delete alias", http.StatusInternalServerError)
 				return
 			}
@@ -139,64 +158,71 @@ func CreateAliasHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("CreateAliasHandler: Got request with params: '%s'", r.URL.Query().Encode())
+
 		err := r.ParseForm()
 		if err != nil {
 			utils.WriteError(w, "invalid request body", http.StatusBadRequest)
 			return
 		}
 
+		alias := r.FormValue("alias")
+		if alias == "" {
+			utils.WriteError(w, "alias must be provided", http.StatusBadRequest)
+			return
+		}
+
 		artistIDStr := r.URL.Query().Get("artist_id")
 		albumIDStr := r.URL.Query().Get("album_id")
 		trackIDStr := r.URL.Query().Get("track_id")
 
-		if artistIDStr == "" && albumIDStr == "" && trackIDStr == "" {
+		if alias == "" || (artistIDStr == "" && albumIDStr == "" && trackIDStr == "") {
-			utils.WriteError(w, "artist_id, album_id, or track_id must be provided", http.StatusBadRequest)
+			l.Debug().Msgf("Request is missing required parameters")
+			utils.WriteError(w, "alias and artist_id, album_id, or track_id must be provided", http.StatusBadRequest)
 			return
 		}
 		if utils.MoreThanOneString(artistIDStr, albumIDStr, trackIDStr) {
+			l.Debug().Msgf("Request is has more than one of artist_id, album_id, and track_id")
 			utils.WriteError(w, "only one of artist_id, album_id, or track_id can be provided at a time", http.StatusBadRequest)
 			return
 		}
 
-		alias := r.FormValue("alias")
-		if alias == "" {
-			utils.WriteError(w, "alias must be provided", http.StatusBadRequest)
-			return
-		}
-
 		if artistIDStr != "" {
 			artistID, err := strconv.Atoi(artistIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Invalid artist id")
 				utils.WriteError(w, "invalid artist_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SaveArtistAliases(ctx, int32(artistID), []string{alias}, "Manual")
 			if err != nil {
-				l.Err(err).Msg("Failed to save alias")
+				l.Err(fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Failed to save artist alias")
 				utils.WriteError(w, "failed to save alias", http.StatusInternalServerError)
 				return
 			}
 		} else if albumIDStr != "" {
 			albumID, err := strconv.Atoi(albumIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Invalid album id")
 				utils.WriteError(w, "invalid album_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SaveAlbumAliases(ctx, int32(albumID), []string{alias}, "Manual")
 			if err != nil {
-				l.Err(err).Msg("Failed to save alias")
+				l.Err(fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Failed to save album alias")
 				utils.WriteError(w, "failed to save alias", http.StatusInternalServerError)
 				return
 			}
 		} else if trackIDStr != "" {
 			trackID, err := strconv.Atoi(trackIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Invalid track id")
 				utils.WriteError(w, "invalid track_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SaveTrackAliases(ctx, int32(trackID), []string{alias}, "Manual")
 			if err != nil {
-				l.Err(err).Msg("Failed to save alias")
+				l.Err(fmt.Errorf("CreateAliasHandler: %w", err)).Msg("Failed to save track alias")
 				utils.WriteError(w, "failed to save alias", http.StatusInternalServerError)
 				return
 			}
@@ -212,6 +238,8 @@ func SetPrimaryAliasHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("SetPrimaryAliasHandler: Got request with params: '%s'", r.URL.Query().Encode())
+
 		// Parse query parameters
 		artistIDStr := r.URL.Query().Get("artist_id")
 		albumIDStr := r.URL.Query().Get("album_id")
@@ -219,47 +247,52 @@ func SetPrimaryAliasHandler(store db.DB) http.HandlerFunc {
 		alias := r.URL.Query().Get("alias")
 
 		if alias == "" || (artistIDStr == "" && albumIDStr == "" && trackIDStr == "") {
+			l.Debug().Msgf("Request is missing required parameters")
 			utils.WriteError(w, "alias and artist_id, album_id, or track_id must be provided", http.StatusBadRequest)
 			return
 		}
 		if utils.MoreThanOneString(artistIDStr, albumIDStr, trackIDStr) {
-			utils.WriteError(w, "only one of artist_id, album_id, or track_id can be provided", http.StatusBadRequest)
+			l.Debug().Msgf("Request is has more than one of artist_id, album_id, and track_id")
+			utils.WriteError(w, "only one of artist_id, album_id, or track_id can be provided at a time", http.StatusBadRequest)
 			return
 		}
 
 		if artistIDStr != "" {
 			artistID, err := strconv.Atoi(artistIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Invalid artist id")
 				utils.WriteError(w, "invalid artist_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SetPrimaryArtistAlias(ctx, int32(artistID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to set primary alias")
+				l.Err(fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Failed to set artist primary alias")
 				utils.WriteError(w, "failed to set primary alias", http.StatusInternalServerError)
 				return
 			}
 		} else if albumIDStr != "" {
 			albumID, err := strconv.Atoi(albumIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Invalid album id")
 				utils.WriteError(w, "invalid album_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SetPrimaryAlbumAlias(ctx, int32(albumID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to set primary alias")
+				l.Err(fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Failed to set album primary alias")
 				utils.WriteError(w, "failed to set primary alias", http.StatusInternalServerError)
 				return
 			}
 		} else if trackIDStr != "" {
 			trackID, err := strconv.Atoi(trackIDStr)
 			if err != nil {
+				l.Debug().AnErr("error", fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Invalid track id")
 				utils.WriteError(w, "invalid track_id", http.StatusBadRequest)
 				return
 			}
 			err = store.SetPrimaryTrackAlias(ctx, int32(trackID), alias)
 			if err != nil {
-				l.Err(err).Msg("Failed to set primary alias")
+				l.Err(fmt.Errorf("SetPrimaryAliasHandler: %w", err)).Msg("Failed to set track primary alias")
 				utils.WriteError(w, "failed to set primary alias", http.StatusInternalServerError)
 				return
 			}

engine/handlers/apikeys.go

@@ -1,6 +1,7 @@
 package handlers
 
 import (
+	"fmt"
 	"net/http"
 	"strconv"
 
@@ -15,37 +16,46 @@ func GenerateApiKeyHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("GenerateApiKeyHandler: Received request with params: '%s'", r.URL.Query().Encode())
+
 		user := middleware.GetUserFromContext(ctx)
 		if user == nil {
+			l.Debug().Msg("GenerateApiKeyHandler: Invalid user retrieved from context")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
+
 		r.ParseForm()
 		label := r.FormValue("label")
 		if label == "" {
+			l.Debug().Msg("GenerateApiKeyHandler: Request rejected due to missing label")
 			utils.WriteError(w, "label is required", http.StatusBadRequest)
 			return
 		}
 
 		apiKey, err := utils.GenerateRandomString(48)
 		if err != nil {
-			l.Err(err).Msg("Failed to generate API key")
+			l.Err(fmt.Errorf("GenerateApiKeyHandler: %w", err)).Msg("Failed to generate API key")
 			utils.WriteError(w, "failed to generate api key", http.StatusInternalServerError)
 			return
 		}
+
 		opts := db.SaveApiKeyOpts{
 			UserID: user.ID,
 			Key:    apiKey,
 			Label:  label,
 		}
-		l.Debug().Any("opts", opts).Send()
+		l.Debug().Msgf("GenerateApiKeyHandler: Saving API key with options: %+v", opts)
+
 		key, err := store.SaveApiKey(ctx, opts)
 		if err != nil {
-			l.Err(err).Msg("Failed to save API key")
+			l.Err(fmt.Errorf("GenerateApiKeyHandler: %w", err)).Msg("Failed to save API key")
 			utils.WriteError(w, "failed to save api key", http.StatusInternalServerError)
 			return
 		}
-		utils.WriteJSON(w, 201, key)
+
+		l.Debug().Msgf("GenerateApiKeyHandler: Successfully saved API key with ID: %d", key.ID)
+		utils.WriteJSON(w, http.StatusCreated, key)
 	}
 }
 
@@ -54,30 +64,39 @@ func DeleteApiKeyHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msgf("DeleteApiKeyHandler: Received request with params: '%s'", r.URL.Query().Encode())
+
 		user := middleware.GetUserFromContext(ctx)
 		if user == nil {
+			l.Debug().Msg("DeleteApiKeyHandler: User could not be verified (context user is nil)")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
 
 		idStr := r.URL.Query().Get("id")
 		if idStr == "" {
+			l.Debug().Msg("DeleteApiKeyHandler: Request rejected due to missing ID")
 			utils.WriteError(w, "id is required", http.StatusBadRequest)
 			return
 		}
+
 		apiKey, err := strconv.Atoi(idStr)
 		if err != nil {
+			l.Debug().AnErr("error", fmt.Errorf("DeleteApiKeyHandler: %w", err)).Msg("Invalid API key ID")
 			utils.WriteError(w, "id is invalid", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("DeleteApiKeyHandler: Deleting API key with ID: %d", apiKey)
+
 		err = store.DeleteApiKey(ctx, int32(apiKey))
 		if err != nil {
-			l.Err(err).Msg("Failed to delete API key")
+			l.Err(fmt.Errorf("DeleteApiKeyHandler: %w", err)).Msg("Failed to delete API key")
 			utils.WriteError(w, "failed to delete api key", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("DeleteApiKeyHandler: Successfully deleted API key with ID: %d", apiKey)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
@@ -87,24 +106,25 @@ func GetApiKeysHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
-		l.Debug().Msgf("Retrieving user from middleware...")
+		l.Debug().Msgf("GetApiKeysHandler: Received request with params: '%s'", r.URL.Query().Encode())
 
 		user := middleware.GetUserFromContext(ctx)
 		if user == nil {
-			l.Debug().Msgf("Could not retrieve user from middleware")
+			l.Debug().Msg("GetApiKeysHandler: Invalid user retrieved from context")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
 
-		l.Debug().Msgf("Retrieved user '%s' from middleware", user.Username)
+		l.Debug().Msgf("GetApiKeysHandler: Retrieving API keys for user ID: %d", user.ID)
 
 		apiKeys, err := store.GetApiKeysByUserID(ctx, user.ID)
 		if err != nil {
-			l.Err(err).Msg("Failed to retrieve API keys")
+			l.Err(fmt.Errorf("GetApiKeysHandler: %w", err)).Msg("Failed to retrieve API keys")
 			utils.WriteError(w, "failed to retrieve api keys", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("GetApiKeysHandler: Successfully retrieved %d API keys for user ID: %d", len(apiKeys), user.ID)
 		utils.WriteJSON(w, http.StatusOK, apiKeys)
 	}
 }
@@ -114,40 +134,50 @@ func UpdateApiKeyLabelHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("UpdateApiKeyLabelHandler: Received request to update API key label")
+
 		user := middleware.GetUserFromContext(ctx)
 		if user == nil {
+			l.Debug().Msg("UpdateApiKeyLabelHandler: Unauthorized request (user context is nil)")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
 
 		idStr := r.URL.Query().Get("id")
 		if idStr == "" {
+			l.Debug().Msg("UpdateApiKeyLabelHandler: Missing API key ID in request")
 			utils.WriteError(w, "id is required", http.StatusBadRequest)
 			return
 		}
+
 		apiKeyID, err := strconv.Atoi(idStr)
 		if err != nil {
+			l.Debug().AnErr("error", fmt.Errorf("UpdateApiKeyLabelHandler: %w", err)).Msg("Invalid API key ID")
 			utils.WriteError(w, "id is invalid", http.StatusBadRequest)
 			return
 		}
 
 		label := r.FormValue("label")
 		if label == "" {
+			l.Debug().Msg("UpdateApiKeyLabelHandler: Missing label in request")
 			utils.WriteError(w, "label is required", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("UpdateApiKeyLabelHandler: Updating label for API key ID %d", apiKeyID)
+
 		err = store.UpdateApiKeyLabel(ctx, db.UpdateApiKeyLabelOpts{
 			UserID: user.ID,
 			ID:     int32(apiKeyID),
 			Label:  label,
 		})
 		if err != nil {
-			l.Err(err).Msg("Failed to update API key label")
+			l.Err(fmt.Errorf("UpdateApiKeyLabelHandler: %w", err)).Msg("Failed to update API key label")
 			utils.WriteError(w, "failed to update api key label", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("UpdateApiKeyLabelHandler: Successfully updated label for API key ID %d", apiKeyID)
 		w.WriteHeader(http.StatusOK)
 	}
 }

engine/handlers/auth.go

@@ -15,30 +15,35 @@ import (
 
 func LoginHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
 		ctx := r.Context()
-		l.Debug().Msg("Recieved login request")
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("LoginHandler: Received login request")
 
 		r.ParseForm()
 		username := r.FormValue("username")
 		password := r.FormValue("password")
 		if username == "" || password == "" {
+			l.Debug().Msg("LoginHandler: Missing username or password")
 			utils.WriteError(w, "username and password are required", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("LoginHandler: Searching for user with username '%s'", username)
 		user, err := store.GetUserByUsername(ctx, username)
 		if err != nil {
-			l.Err(err).Msg("Error searching for user in database")
+			l.Err(err).Msg("LoginHandler: Error searching for user in database")
 			utils.WriteError(w, "internal server error", http.StatusInternalServerError)
 			return
 		} else if user == nil {
+			l.Debug().Msg("LoginHandler: Username or password is incorrect")
 			utils.WriteError(w, "username or password is incorrect", http.StatusBadRequest)
 			return
 		}
 
 		err = bcrypt.CompareHashAndPassword(user.Password, []byte(password))
 		if err != nil {
+			l.Debug().Msg("LoginHandler: Password comparison failed")
 			utils.WriteError(w, "username or password is incorrect", http.StatusBadRequest)
 			return
 		}
@@ -50,9 +55,10 @@ func LoginHandler(store db.DB) http.HandlerFunc {
 			expiresAt = time.Now().Add(30 * 24 * time.Hour)
 		}
 
+		l.Debug().Msgf("LoginHandler: Creating session for user ID %d", user.ID)
 		session, err := store.SaveSession(ctx, user.ID, expiresAt, keepSignedIn)
 		if err != nil {
-			l.Err(err).Msg("Failed to create session")
+			l.Err(err).Msg("LoginHandler: Failed to create session")
 			utils.WriteError(w, "failed to create session", http.StatusInternalServerError)
 			return
 		}
@@ -69,6 +75,7 @@ func LoginHandler(store db.DB) http.HandlerFunc {
 			cookie.Expires = expiresAt
 		}
 
+		l.Debug().Msgf("LoginHandler: Session created successfully for user ID %d", user.ID)
 		http.SetCookie(w, cookie)
 		w.WriteHeader(http.StatusNoContent)
 	}
@@ -76,23 +83,29 @@ func LoginHandler(store db.DB) http.HandlerFunc {
 
 func LogoutHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("LogoutHandler: Received logout request")
 		cookie, err := r.Cookie("koito_session")
 		if err == nil {
+			l.Debug().Msg("LogoutHandler: Found session cookie")
 			sid, err := uuid.Parse(cookie.Value)
 			if err != nil {
+				l.Debug().AnErr("error", err).Msg("LogoutHandler: Invalid session cookie")
 				utils.WriteError(w, "session cookie is invalid", http.StatusUnauthorized)
 				return
 			}
-			err = store.DeleteSession(r.Context(), sid)
+			l.Debug().Msgf("LogoutHandler: Deleting session with ID %s", sid)
+			err = store.DeleteSession(ctx, sid)
 			if err != nil {
-				l.Err(err).Msg("Failed to delete session")
+				l.Err(err).Msg("LogoutHandler: Failed to delete session")
 				utils.WriteError(w, "internal server error", http.StatusInternalServerError)
 				return
 			}
 		}
 
-		// Clear the cookie
+		l.Debug().Msg("LogoutHandler: Clearing session cookie")
 		http.SetCookie(w, &http.Cookie{
 			Name:     "koito_session",
 			Value:    "",
@@ -109,11 +122,17 @@ func MeHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("MeHandler: Received request to retrieve user information")
 		u := middleware.GetUserFromContext(ctx)
 		if u == nil {
-			l.Debug().Msg("Invalid user retrieved from context")
+			l.Debug().Msg("MeHandler: Invalid user retrieved from context")
+			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
+			return
 		}
-		utils.WriteJSON(w, 200, u)
+
+		l.Debug().Msgf("MeHandler: Successfully retrieved user with ID %d", u.ID)
+		utils.WriteJSON(w, http.StatusOK, u)
 	}
 }
 
@@ -122,8 +141,10 @@ func UpdateUserHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("UpdateUserHandler: Received request to update user information")
 		u := middleware.GetUserFromContext(ctx)
 		if u == nil {
+			l.Debug().Msg("UpdateUserHandler: Unauthorized request (user context is nil)")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
@@ -132,18 +153,19 @@ func UpdateUserHandler(store db.DB) http.HandlerFunc {
 		username := r.FormValue("username")
 		password := r.FormValue("password")
 
-		l.Debug().Msgf("Recieved update request for user with id %d", u.ID)
+		l.Debug().Msgf("UpdateUserHandler: Updating user with ID %d", u.ID)
-
 		err := store.UpdateUser(ctx, db.UpdateUserOpts{
 			ID:       u.ID,
 			Username: username,
 			Password: password,
 		})
 		if err != nil {
-			l.Err(err).Msg("Failed to update user")
+			l.Err(err).Msg("UpdateUserHandler: Failed to update user")
 			utils.WriteError(w, err.Error(), http.StatusBadRequest)
 			return
 		}
+
+		l.Debug().Msgf("UpdateUserHandler: Successfully updated user with ID %d", u.ID)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }

engine/handlers/delete.go

@@ -16,64 +16,82 @@ func DeleteTrackHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("DeleteTrackHandler: Received request to delete track")
+
 		trackIDStr := r.URL.Query().Get("id")
 		if trackIDStr == "" {
+			l.Debug().Msg("DeleteTrackHandler: Missing track ID in request")
 			utils.WriteError(w, "track_id must be provided", http.StatusBadRequest)
 			return
 		}
 
 		trackID, err := strconv.Atoi(trackIDStr)
 		if err != nil {
+			l.Debug().AnErr("error", err).Msg("DeleteTrackHandler: Invalid track ID")
 			utils.WriteError(w, "invalid id", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("DeleteTrackHandler: Deleting track with ID %d", trackID)
+
 		err = store.DeleteTrack(ctx, int32(trackID))
 		if err != nil {
-			l.Err(err).Msg("Failed to delete track")
+			l.Err(err).Msg("DeleteTrackHandler: Failed to delete track")
 			utils.WriteError(w, "failed to delete track", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("DeleteTrackHandler: Successfully deleted track with ID %d", trackID)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
 
-// DeleteTrackHandler deletes a track by its ID.
+// DeleteListenHandler deletes a listen record by track ID and timestamp.
 func DeleteListenHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("DeleteListenHandler: Received request to delete listen record")
+
 		trackIDStr := r.URL.Query().Get("track_id")
 		if trackIDStr == "" {
+			l.Debug().Msg("DeleteListenHandler: Missing track ID in request")
 			utils.WriteError(w, "track_id must be provided", http.StatusBadRequest)
 			return
 		}
+
 		trackID, err := strconv.Atoi(trackIDStr)
 		if err != nil {
+			l.Debug().AnErr("error", err).Msg("DeleteListenHandler: Invalid track ID")
 			utils.WriteError(w, "invalid id", http.StatusBadRequest)
 			return
 		}
 
 		unixStr := r.URL.Query().Get("unix")
-		if trackIDStr == "" {
+		if unixStr == "" {
+			l.Debug().Msg("DeleteListenHandler: Missing timestamp in request")
 			utils.WriteError(w, "unix timestamp must be provided", http.StatusBadRequest)
 			return
 		}
+
 		unix, err := strconv.ParseInt(unixStr, 10, 64)
 		if err != nil {
+			l.Debug().AnErr("error", err).Msg("DeleteListenHandler: Invalid timestamp")
 			utils.WriteError(w, "invalid unix timestamp", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("DeleteListenHandler: Deleting listen record for track ID %d at timestamp %d", trackID, unix)
+
 		err = store.DeleteListen(ctx, int32(trackID), time.Unix(unix, 0))
 		if err != nil {
-			l.Err(err).Msg("Failed to delete listen")
+			l.Err(err).Msg("DeleteListenHandler: Failed to delete listen record")
 			utils.WriteError(w, "failed to delete listen", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("DeleteListenHandler: Successfully deleted listen record for track ID %d at timestamp %d", trackID, unix)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
@@ -84,25 +102,32 @@ func DeleteArtistHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("DeleteArtistHandler: Received request to delete artist")
+
 		artistIDStr := r.URL.Query().Get("id")
 		if artistIDStr == "" {
+			l.Debug().Msg("DeleteArtistHandler: Missing artist ID in request")
 			utils.WriteError(w, "id must be provided", http.StatusBadRequest)
 			return
 		}
 
 		artistID, err := strconv.Atoi(artistIDStr)
 		if err != nil {
+			l.Debug().AnErr("error", err).Msg("DeleteArtistHandler: Invalid artist ID")
 			utils.WriteError(w, "invalid id", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("DeleteArtistHandler: Deleting artist with ID %d", artistID)
+
 		err = store.DeleteArtist(ctx, int32(artistID))
 		if err != nil {
-			l.Err(err).Msg("Failed to delete artist")
+			l.Err(err).Msg("DeleteArtistHandler: Failed to delete artist")
 			utils.WriteError(w, "failed to delete artist", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("DeleteArtistHandler: Successfully deleted artist with ID %d", artistID)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
@@ -113,25 +138,32 @@ func DeleteAlbumHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("DeleteAlbumHandler: Received request to delete album")
+
 		albumIDStr := r.URL.Query().Get("id")
 		if albumIDStr == "" {
+			l.Debug().Msg("DeleteAlbumHandler: Missing album ID in request")
 			utils.WriteError(w, "id must be provided", http.StatusBadRequest)
 			return
 		}
 
 		albumID, err := strconv.Atoi(albumIDStr)
 		if err != nil {
+			l.Debug().AnErr("error", err).Msg("DeleteAlbumHandler: Invalid album ID")
 			utils.WriteError(w, "invalid id", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("DeleteAlbumHandler: Deleting album with ID %d", albumID)
+
 		err = store.DeleteAlbum(ctx, int32(albumID))
 		if err != nil {
-			l.Err(err).Msg("Failed to delete album")
+			l.Err(err).Msg("DeleteAlbumHandler: Failed to delete album")
 			utils.WriteError(w, "failed to delete album", http.StatusInternalServerError)
 			return
 		}
 
+		l.Debug().Msgf("DeleteAlbumHandler: Successfully deleted album with ID %d", albumID)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }

engine/handlers/get_album.go

@@ -5,24 +5,41 @@ import (
 	"strconv"
 
 	"github.com/gabehf/koito/internal/db"
+	"github.com/gabehf/koito/internal/logger"
 	"github.com/gabehf/koito/internal/utils"
 )
 
 func GetAlbumHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetAlbumHandler: Received request to retrieve album")
 
 		idStr := r.URL.Query().Get("id")
+		if idStr == "" {
+			l.Debug().Msg("GetAlbumHandler: Missing album ID in request")
+			utils.WriteError(w, "id must be provided", http.StatusBadRequest)
+			return
+		}
+
 		id, err := strconv.Atoi(idStr)
 		if err != nil {
-			utils.WriteError(w, "id is invalid", 400)
+			l.Debug().AnErr("error", err).Msg("GetAlbumHandler: Invalid album ID")
+			utils.WriteError(w, "id is invalid", http.StatusBadRequest)
 			return
 		}
 
-		album, err := store.GetAlbum(r.Context(), db.GetAlbumOpts{ID: int32(id)})
+		l.Debug().Msgf("GetAlbumHandler: Retrieving album with ID %d", id)
+
+		album, err := store.GetAlbum(ctx, db.GetAlbumOpts{ID: int32(id)})
 		if err != nil {
+			l.Err(err).Msgf("GetAlbumHandler: Failed to retrieve album with ID %d", id)
 			utils.WriteError(w, "album with specified id could not be found", http.StatusNotFound)
 			return
 		}
+
+		l.Debug().Msgf("GetAlbumHandler: Successfully retrieved album with ID %d", id)
 		utils.WriteJSON(w, http.StatusOK, album)
 	}
 }

engine/handlers/get_artist.go

@@ -5,24 +5,41 @@ import (
 	"strconv"
 
 	"github.com/gabehf/koito/internal/db"
+	"github.com/gabehf/koito/internal/logger"
 	"github.com/gabehf/koito/internal/utils"
 )
 
 func GetArtistHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetArtistHandler: Received request to retrieve artist")
 
 		idStr := r.URL.Query().Get("id")
+		if idStr == "" {
+			l.Debug().Msg("GetArtistHandler: Missing artist ID in request")
+			utils.WriteError(w, "id must be provided", http.StatusBadRequest)
+			return
+		}
+
 		id, err := strconv.Atoi(idStr)
 		if err != nil {
-			utils.WriteError(w, "id is invalid", 400)
+			l.Debug().AnErr("error", err).Msg("GetArtistHandler: Invalid artist ID")
+			utils.WriteError(w, "id is invalid", http.StatusBadRequest)
 			return
 		}
 
-		artist, err := store.GetArtist(r.Context(), db.GetArtistOpts{ID: int32(id)})
+		l.Debug().Msgf("GetArtistHandler: Retrieving artist with ID %d", id)
+
+		artist, err := store.GetArtist(ctx, db.GetArtistOpts{ID: int32(id)})
 		if err != nil {
+			l.Err(err).Msgf("GetArtistHandler: Failed to retrieve artist with ID %d", id)
 			utils.WriteError(w, "artist with specified id could not be found", http.StatusNotFound)
 			return
 		}
+
+		l.Debug().Msgf("GetArtistHandler: Successfully retrieved artist with ID %d", id)
 		utils.WriteJSON(w, http.StatusOK, artist)
 	}
 }

engine/handlers/get_listen_activity.go

@@ -12,22 +12,58 @@ import (
 
 func GetListenActivityHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetListenActivityHandler: Received request to retrieve listen activity")
 
 		rangeStr := r.URL.Query().Get("range")
-		_range, _ := strconv.Atoi(rangeStr)
+		_range, err := strconv.Atoi(rangeStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid range parameter")
+			utils.WriteError(w, "invalid range parameter", http.StatusBadRequest)
+			return
+		}
 
 		monthStr := r.URL.Query().Get("month")
-		month, _ := strconv.Atoi(monthStr)
+		month, err := strconv.Atoi(monthStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid month parameter")
+			utils.WriteError(w, "invalid month parameter", http.StatusBadRequest)
+			return
+		}
+
 		yearStr := r.URL.Query().Get("year")
-		year, _ := strconv.Atoi(yearStr)
+		year, err := strconv.Atoi(yearStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid year parameter")
+			utils.WriteError(w, "invalid year parameter", http.StatusBadRequest)
+			return
+		}
 
 		artistIdStr := r.URL.Query().Get("artist_id")
-		artistId, _ := strconv.Atoi(artistIdStr)
+		artistId, err := strconv.Atoi(artistIdStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid artist ID parameter")
+			utils.WriteError(w, "invalid artist ID parameter", http.StatusBadRequest)
+			return
+		}
+
 		albumIdStr := r.URL.Query().Get("album_id")
-		albumId, _ := strconv.Atoi(albumIdStr)
+		albumId, err := strconv.Atoi(albumIdStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid album ID parameter")
+			utils.WriteError(w, "invalid album ID parameter", http.StatusBadRequest)
+			return
+		}
+
 		trackIdStr := r.URL.Query().Get("track_id")
-		trackId, _ := strconv.Atoi(trackIdStr)
+		trackId, err := strconv.Atoi(trackIdStr)
+		if err != nil {
+			l.Debug().AnErr("error", err).Msg("GetListenActivityHandler: Invalid track ID parameter")
+			utils.WriteError(w, "invalid track ID parameter", http.StatusBadRequest)
+			return
+		}
 
 		var step db.StepInterval
 		switch strings.ToLower(r.URL.Query().Get("step")) {
@@ -40,7 +76,7 @@ func GetListenActivityHandler(store db.DB) func(w http.ResponseWriter, r *http.R
 		case "year":
 			step = db.StepYear
 		default:
-			l.Debug().Msgf("Using default value '%s' for step", db.StepDefault)
+			l.Debug().Msgf("GetListenActivityHandler: Using default value '%s' for step", db.StepDefault)
 			step = db.StepDay
 		}
 
@@ -54,12 +90,16 @@ func GetListenActivityHandler(store db.DB) func(w http.ResponseWriter, r *http.R
 			TrackID:  int32(trackId),
 		}
 
-		activity, err := store.GetListenActivity(r.Context(), opts)
+		l.Debug().Msgf("GetListenActivityHandler: Retrieving listen activity with options: %+v", opts)
+
+		activity, err := store.GetListenActivity(ctx, opts)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("GetListenActivityHandler: Failed to retrieve listen activity")
-			utils.WriteError(w, err.Error(), 500)
+			utils.WriteError(w, "failed to retrieve listen activity", http.StatusInternalServerError)
 			return
 		}
+
+		l.Debug().Msg("GetListenActivityHandler: Successfully retrieved listen activity")
 		utils.WriteJSON(w, http.StatusOK, activity)
 	}
 }

engine/handlers/get_listens.go

@@ -10,14 +10,22 @@ import (
 
 func GetListensHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetListensHandler: Received request to retrieve listens")
+
 		opts := OptsFromRequest(r)
-		listens, err := store.GetListensPaginated(r.Context(), opts)
+		l.Debug().Msgf("GetListensHandler: Retrieving listens with options: %+v", opts)
+
+		listens, err := store.GetListensPaginated(ctx, opts)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("GetListensHandler: Failed to retrieve listens")
-			utils.WriteError(w, "failed to get listens: "+err.Error(), 400)
+			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusBadRequest)
 			return
 		}
+
+		l.Debug().Msg("GetListensHandler: Successfully retrieved listens")
 		utils.WriteJSON(w, http.StatusOK, listens)
 	}
 }

engine/handlers/get_top_albums.go

@@ -10,14 +10,22 @@ import (
 
 func GetTopAlbumsHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetTopAlbumsHandler: Received request to retrieve top albums")
+
 		opts := OptsFromRequest(r)
-		albums, err := store.GetTopAlbumsPaginated(r.Context(), opts)
+		l.Debug().Msgf("GetTopAlbumsHandler: Retrieving top albums with options: %+v", opts)
+
+		albums, err := store.GetTopAlbumsPaginated(ctx, opts)
 		if err != nil {
-			l.Err(err).Msg("Failed to get top albums")
+			l.Err(err).Msg("GetTopAlbumsHandler: Failed to retrieve top albums")
-			utils.WriteError(w, "failed to get albums", 400)
+			utils.WriteError(w, "failed to get albums", http.StatusBadRequest)
 			return
 		}
+
+		l.Debug().Msg("GetTopAlbumsHandler: Successfully retrieved top albums")
 		utils.WriteJSON(w, http.StatusOK, albums)
 	}
 }

engine/handlers/get_top_artists.go

@@ -10,14 +10,22 @@ import (
 
 func GetTopArtistsHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetTopArtistsHandler: Received request to retrieve top artists")
+
 		opts := OptsFromRequest(r)
-		artists, err := store.GetTopArtistsPaginated(r.Context(), opts)
+		l.Debug().Msgf("GetTopArtistsHandler: Retrieving top artists with options: %+v", opts)
+
+		artists, err := store.GetTopArtistsPaginated(ctx, opts)
 		if err != nil {
-			l.Err(err).Msg("Failed to get top artists")
+			l.Err(err).Msg("GetTopArtistsHandler: Failed to retrieve top artists")
-			utils.WriteError(w, "failed to get artists", 400)
+			utils.WriteError(w, "failed to get artists", http.StatusBadRequest)
 			return
 		}
+
+		l.Debug().Msg("GetTopArtistsHandler: Successfully retrieved top artists")
 		utils.WriteJSON(w, http.StatusOK, artists)
 	}
 }

engine/handlers/get_top_tracks.go

@@ -10,14 +10,22 @@ import (
 
 func GetTopTracksHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetTopTracksHandler: Received request to retrieve top tracks")
+
 		opts := OptsFromRequest(r)
-		tracks, err := store.GetTopTracksPaginated(r.Context(), opts)
+		l.Debug().Msgf("GetTopTracksHandler: Retrieving top tracks with options: %+v", opts)
+
+		tracks, err := store.GetTopTracksPaginated(ctx, opts)
 		if err != nil {
-			l.Err(err).Msg("Failed to get top tracks")
+			l.Err(err).Msg("GetTopTracksHandler: Failed to retrieve top tracks")
-			utils.WriteError(w, "failed to get tracks", 400)
+			utils.WriteError(w, "failed to get tracks", http.StatusBadRequest)
 			return
 		}
+
+		l.Debug().Msg("GetTopTracksHandler: Successfully retrieved top tracks")
 		utils.WriteJSON(w, http.StatusOK, tracks)
 	}
 }

engine/handlers/get_track.go

@@ -11,21 +11,35 @@ import (
 
 func GetTrackHandler(store db.DB) func(w http.ResponseWriter, r *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
-		l := logger.FromContext(r.Context())
+		ctx := r.Context()
+		l := logger.FromContext(ctx)
+
+		l.Debug().Msg("GetTrackHandler: Received request to retrieve track")
 
 		idStr := r.URL.Query().Get("id")
+		if idStr == "" {
+			l.Debug().Msg("GetTrackHandler: Missing track ID in request")
+			utils.WriteError(w, "id must be provided", http.StatusBadRequest)
+			return
+		}
+
 		id, err := strconv.Atoi(idStr)
 		if err != nil {
-			utils.WriteError(w, "id is invalid", 400)
+			l.Debug().AnErr("error", err).Msg("GetTrackHandler: Invalid track ID")
+			utils.WriteError(w, "id is invalid", http.StatusBadRequest)
 			return
 		}
 
-		track, err := store.GetTrack(r.Context(), db.GetTrackOpts{ID: int32(id)})
+		l.Debug().Msgf("GetTrackHandler: Retrieving track with ID %d", id)
+
+		track, err := store.GetTrack(ctx, db.GetTrackOpts{ID: int32(id)})
 		if err != nil {
-			l.Err(err).Msg("Failed to get top albums")
+			l.Err(err).Msgf("GetTrackHandler: Failed to retrieve track with ID %d", id)
 			utils.WriteError(w, "track with specified id could not be found", http.StatusNotFound)
 			return
 		}
+
+		l.Debug().Msgf("GetTrackHandler: Successfully retrieved track with ID %d", id)
 		utils.WriteJSON(w, http.StatusOK, track)
 	}
 }

engine/handlers/handlers.go

@@ -16,19 +16,23 @@ const maximumLimit = 500
 func OptsFromRequest(r *http.Request) db.GetItemsOpts {
 	l := logger.FromContext(r.Context())
 
+	l.Debug().Msg("OptsFromRequest: Parsing query parameters")
+
 	limitStr := r.URL.Query().Get("limit")
 	limit, err := strconv.Atoi(limitStr)
 	if err != nil {
-		l.Debug().Msgf("query parameter 'limit' not specified, using default %d", defaultLimitSize)
+		l.Debug().Msgf("OptsFromRequest: Query parameter 'limit' not specified, using default %d", defaultLimitSize)
 		limit = defaultLimitSize
 	}
 	if limit > maximumLimit {
-		l.Debug().Msgf("limit must not be greater than %d, using default %d", maximumLimit, defaultLimitSize)
+		l.Debug().Msgf("OptsFromRequest: Limit exceeds maximum %d, using default %d", maximumLimit, defaultLimitSize)
 		limit = defaultLimitSize
 	}
+
 	pageStr := r.URL.Query().Get("page")
 	page, _ := strconv.Atoi(pageStr)
 	if page < 1 {
+		l.Debug().Msg("OptsFromRequest: Page parameter is less than 1, defaulting to 1")
 		page = 1
 	}
 
@@ -59,10 +63,13 @@ func OptsFromRequest(r *http.Request) db.GetItemsOpts {
 	case "all_time":
 		period = db.PeriodAllTime
 	default:
-		l.Debug().Msgf("Using default value '%s' for period", db.PeriodDay)
+		l.Debug().Msgf("OptsFromRequest: Using default value '%s' for period", db.PeriodDay)
 		period = db.PeriodDay
 	}
 
+	l.Debug().Msgf("OptsFromRequest: Parsed options: limit=%d, page=%d, week=%d, month=%d, year=%d, artist_id=%d, album_id=%d, track_id=%d, period=%s",
+		limit, page, week, month, year, artistId, albumId, trackId, period)
+
 	return db.GetItemsOpts{
 		Limit:    limit,
 		Period:   period,

engine/handlers/image_handler.go

@@ -23,14 +23,18 @@ func ImageHandler(store db.DB) http.HandlerFunc {
 		size := chi.URLParam(r, "size")
 		filename := chi.URLParam(r, "filename")
 
+		l.Debug().Msgf("ImageHandler: Received request to retrieve image with size '%s' and filename '%s'", size, filename)
+
 		imageSize, err := catalog.ParseImageSize(size)
 		if err != nil {
+			l.Debug().Msg("ImageHandler: Invalid image size parameter")
 			w.WriteHeader(http.StatusNotFound)
 			return
 		}
 
 		imgid, err := uuid.Parse(filename)
 		if err != nil {
+			l.Debug().Msg("ImageHandler: Invalid image filename, serving default image")
 			serveDefaultImage(w, r, imageSize)
 			return
 		}
@@ -38,60 +42,51 @@ func ImageHandler(store db.DB) http.HandlerFunc {
 		desiredImgPath := filepath.Join(cfg.ConfigDir(), catalog.ImageCacheDir, size, filepath.Clean(filename))
 
 		if _, err := os.Stat(desiredImgPath); os.IsNotExist(err) {
-			l.Debug().Msg("Image not found in desired size")
+			l.Debug().Msg("ImageHandler: Image not found in desired size, attempting to retrieve source image")
-			// file doesn't exist in desired size
 
 			fullSizePath := filepath.Join(cfg.ConfigDir(), catalog.ImageCacheDir, string(catalog.ImageSizeFull), filepath.Clean(filename))
 			largeSizePath := filepath.Join(cfg.ConfigDir(), catalog.ImageCacheDir, string(catalog.ImageSizeLarge), filepath.Clean(filename))
 
-			// check if file exists at either full or large size
-			// note: have to check both in case a user switched caching full size on and off
-			// which would result in cache misses from source changing
 			var sourcePath string
 			if _, err = os.Stat(fullSizePath); os.IsNotExist(err) {
 				if _, err = os.Stat(largeSizePath); os.IsNotExist(err) {
-					l.Warn().Msgf("Could not find requested image %s. If this image is tied to an album or artist, it should be replaced", imgid.String())
+					l.Warn().Msgf("ImageHandler: Could not find requested image %s. Serving default image", imgid.String())
 					serveDefaultImage(w, r, imageSize)
 					return
 				} else if err != nil {
-					// non-not found error for full file
+					l.Err(err).Msg("ImageHandler: Failed to access source image file at large size")
-					l.Err(err).Msg("Failed to access source image file")
 					w.WriteHeader(http.StatusInternalServerError)
 					return
 				}
 				sourcePath = largeSizePath
 			} else if err != nil {
-				// non-not found error for full file
+				l.Err(err).Msg("ImageHandler: Failed to access source image file at full size")
-				l.Err(err).Msg("Failed to access source image file")
 				w.WriteHeader(http.StatusInternalServerError)
 				return
 			} else {
 				sourcePath = fullSizePath
 			}
 
-			// source size file was found
+			l.Debug().Msgf("ImageHandler: Found source image file at path '%s'", sourcePath)
-
-			// create and cache image at desired size
 
 			imageBuf, err := os.ReadFile(sourcePath)
 			if err != nil {
-				l.Err(err).Msg("Failed to read source image file")
+				l.Err(err).Msg("ImageHandler: Failed to read source image file")
 				w.WriteHeader(http.StatusInternalServerError)
 				return
 			}
 
 			err = catalog.CompressAndSaveImage(r.Context(), imgid.String(), imageSize, bytes.NewReader(imageBuf))
 			if err != nil {
-				l.Err(err).Msg("Failed to save compressed image to cache")
+				l.Err(err).Msg("ImageHandler: Failed to save compressed image to cache")
 			}
 		} else if err != nil {
-			// non-not found error for desired file
+			l.Err(err).Msg("ImageHandler: Failed to access desired image file")
-			l.Err(err).Msg("Failed to access desired image file")
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
 
-		// Serve image
+		l.Debug().Msgf("ImageHandler: Serving image from path '%s'", desiredImgPath)
 		http.ServeFile(w, r, desiredImgPath)
 	}
 }
@@ -99,15 +94,18 @@ func ImageHandler(store db.DB) http.HandlerFunc {
 func serveDefaultImage(w http.ResponseWriter, r *http.Request, size catalog.ImageSize) {
 	var lock sync.Mutex
 	l := logger.FromContext(r.Context())
+
+	l.Debug().Msgf("serveDefaultImage: Serving default image at size '%s'", size)
+
 	defaultImagePath := filepath.Join(cfg.ConfigDir(), catalog.ImageCacheDir, string(size), "default_img")
 	if _, err := os.Stat(defaultImagePath); os.IsNotExist(err) {
-		l.Debug().Msg("Default image does not exist in cache at desired size")
+		l.Debug().Msg("serveDefaultImage: Default image does not exist in cache at desired size")
 		defaultImagePath := filepath.Join(catalog.SourceImageDir(), "default_img")
 		if _, err = os.Stat(defaultImagePath); os.IsNotExist(err) {
-			l.Debug().Msg("Default image does not exist in cache, attempting to move...")
+			l.Debug().Msg("serveDefaultImage: Default image does not exist in source directory, attempting to move...")
 			err = os.MkdirAll(filepath.Dir(defaultImagePath), 0744)
 			if err != nil {
-				l.Err(err).Msg("Error when attempting to create image_cache/full dir")
+				l.Err(err).Msg("serveDefaultImage: Error when attempting to create image_cache/full directory")
 				w.WriteHeader(http.StatusInternalServerError)
 				return
 			}
@@ -115,94 +113,29 @@ func serveDefaultImage(w http.ResponseWriter, r *http.Request, size catalog.Imag
 			utils.CopyFile(path.Join("assets", "default_img"), defaultImagePath)
 			lock.Unlock()
 		} else if err != nil {
-			// non-not found error
+			l.Err(err).Msg("serveDefaultImage: Error when attempting to read default image in cache")
-			l.Error().Err(err).Msg("Error when attempting to read default image in cache")
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
-		// default_img does (or now does) exist in cache at full size
+
 		file, err := os.Open(path.Join(catalog.SourceImageDir(), "default_img"))
 		if err != nil {
-			l.Err(err).Msg("Error when reading default image from source dir")
+			l.Err(err).Msg("serveDefaultImage: Error when reading default image from source directory")
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
 		err = catalog.CompressAndSaveImage(r.Context(), "default_img", size, file)
 		if err != nil {
-			l.Err(err).Msg("Error when caching default img at desired size")
+			l.Err(err).Msg("serveDefaultImage: Error when caching default image at desired size")
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
 	} else if err != nil {
-		// non-not found error
+		l.Err(err).Msg("serveDefaultImage: Error when attempting to read default image in cache")
-		l.Error().Err(err).Msg("Error when attempting to read default image in cache")
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
-	// serve default_img at desired size
+	l.Debug().Msgf("serveDefaultImage: Successfully serving default image at size '%s'", size)
 	http.ServeFile(w, r, path.Join(cfg.ConfigDir(), catalog.ImageCacheDir, string(size), "default_img"))
 }
-
-// func SearchMissingAlbumImagesHandler(store db.DB) http.HandlerFunc {
-// 	return func(w http.ResponseWriter, r *http.Request) {
-// 		ctx := r.Context()
-// 		l := logger.FromContext(ctx)
-// 		l.Info().Msg("Beginning search for albums with missing images")
-// 		go func() {
-// 			defer func() {
-// 				if r := recover(); r != nil {
-// 					l.Error().Interface("recover", r).Msg("Panic when searching for missing album images")
-// 				}
-// 			}()
-// 			ctx := logger.NewContext(l)
-// 			from := int32(0)
-// 			count := 0
-// 			for {
-// 				albums, err := store.AlbumsWithoutImages(ctx, from)
-// 				if errors.Is(err, pgx.ErrNoRows) {
-// 					break
-// 				} else if err != nil {
-// 					l.Err(err).Msg("Failed to search for missing images")
-// 					return
-// 				}
-// 				l.Debug().Msgf("Queried %d albums on page %d", len(albums), from)
-// 				if len(albums) < 1 {
-// 					break
-// 				}
-// 				for _, a := range albums {
-// 					l.Debug().Msgf("Searching images for album %s", a.Title)
-// 					img, err := imagesrc.GetAlbumImages(ctx, imagesrc.AlbumImageOpts{
-// 						Artists:      utils.FlattenSimpleArtistNames(a.Artists),
-// 						Album:        a.Title,
-// 						ReleaseMbzID: a.MbzID,
-// 					})
-// 					if err == nil && img != "" {
-// 						l.Debug().Msg("Image found! Downloading...")
-// 						imgid, err := catalog.DownloadAndCacheImage(ctx, img)
-// 						if err != nil {
-// 							l.Err(err).Msgf("Failed to download image for %s", a.Title)
-// 							continue
-// 						}
-// 						err = store.UpdateAlbum(ctx, db.UpdateAlbumOpts{
-// 							ID:    a.ID,
-// 							Image: imgid,
-// 						})
-// 						if err != nil {
-// 							l.Err(err).Msgf("Failed to update image for %s", a.Title)
-// 							continue
-// 						}
-// 						l.Info().Msgf("Found new album image for %s", a.Title)
-// 						count++
-// 					}
-// 					if err != nil {
-// 						l.Err(err).Msgf("Failed to get album images for %s", a.Title)
-// 					}
-// 				}
-// 				from = albums[len(albums)-1].ID
-// 			}
-// 			l.Info().Msgf("Completed search, finding %d new images", count)
-// 		}()
-// 		w.WriteHeader(http.StatusOK)
-// 	}
-// }

engine/handlers/lbz_submit_listen.go

@@ -13,7 +13,7 @@ import (
 	"github.com/gabehf/koito/internal/cfg"
 	"github.com/gabehf/koito/internal/db"
 	"github.com/gabehf/koito/internal/logger"
-	mbz "github.com/gabehf/koito/internal/mbz"
+	"github.com/gabehf/koito/internal/mbz"
 	"github.com/gabehf/koito/internal/utils"
 	"github.com/google/uuid"
 	"github.com/rs/zerolog"
@@ -70,60 +70,63 @@ func LbzSubmitListenHandler(store db.DB, mbzc mbz.MusicBrainzCaller) func(w http
 	return func(w http.ResponseWriter, r *http.Request) {
 		l := logger.FromContext(r.Context())
 
+		l.Debug().Msg("LbzSubmitListenHandler: Received request to submit listens")
+
 		var req LbzSubmitListenRequest
 		requestBytes, err := io.ReadAll(r.Body)
 		if err != nil {
+			l.Err(err).Msg("LbzSubmitListenHandler: Failed to read request body")
 			utils.WriteError(w, "failed to read request body", http.StatusBadRequest)
 			return
 		}
 		if err := json.NewDecoder(bytes.NewBuffer(requestBytes)).Decode(&req); err != nil {
-			l.Debug().Err(err).Msg("Failed to decode request")
+			l.Err(err).Msg("LbzSubmitListenHandler: Failed to decode request")
 			utils.WriteError(w, "failed to decode request", http.StatusBadRequest)
 			return
 		}
 
 		u := middleware.GetUserFromContext(r.Context())
 		if u == nil {
+			l.Debug().Msg("LbzSubmitListenHandler: Unauthorized request (user context is nil)")
 			utils.WriteError(w, "unauthorized", http.StatusUnauthorized)
 			return
 		}
 
-		l.Debug().Any("request_body", req).Msg("Recieved request")
+		l.Debug().Any("request_body", req).Msg("LbzSubmitListenHandler: Parsed request body")
 
 		if len(req.Payload) < 1 {
-			l.Error().Msg("Payload is nil")
+			l.Debug().Msg("LbzSubmitListenHandler: Payload is empty")
 			utils.WriteError(w, "payload is nil", http.StatusBadRequest)
 			return
 		}
 
 		if len(req.Payload) > maxListensPerRequest {
-			l.Error().Msg("Payload exceeds max listens per request")
+			l.Debug().Msgf("LbzSubmitListenHandler: Payload exceeds max listens per request (%d > %d)", len(req.Payload), maxListensPerRequest)
 			utils.WriteError(w, "payload exceeds max listens per request", http.StatusBadRequest)
 			return
 		}
 
 		if len(req.Payload) != 1 && req.ListenType != "import" {
-			l.Error().Msg("Payload must only contain one listen for non-import requests")
+			l.Debug().Msg("LbzSubmitListenHandler: Payload must only contain one listen for non-import requests")
 			utils.WriteError(w, "payload must only contain one listen for non-import requests", http.StatusBadRequest)
 			return
 		}
 
 		for _, payload := range req.Payload {
-
 			if payload.TrackMeta.ArtistName == "" || payload.TrackMeta.TrackName == "" {
-				l.Error().Msg("Artist name or track name are missing, unable to process listen")
+				l.Debug().Msg("LbzSubmitListenHandler: Artist name or track name are missing")
 				utils.WriteError(w, "Artist name or track name are missing", http.StatusBadRequest)
 				return
 			}
 
 			if req.ListenType != ListenTypePlayingNow && req.ListenType != ListenTypeSingle && req.ListenType != ListenTypeImport {
-				l.Debug().Msg("No listen type provided, assuming 'single'")
+				l.Debug().Msg("LbzSubmitListenHandler: No listen type provided, assuming 'single'")
 				req.ListenType = "single"
 			}
 
 			artistMbzIDs, err := utils.ParseUUIDSlice(payload.TrackMeta.AdditionalInfo.ArtistMBIDs)
 			if err != nil {
-				l.Debug().Err(err).Msg("Failed to parse one or more uuids")
+				l.Debug().Err(err).Msg("LbzSubmitListenHandler: Failed to parse one or more UUIDs")
 			}
 			rgMbzID, err := uuid.Parse(payload.TrackMeta.AdditionalInfo.ReleaseGroupMBID)
 			if err != nil {
@@ -176,19 +179,23 @@ func LbzSubmitListenHandler(store db.DB, mbzc mbz.MusicBrainzCaller) func(w http
 			if req.ListenType == ListenTypePlayingNow {
 				opts.SkipSaveListen = true
 			}
+
 			_, err, shared := sfGroup.Do(buildCaolescingKey(payload), func() (interface{}, error) {
 				return 0, catalog.SubmitListen(r.Context(), store, opts)
 			})
 			if shared {
-				l.Info().Msg("Duplicate requests detected; results were coalesced")
+				l.Info().Msg("LbzSubmitListenHandler: Duplicate requests detected; results were coalesced")
 			}
 			if err != nil {
+				l.Err(err).Msg("LbzSubmitListenHandler: Failed to submit listen")
 				w.WriteHeader(http.StatusInternalServerError)
 				w.Header().Set("Content-Type", "application/json")
 				w.Write([]byte("{\"status\": \"internal server error\"}"))
+				return
 			}
 		}
 
+		l.Debug().Msg("LbzSubmitListenHandler: Successfully processed listens")
 		w.WriteHeader(http.StatusOK)
 		w.Header().Set("Content-Type", "application/json")
 		w.Write([]byte("{\"status\": \"ok\"}"))
@@ -196,14 +203,13 @@ func LbzSubmitListenHandler(store db.DB, mbzc mbz.MusicBrainzCaller) func(w http
 		if cfg.LbzRelayEnabled() {
 			go doLbzRelay(requestBytes, l)
 		}
-
 	}
 }
 
 func doLbzRelay(requestBytes []byte, l *zerolog.Logger) {
 	defer func() {
 		if r := recover(); r != nil {
-			l.Error().Interface("recover", r).Msg("Panic in doLbzRelay")
+			l.Error().Interface("recover", r).Msg("doLbzRelay: Panic occurred")
 		}
 	}()
 	const (
@@ -211,10 +217,10 @@ func doLbzRelay(requestBytes []byte, l *zerolog.Logger) {
 		initialBackoff   = 5 * time.Second
 		maxBackoff       = 40 * time.Second
 	)
+	l.Debug().Msg("doLbzRelay: Building ListenBrainz relay request")
 	req, err := http.NewRequest("POST", cfg.LbzRelayUrl()+"/submit-listens", bytes.NewBuffer(requestBytes))
 	if err != nil {
-		l.Error().Msg("Failed to build ListenBrainz relay request")
+		l.Err(err).Msg("doLbzRelay: Failed to build ListenBrainz relay request")
-		l.Error().Err(err).Send()
 		return
 	}
 	req.Header.Add("Authorization", "Token "+cfg.LbzRelayToken())
@@ -230,15 +236,16 @@ func doLbzRelay(requestBytes []byte, l *zerolog.Logger) {
 	backoff := initialBackoff
 
 	for {
+		l.Debug().Msg("doLbzRelay: Sending ListenBrainz relay request")
 		resp, err = client.Do(req)
 		if err != nil {
-			l.Err(err).Msg("Failed to send ListenBrainz relay request")
+			l.Err(err).Msg("doLbzRelay: Failed to send ListenBrainz relay request")
 			return
 		}
 		defer resp.Body.Close()
 
 		if resp.StatusCode >= 200 && resp.StatusCode < 300 {
-			l.Info().Msg("Successfully relayed ListenBrainz submission")
+			l.Info().Msg("doLbzRelay: Successfully relayed ListenBrainz submission")
 			return
 		}
 
@@ -248,7 +255,7 @@ func doLbzRelay(requestBytes []byte, l *zerolog.Logger) {
 			l.Warn().
 				Int("status", resp.StatusCode).
 				Str("response", string(body)).
-				Msg("Retryable server error from ListenBrainz relay, retrying...")
+				Msg("doLbzRelay: Retryable server error from ListenBrainz relay, retrying...")
 			time.Sleep(backoff)
 			backoff *= 2
 			if backoff > maxBackoff {
@@ -257,11 +264,10 @@ func doLbzRelay(requestBytes []byte, l *zerolog.Logger) {
 			continue
 		}
 
-		// 4xx status or timeout exceeded
 		l.Warn().
 			Int("status", resp.StatusCode).
 			Str("response", string(body)).
-			Msg("Non-2XX response from ListenBrainz relay")
+			Msg("doLbzRelay: Non-2XX response from ListenBrainz relay")
 		return
 	}
 }

engine/handlers/lbz_validate.go

@@ -21,17 +21,20 @@ func LbzValidateTokenHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
-		l.Debug().Msg("Validating user token...")
+
+		l.Debug().Msg("LbzValidateTokenHandler: Validating user token")
 
 		u := middleware.GetUserFromContext(ctx)
 		var response LbzValidateResponse
 		if u == nil {
+			l.Debug().Msg("LbzValidateTokenHandler: Invalid token, user not found in context")
 			response.Code = http.StatusUnauthorized
 			response.Error = "Incorrect Authorization"
 			w.WriteHeader(http.StatusUnauthorized)
 			utils.WriteJSON(w, http.StatusOK, response)
 		} else {
-			response.Code = 200
+			l.Debug().Msgf("LbzValidateTokenHandler: Token valid for user '%s'", u.Username)
+			response.Code = http.StatusOK
 			response.Message = "Token valid."
 			response.Valid = true
 			response.UserName = u.Username

engine/handlers/merge.go

@@ -13,27 +13,34 @@ func MergeTracksHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		l := logger.FromContext(r.Context())
 
+		l.Debug().Msg("MergeTracksHandler: Received request to merge tracks")
+
 		fromidStr := r.URL.Query().Get("from_id")
 		fromId, err := strconv.Atoi(fromidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeTracksHandler: Invalid from_id parameter")
-			utils.WriteError(w, "from_id is invalid", 400)
+			utils.WriteError(w, "from_id is invalid", http.StatusBadRequest)
 			return
 		}
+
 		toidStr := r.URL.Query().Get("to_id")
 		toId, err := strconv.Atoi(toidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeTracksHandler: Invalid to_id parameter")
-			utils.WriteError(w, "to_id is invalid", 400)
+			utils.WriteError(w, "to_id is invalid", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("MergeTracksHandler: Merging tracks from ID %d to ID %d", fromId, toId)
+
 		err = store.MergeTracks(r.Context(), int32(fromId), int32(toId))
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("MergeTracksHandler: Failed to merge tracks")
 			utils.WriteError(w, "Failed to merge tracks: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
+		l.Debug().Msgf("MergeTracksHandler: Successfully merged tracks from ID %d to ID %d", fromId, toId)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
@@ -42,27 +49,34 @@ func MergeReleaseGroupsHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		l := logger.FromContext(r.Context())
 
+		l.Debug().Msg("MergeReleaseGroupsHandler: Received request to merge release groups")
+
 		fromidStr := r.URL.Query().Get("from_id")
 		fromId, err := strconv.Atoi(fromidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeReleaseGroupsHandler: Invalid from_id parameter")
-			utils.WriteError(w, "from_id is invalid", 400)
+			utils.WriteError(w, "from_id is invalid", http.StatusBadRequest)
 			return
 		}
+
 		toidStr := r.URL.Query().Get("to_id")
 		toId, err := strconv.Atoi(toidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeReleaseGroupsHandler: Invalid to_id parameter")
-			utils.WriteError(w, "to_id is invalid", 400)
+			utils.WriteError(w, "to_id is invalid", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("MergeReleaseGroupsHandler: Merging release groups from ID %d to ID %d", fromId, toId)
+
 		err = store.MergeAlbums(r.Context(), int32(fromId), int32(toId))
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("MergeReleaseGroupsHandler: Failed to merge release groups")
-			utils.WriteError(w, "Failed to merge albums: "+err.Error(), http.StatusInternalServerError)
+			utils.WriteError(w, "Failed to merge release groups: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
+		l.Debug().Msgf("MergeReleaseGroupsHandler: Successfully merged release groups from ID %d to ID %d", fromId, toId)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }
@@ -71,27 +85,34 @@ func MergeArtistsHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		l := logger.FromContext(r.Context())
 
+		l.Debug().Msg("MergeArtistsHandler: Received request to merge artists")
+
 		fromidStr := r.URL.Query().Get("from_id")
 		fromId, err := strconv.Atoi(fromidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeArtistsHandler: Invalid from_id parameter")
-			utils.WriteError(w, "from_id is invalid", 400)
+			utils.WriteError(w, "from_id is invalid", http.StatusBadRequest)
 			return
 		}
+
 		toidStr := r.URL.Query().Get("to_id")
 		toId, err := strconv.Atoi(toidStr)
 		if err != nil {
-			l.Err(err).Send()
+			l.Debug().AnErr("error", err).Msg("MergeArtistsHandler: Invalid to_id parameter")
-			utils.WriteError(w, "to_id is invalid", 400)
+			utils.WriteError(w, "to_id is invalid", http.StatusBadRequest)
 			return
 		}
 
+		l.Debug().Msgf("MergeArtistsHandler: Merging artists from ID %d to ID %d", fromId, toId)
+
 		err = store.MergeArtists(r.Context(), int32(fromId), int32(toId))
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("MergeArtistsHandler: Failed to merge artists")
 			utils.WriteError(w, "Failed to merge artists: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
+		l.Debug().Msgf("MergeArtistsHandler: Successfully merged artists from ID %d to ID %d", fromId, toId)
 		w.WriteHeader(http.StatusNoContent)
 	}
 }

engine/handlers/replace_image.go

@@ -25,51 +25,59 @@ func ReplaceImageHandler(store db.DB) http.HandlerFunc {
 		ctx := r.Context()
 		l := logger.FromContext(ctx)
 
+		l.Debug().Msg("ReplaceImageHandler: Received request to replace image")
+
 		artistIdStr := r.FormValue("artist_id")
 		artistId, _ := strconv.Atoi(artistIdStr)
 		albumIdStr := r.FormValue("album_id")
 		albumId, _ := strconv.Atoi(albumIdStr)
 
 		if artistId != 0 && albumId != 0 {
+			l.Debug().Msg("ReplaceImageHandler: Both artist_id and album_id are set, rejecting request")
 			utils.WriteError(w, "Only one of artist_id and album_id can be set", http.StatusBadRequest)
 			return
 		} else if artistId == 0 && albumId == 0 {
+			l.Debug().Msg("ReplaceImageHandler: Neither artist_id nor album_id are set, rejecting request")
 			utils.WriteError(w, "One of artist_id and album_id must be set", http.StatusBadRequest)
 			return
 		}
 
 		var oldImage *uuid.UUID
 		if artistId != 0 {
+			l.Debug().Msgf("ReplaceImageHandler: Fetching artist with ID %d", artistId)
 			a, err := store.GetArtist(ctx, db.GetArtistOpts{
 				ID: int32(artistId),
 			})
 			if err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Artist with specified ID could not be found")
 				utils.WriteError(w, "Artist with specified id could not be found", http.StatusBadRequest)
 				return
 			}
 			oldImage = a.Image
 		} else if albumId != 0 {
+			l.Debug().Msgf("ReplaceImageHandler: Fetching album with ID %d", albumId)
 			a, err := store.GetAlbum(ctx, db.GetAlbumOpts{
 				ID: int32(albumId),
 			})
 			if err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Album with specified ID could not be found")
 				utils.WriteError(w, "Album with specified id could not be found", http.StatusBadRequest)
 				return
 			}
 			oldImage = a.Image
 		}
 
-		l.Debug().Msgf("Getting image from request...")
+		l.Debug().Msg("ReplaceImageHandler: Getting image from request")
 
 		var id uuid.UUID
 		var err error
 
 		fileUrl := r.FormValue("image_url")
 		if fileUrl != "" {
-			l.Debug().Msg("Image identified as remote file")
+			l.Debug().Msg("ReplaceImageHandler: Image identified as remote file")
 			err = catalog.ValidateImageURL(fileUrl)
 			if err != nil {
-				l.Debug().AnErr("error", err).Msg("Invalid image")
+				l.Debug().AnErr("error", err).Msg("ReplaceImageHandler: Invalid image URL")
 				utils.WriteError(w, "url is invalid or not an image file", http.StatusBadRequest)
 				return
 			}
@@ -80,14 +88,18 @@ func ReplaceImageHandler(store db.DB) http.HandlerFunc {
 			} else {
 				dlSize = catalog.ImageSizeLarge
 			}
-			l.Debug().Msg("Downloading album image from source...")
+			l.Debug().Msg("ReplaceImageHandler: Downloading album image from source")
 			err = catalog.DownloadAndCacheImage(ctx, id, fileUrl, dlSize)
 			if err != nil {
-				l.Err(err).Msg("Failed to cache image")
+				l.Err(err).Msg("ReplaceImageHandler: Failed to cache image")
+				utils.WriteError(w, "Failed to cache image", http.StatusInternalServerError)
+				return
 			}
 		} else {
+			l.Debug().Msg("ReplaceImageHandler: Image identified as uploaded file")
 			file, _, err := r.FormFile("image")
 			if err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Invalid file upload")
 				utils.WriteError(w, "Invalid file", http.StatusBadRequest)
 				return
 			}
@@ -95,22 +107,25 @@ func ReplaceImageHandler(store db.DB) http.HandlerFunc {
 
 			buf := make([]byte, 512)
 			if _, err := file.Read(buf); err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Could not read file")
 				utils.WriteError(w, "Could not read file", http.StatusInternalServerError)
 				return
 			}
 
 			contentType := http.DetectContentType(buf)
 			if !strings.HasPrefix(contentType, "image/") {
+				l.Debug().Msg("ReplaceImageHandler: Uploaded file is not an image")
 				utils.WriteError(w, "Only image uploads are allowed", http.StatusBadRequest)
 				return
 			}
 
 			if _, err := file.Seek(0, io.SeekStart); err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Could not seek file")
 				utils.WriteError(w, "Could not seek file", http.StatusInternalServerError)
 				return
 			}
 
-			l.Debug().Msgf("Saving image to cache...")
+			l.Debug().Msg("ReplaceImageHandler: Saving image to cache")
 
 			id = uuid.New()
 
@@ -123,12 +138,13 @@ func ReplaceImageHandler(store db.DB) http.HandlerFunc {
 
 			err = catalog.CompressAndSaveImage(ctx, id.String(), dlSize, file)
 			if err != nil {
+				l.Err(err).Msg("ReplaceImageHandler: Could not save file")
 				utils.WriteError(w, "Could not save file", http.StatusInternalServerError)
 				return
 			}
 		}
 
-		l.Debug().Msgf("Updating database...")
+		l.Debug().Msg("ReplaceImageHandler: Updating database")
 
 		var imgsrc string
 		if fileUrl != "" {
@@ -138,39 +154,42 @@ func ReplaceImageHandler(store db.DB) http.HandlerFunc {
 		}
 
 		if artistId != 0 {
+			l.Debug().Msgf("ReplaceImageHandler: Updating artist with ID %d", artistId)
 			err := store.UpdateArtist(ctx, db.UpdateArtistOpts{
 				ID:       int32(artistId),
 				Image:    id,
 				ImageSrc: imgsrc,
 			})
 			if err != nil {
-				l.Err(err).Msg("Artist image could not be updated")
+				l.Err(err).Msg("ReplaceImageHandler: Artist image could not be updated")
 				utils.WriteError(w, "Artist image could not be updated", http.StatusInternalServerError)
 				return
 			}
 		} else if albumId != 0 {
+			l.Debug().Msgf("ReplaceImageHandler: Updating album with ID %d", albumId)
 			err := store.UpdateAlbum(ctx, db.UpdateAlbumOpts{
 				ID:       int32(albumId),
 				Image:    id,
 				ImageSrc: imgsrc,
 			})
 			if err != nil {
-				l.Err(err).Msg("Album image could not be updated")
+				l.Err(err).Msg("ReplaceImageHandler: Album image could not be updated")
 				utils.WriteError(w, "Album image could not be updated", http.StatusInternalServerError)
 				return
 			}
 		}
 
 		if oldImage != nil {
-			l.Debug().Msg("Cleaning up old image file...")
+			l.Debug().Msg("ReplaceImageHandler: Cleaning up old image file")
 			err = catalog.DeleteImage(*oldImage)
 			if err != nil {
-				l.Err(err).Msg("Failed to delete old image file")
+				l.Err(err).Msg("ReplaceImageHandler: Failed to delete old image file")
 				utils.WriteError(w, "Could not delete old image file", http.StatusInternalServerError)
 				return
 			}
 		}
 
+		l.Debug().Msg("ReplaceImageHandler: Successfully replaced image")
 		utils.WriteJSON(w, http.StatusOK, ReplaceImageResponse{
 			Success: true,
 			Image:   id.String(),

engine/handlers/replace_image_test.go

@@ -1 +0,0 @@
-package handlers_test

engine/handlers/search.go

@@ -21,6 +21,9 @@ func SearchHandler(store db.DB) http.HandlerFunc {
 		l := logger.FromContext(ctx)
 		q := r.URL.Query().Get("q")
 		artists, err := store.SearchArtists(ctx, q)
+
+		l.Debug().Msgf("SearchHandler: Received search with query: %s", r.URL.Query().Encode())
+
 		if err != nil {
 			l.Err(err).Msg("Failed to search for artists")
 			utils.WriteError(w, "failed to search in database", http.StatusInternalServerError)

engine/handlers/stats.go

@@ -20,6 +20,9 @@ type StatsResponse struct {
 func StatsHandler(store db.DB) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		l := logger.FromContext(r.Context())
+
+		l.Debug().Msg("StatsHandler: Received request to retrieve statistics")
+
 		var period db.Period
 		switch strings.ToLower(r.URL.Query().Get("period")) {
 		case "day":
@@ -33,39 +36,48 @@ func StatsHandler(store db.DB) http.HandlerFunc {
 		case "all_time":
 			period = db.PeriodAllTime
 		default:
-			l.Debug().Msgf("Using default value '%s' for period", db.PeriodDay)
+			l.Debug().Msgf("StatsHandler: Using default value '%s' for period", db.PeriodDay)
 			period = db.PeriodDay
 		}
+
+		l.Debug().Msgf("StatsHandler: Fetching statistics for period '%s'", period)
+
 		listens, err := store.CountListens(r.Context(), period)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("StatsHandler: Failed to fetch listen count")
 			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
 		tracks, err := store.CountTracks(r.Context(), period)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("StatsHandler: Failed to fetch track count")
-			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError)
+			utils.WriteError(w, "failed to get tracks: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
 		albums, err := store.CountAlbums(r.Context(), period)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("StatsHandler: Failed to fetch album count")
-			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError)
+			utils.WriteError(w, "failed to get albums: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
 		artists, err := store.CountArtists(r.Context(), period)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("StatsHandler: Failed to fetch artist count")
-			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError)
+			utils.WriteError(w, "failed to get artists: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
 		timeListenedS, err := store.CountTimeListened(r.Context(), period)
 		if err != nil {
-			l.Err(err).Send()
+			l.Err(err).Msg("StatsHandler: Failed to fetch time listened")
-			utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError)
+			utils.WriteError(w, "failed to get time listened: "+err.Error(), http.StatusInternalServerError)
 			return
 		}
+
+		l.Debug().Msg("StatsHandler: Successfully fetched statistics")
 		utils.WriteJSON(w, http.StatusOK, StatsResponse{
 			ListenCount:   listens,
 			TrackCount:    tracks,

internal/catalog/catalog.go

@@ -95,6 +95,7 @@ func SubmitListen(ctx context.Context, store db.DB, opts SubmitListenOpts) error
 		l.Error().Err(err).Msg("Failed to associate release group to listen")
 		return err
 	}
+	l.Debug().Any("album", rg).Msg("Matched listen to release")
 
 	// ensure artists are associated with release group
 	store.AddArtistsToAlbum(ctx, db.AddArtistsToAlbumOpts{
@@ -114,6 +115,7 @@ func SubmitListen(ctx context.Context, store db.DB, opts SubmitListenOpts) error
 		l.Error().Err(err).Msg("Failed to associate track to listen")
 		return err
 	}
+	l.Debug().Any("track", track).Msg("Matched listen to track")
 
 	if track.Duration == 0 && opts.Duration != 0 {
 		err := store.UpdateTrack(ctx, db.UpdateTrackOpts{
@@ -123,6 +125,7 @@ func SubmitListen(ctx context.Context, store db.DB, opts SubmitListenOpts) error
 		if err != nil {
 			l.Err(err).Msgf("Failed to update duration for track %s", track.Title)
 		}
+		l.Info().Msgf("Duration updated to %d for track '%s'", opts.Duration, track.Title)
 	}
 
 	if opts.SkipSaveListen {