Skip to content

fix(feedback): seal the event time in the ledger, not the write time - #45

Merged
sturlese merged 2 commits into
mainfrom
fix/bughunt-feedback-ledger-timestamp
Sep 4, 2026
Merged

fix(feedback): seal the event time in the ledger, not the write time#45
sturlese merged 2 commits into
mainfrom
fix/bughunt-feedback-ledger-timestamp

Conversation

@sturlese

@sturlese sturlese commented Sep 3, 2026

Copy link
Copy Markdown
Owner

Found by an autonomous bughunt iteration.

Bug

record_feedback takes an at timestamp, writes it to the store row, and then appends the ledger entry without it. The store and the audit ledger end up describing the same event at different times.

when = datetime(2026, 1, 15, 9, 0, tzinfo=UTC)
entry = record_feedback(store, ledger, run.id, "accepted", human_minutes=3, by="ana", at=when)

entry.at                       # 2026-01-15T09:00:00+00:00   (store row)
ledger.entries()[-1]["at"]     # 2026-09-03T23:04:32.780517+00:00   (wall clock)

For a project whose thesis is "an auditable ROI trail", that is the wrong number in the wrong file: the ledger is the artifact a DPO or auditor actually reads, and it contradicts the evidence it is supposed to seal. A backfilled quarter of reviews all land stamped with the day of the import.

The default path was inconsistent too, just less visibly — the row got datetime.now().astimezone() and the chain got a second, later datetime.now(UTC) reading.

Why this is a defect and not the intended design

Three independent signals in the repo say at means event time, not write time:

  1. runner.record already keeps the contractrunner.py:101 is ledger.append(event, data, at=run.finished_at).
  2. ledger.py's module docstring blesses it explicitly"Timestamps may be supplied explicitly (imports, backfills, the demo seeder) — the SEQUENCE proves append order either way." Append order is carried by seq, so the stamp is free to be the event time.
  3. demo.py:358 hand-duplicates the entire feedback_recorded event body purely so it can pass at=when — routing around the module whose own docstring calls itself "the one place feedback becomes evidence — shared by every entry point" and promises "a Slack click lands the identical store row and ledger event as the CLI, because they call the very same code."

Signal 3 is the smoking gun: the seeder had to bypass the shared path precisely because that path could not carry a timestamp.

Fix

One argument — at=entry.at — plus a comment recording why. The chain is unaffected: seq still proves append order, and flightdeck audit verify walks clean.

Test

tests/test_feedback.py:

test asserts
test_backdated_feedback_seals_the_event_time_in_the_ledger a review backdated 200 days seals that time; store row and ledger entry agree
test_feedback_without_an_explicit_time_still_seals_what_the_row_says the default path uses one clock reading, not two, and the chain still verifies

Both verified to fail without the fix (git stash on the source alone) — the second by months, the first by microseconds.

Validation

All three CI jobs green locally:

  • python -m pytest --cov=flightdeck --cov-fail-under=85260 passed, coverage 94.48%
  • ruff check src testsAll checks passed!
  • flightdeck demo + flightdeck audit verify → ledger verified, 2,434 entries, chain intact

Follow-up (deliberately not in this diff)

With the timestamp forwarded, demo.py:358's hand-rolled copy of the event body can collapse into a record_feedback call. That is a refactor with its own risk surface (the seeder would start going through the outcome and unknown-run guards), so it belongs in its own PR rather than riding along with a one-line correctness fix.

🤖 Generated with Claude Code

https://claude.ai/code/session_01XjLWb6igee2tVTG7wg93Fx

sturlese and others added 2 commits September 4, 2026 01:05
record_feedback accepts an `at`, writes it to the store row, and then appended the
ledger entry without it -- so the tamper-evident record an auditor reads disagreed
with the store about when the review happened. A feedback backdated to January was
sealed under September's wall clock. Even the default path took two separate clock
readings, one for the row and one for the chain.

Pass `at=entry.at`, the contract runner.record already keeps with
at=run.finished_at, and that ledger.py's docstring blesses explicitly: timestamps
may be supplied, because append order is proven by the entry's seq rather than by
its stamp. Nothing about the chain changes.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XjLWb6igee2tVTG7wg93Fx
Gate review: forwarding entry.at was right, but it imported the row's local
offset into a ledger every other writer keeps in UTC -- runner.record via
datetime.now(UTC), the demo seeder via explicit tzinfo=UTC. Because `audit tail`
renders entry["at"][:16], slicing the offset off before the reader sees it, a
review recorded from a UTC-7 machine displayed seven hours BEFORE the run it
reviews, with nothing on screen to explain it. That regressed the two live entry
points, the CLI and the Slack button, to fix a path nothing in the product calls
yet.

