slog slog slog slog slog

This commit is contained in:
Evan Jarrett
2025-10-25 13:30:07 -05:00
parent e17600db28
commit bf93dfba03
19 changed files with 155 additions and 151 deletions
+2 -1
View File
@@ -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
}
+6 -6
View File
@@ -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)
+3 -2
View File
@@ -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
+8 -7
View File
@@ -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
+14 -14
View File
@@ -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
}
+2 -2
View File
@@ -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 = "/"
}
+7 -7
View File
@@ -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)
}
}
}
+4 -4
View File
@@ -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)
+6 -6
View File
@@ -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
}
+15 -15
View File
@@ -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
+20 -19
View File
@@ -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)
}
}
}
+3 -2
View File
@@ -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
}
+13 -12
View File
@@ -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
}
+10 -9
View File
@@ -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
+2 -3
View File
@@ -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
+11 -10
View File
@@ -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(&notifyResp); 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)
}
+5 -4
View File
@@ -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)
+19 -19
View File
@@ -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
}
+5 -9
View File
@@ -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 == "" {