Skip to content

init: recover from a stuck sensor, stop restart loops, and quiet the journal - #290

Open
alhasapi wants to merge 8 commits into
uunicorn:masterfrom
alhasapi:fix/init-recovery-and-log-flood
Open

alhasapi wants to merge 8 commits into
uunicorn:masterfrom
alhasapi:fix/init-recovery-and-log-flood

Conversation

@alhasapi

@alhasapi alhasapi commented Oct 9, 2026

Copy link
Copy Markdown

What this fixes

On a Lenovo 06cb:009a (Synaptics Metallica MIS) running Python 3.14, the daemon
can come up with an unresponsive sensor and then crash-loop forever while
flooding the journal:

init.open() -> open_common() -> init_flash() -> get_flash_info()
  -> tls.cmd('3e') -> usb.cmd() -> dev.write(1, out)
usb.core.USBTimeoutError: [Errno 110] Operation timed out

atexit.register(close) is only reached after a successful open_common(),
and close() is the only place that resets the USB device. So a failed init
never reset the sensor, and every systemd restart met the same stuck state.

Machine-generated evidence from the affected host (10 days):

metric value
Scheduled restart job 12,701
max systemd restart counter 5,075
starts on 2026-10-06 5,267
USBTimeoutError: [Errno 110] lines that day 10,530
journal pinned at the default 4 GiB ceiling
unit --debug only, no crash loop (2026-10-01) 113,639 lines / ~106 MiB

Changes (one commit per concern)

  1. flash: tolerate short/empty flash-info reply and never format an unknown IC
    A 0000-only 3e reply crashed unpack(). Return an empty FlashInfo,
    re-query once after reset_blob, and refuse to format if the flash IC is
    still unknown instead of guessing flash parameters.
  2. usb: retry transient 0x0104/0x0401 busy status during send_init
    Bounded cmd_retry_busy() for the busy statuses and USB timeouts; stop
    asserting on the init_hardcoded reply so the clean-slate fallback works.
  3. init: run send_init() before init_flash()
    The ordering that makes protected-flash commands time out on 06cb:009a.
  4. init: reset and re-open the sensor instead of crash-looping
    usb.reset()/usb.reopen() (re-discovery, so a re-enumerated device is
    found again) plus _open_with_recovery(): a bounded number of attempts with
    a hard reset/re-open in between. RebootException still propagates.
  5. dbus: re-acquire the USB device on Resume
    init.resume() re-opens the device and rebuilds state instead of reusing a
    stale post-suspend PyUSB handle.
  6. service: drop --debug default and throttle restarts
    Remove --debug, set Restart=on-failure, RestartSec=5, and bound the
    storm with StartLimitIntervalSec=300 / StartLimitBurst=5.

Relationship to existing work (nothing silently duplicated)

This is a consolidated PR that adopts and credits the open proposals and
adds the pieces none of them covered:

Happy to split or rebase any commit if you prefer a different grouping; they are
deliberately independent.

Testing

  • tests/ (new, pytest, no hardware required): 15 tests —
    full/short flash replies, refusing to format an unknown IC, busy/timeout
    retry bounds, non-timeout errors not retried, init ordering, bounded
    reset/re-open recovery, RebootException propagation, resume re-acquire,
    and the unit file (no --debug, throttled restarts).
  • python -m py_compile clean.
  • Hardware validation on the reporter's 06cb:009a (reboot + suspend/resume
    matrix) is in progress and will be posted here as a follow-up comment.

Marked draft until that hardware run is attached.

Notes

  • The repo has no CI; the tests run with python -m pytest and a local
    pytest.ini.
  • No behavior change for already-working sensors: the normal path is unchanged,
    recovery only engages after a failure.

…own IC

The 06cb:009a sensor replies to the '3e' (get_flash_info) command with only
the 2-byte status word (0000) and no 14-byte header/partition table while its
flash is uninitialized. get_flash_info() unconditionally unpacked the header
and crashed with struct.error, leaving the service in a restart loop.

Return an empty FlashInfo (no IC, no partitions) for short replies, and make
init_flash() re-query once after reset_blob. If the flash IC is still unknown,
refuse to format instead of guessing flash parameters (size/sector size/erase
command), which could corrupt the sensor flash.