Normalize at the append site, so the invariant holds for an explicit caller too:
the alternative of defaulting the row to UTC only covers the path where no `at`
is passed, and lets an explicitly local one back into the file.

The tests were blind to this -- one asserted the sealed stamp equalled
entry.at.isoformat(), a tautology once the value is forwarded verbatim, whatever
offset it carries. They now compare instants and pin the convention: every ledger
stamp ends in +00:00 even when the caller hands in a Tokyo offset, and feedback
never predates its run. Suite green under TZ=UTC, America/Los_Angeles and
Europe/Madrid.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XjLWb6igee2tVTG7wg93Fx
@sturlese

sturlese commented Sep 3, 2026

Copy link
Copy Markdown
Owner Author

Gate verdict — PASS after one amendment round

Two adversarial reviews, each told to refute the fix. They converged independently on the same defect, which is worth recording because it was worse than the bug being fixed.

The finding

Feedback.at defaults to datetime.now().astimezone() — a local offset. Every other writer into this ledger is UTC: runner.record via datetime.now(UTC), the demo seeder via explicit tzinfo=UTC, and ledger.append's own default. Forwarding entry.at verbatim therefore made feedback_recorded the only non-UTC entry type in a previously homogeneous file.

That is not cosmetic, because cli.py:556 renders entry["at"][:16] — it slices the stamp before the offset. Reproduced end-to-end:

$ TZ=America/Los_Angeles flightdeck audit tail -n 4
 0 2026-09-03 23:09  run_completed      run_id 2fcd44198a5c
 1 2026-09-03 16:09  feedback_recorded  run_id 2fcd44198a5c   <- 7h BEFORE the run it reviews

Written 0.1s apart. On main, both read 23:09. So the first commit regressed the two live entry points — flightdeck feedback and the Slack button, neither of which passes at — in order to fix a backdating path nothing in the product calls yet. On the auditor-facing surface of the artifact this project sells as evidence.

The remedy, and why not the other one

One review proposed fixing the row's default instead (at=at or datetime.now(UTC) at the construction site). I normalized at the append site (at=entry.at.astimezone(UTC)) because the row-default fix only covers the path where no at is passed: hand it an explicitly local-offset at and the mixed-convention file comes right back. Normalizing where the entry is sealed makes the invariant unconditional — every ledger stamp is UTC, whatever the caller hands in — and leaves the store row exactly as main writes it.

Verified after the change, same commands:

 0 2026-09-03 23:11  run_completed      "at":"2026-09-03T23:11:23.180888+00:00"
 1 2026-09-03 23:11  feedback_recorded  "at":"2026-09-03T23:11:23.291508+00:00"

The tests were the real failure

Both reviews flagged that the suite shipped this green. test_feedback_without_an_explicit_time_still_seals_what_the_row_says asserted sealed["at"] == entry.at.isoformat() — a tautology once the value is forwarded verbatim: true for any offset. And ledger.verify().ok proves nothing here, since the hash is over the string, so the chain verifies happily with mixed conventions.

Now they compare instants rather than strings, and a third test pins the convention: every stamp ends in +00:00 even when the caller passes a Tokyo offset, and feedback_recorded never predates its run_completed.

Verified

tests fail on main the 2 event-time tests, by months
new UTC test fails on da6e3d5 catches the regression above
suite 261 passed under TZ=UTC, America/Los_Angeles, Europe/Madrid
lint clean
demo + audit verify 2,434 entries, chain intact

Ruled out by the reviews

  • metrics.py never reads ledger at — every window filter and bucket is built from store rows, so no governance counter, report number, CSV field or dashboard value moves.
  • verify() treats at as an opaque string; an out-of-order ledger was built deliberately and still verified ok. Existing ledgers keep their bytes.
  • The demo hand-rolls its own ledger.append and is unaffected — generated both ways and diffed.

CI green. Left open for human review.

@sturlese
sturlese merged commit 3a9c207 into main Sep 4, 2026
5 checks passed
@sturlese
sturlese deleted the fix/bughunt-feedback-ledger-timestamp branch September 4, 2026 07:39
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