TestServerInfo compared two independent clock reads: msg.UptimeSeconds, which the ServerInfo RPC handler computes at handler entry, against time.Since(serverStartTime), which the test reads after the RPC returns. Because the handler runs an external host probe (shelling out to getent plus host stats) before returning, arbitrary probe latency can carry the second read across a whole-second boundary. The handler then legitimately returns 0 while the guard sees >= 1s, producing:
Solution written to ~/solution.md and verified against a faithful repro. Here is the complete document:
TestServerInfo uptime assertion (internal/server)TestServerInfo compared two independent clock reads: msg.UptimeSeconds, which the ServerInfo RPC handler computes at handler entry, against time.Since(serverStartTime), which the test reads after the RPC returns. Because the handler runs an external host probe (shelling out to getent plus host stats) before returning, arbitrary probe latency can carry the second read across a whole-second boundary. The handler then legitimately returns 0 while the guard sees >= 1s, producing:
--- FAIL: TestServerInfo (0.00s)
service_test.go:702: ServerInfo().UptimeSeconds is 0, want seconds since daemon start
FAIL github.com/deployBunker/bunker/internal/server 1.019s
The guard cannot explain its own failure because it is not measuring the same instant the value was derived from. This is a cross-clock, cross-IPC-boundary assertion, not a logic bug in the handler and not a sibling test mutating the global.
Three properties combine to make the test schedule-dependent:
The value is sampled early, the guard samples late. UptimeSeconds is computed at handler entry; the probe runs after; the test's time.Since(serverStartTime) runs after the RPC response, i.e. after the probe. There is no guarantee both reads land in the same one-second bucket.
The handler contains unbounded, host-dependent latency. getent + host stats are external processes. Under CI load their latency is arbitrary; a scheduling stall or slow resolver pushes the guard >= 1s while the entry sample is still in the 0 bucket.
serverStartTime is package-global and set at process init. The test's position in the test binary's lifetime therefore sets the margin to the boundary. When TestServerInfo runs ~1.4s after process init it is only ~0.45s clear of the 1s edge, so even a modest preamble is enough to cross it.
Within a test binary the elapsed time at handler entry and at the assertion can differ by the full probe duration. The test asserts entry_elapsed >= 1 using assert_elapsed, but the only true implication is assert_elapsed >= entry_elapsed. If entry_elapsed == 0 then assert_elapsed can be anything >= 0, including >= 1.
serverStartTime 3661s in the past, so uptime derived from it can never be 0.t.Parallel, so siblings are serial and cannot overwrite the global during TestServerInfo.-run 'TestServerInfo$' alone, with no sibling running.Inject a deterministic start time inside the test so the expected value is known before the RPC, and assert a band around it.
func TestServerInfo(t *testing.T) {
// Inject the start time so the expected uptime does not depend on the age of
// the test binary or on host-probe latency. Restore it for sibling tests.
oldStart := serverStartTime
serverStartTime = time.Now().Add(-2 * time.Second)
t.Cleanup(func() { serverStartTime = oldStart })
msg, err := client.ServerInfo(ctx, &pb.ServerInfoRequest{})
if err != nil {
t.Fatalf("ServerInfo() error = %v", err)
}
// Assert a band around the injected 2s. Independent of test-binary age and
// probe latency; still red for a hardcoded 0 or a value that ignores
// serverStartTime.
if msg.UptimeSeconds < 1 || msg.UptimeSeconds > 3 {
t.Errorf("ServerInfo().UptimeSeconds is %d, want 1..3 seconds since injected daemon start",
msg.UptimeSeconds)
}
}
Replace the old flaky guard (the if time.Since(serverStartTime) >= time.Second { ... } block) with the code above. Also delete/correct any comment above the old guard that claims a razor-edge timing theory — that comment instructs the next agent to copy the flaky pattern.
now - 2s makes the expected uptime deterministic regardless of binary age.t.Cleanup restores the global. Siblings see it unchanged, pass or fail.1..3 spread but still rejects 0. Do not widen to 0..3 — that is a phantom pass.// WRONG: two clock reads, one on each side of an untimed external call.
if time.Since(serverStartTime) >= time.Second {
if msg.UptimeSeconds < 1 { ... }
}
// WRONG: tolerance widened until a hardcoded 0 passes.
if msg.UptimeSeconds < 0 || msg.UptimeSeconds > 3 { ... }
gofmt -l ./internal/server
go build ./...
go vet ./...
go test ./... -count=1
go test ./internal/server/ -count=20 -race
All must be clean.
Inject controlled host-probe latency with a stub getent that sleeps:
mkdir -p /tmp/stub
cat > /tmp/stub/getent <<'EOF'
#!/bin/sh
sleep 2
echo "<ip-address> localhost"
EOF
chmod +x /tmp/stub/getent
PATH=/tmp/stub:$PATH go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
With the old guard this fails every run with the CI message (entry at a few ms → 0; guard at >2s → >= 1s):
service_test.go:702: ServerInfo().UptimeSeconds is 0, want seconds since daemon start
--- FAIL: TestServerInfo (4.01s)
PATH=/tmp/stub:$PATH go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
# --- PASS: TestServerInfo
go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
# --- PASS: TestServerInfo
Hardcode the handler response to 0 (keep the variable used so it compiles):
_ = uptime // force-hardcoded value
return &ServerInfoMsg{UptimeSeconds: 0}
go test ./internal/server/ -run 'TestServerInfo$' -count=1
# FAIL: ServerInfo().UptimeSeconds is 0, want 1..3 seconds since injected daemon start
Also mutate the handler to ignore the start time (uptime := int64(999)); the fixed test must fail:
service_test.go:23: ServerInfo().UptimeSeconds is 999, want 1..3 seconds since injected daemon start
Revert both mutations and confirm green again. This proves the test rejects a hardcoded value and a value that does not depend on serverStartTime.
0), there was no t.Parallel, and the failure reproduced with -run 'TestServerInfo$' alone.0 — phantom pass.t.Cleanup restore, or later tests inherit a start two seconds in the past.Compare a sampled value to a clock read taken at the same sampling instant; inject the start time inside the test and assert a band — never compare a handler-computed value against a clock read after the RPC returned.
I built a faithful repro at ~/repro (internal/server handler + a sleep 2 getent stub on PATH) and ran the full sequence. Results:
ServerInfo().UptimeSeconds is 0, want seconds since daemon start.0 mutation → FAIL ...is 0, want 1..3...; ignores-start 999 mutation → FAIL ...is 999, want 1..3...; revert → PASS.# Evidence - Problem class: go-unit-test-asserts-clock-read-after-rpc-returns - Model: openrouter/deepseek/deepseek-v4.1-flash - Solved: 2026-09-17T19:07:15.312Z - Verification: solution produced by pi in sandbox; see signatures.json
{"description": "SYMPTOM: a Go unit test guarding a derived value flakes red in CI while passing locally and while passing on a sibling run of the same tree minutes later. The assertion compared TWO DIFFERENT CLOCK READS: the value under test (msg.UptimeSeconds) is computed INSIDE the RPC handler at entry, while the guard (time.Since(serverStartTime) >= time.Second) is evaluated AFTER the RPC returned -- and the handler body calls an external host probe (shelling out to getent plus host stats) whose latency is arbitrary and host-dependent. Any schedule that carries the second read across a whole second turns a legitimate 0 into a red, so the guard 'cannot explain' its own failure (the exact sentence the filing foreman wrote). DIAGNOSIS PATH THAT WORKED: (1) instrument both values plus the elapsed time at the assertion site; (2) reproduce by injecting controlled latency instead of hunting the flake -- a stub 'getent' earlier on PATH that sleeps 2s makes it fail 100% of runs: uptime computed at 2ms (=0), guard read at 2.007s (>=1s) -> the CI message verbatim; (3) measure where the test sits in package time: when it runs ~1.4s after process init it is only ~0.45s clear of the 1s boundary, so a ~1s preamble (here: two sibling tests doing real network work) is enough to cross it. FIX SHAPE: never assert a value the handler computed against a clock you read later. Inject the start time inside the test (serverStartTime = time.Now().Add(-2*time.Second) + t.Cleanup restore) and assert a band (1..3), which is independent of test-binary age and still red for a hardcoded 0 or a value that ignores the start time. VERIFY THE FIX BITES: hardcode the field to 0 and confirm the test fails, then revert. TRAPS: (a) a sibling test that mutates the same package global is NOT automatically the cause -- here the sibling injected a start 3661s in the PAST (its value can never be 0), the package had no t.Parallel, and the failure reproduced with -run '<TestName>$' alone, so the sibling hypothesis was disproved by three separate checks; (b) do not 'widen the tolerance' to a range that also accepts a hardcoded 0 -- that is a phantom pass; (c) the old comment above the flaky guard may assert a razor-edge theory that the mechanism contradicts -- correct the doc in the same commit, because it instructs the next agent to copy the flaky pattern.", "environment": "Go repo (bunker): CI ubuntu-latest, package internal/server; RPC handler body runs an external host probe (getent + host stats) before returning", "language": "go", "model": "openrouter/deepseek/deepseek-v4.1-flash", "problem_class": "go-unit-test-asserts-clock-read-after-rpc-returns", "provider": "openrouter", "solved_at": "2026-09-17T19:07:15.312Z", "version": "go1.26.5"}Solution written to ~/solution.md and verified against a faithful repro. Here is the complete document:
TestServerInfo uptime assertion (internal/server)TestServerInfo compared two independent clock reads: msg.UptimeSeconds, which the ServerInfo RPC handler computes at handler entry, against time.Since(serverStartTime), which the test reads after the RPC returns. Because the handler runs an external host probe (shelling out to getent plus host stats) before returning, arbitrary probe latency can carry the second read across a whole-second boundary. The handler then legitimately returns 0 while the guard sees >= 1s, producing:
--- FAIL: TestServerInfo (0.00s)
service_test.go:702: ServerInfo().UptimeSeconds is 0, want seconds since daemon start
FAIL github.com/deployBunker/bunker/internal/server 1.019s
The guard cannot explain its own failure because it is not measuring the same instant the value was derived from. This is a cross-clock, cross-IPC-boundary assertion, not a logic bug in the handler and not a sibling test mutating the global.
Three properties combine to make the test schedule-dependent:
The value is sampled early, the guard samples late. UptimeSeconds is computed at handler entry; the probe runs after; the test's time.Since(serverStartTime) runs after the RPC response, i.e. after the probe. There is no guarantee both reads land in the same one-second bucket.
The handler contains unbounded, host-dependent latency. getent + host stats are external processes. Under CI load their latency is arbitrary; a scheduling stall or slow resolver pushes the guard >= 1s while the entry sample is still in the 0 bucket.
serverStartTime is package-global and set at process init. The test's position in the test binary's lifetime therefore sets the margin to the boundary. When TestServerInfo runs ~1.4s after process init it is only ~0.45s clear of the 1s edge, so even a modest preamble is enough to cross it.
Within a test binary the elapsed time at handler entry and at the assertion can differ by the full probe duration. The test asserts entry_elapsed >= 1 using assert_elapsed, but the only true implication is assert_elapsed >= entry_elapsed. If entry_elapsed == 0 then assert_elapsed can be anything >= 0, including >= 1.
serverStartTime 3661s in the past, so uptime derived from it can never be 0.t.Parallel, so siblings are serial and cannot overwrite the global during TestServerInfo.-run 'TestServerInfo$' alone, with no sibling running.Inject a deterministic start time inside the test so the expected value is known before the RPC, and assert a band around it.
func TestServerInfo(t *testing.T) {
// Inject the start time so the expected uptime does not depend on the age of
// the test binary or on host-probe latency. Restore it for sibling tests.
oldStart := serverStartTime
serverStartTime = time.Now().Add(-2 * time.Second)
t.Cleanup(func() { serverStartTime = oldStart })
msg, err := client.ServerInfo(ctx, &pb.ServerInfoRequest{})
if err != nil {
t.Fatalf("ServerInfo() error = %v", err)
}
// Assert a band around the injected 2s. Independent of test-binary age and
// probe latency; still red for a hardcoded 0 or a value that ignores
// serverStartTime.
if msg.UptimeSeconds < 1 || msg.UptimeSeconds > 3 {
t.Errorf("ServerInfo().UptimeSeconds is %d, want 1..3 seconds since injected daemon start",
msg.UptimeSeconds)
}
}
Replace the old flaky guard (the if time.Since(serverStartTime) >= time.Second { ... } block) with the code above. Also delete/correct any comment above the old guard that claims a razor-edge timing theory — that comment instructs the next agent to copy the flaky pattern.
now - 2s makes the expected uptime deterministic regardless of binary age.t.Cleanup restores the global. Siblings see it unchanged, pass or fail.1..3 spread but still rejects 0. Do not widen to 0..3 — that is a phantom pass.// WRONG: two clock reads, one on each side of an untimed external call.
if time.Since(serverStartTime) >= time.Second {
if msg.UptimeSeconds < 1 { ... }
}
// WRONG: tolerance widened until a hardcoded 0 passes.
if msg.UptimeSeconds < 0 || msg.UptimeSeconds > 3 { ... }
gofmt -l ./internal/server
go build ./...
go vet ./...
go test ./... -count=1
go test ./internal/server/ -count=20 -race
All must be clean.
Inject controlled host-probe latency with a stub getent that sleeps:
mkdir -p /tmp/stub
cat > /tmp/stub/getent <<'EOF'
#!/bin/sh
sleep 2
echo "<ip-address> localhost"
EOF
chmod +x /tmp/stub/getent
PATH=/tmp/stub:$PATH go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
With the old guard this fails every run with the CI message (entry at a few ms → 0; guard at >2s → >= 1s):
service_test.go:702: ServerInfo().UptimeSeconds is 0, want seconds since daemon start
--- FAIL: TestServerInfo (4.01s)
PATH=/tmp/stub:$PATH go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
# --- PASS: TestServerInfo
go test ./internal/server/ -run 'TestServerInfo$' -count=1 -v
# --- PASS: TestServerInfo
Hardcode the handler response to 0 (keep the variable used so it compiles):
_ = uptime // force-hardcoded value
return &ServerInfoMsg{UptimeSeconds: 0}
go test ./internal/server/ -run 'TestServerInfo$' -count=1
# FAIL: ServerInfo().UptimeSeconds is 0, want 1..3 seconds since injected daemon start
Also mutate the handler to ignore the start time (uptime := int64(999)); the fixed test must fail:
service_test.go:23: ServerInfo().UptimeSeconds is 999, want 1..3 seconds since injected daemon start
Revert both mutations and confirm green again. This proves the test rejects a hardcoded value and a value that does not depend on serverStartTime.
0), there was no t.Parallel, and the failure reproduced with -run 'TestServerInfo$' alone.0 — phantom pass.t.Cleanup restore, or later tests inherit a start two seconds in the past.Compare a sampled value to a clock read taken at the same sampling instant; inject the start time inside the test and assert a band — never compare a handler-computed value against a clock read after the RPC returned.
I built a faithful repro at ~/repro (internal/server handler + a sleep 2 getent stub on PATH) and ran the full sequence. Results:
ServerInfo().UptimeSeconds is 0, want seconds since daemon start.0 mutation → FAIL ...is 0, want 1..3...; ignores-start 999 mutation → FAIL ...is 999, want 1..3...; revert → PASS.# Evidence - Problem class: go-unit-test-asserts-clock-read-after-rpc-returns - Model: openrouter/deepseek/deepseek-v4.1-flash - Solved: 2026-09-17T19:07:15.312Z - Verification: solution produced by pi in sandbox; see signatures.json
{"description": "SYMPTOM: a Go unit test guarding a derived value flakes red in CI while passing locally and while passing on a sibling run of the same tree minutes later. The assertion compared TWO DIFFERENT CLOCK READS: the value under test (msg.UptimeSeconds) is computed INSIDE the RPC handler at entry, while the guard (time.Since(serverStartTime) >= time.Second) is evaluated AFTER the RPC returned -- and the handler body calls an external host probe (shelling out to getent plus host stats) whose latency is arbitrary and host-dependent. Any schedule that carries the second read across a whole second turns a legitimate 0 into a red, so the guard 'cannot explain' its own failure (the exact sentence the filing foreman wrote). DIAGNOSIS PATH THAT WORKED: (1) instrument both values plus the elapsed time at the assertion site; (2) reproduce by injecting controlled latency instead of hunting the flake -- a stub 'getent' earlier on PATH that sleeps 2s makes it fail 100% of runs: uptime computed at 2ms (=0), guard read at 2.007s (>=1s) -> the CI message verbatim; (3) measure where the test sits in package time: when it runs ~1.4s after process init it is only ~0.45s clear of the 1s boundary, so a ~1s preamble (here: two sibling tests doing real network work) is enough to cross it. FIX SHAPE: never assert a value the handler computed against a clock you read later. Inject the start time inside the test (serverStartTime = time.Now().Add(-2*time.Second) + t.Cleanup restore) and assert a band (1..3), which is independent of test-binary age and still red for a hardcoded 0 or a value that ignores the start time. VERIFY THE FIX BITES: hardcode the field to 0 and confirm the test fails, then revert. TRAPS: (a) a sibling test that mutates the same package global is NOT automatically the cause -- here the sibling injected a start 3661s in the PAST (its value can never be 0), the package had no t.Parallel, and the failure reproduced with -run '<TestName>$' alone, so the sibling hypothesis was disproved by three separate checks; (b) do not 'widen the tolerance' to a range that also accepts a hardcoded 0 -- that is a phantom pass; (c) the old comment above the flaky guard may assert a razor-edge theory that the mechanism contradicts -- correct the doc in the same commit, because it instructs the next agent to copy the flaky pattern.", "environment": "Go repo (bunker): CI ubuntu-latest, package internal/server; RPC handler body runs an external host probe (getent + host stats) before returning", "language": "go", "model": "openrouter/deepseek/deepseek-v4.1-flash", "problem_class": "go-unit-test-asserts-clock-read-after-rpc-returns", "provider": "openrouter", "solved_at": "2026-09-17T19:07:15.312Z", "version": "go1.26.5"}