Captures stall ~37 s on alternate frames — reproduces in the gphoto2 CLI, so it is not our code

[cmtunderbird]

The number

Measured on scanner-node-0, 12 Aug 2026, ~23:00 EEST, immediately after a battery exchange.

POST /capture, back to back, nothing in between:
  1 -> 200 in  1.85s
  2 -> 200 in 37.32s
  3 -> 200 in 37.38s

Flat at ~37 s, not growing — so this is a fixed timeout being waited out, not something accumulating.

At 1.8 s a frame a 300-page book is ~15 minutes of capture per camera. At 37 s it is five hours. This is a throughput-fatal defect, not a nuisance.

It is also new. This afternoon ten consecutive captures ran at ~1.8 s each; three ran at 1.7 s at 22:37. The change is tonight, and the only physical event between the two is the battery going flat and being swapped.

It is not our code

Same method that exonerated the node during the DMF fault: stop the service and go to the CLI.

Three frames in one gphoto2 process (session stays open — the opposite of our session_per_capture):

Saving file as /tmp/multi_1.arw
ERROR: Could not capture image.
ERROR: Could not capture.
Saving file as /tmp/multi_2.arw
  three frames, one session: 39.05s

Three separate gphoto2 processes (session per capture, like the node):

  separate capture 1: 38.43s
  separate capture 2:  2.26s

So it reproduces with our service stopped, under both session strategies, and one capture in two fails outright with Could not capture image before a retry succeeds. The node's capture_with_retry is the only reason this surfaces as a slow 200 rather than a 503 — which is worth saying plainly: our recovery is currently hiding the fault and reporting success. A run would look healthy at a fifth of the throughput.

What it is not

Ruled out by measurement, not by argument:

• Not our session strategy. One-session and session-per-capture stall identically.
• Not the body's mode settings. Checked after the swap: focusmode: Manual, capturemode: Single Shot, expprogram: M. The DMF fault from earlier tonight is genuinely fixed and is not this. (This was my first hypothesis — that _enforce_capture_prerequisites() runs in connect() but not on the reconnect() path a battery swap takes, so a reset body would come back in DMF unnoticed. The gap in the code is real and worth closing regardless, but it is not the cause here, because the body is in Manual.)
• Not files accumulating on the camera. gphoto2 --list-files → There is no file in folder '/'.
• Not USB autosuspend. The udev rule pins power/control=on, and usb_resets stayed at 1 throughout.
• Not the /status polling in the test harness — removing it changed nothing.

The leading hypothesis

The body's volatile buffer, which is the hazard PR #9's duplicate guard was built against, showing up as a throughput failure instead of a correctness one. libgphoto2's own source predicts the mechanism:

"It may even accumulate so we will get images from history. Camera on-off does not delete RAM. Just USB reconnection helps."

The alternating fast/slow pattern fits: a capture leaves something in body RAM, the next capture collides with it and waits out a timeout that clears it, the one after is clean.

This is testable and untested. If it is right, usb_reset() should restore the fast path, and the alternation should resume from there. That is the next measurement, and it decides everything: if a re-enumeration fixes it we have a workaround we already own; if it does not, the cause is elsewhere.

Worth checking in the same sitting

• Whether a cold body power cycle (not just a USB reset) clears it — the state was introduced by a power event, so it may be clearable by one.
• Whether the ~37 s matches a specific libgphoto2 timeout constant, which would name the wait exactly rather than by its duration.
• Whether it survives a reboot of the Pi. If it does, the state lives in the body.

Related

• The retry that masks this is eadefca; the duplicate guard that anticipated the mechanism is 4440db8. Both in Survive the cable, the power cycle and the battery swap #9.
• /meter reads the embedded JPEG preview — a tone curve, white balance and picture profile, not light #12 (/meter on raw_image_visible) is unaffected.
• Nothing optical has been measured yet and the lens cap is still on, so this blocks nothing physical — but it must be understood before any throughput claim in the blueprint is trusted, and docs/throughput-measured is a branch name that now carries a question mark.

[cmtunderbird]

The volatile-buffer hypothesis is dead, and the debug log names the loop

A USB re-enumeration changes nothing

Controlled run on scanner-node-0. Same service, same session policy, nothing between the phases but the reset:

### PHASE A -- baseline, four back-to-back captures
    seq 951 -> HTTP 200 in   2.03s
    seq 952 -> HTTP 200 in  37.31s
    seq 953 -> HTTP 200 in  37.39s
    seq 954 -> HTTP 200 in  37.31s
    reopens: 7

### PHASE B -- external USB re-enumeration
RESET bus 003 dev 005
devices reset: 1

### PHASE C -- four more, same everything
    seq 961 -> HTTP 200 in  44.92s
    seq 962 -> HTTP 200 in  37.37s
    seq 963 -> HTTP 200 in  37.29s
    seq 964 -> HTTP 200 in  37.29s
    reopens: 14

Phase C is Phase A. So the hypothesis in the issue body — the body's volatile buffer, "just USB reconnection helps" — is falsified. Recording that rather than quietly editing it: it was a reasonable guess from libgphoto2's own source and it was wrong.

