From e92733823db61e5b1b21d8a136be974b3ef73dd3 Mon Sep 17 00:00:00 2001 From: Gabe Farrell Date: Fri, 13 Jun 2025 18:29:08 -0400 Subject: [PATCH] chore: expand debug logging + embeddable version --- cmd/api/main.go | 3 + engine/engine.go | 82 ++++++++++------- engine/engine_test.go | 2 +- engine/handlers/alias.go | 77 +++++++++++----- engine/handlers/apikeys.go | 50 ++++++++--- engine/handlers/auth.go | 48 +++++++--- engine/handlers/delete.go | 44 ++++++++-- engine/handlers/get_album.go | 21 ++++- engine/handlers/get_artist.go | 21 ++++- engine/handlers/get_listen_activity.go | 62 ++++++++++--- engine/handlers/get_listens.go | 16 +++- engine/handlers/get_top_albums.go | 16 +++- engine/handlers/get_top_artists.go | 16 +++- engine/handlers/get_top_tracks.go | 16 +++- engine/handlers/get_track.go | 22 ++++- engine/handlers/handlers.go | 13 ++- engine/handlers/image_handler.go | 117 ++++++------------------- engine/handlers/lbz_submit_listen.go | 46 +++++----- engine/handlers/lbz_validate.go | 7 +- engine/handlers/merge.go | 53 +++++++---- engine/handlers/replace_image.go | 41 ++++++--- engine/handlers/replace_image_test.go | 1 - engine/handlers/search.go | 3 + engine/handlers/stats.go | 32 ++++--- internal/catalog/catalog.go | 3 + 25 files changed, 536 insertions(+), 276 deletions(-) delete mode 100644 engine/handlers/replace_image_test.go diff --git a/cmd/api/main.go b/cmd/api/main.go index cbb9238..54a3076 100644 --- a/cmd/api/main.go +++ b/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) diff --git a/engine/engine.go b/engine/engine.go index f53355a..264cad0 100644 --- a/engine/engine.go +++ b/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 - l.Info().Msg("listening on " + cfg.ListenAddr()) + ready.Store(true) + 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 } diff --git a/engine/engine_test.go b/engine/engine_test.go index c18061c..d93977e 100644 --- a/engine/engine_test.go +++ b/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++ { diff --git a/engine/handlers/alias.go b/engine/handlers/alias.go index 7637571..e84377b 100644 --- a/engine/handlers/alias.go +++ b/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 == "" { - utils.WriteError(w, "artist_id, album_id, or track_id must be provided", http.StatusBadRequest) + 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 } - 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 } diff --git a/engine/handlers/apikeys.go b/engine/handlers/apikeys.go index 9c61346..1a3458b 100644 --- a/engine/handlers/apikeys.go +++ b/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) } } diff --git a/engine/handlers/auth.go b/engine/handlers/auth.go index e4cc5cc..c8edce6 100644 --- a/engine/handlers/auth.go +++ b/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) } } diff --git a/engine/handlers/delete.go b/engine/handlers/delete.go index 1b99325..bb87157 100644 --- a/engine/handlers/delete.go +++ b/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) } } diff --git a/engine/handlers/get_album.go b/engine/handlers/get_album.go index 9d773c1..8c9c8ca 100644 --- a/engine/handlers/get_album.go +++ b/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) } } diff --git a/engine/handlers/get_artist.go b/engine/handlers/get_artist.go index bac18d8..67bb6b6 100644 --- a/engine/handlers/get_artist.go +++ b/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) } } diff --git a/engine/handlers/get_listen_activity.go b/engine/handlers/get_listen_activity.go index 6d3f91c..86cf71a 100644 --- a/engine/handlers/get_listen_activity.go +++ b/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() - utils.WriteError(w, err.Error(), 500) + l.Err(err).Msg("GetListenActivityHandler: Failed to retrieve listen activity") + 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) } } diff --git a/engine/handlers/get_listens.go b/engine/handlers/get_listens.go index 405acaa..a522bc2 100644 --- a/engine/handlers/get_listens.go +++ b/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() - utils.WriteError(w, "failed to get listens: "+err.Error(), 400) + l.Err(err).Msg("GetListensHandler: Failed to retrieve listens") + 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) } } diff --git a/engine/handlers/get_top_albums.go b/engine/handlers/get_top_albums.go index bdda30c..7b9870f 100644 --- a/engine/handlers/get_top_albums.go +++ b/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") - utils.WriteError(w, "failed to get albums", 400) + l.Err(err).Msg("GetTopAlbumsHandler: Failed to retrieve top albums") + utils.WriteError(w, "failed to get albums", http.StatusBadRequest) return } + + l.Debug().Msg("GetTopAlbumsHandler: Successfully retrieved top albums") utils.WriteJSON(w, http.StatusOK, albums) } } diff --git a/engine/handlers/get_top_artists.go b/engine/handlers/get_top_artists.go index 9700d23..ffec344 100644 --- a/engine/handlers/get_top_artists.go +++ b/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") - utils.WriteError(w, "failed to get artists", 400) + l.Err(err).Msg("GetTopArtistsHandler: Failed to retrieve top artists") + utils.WriteError(w, "failed to get artists", http.StatusBadRequest) return } + + l.Debug().Msg("GetTopArtistsHandler: Successfully retrieved top artists") utils.WriteJSON(w, http.StatusOK, artists) } } diff --git a/engine/handlers/get_top_tracks.go b/engine/handlers/get_top_tracks.go index 5937f2b..61f4103 100644 --- a/engine/handlers/get_top_tracks.go +++ b/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") - utils.WriteError(w, "failed to get tracks", 400) + l.Err(err).Msg("GetTopTracksHandler: Failed to retrieve top tracks") + utils.WriteError(w, "failed to get tracks", http.StatusBadRequest) return } + + l.Debug().Msg("GetTopTracksHandler: Successfully retrieved top tracks") utils.WriteJSON(w, http.StatusOK, tracks) } } diff --git a/engine/handlers/get_track.go b/engine/handlers/get_track.go index d97c8be..8fe5753 100644 --- a/engine/handlers/get_track.go +++ b/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) } } diff --git a/engine/handlers/handlers.go b/engine/handlers/handlers.go index 946b6b0..28908f6 100644 --- a/engine/handlers/handlers.go +++ b/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, diff --git a/engine/handlers/image_handler.go b/engine/handlers/image_handler.go index 6e67d40..84d8681 100644 --- a/engine/handlers/image_handler.go +++ b/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") - // file doesn't exist in desired size + l.Debug().Msg("ImageHandler: Image not found in desired size, attempting to retrieve source image") 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("Failed to access source image file") + l.Err(err).Msg("ImageHandler: Failed to access source image file at large size") w.WriteHeader(http.StatusInternalServerError) return } sourcePath = largeSizePath } else if err != nil { - // non-not found error for full file - l.Err(err).Msg("Failed to access source image file") + l.Err(err).Msg("ImageHandler: Failed to access source image file at full size") w.WriteHeader(http.StatusInternalServerError) return } else { sourcePath = fullSizePath } - // source size file was found - - // create and cache image at desired size + l.Debug().Msgf("ImageHandler: Found source image file at path '%s'", sourcePath) 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("Failed to access desired image file") + l.Err(err).Msg("ImageHandler: 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.Error().Err(err).Msg("Error when attempting to read default image in cache") + l.Err(err).Msg("serveDefaultImage: 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.Error().Err(err).Msg("Error when attempting to read default image in cache") + l.Err(err).Msg("serveDefaultImage: 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) -// } -// } diff --git a/engine/handlers/lbz_submit_listen.go b/engine/handlers/lbz_submit_listen.go index 53d79e6..6a0dad1 100644 --- a/engine/handlers/lbz_submit_listen.go +++ b/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.Error().Err(err).Send() + l.Err(err).Msg("doLbzRelay: Failed to build ListenBrainz relay request") 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 } } diff --git a/engine/handlers/lbz_validate.go b/engine/handlers/lbz_validate.go index 583ff5f..6e48626 100644 --- a/engine/handlers/lbz_validate.go +++ b/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 diff --git a/engine/handlers/merge.go b/engine/handlers/merge.go index f11e251..03e83b8 100644 --- a/engine/handlers/merge.go +++ b/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() - utils.WriteError(w, "from_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeTracksHandler: Invalid from_id parameter") + 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() - utils.WriteError(w, "to_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeTracksHandler: Invalid to_id parameter") + 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() - utils.WriteError(w, "from_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeReleaseGroupsHandler: Invalid from_id parameter") + 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() - utils.WriteError(w, "to_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeReleaseGroupsHandler: Invalid to_id parameter") + 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() - utils.WriteError(w, "Failed to merge albums: "+err.Error(), http.StatusInternalServerError) + l.Err(err).Msg("MergeReleaseGroupsHandler: Failed to merge release groups") + 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() - utils.WriteError(w, "from_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeArtistsHandler: Invalid from_id parameter") + 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() - utils.WriteError(w, "to_id is invalid", 400) + l.Debug().AnErr("error", err).Msg("MergeArtistsHandler: Invalid to_id parameter") + 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) } } diff --git a/engine/handlers/replace_image.go b/engine/handlers/replace_image.go index 007a3a0..66c0bbe 100644 --- a/engine/handlers/replace_image.go +++ b/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(), diff --git a/engine/handlers/replace_image_test.go b/engine/handlers/replace_image_test.go deleted file mode 100644 index 4a0e3ad..0000000 --- a/engine/handlers/replace_image_test.go +++ /dev/null @@ -1 +0,0 @@ -package handlers_test diff --git a/engine/handlers/search.go b/engine/handlers/search.go index 51d5a3c..9f29c75 100644 --- a/engine/handlers/search.go +++ b/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) diff --git a/engine/handlers/stats.go b/engine/handlers/stats.go index 107426a..3e01816 100644 --- a/engine/handlers/stats.go +++ b/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() - utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError) + l.Err(err).Msg("StatsHandler: Failed to fetch track count") + 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() - utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError) + l.Err(err).Msg("StatsHandler: Failed to fetch album count") + 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() - utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError) + l.Err(err).Msg("StatsHandler: Failed to fetch artist count") + 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() - utils.WriteError(w, "failed to get listens: "+err.Error(), http.StatusInternalServerError) + l.Err(err).Msg("StatsHandler: Failed to fetch time listened") + 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, diff --git a/internal/catalog/catalog.go b/internal/catalog/catalog.go index 495104d..e7d3641 100644 --- a/internal/catalog/catalog.go +++ b/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 {