diff --git a/README.md b/README.md index a643476..49cafcb 100644 --- a/README.md +++ b/README.md @@ -252,6 +252,10 @@ less than ten times as long after the last look ended as that look took. After a look that took one minute, the next one starts 10 to 15 minutes after that look ended. +Each look also drops the rows of variants whose files are missing. When pixa +cannot read a variant file's size for another reason, it keeps the variant's +row. It logs a warning naming the variant key and the error. + pixa's target is 1-5k r/s, which has not been measured at that rate (see Load Test). Toward it, a cache hit opens the variant's file and nothing else, and makes no database call. The content type comes from the file's first bytes, diff --git a/TODO.md b/TODO.md index f00e81f..4b6920f 100644 --- a/TODO.md +++ b/TODO.md @@ -30,6 +30,13 @@ P2: security: per-origin rate limiting # Completed Steps +- 2026-10-26 the reconciliation pass drops a variant's accounting row only when + its file is missing (closes #340). Any other error reading the file's size + keeps the row. It dropped the row on any error and logged the file as missing. + - The kept row gets the warning "kept accounting row for unreadable variant + file", with the variant key and the error. + - The pass checks for `ErrNotFound`, which `FileStore.Size` returns for a + missing file. - 2026-10-26 on both image routes, a request is answered 499 and logged at info level when its client goes away before its image is ready, unless it is the request making the image (closes #339). It was answered 500 and logged at diff --git a/internal/imgcache/eviction.go b/internal/imgcache/eviction.go index ef5f346..2312a14 100644 --- a/internal/imgcache/eviction.go +++ b/internal/imgcache/eviction.go @@ -613,7 +613,9 @@ func (c *Cache) adoptVariantFile( } // reconcileVariantRows drops accounting rows whose variant files are -// missing, so the database never references deleted content. +// missing, so the database never references deleted content. A file whose +// size cannot be read for another reason may still be on disk, so its row +// stays, with a warning naming its key and the error. func (c *Cache) reconcileVariantRows(ctx context.Context) error { var after imagerequest.VariantKey @@ -641,6 +643,13 @@ func (c *Cache) reconcileVariantRows(ctx context.Context) error { continue } + if !errors.Is(err, ErrNotFound) { + c.log.Warn("kept accounting row for unreadable variant file", + "cache_key", key, "error", err) + + continue + } + _, err = c.db.ExecContext(ctx, `DELETE FROM variant_content WHERE cache_key = ?`, string(key)) if err != nil { diff --git a/internal/imgcache/eviction_internal_test.go b/internal/imgcache/eviction_internal_test.go index 15b2ebc..ed7b4eb 100644 --- a/internal/imgcache/eviction_internal_test.go +++ b/internal/imgcache/eviction_internal_test.go @@ -699,6 +699,92 @@ func TestStartEvictionReconcilesAccountingWithDisk(t *testing.T) { } } +// logLineNaming returns the first line of logs, written by slog's JSON +// handler, that is at level and names the variant key, or "" if none is. +func logLineNaming(logs, level string, key imagerequest.VariantKey) string { + for line := range strings.Lines(logs) { + if strings.Contains(line, `"level":"`+level+`"`) && + strings.Contains(line, `"cache_key":"`+string(key)+`"`) { + return line + } + } + + return "" +} + +// TestReconcileVariantRowsDropsOnlyRowsOfMissingFiles gives +// reconcileVariantRows two tracked variants. The first one's file is a +// symbolic link to itself, so its size cannot be read. Its row must stay, +// with a warning naming its key and the error. The second one has no file. +// Its row must go, with the info line for a missing file. +func TestReconcileVariantRowsDropsOnlyRowsOfMissingFiles(t *testing.T) { + t.Parallel() + + cache, _ := newEvictionTestCache(t, 1<<30) + storeEvictionTestVariant(t, cache, testVariantKeyOne, []byte("variant one")) + storeEvictionTestVariant(t, cache, testVariantKeyTwo, []byte("variant two")) + + unreadablePath := cache.variants.keyToPath(string(testVariantKeyOne)) + + err := os.Remove(unreadablePath) + if err != nil { + t.Fatalf("failed to remove the first variant's file: %v", err) + } + + err = os.Symlink(unreadablePath, unreadablePath) + if err != nil { + t.Fatalf("failed to link the first variant's path to itself: %v", err) + } + + _, statErr := os.Stat(unreadablePath) + if statErr == nil || errors.Is(statErr, fs.ErrNotExist) { + t.Fatalf("os.Stat() of the first variant: error = %v, "+ + "want an error other than a missing file", statErr) + } + + err = os.Remove(cache.variants.keyToPath(string(testVariantKeyTwo))) + if err != nil { + t.Fatalf("failed to remove the second variant's file: %v", err) + } + + var logBuf bytes.Buffer + + cache.log = slog.New(slog.NewJSONHandler(&logBuf, nil)) + + err = cache.reconcileVariantRows(t.Context()) + t.Logf("reconcileVariantRows() error = %v, log: %s", err, logBuf.String()) + + if err != nil { + t.Fatalf("reconcileVariantRows() error = %v", err) + } + + rowQuery := `SELECT COUNT(*) FROM variant_content WHERE cache_key = ?` + + if n := countRows(t, cache, rowQuery, string(testVariantKeyOne)); n != 1 { + t.Errorf("the variant whose size cannot be read has %d rows, want 1", n) + } + + if n := countRows(t, cache, rowQuery, string(testVariantKeyTwo)); n != 0 { + t.Errorf("the variant with no file has %d rows, want 0", n) + } + + logs := logBuf.String() + + warning := logLineNaming(logs, "WARN", testVariantKeyOne) + if !strings.Contains(warning, statErr.Error()) { + t.Errorf("no warning names %s and the error %q", testVariantKeyOne, statErr) + } + + if line := logLineNaming(logs, "INFO", testVariantKeyOne); line != "" { + t.Errorf("the variant whose size cannot be read was logged at info: %s", line) + } + + dropped := logLineNaming(logs, "INFO", testVariantKeyTwo) + if !strings.Contains(dropped, "dropped accounting row for missing variant file") { + t.Errorf("no info line says the file of %s is missing", testVariantKeyTwo) + } +} + // TestPeriodicReconciliationAdoptsFileThatAppearsAfterStartup proves // reconciliation is not a one-shot startup-only pass: it must also run // on the periodic ticker, so a variant file that lands on disk with no