Builds on the analysis and patch in uunicorn#272 and the
short-reply handling in uunicorn#273/uunicorn#245.

Tests: tests/test_flash_info.py (no hardware required).
After a wake-up or reset the 06cb:009a sensor answers the first command(s)
with a transient busy status, which assert_status() treated as a fatal error.
Add cmd_retry_busy(), a bounded retry helper that also retries USB timeout
errors, and use it for RomInfo.get() and get_fw_info() in send_init().

Stop asserting on the init_hardcoded response: a non-zero status there means
'firmware not loaded yet', which the following 4302 check already handles,
so asserting made the clean-slate fallback unreachable (as analysed in uunicorn#272
and fixed in uunicorn#245/uunicorn#273).

Tests: tests/test_usb_retry.py.
On 06cb:009a the protected-flash commands issued by init_flash() time out
when the hardcoded init/firmware blobs from send_init() have not been loaded
first. Reordering the sequence fixes initialization on that hardware (as
tested in uunicorn#272).
When the sensor stops answering, init() raised USBTimeoutError after the 15s
USB timeout. atexit.register(close) is only reached after a successful
open_common(), so the only code that resets the USB device (usb.close()) never
ran; systemd restarted the service straight back into the same stuck state.
On this machine that produced 12,701 restarts and a multi-GB journal.

Add usb.reset()/usb.reopen() (re-discovery, so a re-enumerated device is
found again) and wrap open()/open_devpath() in _open_with_recovery(), which
retries a bounded number of times, resetting and re-opening the device in
between. RebootException (normal post-format reboot) is still propagated.
atexit registration is now idempotent.

Tests: tests/test_init_recovery.py.
Resume() called init.open_common(), which skips usb.open() and reuses the
pre-suspend PyUSB handle. After a resume the kernel has reset/re-enumerated
the device, so operations failed with 'USBError: [Errno 19] No such device'
and the service stayed up but unusable.

Add init.resume(), which resets TLS state, re-acquires the device (usb.reopen()
with a fallback to usb.open()) and re-runs the bounded init recovery. This is
the targeted change discussed in uunicorn#249/uunicorn#285 without the extra systemd unit.

Tests: tests/test_resume.py.
The packaged unit started dbus-service with --debug, which enables DEBUG-level
hex dumps of every USB/TLS command. On 2026-10-01 the unit had only 2 starts
yet wrote 113,639 journal lines (~106 MiB), and it also dumped raw key
material. Debug tracing stays available via an explicit override.

Set Restart=on-failure with RestartSec=5 and bound the restart storm with
StartLimitIntervalSec=300 / StartLimitBurst=5. Previously the unit relied on
Restart=no (which Arch patches to on-failure without a delay); with a 15s
per-attempt init and the default StartLimitBurst=5/10s, the limit never
tripped no matter how many times the service failed.

Tests: tests/test_service_unit.py.
@alhasapi

alhasapi commented Oct 9, 2026

Copy link
Copy Markdown
Author

Test run on the PR branch (no hardware):

tests/test_flash_info.py::test_get_flash_info_parses_full_reply PASSED   [  6%]
tests/test_flash_info.py::test_get_flash_info_short_reply_returns_empty_flashinfo PASSED [ 13%]
tests/test_flash_info.py::test_init_flash_refuses_to_format_without_identified_ic PASSED [ 20%]
tests/test_init_recovery.py::test_open_with_recovery_resets_and_retries PASSED [ 26%]
tests/test_init_recovery.py::test_open_with_recovery_gives_up_bounded PASSED [ 33%]
tests/test_init_recovery.py::test_reboot_exception_is_not_retried PASSED [ 40%]
tests/test_init_recovery.py::test_open_common_loads_firmware_before_flash PASSED [ 46%]
tests/test_resume.py::test_resume_reopens_usb_and_reinitializes PASSED   [ 53%]
tests/test_resume.py::test_resume_falls_back_to_fresh_open PASSED        [ 60%]
tests/test_service_unit.py::test_debug_is_not_enabled_by_default PASSED  [ 66%]
tests/test_service_unit.py::test_restart_is_throttled PASSED             [ 73%]
tests/test_usb_retry.py::test_retries_transient_busy_status PASSED       [ 80%]
tests/test_usb_retry.py::test_retries_transient_usb_timeout PASSED       [ 86%]
tests/test_usb_retry.py::test_non_timeout_usb_error_is_not_retried PASSED [ 93%]
tests/test_usb_retry.py::test_bounded_when_sensor_stays_busy PASSED      [100%]
============================== 15 passed in 0.25s ==============================

Commit range:

bcddb69 service: drop --debug default and throttle restarts
7bebaab dbus: re-acquire the USB device on Resume
5ee8b4f init: reset and re-open the sensor instead of crash-looping
ce41c1a init: run send_init() before init_flash()
6bc143f usb: retry transient 0x0104/0x0401 busy status during send_init
4c0e245 flash: tolerate short/empty flash-info reply and never format an unknown IC

@alhasapi

alhasapi commented Oct 9, 2026

Copy link
Copy Markdown
Author

Local validation (part 1) — applied on the reporting machine

06cb:009a, Arch/Omarchy, Python 3.14.7, pyusb 1.3.1, libusb 1.0.30.
Patched build installed over 0.15 via a local AUR overlay carrying this exact
diff; journald capped at 500 MiB.

Before (from the journal): 12,701 scheduled restarts, max counter 5,075,
5,267 starts on 2026-10-06, 10,530 USBTimeoutError [Errno 110] lines that day,
journal pinned at 4.1 GiB.

After install:

  • NRestarts=0, ActiveState=active through the whole run.
  • 10x net.reactivated.Fprint.Manager.Resume (exercises the new
    init.resume() re-acquire path) and 2x systemctl restart python3-validity (exercises cold init.open()): NRestarts=0 every time,
    no init tracebacks, fprintd-list still lists all 4 enrolled prints.
  • Patched unit output since start: 96 lines / 9.9 KB, 0 init tracebacks;
    the only 7 DEBUG:root lines are the old process shutting down.
  • journalctl --disk-usage → 477.3 MiB (from 4.1 GiB).
resume 1..10: NRestarts=0 active=active OK
restart 1:    NRestarts=0 active=active
restart 2:    NRestarts=0 active=active

Still to do before this comes out of draft: 2 full reboots and >=10 real
suspend/resume cycles with a verification after each. The 10 simulated resumes

  • 2 restarts cover the code paths, but not real USB re-enumeration.

close() only caught RebootException, so a USB error in reboot() (the device is
often already reset/gone during shutdown or suspend) produced an
"Exception ignored in atexit callback" traceback on every stop. Log it at
debug level instead; the USB close still runs in finally.

Tests: tests/test_init_recovery.py.
A cancelled verify (or one that times out waiting for a finger) raised
CancelledException, fell into the generic handler and logged a full chained
traceback containing the 30s USBTimeoutError. This is normal operation and was
a large part of the journal volume. Handle CancelledException and USBError
explicitly with a single log line and keep the existing status callbacks.

Tests: the verify/enroll paths are DBus-bound; behaviour is covered by the
hardware suspend/resume matrix rather than unit tests.
@alhasapi

alhasapi commented Oct 9, 2026

Copy link
Copy Markdown
Author

Two more commits added, plus a fuller local suspend/resume run.

Added commits

  • init: never print a traceback from the atexit reboot handler — close()
    only caught RebootException, so a USB error in reboot() (the device is
    usually already reset/gone during shutdown or suspend) produced
    Exception ignored in atexit callback on every stop.
  • dbus: log expected verify/enroll cancel and timeout without a traceback —
    a cancelled verify (or one timing out waiting for a finger) raised
    CancelledException, hit the generic handler and logged a full chained
    traceback containing the 30s USBTimeoutError. That was a large share of the
    journal volume. Now handled explicitly with a single log line; status
    callbacks unchanged. 17 unit tests total.

Real suspend/resume matrix (no longer simulated)

On the same 06cb:009a host, with the old python3-validity-suspend-hotfix
restart disabled so the new in-process path is exercised:

  • 14 real suspend/resume cycles (kernel PM: suspend entry (deep) /
    PM: suspend exit confirmed for each).
  • open-fprintd-resume.service calls Manager.Resume() -> python-validity
    Device.Resume() -> init.resume(); the sensor re-initializes in the same
    process (Opening sensor: 57K0 FM-3367-001 after every resume).
  • Same PIDs before/after every cycle (no restart), NRestarts=0 throughout,
    0 init tracebacks, fprintd-list returns all 4 enrolled prints immediately
    after wake.
  • journalctl --disk-usage = 432 MiB (from 4.1 GiB).

Remaining before un-drafting: 2 full reboots. A reboot ends the agent session,
so those are being done by the machine owner and the results will be posted.

@alhasapi

alhasapi commented Oct 9, 2026

Copy link
Copy Markdown
Author

Final hardware validation — pulling out of draft

Two full reboots and 14 real suspend/resume cycles on the affected
06cb:009a machine. Everything below is machine-generated.

Reboods (2/2)

boot id NRestarts services init errors DEBUG dumps prints
316dddc6… 0 active/active 0 0 4
c4977e89… 0 active/active 0 0 4

Suspend/resume (14/14)

  • Each cycle confirmed by kernel PM: suspend entry (deep) / PM: suspend exit.
  • open-fprintd-resume.service → Manager.Resume() → Device.Resume() →
    init.resume(); the daemon re-initializes in the same PID
    (Opening sensor: 57K0 FM-3367-001 after every wake).
  • Same PIDs before/after every cycle, NRestarts=0, 0 init tracebacks,
    all fingerprints listed immediately after wake.
  • The old python3-validity-suspend-hotfix restart unit is disabled; the
    in-process path replaces it (and removes the ~2 s lock-screen race it caused).

Journal volume

  • journalctl --disk-usage: 452 MiB (was 4.1 GiB; capped at 500 MiB).
  • Projected after fix: ~2,731 lines/day, i.e. -97.6% vs the
    debug-only day (113,639 lines) and -98.9% vs the worst crash-loop day
    (258,073 lines).

With the two extra commits (atexit hardening + expected cancel/timeout logging),
that is 8 commits and 17 unit tests.

@alhasapi
alhasapi marked this pull request as ready for review October 9, 2026 09:13
@alhasapi

alhasapi commented Oct 9, 2026

Copy link
Copy Markdown
Author

A ready-to-test overlay with this exact patch, the Arch packaging to apply it,
and the raw validation evidence is now public:

https://github.com/alhasapi/python-validity-fix

  • patch/fix.patch — the combined diff (same as this PR's branch)
  • aur/ — PKGBUILD overlay that applies it to 0.15
  • local/ — install/validate scripts + systemd/journald drop-ins
  • docs/ — reboot and 14x suspend/resume evidence, journal-volume numbers

Useful if you want to reproduce the hardware validation without assembling the
patch by hand.

@medden

medden commented Oct 24, 2026

Copy link
Copy Markdown

Tested on hardware: ThinkPad T480, Synaptics 06cb:009a. This fixes the Failed: 0401 init failure.

System

  • Arch Linux (Omarchy 4.0.6), kernel 7.2.8
  • python 3.14.8, libusb 1.0.30, python-pyusb 1.3.1
  • open-fprintd 0.7, fprintd-clients-git 1.90.1
  • BIOS N24ET76W (1.51); sensor reports 57K0 FM-3367-001, FWExt 1.2

Before (AUR python-validity 0.15, unpatched)

  • dbus-service crash-looped. The first 3e command returned 0104, so get_flash_info() raised Exception: Failed: 0401. After a few restarts it hit USBTimeoutError.
  • factory-reset.py also failed with Failed: 0401. A BIOS "Reset Fingerprint Data" plus a full power-off didn't change anything.

After (0.15 + this PR, applied with git apply --exclude='debian/*' --exclude='tests/*' --exclude=pytest.ini)

  • First start: Clean slate, then No firmware detected. Uploading..., then Loaded FWExt version 1.2. The service exited, as expected after the firmware upload.
  • Second start: Flash has 5 partitions, Opening sensor: 57K0 FM-3367-001, then calibration. fprintd-list sees the device.
  • fprintd-enroll gave enroll-completed. fprintd-verify gave verify-match 4 out of 4 times.
  • pam_fprintd works for sudo (3 out of 3).
  • I haven't tested suspend/resume with the patched driver yet. I'll follow up here once I have.

The service file changes didn't apply to the AUR package's unit, so I applied them with sed in the PKGBUILD (drop --debug, add RestartSec=5, StartLimitIntervalSec=300, StartLimitBurst=5).

Thanks for this, and for the root cause in #272. It would be great to see it merged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants