vm: batch 0, evidence re-recordings for #9 #20

Merged
asxpi merged 29 commits from vm/batch-0 into main 2026-11-09 14:55:06 +00:00
Member

Batch 0: re-recordings that close the evidence gaps of #9, the first runs with provenance (#19): each has scenario.py, steps.log, side logs and a filled EVIDENCE.md.

bug result runs
C35 reproduced on prosody (Gajim, Dino); ejabberd control passes 125134, 125811, 142257
C36 reproduced: Kaidan's accept lacks rtcp-mux, aim's libwebrtc rejects it (client-tacky.log) 125726
S14 reproduced with Kaidan (OMEMO 2); Gajim control 131521, 131816
C38 not reproduced (count stable over 3 restarts) 134000
M26 / M28 reproduced (no notification focused; web none at all) 140003, 141044
M27 reproduced (View XML shows 0.3 namespace for an OMEMO 2 message) 131002
P1 reproduced, Kaidan's: the decrypted upload matches aim's announced hash 131002
P2 fixed by #13: call on prosody with TURN, audio and video both ways 130351
P3 reproduced 1 of 4: Dino's audio SSRC sends only RTCP (rtp.log) 130455, 131143, 131724, 132256
C39 stays withdrawn: web shows aim's live test card 133803

Harness (vms:): view_xml(), Kaidan file_record(), interop-aesgcm, omemo_restart.py, undecryptable_count() fix, aim debug_log() → client-tacky.log, window minimize/restore and notify counting in the guest, call-accept and composer fixes, xep0045 join-error shot, longer terminate wait.

🤖 Generated with Claude Code

