diff --git a/TODO.md b/TODO.md index a8ec7c3..622d81f 100644 --- a/TODO.md +++ b/TODO.md @@ -42,6 +42,18 @@ exhaustion that is sooner, never negative; an allowlisted host's URL that has an `exp` follows it too; `immutable` stays, as freshness now ends at the expiry; documented in `README.md`. +- 2026-09-28 cache stats report real numbers (closes #56): `Cache.Stats` + counts the cached source images and processed variants (`source_content` + plus `variant_content`) and takes their size from `Cache.UsageBytes`, + instead of reading `request_cache` and `output_content`, which nothing + writes; those two tables are left in the schema; a disabled disk cache + reports no items and no size. A hit is counted even when the request + context has ended. A miss is counted after it is served or fails, also + when the request context has ended by then, with the bytes it read from + upstream, so `upstream_fetch_count` and `upstream_fetch_bytes` move, + including for an upstream body that fails partway or a fetched source + that then fails the magic byte check; `transform_count` counts each image + the image processor transcodes. - 2026-09-28 strip metadata from processed images (closes #82): every output is exported with govips' `StripMetadata`, so it carries no EXIF, XMP, IPTC or ICC profile; the image is first turned upright with `AutoRotate` (before sizes are diff --git a/internal/imgcache/cache.go b/internal/imgcache/cache.go index 172b40e..e15b90a 100644 --- a/internal/imgcache/cache.go +++ b/internal/imgcache/cache.go @@ -419,19 +419,21 @@ func (c *Cache) Stats(ctx context.Context) (*CacheStats, error) { return nil, fmt.Errorf("failed to get cache stats: %w", err) } - // Get actual item count and total size from content tables - err = c.db.QueryRowContext(ctx, - `SELECT COUNT(*) FROM request_cache`, - ).Scan(&stats.TotalItems) - if err != nil { - c.log.Warn("failed to count cache items for stats", "error", err) - } + // Count and size the cached source images and processed variants. A + // disabled cache holds none, whatever rows an earlier run left. + if !c.disabled { + err = c.db.QueryRowContext(ctx, ` + SELECT (SELECT COUNT(*) FROM source_content) + + (SELECT COUNT(*) FROM variant_content) + `).Scan(&stats.TotalItems) + 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) + stats.TotalSizeBytes, err = c.UsageBytes(ctx) + if err != nil { + c.log.Warn("failed to sum cache size for stats", "error", err) + } } // Compute hit rate as a ratio @@ -481,6 +483,19 @@ func (c *Cache) IncrementStats(ctx context.Context, hit bool, fetchBytes int64) } } +// IncrementTransformCount counts one image transcoded by the image processor. +func (c *Cache) IncrementTransformCount(ctx context.Context) { + _, err := c.db.ExecContext(ctx, ` + UPDATE cache_stats + SET transform_count = transform_count + 1, + last_updated_at = CURRENT_TIMESTAMP + WHERE id = 1 + `) + if err != nil { + c.log.Warn("failed to count transform", "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. diff --git a/internal/imgcache/imgcache.go b/internal/imgcache/imgcache.go index a6a591e..a74e783 100644 --- a/internal/imgcache/imgcache.go +++ b/internal/imgcache/imgcache.go @@ -163,9 +163,11 @@ type ImageCache interface { // CacheStats contains cache statistics type CacheStats struct { - // TotalItems is the number of cached items + // TotalItems is the number of cached source images plus processed + // variants TotalItems int64 - // TotalSizeBytes is the total size of cached content + // TotalSizeBytes is the total size of cached source images and + // processed variants TotalSizeBytes int64 // HitCount is the number of cache hits HitCount int64 diff --git a/internal/imgcache/service.go b/internal/imgcache/service.go index 3b295c7..d85dee8 100644 --- a/internal/imgcache/service.go +++ b/internal/imgcache/service.go @@ -143,7 +143,8 @@ func (s *Service) Get(ctx context.Context, req *ImageRequest) (*ImageResponse, e s.log.Error("failed to get cached variant", "key", result.CacheKey, "error", err) // Fall through to re-process } else { - s.cache.IncrementStats(ctx, true, 0) + // Counted also when the request context has ended meanwhile + s.cache.IncrementStats(context.WithoutCancel(ctx), true, 0) return &ImageResponse{ Content: reader, @@ -155,12 +156,15 @@ func (s *Service) Get(ctx context.Context, req *ImageRequest) (*ImageResponse, e } } - // Cache miss - check if we have source content cached + // Cache miss - process the cached source or fetch it, then count the + // miss with the bytes it fetched from upstream, also when it failed or + // the request context has ended meanwhile cacheKey := CacheKey(req) - s.cache.IncrementStats(ctx, false, 0) + response, fetchedBytes, err := s.processFromSourceOrFetch(ctx, req, cacheKey) + + s.cache.IncrementStats(context.WithoutCancel(ctx), false, fetchedBytes) - response, err := s.processFromSourceOrFetch(ctx, req, cacheKey) if err != nil { return nil, err } @@ -268,22 +272,20 @@ func (s *Service) loadCachedSource(contentHash ContentHash) []byte { } // processFromSourceOrFetch processes an image, using cached source content -// if available. +// if available. It also returns the number of bytes fetched from upstream, +// as fetchAndProcess does, or 0 when the cached source was used. func (s *Service) processFromSourceOrFetch( ctx context.Context, req *ImageRequest, cacheKey VariantKey, -) (*ImageResponse, error) { +) (*ImageResponse, int64, error) { // Check if we have cached source content contentHash, _, err := s.cache.LookupSource(ctx, req) if err != nil { s.log.Warn("source lookup failed", "error", err) } - var ( - sourceData []byte - fetchBytes int64 - ) + var sourceData []byte if contentHash != "" { s.log.Debug("using cached source", "hash", contentHash) @@ -292,26 +294,25 @@ func (s *Service) processFromSourceOrFetch( // Fetch from upstream if we don't have source data or it's empty if len(sourceData) == 0 { - resp, err := s.fetchAndProcess(ctx, req, cacheKey) - if err != nil { - return nil, err - } - - return resp, nil + return s.fetchAndProcess(ctx, req, cacheKey) } - // Process using cached source - fetchBytes = int64(len(sourceData)) + // Process using cached source; nothing was fetched from upstream + resp, err := s.processAndStore( + ctx, req, cacheKey, sourceData, int64(len(sourceData)), + ) - return s.processAndStore(ctx, req, cacheKey, sourceData, fetchBytes) + return resp, 0, err } // fetchAndProcess fetches from upstream, processes, and caches the result. +// It also returns the number of bytes read from upstream, including when +// reading the response or a later step fails. func (s *Service) fetchAndProcess( ctx context.Context, req *ImageRequest, cacheKey VariantKey, -) (*ImageResponse, error) { +) (*ImageResponse, int64, error) { // Fetch from upstream sourceURL := req.SourceURL() @@ -330,20 +331,20 @@ func (s *Service) fetchAndProcess( } } - return nil, fmt.Errorf("upstream fetch failed: %w", err) + return nil, 0, fmt.Errorf("upstream fetch failed: %w", err) } defer func() { _ = fetchResult.Content.Close() }() // Read and validate the source content sourceData, err := io.ReadAll(fetchResult.Content) + fetchBytes := int64(len(sourceData)) + if err != nil { - return nil, fmt.Errorf("failed to read upstream response: %w", err) + return nil, fetchBytes, fmt.Errorf("failed to read upstream response: %w", err) } // Calculate download bitrate - fetchBytes := int64(len(sourceData)) - var downloadRate string if fetchResult.FetchDurationMs > 0 { @@ -368,7 +369,7 @@ func (s *Service) fetchAndProcess( // Validate magic bytes match content type err = magic.ValidateMagicBytes(sourceData, fetchResult.ContentType) if err != nil { - return nil, fmt.Errorf("content validation failed: %w", err) + return nil, fetchBytes, fmt.Errorf("content validation failed: %w", err) } // Store source content @@ -378,7 +379,9 @@ func (s *Service) fetchAndProcess( // Continue even if caching fails } - return s.processAndStore(ctx, req, cacheKey, sourceData, fetchBytes) + resp, err := s.processAndStore(ctx, req, cacheKey, sourceData, fetchBytes) + + return resp, fetchBytes, err } // processAndStore processes an image and stores the result. @@ -406,6 +409,9 @@ func (s *Service) processAndStore( processDuration := time.Since(processStart) + // Counted also when the request context has ended meanwhile + s.cache.IncrementTransformCount(context.WithoutCancel(ctx)) + // Read processed content processedData, err := io.ReadAll(processResult.Content) _ = processResult.Content.Close() diff --git a/internal/imgcache/stats_internal_test.go b/internal/imgcache/stats_internal_test.go index 5076179..94ee241 100644 --- a/internal/imgcache/stats_internal_test.go +++ b/internal/imgcache/stats_internal_test.go @@ -4,6 +4,9 @@ import ( "bytes" "context" "database/sql" + "image/color" + "io" + "io/fs" "log/slog" "math" "strings" @@ -11,6 +14,7 @@ import ( "time" "sneak.berlin/go/pixa/internal/database" + "sneak.berlin/go/pixa/internal/httpfetcher" ) func setupStatsTestDB(t *testing.T) *sql.DB { @@ -125,7 +129,7 @@ func TestStats_LogsFailedCountQueries(t *testing.T) { } _, err = db.ExecContext(t.Context(), - `DROP TABLE request_cache; DROP TABLE output_content`) + `DROP TABLE source_content; DROP TABLE variant_content`) if err != nil { t.Fatal(err) } @@ -183,3 +187,313 @@ func TestIncrementStats_LogsFailedUpdates(t *testing.T) { } } } + +// TestStats_TotalsCountSourcesAndVariants verifies that TotalItems and +// TotalSizeBytes cover the stored source images and processed variants. +func TestStats_TotalsCountSourcesAndVariants(t *testing.T) { + t.Parallel() + + cache, _ := newEvictionTestCache(t, 1<<30) + + storeEvictionTestSource(t, cache, testHostCDN, testPathCat, + bytes.Repeat([]byte{0xAA}, 1000)) + storeEvictionTestVariant(t, cache, testVariantKeyOne, + bytes.Repeat([]byte{0xAB}, 500)) + storeEvictionTestVariant(t, cache, testVariantKeyTwo, + bytes.Repeat([]byte{0xAC}, 250)) + + stats, err := cache.Stats(t.Context()) + if err != nil { + t.Fatalf("Stats() error = %v", err) + } + + if stats.TotalItems != 3 { + t.Errorf("TotalItems = %d, want 3 (1 source, 2 variants)", stats.TotalItems) + } + + if stats.TotalSizeBytes != 1750 { + t.Errorf("TotalSizeBytes = %d, want 1750 (1000+500+250)", + stats.TotalSizeBytes) + } +} + +// TestStats_DisabledCacheReportsNoItems verifies that a disabled disk cache +// reports no items and no size, even when its database still holds the +// rows of an earlier run with the disk cache enabled. +func TestStats_DisabledCacheReportsNoItems(t *testing.T) { + t.Parallel() + + enabled, _ := newEvictionTestCache(t, 1<<30) + + storeEvictionTestSource(t, enabled, testHostCDN, testPathCat, + bytes.Repeat([]byte{0xAA}, 1000)) + storeEvictionTestVariant(t, enabled, testVariantKeyOne, + bytes.Repeat([]byte{0xAB}, 500)) + + disabled, err := NewCache(enabled.db, CacheConfig{ + StateDir: t.TempDir(), + CacheTTL: time.Hour, + NegativeTTL: 5 * time.Minute, + DisableDiskCache: true, + }) + if err != nil { + t.Fatal(err) + } + + stats, err := disabled.Stats(t.Context()) + if err != nil { + t.Fatalf("Stats() error = %v", err) + } + + if stats.TotalItems != 0 || stats.TotalSizeBytes != 0 { + t.Errorf("TotalItems = %d, TotalSizeBytes = %d, want 0 and 0", + stats.TotalItems, stats.TotalSizeBytes) + } +} + +// cacheStatsCounters holds the counters of the cache_stats row, in column +// order. +type cacheStatsCounters struct { + hitCount int64 + missCount int64 + upstreamFetchCount int64 + upstreamFetchBytes int64 + transformCount int64 +} + +// readCacheStatsCounters reads the counters of the cache_stats row. +func readCacheStatsCounters(t *testing.T, cache *Cache) cacheStatsCounters { + t.Helper() + + var got cacheStatsCounters + + err := cache.db.QueryRowContext(t.Context(), ` + SELECT hit_count, miss_count, upstream_fetch_count, + upstream_fetch_bytes, transform_count + FROM cache_stats WHERE id = 1 + `).Scan(&got.hitCount, &got.missCount, &got.upstreamFetchCount, + &got.upstreamFetchBytes, &got.transformCount) + if err != nil { + t.Fatalf("failed to read cache_stats: %v", err) + } + + return got +} + +// TestService_Get_CountsStats walks Get through a miss that fetches the +// source, a hit, a miss that reuses the cached source, and two misses whose +// source cannot be used, checking every cache_stats counter after each. +func TestService_Get_CountsStats(t *testing.T) { + t.Parallel() + + svc, fixtures := SetupTestService(t) + + // NewTestFS builds the same files the test service's fetcher serves. + testFS, _ := NewTestFS(t) + + photo, err := fs.ReadFile(testFS, fixtures.GoodHostJPEG) + if err != nil { + t.Fatal(err) + } + + fake, err := fs.ReadFile(testFS, fixtures.InvalidFile) + if err != nil { + t.Fatal(err) + } + + photoBytes, fakeBytes := int64(len(photo)), int64(len(fake)) + + // want is hits, misses, upstream fetches, upstream bytes, transforms. + steps := []struct { + name string + path string + size int + wantErr bool + want cacheStatsCounters + }{ + {"miss that fetches the source", testPathPhoto, 50, false, + cacheStatsCounters{0, 1, 1, photoBytes, 1}}, + {"hit", testPathPhoto, 50, false, + cacheStatsCounters{1, 1, 1, photoBytes, 1}}, + {"miss that reuses the cached source", testPathPhoto, 25, false, + cacheStatsCounters{1, 2, 1, photoBytes, 2}}, + {"miss whose source fails the magic byte check", "/images/fake.jpg", 50, true, + cacheStatsCounters{1, 3, 2, photoBytes + fakeBytes, 2}}, + {"miss whose source is not found", "/images/nonexistent.jpg", 50, true, + cacheStatsCounters{1, 4, 2, photoBytes + fakeBytes, 2}}, + } + + for _, step := range steps { + resp, err := svc.Get(t.Context(), &ImageRequest{ + SourceHost: fixtures.GoodHost, + SourcePath: step.path, + Size: Size{Width: step.size, Height: step.size}, + Format: FormatJPEG, + Quality: 85, + FitMode: FitCover, + }) + if (err != nil) != step.wantErr { + t.Fatalf("%s: Get() error = %v, want error %t", step.name, err, step.wantErr) + } + + if err == nil { + _ = resp.Content.Close() + } + + got := readCacheStatsCounters(t, svc.cache) + if got != step.want { + t.Fatalf("after the %s: counters = %+v, want %+v", step.name, got, step.want) + } + } +} + +// fakeUpstream answers every fetch with itself as a JPEG body. The body +// serves data, then calls cancel, when set, and returns err; io.EOF ends +// the body normally. +type fakeUpstream struct { + data *bytes.Reader + cancel context.CancelFunc + err error +} + +func (u *fakeUpstream) Fetch( + context.Context, string, +) (*httpfetcher.FetchResult, error) { + return &httpfetcher.FetchResult{ + Content: io.NopCloser(u), + ContentLength: -1, + ContentType: testContentTypeJPEG, + }, nil +} + +func (u *fakeUpstream) Read(p []byte) (int, error) { + if u.data.Len() > 0 { + return u.data.Read(p) + } + + if u.cancel != nil { + u.cancel() + } + + return 0, u.err +} + +// TestService_Get_CountsInterruptedMisses checks every cache_stats counter +// after a miss whose request context ends during or after the upstream +// fetch, and after a miss whose upstream body is over the size limit. +func TestService_Get_CountsInterruptedMisses(t *testing.T) { + t.Parallel() + + photo := generateTestJPEG(t, 100, 100, color.RGBA{255, 0, 0, 255}) + half := len(photo) / 2 + + // want is hits, misses, upstream fetches, upstream bytes, transforms. + tests := []struct { + name string + served int // bytes of the photo the upstream body serves + cancel bool // whether the body then ends the request context + readErr error // what the body then returns + wantErr bool + want cacheStatsCounters + }{ + {"request context ends during the fetch", half, true, context.Canceled, true, + cacheStatsCounters{0, 1, 1, int64(half), 0}}, + {"request context ends after the fetch", len(photo), true, io.EOF, false, + cacheStatsCounters{0, 1, 1, int64(len(photo)), 1}}, + {"upstream body over the size limit", half, false, + httpfetcher.ErrResponseTooLarge, true, + cacheStatsCounters{0, 1, 1, int64(half), 0}}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + svc, fixtures := SetupTestService(t) + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + + upstream := &fakeUpstream{ + data: bytes.NewReader(photo[:tc.served]), + err: tc.readErr, + } + if tc.cancel { + upstream.cancel = cancel + } + + svc.fetcher = upstream + + resp, err := svc.Get(ctx, &ImageRequest{ + SourceHost: fixtures.GoodHost, + SourcePath: testPathPhoto, + Size: Size{Width: 50, Height: 50}, + Format: FormatJPEG, + Quality: 85, + FitMode: FitCover, + }) + t.Logf("Get() error = %v", err) + + if (err != nil) != tc.wantErr { + t.Fatalf("Get() error = %v, want error %t", err, tc.wantErr) + } + + if err == nil { + _ = resp.Content.Close() + } + + got := readCacheStatsCounters(t, svc.cache) + if got != tc.want { + t.Errorf("counters = %+v, want %+v", got, tc.want) + } + }) + } +} + +// TestService_Get_CountsHitAfterRequestEnds checks every cache_stats counter +// after a hit served with a request context that has already ended: only +// the hit count moves. +func TestService_Get_CountsHitAfterRequestEnds(t *testing.T) { + t.Parallel() + + svc, fixtures := SetupTestService(t) + + req := &ImageRequest{ + SourceHost: fixtures.GoodHost, + SourcePath: testPathPhoto, + Size: Size{Width: 50, Height: 50}, + Format: FormatJPEG, + Quality: 85, + FitMode: FitCover, + } + + // A first request caches the variant. + resp, err := svc.Get(t.Context(), req) + if err != nil { + t.Fatalf("first Get() error = %v", err) + } + + _ = resp.Content.Close() + + want := readCacheStatsCounters(t, svc.cache) + want.hitCount++ + + ctx, cancel := context.WithCancel(t.Context()) + cancel() + + resp, err = svc.Get(ctx, req) + if err != nil { + t.Fatalf("Get() with an ended request context: error = %v", err) + } + + _ = resp.Content.Close() + + if resp.CacheStatus != CacheHit { + t.Fatalf("CacheStatus = %v, want %v", resp.CacheStatus, CacheHit) + } + + got := readCacheStatsCounters(t, svc.cache) + if got != want { + t.Errorf("counters = %+v, want %+v", got, want) + } +}