Repository navigation
Description
Found while hardware-verifying #145 (PR #146). It is not caused by that change — it reproduces on an image built from master.
Rate
U64E 601A96, fw v3.15-78-g71480a9d, 48 MHz, onchip profile, tools/uci/rig_https_live.py against github.com:443, all runs 2026-08-28 within about an hour, freshly power-cycled at the start:
| image | failures |
|---|---|
4a1a9fe5 — pre-#145 (i.e. master + #143) |
2 / 4 |
ca1e1c8e / d728b9c6 — with the #145 TOD fix |
4 / 11 |
So roughly one run in three, on both. Passing runs are unremarkable: HTTP 200, CFIN at 47-49 s.
Two signatures
A — $86 UCI_ERR_READ_FAIL, stall at RX. Screen reaches CH SH HK1 KEYS ENC1 RX and stops. net_last_error=$86, net_tcp_state=$00, http_status=$0000, uci_read_hdr=$FFFF (the no-data sentinel). $86 is set when uci_check_err sees the error bit after a SOCKET_READ push; that path forces NET_TCP_ERROR, and net_tcp_close then returns the state to CLOSED.
Note this is the documented …KEYS ENC1 RX screen from CLAUDE.md's device gotchas, with net_last_error=$86 — i.e. it presents exactly as the "real device wedge" half of that discriminator, but a power cycle is not required and the next run frequently passes. (Separately: $86 also appears on fully passing runs, since it is set by the read that ends a normal fetch — corrected in the docs on #143.)
B — $88 UCI_ERR_NO_SOCKET at connect. Fails early, ~33 s, uci_read_hdr never populated. TCP_CONNECT did not yield a socket.
What has been ruled out
- Not the UCI adapter: CIA1 TOD is never started, so the TOD-bounded waits (uci_wait_idle / uci_wait_not_busy / resp reads) are unbounded on real hardware #145 TOD fix. Same rate on the pre-fix image; and one failure occurred on a 20 s-budget instrumented build with
uci_wait_max = 0, meaning no bounded wait crossed even one tenth boundary, so no timeout could have fired. - Not bounded-wait duration. Instrumented high-water mark over four full handshakes is one tenth (0.1 s) against a 5 s budget.
- Not socket-pool exhaustion of the kind in UCI network target leaks UDP sockets that are never CLOSEd — pool exhausts, only a power cycle recovers GideonZ/1541ultimate#808. The flashed build carries that PR's fix (#814), confirmed behaviourally on this device by the firmware lane. Our client also issues
CLOSE_SOCKETon every normal exit path (http.s,boot.s) and holds exactly one socket at a time, so the cap-of-4 close-oldest path is never reached.
Leading hypotheses (from the firmware lane, GideonZ/1541ultimate#814's author)
- TIME_WAIT PCB pressure. #814 bounds the UCI socket table, not lwip's pools. A TCP socket closed mid-connection lingers in TIME_WAIT holding a PCB after the table slot is already freed. A signature-A failure parks the machine mid-connection, so a transient open failure on the next run — signature B — is consistent. That would make A and B one story: A causes B.
- Stale-handle EBADF. #814 makes READ/WRITE/CLOSE on a handle the target does not own return an error rather than passing it to lwip. A read on a socket closed underneath us now produces an error bit, which is exactly
$86. Worth noting this failure mode did not exist before #814, though signature A also reproduces on our pre-UCI adapter: CIA1 TOD is never started, so the TOD-bounded waits (uci_wait_idle / uci_wait_not_busy / resp reads) are unbounded on real hardware #145 image, which was run against the same firmware.
Suggested next steps
- Re-run the same matrix against the pre-#814 firmware still on the device at
/USB1/update_v3.15-74-g6b5ffc21.u64to see whether the rate changes. That discriminates "our bug, newly visible" from "firmware behaviour change". - Capture the STATUS-channel string on the
$86path rather than collapsing it to one error code — the firmware returns ASCII (85,ERROR OPENING SOCKET,12,SEND ERROR: 9, …) and we currently discard which one. - Check whether signature B only ever follows a signature-A run. If so, hypothesis 1 is confirmed and the fix is client-side teardown after a stalled connection.
Not blocking #146; that PR is green on this device and this predates it.
Activity
JC-000 commentedon Aug 28, 2026
Substantive lead: the failures carry command-framing desync statuses
PR #148 makes the adapter keep the firmware's STATUS line instead of discarding it. On this device, failing and erroring runs report:
net_last_error$8681,INVALID PARAMS$8821,UNKNOWN COMMAND$0002,NO DATA: 11(routine EWOULDBLOCK)Both strings match the firmware source byte-for-byte including their declared lengths (17 and 18) —
command_intf.cc:243,network_target.cc:18— so the capture is real, not an artifact of the buffer.81,INVALID PARAMSis emitted at a dozen sites innetwork_target.cc, every one of them a wrong parameter length.21,UNKNOWN COMMANDis an unrecognised command id. Neither is a network condition: both say the firmware could not parse the command we sent. That reframes this issue — the$86/$88codes are downstream of command-framing desync, not of socket state.Mechanism, with source evidence
While capturing the line I found why it was never visible.
uci_drain_statuspulsedNEXT_DATAper byte, and that bit is DATA_ACCEPT, not a per-byte advance (command_protocol.vhd: it setshandshake_in(1)and clearsstate(1), ending the data phase; reading the status slot advancesstatus_pointeron its own). The drain read one byte, accepted the whole block, and stopped — so every status line was truncated after one byte, invisibly.That is #144's mechanism, now with wire evidence.
uci_drain_respanduci_read_resp_bytesdo the same per-byte pulse and are on the data path, where a premature accept would leave the command interface mid-transaction and mis-frame the next command — which is exactly what21,UNKNOWN COMMANDand81,INVALID PARAMSreport.I did not touch those two in #148: fixing the data path is #144's job and deserves its own hardware matrix, not a drive-by in a diagnostic PR.
What this does to the earlier hypotheses
85,ERROR OPENING SOCKET, which has not appeared once.02,NO DATA: 9cannot be filtered out if it ever occurs — so this is now falsifiable rather than merely unobserved.Both remain possible; they are just no longer the leading explanation. The leading explanation is now our own command framing, i.e. #144.
Next step is #144: fix the per-byte accept on the response path and re-run the 4-run matrix from the top of this issue.
JC-000 commentedon Aug 28, 2026
Correction:
21,UNKNOWN COMMANDdoes not prove the command byte was badMy previous comment said both captured lines mean "the firmware could not parse the command we sent" and inferred the fault was in our command byte. The firmware lane reviewed it and the
21half is weaker than I claimed. Verified against the source here:21,UNKNOWN COMMANDis emitted from six places, not one:The base-class
parse_commanddefault means any target that doesn't override it answers with that identical string. So the line does not identify which target rejected us, and it is at least as consistent with our frame shifting so the target byte changed — i.e. we were talking to the DOS target or an unimplemented one — as with reachingNetworkTargetwith a corrupted command byte. Those want different fixes.The proposed tell (an empty reply implying
NetworkTarget) does not discriminate either. Five of the six sites pair the status withc_message_empty:command_target.h:38,network_target.cc:179,control_target.cc:117(set as defaults before its switch runs),dos.cc:521anddos.cc:761. The lone exception isdos.cc:538, which sets*reply = &data_messagewith//*reply = &c_message_empty;commented out directly above — a deliberate exception left in place.81,INVALID PARAMSis unaffected — eight sites innetwork_target.cc(:70,:82,:103,:125,:145,:153,:161,:169), all per-command length checks. That one does mean right command, wrong length.What survives: both lines say a command we sent was not parseable as sent. That is a framing problem rather than a network condition, and still points at the per-byte-accept defect (#144). What does not survive is my narrower claim about which byte is wrong.
Also excluded while checking: our command IDs match
network_target.hexactly —OPEN_TCP $07,OPEN_UDP $08,CLOSE_SOCKET $09,READ_SOCKET $10,WRITE_SOCKET $11. The off-by-seven hazard in those decimal-looking hex values is not our bug.Cheapest way to settle target-vs-command once #144's drain fix lands: log the bytes we actually put on the bus and compare, rather than inferring from the status line.
(Edited: the empty-reply count is five of six, not four —
control_target.cc:117sets the pair as defaults before its switch. Conclusion unchanged and slightly strengthened.)uci: capture the firmware's STATUS line instead of discarding it (#147)
Merge pull request #148 from JC-000/diag/147-capture-uci-status
JC-000 commentedon Aug 29, 2026
The failure-rate data in this issue is contaminated — treat it as unusable
The U64E was mid firmware-test-cycle while I was measuring, with the firmware lane exercising socket-lifecycle scenarios on the same device. I did not know that at the time. Their harness reaches the device without taking
DeviceLock, so the lock I held did not exclude them, and nothing in my run output would have shown the overlap.That is not a footnote. The scenarios being run were
abandoned-sockets-are-bounded(eight consecutiveOPEN_UDPs) andreset-closes-uci-sockets(repeatedmachine:resetwith sockets open). Concurrent socket-pool churn and machine resets are an excellent way to produce, in my runs:$88 NO_SOCKETat connect,21,UNKNOWN COMMAND/81,INVALID PARAMS.That last one matters most: my inference that our command framing is broken is no longer supported. Interleaved activity on the shared command interface is a more parsimonious explanation for those two status lines than a latent framing bug in our adapter, and I cannot separate them from the data I have.
Specifically withdrawn, pending a clean re-run
$86and$88signatures.What still stands, and why
tod_stop <= '1'at reset; only a TENTHS write clears it), plus the keypress hypothesis was tested and falsified.NEXT_DATAtruncation is explained bycommand_protocol.vhd(the bit is DATA_ACCEPT; it clearsstate(1)), reproduced deterministically as one byte vs the full line, and the captured strings match the firmware's declared lengths byte-for-byte. Contention does not produce that pattern.Redoing this properly
The matrix needs re-running in a window where the device is known quiet, with the firmware lane's build identity pinned and unchanged across both arms, n>=4 per arm. Until then this issue has a hypothesis and no measurement.
Filed against myself as much as anything: I ran a 15-run campaign on a shared device without first confirming nobody else was using it, and the queue-bypass hazard was already known in this project's own notes.
JC-000 commentedon Aug 29, 2026
Partially un-withdrawing: the contention basis does not hold for the 08-28 campaign
The firmware lane pulled their timestamps and neither of their wedges overlaps my runs. Their suite ran 05:53:17 → failed 06:00:46 today; last night's wedge was ~19:02, after a flash at 19:01:44. Their device-side activity on 08-28 was a short probe ~13:40, builds and an FTP upload 16:35–16:46, and the flash at 18:58.
My 08-28 campaign began ~14:06 and ended ~18:06. On both sides' accounts that window contains none of their command-interface activity — their socket-churn probe (the
abandoned-sockets-are-boundedscenario, eight consecutiveOPEN_UDPs) preceded my first run by roughly 25 minutes, and the FTP upload is file transfer, not command-interface traffic.So my previous comment was over-broad. The specific mechanism I withdrew on — their runs interleaving with mine — is not supported by either timeline for that campaign. I withdrew on the strength of "the device was in use" without checking whether the use overlapped, which is the same error in the other direction as the one I made earlier in this issue.
What I am not doing: declaring the numbers sound
Two limitations survive the correction, and they are mine, not theirs:
tests/e2etakes no lock and mine cannot see it, so "nobody happened to be running" is a fact about that afternoon, not a guarantee the campaign was isolated.Status of the data, therefore: provisional, not withdrawn. The 2/4 control vs 4/11 rate and the two failure signatures stand as observations. The inference that they point at our command framing (#144) goes back to being a live hypothesis with weak support — it was never strong, since
21,UNKNOWN COMMANDhas six emission sites and cannot identify which target rejected us.Re-running the matrix on a confirmed-quiet device with a pinned firmware build is still the right move, and now it is cheap confirmation rather than a rescue.
Today's runs (08-29, 06:00–06:10) ARE contaminated, and now explainably so
Separate from the above. My first run today started at 06:00:52 — six seconds after their suite wedged at 06:00:46, on a device awaiting a power cycle. That accounts for the
NETWORK INIT FAILEDat the$DF1DID probe and thenet_last_error=0x89timeouts I saw while checking #149, without implicating that PR's change. Those three runs stay invalid; #149's hardware verification is still pending.JC-000 commentedon Aug 29, 2026
Leading hypothesis is now OUR fence constant, not command framing
Re-measured on a confirmed-quiet bench with the firmware pinned, and the result points somewhere I had not been looking.
Device identity (recorded properly this time —
/v1/infosays "3.15" for all of it and is useless):The measurement
Both arms on the same firmware, same PRG source, differing only in
UCI_FENCE_OUTER(the delay loop after every$DF1C-$DF1Faccess): shipping value 5, versus 10.$88 NO_SOCKETThe pass/fail difference (3/7 vs 1/6) is weak. The signature difference is the interesting one: every
21,UNKNOWN COMMANDand81,INVALID PARAMSin this campaign occurred at the shipping fence, and none at double. Fisher exact two-sided on 4/7 vs 0/6 gives p = 0.07 — suggestive, not significant, and I am not claiming otherwise at this n.Note also that the framing status appears on passing runs too (run 14 passed carrying
81,INVALID PARAMS), which is why the status line is a better discriminator here than the outcome: the adapter often recovers, so pass/fail undercounts the underlying events.The one failure at x2 is qualitatively different: it reached CFIN — the full TLS handshake completed to client Finished — and failed at the response, with
net_last_error=0x00and no status captured. Not a framing signature.Why this is mechanistically plausible
CLAUDE.md already documents the symptom of an under-length fence, from the C64 Ultimate bracketing work: "the symptom below the floor is a silently lost TCP_CONNECT push →
NO_SOCKET". That is runs 1 and 2 exactly.And the core moved. Per the firmware lane, 1.4E → 1.4F came from commit
59594060, "Updated REU - no initial delay on U64/U64E2, because of Turbo Mode", which touchesslot_server_v4.vhd— the cartridge-slot server upstream of every$DF1xaccess. A commit whose subject is removing a delay, in the path our fence exists to pad, in a build that was also re-placed and re-routed. They are explicit that there is no deliberate change to the command interface, and equally explicit that this is not the same claim as "the timing floor did not move".What this would mean
If it holds, #147 is a timing bug on our side that the core update made much more visible, and:
UCI_FENCE_INNER = 217/OUTER = 5was bracketed empirically against the old core and has no upstream specification behind it.Not yet done, and needed before any fix
Doubling the fence is not the fix — it taxes every register access. The floor on 1.4F needs bracketing the way the C64 Ultimate's was (FAIL/PASS either side), then a constant set with margin above it. n also needs to be larger than 6-7 per arm.
Wider point, which the firmware lane is raising upstream: there is no documented minimum inter-access gap for
$DF1B-$DF1Fanywhere in the firmware repo or its docs. In-tree 6502 clients encode it implicitly and differently — one polls the state register, another relies on 1 MHz instruction timing — and none states a number. So every UCI client in the field carries an uncalibrated constant that a core update can invalidate silently.http: 24-bit chunk size, saturating on overflow (#147)
JC-000 commentedon Sep 25, 2026
Re-measured 2026-09-25 on the U64E (fw 3.15, core 1.50), github.com at 48 MHz
These runs replace the 2026-08 rate data. The failure mode is different now.
1. On master (uci-onchip
ea3e8857…),rig_https_livefails on github.com's chunk sizes, not on anything in UCI. The 576 KB page arrives as chunks of 32768, 65536, 65536, 67880, … B.http_chunk_remwas 16-bit:10000chunk-size line wrapped to 0 and parsed as the terminal chunk.10928line wrapped to0x0928and desynced the parser.Earlier PASSes of this rig against large pages are therefore not evidence. Fixed in #252. The EOF-as-no-data hang and a
-1write loop that turned a server hang-up into a 900 s hang are fixed in #253.2. With the parser fixed, the body still ends short, always at the same byte offset:
8f40083c…(#252),rig_https_live01,CONNECTION CLOSED BY HOSTc4f60c3f…(#252+#253),rig_https_bannerc4f60c3f…,rig_https_bannerHalving the rate doubled the elapsed time and did not move the cut. It is byte-positioned, not time-based.
What I ruled out:
tcp_recv_overflow=0.net_tcp_statewas still CONNECTED at the dump, so our close path never ran. The firmware's status isrecv()==0, i.e. a FIN on its side.SO_RCVBUF=4096: 1.8 KB/s (323 s) and 2.35 KB/s.openssl s_client -tls1_3 -ciphersuites TLS_CHACHA20_POLY1305_SHA256 -groups X25519 -maxfraglen 512with the C64's exact request bytes, read at 2.35 KB/s: 581,719 B in 248 s.So on the C64/U64E path, the TCP stream ends ~26 KB (~52 TLS records) before the end of the response, at a stable offset, mid-record, with a FIN. The cause is not established. Next discriminators, beyond our code:
Left open.
Update: the two remaining discriminators
openssl s_client -tls1_3 -ciphersuites TLS_CHACHA20_POLY1305_SHA256 -groups X25519 -maxfraglen 512, with the C64's request bytes, piped through a reader held to 2.35 KB/s: full body, 581,719 B in 247.6 s. The caveat:s_clientcannot setSO_RCVBUF, so the Mac's receive buffer may absorb more than the U64E's window would.rig_https_localon a http: 24-bit chunk size, saturating on overflow (#147) #252+uci: close retry (#243), EOF closes the socket state, -1 write fails the send #253 uci-onchip SNI image (9c56bfd5…), its listener serving github's own 576 KB body with github's real chunking (32768 65536 68552×6 8 66591 0).http_getC=0, HTTP 200, complete.The same page, at the same pace, through the same client code, completes from a local server and is cut ~26 KB early from github.com. The cut is byte-positioned (24 MHz vs 48 MHz above). What remains is the interaction between github's side and the U64E's TCP stack, which a host client cannot reproduce. Left open; not ours to fix in the client.
http: 24-bit chunk size, saturating on overflow (#147)
Merge pull request #252 from JC-000/fix/147-chunk-size-24bit
JC-000 commentedon Sep 28, 2026
Reopening: closed 2026-09-25 without a linked fix. #252 fixed the 16-bit chunk wrap, but a fixed-byte cut (~544.67 KB of body, clock-invariant 24/48 MHz) remains on github.com → U64E and is under investigation.
JC-000 commentedon Sep 28, 2026
2026-09-28 investigation: github.com's edge ends the stream early, not the U64E or our client
All runs are on the U64E (commit
c47155b7, core 1.50) at 48 MHz, uci-onchip, through DeviceLock. Every run closed cleanly with 'Q'. Values are labelled [M] measured or [I] inferred.Confound in the earlier controls [M]. This Mac runs Cloudflare WARP in full-tunnel mode. Every host control above (curl, Python,
openssl -maxfraglen) reached github from a Cloudflare egress IP, so none of them ran over the U64E's path. WARP's edge also drains github fast.U64E runs [M]
b4d580dc…9279(diag-only: SNI and Host header = github.com)/794c3a40…94ca(= masterf38179b)/047de83b…6166/torvalds/linux/blob/master/Makefile(~797 KB)f0e93d6f…87ee/torvalds/linux(~325 KB)9bf491e2…7c2f/wiki/Commodore_64In every FAIL the ring was empty, overflow was 0,
net_last_errorwas 0, and the socket was CLOSED. The rate held at 4.6 records/s up to the cut. Connection age at the cut was 185, 290 and 390 s, so the cut is not time-since-connect.Direct-path host control [M]
For this test a temporary WARP exclusion was added for 140.82.112.0/20, routed via en0 through the ISP. It has since been removed.
UNEXPECTED_EOF_WHILE_READING). Every complete run ended with close_notify.FP.seq 590077:590917), in sequence right after the last data byte.What this rules in and out
01,CONNECTION CLOSED BY HOSTis only everrecv()==0, i.e. an in-order FIN. The U64E carried 610 KB through the relay and 751 KB from wikipedia intact.This is not fixable in the client. The only client-side change available is how a mid-record EOF without close_notify is reported, and that already reports as TRUNCATED.
JC-000 commentedon Sep 28, 2026
Closing as external. The cut is github-side: github's edge sends an in-sequence FIN without TLS close_notify on some slow-draining connections. It reproduces from a macOS client on the same direct path with no U64E involved, and the U64E completes the same page through a relay and a 751 KB wikipedia page directly. Evidence: #147 (comment). Our client reports the cut as a failure (C=1), not as a complete body.
JC-000 commentedon Oct 14, 2026
New data, 2026-10-14: on the U64E, the fast-draining client gets the whole github page
The U64E fetched github.com
/through the ESP32 TLS-offload client (BACKEND=uci-m3). The client now drains about 17× faster since #296 removed its read delays;M3_READ_FENCE=1rebuilds the old, slow client byte for byte. The two builds were run alternately, in one session, on the same firmware. Each run's expected size is a curl fetch of the same URL taken just before it.Device: U64E, fw 3.15 git 3a1ff9ff, FPGA 126, core 1.50, 48 MHz. Both builds are from master 71b047e and pass
tools/check_m3_client.py(54/54).d34b92cc…7eb9502d…</html>, C=000,OK05,TLS CLOSED WITHOUT NOTIFYnet_last_error=$00on every run.What this shows. On this stack, drain rate decides whether the body completes. That fits the slow-reader explanation in this issue, and it is the first time any client on our device has received the full github page.
What it does not show.
The issue stays closed: the cut is still github-side.