Batch 0: re-recordings that close the evidence gaps of #9, the first runs with provenance (#19): each has `scenario.py`, `steps.log`, side logs and a filled `EVIDENCE.md`. | bug | result | runs | |---|---|---| | C35 | reproduced on prosody (Gajim, Dino); ejabberd control passes | 125134, 125811, 142257 | | C36 | reproduced: Kaidan's accept lacks rtcp-mux, aim's libwebrtc rejects it (`client-tacky.log`) | 125726 | | S14 | reproduced with Kaidan (OMEMO 2); Gajim control | 131521, 131816 | | C38 | not reproduced (count stable over 3 restarts) | 134000 | | M26 / M28 | reproduced (no notification focused; web none at all) | 140003, 141044 | | M27 | reproduced (View XML shows 0.3 namespace for an OMEMO 2 message) | 131002 | | P1 | reproduced, Kaidan's: the decrypted upload matches aim's announced hash | 131002 | | P2 | fixed by #13: call on prosody with TURN, audio and video both ways | 130351 | | P3 | reproduced 1 of 4: Dino's audio SSRC sends only RTCP (`rtp.log`) | 130455, 131143, 131724, 132256 | | C39 | stays withdrawn: web shows aim's live test card | 133803 | Harness (`vms:`): `view_xml()`, Kaidan `file_record()`, `interop-aesgcm`, `omemo_restart.py`, `undecryptable_count()` fix, aim `debug_log()` → `client-tacky.log`, window minimize/restore and notify counting in the guest, call-accept and composer fixes, xep0045 join-error shot, longer terminate wait. 🤖 Generated with [Claude Code](https://claude.com/claude-code)
On Prosody the room aim creates stays locked (#9 C35) and the peer's
join fails; the recorded runs had only the screenshot from before the
click. When the peer gets no self-presence, log the error condition of
its error presence and take a join-error shot before the step fails.

Assisted-by: Claude:opus-5-5
#9 C36 needs aim's own rejection of Kaidan's session-accept in a log:
it was only on screen because aim-debug.log stops after the connect.
debug_log() turns on "Write a log file" and "Log WebRTC internals";
the profile's tacky.log from this start on is copied into a recorded
run as client-tacky.log, where libwebrtc logs "Failed to set remote
answer sdp: ... RTCP-MUX is not enabled when it is required".
xep0167.py turns it on and quotes the errors in steps.log.

For M26/M28, xep0184.py now also delivers a line to each side while
it is focused with another chat open and while it is minimized, and
counts the Notify calls with their notify.log lines (minimize(),
restore(), window_state(), notify_calls()).

Assisted-by: Claude:opus-5-5
Re-records #9 C35 with the peer's refusal on screen. aim creates
claude-test-165135 and gets status 201 + 110 as owner, but sends no
muc#owner instant-room submit (0 in client.log). Prosody keeps the room
locked ("Room is locked, denying entry", server.log:1195) and answers
Gajim's join with item-not-found (peer-gajim.log:1490); Gajim shows
"Failed to Join Group Chat / item-not-found" (shot-2).

Assisted-by: Claude:opus-5-5
Re-records #9 C35 with Dino's refusal on screen. aim creates
claude-test-165811 and gets status 201 + 110 as owner, but sends no
muc#owner instant-room submit (0 in client.log). Prosody keeps the room
locked ("Room is locked, denying entry", server.log:1227) and answers
Dino's join with item-not-found (peer-dino.log:1927); Dino's Join
Channel dialog shows "Room does not exist" (shot-2).

Assisted-by: Claude:opus-5-5
Re-records #9 C36 with aim's own rejection in a log. aim's
session-initiate offers <rtcp-mux/> and BUNDLE (client.log:226);
Kaidan 0.16's session-accept has neither (client.log:248). aim's
libwebrtc refuses the answer, now logged in client-tacky.log:217:
"Failed to set remote answer sdp: The m= section with mid='0' is
invalid. RTCP-MUX is not enabled when it is required", the same text
on aim's call window (shot-3, shot-9) while it keeps ringing. aim sends
no session-terminate; Kaidan ends both calls with failed-transport
(client.log:277, :381). No RTP on either NIC (rtp.log), no tone heard.

Assisted-by: Claude:opus-5-5
Control for #9 P2: the first recorded call on prosody since #13 added
coturn. extdisco now returns STUN and TURN (client.log:232), both sides
offer relay candidates, and both the audio and the video call connect:
tones heard both ways (shares 1.00 / 0.99), 400 opus packets each way
in 8 s on both NICs, VP8 both ways and live test cards in both video
windows. Dino's audio was present in both calls (P3 not seen here).

Assisted-by: Claude:opus-5-5
#9 P3 attempt 1 (of up to 5): Dino was not silent. Both calls carried
the tones both ways (aim hears 660 Hz 1.00, Dino hears 440 Hz 0.99),
and rtp_stats on Dino's NIC shows 400 opus packets out per 8 s in the
audio and in the video call (rtp.log), beside 267 VP8 out and 1489
VP8 in. Both test cards were live on the other side, so aim's camera
reaches Dino (C39's withdrawal holds here too). A control for P3.

Assisted-by: Claude:opus-5-5
Assisted-by: Claude:opus-5-5
P1 (Kaidan's "Checksum does not match") and M27 (View XML's EME
namespace) had their proof checked by hand after the run, so nothing of
it was recorded. xep0363.py now opens aim's View XML on the picture it
sent (screenshot, the stored record copied into steps.log), compares its
EME namespace with the wire, reads the receiver's own record of the file
(Kaidan: its sqlite database, URL, announced hash, error text), fetches
the aesgcm:// URL in aim's VM and decrypts it with interop-aesgcm, and
logs the plaintext and ciphertext sha-256 next to the announced one.

C38 (the "can't be read" count growing per sign-in) needs aim restarted
several times with the count and the MAM results read after each start:
omemo_restart.py does that and counts archived key-exchange results that
come back on more than one sign-in.

Assisted-by: Claude:opus-5-5
Re-records #9 P1 with the proof that was only checked by hand before.
aim pastes a picture into an OMEMO 2 chat; Kaidan 0.16 shows "Transfer
failed: Checksum does not match" and keeps no file. aim's VM fetched
the aesgcm upload and decrypted it: the plaintext's sha-256 equals the
hash aim announced and the hash Kaidan stored, so the fault is Kaidan's
check, not aim's metadata (cause: peer).

The same run records #9 M27: aim's View XML of that message shows EME
namespace eu.siacs.conversations.axolotl, the wire had
urn:xmpp:omemo:2.

Assisted-by: Claude:opus-5-5
aim's XML log lags the click by up to ~30 s, so the 20 s wait for its
session-terminate read 0 in the recorded prosody call run although the
terminate was sent (client.log:295 of 20261109-130351). Wait 60 s; the
explore re-run (b0pr-x167) counts it in both calls.

AGENTS.md: prosody calls pass since #13 (recorded, audio and video),
and what the C35 runs show and leave behind (join-error shot, the
follow-on talk failures, locked claude-test rooms).

Assisted-by: Claude:opus-5-5
#9 P3 attempt 2 (of up to 5): Dino was not silent again. The tones
went both ways in the audio and the video call, and rtp_stats on
Dino's NIC shows opus out in both calls (rtp.log:153, :174)
beside its VP8; the test cards were live on both sides. A control.

Assisted-by: Claude:opus-5-5
Re-records #9 S14 with its evidence. In an OMEMO 2 chat aim retracts
its own message: the <retract/>, the fallback body and <fallback/> go
out with no <encrypted/>, while the original was OMEMO 2. Kaidan 0.16,
which has no XEP-0424, keeps the original and shows the clear fallback
as a new message marked Unencrypted. Kaidan's own leg is a skip.

Assisted-by: Claude:opus-5-5
Control for #9 S14. Retraction works both ways: Gajim applies aim's
retraction and aim applies Gajim's. aim's retraction goes out in the
clear here too (OMEMO 0.3 chat), the same leak as in the Kaidan run.

Assisted-by: Claude:opus-5-5
#9 P3 attempt 3 (of up to 5): Dino was not silent again. The tones
went both ways in the audio and the video call, and rtp_stats on
Dino's NIC shows opus out in both calls (rtp.log:153, :175)
beside its VP8; the test cards were live on both sides. A control.

Assisted-by: Claude:opus-5-5
#9 P3 reproduced on attempt 4 of this batch (1-3 passed). In the
video call aim heard none of Dino's 660 Hz while Dino heard aim's
440 Hz and both test cards were live. rtp_stats over the same 8 s:
Dino's NIC sent 259 VP8 packets and, for its audio SSRC 290fc134
(the opus payloader of peer-dino.log:3645), only RTCP, no opus RTP;
aim's NIC got no opus. Dino's record stream from FakeMic was open
and uncorked. So Dino does not send the audio it accepted with
senders='both'; aim is not dropping it. Cause: peer (Dino 0.5.1).

Assisted-by: Claude:opus-5-5
undecryptable_count() returned (0, 0) while aim showed "2 encrypted
messages can't be read on this device (2 could not be decrypted)":
full-screen tesseract reads the small grey pill on the patterned pane
as "2 encrypt" at best. Find any such word, then OCR the pill's band
alone, upscaled with its grey levels stretched (ocr_band, --psm 7).

omemo_restart.py parsed no MAM results: aim's JSON lines end in
","bytes":…}, not "}. Take the result per line.

Assisted-by: Claude:opus-5-5
In an aim -> web video call web never answered: the incoming sheet was
up, but find_color boxed every greenish pixel on screen (a picture in
the dimmed chat behind the sheet), wider than a button, and the
pointer left on "Answer" by the audio call hid the label from OCR.
Move the pointer off first and fall back to the "Decline" label, the
Answer button being 87 px left and 41 px above it.

Assisted-by: Claude:opus-5-5
The band read of bc25552 still depended on full-screen OCR finding a
word of the pill, which failed after every restart in the C38 run while
the pill showed "2 encrypted messages can't be read". Sweep the pane's
middle in overlapping 28 px bands instead, each OCR'd alone (~6 s).

Document View XML, Kaidan's database, interop-aesgcm, the pill and the
harness_commit rebase pitfall in AGENTS.md, the new helpers and
omemo_restart.py in README.md; vmrun.zsh records RESTARTS.

Assisted-by: Claude:opus-5-5
Re-records #9 C39 (withdrawn, harness) as a control. In aim's video
call to anotherim-web, web's main view shows aim's test card "aim ->
440 Hz" live (13:41:48, counter 3213 in shot-10; 13:42:00, 3392 in
shot-12), and web's getStats counts inbound video 640x480 growing
from 359 to 4372 packets (web-rtp.log:8-12); 1570 video packets in
8 s reach web's NIC (rtp.log:173). Tones both ways in both calls.
aim's outgoing video works; C39 stays withdrawn.

