7 Commits
Author SHA1 Message Date
clawbot 9f1e9f5253 Rewrite AGENTS.md in short plain sentences (#327)
check / check (push) Waiting to run
Every rule keeps its meaning and emphasis. Sentences are split so each
holds one idea, with the main rule before its exception and every
command, file name and identifier in backticks.

Three statements were false against the repo or the standing rulings
on record and are corrected:

- the format check is `make fmt-check`, not `make check-fmt`
- a feature branch reaches `next` through a PR that passes review, is
  merged only when the feature is completely finished and the code is
  up to standards, and is deleted after the merge; only the user
  merges `next` into `main`
- the naming example uses the code's term: `al` is bad,
  `SourceHostAllowlist` is good

The `Last Updated` line takes today's date.

Model: fable-5-1
2026-10-27 05:06:36 +01:00
clawbot 2c90144e7b Go on past cache entries the reconciliation pass cannot read (closes #343)
check / check (push) Canceled after 0s
The walk of each storage directory returned the error of a directory it
could not list, or of a source or variant file whose info it could not
read. The pass then stopped before its later checks, every time it ran.
Now reconcileFiles skips a directory it cannot list and a file whose
info it cannot read, temp files included. It logs a warning naming the
path and the error, and the walk goes on. It reads each file's info
once and hands it to sweepStaleTempFile, reconcileVariantFile or
reconcileSourceFile. A file renamed or removed after its directory was
listed is skipped with no warning. A cancelled context still stops the
walk with its error. README.md says so under Storage.

Model: opus-5-5
2026-10-27 01:13:55 +00:00
clawbot 26b5160aa8 Test that reconciliation goes on past entries it cannot read
Each storage directory gets a directory the pass cannot list and a file
whose info it cannot read. Their paths are longer than Linux accepts,
even for root. The test wants a warning naming each path and the error.
It also wants the rest of the pass done: a variant file with no row
adopted, the row of a missing variant file dropped, a source file with
no row removed, and a wrong usage total corrected. A second test puts a
temp file whose info cannot be read in each storage directory and wants
the same warning. On next the first test's pass stops at the first such
directory and returns its error. The second test gets no warning.

Model: opus-5-5
2026-10-27 01:12:34 +00:00
clawbot 33045a24b5 Keep a variant's accounting row when its file cannot be read (closes #340)
check / check (push) Canceled after 0s
The reconciliation pass dropped a variant's accounting row on any error
reading its file's size, and logged every such file as missing. A file
still on disk then had no row, so eviction no longer counted it against
cache_max_bytes. Now only a missing file (ErrNotFound, which
FileStore.Size returns for it) loses its row, with the same info line.
Any other error keeps the row and logs a warning naming the variant key
and the error, and the pass goes on to the next key. README.md says so
under Storage.

Model: opus-5-5
2026-10-26 23:56:34 +00:00
clawbot 701ed9b94b Test that reconciliation drops a variant's row only when its file is missing
check / check (push) Canceled after 0s
reconcileVariantRows is given two tracked variants. The first one's
file is a symbolic link to itself, so reading its size fails with an
error other than a missing file. The test wants its row kept, with a
warning naming its key and the error. The second one has no file, and
the test wants its row dropped with the info line for a missing file.
The test fails on next, which drops both rows and logs both files as
missing. The fix follows in the next commit.

Model: opus-5-5
2026-10-26 23:54:24 +00:00
clawbot 233765033a Answer 499 to a client that goes away while waiting for an image (closes #339)
check / check (push) Canceled after 0s
When a request waits for an image another request is making and its
client goes away, the image proxy returns context.Canceled. serveImage
now answers it 499, the status nginx calls "client closed request". It
logs it once at info level with the request_id, host and path. It was
answered 500 and logged at error level, as pixa's own failure. A
cancellation while the request's context is live is still answered 500.
The request making the image is still answered as before. README.md
lists the 499 on both image routes.

Model: opus-5-5
2026-10-26 23:37:35 +00:00
clawbot d33316caf3 Test that a client leaving while another request makes its image gets 499
On both image routes, a request waits for an image another request is
making, and its client goes away. The first test wants that request
answered 499 and logged once at info level. It fails on next, which
answers 500 and logs it at error level. The second test pins the 500
that a cancellation keeps while the request's context is live; it
passes on next. The fix follows in the next commit.

Model: opus-5-5
2026-10-26 23:26:07 +00:00
7 changed files with 631 additions and 86 deletions
+52 -51
View File
@@ -1,75 +1,76 @@
# Repository Rules
Last Updated 2026-01-08
Last Updated 2026-10-27
These rules MUST be followed at all times, it is very important.
These rules MUST be followed at all times. This is very important.
- Never use `git add -A` - add specific changes to a deliberate commit. A commit
should contain one change. After each change, make a commit with a good
one-line summary.
- Never use `git add -A`. Stage specific changes for a deliberate commit. A
commit holds one change. After each change, make a commit with a good one-line
summary.
- NEVER modify the linter config without asking first.
- NEVER modify tests to exclude special cases or otherwise get them to pass
without asking first. In almost all cases, the code should be changed, NOT the
tests. If you think the test needs to be changed, make your case for that and
ask for permission to proceed, then stop. You need explicit user approval to
modify existing tests. A bug fix may change an existing test without asking
when that test pins exactly the behavior the filed bug calls wrong, and the
change moves it to the fixed behavior and nothing else; any other change to an
existing test still needs explicit user approval. (You do not need user
approval for writing NEW tests.)
- NEVER modify a test to exclude special cases or otherwise make it pass without
asking first. In almost all cases, change the code, NOT the test. You need
explicit user approval to modify an existing test. If you think a test needs
to change, make your case and ask for permission to proceed. Then stop. A bug
fix may change an existing test without asking only when that test pins
exactly the behavior the filed bug calls wrong. The change must then move the
test to the fixed behavior and nothing else. Any other change to an existing
test needs explicit user approval. Writing NEW tests needs no approval.
- When linting, assume the linter config is CORRECT, and that each item output
by the linter is something that legitimately needs fixing in the code.
- When linting, assume the linter config is CORRECT. Treat each item the linter
reports as something that legitimately needs fixing in the code.
- When running tests, use `make test`.
- Before commits, run `make check`. This runs `make lint` and `make test` and
`make check-fmt`. Any issues discovered MUST be resolved before committing
unless explicitly told otherwise.
- Before committing, run `make check`. It runs `make test`, `make lint` and
`make fmt-check`. Any issue it finds MUST be resolved before committing,
unless you are explicitly told otherwise.
- When fixing a bug, write a failing test for the bug FIRST. Add appropriate
logging to the test to ensure it is written correctly. Commit that. Then go
about fixing the bug until the test passes (without modifying the test
further). Then commit that.
logging to the test, to make sure the test is written correctly. Commit that.
Then work on the fix until the test passes, without changing the test further.
Then commit the fix.
- When adding a new feature, do the same - implement a test first (TDD). It
doesn't have to be super complex. Commit the test, then commit the feature.
- When adding a new feature, do the same: write a test first (test-driven
development, TDD). The test does not need to be very complex. Commit the test,
then commit the feature.
- When adding a new feature, use a feature branch. When the feature is
completely finished and the code is up to standards (passes `make check`) then
and only then can the feature branch be merged into `main` and the branch
deleted.
- When adding a new feature, use a feature branch. The feature branch reaches
`next` through a PR that passes review. It is merged only when the feature is
completely finished and the code is up to standards. The code is up to
standards when it passes `make check`. The branch is deleted after the merge.
Only the user merges `next` into `main`.
- Write godoc documentation comments for all exported types and functions as you
go along.
- Write `godoc` comments for all exported types and functions as you go along.
- ALWAYS be consistent in naming. If you name something one thing in one place,
name it the EXACT SAME THING in another place.
- ALWAYS be consistent in naming. If you name something one way in one place,
use the EXACT SAME name in every other place.
- Be descriptive and specific in naming. `wl` is bad; `SourceHostWhitelist` is
- Be descriptive and specific in naming. `al` is bad; `SourceHostAllowlist` is
good. `ConnsPerHost` is bad; `MaxConnectionsPerHost` is good.
- This is not prototype or teaching code - this is designed for production. Any
security issues (such as denial of service) or other web vulnerabilities are
P1 bugs and must be added to TODO.md at the top.
- This is not prototype or teaching code. It is designed for production. Any
security issue (such as denial of service) or other web vulnerability is a P1
bug. It must be added at the top of `TODO.md`.
- As this is production code, no stubbing of implementations unless specifically
instructed. We need working implementations.
- Do not stub an implementation unless you are specifically instructed to. This
is production code, and we need working implementations.
- NEVER silently fall back to a different setting when a user's parameter
explicitly specifies a value. If a user requests format=webp and WebP encoding
is not supported, return an error - do NOT silently output PNG instead. If a
user specifies fit=invalid and that fit mode doesn't exist, return an error -
do NOT silently default to "cover". Silent fallbacks violate the principle of
least surprise and mask bugs. The only acceptable defaults are for OMITTED
parameters, never for INVALID explicit values.
explicitly specifies a value. For example, if a user requests `format=webp`
and WebP encoding is not supported, return an error. Do NOT silently output
PNG instead. If a user specifies `fit=invalid` and that fit mode does not
exist, return an error. Do NOT silently default to `cover`. A silent fallback
violates the principle of least surprise and masks bugs. Defaults are
acceptable only for OMITTED parameters, never for INVALID explicit values.
- Avoid vendoring deps unless specifically instructed to. NEVER commit the
vendor directory, NEVER commit compiled binaries. If these directories or
files exist, add them to .gitignore (and commit the .gitignore) if they are
not already in there. Keep the entire git repository (with history) small -
under 20MiB, unless you specifically must commit larger files (e.g. test
fixture example media files). Only OUR source code and immediately supporting
files (such as test examples) goes into the repo/history.
- Avoid vendoring dependencies unless specifically instructed to. NEVER commit
the `vendor/` directory. NEVER commit compiled binaries. If such a directory
or file exists and `.gitignore` does not list it, add it to `.gitignore`.
Commit that `.gitignore` change. Keep the entire git repository, history
included, under 20 MiB. Go over 20 MiB only when you specifically must commit
a large file, such as a media file used as a test fixture. Only OUR source
code and its immediately supporting files, such as test examples, go into the
repository and its history.
+12
View File
@@ -252,6 +252,15 @@ 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.
During a look, pixa skips a directory it cannot list and a file whose size it
cannot read. It logs a warning naming the path and the error, and goes on with
the rest of the look. A file renamed or removed after pixa listed its directory
gets no warning.
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,
@@ -310,6 +319,8 @@ path under `/v1/` answers 200, in maintenance mode too.
- 403 when the upstream host, or a host it redirects to, has an address in a
blocked network (see `blocked_networks`).
- 429 over `image_requests_per_minute` (below).
- 499, with no body, when the client goes away before its image is ready,
unless its request is the one making the image (below).
- 415 when the upstream answers with a `Content-Type` that is not one of the
source formats (below).
- 415 when the upstream sends a body whose first bytes are not those of the
@@ -341,6 +352,7 @@ path under `/v1/` answers 200, in maintenance mode too.
- 403
- 415
- 429
- 499, with no body
- 502
- 503
- 504
+29
View File
@@ -30,6 +30,35 @@ P2: security: per-origin rate limiting
# Completed Steps
- 2026-10-27 the reconciliation pass skips a directory it cannot list and a file
whose info it cannot read, and goes on (closes #343). It stopped before its
later checks at a directory it could not list, or at a source or variant file
whose info it could not read.
- It logs the warning "skipped unreadable entry in cache directory", with
the path and the error.
- A file renamed or removed after its directory was listed gets no warning.
- `reconcileFiles` reads each file's info once, before the temp-file check,
and hands it to `sweepStaleTempFile`, `reconcileVariantFile` or
`reconcileSourceFile`.
- A cancelled context still stops the walk with its error.
- 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
error level, as pixa's own failure.
- The line is "client went away before the image was ready". It carries the
`request_id`, the host and the path.
- The 499 has no body, since nobody reads it.
- `serveImage` answers it before calling `respondImageError`, which cannot
see the request's context.
- An error wrapping `context.Canceled` while the request's context is live
is still answered 500 and logged at error level.
- 2026-10-26 `README.md`'s Design section starts with a Concepts list (closes
#321). Each concept gets one sentence, under the name the code gives it.
- Storage calls the transformed images variants, in shorter sentences.
@@ -0,0 +1,177 @@
package handlers
import (
"bytes"
"context"
"encoding/json"
"log/slog"
"net/http"
"net/http/httptest"
"slices"
"testing"
"time"
"github.com/go-chi/chi/v5/middleware"
"sneak.berlin/go/pixa/internal/httpfetcher"
"sneak.berlin/go/pixa/internal/imagerequest"
)
// heldFetcher sends on started when a fetch begins, and holds the fetch until
// release is closed. It then fails the fetch as an upstream error.
type heldFetcher struct {
started chan struct{}
release chan struct{}
}
// Fetch sends on f.started, waits for f.release to be closed, and returns
// httpfetcher.ErrUpstreamError.
func (f heldFetcher) Fetch(
context.Context, imagerequest.Source,
) (*httpfetcher.FetchResult, error) {
f.started <- struct{}{}
<-f.release
return nil, httpfetcher.ErrUpstreamError
}
// readLogLines decodes the JSON log lines in logs.
func readLogLines(t *testing.T, logs *bytes.Buffer) []map[string]any {
t.Helper()
t.Logf("logged:\n%s", logs.String())
var lines []map[string]any
dec := json.NewDecoder(logs)
for dec.More() {
var line map[string]any
err := dec.Decode(&line)
if err != nil {
t.Fatalf("decoding log line: %v", err)
}
lines = append(lines, line)
}
return lines
}
// TestImageRoutes_ClientGoneWhileWaitingAnswers499 checks that both image
// routes answer 499 to a request whose client goes away while it waits for an
// image another request is making. A first request's fetch is held, so the
// image is being made, and a second request for the same image waits for it
// until its client goes away. The second request must be logged once at info
// level with its request ID and the source host and path. Nothing may be
// logged at error level.
func TestImageRoutes_ClientGoneWhileWaitingAnswers499(t *testing.T) {
t.Parallel()
const requestID = "test-request-id"
for route, imageURL := range photoURLsByRoute() {
t.Run(route, func(t *testing.T) {
t.Parallel()
var logs bytes.Buffer
fetcher := heldFetcher{started: make(chan struct{}), release: make(chan struct{})}
h, routes := newRoutesFetchingThrough(t, fetcher,
slog.New(slog.NewJSONHandler(&logs, nil)))
target := imageURL(t, h)
firstDone := make(chan struct{})
go func() {
defer close(firstDone)
sendGet(t, routes, target)
}()
<-fetcher.started
ctx, cancel := context.WithCancel(context.WithValue(t.Context(),
middleware.RequestIDKey, requestID))
rec := httptest.NewRecorder()
secondDone := make(chan struct{})
go func() {
defer close(secondDone)
routes.ServeHTTP(rec, httptest.NewRequestWithContext(
ctx, http.MethodGet, target, nil))
}()
// Give the second request time to start waiting for the first
// request's image. The fetch is still held, so the second request
// can end only because its client went away
time.Sleep(100 * time.Millisecond)
cancel()
<-secondDone
close(fetcher.release)
<-firstDone
if rec.Code != 499 {
t.Errorf("status = %d, want 499", rec.Code)
}
var clientGoneLines int
for _, line := range readLogLines(t, &logs) {
if line["level"] == slog.LevelError.String() {
t.Errorf("logged at error level: %v", line["msg"])
}
if line["level"] == slog.LevelInfo.String() &&
line["msg"] == "client went away before the image was ready" &&
line["request_id"] == requestID &&
line["host"] == signedHost &&
line["path"] == photoPath {
clientGoneLines++
}
}
if clientGoneLines != 1 {
t.Errorf("info line naming the request logged %d times, want 1",
clientGoneLines)
}
})
}
}
// TestImageRoutes_CanceledWithLiveRequestAnswers500 checks that both image
// routes answer 500, logged as "failed to get image" at error level, for an
// image service error that wraps context.Canceled while the request's own
// context is live. Its client has not gone away, so the cancellation is
// pixa's own failure.
func TestImageRoutes_CanceledWithLiveRequestAnswers500(t *testing.T) {
t.Parallel()
for route, imageURL := range photoURLsByRoute() {
t.Run(route, func(t *testing.T) {
t.Parallel()
var logs bytes.Buffer
h, routes := newRoutesFetchingThrough(t,
failingFetcher{err: context.Canceled},
slog.New(slog.NewJSONHandler(&logs, nil)))
rec := sendGet(t, routes, imageURL(t, h))
if rec.Code != http.StatusInternalServerError {
t.Errorf("status = %d, want %d",
rec.Code, http.StatusInternalServerError)
}
if !slices.ContainsFunc(readLogLines(t, &logs),
func(line map[string]any) bool {
return line["level"] == slog.LevelError.String() &&
line["msg"] == "failed to get image"
}) {
t.Error(`no "failed to get image" line logged at error level`)
}
})
}
}
+24 -1
View File
@@ -1,6 +1,7 @@
package handlers
import (
"context"
"errors"
"fmt"
"io"
@@ -19,6 +20,12 @@ import (
"sneak.berlin/go/pixa/internal/magic"
)
// statusClientClosedRequest is the status nginx calls "client closed
// request". The image routes answer it when the client goes away before its
// image is ready, unless its request is the one making the image. Nobody reads
// it; it is for logs and metrics.
const statusClientClosedRequest = 499
// HandleImage handles the main image proxy route:
// /v1/image/<host>/<path>/<width>x<height>.<format>, or with no format
// /v1/image/<host>/<path>/<width>x<height>
@@ -345,7 +352,8 @@ func notModified(w http.ResponseWriter, r *http.Request, etag string) bool {
// serveImage serves the image that req asks for. Both image routes call it
// once they have the request and its URL's expiry, which ends the
// Cache-Control max-age. It chooses the format for the format auto, answers
// If-None-Match with 304 and HEAD with the headers only, and answers an error
// If-None-Match with 304 and HEAD with the headers only. It answers 499 when
// the image service stopped because the client went away, and any other error
// of the image service with respondImageError.
func (s *Handlers) serveImage(
w http.ResponseWriter, r *http.Request,
@@ -362,6 +370,21 @@ func (s *Handlers) serveImage(
startTime := time.Now()
resp, err := s.imgSvc.Get(r.Context(), req)
// The client went away before its image was ready, which is not pixa's
// failure. A cancellation while the request's context is live is pixa's,
// and respondImageError answers it 500.
if errors.Is(err, context.Canceled) && r.Context().Err() != nil {
s.log.Info("client went away before the image was ready",
"request_id", middleware.GetReqID(r.Context()),
"host", req.Source.Host,
"path", req.Source.Path,
)
w.WriteHeader(statusClientClosedRequest)
return
}
if err != nil {
s.respondImageError(w, req, err)
+50 -34
View File
@@ -515,12 +515,15 @@ func (c *Cache) reconcileAccounting(ctx context.Context) error {
}
// reconcileFiles walks baseDir, one of the cache's storage directories,
// sweeping stale temp files and passing each other file, with its name, to
// reconcileFile. Once ctx is cancelled it stops at the next file and
// returns ctx's error.
// sweeping stale temp files and passing each other file, with its info and
// name, to reconcileFile. It skips a directory it cannot list and a file
// whose info it cannot read, so one such entry does not stop the pass. It
// logs a warning naming the path and the error. A file renamed or removed
// after its directory was listed is skipped with no warning. Once ctx is
// cancelled it stops at the next file and returns ctx's error.
func (c *Cache) reconcileFiles(
ctx context.Context, baseDir string,
reconcileFile func(path string, entry fs.DirEntry, name string) error,
reconcileFile func(path string, info fs.FileInfo, name string) error,
) error {
return filepath.WalkDir(
baseDir,
@@ -529,19 +532,38 @@ func (c *Cache) reconcileFiles(
return ctx.Err()
}
if err != nil || entry.IsDir() {
return err
if err != nil {
c.log.Warn("skipped unreadable entry in cache directory",
"path", path, "error", err)
return nil
}
if entry.IsDir() {
return nil
}
info, err := entry.Info()
if errors.Is(err, fs.ErrNotExist) {
return nil
}
if err != nil {
c.log.Warn("skipped unreadable entry in cache directory",
"path", path, "error", err)
return nil
}
name := entry.Name()
if strings.HasPrefix(name, tempFilePrefix) {
c.sweepStaleTempFile(path, entry)
c.sweepStaleTempFile(path, info)
return nil
}
return reconcileFile(path, entry, name)
return reconcileFile(path, info, name)
},
)
}
@@ -551,8 +573,8 @@ func (c *Cache) reconcileFiles(
// and sweeping stale temp files.
func (c *Cache) reconcileVariantFiles(ctx context.Context) error {
return c.reconcileFiles(ctx, c.variants.baseDir,
func(path string, entry fs.DirEntry, name string) error {
return c.reconcileVariantFile(ctx, path, entry, imagerequest.VariantKey(name))
func(path string, info fs.FileInfo, name string) error {
return c.reconcileVariantFile(ctx, path, info, imagerequest.VariantKey(name))
})
}
@@ -562,16 +584,11 @@ func (c *Cache) reconcileVariantFiles(ctx context.Context) error {
// crash or a restored snapshot can leave it, is removed with its row and
// a warning naming it, so the variant is converted again.
func (c *Cache) reconcileVariantFile(
ctx context.Context, path string, entry fs.DirEntry, cacheKey imagerequest.VariantKey,
ctx context.Context, path string, info fs.FileInfo, cacheKey imagerequest.VariantKey,
) error {
info, err := entry.Info()
if err != nil {
return fmt.Errorf("failed to stat variant file: %w", err)
}
var recordedSize int64
err = c.db.QueryRowContext(ctx,
err := c.db.QueryRowContext(ctx,
`SELECT size_bytes FROM variant_content WHERE cache_key = ?`, string(cacheKey),
).Scan(&recordedSize)
@@ -613,7 +630,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 +660,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 {
@@ -705,8 +731,8 @@ func queryStringColumn[T ~string](
// and sweeping stale temp files.
func (c *Cache) reconcileSourceFiles(ctx context.Context) error {
return c.reconcileFiles(ctx, c.srcContent.baseDir,
func(path string, entry fs.DirEntry, name string) error {
return c.reconcileSourceFile(ctx, path, entry, imagerequest.SourceKey(name))
func(path string, info fs.FileInfo, name string) error {
return c.reconcileSourceFile(ctx, path, info, imagerequest.SourceKey(name))
})
}
@@ -717,16 +743,11 @@ func (c *Cache) reconcileSourceFiles(ctx context.Context) error {
// is removed with its row and a warning naming it, so the source is
// fetched again.
func (c *Cache) reconcileSourceFile(
ctx context.Context, path string, entry fs.DirEntry, key imagerequest.SourceKey,
ctx context.Context, path string, info fs.FileInfo, key imagerequest.SourceKey,
) error {
info, err := entry.Info()
if err != nil {
return fmt.Errorf("failed to stat source content file: %w", err)
}
var recordedSize int64
err = c.db.QueryRowContext(ctx,
err := c.db.QueryRowContext(ctx,
`SELECT size_bytes FROM source_content WHERE source_key = ?`,
string(key),
).Scan(&recordedSize)
@@ -891,17 +912,12 @@ func (c *Cache) correctUsageTotal(
// sweepStaleTempFile removes a temp file left behind by a crashed
// write once it is old enough that no in-flight store can own it.
func (c *Cache) sweepStaleTempFile(path string, entry fs.DirEntry) {
info, err := entry.Info()
if err != nil {
return
}
func (c *Cache) sweepStaleTempFile(path string, info fs.FileInfo) {
if time.Since(info.ModTime()) < staleTempFileAge {
return
}
err = os.Remove(path)
err := os.Remove(path)
if err != nil && !os.IsNotExist(err) {
c.log.Warn("failed to remove stale temp file", "path", path, "error", err)
+287
View File
@@ -9,8 +9,10 @@ import (
"log/slog"
"os"
"path/filepath"
"slices"
"strings"
"sync"
"syscall"
"testing"
"time"
@@ -699,6 +701,291 @@ 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)
}
}
// openDirectoryNearPathLimit makes a chain of directories inside dir, each
// named with 255 zeros, the longest name Linux allows. Linux refuses a path
// of 4096 bytes or more, and the chain goes as deep as it can below that.
// It returns the chain's deepest directory as an os.Root, closed when the
// test ends. An entry made through it with a 255-byte name has a path even
// the root user cannot read. The os.Root can make that entry because it
// names the entry only by its name, not by the whole path.
func openDirectoryNearPathLimit(t *testing.T, dir string) *os.Root {
t.Helper()
name := strings.Repeat("0", 255)
deepest := dir
for len(filepath.Join(deepest, name)) < 4096 {
deepest = filepath.Join(deepest, name)
}
err := os.MkdirAll(deepest, StorageDirPerm)
if err != nil {
t.Fatalf("failed to make a chain of directories: %v", err)
}
root, err := os.OpenRoot(deepest)
if err != nil {
t.Fatalf("os.OpenRoot(%s) error = %v", deepest, err)
}
t.Cleanup(func() { _ = root.Close() })
return root
}
// makeEntriesTooLongToRead makes a new directory and a new file in the
// deepest directory of the chain that openDirectoryNearPathLimit makes
// inside dir. Even the root user can then neither list the new directory
// nor read the new file's info. It returns the paths of the new directory
// and the new file.
func makeEntriesTooLongToRead(t *testing.T, dir string) []string {
t.Helper()
deepest := openDirectoryNearPathLimit(t, dir)
dirName := strings.Repeat("0", 255)
err := deepest.Mkdir(dirName, StorageDirPerm)
if err != nil {
t.Fatalf("failed to make a directory too deep to list: %v", err)
}
fileName := strings.Repeat("1", 255)
err = deepest.WriteFile(fileName, []byte("unreadable"), StorageFilePerm)
if err != nil {
t.Fatalf("failed to make a file too deep to read: %v", err)
}
return []string{
filepath.Join(deepest.Name(), dirName),
filepath.Join(deepest.Name(), fileName),
}
}
// makeTempFileTooLongToRead makes a temp file in the deepest directory of
// the chain that openDirectoryNearPathLimit makes inside dir. Even the
// root user then cannot read the temp file's info. It returns the temp
// file's path.
func makeTempFileTooLongToRead(t *testing.T, dir string) string {
t.Helper()
deepest := openDirectoryNearPathLimit(t, dir)
name := tempFilePrefix + strings.Repeat("1", 255-len(tempFilePrefix))
err := deepest.WriteFile(name, []byte("partial"), StorageFilePerm)
if err != nil {
t.Fatalf("failed to make a temp file too deep to read: %v", err)
}
return filepath.Join(deepest.Name(), name)
}
// assertSkippedEntryWarning checks that logs hold the warning "skipped
// unreadable entry in cache directory" naming path, with the error
// ENAMETOOLONG for that path.
func assertSkippedEntryWarning(t *testing.T, logs, path string) {
t.Helper()
for line := range strings.Lines(logs) {
if strings.Contains(line, `"level":"WARN"`) &&
strings.Contains(line, `"msg":"skipped unreadable entry in cache directory"`) &&
strings.Contains(line, `"path":"`+path+`"`) &&
strings.Contains(line, path+": "+syscall.ENAMETOOLONG.Error()) {
return
}
}
t.Errorf("no warning %q names %s with the error %q",
"skipped unreadable entry in cache directory", path, syscall.ENAMETOOLONG)
}
// TestReconciliationGoesOnPastEntriesItCannotRead puts, in each storage
// directory, a directory the pass cannot list and a file whose info it
// cannot read. The pass walks each directory in name order, so it reaches
// them before the cache's files, whose keys start with a letter. It must
// log a warning naming each one's path and the error, and still do the
// rest of its work:
// - adopt a variant file that has no row
// - drop the row of a variant whose file is missing
// - remove a source file that has no row
// - correct a wrong total cache usage
func TestReconciliationGoesOnPastEntriesItCannotRead(t *testing.T) {
t.Parallel()
cache, _ := newEvictionTestCache(t, 1<<30)
ctx := t.Context()
untrackedVariant := []byte("variant with no row")
err := cache.variants.Write(string(testVariantKeyOne), untrackedVariant)
if err != nil {
t.Fatalf("failed to write a variant file with no row: %v", err)
}
storeEvictionTestVariant(t, cache, testVariantKeyTwo, []byte("variant two"))
err = os.Remove(cache.variants.keyToPath(string(testVariantKeyTwo)))
if err != nil {
t.Fatalf("failed to remove the second variant's file: %v", err)
}
untrackedSourceKey := "ffeeddcc0001"
err = cache.srcContent.Write(untrackedSourceKey, []byte("source with no row"))
if err != nil {
t.Fatalf("failed to write a source file with no row: %v", err)
}
_, err = cache.db.ExecContext(ctx,
`UPDATE cache_usage SET total_size_bytes = 1 WHERE id = 1`)
if err != nil {
t.Fatalf("failed to set a wrong total: %v", err)
}
unreadable := slices.Concat(
makeEntriesTooLongToRead(t, cache.variants.baseDir),
makeEntriesTooLongToRead(t, cache.srcContent.baseDir),
)
logs := reconcileAsAtStartup(t, cache)
for _, path := range unreadable {
assertSkippedEntryWarning(t, logs, path)
}
rowQuery := `SELECT COUNT(*) FROM variant_content WHERE cache_key = ?`
if n := countRows(t, cache, rowQuery, string(testVariantKeyOne)); n != 1 {
t.Errorf("the variant file with no row got %d rows, want 1", n)
}
if n := countRows(t, cache, rowQuery, string(testVariantKeyTwo)); n != 0 {
t.Errorf("the variant with no file kept %d rows, want 0", n)
}
_, err = os.Stat(cache.srcContent.keyToPath(untrackedSourceKey))
if err == nil {
t.Error("the source file with no row is still on disk")
}
usage, err := cache.UsageBytes(ctx)
if err != nil {
t.Fatalf("UsageBytes() error = %v", err)
}
if usage != int64(len(untrackedVariant)) {
t.Errorf("UsageBytes() = %d, want %d, the size of the adopted variant",
usage, len(untrackedVariant))
}
}
// TestReconciliationWarnsOfTempFilesWhoseInfoItCannotRead puts, in each
// storage directory, a temp file whose info the pass cannot read. The
// pass must log a warning naming each one's path and the error, as it
// does for any other file whose info it cannot read.
func TestReconciliationWarnsOfTempFilesWhoseInfoItCannotRead(t *testing.T) {
t.Parallel()
cache, _ := newEvictionTestCache(t, 1<<30)
unreadable := []string{
makeTempFileTooLongToRead(t, cache.variants.baseDir),
makeTempFileTooLongToRead(t, cache.srcContent.baseDir),
}
logs := reconcileAsAtStartup(t, cache)
for _, path := range unreadable {
assertSkippedEntryWarning(t, logs, path)
}
}
// 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