reopens is the useful secondary number: 7 for four captures, 14 for eight. One reopen for the fast capture, two for each slow one — a failed attempt, a recover(), and a retry that succeeds. That is capture_with_retry converting a hard failure into a slow success, which is the monitoring defect noted in the issue body and is now confirmed rather than inferred.

Note also that only a process restart buys a fast capture, and only ever one. A device-level reset does not.

What the body is actually doing for 35 seconds

gphoto2 --debug on two frames in one process, 229 MB of trace:

Capturing frame #1/2...
New file is in location /capt0000.arw on the camera
Saving file as /tmp/d_1.arw
Deleting file /capt0000.arw on the camera
Capturing frame #2/2...
ERROR: Could not capture image.
ERROR: Could not capture.

Elapsed 23:22:27.84 → 23:23:08.65 = 40.81 s.

Scanning the trace for stalls: zero gaps longer than 2 s. There is no blocking wait. It is a poll loop, turning over roughly every 0.5 s from ~5 s to ~40.8 s:

37.836915 gp_port_set_timeout (2): Setting port timeout to 150 milliseconds.
38.137237 gp_port_set_timeout (2): Setting port timeout to 20000 milliseconds.
38.239559 gp_port_get_timeout (2): Current port timeout is 20000 milliseconds.
38.239561 gp_port_set_timeout (2): Setting port timeout to 150 milliseconds.
...

That is the Sony driver's wait-for-object loop, spinning until its budget runs out. The body is never signalling that a frame was taken. The capture command is accepted; the object-added event never arrives.

The leading hypothesis now, and it is one we already wrote down

recover()'s give-up message, added in 4440db8, says:

If captures fail while reads succeed, check the card is seated: a cardless body answers config queries and then times out on the shutter.

Reads succeed. Config queries succeed. --list-files answers. The shutter times out. That is the cardless signature as this repo already documented it.

And there is a mechanism for why it would appear tonight and not this afternoon: on the ILCE-6000 the battery and the SD card share a single compartment. The door was opened ~20 minutes before the first slow capture, to change a flat battery. A card knocked loose, or re-seated without clicking home, fits every observation:

• first capture after a process start succeeds — one frame's worth of buffer
• every subsequent capture waits out the object-added timeout
• a USB reset does not help, because the fault is not on the bus
• the gphoto2 CLI behaves identically, because it is not a software fault at all

Untested at the time of writing; the card has not yet been reseated. If reseating fixes it, the interesting defect is not the camera — it is that the node had this exact diagnosis in a string and no way to surface it at the right moment. A 37 s capture that returns 200 gives an operator nothing to search for. That is the part worth fixing here regardless of what the card turns out to be doing.

[cmtunderbird]

Reseating the card did not fix it — but the body reports no storage at all

Six captures after the card was pulled and pushed back in, service restarted first:

    seq 971 -> HTTP 200 in   2.06s
    seq 972 -> HTTP 200 in  37.13s
    seq 973 -> HTTP 200 in  37.36s
    seq 974 -> HTTP 200 in  37.44s
    seq 975 -> HTTP 200 in  37.38s
    seq 976 -> HTTP 200 in  37.34s
    reopens: 11

Unchanged. So the reseat hypothesis is falsified as stated — that is now two of my hypotheses dead in this issue.

But the component was right. With the service stopped:

$ gphoto2 --storage-info
(no output)

Nothing. Not an error, not a store with zero free bytes — the body enumerates no storage whatsoever. A body with a working card prints a store description with capacity and free space here. This is consistent with the earlier gphoto2 --list-files → There is no file in folder '/', which I had read as "no accumulated frames" and which in fact says something much stronger.

So the reading is: the card is present in the slot but the body is not seeing usable storage. Reseating cured the contact if contact was ever the fault; it did not cure this. Candidates, in the order they are cheap to test:

1. The camera's own screen. If it shows No Card, this is settled in two seconds and the rest of this comment is unnecessary.
2. The card filled up. ~256 frames were taken tonight (DSC01067 → DSC01323), each a 24,513,792-byte ARW — roughly 6.3 GB. On an 8 GB card that is full, and full arrived at about the hour the stalls started. A full store may enumerate oddly rather than reporting zero free.
3. The card failed, or was damaged by the door opening under power.

Why this matches the symptom exactly

The repo established the mechanism days ago, in recover()'s give-up string:

a cardless body answers config queries and then times out on the shutter

Every observation fits: config reads succeed, --summary succeeds, the shutter is accepted and never signals an object-added event, the driver polls for ~35 s and gives up, and one capture per process start succeeds because there is a frame's worth of buffer ahead of the store.

The engineering lesson, which is not about the card

This node spent an evening reporting HTTP 200 and connected: true while the body had no storage. /status publishes staged_frames, frames_evicted, session_reopens, usb_resets and staging_free_mb — every one of them about our disk. It publishes nothing at all about the camera's.

gphoto2 --storage-info is one PTP call. It should be part of connect(), surfaced in /status, and asserted in check-node.sh. A body with no store cannot scan a book, and that is knowable at connect rather than 37 seconds at a time.

Filing that as the concrete change this issue produces, whatever the card turns out to be doing.