Assisted-by: Claude:opus-5-5
Re-records #9 C38 with omemo_restart.py: OMEMO 2 both ways, then aim
restarted three times with its "can't be read" count read after each
start. The count stayed at 2 every time, while every sign-in fetched
the same three archived key-exchange messages again (aim's own, with
kex for another vm-aim device). C38 did not reproduce in this run; the
two counted messages appeared once, during the S14 run at 13:16.

Assisted-by: Claude:opus-5-5
P1 is now proven Kaidan's: the announced hash equals the decrypted
upload's. M27 reproduced in the same run. S14 reproduced with a Gajim
control. C38 did not reproduce over three restarts. The explore re-run
of xep0363.py on this tree gives the same results.

Assisted-by: Claude:opus-5-5
The first xep0184 window-state run broke on two things. restore()
mapped and maximized every window of the class, which raised one of
Gajim's hidden popovers (its formatting menu) to the full screen;
it now brings back only the windows minimize() iconified. And Gajim's
composer click at -390 hit the formatting button: with the chat list
730 px wide the field spans only -383..-178, so click at -250.

Assisted-by: Claude:opus-5-5
dbus-monitor wrote notify.log block-buffered, so notify_calls() read in
the xep0184 window-state steps missed a Notify that came a second after
the message (Gajim minimized, 140003). Run it under stdbuf -oL.

