From dd2d256bc2b82bead50e782da6f21b869cd2bb44 Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 28 Sep 2026 17:16:53 +0000 Subject: [PATCH 1/4] Test that an unparseable exp on /v1/image/ is refused with 400 (closes #72) An exp that is not a whole number, or an empty exp=, is ignored today, so a URL for a host that needs a signature gets 401 as if it had no exp. This test asks for a 400 naming exp and the value instead; it fails until the route refuses it. A URL without exp still gets 401. Model: opus-5-5 --- .../handlers/image_signature_internal_test.go | 51 +++++++++++++++++++ 1 file changed, 51 insertions(+) diff --git a/internal/handlers/image_signature_internal_test.go b/internal/handlers/image_signature_internal_test.go index a045f0e..c435668 100644 --- a/internal/handlers/image_signature_internal_test.go +++ b/internal/handlers/image_signature_internal_test.go @@ -1,6 +1,7 @@ package handlers import ( + "encoding/json" "fmt" "net/http" "net/http/httptest" @@ -118,3 +119,53 @@ func TestHandleImage_GeneratedSignedURLVerifies(t *testing.T) { }) } } + +// TestHandleImage_InvalidExp_Returns400 sends a signed-host URL whose exp is +// not a whole number, and one whose exp is empty. Each is refused with 400 +// naming exp and the value, not with the 401 a URL without exp still gets. +func TestHandleImage_InvalidExp_Returns400(t *testing.T) { + t.Parallel() + + tests := []struct { + query string + wantStatus int + wantError string + }{ + {"sig=x&exp=banana", http.StatusBadRequest, + `invalid exp: not a number, got "banana"`}, + {"sig=x&exp=", http.StatusBadRequest, `invalid exp: not a number, got ""`}, + {"sig=x", http.StatusUnauthorized, "unauthorized"}, + } + + for _, tt := range tests { + t.Run(tt.query, func(t *testing.T) { + t.Parallel() + + fix := setupTestHandler(t) + + r := chi.NewRouter() + r.Get("/v1/image/*", fix.handler.HandleImage()) + + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, + "/v1/image/"+signedHost+"/images/photo.jpg/50x50.jpeg?"+tt.query, nil) + rec := httptest.NewRecorder() + + r.ServeHTTP(rec, req) + t.Logf("GET %s: %d %s", req.URL, rec.Code, rec.Body) + + var body struct { + Error string `json:"error"` + } + + err := json.NewDecoder(rec.Body).Decode(&body) + if err != nil { + t.Fatalf("decoding response body: %v", err) + } + + if rec.Code != tt.wantStatus || body.Error != tt.wantError { + t.Errorf("got %d %q, want %d %q", + rec.Code, body.Error, tt.wantStatus, tt.wantError) + } + }) + } +} -- 2.54.0 From 0ec806fb67687a307455a5e4b79c7d192536b4dd Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 28 Sep 2026 17:24:13 +0000 Subject: [PATCH 2/4] Refuse an unparseable exp with 400; log swallowed cache errors (closes #72) An exp that was not a whole number, or empty, was ignored, so a URL for a host that needs a signature got 401 as if it had no exp. It is now a 400 naming exp and the value; only an exp missing from the URL is unchanged. A failed variant .meta write, source metadata JSON write, Stats count query, stats counter update, negative cache write or expired negative cache delete was discarded without a trace. Each is now logged at warn with the path or key and the error, and stays non-fatal. VariantStorage takes the cache's logger for this. The metadata JSON write moved out of StoreSource into writeMetadataSidecar to keep StoreSource within the function length limit. Model: opus-5-5 --- README.md | 4 +- TODO.md | 9 ++++ internal/handlers/image.go | 30 ++++++++++--- internal/imgcache/cache.go | 83 +++++++++++++++++++++++++----------- internal/imgcache/service.go | 7 ++- internal/imgcache/storage.go | 13 ++++-- 6 files changed, 112 insertions(+), 34 deletions(-) diff --git a/README.md b/README.md index 5a1785c..ce8883d 100644 --- a/README.md +++ b/README.md @@ -127,7 +127,9 @@ Where: - `width` — requested width in pixels, `0` for original - `height` — requested height in pixels, `0` for original - `format` — output format (jpeg, png, webp, avif, gif, orig) -- `expiration` — Unix timestamp when signature expires +- `expiration` — the URL's `exp` query parameter, the Unix timestamp when + the signature expires; a request whose `exp` is not a whole number, an + empty `exp=` included, is refused with 400 - `quality` — the URL's `q` query parameter, a whole number from 1 to 100, or `85` when the URL has no `q`; a request whose `q` is anything else is refused with 400 diff --git a/TODO.md b/TODO.md index a327b56..672d6d1 100644 --- a/TODO.md +++ b/TODO.md @@ -30,6 +30,15 @@ exhaustion # Completed Steps +- 2026-09-28 refuse an unparseable `exp` on `/v1/image/` and log swallowed + cache errors (closes #72): an `exp` in the URL that is not a whole + number, an empty `exp=` included, is a 400 naming `exp` and the value, + instead of being ignored and answered with 401 as if the URL had no + `exp`; only an `exp` missing from the URL is unchanged; `README.md` says + so where it documents `exp`. A failed variant `.meta` write, source + metadata JSON write, `Stats` count query, stats counter update, negative + cache write or expired negative cache delete is now logged at `warn` + with the path or key and the error, and stays non-fatal. - 2026-09-28 refuse an empty `fit` on `/v1/image/` (closes #139): a `fit` in the URL with an empty value (`fit=`) is a 400 naming `fit`, instead of being served as `cover` and verified against a signature diff --git a/internal/handlers/image.go b/internal/handlers/image.go index 5139905..00b271e 100644 --- a/internal/handlers/image.go +++ b/internal/handlers/image.go @@ -116,11 +116,11 @@ func (s *Handlers) parseImageRequest( req.Signature = query.Get("sig") - if expStr := query.Get("exp"); expStr != "" { - exp, parseErr := strconv.ParseInt(expStr, 10, 64) - if parseErr == nil { - req.Expires = time.Unix(exp, 0) - } + req.Expires, err = parseExpires(query) + if err != nil { + s.respondError(w, err.Error(), http.StatusBadRequest) + + return nil, false } // Parse optional quality and fit params. Only a q missing from the URL is @@ -174,6 +174,26 @@ func (s *Handlers) parseImageRequest( return req, true } +// parseExpires reads the exp query parameter, a Unix time in seconds. An exp +// missing from the URL gives the zero time, which the signature check takes +// as no expiration. An exp in the URL that is not a whole number, an empty +// one included, is an error naming exp and the value. +func parseExpires(query url.Values) (time.Time, error) { + if !query.Has("exp") { + return time.Time{}, nil + } + + expStr := query.Get("exp") + + exp, err := strconv.ParseInt(expStr, 10, 64) + if err != nil { + return time.Time{}, fmt.Errorf("%w exp: not a number, got %q", + errInvalidFormField, expStr) + } + + return time.Unix(exp, 0), nil +} + // respondImageError maps image retrieval errors to HTTP responses. func (s *Handlers) respondImageError( w http.ResponseWriter, req *imgcache.ImageRequest, err error, diff --git a/internal/imgcache/cache.go b/internal/imgcache/cache.go index f31880b..172b40e 100644 --- a/internal/imgcache/cache.go +++ b/internal/imgcache/cache.go @@ -125,7 +125,7 @@ func NewCache(db *sql.DB, config CacheConfig) (*Cache, error) { } variants, err := NewVariantStorage( - filepath.Join(config.StateDir, "cache", "variants"), + filepath.Join(config.StateDir, "cache", "variants"), log, ) if err != nil { return nil, fmt.Errorf("failed to create variant storage: %w", err) @@ -263,23 +263,7 @@ func (c *Cache) StoreSource( return "", fmt.Errorf("failed to insert source metadata: %w", err) } - // Store metadata JSON file - meta := &SourceMetadata{ - Host: req.SourceHost, - Path: req.SourcePath, - Query: req.SourceQuery, - ContentHash: string(contentHash), - StatusCode: result.StatusCode, - ContentType: result.ContentType, - ContentLength: result.ContentLength, - ResponseHeaders: result.Headers, - FetchedAt: time.Now().UTC().Unix(), - FetchDurationMs: result.FetchDurationMs, - RemoteAddr: result.RemoteAddr, - } - - // A failure here is non-fatal; the metadata is in the database. - _ = c.srcMetadata.Store(req.SourceHost, pathHash, meta) + c.writeMetadataSidecar(req, pathHash, contentHash, result) c.notifyWritePressure() @@ -436,12 +420,19 @@ func (c *Cache) Stats(ctx context.Context) (*CacheStats, error) { } // Get actual item count and total size from content tables - _ = c.db.QueryRowContext(ctx, + err = c.db.QueryRowContext(ctx, `SELECT COUNT(*) FROM request_cache`, ).Scan(&stats.TotalItems) - _ = c.db.QueryRowContext(ctx, + if err != nil { + c.log.Warn("failed to count cache items for stats", "error", err) + } + + err = c.db.QueryRowContext(ctx, `SELECT COALESCE(SUM(size_bytes), 0) FROM output_content`, ).Scan(&stats.TotalSizeBytes) + if err != nil { + c.log.Warn("failed to sum cache size for stats", "error", err) + } // Compute hit rate as a ratio if stats.HitCount+stats.MissCount > 0 { @@ -453,15 +444,17 @@ func (c *Cache) Stats(ctx context.Context) (*CacheStats, error) { // IncrementStats increments cache statistics. func (c *Cache) IncrementStats(ctx context.Context, hit bool, fetchBytes int64) { + var err error + if hit { - _, _ = c.db.ExecContext(ctx, ` + _, err = c.db.ExecContext(ctx, ` UPDATE cache_stats SET hit_count = hit_count + 1, last_updated_at = CURRENT_TIMESTAMP WHERE id = 1 `) } else { - _, _ = c.db.ExecContext(ctx, ` + _, err = c.db.ExecContext(ctx, ` UPDATE cache_stats SET miss_count = miss_count + 1, last_updated_at = CURRENT_TIMESTAMP @@ -469,14 +462,52 @@ func (c *Cache) IncrementStats(ctx context.Context, hit bool, fetchBytes int64) `) } + if err != nil { + c.log.Warn("failed to count cache hit or miss", "hit", hit, "error", err) + } + if fetchBytes > 0 { - _, _ = c.db.ExecContext(ctx, ` + _, err = c.db.ExecContext(ctx, ` UPDATE cache_stats SET upstream_fetch_count = upstream_fetch_count + 1, upstream_fetch_bytes = upstream_fetch_bytes + ?, last_updated_at = CURRENT_TIMESTAMP WHERE id = 1 `, fetchBytes) + if err != nil { + c.log.Warn("failed to count upstream fetch", + "fetch_bytes", fetchBytes, "error", err) + } + } +} + +// writeMetadataSidecar writes the JSON metadata sidecar of a stored source. +// A failure is logged and is otherwise non-fatal; the metadata is in the +// database. +func (c *Cache) writeMetadataSidecar( + req *ImageRequest, + pathHash PathHash, + contentHash ContentHash, + result *httpfetcher.FetchResult, +) { + meta := &SourceMetadata{ + Host: req.SourceHost, + Path: req.SourcePath, + Query: req.SourceQuery, + ContentHash: string(contentHash), + StatusCode: result.StatusCode, + ContentType: result.ContentType, + ContentLength: result.ContentLength, + ResponseHeaders: result.Headers, + FetchedAt: time.Now().UTC().Unix(), + FetchDurationMs: result.FetchDurationMs, + RemoteAddr: result.RemoteAddr, + } + + err := c.srcMetadata.Store(req.SourceHost, pathHash, meta) + if err != nil { + c.log.Warn("failed to write metadata sidecar", + "host", req.SourceHost, "path_hash", pathHash, "error", err) } } @@ -528,10 +559,14 @@ func (c *Cache) checkNegativeCache( // Check if expired if time.Now().After(expiresAt) { // Clean up expired entry - _, _ = c.db.ExecContext(ctx, ` + _, err = c.db.ExecContext(ctx, ` DELETE FROM negative_cache WHERE source_host = ? AND source_path = ? AND source_query = ? `, req.SourceHost, req.SourcePath, req.SourceQuery) + if err != nil { + c.log.Warn("failed to delete expired negative cache entry", + "host", req.SourceHost, "path", req.SourcePath, "error", err) + } return false, nil } diff --git a/internal/imgcache/service.go b/internal/imgcache/service.go index d6e07df..3b295c7 100644 --- a/internal/imgcache/service.go +++ b/internal/imgcache/service.go @@ -322,7 +322,12 @@ func (s *Service) fetchAndProcess( // Store negative cache for certain errors if isNegativeCacheable(err) { statusCode := extractStatusCode(err) - _ = s.cache.StoreNegative(ctx, req, statusCode, err.Error()) + + storeErr := s.cache.StoreNegative(ctx, req, statusCode, err.Error()) + if storeErr != nil { + s.log.Warn("failed to store negative cache entry", + "host", req.SourceHost, "path", req.SourcePath, "error", storeErr) + } } return nil, fmt.Errorf("upstream fetch failed: %w", err) diff --git a/internal/imgcache/storage.go b/internal/imgcache/storage.go index 893b176..b9487ce 100644 --- a/internal/imgcache/storage.go +++ b/internal/imgcache/storage.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "io" + "log/slog" "os" "path/filepath" "time" @@ -392,6 +393,7 @@ func CacheKey(req *ImageRequest) VariantKey { // Unlike ContentStorage, the key is provided by the caller (not computed from content). type VariantStorage struct { baseDir string + log *slog.Logger } // VariantMeta contains metadata about a cached variant. @@ -404,13 +406,14 @@ type VariantMeta struct { } // NewVariantStorage creates a new variant storage at the given base directory. -func NewVariantStorage(baseDir string) (*VariantStorage, error) { +// A failed .meta write is logged to log. +func NewVariantStorage(baseDir string, log *slog.Logger) (*VariantStorage, error) { err := os.MkdirAll(baseDir, StorageDirPerm) if err != nil { return nil, fmt.Errorf("failed to create variant storage directory: %w", err) } - return &VariantStorage{baseDir: baseDir}, nil + return &VariantStorage{baseDir: baseDir, log: log}, nil } // Store writes content and metadata to storage at the given key. @@ -478,7 +481,11 @@ func (s *VariantStorage) Store( } // Metadata write failure is non-fatal; content is already stored. - _ = os.WriteFile(metaPath, metaData, StorageFilePerm) + err = os.WriteFile(metaPath, metaData, StorageFilePerm) + if err != nil { + s.log.Warn("failed to write variant metadata sidecar", + "path", metaPath, "error", err) + } return size, nil } -- 2.54.0 From 004ccf3fc849ee881dec3cc61352fca2e6833716 Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 28 Sep 2026 17:43:34 +0000 Subject: [PATCH 3/4] Test the warn lines of failed cache writes and stats queries (closes #72) A directory where a variant .meta file goes, and dropped tables in the test database, make the variant .meta write, the two Stats count queries and the stats counter updates fail. Each test hands the cache or NewVariantStorage a logger writing to a buffer, checks the warn line, and checks the store and Stats calls still succeed. Model: opus-5-5 --- internal/imgcache/stats_internal_test.go | 82 ++++++++++++++++++++++ internal/imgcache/storage_internal_test.go | 34 +++++++++ 2 files changed, 116 insertions(+) diff --git a/internal/imgcache/stats_internal_test.go b/internal/imgcache/stats_internal_test.go index 4cecd4c..5076179 100644 --- a/internal/imgcache/stats_internal_test.go +++ b/internal/imgcache/stats_internal_test.go @@ -1,9 +1,12 @@ package imgcache import ( + "bytes" "context" "database/sql" + "log/slog" "math" + "strings" "testing" "time" @@ -101,3 +104,82 @@ func TestStats_ZeroCounts(t *testing.T) { t.Errorf("HitRate = %f, want 0.0 for zero counts", stats.HitRate) } } + +// TestStats_LogsFailedCountQueries verifies that a failed item count query +// and a failed size query are each logged at warn and Stats still succeeds. +func TestStats_LogsFailedCountQueries(t *testing.T) { + t.Parallel() + + db := setupStatsTestDB(t) + + var logBuf bytes.Buffer + + cache, err := NewCache(db, CacheConfig{ + StateDir: t.TempDir(), + CacheTTL: time.Hour, + NegativeTTL: 5 * time.Minute, + Logger: slog.New(slog.NewJSONHandler(&logBuf, nil)), + }) + if err != nil { + t.Fatal(err) + } + + _, err = db.ExecContext(t.Context(), + `DROP TABLE request_cache; DROP TABLE output_content`) + if err != nil { + t.Fatal(err) + } + + _, err = cache.Stats(t.Context()) + if err != nil { + t.Fatalf("Stats() error = %v, want nil", err) + } + + for _, msg := range []string{ + "failed to count cache items for stats", + "failed to sum cache size for stats", + } { + want := `"level":"WARN","msg":"` + msg + `"` + if !strings.Contains(logBuf.String(), want) { + t.Errorf("log missing %s; got %q", want, logBuf.String()) + } + } +} + +// TestIncrementStats_LogsFailedUpdates verifies that a failed hit or miss +// count update and a failed upstream fetch count update are each logged at +// warn. +func TestIncrementStats_LogsFailedUpdates(t *testing.T) { + t.Parallel() + + db := setupStatsTestDB(t) + + var logBuf bytes.Buffer + + cache, err := NewCache(db, CacheConfig{ + StateDir: t.TempDir(), + CacheTTL: time.Hour, + NegativeTTL: 5 * time.Minute, + Logger: slog.New(slog.NewJSONHandler(&logBuf, nil)), + }) + if err != nil { + t.Fatal(err) + } + + _, err = db.ExecContext(t.Context(), `DROP TABLE cache_stats`) + if err != nil { + t.Fatal(err) + } + + cache.IncrementStats(t.Context(), false, 1024) + + for _, msg := range []string{ + "failed to count cache hit or miss", + "failed to count upstream fetch", + } { + want := `"level":"WARN","msg":"` + msg + `"` + if !strings.Contains(logBuf.String(), want) { + t.Errorf("log missing %s; got %q", want, logBuf.String()) + } + } +} diff --git a/internal/imgcache/storage_internal_test.go b/internal/imgcache/storage_internal_test.go index a72ec94..0465bb1 100644 --- a/internal/imgcache/storage_internal_test.go +++ b/internal/imgcache/storage_internal_test.go @@ -4,8 +4,10 @@ import ( "bytes" "errors" "io" + "log/slog" "os" "path/filepath" + "strings" "testing" ) @@ -404,3 +406,35 @@ func TestCacheKey(t *testing.T) { t.Error("CacheKey() produced same key for different quality") } } + +// TestVariantStorage_StoreLogsFailedMetaWrite verifies that a .meta write +// that fails is logged at warn and the store still succeeds. +func TestVariantStorage_StoreLogsFailedMetaWrite(t *testing.T) { + t.Parallel() + + var logBuf bytes.Buffer + + storage, err := NewVariantStorage( + t.TempDir(), slog.New(slog.NewJSONHandler(&logBuf, nil))) + if err != nil { + t.Fatalf("NewVariantStorage() error = %v", err) + } + + key := CacheKey(&ImageRequest{SourceHost: testHostCDN, SourcePath: testPathCat}) + + // A directory where the .meta file goes makes the .meta write fail. + err = os.MkdirAll(storage.keyToPath(key)+".meta", StorageDirPerm) + if err != nil { + t.Fatalf("failed to create directory: %v", err) + } + + _, err = storage.Store(key, bytes.NewReader([]byte("variant data")), "image/webp") + if err != nil { + t.Fatalf("Store() error = %v, want nil", err) + } + + want := `"level":"WARN","msg":"failed to write variant metadata sidecar"` + if !strings.Contains(logBuf.String(), want) { + t.Errorf("log missing %s; got %q", want, logBuf.String()) + } +} -- 2.54.0 From 6735b42e5587864988c8fef794434702e5068e7d Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 28 Sep 2026 17:43:34 +0000 Subject: [PATCH 4/4] Name exp in the errInvalidFormField comment (closes #72) parseExpires wraps errInvalidFormField for exp, so its comment names exp alongside q. Model: opus-5-5 --- internal/handlers/auth.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/handlers/auth.go b/internal/handlers/auth.go index 171b900..a0ad493 100644 --- a/internal/handlers/auth.go +++ b/internal/handlers/auth.go @@ -18,9 +18,9 @@ import ( "sneak.berlin/go/pixa/internal/templates" ) -// errInvalidFormField reports a generator form field, or the q parameter of -// /v1/image/, whose value is non-numeric or out of range. The offending field -// name is wrapped in so the response can name it. +// errInvalidFormField reports a generator form field, or the q or exp +// parameter of /v1/image/, whose value is non-numeric or out of range. The +// offending field name is wrapped in so the response can name it. var errInvalidFormField = errors.New("invalid") // Bounds for the generator's quality and ttl fields; the quality bounds also -- 2.54.0