Keep a variant's accounting row when its file cannot be read (closes #340) #342

Merged
clawbot merged 2 commits from issue-340-reconcile-read-errors into next 2026-10-27 01:04:23 +01:00
4 changed files with 107 additions and 1 deletions
+4
View File
@@ -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 look that took one minute, the next one starts 10 to 15 minutes after that look
ended. 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 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 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, makes no database call. The content type comes from the file's first bytes,
+7
View File
@@ -30,6 +30,13 @@ P2: security: per-origin rate limiting
# Completed Steps # 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 - 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 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 request making the image (closes #339). It was answered 500 and logged at
+10 -1
View File
@@ -613,7 +613,9 @@ func (c *Cache) adoptVariantFile(
} }
// reconcileVariantRows drops accounting rows whose variant files are // 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 { func (c *Cache) reconcileVariantRows(ctx context.Context) error {
var after imagerequest.VariantKey var after imagerequest.VariantKey
@@ -641,6 +643,13 @@ func (c *Cache) reconcileVariantRows(ctx context.Context) error {
continue 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, _, err = c.db.ExecContext(ctx,
`DELETE FROM variant_content WHERE cache_key = ?`, string(key)) `DELETE FROM variant_content WHERE cache_key = ?`, string(key))
if err != nil { if err != nil {
@@ -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 // TestPeriodicReconciliationAdoptsFileThatAppearsAfterStartup proves
// reconciliation is not a one-shot startup-only pass: it must also run // 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 // on the periodic ticker, so a variant file that lands on disk with no