Assisted-by: Claude:opus-5-5
Re-records #9 M26 with the notifications captured per window state.
Receipts and displayed markers pass both ways. aim got Gajim's line
focused with the chat closed, focused with Saved messages open and
minimized; notify-aim.log has one Notify, for the minimized case only
(:5). Gajim notified in all three states (notify-gajim.log:5, :34,
:63), focused too. Judged as before: aim does not notify while its
window has focus (UX, may be intended).

Assisted-by: Claude:opus-5-5
The line-buffering of 5493897 was not the cause: aim minimized in the
web run notified 2 s after the message (notify-aim.log:5) and
notify_calls() still counted 0 half a minute later. The host's view
of the guest's /out lags its writes (the lag aim's XML log shows), so
notify_size() and notify_calls() now read notify.log in the guest, and
dbus-monitor runs as before. The Gajim run's EVIDENCE.md said
"block-buffered"; corrected.

web: OCR missed "Saved messages" in the account menu; fall back to the
third item's position.

Assisted-by: Claude:opus-5-5
Re-records #9 M28 (and M26) with the notifications captured per
window state. Receipts and displayed markers pass both ways.
anotherim-web got aim's line focused with no chat open, focused with
a menu open and minimized: notify-web.log has no Notify call at all.
In the same run aim notified only when minimized (notify-aim.log:5),
not while focused with the chat closed or Saved messages open. A real
browser outside the harness's Chromium app window was not tried.

Assisted-by: Claude:opus-5-5
#9 C35 control on ejabberd. aim joins a fresh room and gets status
201 + 110 as owner (client.log:197), and again submits no muc#owner
instant-room form (none in client.log). ejabberd opens the room
anyway: Gajim joins as participant (peer-gajim.log:1661) and a line
goes each way. The prosody run of this batch shows the same aim
behaviour with the room kept locked.

Assisted-by: Claude:opus-5-5
vms: AGENTS notes from batch 0 on ejabberd
All checks were successful
/ check (pull_request) Successful in 4m16s
46f5e3b69d
Window states and where to read notify.log (the guest: the host lags),
answering aim/web's incoming sheet, Gajim's composer with a wide chat
list, web's Saved messages fallback, and the batch-0 results: C36, P3,
M26 and M28 reproduced, C39 stays withdrawn, C35's ejabberd control,
aim's minimized notification not reliable (2 of 4 xep0184 runs).

Assisted-by: Claude:opus-5-5
asxpi merged commit 31e664043d into main 2026-11-09 14:55:06 +00:00
Sign in to join this conversation.
No reviewers
No labels
No milestone
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
another-im/interop!20
No description provided.