diff --git a/pkg/appview/config.go b/pkg/appview/config.go index 122f056..1a3e438 100644 --- a/pkg/appview/config.go +++ b/pkg/appview/config.go @@ -9,6 +9,7 @@ import ( "crypto/rand" "encoding/hex" "fmt" + "log/slog" "net/url" "os" "strconv" @@ -339,7 +340,7 @@ func getDurationOrDefault(envKey string, defaultValue time.Duration) time.Durati parsed, err := time.ParseDuration(envVal) if err != nil { - fmt.Printf("Warning: Invalid %s '%s', using default %s\n", envKey, envVal, defaultValue) + slog.Warn("Invalid duration, using default", "env_key", envKey, "env_value", envVal, "default", defaultValue) return defaultValue } diff --git a/pkg/appview/db/readonly.go b/pkg/appview/db/readonly.go index 786cc96..3cae1f7 100644 --- a/pkg/appview/db/readonly.go +++ b/pkg/appview/db/readonly.go @@ -3,7 +3,7 @@ package db import ( "context" "database/sql" - "fmt" + "log/slog" "os" "path/filepath" "time" @@ -35,7 +35,7 @@ func readOnlyAuthorizerCallback(action int, arg1, arg2, dbName string) int { action == sqlite3.SQLITE_INSERT || action == sqlite3.SQLITE_DELETE || action == sqlite3.SQLITE_SELECT { if sensitiveTables[tableName] { - fmt.Printf("SECURITY: Blocked access to sensitive table '%s' (action=%d)\n", tableName, action) + slog.Warn("Blocked access to sensitive table", "component", "SECURITY", "table", tableName, "action", action) return sqlite3.SQLITE_DENY } } @@ -65,14 +65,14 @@ func InitializeDatabase(uiEnabled bool, dbPath string) (*sql.DB, *sql.DB, *Sessi // Ensure directory exists dbDir := filepath.Dir(dbPath) if err := os.MkdirAll(dbDir, 0700); err != nil { - fmt.Printf("Warning: Failed to create UI database directory: %v\n", err) + slog.Warn("Failed to create UI database directory", "error", err) return nil, nil, nil } // Initialize read-write database (for writes and auth operations) database, err := InitDB(dbPath) if err != nil { - fmt.Printf("Warning: Failed to initialize UI database: %v\n", err) + slog.Warn("Failed to initialize UI database", "error", err) return nil, nil, nil } @@ -81,11 +81,11 @@ func InitializeDatabase(uiEnabled bool, dbPath string) (*sql.DB, *sql.DB, *Sessi // This prevents accidental writes and blocks access to sensitive tables even if SQL injection occurs readOnlyDB, err := sql.Open(ReadOnlyDriverName, "file:"+dbPath+"?mode=ro") if err != nil { - fmt.Printf("Warning: Failed to open read-only database connection: %v\n", err) + slog.Warn("Failed to open read-only database connection", "error", err) return nil, nil, nil } - fmt.Printf("UI database (readonly) initialized at %s\n", dbPath) + slog.Info("UI database initialized", "mode", "readonly", "path", dbPath) // Create SQLite-backed session store sessionStore := NewSessionStore(database) diff --git a/pkg/appview/db/schema.go b/pkg/appview/db/schema.go index 37aab14..1a44026 100644 --- a/pkg/appview/db/schema.go +++ b/pkg/appview/db/schema.go @@ -9,6 +9,7 @@ import ( "embed" "fmt" "io/fs" + "log/slog" "path/filepath" "sort" "strconv" @@ -84,7 +85,7 @@ func runMigrations(db *sql.DB) error { } // Apply migration - fmt.Printf("Applying migration %d: %s\n%s\n", m.Version, m.Name, m.Description) + slog.Info("Applying migration", "version", m.Version, "name", m.Name, "description", m.Description) if _, err := db.Exec(m.Query); err != nil { return fmt.Errorf("failed to apply migration %d (%s): %w", m.Version, m.Name, err) } @@ -94,7 +95,7 @@ func runMigrations(db *sql.DB) error { return fmt.Errorf("failed to record migration %d: %w", m.Version, err) } - fmt.Printf("Migration %d applied successfully\n", m.Version) + slog.Info("Migration applied successfully", "version", m.Version) } return nil diff --git a/pkg/appview/db/session_store.go b/pkg/appview/db/session_store.go index 42d92ab..67c19c6 100644 --- a/pkg/appview/db/session_store.go +++ b/pkg/appview/db/session_store.go @@ -6,6 +6,7 @@ import ( "database/sql" "encoding/base64" "fmt" + "log/slog" "net/http" "time" ) @@ -83,7 +84,7 @@ func (s *SessionStore) Get(id string) (*Session, bool) { return nil, false } if err != nil { - fmt.Printf("Warning: Failed to query session: %v\n", err) + slog.Warn("Failed to query session", "error", err) return nil, false } @@ -124,7 +125,7 @@ func (s *SessionStore) Delete(id string) { `, id) if err != nil { - fmt.Printf("Warning: Failed to delete session: %v\n", err) + slog.Warn("Failed to delete session", "error", err) } } @@ -136,13 +137,13 @@ func (s *SessionStore) DeleteByDID(did string) { `, did) if err != nil { - fmt.Printf("Warning: Failed to delete sessions for DID %s: %v\n", did, err) + slog.Warn("Failed to delete sessions for DID", "did", did, "error", err) return } deleted, _ := result.RowsAffected() if deleted > 0 { - fmt.Printf("Deleted %d UI session(s) for DID %s due to OAuth failure\n", deleted, did) + slog.Info("Deleted UI sessions for DID due to OAuth failure", "count", deleted, "did", did) } } @@ -154,13 +155,13 @@ func (s *SessionStore) Cleanup() { `) if err != nil { - fmt.Printf("Warning: Failed to cleanup sessions: %v\n", err) + slog.Warn("Failed to cleanup sessions", "error", err) return } deleted, _ := result.RowsAffected() if deleted > 0 { - fmt.Printf("Cleaned up %d expired UI sessions\n", deleted) + slog.Info("Cleaned up expired UI sessions", "count", deleted) } } @@ -177,7 +178,7 @@ func (s *SessionStore) CleanupContext(ctx context.Context) error { deleted, _ := result.RowsAffected() if deleted > 0 { - fmt.Printf("Cleaned up %d expired UI sessions\n", deleted) + slog.Info("Cleaned up expired UI sessions", "count", deleted) } return nil diff --git a/pkg/appview/handlers/api.go b/pkg/appview/handlers/api.go index 90d0df8..16611e2 100644 --- a/pkg/appview/handlers/api.go +++ b/pkg/appview/handlers/api.go @@ -6,7 +6,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "net/http" "atcr.io/pkg/appview/db" @@ -41,16 +41,16 @@ func (h *StarRepositoryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request // Resolve owner's handle to DID ownerDID, err := resolveIdentityToDID(r.Context(), h.Directory, handle) if err != nil { - log.Printf("StarRepository: Failed to resolve handle %s: %v", handle, err) + slog.Warn("Failed to resolve handle for star", "handle", handle, "error", err) http.Error(w, fmt.Sprintf("Failed to resolve handle: %v", err), http.StatusBadRequest) return } // Get OAuth session for the authenticated user - log.Printf("StarRepository: Getting OAuth session for user DID %s", user.DID) + slog.Debug("Getting OAuth session for star", "user_did", user.DID) session, err := h.Refresher.GetSession(r.Context(), user.DID) if err != nil { - log.Printf("StarRepository: Failed to get OAuth session for %s: %v", user.DID, err) + slog.Warn("Failed to get OAuth session for star", "user_did", user.DID, "error", err) http.Error(w, fmt.Sprintf("Failed to get OAuth session: %v", err), http.StatusUnauthorized) return } @@ -66,7 +66,7 @@ func (h *StarRepositoryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request // Write star record to user's PDS _, err = pdsClient.PutRecord(r.Context(), atproto.StarCollection, rkey, starRecord) if err != nil { - log.Printf("StarRepository: Failed to create star record: %v", err) + slog.Error("Failed to create star record", "error", err) http.Error(w, fmt.Sprintf("Failed to create star: %v", err), http.StatusInternalServerError) return } @@ -100,16 +100,16 @@ func (h *UnstarRepositoryHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Resolve owner's handle to DID ownerDID, err := resolveIdentityToDID(r.Context(), h.Directory, handle) if err != nil { - log.Printf("UnstarRepository: Failed to resolve handle %s: %v", handle, err) + slog.Warn("Failed to resolve handle for unstar", "handle", handle, "error", err) http.Error(w, fmt.Sprintf("Failed to resolve handle: %v", err), http.StatusBadRequest) return } // Get OAuth session for the authenticated user - log.Printf("UnstarRepository: Getting OAuth session for user DID %s", user.DID) + slog.Debug("Getting OAuth session for unstar", "user_did", user.DID) session, err := h.Refresher.GetSession(r.Context(), user.DID) if err != nil { - log.Printf("UnstarRepository: Failed to get OAuth session for %s: %v", user.DID, err) + slog.Warn("Failed to get OAuth session for unstar", "user_did", user.DID, "error", err) http.Error(w, fmt.Sprintf("Failed to get OAuth session: %v", err), http.StatusUnauthorized) return } @@ -120,16 +120,16 @@ func (h *UnstarRepositoryHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Delete star record from user's PDS rkey := atproto.StarRecordKey(ownerDID, repository) - log.Printf("UnstarRepository: Deleting star record for %s/%s (rkey: %s)", handle, repository, rkey) + slog.Debug("Deleting star record", "handle", handle, "repository", repository, "rkey", rkey) err = pdsClient.DeleteRecord(r.Context(), atproto.StarCollection, rkey) if err != nil { // If record doesn't exist, still return success (idempotent) if !errors.Is(err, atproto.ErrRecordNotFound) { - log.Printf("UnstarRepository: Failed to delete star record: %v", err) + slog.Error("Failed to delete star record", "error", err) http.Error(w, fmt.Sprintf("Failed to delete star: %v", err), http.StatusInternalServerError) return } - log.Printf("UnstarRepository: Star record not found (already unstarred)") + slog.Debug("Star record not found, already unstarred") } // Return success @@ -162,7 +162,7 @@ func (h *CheckStarHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Resolve owner's handle to DID ownerDID, err := resolveIdentityToDID(r.Context(), h.Directory, handle) if err != nil { - log.Printf("CheckStar: Failed to resolve handle %s: %v", handle, err) + slog.Warn("Failed to resolve handle for check star", "handle", handle, "error", err) http.Error(w, fmt.Sprintf("Failed to resolve handle: %v", err), http.StatusBadRequest) return } @@ -170,7 +170,7 @@ func (h *CheckStarHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Get OAuth session for the authenticated user session, err := h.Refresher.GetSession(r.Context(), user.DID) if err != nil { - log.Printf("CheckStar: Failed to get OAuth session for %s: %v", user.DID, err) + slog.Debug("Failed to get OAuth session for check star", "user_did", user.DID, "error", err) // No OAuth session - return not starred w.Header().Set("Content-Type", "application/json") json.NewEncoder(w).Encode(map[string]bool{"starred": false}) @@ -250,7 +250,7 @@ func (h *ManifestDetailHandler) ServeHTTP(w http.ResponseWriter, r *http.Request http.Error(w, "Manifest not found", http.StatusNotFound) return } - log.Printf("GetManifestDetail error: %v", err) + slog.Error("Failed to get manifest detail", "error", err) http.Error(w, "Failed to fetch manifest", http.StatusInternalServerError) return } diff --git a/pkg/appview/handlers/auth.go b/pkg/appview/handlers/auth.go index b215345..4aaea70 100644 --- a/pkg/appview/handlers/auth.go +++ b/pkg/appview/handlers/auth.go @@ -1,8 +1,8 @@ package handlers import ( - "fmt" "html/template" + "log/slog" "net/http" ) @@ -13,7 +13,7 @@ type LoginHandler struct { func (h *LoginHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { returnTo := r.URL.Query().Get("return_to") - fmt.Printf("DEBUG [login]: GET request. return_to param=%s, full query=%s\n", returnTo, r.URL.RawQuery) + slog.Debug("Login GET request", "return_to", returnTo, "query", r.URL.RawQuery) if returnTo == "" { returnTo = "/" } diff --git a/pkg/appview/handlers/logout.go b/pkg/appview/handlers/logout.go index f378c95..cd567a5 100644 --- a/pkg/appview/handlers/logout.go +++ b/pkg/appview/handlers/logout.go @@ -1,7 +1,7 @@ package handlers import ( - "fmt" + "log/slog" "net/http" "atcr.io/pkg/appview/db" @@ -32,28 +32,28 @@ func (h *LogoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Parse DID for OAuth logout did, err := syntax.ParseDID(uiSession.DID) if err != nil { - fmt.Printf("WARNING [logout]: Failed to parse DID %s: %v\n", uiSession.DID, err) + slog.Warn("Failed to parse DID for logout", "component", "logout", "did", uiSession.DID, "error", err) } else { // Attempt to revoke OAuth tokens on PDS side if uiSession.OAuthSessionID != "" { // Call indigo's Logout to revoke tokens on PDS if err := h.OAuthApp.GetClientApp().Logout(r.Context(), did, uiSession.OAuthSessionID); err != nil { // Log error but don't block logout - best effort revocation - fmt.Printf("WARNING [logout]: Failed to revoke OAuth tokens for %s on PDS: %v\n", uiSession.DID, err) + slog.Warn("Failed to revoke OAuth tokens on PDS", "component", "logout", "did", uiSession.DID, "error", err) } else { - fmt.Printf("INFO [logout]: Successfully revoked OAuth tokens for %s on PDS\n", uiSession.DID) + slog.Info("Successfully revoked OAuth tokens on PDS", "component", "logout", "did", uiSession.DID) } // Invalidate refresher cache to clear local access tokens h.Refresher.InvalidateSession(uiSession.DID) - fmt.Printf("INFO [logout]: Invalidated local OAuth cache for %s\n", uiSession.DID) + slog.Info("Invalidated local OAuth cache", "component", "logout", "did", uiSession.DID) // Delete OAuth session from database (cleanup, might already be done by Logout) if err := h.OAuthStore.DeleteSession(r.Context(), did, uiSession.OAuthSessionID); err != nil { - fmt.Printf("WARNING [logout]: Failed to delete OAuth session from database: %v\n", err) + slog.Warn("Failed to delete OAuth session from database", "component", "logout", "error", err) } } else { - fmt.Printf("WARNING [logout]: No OAuth session ID found for user %s\n", uiSession.DID) + slog.Warn("No OAuth session ID found for user", "component", "logout", "did", uiSession.DID) } } } diff --git a/pkg/appview/handlers/repository.go b/pkg/appview/handlers/repository.go index c363058..8a30bf1 100644 --- a/pkg/appview/handlers/repository.go +++ b/pkg/appview/handlers/repository.go @@ -4,7 +4,7 @@ import ( "context" "database/sql" "html/template" - "log" + "log/slog" "net/http" "sync" "time" @@ -139,7 +139,7 @@ func (h *RepositoryPageHandler) ServeHTTP(w http.ResponseWriter, r *http.Request // Fetch repository metadata from annotations table metadata, err := db.GetRepositoryMetadata(h.DB, owner.DID, repository) if err != nil { - log.Printf("Failed to fetch repository metadata: %v", err) + slog.Warn("Failed to fetch repository metadata", "error", err) // Continue without metadata on error } else { repo.Title = metadata["org.opencontainers.image.title"] @@ -155,7 +155,7 @@ func (h *RepositoryPageHandler) ServeHTTP(w http.ResponseWriter, r *http.Request // Fetch star count stats, err := db.GetRepositoryStats(h.DB, owner.DID, repository) if err != nil { - log.Printf("Failed to fetch repository stats: %v", err) + slog.Warn("Failed to fetch repository stats", "error", err) // Continue with zero stats on error stats = &db.RepositoryStats{StarCount: 0} } @@ -193,7 +193,7 @@ func (h *RepositoryPageHandler) ServeHTTP(w http.ResponseWriter, r *http.Request html, err := h.ReadmeCache.Get(ctx, repo.ReadmeURL) if err != nil { - log.Printf("Failed to fetch README from %s: %v", repo.ReadmeURL, err) + slog.Warn("Failed to fetch README", "url", repo.ReadmeURL, "error", err) // Continue without README on error } else { readmeHTML = template.HTML(html) diff --git a/pkg/appview/handlers/settings.go b/pkg/appview/handlers/settings.go index 21548cc..c7d9e48 100644 --- a/pkg/appview/handlers/settings.go +++ b/pkg/appview/handlers/settings.go @@ -1,8 +1,8 @@ package handlers import ( - "fmt" "html/template" + "log/slog" "net/http" "time" @@ -30,7 +30,7 @@ func (h *SettingsHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { session, err := h.Refresher.GetSession(r.Context(), user.DID) if err != nil { // OAuth session not found or expired - redirect to re-authenticate - fmt.Printf("WARNING [settings]: OAuth session not found for %s: %v - redirecting to login\n", user.DID, err) + slog.Warn("OAuth session not found, redirecting to login", "component", "settings", "did", user.DID, "error", err) http.Redirect(w, r, "/auth/oauth/login?return_to=/settings", http.StatusFound) return } @@ -45,19 +45,19 @@ func (h *SettingsHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { profile, err := storage.GetProfile(r.Context(), client) if err != nil { // Error fetching profile - log out user - fmt.Printf("WARNING [settings]: Failed to fetch profile for %s: %v - logging out\n", user.DID, err) + slog.Warn("Failed to fetch profile, logging out", "component", "settings", "did", user.DID, "error", err) http.Redirect(w, r, "/auth/logout", http.StatusFound) return } if profile == nil { // Profile doesn't exist yet (404) - user needs to log out and back in to create it - fmt.Printf("WARNING [settings]: Profile doesn't exist for %s - logging out\n", user.DID) + slog.Warn("Profile doesn't exist, logging out", "component", "settings", "did", user.DID) http.Redirect(w, r, "/auth/logout", http.StatusFound) return } - fmt.Printf("DEBUG [settings]: Fetched profile for %s: defaultHold=%s\n", user.DID, profile.DefaultHold) + slog.Debug("Fetched profile", "component", "settings", "did", user.DID, "default_hold", profile.DefaultHold) data := struct { PageData @@ -100,7 +100,7 @@ func (h *UpdateDefaultHoldHandler) ServeHTTP(w http.ResponseWriter, r *http.Requ session, err := h.Refresher.GetSession(r.Context(), user.DID) if err != nil { // OAuth session not found or expired - redirect to re-authenticate - fmt.Printf("WARNING [settings]: OAuth session not found for %s: %v - redirecting to login\n", user.DID, err) + slog.Warn("OAuth session not found, redirecting to login", "component", "settings", "did", user.DID, "error", err) http.Redirect(w, r, "/auth/oauth/login?return_to=/settings", http.StatusFound) return } diff --git a/pkg/appview/holdhealth/worker.go b/pkg/appview/holdhealth/worker.go index e094fdf..f65e694 100644 --- a/pkg/appview/holdhealth/worker.go +++ b/pkg/appview/holdhealth/worker.go @@ -4,7 +4,7 @@ import ( "context" "database/sql" "fmt" - "log" + "log/slog" "strings" "sync" "time" @@ -56,16 +56,16 @@ func (w *Worker) Start(ctx context.Context) { go func() { defer w.wg.Done() - log.Println("Hold health worker: Starting background health checks") + slog.Info("Hold health worker starting background health checks") // Wait for services to be ready (Docker startup race condition) if w.startupDelay > 0 { - log.Printf("Hold health worker: Waiting %s for services to be ready...", w.startupDelay) + slog.Info("Hold health worker waiting for services to be ready", "delay", w.startupDelay) select { case <-time.After(w.startupDelay): // Continue with initial check case <-ctx.Done(): - log.Println("Hold health worker: Context cancelled during startup delay") + slog.Info("Hold health worker context cancelled during startup delay") return } } @@ -76,15 +76,15 @@ func (w *Worker) Start(ctx context.Context) { for { select { case <-ctx.Done(): - log.Println("Hold health worker: Context cancelled, stopping") + slog.Info("Hold health worker context cancelled, stopping") return case <-w.stopChan: - log.Println("Hold health worker: Stop signal received") + slog.Info("Hold health worker stop signal received") return case <-w.refreshTicker.C: w.refreshAllHolds(ctx) case <-w.cleanupTicker.C: - log.Println("Hold health worker: Running cache cleanup") + slog.Info("Hold health worker running cache cleanup") w.checker.Cleanup() } } @@ -97,26 +97,26 @@ func (w *Worker) Stop() { w.refreshTicker.Stop() w.cleanupTicker.Stop() w.wg.Wait() - log.Println("Hold health worker: Stopped") + slog.Info("Hold health worker stopped") } // refreshAllHolds queries the database for unique hold endpoints and refreshes their health status func (w *Worker) refreshAllHolds(ctx context.Context) { - log.Println("Hold health worker: Starting refresh cycle") + slog.Info("Hold health worker starting refresh cycle") // Get unique hold endpoints from database endpoints, err := w.db.GetUniqueHoldEndpoints() if err != nil { - log.Printf("Hold health worker: Failed to fetch hold endpoints: %v", err) + slog.Error("Hold health worker failed to fetch hold endpoints", "error", err) return } if len(endpoints) == 0 { - log.Println("Hold health worker: No hold endpoints to check") + slog.Info("Hold health worker no hold endpoints to check") return } - log.Printf("Hold health worker: Fetched %d hold endpoint entries from database", len(endpoints)) + slog.Info("Hold health worker fetched hold endpoint entries from database", "count", len(endpoints)) // Deduplicate endpoints by normalizing to canonical DID format // This handles cases where the same hold is stored with different representations: @@ -141,7 +141,7 @@ func (w *Worker) refreshAllHolds(ctx context.Context) { uniqueEndpoints = append(uniqueEndpoints, normalizedDID) } - log.Printf("Hold health worker: Checking %d unique hold endpoints (deduplicated from %d)", len(uniqueEndpoints), len(endpoints)) + slog.Info("Hold health worker checking unique hold endpoints", "unique_count", len(uniqueEndpoints), "total_count", len(endpoints)) // Check health concurrently with rate limiting // Use a semaphore to limit concurrent requests (max 10 at a time) @@ -174,7 +174,7 @@ func (w *Worker) refreshAllHolds(ctx context.Context) { reachable++ } else { unreachable++ - log.Printf("Hold health worker: Hold unreachable: %s (error: %v)", ep, err) + slog.Warn("Hold health worker hold unreachable", "endpoint", ep, "error", err) } statsMu.Unlock() }(endpoint) @@ -183,7 +183,7 @@ func (w *Worker) refreshAllHolds(ctx context.Context) { // Wait for all checks to complete wg.Wait() - log.Printf("Hold health worker: Refresh complete - %d reachable, %d unreachable", reachable, unreachable) + slog.Info("Hold health worker refresh complete", "reachable", reachable, "unreachable", unreachable) } // DBAdapter wraps sql.DB to implement DBQuerier interface diff --git a/pkg/appview/jetstream/backfill.go b/pkg/appview/jetstream/backfill.go index 981e93c..2634704 100644 --- a/pkg/appview/jetstream/backfill.go +++ b/pkg/appview/jetstream/backfill.go @@ -5,6 +5,7 @@ import ( "database/sql" "encoding/json" "fmt" + "log/slog" "strings" "time" @@ -52,13 +53,13 @@ func NewBackfillWorker(database *sql.DB, relayEndpoint, defaultHoldDID string, t // Start runs the backfill for all ATCR collections func (b *BackfillWorker) Start(ctx context.Context) error { - fmt.Println("Backfill: Starting sync-based backfill...") + slog.Info("Backfill: Starting sync-based backfill...") // First, query and cache the default hold's captain record if b.defaultHoldDID != "" { - fmt.Printf("Backfill: Querying default hold captain record: %s\n", b.defaultHoldDID) + slog.Info("Backfill: Querying default hold captain record: %s\n", b.defaultHoldDID) if err := b.queryCaptainRecord(ctx, b.defaultHoldDID); err != nil { - fmt.Printf("WARNING: Failed to query default hold captain record: %v\n", err) + slog.Warn("Backfill: Failed to query default hold captain record: %v\n", err) // Don't fail the whole backfill - just warn } } @@ -71,16 +72,16 @@ func (b *BackfillWorker) Start(ctx context.Context) error { } for _, collection := range collections { - fmt.Printf("Backfill: Processing collection: %s\n", collection) + slog.Info("Backfill: Processing collection: %s\n", collection) if err := b.backfillCollection(ctx, collection); err != nil { return fmt.Errorf("failed to backfill collection %s: %w", collection, err) } - fmt.Printf("Backfill: Completed collection: %s\n", collection) + slog.Info("Backfill: Completed collection: %s\n", collection) } - fmt.Println("Backfill: All collections completed!") + slog.Info("Backfill: All collections completed!") return nil } @@ -98,13 +99,13 @@ func (b *BackfillWorker) backfillCollection(ctx context.Context, collection stri return fmt.Errorf("failed to list repos: %w", err) } - fmt.Printf("Backfill: Found %d repos with %s (cursor: %s)\n", len(result.Repos), collection, repoCursor) + slog.Info("Backfill: Found %d repos with %s (cursor: %s)\n", len(result.Repos), collection, repoCursor) // Process each repo (DID) for _, repo := range result.Repos { recordCount, err := b.backfillRepo(ctx, repo.DID, collection) if err != nil { - fmt.Printf("WARNING: Failed to backfill repo %s: %v\n", repo.DID, err) + slog.Warn("Backfill: Failed to backfill repo %s: %v\n", repo.DID, err) continue } @@ -112,7 +113,7 @@ func (b *BackfillWorker) backfillCollection(ctx context.Context, collection stri processedRecords += recordCount if processedRepos%10 == 0 { - fmt.Printf("Backfill: Progress - %d repos, %d records\n", processedRepos, processedRecords) + slog.Info("Backfill: Progress - %d repos, %d records\n", processedRepos, processedRecords) } } @@ -124,7 +125,7 @@ func (b *BackfillWorker) backfillCollection(ctx context.Context, collection stri repoCursor = result.Cursor } - fmt.Printf("Backfill: Collection %s complete - %d repos, %d records\n", collection, processedRepos, processedRecords) + slog.Info("Backfill: Collection %s complete - %d repos, %d records\n", collection, processedRepos, processedRecords) return nil } @@ -196,7 +197,7 @@ func (b *BackfillWorker) backfillRepo(ctx context.Context, did, collection strin } if err := b.processRecord(ctx, did, collection, &record); err != nil { - fmt.Printf("WARNING: Failed to process record %s: %v\n", record.URI, err) + slog.Warn("Backfill: Failed to process record %s: %v\n", record.URI, err) continue } recordCount++ @@ -212,19 +213,19 @@ func (b *BackfillWorker) backfillRepo(ctx context.Context, did, collection strin // Reconcile deletions - remove records from DB that no longer exist on PDS if err := b.reconcileDeletions(did, collection, foundManifestDigests, foundTags, foundStars); err != nil { - fmt.Printf("WARNING: Failed to reconcile deletions for %s: %v\n", did, err) + slog.Warn("Backfill: Failed to reconcile deletions for %s: %v\n", did, err) } // After processing manifests, clean up orphaned tags (tags pointing to non-existent manifests) if collection == atproto.ManifestCollection { if err := db.CleanupOrphanedTags(b.db, did); err != nil { - fmt.Printf("WARNING: Failed to cleanup orphaned tags for %s: %v\n", did, err) + slog.Warn("Backfill: Failed to cleanup orphaned tags for %s: %v\n", did, err) } // Reconcile annotations - ensure they come from newest manifest per repository // This fixes out-of-order backfill where older manifests can overwrite newer annotations if err := b.reconcileAnnotations(ctx, did, pdsClient); err != nil { - fmt.Printf("WARNING: Failed to reconcile annotations for %s: %v\n", did, err) + slog.Warn("Backfill: Failed to reconcile annotations for %s: %v\n", did, err) } } @@ -249,7 +250,7 @@ func (b *BackfillWorker) reconcileDeletions(did, collection string, foundManifes // Log deletions deleted := len(dbDigests) - len(foundManifestDigests) if deleted > 0 { - fmt.Printf("Backfill: Deleted %d orphaned manifests for %s\n", deleted, did) + slog.Info("Backfill: Deleted %d orphaned manifests for %s\n", deleted, did) } case atproto.TagCollection: @@ -267,7 +268,7 @@ func (b *BackfillWorker) reconcileDeletions(did, collection string, foundManifes // Log deletions deleted := len(dbTags) - len(foundTags) if deleted > 0 { - fmt.Printf("Backfill: Deleted %d orphaned tags for %s\n", deleted, did) + slog.Info("Backfill: Deleted %d orphaned tags for %s\n", deleted, did) } case atproto.StarCollection: @@ -342,7 +343,7 @@ func (b *BackfillWorker) queryCaptainRecord(ctx context.Context, holdDID string) // Retry on connection errors (hold service might still be starting) if attempt < maxRetries && strings.Contains(err.Error(), "connection refused") { - fmt.Printf("Backfill: Hold not ready (attempt %d/%d), retrying in 2s...\n", attempt, maxRetries) + slog.Info("Backfill: Hold not ready (attempt %d/%d), retrying in 2s...\n", attempt, maxRetries) time.Sleep(2 * time.Second) continue } @@ -364,7 +365,7 @@ func (b *BackfillWorker) queryCaptainRecord(ctx context.Context, holdDID string) return fmt.Errorf("failed to cache captain record: %w", err) } - fmt.Printf("Backfill: Cached captain record for hold %s (owner: %s)\n", holdDID, captainRecord.OwnerDID) + slog.Info("Backfill: Cached captain record for hold %s (owner: %s)\n", holdDID, captainRecord.OwnerDID) return nil } @@ -416,7 +417,7 @@ func (b *BackfillWorker) reconcileAnnotations(ctx context.Context, did string, p if err != nil { fmt.Printf("WARNING [backfill]: Failed to reconcile annotations for %s/%s: %v\n", did, repo, err) } else { - fmt.Printf("Backfill: Reconciled annotations for %s/%s from newest manifest %s\n", did, repo, newestManifest.Digest) + slog.Info("Backfill: Reconciled annotations for %s/%s from newest manifest %s\n", did, repo, newestManifest.Digest) } } } diff --git a/pkg/appview/jetstream/processor.go b/pkg/appview/jetstream/processor.go index f20cb0a..615bc93 100644 --- a/pkg/appview/jetstream/processor.go +++ b/pkg/appview/jetstream/processor.go @@ -5,6 +5,7 @@ import ( "database/sql" "encoding/json" "fmt" + "log/slog" "strings" "time" @@ -111,7 +112,7 @@ func (p *Processor) EnsureUser(ctx context.Context, did string) error { publicClient := atproto.NewClient("https://public.api.bsky.app", "", "") profile, err := publicClient.GetActorProfile(ctx, resolvedDID) if err != nil { - fmt.Printf("WARNING [processor]: Failed to fetch profile for DID %s: %v\n", resolvedDID, err) + slog.Warn("Failed to fetch profile", "component", "processor", "did", resolvedDID, "error", err) // Continue without avatar } else { avatar = profile.Avatar @@ -307,7 +308,7 @@ func (p *Processor) ProcessSailorProfile(ctx context.Context, did string, record // Convert hold URL/DID to canonical DID holdDID := atproto.ResolveHoldDIDFromURL(profileRecord.DefaultHold) if holdDID == "" { - fmt.Printf("WARNING [processor]: Invalid hold reference in profile for %s: %s\n", did, profileRecord.DefaultHold) + slog.Warn("Invalid hold reference in profile", "component", "processor", "did", did, "default_hold", profileRecord.DefaultHold) return nil } diff --git a/pkg/appview/jetstream/worker.go b/pkg/appview/jetstream/worker.go index ff9f930..e315fdf 100644 --- a/pkg/appview/jetstream/worker.go +++ b/pkg/appview/jetstream/worker.go @@ -8,6 +8,7 @@ import ( "database/sql" "encoding/json" "fmt" + "log/slog" "net/url" "sync" "time" @@ -89,7 +90,7 @@ func (w *Worker) Start(ctx context.Context) error { // Calculate lag (cursor is in microseconds) now := time.Now().UnixMicro() lagSeconds := float64(now-w.startCursor) / 1_000_000.0 - fmt.Printf("Jetstream: Starting from cursor %d (%.1f seconds behind live)\n", w.startCursor, lagSeconds) + slog.Info("Jetstream: Starting from cursor %d (%.1f seconds behind live)\n", w.startCursor, lagSeconds) } // Disable compression for now to debug @@ -138,7 +139,7 @@ func (w *Worker) Start(ctx context.Context) error { } defer decoder.Close() - fmt.Println("Connected to Jetstream, listening for events...") + slog.Info("Connected to Jetstream, listening for events...") // Start heartbeat ticker to show Jetstream is alive heartbeatTicker := time.NewTicker(30 * time.Second) @@ -169,7 +170,7 @@ func (w *Worker) Start(ctx context.Context) error { // If no pong for 60 seconds, connection is likely dead if timeSinceLastPong > 60*time.Second { - fmt.Printf("Jetstream: No pong received for %s (sent %d pings, got %d pongs), closing connection\n", + slog.Info("Jetstream: No pong received for %s (sent %d pings, got %d pongs), closing connection\n", timeSinceLastPong, pingsTotal, pongsTotal) conn.Close() return @@ -178,7 +179,7 @@ func (w *Worker) Start(ctx context.Context) error { // Send ping with write deadline conn.SetWriteDeadline(time.Now().Add(10 * time.Second)) if err := conn.WriteMessage(websocket.PingMessage, nil); err != nil { - fmt.Printf("Jetstream: Failed to send ping: %v\n", err) + slog.Info("Jetstream: Failed to send ping: %v\n", err) conn.Close() return } @@ -200,7 +201,7 @@ func (w *Worker) Start(ctx context.Context) error { return ctx.Err() case <-heartbeatTicker.C: elapsed := time.Since(lastHeartbeat) - fmt.Printf("Jetstream: Alive (processed %d events in last %.0fs)\n", eventCount, elapsed.Seconds()) + slog.Info("Jetstream: Alive (processed %d events in last %.0fs)\n", eventCount, elapsed.Seconds()) eventCount = 0 lastHeartbeat = time.Now() default: @@ -236,7 +237,7 @@ func (w *Worker) Start(ctx context.Context) error { } // Log detailed context about the failure - fmt.Printf("Jetstream: Connection closed after %s\n", connDuration) + slog.Info("Jetstream: Connection closed after %s\n", connDuration) fmt.Printf(" - Events in last 30s: %d\n", eventCount) fmt.Printf(" - Time since last event: %s\n", timeSinceLastEvent) fmt.Printf(" - Ping/Pong: %d/%d (%.1f%% success)\n", pongsTotal, pingsTotal, pongRate) @@ -312,15 +313,15 @@ func (w *Worker) processMessage(message []byte) error { // Process based on collection switch commit.Collection { case atproto.ManifestCollection: - fmt.Printf("Jetstream: Processing manifest event: did=%s, operation=%s, rkey=%s\n", + slog.Info("Jetstream: Processing manifest event: did=%s, operation=%s, rkey=%s\n", commit.DID, commit.Operation, commit.RKey) return w.processManifest(commit) case atproto.TagCollection: - fmt.Printf("Jetstream: Processing tag event: did=%s, operation=%s, rkey=%s\n", + slog.Info("Jetstream: Processing tag event: did=%s, operation=%s, rkey=%s\n", commit.DID, commit.Operation, commit.RKey) return w.processTag(commit) case atproto.StarCollection: - fmt.Printf("Jetstream: Processing star event: did=%s, operation=%s, rkey=%s\n", + slog.Info("Jetstream: Processing star event: did=%s, operation=%s, rkey=%s\n", commit.DID, commit.Operation, commit.RKey) return w.processStar(commit) default: @@ -372,13 +373,13 @@ func (w *Worker) processTag(commit *CommitEvent) error { if commit.Operation == "delete" { // Delete tag - decode rkey back to repository and tag repo, tag := atproto.RKeyToRepositoryTag(commit.RKey) - fmt.Printf("Jetstream: Deleting tag: did=%s, repository=%s, tag=%s (from rkey=%s)\n", + slog.Info("Jetstream: Deleting tag: did=%s, repository=%s, tag=%s (from rkey=%s)\n", commit.DID, repo, tag, commit.RKey) if err := db.DeleteTag(w.db, commit.DID, repo, tag); err != nil { - fmt.Printf("Jetstream: ERROR deleting tag: %v\n", err) + slog.Info("Jetstream: ERROR deleting tag: %v\n", err) return err } - fmt.Printf("Jetstream: Successfully deleted tag: did=%s, repository=%s, tag=%s\n", + slog.Info("Jetstream: Successfully deleted tag: did=%s, repository=%s, tag=%s\n", commit.DID, repo, tag) return nil } diff --git a/pkg/appview/middleware/registry.go b/pkg/appview/middleware/registry.go index 3a4092b..d790821 100644 --- a/pkg/appview/middleware/registry.go +++ b/pkg/appview/middleware/registry.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "strings" "sync" @@ -160,7 +161,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name return nil, fmt.Errorf("no PDS endpoint found for %s", identityStr) } - fmt.Printf("DEBUG [registry/middleware]: Resolved identity: did=%s, pds=%s, handle=%s\n", did, pdsEndpoint, handle) + slog.Debug("Resolved identity", "component", "registry/middleware", "did", did, "pds", pdsEndpoint, "handle", handle) // Query for hold DID - either user's hold or default hold service holdDID := nr.findHoldDID(ctx, did, pdsEndpoint) @@ -174,7 +175,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name // This ensures users can push immediately after docker login without web sign-in // EnsureCrewMembership is best-effort and logs errors without failing the request if holdDID != "" && nr.refresher != nil { - fmt.Printf("DEBUG [registry/middleware]: Auto-reconciling crew membership for DID=%s at hold=%s\n", did, holdDID) + slog.Debug("Auto-reconciling crew membership", "component", "registry/middleware", "did", did, "hold_did", holdDID) client := atproto.NewClient(pdsEndpoint, did, "") storage.EnsureCrewMembership(ctx, client, nr.refresher, holdDID) } @@ -185,8 +186,8 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name var err error serviceToken, err = token.GetOrFetchServiceToken(ctx, nr.refresher, did, holdDID, pdsEndpoint) if err != nil { - fmt.Printf("ERROR [registry/middleware]: Failed to get service token for DID=%s: %v\n", did, err) - fmt.Printf("ERROR [registry/middleware]: User needs to re-authenticate via credential helper\n") + slog.Error("Failed to get service token", "component", "registry/middleware", "did", did, "error", err) + slog.Error("User needs to re-authenticate via credential helper", "component", "registry/middleware") return nil, nr.authErrorMessage("OAuth session expired") } } @@ -219,7 +220,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name apiClient := session.APIClient() atprotoClient = atproto.NewClientWithIndigoClient(pdsEndpoint, did, apiClient) } else { - fmt.Printf("DEBUG [registry/middleware]: OAuth refresh failed for DID=%s: %v, falling back to Basic Auth\n", did, err) + slog.Debug("OAuth refresh failed, falling back to Basic Auth", "component", "registry/middleware", "did", did, "error", err) } } @@ -227,10 +228,10 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name if atprotoClient == nil { accessToken, ok := auth.GetGlobalTokenCache().Get(did) if !ok { - fmt.Printf("DEBUG [registry/middleware]: No cached access token found for DID=%s (neither OAuth nor Basic Auth)\n", did) + slog.Debug("No cached access token found (neither OAuth nor Basic Auth)", "component", "registry/middleware", "did", did) accessToken = "" // Will fail on manifest push, but let it try } else { - fmt.Printf("DEBUG [registry/middleware]: Using Basic Auth access token for DID=%s (length=%d)\n", did, len(accessToken)) + slog.Debug("Using Basic Auth access token", "component", "registry/middleware", "did", did, "token_length", len(accessToken)) } atprotoClient = atproto.NewClient(pdsEndpoint, did, accessToken) } @@ -304,7 +305,7 @@ func (nr *NamespaceResolver) findHoldDID(ctx context.Context, did, pdsEndpoint s profile, err := storage.GetProfile(ctx, client) if err != nil { // Error reading profile (not a 404) - log and continue - fmt.Printf("WARNING: failed to read profile for %s: %v\n", did, err) + slog.Warn("Failed to read profile", "did", did, "error", err) } if profile != nil && profile.DefaultHold != "" { @@ -314,7 +315,7 @@ func (nr *NamespaceResolver) findHoldDID(ctx context.Context, did, pdsEndpoint s if nr.isHoldReachable(ctx, profile.DefaultHold) { return profile.DefaultHold } - fmt.Printf("DEBUG [registry/middleware/testmode]: User's defaultHold %s unreachable, falling back to default\n", profile.DefaultHold) + slog.Debug("User's defaultHold unreachable, falling back to default", "component", "registry/middleware/testmode", "default_hold", profile.DefaultHold) return nr.defaultHoldDID } return profile.DefaultHold diff --git a/pkg/appview/readme/cache.go b/pkg/appview/readme/cache.go index 59b73c5..c14c730 100644 --- a/pkg/appview/readme/cache.go +++ b/pkg/appview/readme/cache.go @@ -7,7 +7,7 @@ package readme import ( "context" "database/sql" - "fmt" + "log/slog" "time" ) @@ -54,8 +54,7 @@ func (c *Cache) Get(ctx context.Context, readmeURL string) (string, error) { // Store in cache if err := c.storeInDB(readmeURL, html); err != nil { // Log error but don't fail - we have the content - // In production, you'd use proper logging here - fmt.Printf("Failed to cache README: %v\n", err) + slog.Warn("Failed to cache README", "error", err) } return html, nil diff --git a/pkg/appview/storage/manifest_store.go b/pkg/appview/storage/manifest_store.go index 2c7cc6b..a452d4e 100644 --- a/pkg/appview/storage/manifest_store.go +++ b/pkg/appview/storage/manifest_store.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "io" + "log/slog" "maps" "net/http" "strings" @@ -88,7 +89,7 @@ func (s *ManifestStore) Get(ctx context.Context, dgst digest.Digest, options ... if s.ctx.Database != nil { go func() { if err := s.ctx.Database.IncrementPullCount(s.ctx.DID, s.ctx.Repository); err != nil { - fmt.Printf("WARNING: Failed to increment pull count for %s/%s: %v\n", s.ctx.DID, s.ctx.Repository, err) + slog.Warn("Failed to increment pull count", "did", s.ctx.DID, "repository", s.ctx.Repository, "error", err) } }() } @@ -143,7 +144,7 @@ func (s *ManifestStore) Put(ctx context.Context, manifest distribution.Manifest, labels, err := s.extractConfigLabels(ctx, manifestRecord.Config.Digest) if err != nil { // Log error but don't fail the push - labels are optional - fmt.Printf("WARNING: Failed to extract config labels: %v\n", err) + slog.Warn("Failed to extract config labels", "error", err) } else { // Initialize annotations map if needed if manifestRecord.Annotations == nil { @@ -153,7 +154,7 @@ func (s *ManifestStore) Put(ctx context.Context, manifest distribution.Manifest, // Copy labels to annotations (Dockerfile LABELs → manifest annotations) maps.Copy(manifestRecord.Annotations, labels) - fmt.Printf("DEBUG: Extracted %d labels from config blob\n", len(labels)) + slog.Debug("Extracted labels from config blob", "count", len(labels)) } } @@ -168,7 +169,7 @@ func (s *ManifestStore) Put(ctx context.Context, manifest distribution.Manifest, if s.ctx.Database != nil { go func() { if err := s.ctx.Database.IncrementPushCount(s.ctx.DID, s.ctx.Repository); err != nil { - fmt.Printf("WARNING: Failed to increment push count for %s/%s: %v\n", s.ctx.DID, s.ctx.Repository, err) + slog.Warn("Failed to increment push count", "did", s.ctx.DID, "repository", s.ctx.Repository, "error", err) } }() } @@ -192,7 +193,7 @@ func (s *ManifestStore) Put(ctx context.Context, manifest distribution.Manifest, if tag != "" && s.ctx.ServiceToken != "" && s.ctx.Handle != "" { go func() { if err := s.notifyHoldAboutManifest(context.Background(), manifestRecord, tag, dgst.String()); err != nil { - fmt.Printf("WARNING: Failed to notify hold about manifest: %v\n", err) + slog.Warn("Failed to notify hold about manifest", "error", err) } }() } @@ -362,7 +363,7 @@ func (s *ManifestStore) notifyHoldAboutManifest(ctx context.Context, manifestRec // Parse response (optional logging) var notifyResp map[string]any if err := json.NewDecoder(resp.Body).Decode(¬ifyResp); err == nil { - fmt.Printf("INFO: Hold notification successful for %s:%s - %+v\n", s.ctx.Repository, tag, notifyResp) + slog.Info("Hold notification successful", "repository", s.ctx.Repository, "tag", tag, "response", notifyResp) } return nil @@ -386,11 +387,11 @@ func (s *ManifestStore) refreshReadmeCache(ctx context.Context, manifestRecord * return } - fmt.Printf("INFO: Refreshing README cache for %s/%s from %s\n", s.ctx.DID, s.ctx.Repository, readmeURL) + slog.Info("Refreshing README cache", "did", s.ctx.DID, "repository", s.ctx.Repository, "url", readmeURL) // Invalidate the cached entry first if err := s.ctx.ReadmeCache.Invalidate(readmeURL); err != nil { - fmt.Printf("WARNING: Failed to invalidate README cache for %s: %v\n", readmeURL, err) + slog.Warn("Failed to invalidate README cache", "url", readmeURL, "error", err) // Continue anyway - Get() will still fetch fresh content } @@ -401,10 +402,10 @@ func (s *ManifestStore) refreshReadmeCache(ctx context.Context, manifestRecord * _, err := s.ctx.ReadmeCache.Get(ctxWithTimeout, readmeURL) if err != nil { - fmt.Printf("WARNING: Failed to refresh README cache for %s: %v\n", readmeURL, err) + slog.Warn("Failed to refresh README cache", "url", readmeURL, "error", err) // Not a critical error - cache will be refreshed on next page view return } - fmt.Printf("INFO: README cache refreshed successfully for %s\n", readmeURL) + slog.Info("README cache refreshed successfully", "url", readmeURL) } diff --git a/pkg/appview/storage/profile.go b/pkg/appview/storage/profile.go index 47613c5..76f6440 100644 --- a/pkg/appview/storage/profile.go +++ b/pkg/appview/storage/profile.go @@ -5,6 +5,7 @@ import ( "encoding/json" "errors" "fmt" + "log/slog" "sync" "time" @@ -46,7 +47,7 @@ func EnsureProfile(ctx context.Context, client *atproto.Client, defaultHoldDID s return fmt.Errorf("failed to create sailor profile: %w", err) } - fmt.Printf("DEBUG [profile]: Created sailor profile with defaultHold=%s\n", normalizedDID) + slog.Debug("Created sailor profile", "component", "profile", "default_hold", normalizedDID) return nil } @@ -95,9 +96,9 @@ func GetProfile(ctx context.Context, client *atproto.Client) (*atproto.SailorPro // Update the profile on the PDS profile.UpdatedAt = time.Now() if err := UpdateProfile(ctx, client, &profile); err != nil { - fmt.Printf("WARNING [profile]: Failed to persist URL-to-DID migration for %s: %v\n", did, err) + slog.Warn("Failed to persist URL-to-DID migration", "component", "profile", "did", did, "error", err) } else { - fmt.Printf("DEBUG [profile]: Persisted defaultHold migration to DID: %s (for DID: %s)\n", migratedDID, did) + slog.Debug("Persisted defaultHold migration to DID", "component", "profile", "migrated_did", migratedDID, "did", did) } }() } @@ -113,7 +114,7 @@ func UpdateProfile(ctx context.Context, client *atproto.Client, profile *atproto // This ensures we always store DIDs, even if user provides a URL if profile.DefaultHold != "" && !atproto.IsDID(profile.DefaultHold) { profile.DefaultHold = atproto.ResolveHoldDIDFromURL(profile.DefaultHold) - fmt.Printf("DEBUG [profile]: Normalized defaultHold to DID: %s\n", profile.DefaultHold) + slog.Debug("Normalized defaultHold to DID", "component", "profile", "default_hold", profile.DefaultHold) } _, err := client.PutRecord(ctx, atproto.SailorProfileCollection, ProfileRKey, profile) diff --git a/pkg/appview/storage/proxy_blob_store.go b/pkg/appview/storage/proxy_blob_store.go index e3a8241..db9304b 100644 --- a/pkg/appview/storage/proxy_blob_store.go +++ b/pkg/appview/storage/proxy_blob_store.go @@ -6,6 +6,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "sync" "time" @@ -41,8 +42,7 @@ func NewProxyBlobStore(ctx *RegistryContext) *ProxyBlobStore { // Resolve DID to URL once at construction time holdURL := atproto.ResolveHoldURL(ctx.HoldDID) - fmt.Printf("DEBUG [proxy_blob_store]: NewProxyBlobStore created with holdDID=%s, holdURL=%s, userDID=%s, repo=%s\n", - ctx.HoldDID, holdURL, ctx.DID, ctx.Repository) + slog.Debug("NewProxyBlobStore created", "component", "proxy_blob_store", "hold_did", ctx.HoldDID, "hold_url", holdURL, "user_did", ctx.DID, "repo", ctx.Repository) return &ProxyBlobStore{ ctx: ctx, @@ -67,7 +67,7 @@ func (p *ProxyBlobStore) doAuthenticatedRequest(ctx context.Context, req *http.R // Middleware fails fast with HTTP 401 if OAuth session is invalid if p.ctx.ServiceToken == "" { // Should never happen - middleware validates OAuth before handlers run - fmt.Printf("ERROR [proxy_blob_store]: No service token in context for DID=%s\n", p.ctx.DID) + slog.Error("No service token in context", "component", "proxy_blob_store", "did", p.ctx.DID) return nil, fmt.Errorf("no service token available (middleware should have validated)") } @@ -99,17 +99,17 @@ func (p *ProxyBlobStore) checkWriteAccess(ctx context.Context) error { return nil // No authorization check if authorizer not configured } - fmt.Printf("[checkWriteAccess] Checking write access for userDID=%s to holdDID=%s\n", p.ctx.DID, p.ctx.HoldDID) + slog.Debug("Checking write access", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) allowed, err := p.ctx.Authorizer.CheckWriteAccess(ctx, p.ctx.HoldDID, p.ctx.DID) if err != nil { - fmt.Printf("[checkWriteAccess] Authorization check error: %v\n", err) + slog.Error("Authorization check error", "component", "proxy_blob_store", "error", err) return fmt.Errorf("authorization check failed: %w", err) } if !allowed { - fmt.Printf("[checkWriteAccess] Write access DENIED for userDID=%s to holdDID=%s\n", p.ctx.DID, p.ctx.HoldDID) + slog.Warn("Write access denied", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) return errcode.ErrorCodeDenied.WithMessage(fmt.Sprintf("write access denied to hold %s", p.ctx.HoldDID)) } - fmt.Printf("[checkWriteAccess] Write access ALLOWED for userDID=%s to holdDID=%s\n", p.ctx.DID, p.ctx.HoldDID) + slog.Debug("Write access allowed", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) return nil } @@ -243,14 +243,14 @@ func (p *ProxyBlobStore) Put(ctx context.Context, mediaType string, content []by // Use Create() flow for all uploads (goes through multipart XRPC endpoints) writer, err := p.Create(ctx) if err != nil { - fmt.Printf("[proxy_blob_store/Put] Failed to create writer: %v\n", err) + slog.Error("Failed to create writer", "component", "proxy_blob_store/Put", "error", err) return distribution.Descriptor{}, err } // Write the content if _, err := writer.Write(content); err != nil { writer.Cancel(ctx) - fmt.Printf("[proxy_blob_store/Put] Failed to write content: %v\n", err) + slog.Error("Failed to write content", "component", "proxy_blob_store/Put", "error", err) return distribution.Descriptor{}, err } @@ -261,11 +261,11 @@ func (p *ProxyBlobStore) Put(ctx context.Context, mediaType string, content []by MediaType: mediaType, }) if err != nil { - fmt.Printf("[proxy_blob_store/Put] Failed to commit: %v\n", err) + slog.Error("Failed to commit", "component", "proxy_blob_store/Put", "error", err) return distribution.Descriptor{}, err } - fmt.Printf("[proxy_blob_store/Put] Upload successful: digest=%s, size=%d\n", dgst, len(content)) + slog.Debug("Upload successful", "component", "proxy_blob_store/Put", "digest", dgst, "size", len(content)) return desc, nil } @@ -393,7 +393,7 @@ func (p *ProxyBlobStore) getPresignedURL(ctx context.Context, operation string, return "", fmt.Errorf("hold service returned empty URL") } - fmt.Printf("DEBUG [proxy_blob_store]: Got presigned HEAD URL from hold service: %s\n", result.URL) + slog.Debug("Got presigned HEAD URL from hold service", "component", "proxy_blob_store", "url", result.URL) return result.URL, nil } @@ -676,7 +676,7 @@ func (w *ProxyBlobWriter) flushPart() error { ETag: etag, }) - fmt.Printf("[flushPart] Part %d uploaded successfully: ETag=%s\n", w.partNumber, etag) + slog.Debug("Part uploaded successfully", "component", "proxy_blob_store/flushPart", "part_number", w.partNumber, "etag", etag) // Reset buffer and increment part number w.buffer.Reset() @@ -734,7 +734,7 @@ func (w *ProxyBlobWriter) Commit(ctx context.Context, desc distribution.Descript // Flush any remaining buffered data if w.buffer.Len() > 0 { - fmt.Printf("[Commit] Flushing final buffer: %d bytes\n", w.buffer.Len()) + slog.Debug("Flushing final buffer", "component", "proxy_blob_store/Commit", "bytes", w.buffer.Len()) if err := w.flushPart(); err != nil { // Try to abort multipart on error tempDigest := fmt.Sprintf("uploads/temp-%s", w.id) @@ -745,12 +745,12 @@ func (w *ProxyBlobWriter) Commit(ctx context.Context, desc distribution.Descript // Complete multipart upload - XRPC complete action handles move internally // Send the real digest (not tempDigest) so hold can move temp → final location - fmt.Printf("🔒 [Commit] Completing multipart upload: uploadID=%s, parts=%d, digest=%s\n", w.uploadID, len(w.parts), desc.Digest) + slog.Info("Completing multipart upload", "component", "proxy_blob_store/Commit", "upload_id", w.uploadID, "parts", len(w.parts), "digest", desc.Digest) if err := w.store.completeMultipartUpload(ctx, desc.Digest.String(), w.uploadID, w.parts); err != nil { return distribution.Descriptor{}, fmt.Errorf("failed to complete multipart upload: %w", err) } - fmt.Printf("[Commit] Upload completed successfully: digest=%s, size=%d, parts=%d\n", desc.Digest, w.size, len(w.parts)) + slog.Info("Upload completed successfully", "component", "proxy_blob_store/Commit", "digest", desc.Digest, "size", w.size, "parts", len(w.parts)) return distribution.Descriptor{ Digest: desc.Digest, @@ -763,7 +763,7 @@ func (w *ProxyBlobWriter) Commit(ctx context.Context, desc distribution.Descript func (w *ProxyBlobWriter) Cancel(ctx context.Context) error { w.closed = true - fmt.Printf("[Cancel] Cancelling upload: id=%s\n", w.id) + slog.Debug("Cancelling upload", "component", "proxy_blob_store/Cancel", "id", w.id) // Remove from global uploads map globalUploadsMu.Lock() @@ -773,11 +773,11 @@ func (w *ProxyBlobWriter) Cancel(ctx context.Context) error { // Abort multipart upload tempDigest := fmt.Sprintf("uploads/temp-%s", w.id) if err := w.store.abortMultipartUpload(ctx, tempDigest, w.uploadID); err != nil { - fmt.Printf("⚠️ [Cancel] Failed to abort multipart upload: %v\n", err) + slog.Warn("Failed to abort multipart upload", "component", "proxy_blob_store/Cancel", "error", err) // Continue anyway - we want to mark upload as cancelled } - fmt.Printf("[Cancel] Upload cancelled: id=%s\n", w.id) + slog.Debug("Upload cancelled", "component", "proxy_blob_store/Cancel", "id", w.id) return nil } diff --git a/pkg/appview/storage/routing_repository.go b/pkg/appview/storage/routing_repository.go index c44a3f3..1d0bc44 100644 --- a/pkg/appview/storage/routing_repository.go +++ b/pkg/appview/storage/routing_repository.go @@ -6,7 +6,7 @@ package storage import ( "context" - "fmt" + "log/slog" "time" "github.com/distribution/distribution/v3" @@ -46,8 +46,7 @@ func (r *RoutingRepository) Manifests(ctx context.Context, options ...distributi if holdDID := r.manifestStore.GetLastFetchedHoldDID(); holdDID != "" { // Cache for 10 minutes - should cover typical pull operations GetGlobalHoldCache().Set(r.Ctx.DID, r.Ctx.Repository, holdDID, 10*time.Minute) - fmt.Printf("DEBUG [storage/routing]: Cached hold DID: did=%s, repo=%s, hold=%s\n", - r.Ctx.DID, r.Ctx.Repository, holdDID) + slog.Debug("Cached hold DID", "component", "storage/routing", "did", r.Ctx.DID, "repo", r.Ctx.Repository, "hold", holdDID) } }() @@ -59,8 +58,7 @@ func (r *RoutingRepository) Manifests(ctx context.Context, options ...distributi func (r *RoutingRepository) Blobs(ctx context.Context) distribution.BlobStore { // Return cached blob store if available if r.blobStore != nil { - fmt.Printf("DEBUG [storage/blobs]: Returning cached blob store for did=%s, repo=%s\n", - r.Ctx.DID, r.Ctx.Repository) + slog.Debug("Returning cached blob store", "component", "storage/blobs", "did", r.Ctx.DID, "repo", r.Ctx.Repository) return r.blobStore } @@ -71,12 +69,10 @@ func (r *RoutingRepository) Blobs(ctx context.Context) distribution.BlobStore { if cachedHoldDID, ok := GetGlobalHoldCache().Get(r.Ctx.DID, r.Ctx.Repository); ok { // Use cached hold DID from manifest holdDID = cachedHoldDID - fmt.Printf("DEBUG [storage/blobs]: Using cached hold from manifest: did=%s, repo=%s, hold=%s\n", - r.Ctx.DID, r.Ctx.Repository, cachedHoldDID) + slog.Debug("Using cached hold from manifest", "component", "storage/blobs", "did", r.Ctx.DID, "repo", r.Ctx.Repository, "hold", cachedHoldDID) } else { // No cached hold, use discovery-based DID (for push or first pull) - fmt.Printf("DEBUG [storage/blobs]: Using discovery-based hold: did=%s, repo=%s, hold=%s\n", - r.Ctx.DID, r.Ctx.Repository, holdDID) + slog.Debug("Using discovery-based hold", "component", "storage/blobs", "did", r.Ctx.DID, "repo", r.Ctx.Repository, "hold", holdDID) } if holdDID == "" {