Repository navigation
Two rare read failures at 150 ms: a request never written, and a stale reply #130
Description
What to do
Find out why the ESC of an Integro refused three mailbox writes with "the slave did not accept the mailbox write; SM0 status 0x32" while 2 % of the frames were 150 ms late, when the status read just before each write said SM0 was empty. Do it in this order:
- Run
NETEM="delay 150ms reorder 98% 0%" CAPTURE=120 tools/flaky-bus.sh sm0-refusal 10 enp0s13f0u1u4u2on the Integro, so the capture of Ship a capture program that records how late the frames of a host come back #123 records the frames beside the server log. - For each refusal, find in the capture the status reads of
ecx_mbxemptybefore the write, and whether the frame the port took as the answer was a late return of an earlier read with the same header. - If it was, decide what tells two identical register reads apart, and record the decision in a
NEXTGEN.mdsession. If it was not, record the cause found.
Why
ecx_mbxsendonce writes only after ecx_mbxempty read SM0 as empty, and the ESC refuses a write to a full SM0 with a working counter of 0. The three refusals came after both attempts, and the refusal suffix read SM0 as empty again (0x32, bit 3 clear). So either the status read was answered with a stale frame, or SM0 filled between the read and the write, which nothing else on the master does.
The frame-header check of ports/soem compares command, offset, length and position, and the status reads of ecx_mbxempty go out every 200 µs with the same header. Only the frame index tells them apart, and a 150 ms-late frame can carry the index of a newer read. That is a guess, not a measurement. If it is the cause, the limit the port comment states for cyclic frames also holds for a register read that is sent again and again, and a write refused for a stale status costs the caller one failed request.
Done when
- A capture and the server log of one refusal are on file, and
NEXTGEN.mdnames the cause. - If the cause is a stale status frame: a decision on what tells two identical register reads apart, built or deferred with the reason.
- If a change is built: the same run shows no refusal with SM0 read as empty.
Notes
- Seen on 2026-10-22, three times in 10 rounds of a full parameter read on the bench Integro (product 0x401, firmware v5.6.11), Fedora 44 without a real-time kernel. The log is
out/flaky-bus/127-late150/server.log, lines 4065, 5285 and 7705. - Not seen at 25 ms, without netem, or under 1 % loss.
- The port's write-once rule is not the cause: a refused write is sent once more after SM0 empties, and both copies were refused.
- Out of scope: a retry of a refused read in
readSdo. Whether that is right depends on the cause.
Activity
markosankovic commentedon Oct 22, 2026
A second reading of the symptom, from the Circulo capture of 2026-10-22 (
out/flaky-bus/127c-late150-cap2, 20 rounds, 2 % of the frames 150 ms late).One read failed the same way:
SDOread slave 1 0x1A02:07 failed (the slave did not accept the mailbox write; SM0 status 0x02), at 11:09:25.221. The capture of that run holds 6802 mailbox writes and not one return with a working counter of 0. So the port never sent that write.ecx_mbxsendoncereturns 0 without a write whenecx_mbxemptydoes not read SM0 as empty withinEC_TIMEOUTTXM, 20 ms, and the refusal suffix then reads SM0 as empty because the drive took the previous message out in the meantime. The failure came one second after the aborted file read of #131, when the drive was slow to take its mailbox.So the Integro's "SM0 status 0x32" may be the same thing: not a refused write, but a write never sent because the drive held the previous message longer than 20 ms. Step 2 of the task should check the capture for a refusal frame before it looks for a stale one. If there is none, the question becomes whether 20 ms is the right wait for SM0 to empty on a drive that is busy, and whether a read that never went out should be asked again like a read that got no answer.
markosankovic commentedon Oct 22, 2026
Restated, 2026-10-22 evening
The question as filed is answered: the ESC did not refuse the write. In every capture of the day, 10521 writes in one of them, no mailbox write returned a working counter of 0. The port never sent those requests, because
ecx_mbxemptydid not read SM0 as empty withinEC_TIMEOUTTXM, 20 ms, and the refusal suffix read it as empty a moment later. On the Integro that happened right after an aborted file read, when the drive was slow to take its mailbox. The title stays for the history; this comment is what the issue is about now.Two symptoms remain, both rare and both only under 2 % of the frames 150 ms late, which is past the 100 ms design point:
uploadSdoasks once more when the working counter is 0 and the drive queued no reason, which is this case and never a refusal. About fifteen lines, no cost on a read that succeeds, 20 ms more on one that is retried.ecx_SDOread. 4 in the same run. A stale message in SM1, source unknown; a read cannot be matched on its data the way a write can. Needs a capture of one instance.Nothing wrong is accepted in either case: the read fails and the caller sees it.
Decide after the capture from the reporter's PC (the one of #113, #115 and #119), which is the first measurement of a real slow host. If its log shows symptom 1, build the retry. If its capture holds symptom 2, read the frames. If neither appears, close this with no change.
[-]Find out why an Integro refused a mailbox write after SM0 read as empty[/-][+]Two rare read failures at 150 ms: a request never written, and a stale reply[/+]