ap: fix driver_name() silently caching wrong value on startup race
Path.resolve() doesn't raise on a nonexistent path — it just returns the syntactic path unchanged — so when driver_name() ran before the radio's netdev had enumerated (startup race with USB re-enum), it silently returned the literal string "driver" instead of None. The loop's retry guard (`if driver is None: retry`) never fired since "driver" is truthy, so the bogus value was cached for the service's entire uptime and the queue-flush wedge regex could never match real driver names — the 3rd check added 2026-08-19 was silently inert. Fixes 2026-08-23 recurrence where the 5GHz SSID went invisible and hostapd never got restarted. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YJfEELeh3ercpRBp8yYrYS
This commit is contained in:
co-authored by
Claude Sonnet 5
parent
db22cb50d6
commit
a99a39a859
+72
-12
@@ -8,16 +8,23 @@ exits and systemd restarts it (Restart=always, no start limit) until the interfa
|
|||||||
returns. This daemon is the backstop for the case systemd *can't* see: hostapd stays
|
returns. This daemon is the backstop for the case systemd *can't* see: hostapd stays
|
||||||
running but the radio has wedged and stopped serving (dmesg "timed out to flush queues").
|
running but the radio has wedged and stopped serving (dmesg "timed out to flush queues").
|
||||||
|
|
||||||
Every `interval` seconds it checks two things: hostapd's self-reported state via the
|
Every `interval` seconds it checks three things: hostapd's self-reported state via the
|
||||||
control socket (hostapd_cli status -> state=ENABLED), AND the kernel's ground truth for
|
control socket (hostapd_cli status -> state=ENABLED), the kernel's ground truth for the
|
||||||
the netdev (operstate up + still a port of the bridge). Both matter because they fail
|
netdev (operstate up + still a port of the bridge), and the kernel log for a TX-queue
|
||||||
independently: hostapd_cli keeps answering state=ENABLED off stale in-memory state after
|
wedge on this radio's driver (rtw88/rtw89 "timed out to flush queue(s)"). All three
|
||||||
the USB radio is torn down and re-enumerated underneath a still-running hostapd — the
|
matter because they fail independently: hostapd_cli keeps answering state=ENABLED off
|
||||||
netdev is recreated DOWN and dropped from the bridge, but hostapd never noticed and never
|
stale in-memory state after the USB radio is torn down and re-enumerated underneath a
|
||||||
exited, so Restart=always never fired. The link check catches exactly that. If the AP is
|
still-running hostapd — the netdev is recreated DOWN and dropped from the bridge, but
|
||||||
unhealthy for `fail_threshold` checks in a row, it clears any failed state and restarts
|
hostapd never noticed and never exited, so Restart=always never fired. The link check
|
||||||
hostapd. If the interface is simply gone (mid re-enumeration) it waits — there is
|
catches exactly that. Separately, the radio can wedge without any re-enumeration at
|
||||||
nothing to restart onto, and Restart=always reclaims it when it reappears. Stdlib only.
|
all: hostapd keeps reporting state=ENABLED and the netdev stays up/bridged throughout,
|
||||||
|
but the driver silently stops moving frames (2026-08-19: 5GHz AP unreachable for ~1.5h,
|
||||||
|
hostapd and link both reported healthy the whole time; dmesg showed
|
||||||
|
"rtw89_8852bu ...: timed out to flush queues" at the moment clients dropped). The
|
||||||
|
queue-flush check catches that. If the AP is unhealthy for `fail_threshold` checks in a
|
||||||
|
row, it clears any failed state and restarts hostapd. If the interface is simply gone
|
||||||
|
(mid re-enumeration) it waits — there is nothing to restart onto, and Restart=always
|
||||||
|
reclaims it when it reappears. Stdlib only.
|
||||||
|
|
||||||
Usage: van-ap-watchdog [hostapd.conf path] [systemd unit]
|
Usage: van-ap-watchdog [hostapd.conf path] [systemd unit]
|
||||||
Defaults watch the 5GHz AP (/etc/hostapd/hostapd.conf, unit hostapd); the 2.4GHz
|
Defaults watch the 5GHz AP (/etc/hostapd/hostapd.conf, unit hostapd); the 2.4GHz
|
||||||
@@ -28,6 +35,7 @@ import re
|
|||||||
import subprocess
|
import subprocess
|
||||||
import sys
|
import sys
|
||||||
import time
|
import time
|
||||||
|
from datetime import datetime
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
|
|
||||||
HOSTAPD_CONF = sys.argv[1] if len(sys.argv) > 1 else "/etc/hostapd/hostapd.conf"
|
HOSTAPD_CONF = sys.argv[1] if len(sys.argv) > 1 else "/etc/hostapd/hostapd.conf"
|
||||||
@@ -85,6 +93,47 @@ def link_healthy(ifname, bridge):
|
|||||||
return True
|
return True
|
||||||
|
|
||||||
|
|
||||||
|
def driver_name(ifname):
|
||||||
|
"""Kernel driver bound to the interface's USB device (e.g. rtw89_8852bu). Used to
|
||||||
|
scope the queue-flush-timeout check to this radio, so the 2.4GHz and 5GHz watchdog
|
||||||
|
instances don't trip on each other's dmesg lines.
|
||||||
|
|
||||||
|
Path.resolve() doesn't raise on a missing path — it just returns the syntactic
|
||||||
|
path unchanged — so if this runs before the interface has enumerated (e.g. right
|
||||||
|
at watchdog startup, mid USB re-enum) a naive .resolve().name silently returns the
|
||||||
|
literal string "driver" instead of None, and that bogus value gets cached forever
|
||||||
|
by the caller's `if driver is None: retry` check. Explicitly check existence first
|
||||||
|
so a not-yet-enumerated device correctly yields None and gets retried."""
|
||||||
|
p = Path(f"/sys/class/net/{ifname}/device/driver")
|
||||||
|
try:
|
||||||
|
if not p.exists():
|
||||||
|
return None
|
||||||
|
return p.resolve().name
|
||||||
|
except OSError:
|
||||||
|
return None
|
||||||
|
|
||||||
|
|
||||||
|
def queue_flush_wedged(driver, since):
|
||||||
|
"""True if this radio's driver logged a TX-queue-flush timeout since `since`. Both
|
||||||
|
rtw88 ("timed out to flush queue %d") and rtw89 ("timed out to flush queues") share
|
||||||
|
the substring "timed out to flush queue". This is the one signal that still catches
|
||||||
|
a wedge when hostapd_cli and the netdev both keep reporting healthy (see module
|
||||||
|
docstring, 2026-08-19 incident)."""
|
||||||
|
if not driver:
|
||||||
|
return False
|
||||||
|
pattern = rf"^{re.escape(driver)} .*timed out to flush queue"
|
||||||
|
try:
|
||||||
|
out = subprocess.run(
|
||||||
|
["journalctl", "-k", "--since", since.strftime("%Y-%m-%d %H:%M:%S"),
|
||||||
|
"-g", pattern, "-o", "cat", "--no-pager"],
|
||||||
|
capture_output=True, text=True, timeout=10,
|
||||||
|
).stdout
|
||||||
|
except (OSError, subprocess.SubprocessError) as e:
|
||||||
|
log(f"journalctl queue-flush check failed: {e}", "warn")
|
||||||
|
return False
|
||||||
|
return bool(out.strip())
|
||||||
|
|
||||||
|
|
||||||
def ap_enabled(ifname):
|
def ap_enabled(ifname):
|
||||||
"""True if hostapd reports the AP as beaconing (state=ENABLED). False if it's
|
"""True if hostapd reports the AP as beaconing (state=ENABLED). False if it's
|
||||||
running but not enabled; None if the control socket is unreachable (hostapd down)."""
|
running but not enabled; None if the control socket is unreachable (hostapd down)."""
|
||||||
@@ -120,13 +169,17 @@ def main():
|
|||||||
log("no interface= in hostapd.conf; nothing to watch", "crit")
|
log("no interface= in hostapd.conf; nothing to watch", "crit")
|
||||||
sys.exit(1)
|
sys.exit(1)
|
||||||
bridge = ap_bridge()
|
bridge = ap_bridge()
|
||||||
|
driver = driver_name(ifname)
|
||||||
log(f"van-ap-watchdog up: watching {ifname}"
|
log(f"van-ap-watchdog up: watching {ifname}"
|
||||||
f"{f' on {bridge}' if bridge else ''} every {INTERVAL}s "
|
f"{f' on {bridge}' if bridge else ''}"
|
||||||
|
f"{f' (driver {driver})' if driver else ''} every {INTERVAL}s "
|
||||||
f"(restart after {FAIL_THRESHOLD} bad checks)")
|
f"(restart after {FAIL_THRESHOLD} bad checks)")
|
||||||
|
|
||||||
bad = 0
|
bad = 0
|
||||||
waiting = False # latch so "interface absent" logs once, not every tick
|
waiting = False # latch so "interface absent" logs once, not every tick
|
||||||
|
last_check = datetime.now() # window start for the queue-flush dmesg check
|
||||||
while True:
|
while True:
|
||||||
|
now = datetime.now()
|
||||||
if not iface_present(ifname):
|
if not iface_present(ifname):
|
||||||
if not waiting:
|
if not waiting:
|
||||||
log(f"{ifname} absent — USB re-enumeration in progress; "
|
log(f"{ifname} absent — USB re-enumeration in progress; "
|
||||||
@@ -135,7 +188,13 @@ def main():
|
|||||||
bad = 0
|
bad = 0
|
||||||
else:
|
else:
|
||||||
waiting = False
|
waiting = False
|
||||||
if ap_enabled(ifname) and link_healthy(ifname, bridge):
|
if driver is None: # fill in late if the watchdog started before the device existed
|
||||||
|
driver = driver_name(ifname)
|
||||||
|
wedged = queue_flush_wedged(driver, last_check)
|
||||||
|
if wedged:
|
||||||
|
log(f"{ifname} ({driver}) logged a TX queue flush timeout — "
|
||||||
|
f"radio wedged despite healthy hostapd/link state", "warn")
|
||||||
|
if ap_enabled(ifname) and link_healthy(ifname, bridge) and not wedged:
|
||||||
if bad:
|
if bad:
|
||||||
log(f"AP {ifname} beaconing again")
|
log(f"AP {ifname} beaconing again")
|
||||||
bad = 0
|
bad = 0
|
||||||
@@ -144,6 +203,7 @@ def main():
|
|||||||
if bad >= FAIL_THRESHOLD:
|
if bad >= FAIL_THRESHOLD:
|
||||||
recover(ifname)
|
recover(ifname)
|
||||||
bad = 0
|
bad = 0
|
||||||
|
last_check = now
|
||||||
time.sleep(INTERVAL)
|
time.sleep(INTERVAL)
|
||||||
|
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user