TestService_Get_ReturnsByItsDeadline fails when the host is busy #224

Open
opened 2026-10-08 02:45:01 +02:00 by clawbot · 2 comments
Collaborator

TestService_Get_ReturnsByItsDeadline (internal/imgcache/concurrent_misses_internal_test.go) failed on next (15d9543) in the first test run of script/cibuild, on a host busy with other builds:

--- FAIL: TestService_Get_ReturnsByItsDeadline (8.97s)
    concurrent_misses_internal_test.go:434: request did not return by its deadline

The test gives a request a 200 ms deadline and fails if the request has not returned one second later. In the same run, converting the 100x100 test photo took up to 1.25 seconds, so that second may be too short on a loaded host; it may also be a request that really does return late. Which of the two it is is not yet known. SQLite locking is not the cause: this test's database already has one connection.

Model: opus-5-5

`TestService_Get_ReturnsByItsDeadline` (`internal/imgcache/concurrent_misses_internal_test.go`) failed on `next` (`15d9543`) in the first test run of `script/cibuild`, on a host busy with other builds: ``` --- FAIL: TestService_Get_ReturnsByItsDeadline (8.97s) concurrent_misses_internal_test.go:434: request did not return by its deadline ``` The test gives a request a 200 ms deadline and fails if the request has not returned one second later. In the same run, converting the 100x100 test photo took up to 1.25 seconds, so that second may be too short on a loaded host; it may also be a request that really does return late. Which of the two it is is not yet known. SQLite locking is not the cause: this test's database already has one connection. Model: opus-5-5
Author
Collaborator

Plan

This makes next fail on a busy host, so it comes right after #223.

In this test the upstream fetch is held and never released before the deadline, so no image is converted while the request waits; the slow conversion in that run does not explain a late return by itself. Find out what the request was waiting on when its 200 ms deadline passed. Run the test under load, with a stack dump of the waiting goroutines once the deadline has passed (for example from a temporary change in the test, kept out of the PR).

Definition of done

  • The cause is named in the PR body in one or two plain sentences.
  • If the request really can return late (something it waits on does not stop at its context's deadline), the code is fixed. The test keeps what it checks: a request whose fetch is held returns context.DeadlineExceeded soon after its deadline.
  • If the request returns on time and only the test's one-second margin is too short under load, the test is not changed: CLAUDE.md needs the owner's approval to change an existing test. The case for a change goes to him on this issue. The change should mean nothing slow happens between the deadline and the check, not just a longer margin.
  • script/cibuild passes on a busy host. One way to check: run it while another Docker build of this repo runs.

Model: opus-5-5

## Plan This makes `next` fail on a busy host, so it comes right after https://git.eeqj.de/sneak/pixa/issues/223. In this test the upstream fetch is held and never released before the deadline, so no image is converted while the request waits; the slow conversion in that run does not explain a late return by itself. Find out what the request was waiting on when its 200 ms deadline passed. Run the test under load, with a stack dump of the waiting goroutines once the deadline has passed (for example from a temporary change in the test, kept out of the PR). ## Definition of done - The cause is named in the PR body in one or two plain sentences. - If the request really can return late (something it waits on does not stop at its context's deadline), the code is fixed. The test keeps what it checks: a request whose fetch is held returns `context.DeadlineExceeded` soon after its deadline. - If the request returns on time and only the test's one-second margin is too short under load, the test is not changed: `CLAUDE.md` needs the owner's approval to change an existing test. The case for a change goes to him on this issue. The change should mean nothing slow happens between the deadline and the check, not just a longer margin. - `script/cibuild` passes on a busy host. One way to check: run it while another Docker build of this repo runs. Model: opus-5-5
clawbot self-assigned this 2026-10-08 02:58:47 +02:00
Author
Collaborator

Question: CLAUDE.md needs your approval to change an existing test. May TestService_Get_ReturnsByItsDeadline be changed as recommended below (run it on its own, not in parallel)? Until then this test can still fail on a busy host.

The request does not return late. The test's one-second check is too tight when its process gets too little CPU.

What the test waits on. The held fetch returns once its context ends, and the request once the fetch does. Go ends a context at its deadline from a goroutine it starts at that moment. There are two here: one for the request's context, and one for the fetch's, which processOrWait gives the same deadline. After those have run, the request makes one database write to count the miss, about a millisecond, and returns.

Why it fails under load. In a temporary test, not committed, I ran this case 32 times at once with Go held to 2 CPUs beside 96 to 160 busy goroutines. Requests returned up to 3.8 seconds after their deadline. A goroutine dump taken 300 ms after the deadline showed every late request still waiting for its context to end, and the goroutines that end the contexts still waiting to run. Nothing the request waits on ignores its deadline. In the failing run the test took 8.97 seconds in all for at most 1.2 seconds of waiting, so its process was badly starved.

Recommended change. Remove t.Parallel() from this test, with //nolint:paralleltest and the reason. Every other test in internal/imgcache runs in parallel, so this one would run alone in its test binary before they start, and their image conversions would no longer share its process while it waits. The deadline, the margin and the error check stay as they are. Other packages' tests and other builds still share the host, and I could not make the test fail at today's load, so this is not proven against a host as busy as the failing run's.

Alternative. Check the order of events instead of the time. The held fetch records the deadline of the context it is given; the test checks that it is the request's deadline, then waits for the answer without a timer of its own and checks for context.DeadlineExceeded. Load cannot fail it, but a request that is late for some other reason after its fetch has ended would be caught only if it never returns, by the 90-second test timeout.

Model: opus-5-5

**Question:** `CLAUDE.md` needs your approval to change an existing test. May `TestService_Get_ReturnsByItsDeadline` be changed as recommended below (run it on its own, not in parallel)? Until then this test can still fail on a busy host. The request does not return late. The test's one-second check is too tight when its process gets too little CPU. **What the test waits on.** The held fetch returns once its context ends, and the request once the fetch does. Go ends a context at its deadline from a goroutine it starts at that moment. There are two here: one for the request's context, and one for the fetch's, which `processOrWait` gives the same deadline. After those have run, the request makes one database write to count the miss, about a millisecond, and returns. **Why it fails under load.** In a temporary test, not committed, I ran this case 32 times at once with Go held to 2 CPUs beside 96 to 160 busy goroutines. Requests returned up to 3.8 seconds after their deadline. A goroutine dump taken 300 ms after the deadline showed every late request still waiting for its context to end, and the goroutines that end the contexts still waiting to run. Nothing the request waits on ignores its deadline. In the failing run the test took 8.97 seconds in all for at most 1.2 seconds of waiting, so its process was badly starved. **Recommended change.** Remove `t.Parallel()` from this test, with `//nolint:paralleltest` and the reason. Every other test in `internal/imgcache` runs in parallel, so this one would run alone in its test binary before they start, and their image conversions would no longer share its process while it waits. The deadline, the margin and the error check stay as they are. Other packages' tests and other builds still share the host, and I could not make the test fail at today's load, so this is not proven against a host as busy as the failing run's. **Alternative.** Check the order of events instead of the time. The held fetch records the deadline of the context it is given; the test checks that it is the request's deadline, then waits for the answer without a timer of its own and checks for `context.DeadlineExceeded`. Load cannot fail it, but a request that is late for some other reason after its fetch has ended would be caught only if it never returns, by the 90-second test timeout. Model: opus-5-5
clawbot removed their assignment 2026-10-08 04:16:21 +02:00
sneak was assigned by clawbot 2026-10-08 04:16:21 +02:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/pixa#224