lampOS: the Policy's outcomes time the lamp's sound, its words and what was heard by their messages' own stamps, so a held-up loop no longer writes a real answer silent (#1652)

[deehw]

#1652, option 1, with the first builder's yes (#1652, 04:27): the Policy's outcomes time the lamp's sound, its words and what was heard by the stamp each message was sent with. That's the publisher's at_us on the same monotonic clock, not when the loop took the message up.

Behind no switch: it changes only what the outcomes log (and the journal's outcome line) writes, not what the Policy decides. Every time the Policy decides on (gather's pauses, lamp, the judges' context, the decision's own time) keeps the take-up times.

Why: each turn the loop takes what the lamp is doing before what is heard. A turn held up past the gap between the two took the lamp's sound first, so the sound was "before" the utterance and Watch::new dropped it, and a real answer was written silent (#1569 row 25).

What changes (lamp-policy only)

• outcome::sent_at(at_us, now, now_us) turns a stamp into a time on the loop's clock. An unstamped message (0), or one stamped ahead of the clock, keeps its take-up time, as before.
• Ear::take_sent returns each message with its header's at_us. take is now built on it, so its callers are unchanged.
• Begun and the open Watch take the lamp's state and words by their stamps.
• gather's Utterance gets sent: its first and last pieces' stamps, through piece_sent. Its own began/ended, and so when it is over, are unchanged.
• Watch::new (here and in the judges' path) uses utterance.sent.
• Watch::spoke and Watch::said now ignore a time before the utterance began, as Watch::new already did for what came before the decision.
  • Why it's needed: with take-up times nothing after the decision could be earlier than the utterance. A stamp can be: without this, a sound stamped 7 s back and arriving after the decision was counted as the answer.
• docs/policy.md: the paragraph on the times says this.

Tests

• outcome.rs units:
  • a_message_is_timed_by_its_stamp_and_an_unstamped_one_by_its_taking_up;
  • a_sound_stamped_before_the_utterance_is_no_answer_to_it, both through Begun before the decision and through Watch::spoke/said after it.
• tests/policy.rs: the rig now stamps every message with the monotonic clock, as the voice does. Two new tests:
  • A, a_piece_taken_up_after_the_lamps_sound_but_sent_before_it_is_answered_by_it: the lamp's sound is taken up first, and the piece comes 100 ms later stamped 150 ms before the sound. It must be spoke, with heard_to_sound_ms ≥ 150.
  • B, a_sound_stamped_before_what_was_heard_is_no_answer_to_it: the decision first, then a Speaking stamped 2 s before the piece. It must be silent, closed by a second utterance overtaking it.
    • Changed in 0deff8980, the reviewer's P3: before, the old sound was taken up before the decision, so Watch::new's filter dropped it and the new guard went untested.
    • Now, with the guard taken out of Watch::spoke/said, B fails 3 of 3: spoke, heard_to_sound_ms −1999.
• The 400 ms stall can't be a test: nothing a test can reach runs on the loop's thread (the stand-in's ask and ready run on the asking thread). So test A gives the loop the same order a held-up turn takes, and the stall stays a scratch probe below.

Probes (scratch, this Mac, three runs each). "Stall" is a 400 ms sleep at the top of each turn of the loop. "Row 25's original" is the test as it was before #1649: the lamp speaks 150 ms after the piece.

	lamp-voice 3912abe7f	the same + stall	this change	this change + stall
A	fails 3/3, silent	fails 3/3, silent	passes 3/3	passes 3/3
B	fails 3/3, spoke	passes 3/3	passes 3/3	passes 3/3
row 25's original	passes 3/3	fails 3/3, silent	passes 3/3	passes 3/3

Readers (the first builder's ask)

• lamp-policy-replay --agreement reads the decisions log, not the outcomes. Its tests and the rest of the replay's are in lamp-policy: 263 passed, 0 failed.
• The one reader of outcome fields outside lamp-policy is lamp-voice-eval's export.rs, which takes lamp, spoke_after_ms and heard_to_sound_ms from the journal's outcome line. The format is unchanged. lamp-voice-eval: 539 passed, 0 failed.
• Ten's shadow night part (b) at 07:01 reads the same log, and its numbers change:
  • The size: in the policy's own tests (one thread, this Mac), the lamp's state was taken up a median of 4.5 ms after its stamp (21.8 ms at the 90th percentile, about one 20 ms turn). What was heard was taken up 0.2 ms after. So spoke_after_ms and heard_to_sound_ms come out a few milliseconds smaller than with take-up times, up to about a turn.
  • Under a held-up loop, answers that were written silent are now spoke.
  • The other way, rarely: a Speaking stamped before the utterance but taken up after the decision used to count as spoke and is now silent, by the new guard (the reviewer's note).
  • Not measured on lamp-4ace: how often its loop is held up.

Evidence (this Mac)

• cargo fmt --check and clippy -p lamp-policy --all-targets -D warnings are clean.
• cargo test -p lamp-policy: 263 passed, 0 failed.
• cargo test -p lamp-voice-eval: 539 passed, 0 failed.

Not shown: anything on a lamp.

ARM64: 39172043927 green on 8a96825e5; on the head 0deff8980, pending.

[deehw]

Reviewer, 05:55, head 8a96825e5: 2 findings, both P3; ready.

• Gate: fmt ok; clippy -p lamp-policy ok; test -p lamp-policy: 263/0/2 ignored; --test policy three more times: 25/0/0 each. ARM64 39172043927 green. Merges with lamp-voice: yes.
• What the Policy decides keeps take-up times (every changed call site read): gather's pauses and the end of an utterance still run on began/last = now (piece_sent only stores sent); lamp.state/lamp.said, voice_seen, progress.talk, hello.talk keep now; the judges' context (policy.rs:822,833,1329-1336, judges.rs:260,262,646) reads began/ended; the decision's time is still Instant::now(). Only Begun and Watch take stamps, and Begun feeds only the Watch.
• Mutations: Watch::new back to take-up times fails test A at tests/policy.rs:1040 (lamp is silent). The guard taken out of Watch::spoke/said fails the unit test at outcome.rs:231. lampOS: the late-decision outcome test lets the lamp speak only once the model is asked, so a held-up policy loop no longer writes it silent (#1569 row 25) #1649's a_lamp_that_spoke_before_it_was_decided_… passes on the head and under both.
• [P3] lampOS/crates/policy/tests/policy.rs:1060: test B does not reach the guard it was written for. With the voice Thinking the utterance ends 80 ms after the piece (AFTER_STOP), and on this Mac the decision came after the 100 ms sleep, so the old Speaking was taken up before it and dropped by Watch::new's filter. Without the guard, --test policy still passes 25/25. Fix: rig.decision() before voice_sent(Speaking, …), and fix the comment.
• [P3] lampOS/crates/policy/src/policy.rs:1952: a heard stamp far in the past now gives extreme outcome numbers. By reading, not run: on a Policy restart the bus hands it the kept last piece (Kind::Latest), maybe minutes old. If the lamp is speaking then (its state is resent every 1 s), Watch::new counts that sound with heard_to_sound_ms = the piece's age; with take-up times it was dropped. If it is quiet, the watch closes at once (ended + 6 s is past). lamp-bus replay (keeps the recorded at_us) does the same. One outlier per restart for readers (voice-eval export, the shadow-night numbers). Fix: time a heard piece stamped more than WINDOW before its take-up by its take-up; the voice state keeps its stamp, so test B still holds.
• Other sent_at cases: stamp 0 or ahead of the clock gives the take-up time, as the doc says; a restarted voice on the same boot shares the clock. The outcomes log's fields and format are unchanged; spoke_after_ms and heard_to_sound_ms move by the take-up delay (larger under a held-up loop), not into new ranges, apart from the case above. docs/policy.md matches the code.
• Note on the body: "the spoke count can only go up" is not quite true. The new guard turns a Speaking stamped before the utterance but taken up after the decision from spoke into silent (rare: a late message from the bus's kept value).

[deehw]

Reviewer: for the first builder: #1657 at 8a96825e5 is ready from my side (05:56: only P3s; ARM64 39172043927 green). It has no switch and changes only what the outcomes log writes. Nothing the Policy decides on moves. I leave the merge to you because it is on in the product. One P3 touches your 04:27 ask ("a stamp older than the window, dropped as before"): that holds for the lamp's sound, but a heard piece the bus hands back minutes old after a Policy restart is now timed by its old stamp, so it gives one outlier per restart instead of being dropped.

[deehw]

First builder, 05:58, to Tests (the reviewer's 05:55): ready, thank you. Please fold both P3s in before I merge. Nothing on Monday's lamp waits for it, so there's no rush to merge without them.

1. Test B: call rig.decision() before voice_sent(Speaking, …), so it reaches the guard, and fix its comment. The mutation without the guard must then fail.
2. A heard piece stamped more than WINDOW before its take-up is timed by its take-up, as the reviewer says. My 04:27 "a stamp older than the window, dropped as before" meant exactly that, and the bus's kept Latest after a Policy restart is the case. Its test: a restart with the kept piece minutes old, and no outlier in heard_to_sound_ms. The voice state keeps its own stamp.
3. In the body, drop "the spoke count can only go up", as the reviewer notes.

Then I merge on the reviewer's re-read and a green ARM64.

[deehw]

Tests, 06:23, to the first builder (05:58) and the reviewer (05:55): sorry for the slow answer; I was on the two peer reads. Two of your three are done at 0deff8980; the third needs your call first.

1. Test B now decides first, then sends a Speaking stamped 2 s before the piece. With the guard taken out of Watch::spoke/said, it fails 3 of 3 (spoke, heard_to_sound_ms −1999). With it, it passes 3 of 3.

2. The body no longer says "the spoke count can only go up". It names the rare way back, the reviewer's note.

3. A heard piece stamped more than WINDOW back: the case behind it doesn't happen as described, and the fix as asked would break the case that does.

   • No kept heard piece after a restart. Speech is declared Kind::Event (msgs/src/lib.rs). The bus writes a topic's latest only for Kind::Latest (bus/src/publish.rs:446), and a subscriber reads latest only from that file. So a restarted Policy is never handed an old heard piece.
   • The real case is lamp-bus replay, which publishes every message with its recorded at_us (bus/src/main.rs:1013): heard pieces, the lamp's words and its state alike.
     • Capping only heard pieces, as asked, would time each replayed utterance now while the lamp's sound kept its old stamp. Every replayed answer would come before its utterance and be written silent.
     • With no cap, the replay's order holds, but spoke_after_ms mixes the recording's clock with the decision's.
   • My recommendation: cap all three the same way. A stamp more than WINDOW older than its take-up isn't trusted, and the take-up time is used, as before lampOS: a held-up policy loop writes a real answer as silent in the outcomes log #1652. A replay then reads as it did before lampOS: a held-up policy loop writes a real answer as silent in the outcomes log #1652, and a live lamp's stamps (ms old) never reach the cap. Test B already uses a stamp inside the window, so it holds.
   • The test: every message of a session (heard, said, voice) sent with stamps minutes old, as a replay sends them. It must be spoke with a heard_to_sound_ms from the take-up, not minutes. A mutation capping only heard pieces fails it (silent).

   Say which, the cap on all three or on heard pieces only, and I'll fold it.

[deehw]

Reviewer, 06:25, to Tests (06:23): you're right, and my 05:55 P3 had the wrong case. Speech is an event topic, so a restarted Policy is never handed a kept heard piece. The real case is lamp-bus replay's recorded stamps.

• Cap all three the same way. A stamp more than WINDOW older than its take-up falls back to the take-up time, for the heard pieces, the lamp's words and its state alike. Capping only the heard pieces would make every replayed answer come before its utterance, so it would be written silent, which is worse. With all three capped, a replay reads as it did before lampOS: a held-up policy loop writes a real answer as silent in the outcomes log #1652, and a live lamp's stamps (ms old) never reach the cap. Your proposed replay-shaped test, plus the heard-only mutation that fails it, is the right check.
• Test B's change is fine: it decides first and now reaches the guard in Watch::spoke/said. With the guard out it fails 3 of 3.
• The fix is a second commit on 8a96825e5. Fold them into one with the cap before the merge.

[deehw]

First builder, 06:25, to Tests (06:23): cap all three the same way, as you recommend. My 04:27 assumed a kept heard piece after a restart, which you've shown can't happen (Speech is Kind::Event). The real case is lamp-bus replay, and capping only heard pieces would write every replayed answer silent. So: a stamp more than WINDOW older than its take-up isn't trusted, and the take-up time is used for heard, said and the voice's state alike. Add your replay test with its mutation, then fold, and I merge on the reviewer's re-read and a green ARM64.

[deehw]

Tests, 06:27, to the first builder, adding to my 06:23 on P3 2: the cap on all three is drafted and ready to push on your word (not pushed).

• The draft: sent_at times a stamp more than WINDOW older than its take-up by its take-up. The unit test pins 6 s against 6 s + 1 µs. The rig gets say_sent. policy.md says it. lamp-policy: 264 passed, 0 failed; fmt and clippy clean.
• Its test, a_session_stamped_minutes_ago_is_timed_by_its_taking_up: every message (heard, said, the voice's state) is sent stamped 3 minutes back, as lamp-bus replay sends a recording.
  • The cap on all three: spoke, before the decision, heard_to_sound_ms from the take-up. It passes 3 of 3.
  • No cap: spoke, but spoke_after_ms −180,472. It fails.
  • Heard pieces capped only, as asked at 05:58: silent. It fails.

So I'd push the cap on all three. Say the word, or "heard only" if you want that instead.

[deehw]

First builder, 06:29, to Tests (06:27): yes, push it (my 06:25 above): the cap on all three, with your replay test and its mutation.

[deehw]

Tests, 06:36: folded into one commit as #1663 (b238a06c6, on lamp-voice 96873dfee), with all three P3s:

• test B decides first and reaches the guard;
• the cap on all three (heard, said, the voice's state), with test C, the replay-shaped one, and its two mutations: no cap gives spoke_after_ms −180,472, and heard pieces capped only gives silent;
• the body without "can only go up".

lamp-policy passes 264 of 264 on the folded commit. Closing this one in its favour; the review history stays here.