diff --git a/CLAUDE.md b/CLAUDE.md index 268c4ad..db2dbf3 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -22,6 +22,7 @@ Reasoning belongs in `docs/`. | `docs/pin-allocation.md` | Which sensor is on which expander pin, and why allocation is not installation | | `docs/block-detector-wiring.md` | The LM-iD output stage: its two modes, why Input A is unpowered, the 3.3 V hazard if it is not | | `docs/point-position-feedback.md` | Board 3 (`0x22`): why two inputs per point, the `0x22` allocation, and why command and feedback being different devices is the hazard. **Not built** | +| `docs/startup-and-status-led.md` | The power-on race with the modem, the retry-then-reset policy, and **what the LED flash codes mean** | | `docs/DEVELOPMENT_NOTES.md` | Module conventions, the MCP23017 pin map, hardware wiring | | `docs/PN7150_STATE_MACHINE_PLAN.md` | The NCI state machine the RFID reader implements | | `docs/MQTT_AT_COMMANDS.md` | The ESP-AT command set the transport speaks | @@ -113,8 +114,11 @@ publish contract readings that the orchestrator trusts, and the block follows th ``` src/lib/ -> device /lib mqtt_at.py ESP-AT transport. Length-aware frames, reconnect, failures returned. + Waits for the modem to answer before commanding it. layout_mqtt.py The contract: topics, payloads, QoS, retention, the 25 s re-assert. sensor_wiring.py Allocation vs installed, and the occupancy polarity. No `machine`. + node_startup.py Retry-then-reset startup policy, and the LED code table. No `machine`. + status_led.py The onboard LED as a countable flash code. No `machine`. mcp23017_io.py I2C expander, in and out. Poll-only. input_pin_monitor.py Native Pico GPIO, IRQ + timer debounce. Currently unused. pcf8591_adc.py I2C ADC. Wired to nothing; no contract topic for analog yet. @@ -151,6 +155,11 @@ directory on the path for the same reason. ### Traps +- **A node that cannot start flashes a code and reboots — it no longer dies quietly.** + Solid LED is running, `N` flashes is a failure at stage `N`, dark is no power or a hard + crash. Codes and the retry policy are in `docs/startup-and-status-led.md`. Until 2026-08-27 + a modem still booting when the Pico reached `AT+RST` killed the node outright, with the LED + never lighting — the intermittent "doesn't come up after a power cycle". - **A point is commanded and read by two devices that know nothing about each other.** The Cobalt takes DCC accessory commands and can report nothing; position comes only from its `S2` contacts on board 3. So `points.dcc_address` (orchestrator) and `pointId` → pins (here) diff --git a/docs/startup-and-status-led.md b/docs/startup-and-status-led.md new file mode 100644 index 0000000..76125de --- /dev/null +++ b/docs/startup-and-status-led.md @@ -0,0 +1,112 @@ +# Node startup, and what the LED is telling you + +## The fault this is about + +The IO node did not always come up after a power cycle. When it failed it failed +completely and silently: the onboard LED never lit, nothing appeared on the broker, and +the board sat at a REPL until someone power-cycled it again. The orchestrator behaved +correctly — the Goods Shed sensors went stale, the block degraded to `unknown`, and the +fail-safe rule treated that as occupied — but nothing anywhere pointed at the node. + +That is the failure this repo rates worst. The node stopped reporting and said nothing. + +## Root cause: the Pico wins the power-on race + +The Pico and the ESP-AT modem come out of a power cycle together, and the Pico is much +faster. Measured on the bench, 2026-08-27: + +| Event | Time from power-on | +|---|---| +| Pico reaches its first AT command | ~300 ms (MicroPython's boot, plus **19 ms** of I2C and expander setup) | +| Modem reaches `ready` | **1.2 s – 3.5 s** | + +Both ends of the modem's spread were measured in the same session: one reset reached +`ready` at 3471 ms, another at 1232 ms. The variance is Ethernet link negotiation — +`+ETH_CONNECTED` came at 3460 ms and 1221 ms respectively. + +`MQTTATClient.setup()` opened by sending `AT+RST` and waiting on the constructor's +2000 ms default. So the deadline for a reply fell about 2.3 s after power-on, while the +modem became ready somewhere between 1.2 s and 3.5 s. **Sometimes it made it, sometimes +it did not** — which is exactly the reported "doesn't always start". + +A command sent into that window is not refused. It is swallowed whole: no echo, no +reply. Reproduced deterministically by commanding the modem mid-boot: + +``` +STEP 3 - the cold-boot race: command the modem while it is still booting. + modem is now rebooting; waiting 200 ms then sending AT+RST as setup() does + -> OK within setup()'s 2000 ms default? NO -> RuntimeError('AT+RST failed') +``` + +The exception propagated out of `main()`, which was called bare at module scope, so +`main.py` simply ended. + +## Fix 1: ask before commanding + +`MQTTATClient.wait_for_modem()` polls a bare `AT` until the modem answers, for up to +15 s, before anything else is sent. Only then does `AT+RST` go out. A modem that never +answers now raises `ModemNotResponding` rather than looking like a failed reset. + +A related blind spot was closed at the same time: `wait_for_line()` only inspects lines +recorded *after* it is called, so an `+ETH_GOT_IP` arriving in the same read as the +reset's own `OK` would have been missed, and `setup()` would have sat out its full 30 s +and then raised as though the network were down. `setup()` now checks what has already +arrived before it starts waiting. + +## Fix 2: a node that cannot start must not fall silent + +`node_startup.start_supervised()` retries startup three times — flashing for 2 s, 5 s +and 10 s between attempts — and then resets the board, which starts the cycle again. +It never returns without a running node. + +The first retry alone covers the fault above: the modem needs at most 3.5 s from cold +and `wait_for_modem()` now waits for it, so anything still failing on the second attempt +is a real fault rather than the power-on race. + +A crash in the *main loop* is treated the same way, for the same reason — it is equally +a node that stopped reporting without saying so. + +Retrying a wiring fault forever is deliberate. An expander missing at boot is usually a +loose ribbon cable, not a permanent fact, and a board that keeps trying and keeps +flashing is easier to find than one that is simply dark. + +## The flash codes + +| LED | Meaning | +|---|---| +| **Solid on** | Running: sensors configured, broker link up | +| **Off** | No power, or a hard crash that took the board out | +| **N flashes, pause, repeat** | Startup failed at stage N — retrying, then resetting | + +| Code | Stage | What it means | Where to look | +|---|---|---|---| +| **2** | Sensors | A configured expander is not on the I2C bus | Ribbon to boards 1/2, `config.py` addresses | +| **3** | Modem | The ESP-AT modem is not answering AT commands | UART wiring GP8/GP9, modem power | +| **4** | Network | The modem answers, but never reported an IP | Ethernet cable, DHCP, switch port | +| **5** | Broker | Network is up, the MQTT link could not be made | Mosquitto on the bench box, `MQTT_HOST` | +| **6** | Runtime | The node came up, then the main loop crashed | USB console — this one is a bug, not wiring | +| **7** | Unknown | Something else | USB console | + +Codes start at 2 on purpose. A single flash is too easily confused with a board merely +blinking on boot, and a miscounted code is worse than no code. + +The pattern is 200 ms on, 250 ms between flashes, and a 1400 ms gap before the cycle +repeats. The gap is deliberately much longer than the space between flashes — otherwise +a 2 reads as a 4. A cycle is always completed once started, so a code is never cut off +half way through. + +## Reading a code + +Count the flashes between the long gaps. Then plug the USB lead in and look at the +console — every failure prints the exception and the code it chose before it flashes. + +## What is covered by the host suite, and what is not + +`tests/test_mqtt_setup.py`, `tests/test_node_startup.py` and `tests/test_status_led.py` +prove the probe, the retry-then-reset policy, the code mapping, and the flash pattern +against a scripted modem, with no hardware attached. + +What the host suite cannot prove is that the LED pin actually lights and that the +modem's real boot timing stays inside the 15 s budget. Both were checked on the bench — +see the timings above, and `scripts/` has no permanent home for the diagnostic, which +lived in the scratchpad. diff --git a/src/apps/io-node/main.py b/src/apps/io-node/main.py index 28c7050..8e424f5 100644 --- a/src/apps/io-node/main.py +++ b/src/apps/io-node/main.py @@ -2,19 +2,31 @@ Deployed as the board's `/main.py`, with `src/lib/*` in `/lib`. All wiring and identity lives in `config.py`; this file only assembles it and runs the loop. + +Startup is supervised (`node_startup.py`): a failure on the way up is flashed on the +onboard LED, retried, and eventually met with a board reset, rather than dropping to a +REPL that nobody is watching. """ -from machine import I2C, Pin +from machine import I2C, Pin, reset from utime import sleep_ms, ticks_ms from layout_mqtt import LayoutMQTT from mcp23017_io import MCP23017Expander from mqtt_at import MQTTATClient +from node_startup import CODE_RUNTIME, SensorWiringError, start_supervised from sensor_wiring import is_occupied, select_installed +from status_led import StatusLED import config +# How long to flash the runtime code before rebooting after a crash in the main loop. +# Long enough to be seen and counted, short enough that the node is not off the air for +# any longer than the diagnosis needs. +RUNTIME_CRASH_FLASH_MS = 5000 + + def build_sensors(i2c, wiring): """Configure one input pin per installed sensor, sharing an expander per address. @@ -29,7 +41,7 @@ def build_sensors(i2c, wiring): for entry in wiring: address = entry["expander"] if address not in available: - raise RuntimeError( + raise SensorWiringError( "expander 0x%02X not on the bus (found %s) — %s cannot be published" % (address, [hex(a) for a in available], entry["sensor_id"])) @@ -44,9 +56,12 @@ def build_sensors(i2c, wiring): return sensors -def main(): - led = Pin("LED", Pin.OUT) +def bring_up(): + """One complete startup attempt, from a clean slate. + Everything that can fail on the way up lives in here so a retry starts over rather + than resuming from whatever half-configured state the last failure left behind. + """ # Resolve and validate the wiring before touching the modem, so a config mistake # fails immediately and obviously rather than as silence on the broker. wiring = select_installed(config.SENSORS, config.INSTALLED) @@ -62,7 +77,12 @@ def main(): rx_pin=config.MQTT_RX_PIN, baud=config.MQTT_BAUD, client_id=config.MQTT_CLIENT_ID, ) - client.setup() + try: + client.setup() + except Exception: + # Hand the UART back before the next attempt tries to claim the same pins. + client.close() + raise layout = LayoutMQTT( client, config.LAYOUT_ID, @@ -78,30 +98,54 @@ def main(): for sensor_id, pin in sensors: layout.publish_sensor(sensor_id, is_occupied(pin.state, config.ACTIVE_LOW), now) - led.on() - print("io-node: running") + return sensors, layout, client - try: - while True: - now = ticks_ms() - for sensor_id, pin in sensors: - if pin.update_state(): - layout.publish_sensor( - sensor_id, is_occupied(pin.state, config.ACTIVE_LOW), now) +def run(sensors, layout, client): + """The main loop. Returns only on KeyboardInterrupt.""" + while True: + now = ticks_ms() + + for sensor_id, pin in sensors: + if pin.update_state(): + layout.publish_sensor( + sensor_id, is_occupied(pin.state, config.ACTIVE_LOW), now) - # Re-assert anything that has gone quiet, and retry anything that failed. - # Without this every block these sensors feed degrades to `unknown` within - # the backend's freshness window, and `unknown` is treated as occupied. - layout.tick(now) + # Re-assert anything that has gone quiet, and retry anything that failed. + # Without this every block these sensors feed degrades to `unknown` within + # the backend's freshness window, and `unknown` is treated as occupied. + layout.tick(now) - client.poll() - sleep_ms(config.LOOP_SLEEP_MS) + client.poll() + sleep_ms(config.LOOP_SLEEP_MS) + +def main(): + led = StatusLED(Pin("LED", Pin.OUT)) + led.off() + + def report(exc, code, attempt, delay_ms): + print("io-node: startup attempt %d failed — %s: %s" % (attempt, type(exc).__name__, exc)) + print("io-node: flashing code %d for %d ms, then retrying" % (code, delay_ms)) + led.flash(code, delay_ms) + + sensors, layout, client = start_supervised(bring_up, report, reset) + + led.on() + print("io-node: running") + + try: + run(sensors, layout, client) except KeyboardInterrupt: print("io-node: interrupted") - finally: led.off() + except Exception as exc: + # A crash in the loop is the same failure as a crash on the way up: the node + # stops reporting and says nothing about it. Flash it, then come back from cold + # rather than falling out to a REPL nobody is watching. + print("io-node: run loop crashed — %s: %s" % (type(exc).__name__, exc)) + led.flash(CODE_RUNTIME, RUNTIME_CRASH_FLASH_MS) + reset() main() diff --git a/src/lib/mqtt_at.py b/src/lib/mqtt_at.py index f7e650d..276fcc9 100644 --- a/src/lib/mqtt_at.py +++ b/src/lib/mqtt_at.py @@ -78,6 +78,34 @@ def _sleep_ms(ms): RECONNECT_BACKOFF_MS = 5000 +# How long to wait for the modem to start answering at all, and how long each probe +# gets. See `wait_for_modem()` for why asking first is not optional. +MODEM_READY_TIMEOUT_MS = 15000 +MODEM_PROBE_INTERVAL_MS = 500 + + +# --- startup failures ------------------------------------------------------ +# +# These subclass `RuntimeError`, which is what `setup()` used to raise and what any +# existing caller already catches. The subclasses exist so a supervisor can tell *which* +# stage failed without matching on message text — the node flashes a different LED code +# for each, and on a headless board that code is the only diagnostic there is. + +class ATError(RuntimeError): + """Base for the transport's startup failures.""" + + +class ModemNotResponding(ATError): + """The modem is not answering AT commands at all.""" + + +class NetworkNotReady(ATError): + """The modem answers, but never reported an IP address.""" + + +class BrokerUnreachable(ATError): + """The network is up, but the broker link could not be established.""" + def _take_line(buf): """Take one CRLF-terminated line, or None if it has not fully arrived.""" @@ -192,6 +220,32 @@ def __init__(self, host: str, port: int = 1883, uart=None, uart_id=1, tx_pin=8, self._subscriptions = [] self._lwt = None + def wait_for_modem(self, timeout_ms=MODEM_READY_TIMEOUT_MS, + probe_interval_ms=MODEM_PROBE_INTERVAL_MS): + """Poll bare `AT` until the modem answers. True once it does, False on timeout. + + The Pico and the modem leave a power cycle together, and the Pico wins: it is + issuing commands about 300 ms in (MicroPython's own boot, plus 19 ms of I2C and + expander setup), while the modem needs 1.2-3.5 s to reach `ready` — the spread + is Ethernet link negotiation. Measured on the bench, 2026-08-27. + + A command sent into that window is not refused, it is swallowed whole: no echo + and no reply. So `AT+RST` used to time out against its 2 s default whenever the + link took the slow path, which killed the node outright — the intermittent + "doesn't come up after a power cycle". Ask the modem whether it is there before + giving it an order. + """ + deadline = _now_ms() + int(timeout_ms) + while True: + if self.send_at_and_wait('AT', timeout_ms=probe_interval_ms): + # Drop whatever the modem's boot log left behind. Nothing legitimate is + # in flight at this point, and the bytes a booting ESP emits are at + # another baud rate entirely — noise, not frames. + self._rx_buffer = b"" + return True + if _now_ms() >= deadline: + return False + def setup(self): """Initialise UART, apply base config and connect to broker. @@ -204,33 +258,52 @@ def setup(self): raise RuntimeError('machine.UART and machine.Pin not available; provide an existing uart instance when not on MicroPython') self.uart = UART(self.uart_id, baudrate=self.baud, tx=Pin(self.tx_pin), rx=Pin(self.rx_pin)) + # The modem has to be asked whether it is awake before it is given an order. + if not self.wait_for_modem(): + self._dump('modem ready') + raise ModemNotResponding( + 'modem did not answer AT within %d ms' % MODEM_READY_TIMEOUT_MS) + # reset the network module in case this isn't a fresh power-on - ok = self.send_at_and_wait('AT+RST') + ok = self.send_at_and_wait('AT+RST', timeout_ms=5000) if not ok: self._log('Warning: AT+RST returned ERROR or timed out') - raise RuntimeError('AT+RST failed') + self._dump('reset') + raise ModemNotResponding('AT+RST failed') # wait for network ready indication from modem: '+ETH_GOT_IP:...' line # the module typically prints 'ready' then '+ETH_GOT_IP:' when ready. - got_ip = self.wait_for_line('+ETH_GOT_IP:', timeout_ms=30000) + # + # Check what has already arrived before waiting. On a fast link the IP can land + # in the same read as the reset's own OK, and `wait_for_line` only inspects + # lines recorded after it is called — so it would sit out its whole 30 s waiting + # for a line that has been and gone, and then raise as though the network were + # down. + got_ip = None + for line in self.lines_since_command(): + if line.startswith('+ETH_GOT_IP:'): + got_ip = line + break + if got_ip is None: + got_ip = self.wait_for_line('+ETH_GOT_IP:', timeout_ms=30000) if not got_ip: self._dump('post-reset') - raise RuntimeError('Network device did not report IP after reset') + raise NetworkNotReady('Network device did not report IP after reset') config_cmd = 'AT+MQTTUSERCFG=0,1,"%s","","",0,0,""' % self.client_id if not self.send_at_and_wait(config_cmd, timeout_ms=50000): self._dump('base config') - raise RuntimeError('set_base_config returned ERROR or timed out') + raise BrokerUnreachable('set_base_config returned ERROR or timed out') # The will, if one was registered, has to be in place before the connect — # the broker only reads it at connection time. if not self._apply_lwt(): self._dump('lwt config') - raise RuntimeError('AT+MQTTCONNCFG returned ERROR or timed out') + raise BrokerUnreachable('AT+MQTTCONNCFG returned ERROR or timed out') if not self._connect(): self._dump('connect') - raise RuntimeError('connect returned ERROR or timed out') + raise BrokerUnreachable('connect returned ERROR or timed out') # `_connect()` returning True only means the modem accepted the command. The # broker link is confirmed by the modem's own +MQTTCONNECTED notification, @@ -238,7 +311,7 @@ def setup(self): if not self.connected: if self.wait_for_line('+MQTTCONNECTED', timeout_ms=5000) is None: self._dump('connect') - raise RuntimeError('modem accepted AT+MQTTCONN but never reported +MQTTCONNECTED') + raise BrokerUnreachable('modem accepted AT+MQTTCONN but never reported +MQTTCONNECTED') self._next_reconnect_ms = None def _write_line(self, line: str): @@ -660,4 +733,5 @@ def _parse_mqttsubrecv_line(raw_line: str): except Exception: parse_mqttsubrecv_line = None -__all__ = ['MQTTATClient'] +__all__ = ['MQTTATClient', 'ATError', 'ModemNotResponding', 'NetworkNotReady', + 'BrokerUnreachable'] diff --git a/src/lib/node_startup.py b/src/lib/node_startup.py new file mode 100644 index 0000000..805749c --- /dev/null +++ b/src/lib/node_startup.py @@ -0,0 +1,107 @@ +"""Startup supervision: a node that cannot start must say so, not exit. + +`main()` used to be called bare at module scope, so any exception on the way up +propagated out, `main.py` ended, and the board sat at the REPL with its LED off until +somebody power-cycled it. That is the failure this repo rates worst — the node stopped +reporting and said nothing. The orchestrator did what it should (the block degraded to +`unknown`, which the fail-safe rule treats as occupied), but nothing pointed at the node. + +So startup is retried, and if it still will not come up the board is reset and tries +again from cold, forever. Each failure flashes a code on the onboard LED first, because +that is the only thing anybody can see (`status_led.py`). + +## The flash codes + +| Code | Stage | What it means | +|------|------------------|--------------------------------------------------------| +| 2 | Sensors | A configured expander is not on the I2C bus | +| 3 | Modem | The ESP-AT modem is not answering AT commands | +| 4 | Network | The modem answers, but never reported an IP | +| 5 | Broker | Network is up, but the MQTT link could not be made | +| 6 | Runtime | The node came up, then the main loop crashed | +| 7 | Unknown | Something else — read the USB console | + +Codes start at 2 deliberately. A single flash is too easily confused with a board that +is merely blinking on boot, and a code that gets miscounted is worse than no code. + +**No `machine` import here.** The reset function is passed in, so the whole policy is +provable on the host — including that it eventually resets, which is not something you +want to discover by watching a baseboard. +""" + +from mqtt_at import BrokerUnreachable, ModemNotResponding, NetworkNotReady + + +CODE_SENSORS = 2 +CODE_MODEM = 3 +CODE_NETWORK = 4 +CODE_BROKER = 5 +CODE_RUNTIME = 6 +CODE_UNKNOWN = 7 + +# Three attempts, flashing for 2 s, 5 s and 10 s between them, then a hard reset — about +# 17 s of trying before the board goes round again. +# +# The first retry alone covers the fault this was written for: the modem needs at most +# 3.5 s from cold and `wait_for_modem()` now waits for it, so anything still failing on +# attempt two is a real fault rather than the power-on race. +RETRY_BACKOFF_MS = (2000, 5000, 10000) + + +class SensorWiringError(RuntimeError): + """The configured wiring is not what is on the I2C bus. + + Its own type so it can be told apart from a transport failure without matching on + message text: a missing expander flashes a different code from a missing broker, + and those two send you to opposite ends of the layout. + """ + + +class StartupFailed(RuntimeError): + """Every attempt failed and the board was reset. + + On the device `reset()` never returns, so this is only ever raised on the host — + where it is what keeps a failed startup from looking like a successful one. + """ + + +def code_for_error(exc): + """Map an exception to the LED code for the stage that raised it.""" + if isinstance(exc, SensorWiringError): + return CODE_SENSORS + if isinstance(exc, ModemNotResponding): + return CODE_MODEM + if isinstance(exc, NetworkNotReady): + return CODE_NETWORK + if isinstance(exc, BrokerUnreachable): + return CODE_BROKER + return CODE_UNKNOWN + + +def start_supervised(attempt, on_failure, reset, backoff_ms=RETRY_BACKOFF_MS): + """Run `attempt()` until it succeeds; reset the board if it never does. + + - `attempt()` performs one complete startup from a clean slate and returns whatever + the caller needs to run. It must be safe to call again after it has raised. + - `on_failure(exc, code, attempt_number, delay_ms)` reports the failure and is + expected to *take* `delay_ms` doing it — the caller spends that time flashing + `code` on the LED, which is both the wait and the diagnostic. + - `reset()` restarts the board. + + Returns whatever `attempt()` returned. + """ + for number, delay_ms in enumerate(backoff_ms, start=1): + try: + return attempt() + except Exception as exc: + on_failure(exc, code_for_error(exc), number, delay_ms) + + reset() + raise StartupFailed("startup failed %d times; board reset" % len(backoff_ms)) + + +__all__ = [ + "CODE_SENSORS", "CODE_MODEM", "CODE_NETWORK", "CODE_BROKER", "CODE_RUNTIME", + "CODE_UNKNOWN", "RETRY_BACKOFF_MS", "SensorWiringError", "StartupFailed", + "code_for_error", "start_supervised", +] diff --git a/src/lib/status_led.py b/src/lib/status_led.py new file mode 100644 index 0000000..c8fdcf6 --- /dev/null +++ b/src/lib/status_led.py @@ -0,0 +1,84 @@ +"""The onboard LED as the node's only diagnostic channel. + +A node on the layout has no console. The board is behind the baseboard, the USB lead is +not plugged into anything, and the first thing anyone notices about a node that failed +to start is that its LED never came on. So the LED has to carry more than "powered": + +| LED | Meaning | +|--------------------------|----------------------------------------------------| +| Solid on | Running: sensors configured, broker link up | +| Off | No power, or a hard crash that took the board out | +| N flashes, pause, repeat | Startup failed at stage N; retrying, then resetting| + +The codes themselves live in `node_startup.py`, next to the policy that chooses them — +this module only knows how to make a countable pattern out of a number. + +**No `machine` import here.** The pin is passed in, so the whole pattern is provable on +the host rather than by standing in front of the baseboard counting. +""" + +from utime import sleep_ms as _sleep_ms, ticks_diff as _ticks_diff, ticks_ms as _ticks_ms + + +# Slow enough to count from across a room, and slow enough that a phone camera catches +# it. The gap has to be clearly longer than the off time between flashes or a 2 reads as +# a 4 — the whole value of a code is that it is unambiguous at a glance. +FLASH_ON_MS = 200 +FLASH_OFF_MS = 250 +GAP_MS = 1400 + + +def blink_plan(code, on_ms=FLASH_ON_MS, off_ms=FLASH_OFF_MS, gap_ms=GAP_MS): + """One cycle of `code` flashes as a list of `(level, duration_ms)` steps. + + The last flash is followed by the long gap rather than the short one, which is what + separates one cycle from the next. + """ + if code < 1: + raise ValueError("a flash code must be at least 1, got %r" % (code,)) + + plan = [] + for index in range(code): + last = index == code - 1 + plan.append((1, on_ms)) + plan.append((0, gap_ms if last else off_ms)) + return plan + + +class StatusLED: + """Drives a `machine.Pin` (or anything with `value()`) as a status indicator.""" + + def __init__(self, pin, sleep_ms=None, ticks_ms=None, ticks_diff=None): + self._pin = pin + self._sleep_ms = sleep_ms if sleep_ms is not None else _sleep_ms + self._ticks_ms = ticks_ms if ticks_ms is not None else _ticks_ms + self._ticks_diff = ticks_diff if ticks_diff is not None else _ticks_diff + + def on(self): + self._pin.value(1) + + def off(self): + self._pin.value(0) + + def flash(self, code, duration_ms): + """Repeat `code` for about `duration_ms`, then go dark. + + Always completes the cycle it is in, so it can overrun `duration_ms` by up to + one cycle. That is deliberate: a code cut off half way through cannot be + counted, and counting it is the entire point. At least one full cycle is always + shown, even when `duration_ms` is 0. + """ + plan = blink_plan(code) + start = self._ticks_ms() + + while True: + for level, hold_ms in plan: + self._pin.value(level) + self._sleep_ms(hold_ms) + if self._ticks_diff(self._ticks_ms(), start) >= duration_ms: + break + + self.off() + + +__all__ = ["StatusLED", "blink_plan", "FLASH_ON_MS", "FLASH_OFF_MS", "GAP_MS"] diff --git a/tests/test_mqtt_setup.py b/tests/test_mqtt_setup.py new file mode 100644 index 0000000..c3fd474 --- /dev/null +++ b/tests/test_mqtt_setup.py @@ -0,0 +1,156 @@ +"""`setup()` against a modem that is still booting. + +The node used to die outright on a power cycle, roughly whenever the Ethernet link took +the slow path. The Pico reaches its first AT command about 300 ms after power-on; the +modem needs 1.2-3.5 s to reach `ready`, and a command sent into that window is swallowed +whole — no echo, no reply. `AT+RST` then timed out against its 2 s default and +`main.py` exited to a REPL nobody was watching. + +Measured on the bench 2026-08-27; the modem's boot spread is Ethernet negotiation. +""" + +import pytest + +from mqtt_at import ( + BrokerUnreachable, MQTTATClient, ModemNotResponding, NetworkNotReady, +) + +CONNECTED = '+MQTTCONNECTED:0,1,"172.18.10.240","1883","",1' + + +def make_client(uart, **kwargs): + return MQTTATClient("172.18.10.240", 1883, uart=uart, **kwargs) + + +def booting_modem(silent_probes=0, got_ip=True, broker="ok"): + """A modem that ignores everything until it has finished booting. + + `silent_probes` is how many bare `AT`s go unanswered before it wakes up. Silence is + the point: a booting ESP does not answer with ERROR, it does not answer at all. + """ + state = {"probes": 0} + + def reply(line): + if line == "AT": + state["probes"] += 1 + return None if state["probes"] <= silent_probes else "OK" + if state["probes"] <= silent_probes: + return None + if line == "AT+RST": + return "OK\r\n+ETH_GOT_IP:172.18.10.98" if got_ip else "OK" + if line.startswith("AT+MQTTCONN="): + if broker == "refused": + return "ERROR" + return "OK\r\n" + CONNECTED if broker == "ok" else "OK" + return "OK" + + return reply + + +# --- waiting for the modem -------------------------------------------------- + +def test_the_modem_is_asked_whether_it_is_awake_before_it_is_given_an_order(uart): + """The regression. Four probes of silence is ~2 s — the old deadline for AT+RST.""" + client = make_client(uart) + uart.auto_reply = booting_modem(silent_probes=4) + + client.setup() + + sent = uart.sent_lines + assert sent[:5] == ["AT"] * 5, "it must probe until answered, not assume" + assert sent[5] == "AT+RST", "the reset only goes out once the modem has answered" + assert client.connected is True + + +def test_startup_survives_a_modem_slower_than_the_old_two_second_deadline(uart, clock): + client = make_client(uart) + uart.auto_reply = booting_modem(silent_probes=6) # ~3 s, the measured worst case + + client.setup() + + assert clock.ticks_ms() > 2000, \ + "this must be the case the old 2 s AT+RST timeout would have killed" + + +def test_a_modem_that_never_wakes_says_so_and_never_sends_a_reset(uart): + client = make_client(uart) + uart.auto_reply = booting_modem(silent_probes=10_000) + + with pytest.raises(ModemNotResponding): + client.setup() + + assert "AT+RST" not in uart.sent_lines, \ + "commanding a modem that has not answered is what produced the silent death" + + +def test_wait_for_modem_returns_as_soon_as_it_answers(uart): + client = make_client(uart) + uart.auto_reply = booting_modem(silent_probes=2) + + assert client.wait_for_modem(timeout_ms=10_000, probe_interval_ms=500) is True + assert uart.sent_lines == ["AT"] * 3 + + +def test_wait_for_modem_gives_up_rather_than_blocking_forever(uart, clock): + client = make_client(uart) + uart.auto_reply = None # total silence + + assert client.wait_for_modem(timeout_ms=2000, probe_interval_ms=500) is False + assert clock.ticks_ms() >= 2000 + + +def test_boot_chatter_does_not_stop_the_modem_being_detected(uart): + client = make_client(uart) + + def reply(line): + uart.feed_line("ets Jun 8 2016 00:22:57 rst cause:2") # ESP boot log + return "OK" + + uart.auto_reply = reply + + assert client.wait_for_modem(timeout_ms=1000) is True + assert client._rx_buffer == b"", \ + "stale bytes must not be left to prefix the reset's reply" + + +# --- the stage a failure came from ------------------------------------------ + +def test_a_network_that_never_reports_an_ip_is_its_own_failure(uart): + client = make_client(uart) + uart.auto_reply = booting_modem(got_ip=False) + + with pytest.raises(NetworkNotReady): + client.setup() + + +def test_an_ip_arriving_with_the_resets_own_ok_is_not_missed(uart, clock): + """A fast link puts both in the same read. Waiting for it again would time out.""" + client = make_client(uart) + uart.auto_reply = booting_modem() + + client.setup() + + assert clock.ticks_ms() < 30_000, "it must not have sat out the 30 s IP wait" + + +def test_a_broker_that_refuses_the_connection_is_its_own_failure(uart): + client = make_client(uart) + uart.auto_reply = booting_modem(broker="refused") + + with pytest.raises(BrokerUnreachable): + client.setup() + + +def test_a_modem_that_accepts_the_connect_but_never_confirms_it_is_a_broker_failure(uart): + """A True from the modem means it took the command, not that the broker answered.""" + client = make_client(uart) + uart.auto_reply = booting_modem(broker="silent") + + with pytest.raises(BrokerUnreachable): + client.setup() + + +def test_the_startup_failures_are_still_runtime_errors(uart): + """They subclass RuntimeError, which is what callers already catch.""" + for failure in (ModemNotResponding, NetworkNotReady, BrokerUnreachable): + assert issubclass(failure, RuntimeError) diff --git a/tests/test_node_startup.py b/tests/test_node_startup.py new file mode 100644 index 0000000..5cd2f0e --- /dev/null +++ b/tests/test_node_startup.py @@ -0,0 +1,142 @@ +"""Startup supervision: the node retries, reports, and eventually resets. + +The behaviour being protected here is that a node which cannot start never falls silent. +It used to: `main()` was called bare, the exception propagated out of `main.py`, and the +board sat at a REPL with its LED off until someone power-cycled it. Nothing in the +system pointed at the node — the orchestrator only saw a sensor go stale. +""" + +import pytest + +from mqtt_at import BrokerUnreachable, ModemNotResponding, NetworkNotReady +from node_startup import ( + CODE_BROKER, CODE_MODEM, CODE_NETWORK, CODE_RUNTIME, CODE_SENSORS, CODE_UNKNOWN, + RETRY_BACKOFF_MS, SensorWiringError, StartupFailed, code_for_error, start_supervised, +) + + +class Recorder: + """Stands in for the LED and the reset line.""" + + def __init__(self): + self.failures = [] # (code, attempt_number, delay_ms) + self.resets = 0 + + def on_failure(self, exc, code, attempt, delay_ms): + self.failures.append((code, attempt, delay_ms)) + + def reset(self): + self.resets += 1 + + @property + def codes(self): + return [code for code, _attempt, _delay in self.failures] + + +def always_failing(exc): + def attempt(): + raise exc + return attempt + + +# --- the codes -------------------------------------------------------------- + +@pytest.mark.parametrize("exc, expected", [ + (SensorWiringError("expander 0x21 not on the bus"), CODE_SENSORS), + (ModemNotResponding("AT+RST failed"), CODE_MODEM), + (NetworkNotReady("no IP"), CODE_NETWORK), + (BrokerUnreachable("connect timed out"), CODE_BROKER), +]) +def test_each_stage_gets_its_own_code(exc, expected): + assert code_for_error(exc) == expected + + +def test_an_unrecognised_failure_still_gets_a_code(): + """Silence is the failure being fixed. Anything unclassified still flashes.""" + assert code_for_error(ValueError("something else entirely")) == CODE_UNKNOWN + + +def test_the_codes_are_all_distinct_and_countable(): + codes = [CODE_SENSORS, CODE_MODEM, CODE_NETWORK, CODE_BROKER, CODE_RUNTIME, + CODE_UNKNOWN] + assert len(set(codes)) == len(codes) + assert min(codes) >= 2, "a single flash is too easily confused with a boot blink" + + +# --- retrying --------------------------------------------------------------- + +def test_a_transient_failure_is_retried_and_the_node_comes_up(): + """The fault this was written for: the modem is asleep, then it is not.""" + calls = {"n": 0} + + def attempt(): + calls["n"] += 1 + if calls["n"] < 3: + raise ModemNotResponding("modem did not answer AT") + return "running" + + recorder = Recorder() + + assert start_supervised(attempt, recorder.on_failure, recorder.reset) == "running" + assert calls["n"] == 3 + assert recorder.codes == [CODE_MODEM, CODE_MODEM] + assert recorder.resets == 0, "a startup that succeeded must not reset the board" + + +def test_a_successful_first_attempt_reports_nothing(): + recorder = Recorder() + + assert start_supervised(lambda: "running", recorder.on_failure, recorder.reset) == "running" + assert recorder.failures == [] + assert recorder.resets == 0 + + +def test_every_failure_is_reported_before_the_next_attempt(): + """The reporting callback is also the wait — the LED flashes for the backoff.""" + recorder = Recorder() + + with pytest.raises(StartupFailed): + start_supervised(always_failing(BrokerUnreachable("no broker")), + recorder.on_failure, recorder.reset) + + assert [delay for _code, _attempt, delay in recorder.failures] == list(RETRY_BACKOFF_MS) + assert [attempt for _code, attempt, _delay in recorder.failures] == [1, 2, 3] + assert all(delay > 0 for _c, _a, delay in recorder.failures), \ + "a zero wait would flash a code nobody could see" + + +# --- giving up -------------------------------------------------------------- + +def test_the_board_is_reset_when_every_attempt_fails(): + recorder = Recorder() + + with pytest.raises(StartupFailed): + start_supervised(always_failing(NetworkNotReady("no IP")), + recorder.on_failure, recorder.reset) + + assert recorder.resets == 1 + assert len(recorder.failures) == len(RETRY_BACKOFF_MS) + + +def test_a_failed_startup_never_returns_as_though_it_worked(): + """On the device `reset()` never returns. On the host it does, and a bare return + here would hand `main()` a None it would then try to run.""" + recorder = Recorder() + + with pytest.raises(StartupFailed): + start_supervised(always_failing(ValueError("unclassified")), + recorder.on_failure, recorder.reset) + + assert recorder.codes == [CODE_UNKNOWN] * len(RETRY_BACKOFF_MS) + + +def test_a_wiring_fault_is_retried_too_rather_than_halting(): + """An expander missing at boot is usually a loose ribbon, not a permanent fact.""" + recorder = Recorder() + + with pytest.raises(StartupFailed): + start_supervised(always_failing(SensorWiringError("expander 0x21 missing")), + recorder.on_failure, recorder.reset) + + assert recorder.codes == [CODE_SENSORS] * len(RETRY_BACKOFF_MS) + assert recorder.resets == 1 diff --git a/tests/test_status_led.py b/tests/test_status_led.py new file mode 100644 index 0000000..ace377e --- /dev/null +++ b/tests/test_status_led.py @@ -0,0 +1,94 @@ +"""The LED codes, proved on the host rather than by counting flashes on a baseboard. + +The onboard LED is the only thing a node tells you when it cannot start, so a code that +is miscountable is a code that lies. These tests pin the shape of the pattern. +""" + +import pytest + +import fakes +from status_led import FLASH_OFF_MS, FLASH_ON_MS, GAP_MS, StatusLED, blink_plan + + +def cycle_ms(code): + return sum(duration for _level, duration in blink_plan(code)) + + +def make_led(clock): + """A LED on a fake pin, with every sleep recorded as (level held, how long).""" + pin = fakes.FakePin("LED", value=0) + seen = [] + + def sleeping(ms): + seen.append((pin.value(), ms)) + clock.advance(ms) + + led = StatusLED(pin, sleep_ms=sleeping, ticks_ms=clock.ticks_ms, + ticks_diff=fakes.ticks_diff) + return led, pin, seen + + +# --- the pattern ----------------------------------------------------------- + +def test_the_plan_is_that_many_flashes(): + assert blink_plan(2) == [(1, FLASH_ON_MS), (0, FLASH_OFF_MS), + (1, FLASH_ON_MS), (0, GAP_MS)] + + +def test_the_cycle_ends_on_the_long_gap(): + """What separates one cycle from the next, and so a 2 from a 4.""" + for code in (2, 3, 4, 5, 6, 7): + plan = blink_plan(code) + assert plan[-1] == (0, GAP_MS) + assert plan.count((1, FLASH_ON_MS)) == code + # Only the final off is long, or the flashes run together. + assert [d for level, d in plan if level == 0].count(GAP_MS) == 1 + + +def test_the_gap_is_clearly_longer_than_the_space_between_flashes(): + assert GAP_MS >= FLASH_OFF_MS * 3 + + +def test_a_code_below_one_is_refused(): + with pytest.raises(ValueError): + blink_plan(0) + + +# --- driving the pin ------------------------------------------------------- + +def test_flash_shows_a_whole_cycle_even_for_a_zero_duration(clock): + """A code cut off half way through cannot be counted, which is the whole point.""" + led, pin, seen = make_led(clock) + + led.flash(3, 0) + + assert seen == blink_plan(3) + assert pin.value() == 0, "the LED must not be left lit by a failure code" + + +def test_flash_repeats_until_the_duration_is_up(clock): + led, _pin, seen = make_led(clock) + code = 2 + + led.flash(code, cycle_ms(code) + 50) + + assert seen == blink_plan(code) * 2 + + +def test_flash_leaves_the_led_off_so_running_is_unambiguous(clock): + """Solid on means running. A code that ended lit would read as a healthy node.""" + led, pin, _seen = make_led(clock) + + led.flash(5, 100) + + assert pin.value() == 0 + + +def test_on_and_off_drive_the_pin(clock): + led, pin, _seen = make_led(clock) + + led.on() + assert pin.value() == 1 + + led.off() + assert pin.value() == 0