Skip to content

fix(preflight): stamp the docker --since window as UTC, not as a bare timestamp - #171

Merged
glennneuber merged 1 commit into
mainfrom
fix/docker-logs-since-timezone
Aug 17, 2026
Merged

glennneuber merged 1 commit into
mainfrom
fix/docker-logs-since-timezone

Conversation

@glennneuber

Copy link
Copy Markdown

The bug

probes.py:container_logs formats since_epoch with time.gmtime — UTC — but emits it with no timezone. Docker assumes the client's local timezone for a timestamp carrying no zone, so off UTC the window silently becomes the wrong window.

Measured on this +1000 host against a live container, asking for 60 seconds:

since='2026-08-17T06:05:31'   -> 51 load_hparams lines
since='2026-08-17T06:05:31Z'  ->  0 load_hparams lines

The two failure modes are not symmetric

  • West of UTC the window opens late and admits nothing → reads as "no data", at worst a false SKIP.
  • East of UTC it opens early — ten hours early here — and admits load_hparams lines from previous loads of other models. A caller that should have seen nothing and reported no data instead receives a complete, plausible, wrong answer.

The second is the dangerous one, and the function's own docstring asserted the opposite guarantee:

--since is load-bearing: it is what guarantees the load_hparams line we read was emitted by THIS build during THIS run, not left over from a previous one.

On any non-UTC host it guaranteed no such thing. check_payload_proof reads the same lines through this helper and has carried the same exposure since it was written.

Why it matters more now

Not hypothetical — this window surfaced qwen35moe metadata into a dense qwen35 reading during a benchmark session on this host, caught only by cross-checking ollama show (head_count 24/embedding 5120 vs 16/2048).

It also raises the stakes for #168, which generates an expectation row from these logs. There, an early window turns a safe TODO into a wrong pixel budget committed to expectations.toml as a measured value — the exact error class that PR exists to eliminate. #168's last-wins aggregation makes its happy path accidentally correct, so this would not have shown up in its testing.

The fix

-    since = time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(since_epoch))
+    since = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(since_epoch))

One line, in the shared helper, so every consumer benefits. The docstring now explains that the Z is part of the guarantee rather than formatting, and carries the measured numbers above so nobody "tidies" it away.

Tests

Three cases in TestContainerLogsWindow, asserting the emitted stamp through the log_cmd seam and through the plain docker logs argv, so the two paths cannot drift apart:

test asserts
test_since_carries_an_explicit_zone the stamp ends with Z
test_since_is_utc_not_local the Z is truthful, not decoration
test_default_docker_argv_carries_the_same_stamp the non-log_cmd path agrees
against the previous format:  Ran 3 tests — FAILED (failures=3)
with the fix:                 Ran 3 tests — OK
full preflight suite:         Ran 37 tests — OK

Independent of #168 — touches no file that PR touches, so the two merge in either order.

🤖 Generated with Claude Code

… timestamp

container_logs formats `since_epoch` with time.gmtime — UTC — but emitted it
with no timezone. Docker assumes the CLIENT'S LOCAL TIMEZONE for a timestamp
carrying no zone, so off UTC the window silently becomes the wrong window.
Measured on a +1000 host against a live container, asking for 60 seconds:

    since='2026-08-17T06:05:31'   -> 51 load_hparams lines
    since='2026-08-17T06:05:31Z'  ->  0 load_hparams lines

Both failure modes are silent, and they are not symmetric. West of UTC the
window opens LATE and admits nothing, which reads as "no data" and is at worst
a false SKIP. East of UTC it opens EARLY — ten hours early here — and admits
load_hparams lines from previous loads of OTHER MODELS. A caller that should
have seen nothing and reported no data instead receives a complete, plausible,
wrong answer.

That is the dangerous direction, because the function's own docstring asserts
the opposite guarantee:

    `--since` is load-bearing: it is what guarantees the load_hparams line we
    read was emitted by THIS build during THIS run, not left over from a
    previous one.

On any non-UTC host it guaranteed no such thing. check_payload_proof reads the
same lines through this helper and has carried the same exposure.

Not hypothetical: this window surfaced qwen35moe metadata into a dense qwen35
reading in a benchmark session on this host, caught only by cross-checking
`ollama show` (head_count 24/embedding 5120 vs 16/2048). It also raises the
stakes for anything that GENERATES an expectation row from these logs, where a
wrong pixel budget is committed to expectations.toml as a measured value rather
than surfaced as a TODO.

Three regression tests assert the emitted stamp through the log_cmd seam and
through the plain `docker logs` argv, so the two paths cannot drift. All three
fail against the previous format and pass with it; 37 green.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant