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, on every host; 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, with tests for
those that can be made to fail. VariantStorage takes the cache's logger.

Model: opus-5-5

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

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

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
+// errInvalidFormField reports a generator form field, or the q or exp
-// /v1/image/, whose value is non-numeric or out of range. The offending field
+// parameter of /v1/image/, whose value is non-numeric or out of range. The
-// name is wrapped in so the response can name it.
+// 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

internal/handlers/image.go

@@ -116,11 +116,11 @@ func (s *Handlers) parseImageRequest(
 
 	req.Signature = query.Get("sig")
 
-	if expStr := query.Get("exp"); expStr != "" {
+	req.Expires, err = parseExpires(query)
-		exp, parseErr := strconv.ParseInt(expStr, 10, 64)
+	if err != nil {
-		if parseErr == nil {
+		s.respondError(w, err.Error(), http.StatusBadRequest)
-			req.Expires = time.Unix(exp, 0)
+
-		}
+		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,

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)
+			}
+		})
+	}
+}

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
+	c.writeMetadataSidecar(req, pathHash, contentHash, result)
-	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.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
 	}

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)

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())
+		}
+	}
+}

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
 }

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())
+	}
+}