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