From ef39152f4e84b5197c0345af918aa80e2d9f3c81 Mon Sep 17 00:00:00 2001 From: Kyle Isom Date: Thu, 26 Mar 2026 12:47:44 -0700 Subject: [PATCH] Add structured error logging to OCI handlers Every 500 response in the OCI package silently discarded the actual error, making production debugging impossible. Add slog.Error before each 500 response with the error and relevant context (repo, digest, tag, uuid). Add slog.Info for state-mutating successes (manifest push, blob upload complete, deletions). Logger is injected into the OCI Handler via constructor, falling back to slog.Default() if nil. Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/mcrsrv/main.go | 2 +- internal/oci/blob.go | 7 +++++++ internal/oci/blob_test.go | 10 +++++----- internal/oci/catalog.go | 2 ++ internal/oci/catalog_test.go | 6 +++--- internal/oci/delete.go | 8 ++++++++ internal/oci/delete_test.go | 16 ++++++++-------- internal/oci/handler.go | 10 ++++++++-- internal/oci/manifest.go | 6 ++++++ internal/oci/manifest_test.go | 14 +++++++------- internal/oci/push_test.go | 16 ++++++++-------- internal/oci/tags.go | 3 +++ internal/oci/tags_test.go | 8 ++++---- internal/oci/upload.go | 15 +++++++++++++++ internal/oci/upload_test.go | 2 +- 15 files changed, 86 insertions(+), 39 deletions(-) diff --git a/cmd/mcrsrv/main.go b/cmd/mcrsrv/main.go index 8750c6f..a6a4b16 100644 --- a/cmd/mcrsrv/main.go +++ b/cmd/mcrsrv/main.go @@ -121,7 +121,7 @@ func runServer(configPath string) error { } // Create OCI handler and HTTP router. - ociHandler := oci.NewHandler(database, store, policyEngine, auditFn) + ociHandler := oci.NewHandler(database, store, policyEngine, auditFn, logger) router := server.NewRouter(authClient, authClient, cfg.MCIAS.ServiceName, ociHandler.Router()) // Mount admin REST endpoints. diff --git a/internal/oci/blob.go b/internal/oci/blob.go index 91da9e7..d6d9d91 100644 --- a/internal/oci/blob.go +++ b/internal/oci/blob.go @@ -23,12 +23,14 @@ func (h *Handler) handleBlobGet(w http.ResponseWriter, r *http.Request, repo, di fmt.Sprintf("repository %q not found", repo)) return } + h.log.Error("blob get: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } exists, err := h.db.BlobExistsInRepo(repoID, digest) if err != nil { + h.log.Error("blob get: check blob exists in repo", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -40,12 +42,14 @@ func (h *Handler) handleBlobGet(w http.ResponseWriter, r *http.Request, repo, di size, err := h.blobs.Stat(digest) if err != nil { + h.log.Error("blob get: stat blob in storage", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "BLOB_UNKNOWN", http.StatusNotFound, "blob not found in storage") return } rc, err := h.blobs.Open(digest) if err != nil { + h.log.Error("blob get: open blob in storage", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -70,12 +74,14 @@ func (h *Handler) handleBlobHead(w http.ResponseWriter, r *http.Request, repo, d fmt.Sprintf("repository %q not found", repo)) return } + h.log.Error("blob head: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } exists, err := h.db.BlobExistsInRepo(repoID, digest) if err != nil { + h.log.Error("blob head: check blob exists in repo", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -87,6 +93,7 @@ func (h *Handler) handleBlobHead(w http.ResponseWriter, r *http.Request, repo, d size, err := h.blobs.Stat(digest) if err != nil { + h.log.Error("blob head: stat blob in storage", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "BLOB_UNKNOWN", http.StatusNotFound, "blob not found in storage") return } diff --git a/internal/oci/blob_test.go b/internal/oci/blob_test.go index 8d45896..21557de 100644 --- a/internal/oci/blob_test.go +++ b/internal/oci/blob_test.go @@ -15,7 +15,7 @@ func TestBlobGet(t *testing.T) { blobs := newFakeBlobs() blobs.data["sha256:layerdigest"] = []byte("layer-content-bytes") - h := NewHandler(fdb, blobs, allowAll(), nil) + h := NewHandler(fdb, blobs, allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/blobs/sha256:layerdigest", nil) @@ -47,7 +47,7 @@ func TestBlobHead(t *testing.T) { blobs := newFakeBlobs() blobs.data["sha256:layerdigest"] = []byte("layer-content-bytes") - h := NewHandler(fdb, blobs, allowAll(), nil) + h := NewHandler(fdb, blobs, allowAll(), nil, nil) router := testRouter(h) req := authedRequest("HEAD", "/v2/myrepo/blobs/sha256:layerdigest", nil) @@ -79,7 +79,7 @@ func TestBlobGetNotInRepo(t *testing.T) { blobs := newFakeBlobs() blobs.data["sha256:orphan"] = []byte("data") - h := NewHandler(fdb, blobs, allowAll(), nil) + h := NewHandler(fdb, blobs, allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/blobs/sha256:orphan", nil) @@ -103,7 +103,7 @@ func TestBlobGetRepoNotFound(t *testing.T) { fdb := newFakeDB() // No repos. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/nosuchrepo/blobs/sha256:abc", nil) @@ -131,7 +131,7 @@ func TestBlobGetMultiSegmentRepo(t *testing.T) { blobs := newFakeBlobs() blobs.data["sha256:layerdigest"] = []byte("data") - h := NewHandler(fdb, blobs, allowAll(), nil) + h := NewHandler(fdb, blobs, allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/org/team/app/blobs/sha256:layerdigest", nil) diff --git a/internal/oci/catalog.go b/internal/oci/catalog.go index a44ed73..fbcda55 100644 --- a/internal/oci/catalog.go +++ b/internal/oci/catalog.go @@ -32,6 +32,7 @@ func (h *Handler) handleCatalog(w http.ResponseWriter, r *http.Request) { if n == 0 { repos, err := h.db.ListRepositoryNames(last, 10000) if err != nil { + h.log.Error("catalog: list repository names", "error", err) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -45,6 +46,7 @@ func (h *Handler) handleCatalog(w http.ResponseWriter, r *http.Request) { repos, err := h.db.ListRepositoryNames(last, n+1) if err != nil { + h.log.Error("catalog: list repository names (paginated)", "error", err) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } diff --git a/internal/oci/catalog_test.go b/internal/oci/catalog_test.go index 1496664..a3a947e 100644 --- a/internal/oci/catalog_test.go +++ b/internal/oci/catalog_test.go @@ -13,7 +13,7 @@ func TestCatalog(t *testing.T) { fdb.addRepo("bravo/svc", 2) fdb.addRepo("charlie/app", 3) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/_catalog", nil) @@ -46,7 +46,7 @@ func TestCatalogPagination(t *testing.T) { fdb.addRepo("bravo/svc", 2) fdb.addRepo("charlie/app", 3) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) // First page: n=2. @@ -103,7 +103,7 @@ func TestCatalogPagination(t *testing.T) { func TestCatalogEmpty(t *testing.T) { fdb := newFakeDB() - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/_catalog", nil) diff --git a/internal/oci/delete.go b/internal/oci/delete.go index e9ef5ff..eeacfc2 100644 --- a/internal/oci/delete.go +++ b/internal/oci/delete.go @@ -30,6 +30,7 @@ func (h *Handler) handleManifestDelete(w http.ResponseWriter, r *http.Request, r fmt.Sprintf("repository %q not found", repo)) return } + h.log.Error("manifest delete: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -40,12 +41,15 @@ func (h *Handler) handleManifestDelete(w http.ResponseWriter, r *http.Request, r fmt.Sprintf("manifest %q not found", reference)) return } + h.log.Error("manifest delete: delete from database", "error", err, "repo", repo, "digest", reference) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } h.audit(r, "manifest_deleted", repo, reference) + h.log.Info("manifest deleted", "repo", repo, "digest", reference) + w.WriteHeader(http.StatusAccepted) } @@ -64,6 +68,7 @@ func (h *Handler) handleBlobDelete(w http.ResponseWriter, r *http.Request, repo, fmt.Sprintf("repository %q not found", repo)) return } + h.log.Error("blob delete: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -74,11 +79,14 @@ func (h *Handler) handleBlobDelete(w http.ResponseWriter, r *http.Request, repo, fmt.Sprintf("blob %q not found in repository", digest)) return } + h.log.Error("blob delete: delete from database", "error", err, "repo", repo, "digest", digest) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } h.audit(r, "blob_deleted", repo, digest) + h.log.Info("blob deleted", "repo", repo, "digest", digest) + w.WriteHeader(http.StatusAccepted) } diff --git a/internal/oci/delete_test.go b/internal/oci/delete_test.go index dec957a..4983fe5 100644 --- a/internal/oci/delete_test.go +++ b/internal/oci/delete_test.go @@ -13,7 +13,7 @@ func TestManifestDeleteByDigest(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/manifests/sha256:aaaa", nil) @@ -37,7 +37,7 @@ func TestManifestDeleteByTagUnsupported(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/manifests/latest", nil) @@ -62,7 +62,7 @@ func TestManifestDeleteNotFound(t *testing.T) { fdb.addRepo("myrepo", 1) // No manifests added. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/manifests/sha256:nonexistent", nil) @@ -85,7 +85,7 @@ func TestManifestDeleteNotFound(t *testing.T) { func TestManifestDeleteRepoNotFound(t *testing.T) { fdb := newFakeDB() - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/nosuchrepo/manifests/sha256:aaaa", nil) @@ -111,7 +111,7 @@ func TestManifestDeleteCascadesTag(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/manifests/sha256:aaaa", nil) @@ -134,7 +134,7 @@ func TestBlobDelete(t *testing.T) { fdb.addRepo("myrepo", 1) fdb.addBlob(1, "sha256:b1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/blobs/sha256:b1", nil) @@ -157,7 +157,7 @@ func TestBlobDeleteNotInRepo(t *testing.T) { fdb.addRepo("myrepo", 1) // Blob not added to this repo. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/myrepo/blobs/sha256:nonexistent", nil) @@ -180,7 +180,7 @@ func TestBlobDeleteNotInRepo(t *testing.T) { func TestBlobDeleteRepoNotFound(t *testing.T) { fdb := newFakeDB() - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("DELETE", "/v2/nosuchrepo/blobs/sha256:b1", nil) diff --git a/internal/oci/handler.go b/internal/oci/handler.go index 1f1992f..95a0ad4 100644 --- a/internal/oci/handler.go +++ b/internal/oci/handler.go @@ -2,6 +2,7 @@ package oci import ( "io" + "log/slog" "net/http" "strings" @@ -61,16 +62,21 @@ type Handler struct { policy PolicyEval auditFn AuditFunc uploads *uploadManager + log *slog.Logger } -// NewHandler creates a new OCI handler. -func NewHandler(querier DBQuerier, blobs BlobStore, pol PolicyEval, auditFn AuditFunc) *Handler { +// NewHandler creates a new OCI handler. If logger is nil, slog.Default() is used. +func NewHandler(querier DBQuerier, blobs BlobStore, pol PolicyEval, auditFn AuditFunc, logger *slog.Logger) *Handler { + if logger == nil { + logger = slog.Default() + } return &Handler{ db: querier, blobs: blobs, policy: pol, auditFn: auditFn, uploads: newUploadManager(), + log: logger.With("component", "oci"), } } diff --git a/internal/oci/manifest.go b/internal/oci/manifest.go index 9ce62de..c1aab6b 100644 --- a/internal/oci/manifest.go +++ b/internal/oci/manifest.go @@ -59,6 +59,7 @@ func (h *Handler) resolveManifest(w http.ResponseWriter, repo, reference string) fmt.Sprintf("repository %q not found", repo)) return nil, false } + h.log.Error("manifest resolve: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return nil, false } @@ -75,6 +76,7 @@ func (h *Handler) resolveManifest(w http.ResponseWriter, repo, reference string) fmt.Sprintf("manifest %q not found", reference)) return nil, false } + h.log.Error("manifest resolve: lookup manifest", "error", err, "repo", repo, "reference", reference) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return nil, false } @@ -175,6 +177,7 @@ func (h *Handler) handleManifestPut(w http.ResponseWriter, r *http.Request, repo for _, bd := range blobDigests { exists, err := h.db.BlobExists(bd) if err != nil { + h.log.Error("manifest push: check blob exists", "error", err, "repo", repo, "blob_digest", bd) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -197,6 +200,7 @@ func (h *Handler) handleManifestPut(w http.ResponseWriter, r *http.Request, repo BlobDigests: blobDigests, } if err := h.db.PushManifest(params); err != nil { + h.log.Error("manifest push: write to database", "error", err, "repo", repo, "digest", computedDigest, "tag", tag) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -215,6 +219,8 @@ func (h *Handler) handleManifestPut(w http.ResponseWriter, r *http.Request, repo h.auditFn("manifest_pushed", actorID, repo, computedDigest, r.RemoteAddr, details) } + h.log.Info("manifest pushed", "repo", repo, "digest", computedDigest, "tag", tag, "size", len(body)) + w.Header().Set("Location", fmt.Sprintf("/v2/%s/manifests/%s", repo, computedDigest)) w.Header().Set("Docker-Content-Digest", computedDigest) w.Header().Set("Content-Type", mediaType) diff --git a/internal/oci/manifest_test.go b/internal/oci/manifest_test.go index 0295d74..2b8fa6b 100644 --- a/internal/oci/manifest_test.go +++ b/internal/oci/manifest_test.go @@ -13,7 +13,7 @@ func TestManifestGetByTag(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/manifests/latest", nil) @@ -43,7 +43,7 @@ func TestManifestGetByDigest(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/manifests/sha256:aaaa", nil) @@ -67,7 +67,7 @@ func TestManifestHead(t *testing.T) { content := []byte(`{"schemaVersion":2}`) fdb.addManifest(1, "latest", "sha256:aaaa", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("HEAD", "/v2/myrepo/manifests/latest", nil) @@ -95,7 +95,7 @@ func TestManifestGetRepoNotFound(t *testing.T) { fdb := newFakeDB() // No repos added. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/nosuchrepo/manifests/latest", nil) @@ -120,7 +120,7 @@ func TestManifestGetManifestNotFoundByTag(t *testing.T) { fdb.addRepo("myrepo", 1) // No manifests added. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/manifests/nonexistent", nil) @@ -145,7 +145,7 @@ func TestManifestGetManifestNotFoundByDigest(t *testing.T) { fdb.addRepo("myrepo", 1) // No manifests added. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/manifests/sha256:nonexistent", nil) @@ -171,7 +171,7 @@ func TestManifestGetMultiSegmentRepo(t *testing.T) { content := []byte(`{"layers":[]}`) fdb.addManifest(1, "v1.0", "sha256:cccc", "application/vnd.oci.image.manifest.v1+json", content) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/org/team/app/manifests/v1.0", nil) diff --git a/internal/oci/push_test.go b/internal/oci/push_test.go index 8a00515..63e6bfd 100644 --- a/internal/oci/push_test.go +++ b/internal/oci/push_test.go @@ -32,7 +32,7 @@ func TestManifestPushByTag(t *testing.T) { fdb.addGlobalBlob("sha256:config1") fdb.addGlobalBlob("sha256:layer1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) content := makeManifest("sha256:config1", []string{"sha256:layer1"}) @@ -79,7 +79,7 @@ func TestManifestPushByDigest(t *testing.T) { fdb.addRepo("myrepo", 1) fdb.addGlobalBlob("sha256:config1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) content := makeManifest("sha256:config1", nil) @@ -107,7 +107,7 @@ func TestManifestPushDigestMismatch(t *testing.T) { fdb := newFakeDB() fdb.addRepo("myrepo", 1) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) content := []byte(`{"schemaVersion":2}`) @@ -137,7 +137,7 @@ func TestManifestPushMissingBlob(t *testing.T) { // Config blob exists but layer blob does not. fdb.addGlobalBlob("sha256:config1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) content := makeManifest("sha256:config1", []string{"sha256:missing_layer"}) @@ -164,7 +164,7 @@ func TestManifestPushMalformed(t *testing.T) { fdb := newFakeDB() fdb.addRepo("myrepo", 1) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedPushRequest("PUT", "/v2/myrepo/manifests/latest", []byte("not valid json")) @@ -189,7 +189,7 @@ func TestManifestPushEmpty(t *testing.T) { fdb := newFakeDB() fdb.addRepo("myrepo", 1) - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedPushRequest("PUT", "/v2/myrepo/manifests/latest", nil) @@ -207,7 +207,7 @@ func TestManifestPushUpdatesTag(t *testing.T) { fdb.addRepo("myrepo", 1) fdb.addGlobalBlob("sha256:config1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) // First push with tag "latest". @@ -248,7 +248,7 @@ func TestManifestPushRepushIdempotent(t *testing.T) { fdb.addRepo("myrepo", 1) fdb.addGlobalBlob("sha256:config1") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) content := makeManifest("sha256:config1", nil) diff --git a/internal/oci/tags.go b/internal/oci/tags.go index 5df524f..a8b64b7 100644 --- a/internal/oci/tags.go +++ b/internal/oci/tags.go @@ -28,6 +28,7 @@ func (h *Handler) handleTagsList(w http.ResponseWriter, r *http.Request, repo st fmt.Sprintf("repository %q not found", repo)) return } + h.log.Error("tags list: lookup repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -47,6 +48,7 @@ func (h *Handler) handleTagsList(w http.ResponseWriter, r *http.Request, repo st if n == 0 { tags, err := h.db.ListTags(repoID, last, 10000) if err != nil { + h.log.Error("tags list: list tags", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -61,6 +63,7 @@ func (h *Handler) handleTagsList(w http.ResponseWriter, r *http.Request, repo st // Request n+1 to detect if there are more results. tags, err := h.db.ListTags(repoID, last, n+1) if err != nil { + h.log.Error("tags list: list tags (paginated)", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } diff --git a/internal/oci/tags_test.go b/internal/oci/tags_test.go index 6ac8418..e1c5583 100644 --- a/internal/oci/tags_test.go +++ b/internal/oci/tags_test.go @@ -14,7 +14,7 @@ func TestTagsList(t *testing.T) { fdb.addTag(1, "v1.0") fdb.addTag(1, "v2.0") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/tags/list", nil) @@ -50,7 +50,7 @@ func TestTagsListPagination(t *testing.T) { fdb.addTag(1, "beta") fdb.addTag(1, "gamma") - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) // First page: n=2. @@ -109,7 +109,7 @@ func TestTagsListEmpty(t *testing.T) { fdb.addRepo("myrepo", 1) // No tags. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/myrepo/tags/list", nil) @@ -133,7 +133,7 @@ func TestTagsListRepoNotFound(t *testing.T) { fdb := newFakeDB() // No repos. - h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil) + h := NewHandler(fdb, newFakeBlobs(), allowAll(), nil, nil) router := testRouter(h) req := authedRequest("GET", "/v2/nosuchrepo/tags/list", nil) diff --git a/internal/oci/upload.go b/internal/oci/upload.go index 50a8ce1..f332236 100644 --- a/internal/oci/upload.go +++ b/internal/oci/upload.go @@ -64,18 +64,21 @@ func (h *Handler) handleUploadInitiate(w http.ResponseWriter, r *http.Request, r // Create repository if it doesn't exist (implicit creation). repoID, err := h.db.GetOrCreateRepository(repo) if err != nil { + h.log.Error("upload initiate: get or create repository", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } uuid, err := generateUUID() if err != nil { + h.log.Error("upload initiate: generate uuid", "error", err, "repo", repo) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } // Insert upload row in DB. if err := h.db.CreateUpload(uuid, repoID); err != nil { + h.log.Error("upload initiate: create upload in database", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -85,12 +88,15 @@ func (h *Handler) handleUploadInitiate(w http.ResponseWriter, r *http.Request, r if err != nil { // Clean up DB row on storage failure. _ = h.db.DeleteUpload(uuid) + h.log.Error("upload initiate: start upload in storage", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } h.uploads.set(uuid, bw) + h.log.Info("upload initiated", "repo", repo, "uuid", uuid) + w.Header().Set("Location", fmt.Sprintf("/v2/%s/blobs/uploads/%s", repo, uuid)) w.Header().Set("Docker-Upload-UUID", uuid) w.Header().Set("Range", "0-0") @@ -112,6 +118,7 @@ func (h *Handler) handleUploadChunk(w http.ResponseWriter, r *http.Request, repo // Append request body to upload file. n, err := io.Copy(bw, r.Body) if err != nil { + h.log.Error("upload chunk: write to storage", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "write failed") return } @@ -119,6 +126,7 @@ func (h *Handler) handleUploadChunk(w http.ResponseWriter, r *http.Request, repo // Update offset in DB. newOffset := bw.BytesWritten() if err := h.db.UpdateUploadOffset(uuid, newOffset); err != nil { + h.log.Error("upload chunk: update offset in database", "error", err, "repo", repo, "uuid", uuid, "offset", newOffset) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -152,6 +160,7 @@ func (h *Handler) handleUploadComplete(w http.ResponseWriter, r *http.Request, r // If request body is non-empty, append it first (monolithic upload). if r.ContentLength != 0 { if _, err := io.Copy(bw, r.Body); err != nil { + h.log.Error("upload complete: write final chunk to storage", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "write failed") return } @@ -172,6 +181,7 @@ func (h *Handler) handleUploadComplete(w http.ResponseWriter, r *http.Request, r writeOCIError(w, "DIGEST_INVALID", http.StatusBadRequest, "invalid digest format") return } + h.log.Error("upload complete: commit blob", "error", err, "repo", repo, "uuid", uuid, "digest", digest) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "commit failed") return } @@ -180,6 +190,7 @@ func (h *Handler) handleUploadComplete(w http.ResponseWriter, r *http.Request, r // Insert blob row (no-op if already exists — content-addressed dedup). if err := h.db.InsertBlob(digest, size); err != nil { + h.log.Error("upload complete: insert blob in database", "error", err, "repo", repo, "digest", digest, "size", size) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -189,6 +200,8 @@ func (h *Handler) handleUploadComplete(w http.ResponseWriter, r *http.Request, r h.audit(r, "blob_uploaded", repo, digest) + h.log.Info("blob upload complete", "repo", repo, "digest", digest, "size", size) + w.Header().Set("Location", fmt.Sprintf("/v2/%s/blobs/%s", repo, digest)) w.Header().Set("Docker-Content-Digest", digest) w.WriteHeader(http.StatusCreated) @@ -206,6 +219,7 @@ func (h *Handler) handleUploadStatus(w http.ResponseWriter, r *http.Request, rep writeOCIError(w, "BLOB_UPLOAD_UNKNOWN", http.StatusNotFound, "upload not found") return } + h.log.Error("upload status: lookup upload", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } @@ -233,6 +247,7 @@ func (h *Handler) handleUploadCancel(w http.ResponseWriter, r *http.Request, rep writeOCIError(w, "BLOB_UPLOAD_UNKNOWN", http.StatusNotFound, "upload not found") return } + h.log.Error("upload cancel: delete upload from database", "error", err, "repo", repo, "uuid", uuid) writeOCIError(w, "UNKNOWN", http.StatusInternalServerError, "internal error") return } diff --git a/internal/oci/upload_test.go b/internal/oci/upload_test.go index 4d524df..b85a3c9 100644 --- a/internal/oci/upload_test.go +++ b/internal/oci/upload_test.go @@ -21,7 +21,7 @@ func testHandlerWithStorage(t *testing.T, fdb *fakeDB) (*Handler, *chi.Mux) { t.Helper() dir := t.TempDir() store := storage.New(dir+"/layers", dir+"/uploads") - h := NewHandler(fdb, store, allowAll(), nil) + h := NewHandler(fdb, store, allowAll(), nil, nil) router := chi.NewRouter() router.Mount("/v2", h.Router()) return h, router