diff --git a/CHANGELOG.md b/CHANGELOG.md index 470da292..93b4ca20 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -373,6 +373,21 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **A dropped Bluetooth peripheral comes back in seconds, and never stops + trying.** The first retry is immediate, then half a second, a second, and + every two seconds after that, for as long as the device is in use; before, + retries started after 5 seconds, backed off to a minute and gave up after + twelve. A peripheral with an advertised name is looked for by name first, + because a peripheral using BLE privacy re-advertises at a new address after + every drop, and scanning for the old one cost each reconnect several seconds + for nothing. +- **A Maimu resumes its pulse train after a dropout.** It used to come back + `off`. It now resends its last command, a train for whatever is left of its + duration. Commands sent while the link is down no longer block the flow and + then replay in a burst; the newest one is sent on reconnect. The node's + duty-cycle setting now goes through a `train(on_ms, off_ms, duration_s)` + action, which the device control panel offers as well. + - **Three examples would not start** (`box_new`, `box_pi_side`, `dispense`): they held connections to nodes that no longer existed. Those connections are removed; they never loaded, so the experiments behave as before. diff --git a/docs-site/reference/devices.md b/docs-site/reference/devices.md index de15b147..39962d48 100644 --- a/docs-site/reference/devices.md +++ b/docs-site/reference/devices.md @@ -55,21 +55,24 @@ A BLE peripheral that goes out of range, loses power, or is claimed by another central is noticed straight away, not at the next write. Its row in the [Hardware panel](../building/devices.md) and its own dot on the status strip (shown beside the board dots for any peripheral that tracks its own link) both -move to **Disconnected**, and GLIDER starts retrying on its own: 5 seconds, -then 10, 20, 40 and 60, up to twelve attempts, before it gives up and shows -**Error**. +move to **Disconnected**, and GLIDER starts retrying on its own: straight +away, then after half a second, a second, and every two seconds from then on, +for as long as the device is in use. It does not give up. A peripheral with an +advertised name is looked for by that name first, because a peripheral using +BLE privacy comes back at a new address after every drop. - The Bluetooth **board**'s own dot stays green throughout. That is the host adapter, and it is genuinely fine — it is the peripheral that went away, which is why a peripheral that owns its link gets a dot of its own. - A run is not paused by a dropped peripheral. You get a warning notification - and the retries continue underneath it; only **Error** — retries exhausted — - needs you to go and look. -- **A Maimu comes back off.** The stimulator runs a pulse train in its own - firmware, so a link that died mid-train left it stimulating with nothing - attached to stop it. When the reconnect succeeds, GLIDER writes `off` before - anything else, so the device returns in a known state instead of resuming a - pattern nobody is watching. Re-issue the pulse yourself if you still want it. + and the retries continue underneath it. +- **A Maimu comes back doing what it was last told.** Its firmware turns the + light off the moment the link drops. When the reconnect succeeds, GLIDER + resends the last command: a pulse train for whatever is left of its + duration, `on` as `on`, and `off` if nothing was asked or the train has run + out. Commands the flow sends while the link is down do not hold the flow up; + the newest one is what goes out on reconnect. The log says when a train was + resumed, so the gap in stimulation is on record. !!! tip "Two stimulators with the same name" A strip dot is labelled with the device's name, since that is usually more diff --git a/plugins/glider-maimu/README.md b/plugins/glider-maimu/README.md index 940036ab..6abc0b9d 100644 --- a/plugins/glider-maimu/README.md +++ b/plugins/glider-maimu/README.md @@ -92,12 +92,14 @@ therefore writes `off` before it disconnects, bounded so it cannot eat GLIDER's emergency-stop budget. Emergency stop, End Experiment and app quit all stop the device through that one path. -The same reasoning covers a link that drops on its own — out of range, out of -power, claimed by another central. GLIDER reconnects it with bounded backoff -(5, 10, 20, 40 and 60 seconds, up to twelve attempts) and, the moment it is -back, writes `off` before anything else touches the device. A stimulator that -reconnected mid-pattern comes back in a known state instead of resuming one -nobody is watching — re-issue the pulse yourself if you still want it. +A link that drops on its own — out of range, out of power, claimed by another +central — is different. The firmware turns the light off the moment the link +goes, and GLIDER starts reconnecting straight away, then every few seconds at +most, without giving up. The device remembers the last command it was given and +resends it the moment the link is back: a train for whatever is left of its +duration, `on` as `on`, and `off` if nothing was asked or the train has run +out. Commands that arrive while the link is down return immediately instead of +holding up the flow, and only the newest is sent on reconnect. ## Development diff --git a/plugins/glider-maimu/src/glider_maimu/device.py b/plugins/glider-maimu/src/glider_maimu/device.py index 7fe0e2a8..bcc9f996 100644 --- a/plugins/glider-maimu/src/glider_maimu/device.py +++ b/plugins/glider-maimu/src/glider_maimu/device.py @@ -3,15 +3,17 @@ The Maimu is a Nordic/Zephyr Bluetooth LE peripheral with exactly one writable GATT characteristic that accepts three UTF-8 commands:: - on turn on and stay on - off turn off - , toggle every period_ms ms, for duration_s seconds + on turn on and stay on + off turn off + , toggle every period_ms ms, for duration_s seconds + p,, on_ms on / off_ms off, for duration_s seconds + (firmware 0.1.0+; older firmware ignores it) Running one through the generic ``BLEWrite`` / ``BLE`` device works, but means pasting both UUIDs into the Add Device dialog and then remembering that the action is called ``write`` and that a pulse is spelled ``"500,10"``. This device bakes the protocol in: the UUIDs are defaults and the commands are named actions -(``on`` / ``off`` / ``pulse``). +(``on`` / ``off`` / ``pulse`` / ``train``). It subclasses :class:`~glider.hal.devices.ble_device.BLEDevice` rather than ``BaseDevice`` so it inherits that class's connection plumbing unchanged -- @@ -26,17 +28,22 @@ ``off`` before it disconnects -- which puts emergency stop, End Experiment and app quit all on the same path. -The same reasoning covers a *dropped* link: :meth:`MaimuDevice._on_reconnected` -writes ``off`` when the automatic reconnect succeeds, so a stimulator that came -back mid-pattern is put in a known state instead of left running one nobody -asked for. +A *dropped* link is different: the firmware turns the light off the moment the +link goes, but the experiment still wants whatever it last asked for. So the +device remembers its last command, and :meth:`MaimuDevice._on_reconnected` +puts it back the moment the link returns -- a train for whatever is left of its +duration, ``off`` if nothing was asked or the train has run out. Commands that +arrive while the link is down update that memory and return at once instead of +holding the flow up behind a reconnect; the newest one is what gets sent. """ import asyncio import logging +import time from collections.abc import Callable from typing import TYPE_CHECKING, Any +from glider.hal.base_board import ConnectionState from glider.hal.base_device import DeviceConfig from glider.hal.devices.ble_device import BLEDevice @@ -132,6 +139,35 @@ class MaimuDevice(BLEDevice): "help": "How long the train runs. The firmware stops on its own.", }, ], + "train": [ + { + "key": "on_ms", + "label": "On (ms)", + "type": "int", + "default": 500, + "min": 1, + "max": 3_600_000, + "help": "How long each pulse stays on. 20 Hz with 10 ms pulses: On 10, Off 40.", + }, + { + "key": "off_ms", + "label": "Off (ms)", + "type": "int", + "default": 500, + "min": 1, + "max": 3_600_000, + "help": "Gap between pulses. Unequal On/Off needs firmware 0.1.0+.", + }, + { + "key": "duration_s", + "label": "Duration (s)", + "type": "int", + "default": 10, + "min": 1, + "max": 86_400, + "help": "How long the train runs. The firmware stops on its own.", + }, + ], } def __init__(self, board: "BaseBoard", config: DeviceConfig, name: str | None = None): @@ -141,6 +177,13 @@ def __init__(self, board: "BaseBoard", config: DeviceConfig, name: str | None = config.settings.setdefault("write_char_uuid", DEFAULT_WRITE_CHAR_UUID) config.settings.setdefault("service_uuid", DEFAULT_SERVICE_UUID) super().__init__(board, config, name) + # The last command the experiment gave, so a reconnect can put it back: + # ("on",), ("off",) or ("train", on_ms, off_ms, duration_s, ends_at) + # with ends_at on the perf_counter clock. None until the first command. + self._desired: tuple | None = None + # Serializes "remember a command, send it" against the reconnect hook, + # so the hook can never send an older command over a newer one. + self._desired_lock = asyncio.Lock() # --- identity --- @@ -161,6 +204,7 @@ def actions(self) -> dict[str, Callable]: "on": self.on, "off": self.off, "pulse": self.pulse, + "train": self.train, "write": self.write, } @@ -168,11 +212,11 @@ def actions(self) -> dict[str, Callable]: async def on(self) -> None: """Turn the stimulator on and leave it on.""" - await self.write("on") + await self._command(("on",)) async def off(self) -> None: """Turn the stimulator off.""" - await self.write("off") + await self._command(("off",)) async def pulse(self, period_ms: Any, duration_s: Any) -> None: """Toggle every ``period_ms`` milliseconds for ``duration_s`` seconds. @@ -185,12 +229,93 @@ async def pulse(self, period_ms: Any, duration_s: Any) -> None: """ period = self._whole_number(period_ms, "period_ms") duration = self._whole_number(duration_s, "duration_s") - # Two args -> BLEDevice.write comma-joins them: "500,10". - await self.write(period, duration) + await self._command(("train", period, period, duration, self._deadline(duration))) + + async def train(self, on_ms: Any, off_ms: Any, duration_s: Any) -> None: + """Pulse ``on_ms`` on / ``off_ms`` off for ``duration_s`` seconds. + + e.g. ``train(10, 40, 10)`` writes ``"p10,40,10"`` -- 10 ms pulses at + 20 Hz for 10 seconds. Equal on and off times go out as the original + ``,`` command, which every firmware understands. + """ + on = self._whole_number(on_ms, "on_ms") + off = self._whole_number(off_ms, "off_ms") + duration = self._whole_number(duration_s, "duration_s") + await self._command(("train", on, off, duration, self._deadline(duration))) + + # --- remembered command --- + + @staticmethod + def _deadline(duration_s: int) -> float: + return time.perf_counter() + duration_s + + @staticmethod + def _wire(desired: tuple, *, resume: bool = False) -> tuple: + """The write() arguments for a remembered command. + + A first send uses the train's full duration. A resend after a reconnect + uses what is left of it, rounded down so the train never outlasts the + one that was asked for, and turns into ``off`` once under a second is + left. + """ + if desired[0] != "train": + return desired + _, on, off, duration, ends_at = desired + if resume: + left = ends_at - time.perf_counter() + if left < 1: + return ("off",) + duration = int(left) + # Two or three args -> BLEDevice.write comma-joins them: "500,10". + return (on, duration) if on == off else (f"p{on}", off, duration) + + def _link_is_down(self) -> bool: + return self._initialized and self.link_state in ( + ConnectionState.DISCONNECTED, + ConnectionState.RECONNECTING, + ) + + async def _command(self, desired: tuple) -> None: + """Remember ``desired``, then send it -- unless the link is down. + + With the link down a write would block the flow behind a reconnect of + several seconds, and every command queued up that way used to land in a + burst once it came back, oldest first. Remembering the newest and + returning means the reconnect sends exactly one command: the current one. + """ + async with self._desired_lock: + self._desired = desired + wire = self._wire(desired) + if self._link_is_down(): + logger.warning( + "Maimu %s: link is down; %s will be sent as soon as it reconnects", + self._name, + ",".join(str(a) for a in wire), + ) + # Normally already running; this covers a drop no callback reported. + self._start_reconnect() + return + # Once, with no reconnect inside the write: the command is + # remembered, so if the link died under it the reconnect sends it -- + # and an in-band reconnect would hold this lock, and the flow behind + # it, for seconds. + try: + await self.write(*wire, retry=False) + except Exception: + client = self._client + if not self._initialized or (client is not None and client.is_connected): + raise # the link is up (or we are shutting down): a real failure + logger.warning( + "Maimu %s: link dropped while sending %s; it will be sent as soon " + "as it reconnects", + self._name, + ",".join(str(a) for a in wire), + ) + self._start_reconnect() @staticmethod def _whole_number(value: Any, field: str) -> int: - """Coerce a pulse argument to a positive whole number. + """Coerce a pulse or train argument to a positive whole number. The firmware ``atoi``s both fields, so a fractional or non-numeric value would be silently truncated into a command that does something other @@ -200,35 +325,47 @@ def _whole_number(value: Any, field: str) -> int: try: number = float(value) except (TypeError, ValueError) as e: - raise ValueError(f"Maimu.pulse: {field} must be a number, got {value!r}") from e + raise ValueError(f"Maimu: {field} must be a number, got {value!r}") from e if not number.is_integer(): - raise ValueError(f"Maimu.pulse: {field} must be a whole number, got {value!r}") + raise ValueError(f"Maimu: {field} must be a whole number, got {value!r}") number = int(number) if number < 1: - raise ValueError(f"Maimu.pulse: {field} must be at least 1, got {value!r}") + raise ValueError(f"Maimu: {field} must be at least 1, got {value!r}") return number # --- lifecycle --- async def _on_reconnected(self) -> None: - """Come back off. - - The firmware runs a pulse autonomously, so a link that dropped - mid-train left the stimulator running with nothing attached to stop - it. Whatever it is doing, it has been doing it unsupervised, and this - is the first moment anyone can say otherwise -- so the device is put - in a known state rather than resumed in an unknown one. - - Same reasoning as :meth:`shutdown`, and the same best-effort - treatment: BLEDevice logs a failure here and leaves the link up, - because the link genuinely did reconnect. - - This and :meth:`shutdown` are independent safety paths that can both - fire for the same event -- a reconnect landing just as a shutdown - begins -- so ``off`` may be written twice in a row. That duplication - is safety-neutral and deliberate; it is not a bug to collapse. + """Put back the last command the experiment gave. + + The firmware turns the light off when the link drops, so whatever the + experiment asked for has been interrupted, not continued. A train that + still has time left is resent for that remaining time; ``on`` is resent + as ``on``; anything else -- ``off``, a train that ran out, or no command + yet -- writes ``off``, so the device is always left in a known state. + + Held under the command lock so a command the flow sends at the same + moment is never overwritten by an older one from here. Sent once, with + no reconnect inside the write: if the link dies again before it lands, + the reconnect loop carries on and calls this again, which then works out + what is left of the train at that later moment rather than sending a + figure that went stale while it waited. + + Best-effort, like :meth:`shutdown`: BLEDevice logs a failure here and + leaves the link up, because the link genuinely did reconnect. This and + :meth:`shutdown` can both fire for the same event, so ``off`` may be + written twice in a row; that is safety-neutral and deliberate. """ - await self.write("off") + async with self._desired_lock: + desired = self._desired + wire = self._wire(desired, resume=True) if desired is not None else ("off",) + if wire != ("off",): + logger.warning( + "Maimu %s: link restored; resuming %s", + self._name, + ",".join(str(a) for a in wire), + ) + await self.write(*wire, retry=False) async def shutdown(self) -> None: """Stop the stimulator, then disconnect. @@ -253,6 +390,9 @@ async def shutdown(self) -> None: state. That is the same news as a failed write, so it gets the same warning. """ + # Forget the last command first, so a reconnect landing during the + # shutdown can only ever put the device back to off. + self._desired = None try: if self._initialized and self._client is not None: try: diff --git a/plugins/glider-maimu/src/glider_maimu/node.py b/plugins/glider-maimu/src/glider_maimu/node.py index 8affe288..0847fd82 100644 --- a/plugins/glider-maimu/src/glider_maimu/node.py +++ b/plugins/glider-maimu/src/glider_maimu/node.py @@ -167,12 +167,10 @@ async def hardware_operation(self) -> None: """Send the configured command, then trigger the exec output.""" off_ms = self._off_ms or self._period_ms if self._mode == MODE_PULSE and off_ms != self._period_ms: - # "p,," (firmware 0.1.0+). The 'p' makes - # older firmware ignore it rather than misread "10,40,10" as a - # 10 ms toggle for 40 s. - await self._device.execute_action( - "write", f"p{self._period_ms}", off_ms, self._duration_s - ) + # Sent as "p,," (firmware 0.1.0+). The + # 'p' makes older firmware ignore it rather than misread "10,40,10" + # as a 10 ms toggle for 40 s. + await self._device.execute_action("train", self._period_ms, off_ms, self._duration_s) elif self._mode == MODE_PULSE: await self._device.execute_action(MODE_PULSE, self._period_ms, self._duration_s) else: diff --git a/plugins/glider-maimu/tests/test_device.py b/plugins/glider-maimu/tests/test_device.py index 1af51270..c25472b0 100644 --- a/plugins/glider-maimu/tests/test_device.py +++ b/plugins/glider-maimu/tests/test_device.py @@ -121,7 +121,7 @@ def test_device_type_is_maimu(): def test_actions_are_the_command_set(): - assert set(_make_device().actions) == {"on", "off", "pulse", "write"} + assert set(_make_device().actions) == {"on", "off", "pulse", "train", "write"} def test_read_is_not_offered(): @@ -215,6 +215,20 @@ async def test_pulse_writes_whole_numbers_from_floats(fake_bleak): assert created["client"].written == [b"500,10"] +async def test_train_writes_the_on_off_command(fake_bleak): + _module, created = fake_bleak + device = await _initialized() + await device.train(10, 40, 10) + assert created["client"].written == [b"p10,40,10"] + + +async def test_a_symmetric_train_uses_the_original_command(fake_bleak): + _module, created = fake_bleak + device = await _initialized() + await device.train(500, 500, 10) + assert created["client"].written == [b"500,10"] + + async def test_command_goes_to_the_configured_characteristic(fake_bleak): _module, created = fake_bleak device = await _initialized() diff --git a/plugins/glider-maimu/tests/test_device_reconnect.py b/plugins/glider-maimu/tests/test_device_reconnect.py index 676a6b75..d94d2232 100644 --- a/plugins/glider-maimu/tests/test_device_reconnect.py +++ b/plugins/glider-maimu/tests/test_device_reconnect.py @@ -1,15 +1,16 @@ -"""A Maimu comes back off. - -The firmware runs a pulse autonomously, so a link that died mid-train left a -stimulator running with nothing attached to stop it. The reconnect is the -first chance anyone has had to say otherwise, and it takes it -- the device -never silently resumes whatever it was doing. - -Same reasoning as shutdown(), which writes 'off' before it disconnects. +"""A Maimu comes back doing what the experiment last asked for. + +The firmware turns the light off the moment the link drops, so a train cut off +by a drop has been interrupted, not continued. The reconnect puts the last +command back -- a train for whatever is left of it -- and with nothing asked, +or the train run out, it writes 'off', so the device is always in a known state. +Commands that arrive while the link is down must not hold the flow up; the +newest one is what the reconnect sends. """ import asyncio import sys +import types import pytest @@ -33,6 +34,8 @@ def __init__(self, address, disconnected_callback=None): self.disconnected_callback = disconnected_callback async def connect(self): + if getattr(self, "connect_error", None): + raise self.connect_error self.is_connected = True async def disconnect(self): @@ -55,6 +58,7 @@ def fake_bleak(monkeypatch): def make_client(address, *a, disconnected_callback=None, **k): client = _FakeClient(address, disconnected_callback) + client.connect_error = created.get("connect_error") created["client"] = client created["clients"].append(client) return client @@ -131,39 +135,160 @@ async def test_off_is_the_first_thing_on_the_new_link(fake_bleak): await device.shutdown() -async def test_a_write_retry_does_not_write_off(fake_bleak): - """The retry path carries the caller's own command; 'off' would cancel it.""" +async def test_a_command_whose_write_dies_with_the_link_is_sent_on_reconnect(fake_bleak, clock): + """No reconnect inside the write: it held the command lock, and the flow + behind it, for seconds. The command is remembered, the call returns, and the + reconnect delivers it -- once, and never behind an 'off'.""" _module, created = fake_bleak device = await _initialized() original = device._client - failing = {"first": True} calls = {"n": 0} - async def _flaky(char, data, response=False): + async def _dies(char, data, response=False): calls["n"] += 1 - if failing["first"]: - failing["first"] = False - original.is_connected = False # a real drop: retries only fire when the link is down - raise OSError("link dropped mid-write") - original.written.append(bytes(data)) - - device._client.write_gatt_char = _flaky - # original.is_connected is still True here, so _ensure_connected()'s first, - # unconditional call short-circuits and op() runs straight into _flaky, - # which drops the link and raises -- that drives _with_retry into its - # reconnect branch, the reconnect-inside-a-write path this test polices. + original.is_connected = False # the link went down under this write + raise OSError("link dropped mid-write") + + original.write_gatt_char = _dies clients_before = len(created["clients"]) - await device.pulse(500, 10) - await asyncio.sleep(0) + await asyncio.wait_for(device.pulse(500, 10), timeout=0.5) + await _settle(device) + written = await _first_write_on_the_new_link(device) - # Prove the retry path was actually taken, not skipped: _flaky was entered - # (and raised) exactly once, and a fresh client was built to carry the - # retried write -- so the write that landed did not go through _flaky - # again. assert calls["n"] == 1 assert len(created["clients"]) == clients_before + 1 - assert device._client is not original - assert b"off" not in device._client.written - assert device._client.written == [b"500,10"] + assert written == [b"500,10"] + await device.shutdown() + + +async def test_a_bounced_link_resends_what_is_left_at_that_later_moment(fake_bleak, clock): + """The resend is worked out when it is sent, not before a second drop: a + figure computed before the bounce would run the train past its end.""" + _module, created = fake_bleak + device = await _initialized() + await device.train(10, 40, 1200) + first_resend = {"done": False} + original_hook = device._on_reconnected + + async def _bounce_once(): + if not first_resend["done"]: + first_resend["done"] = True + clock[0] += 30 # the bounce costs time + device._client.drop() + await original_hook() + + device._on_reconnected = _bounce_once + clock[0] += 100 + created["client"].drop() + await asyncio.wait_for(device._reconnect_task, timeout=5) + + assert device.link_state is ConnectionState.CONNECTED + assert device._client.written == [b"p10,40,1070"] + await device.shutdown() + + +# --- putting the last command back --------------------------------------------- + + +@pytest.fixture +def clock(monkeypatch): + """The device's view of time, moved by hand: [now] in seconds.""" + now = [1000.0] + monkeypatch.setattr( + "glider_maimu.device.time", types.SimpleNamespace(perf_counter=lambda: now[0]) + ) + return now + + +async def _first_write_on_the_new_link(device): + for _ in range(200): + if device._client.written: + return device._client.written + await asyncio.sleep(0) + raise AssertionError("nothing was written after the reconnect") + + +async def test_a_train_cut_off_by_a_drop_resumes_for_what_is_left(fake_bleak, clock): + _module, created = fake_bleak + device = await _initialized() + await device.train(10, 40, 1200) + assert created["client"].written == [b"p10,40,1200"] + + clock[0] += 200.4 + created["client"].drop() + await _settle(device) + + assert await _first_write_on_the_new_link(device) == [b"p10,40,999"] + await device.shutdown() + + +async def test_a_symmetric_train_resumes_in_the_original_form(fake_bleak, clock): + _module, created = fake_bleak + device = await _initialized() + await device.pulse(500, 10) + + clock[0] += 3.5 + created["client"].drop() + await _settle(device) + + assert await _first_write_on_the_new_link(device) == [b"500,6"] + await device.shutdown() + + +@pytest.mark.parametrize("elapsed", [1200.0, 1199.5, 5000.0]) +async def test_a_train_with_under_a_second_left_comes_back_off(fake_bleak, clock, elapsed): + _module, created = fake_bleak + device = await _initialized() + await device.train(10, 40, 1200) + + clock[0] += elapsed + created["client"].drop() + await _settle(device) + + assert await _first_write_on_the_new_link(device) == [b"off"] + await device.shutdown() + + +@pytest.mark.parametrize("command, expected", [("on", b"on"), ("off", b"off")]) +async def test_on_and_off_are_put_back_as_they_were(fake_bleak, command, expected): + _module, created = fake_bleak + device = await _initialized() + await getattr(device, command)() + + created["client"].drop() + await _settle(device) + + assert await _first_write_on_the_new_link(device) == [expected] + await device.shutdown() + + +async def test_commands_during_a_drop_return_at_once_and_the_newest_wins(fake_bleak, clock): + """Zone enter/exit kept firing while the link was down. Each used to block + the flow behind the reconnect and then land in a burst, oldest first.""" + _module, created = fake_bleak + device = await _initialized() + created["connect_error"] = OSError("out of range") + created["client"].drop() + for _ in range(20): + await asyncio.sleep(0) + assert device.link_state is ConnectionState.RECONNECTING + + await asyncio.wait_for(device.train(10, 40, 1200), timeout=0.5) # mouse enters + await asyncio.wait_for(device.off(), timeout=0.5) # mouse leaves + await asyncio.wait_for(device.train(10, 40, 1200), timeout=0.5) # and back in + + assert all(client.written == [] for client in created["clients"][1:]) + + created["connect_error"] = None # back in range + await _settle(device) + assert await _first_write_on_the_new_link(device) == [b"p10,40,1200"] + await device.shutdown() + + +async def test_shutdown_forgets_the_last_command(fake_bleak): + _module, created = fake_bleak + device = await _initialized() + await device.train(10, 40, 1200) await device.shutdown() + assert device._desired is None diff --git a/plugins/glider-maimu/tests/test_node.py b/plugins/glider-maimu/tests/test_node.py index 3ce2257b..e6c628e9 100644 --- a/plugins/glider-maimu/tests/test_node.py +++ b/plugins/glider-maimu/tests/test_node.py @@ -76,7 +76,7 @@ async def test_off_sends_the_duty_cycle_command(): node = _node(mode="pulse", period_ms=10, duration_s=10) node.off_ms = 40 await node.hardware_operation() - assert node._device.calls == [("write", ("p10", 40, 10))] + assert node._device.calls == [("train", (10, 40, 10))] def test_off_round_trips_and_old_files_default_to_symmetric(): diff --git a/plugins/glider-maimu/tests/test_pulse_schema.py b/plugins/glider-maimu/tests/test_pulse_schema.py index c728be85..f4414ceb 100644 --- a/plugins/glider-maimu/tests/test_pulse_schema.py +++ b/plugins/glider-maimu/tests/test_pulse_schema.py @@ -28,9 +28,15 @@ def test_pulse_declares_both_arguments(): ] -def test_pulse_is_the_only_declared_action(): +def test_pulse_and_train_are_the_only_declared_actions(): """on/off/write need nothing; declaring them would only add empty forms.""" - assert set(MaimuDevice.ACTION_ARGS_SCHEMA) == {"pulse"} + assert set(MaimuDevice.ACTION_ARGS_SCHEMA) == {"pulse", "train"} + + +def test_train_declares_its_arguments_in_signature_order(): + """The panels pass these positionally; a swap would invert on and off.""" + params = list(inspect.signature(MaimuDevice.train).parameters)[1:] + assert [f["key"] for f in _device().action_args_schema("train")] == params def test_the_declared_order_matches_the_signature(): diff --git a/src/glider/gui/main_window.py b/src/glider/gui/main_window.py index c22990cf..9c1855cf 100644 --- a/src/glider/gui/main_window.py +++ b/src/glider/gui/main_window.py @@ -2554,10 +2554,10 @@ def _on_device_link_change(self, device_id: str, state) -> None: if self._core.state != SessionState.RUNNING: return if state is BoardConnectionState.ERROR: - # ERROR is the bounded reconnect loop's own terminal give-up state - # (12 attempts -- see BLEDevice.MAX_RECONNECT_ATTEMPTS), reached - # only after retrying is already over, so unlike DISCONNECTED this - # is not "hang on" -- it is "go and look at this". + # ERROR is the reconnect loop's own terminal give-up state, reached + # only when a device sets a finite MAX_RECONNECT_ATTEMPTS and + # retrying is already over, so unlike DISCONNECTED this is not + # "hang on" -- it is "go and look at this". body = ( f"{label} could not be reconnected and needs attention. " "GLIDER has stopped retrying; the experiment has not been paused." diff --git a/src/glider/hal/devices/ble_device.py b/src/glider/hal/devices/ble_device.py index 939bf0f1..4fd8f0d1 100644 --- a/src/glider/hal/devices/ble_device.py +++ b/src/glider/hal/devices/ble_device.py @@ -26,6 +26,7 @@ """ import asyncio +import itertools import logging import time from collections.abc import Callable @@ -118,6 +119,9 @@ class BLEDevice(BaseDevice): def __init__(self, board: "BaseBoard", config: DeviceConfig, name: str | None = None): super().__init__(board, config, name) self._resolved_address: str | None = None + # True once the advertised name has been heard on this host, which is + # what makes looking for it first on a reconnect worth the scan. + self._name_seen = False self._apply_setting_caches(config.settings) # validates; sets the caches self._client = None # BleakClient, created in initialize() @@ -268,16 +272,25 @@ async def poll_link(self) -> None: # --- reconnect --- - #: Backoff base, doubling per attempt. Deliberately the same numbers as - #: BaseBoard._attempt_reconnect: a peripheral and a board that drop for the - #: same reason should not retry on two different rhythms. - RECONNECT_BASE_S: float = 5.0 - RECONNECT_MAX_BACKOFF_S: float = 60.0 - MAX_RECONNECT_ATTEMPTS: int = 12 + #: Backoff base, doubling per attempt after an immediate first try. Much + #: tighter than BaseBoard._attempt_reconnect on purpose: a peripheral worn + #: by an animal drops for a second at a time, mid-run, and every second + #: spent waiting is a second of stimulus the animal did not get. A failed + #: attempt is itself a scan of several seconds, so this cannot hammer the + #: adapter. + RECONNECT_BASE_S: float = 0.5 + RECONNECT_MAX_BACKOFF_S: float = 2.0 + #: None = keep trying for as long as the device is initialized. A limit + #: gave up mid-experiment and left the device dead until someone noticed. + MAX_RECONNECT_ATTEMPTS: int | None = None def _backoff_for(self, attempt: int) -> float: - """Seconds to wait before ``attempt`` (0-based): 5, 10, 20, 40, 60, 60…""" - return min(self.RECONNECT_BASE_S * (2**attempt), self.RECONNECT_MAX_BACKOFF_S) + """Seconds to wait before ``attempt`` (0-based): 0, 0.5, 1, 2, 2, 2…""" + if attempt == 0: + return 0.0 + # Exponent capped so an endless retry never overflows the float. + doubling = 2 ** min(attempt - 1, 30) + return min(self.RECONNECT_BASE_S * doubling, self.RECONNECT_MAX_BACKOFF_S) async def _on_reconnected(self) -> None: """Hook: the link is back up and any subscription has been restored. @@ -317,13 +330,17 @@ def _start_reconnect(self) -> None: self._reconnect_task.add_done_callback(log_task_exception) async def _reconnect_loop(self) -> None: - """Retry with bounded exponential backoff; give up into ERROR. + """Retry at once, then on a short backoff, until the link is back. - Mirrors BaseBoard._attempt_reconnect, including clearing the task - handle in ``finally`` so a later drop can start a fresh one. + Only a finite ``MAX_RECONNECT_ATTEMPTS`` gives up into ERROR. Clears + the task handle in ``finally``, as BaseBoard._attempt_reconnect does, so + a later drop can start a fresh one. """ + limit = self.MAX_RECONNECT_ATTEMPTS + attempts = itertools.count() if limit is None else range(limit) + started = time.perf_counter() try: - for attempt in range(self.MAX_RECONNECT_ATTEMPTS): + for attempt in attempts: try: await asyncio.sleep(self._backoff_for(attempt)) except asyncio.CancelledError: @@ -365,6 +382,7 @@ async def _reconnect_loop(self) -> None: self._set_link(ConnectionState.CONNECTED) return self._client = None + await self._look_for_name_first() await self._ensure_connected() # _ensure_connected() publishes CONNECTED itself the moment the # socket is up, but the required order is subscribe-then-publish: @@ -388,11 +406,14 @@ async def _reconnect_loop(self) -> None: # genuinely is connected. A half-usable client is worse than # none, so the next attempt has to rebuild from nothing. self._client = None - logger.info( - "BLE %s: reconnect attempt %d/%d failed (%s)", + # Every attempt for the first few, then one line in thirty: + # a retry that never gives up must not bury the log. + logger.log( + logging.INFO if attempt < 5 or attempt % 30 == 0 else logging.DEBUG, + "BLE %s: reconnect attempt %d%s failed (%s)", self._name, attempt + 1, - self.MAX_RECONNECT_ATTEMPTS, + "" if limit is None else f"/{limit}", e, ) self._set_link(ConnectionState.RECONNECTING) @@ -400,29 +421,74 @@ async def _reconnect_loop(self) -> None: # The link is up. Say so before running the hook: it is true, # and an override that writes needs write() to work. + logger.info( + "BLE %s: reconnected after %.1f s (%d attempt%s)", + self._name, + time.perf_counter() - started, + attempt + 1, + "" if attempt == 0 else "s", + ) self._set_link(ConnectionState.CONNECTED) + hook_error = None try: await self._on_reconnected() except asyncio.CancelledError: raise - except Exception as e: # noqa: BLE001 - the link is still up + except Exception as e: # noqa: BLE001 - reported below + hook_error = e + client = self._client + if self._initialized and (client is None or not client.is_connected): + # The link died again while the hook ran -- a plug that + # bounced, a peripheral at the edge of range. Its disconnect + # callback found this loop still running and so started + # nothing; carry on here rather than leave the device + # resting at DISCONNECTED with no one retrying it. + logger.info( + "BLE %s: link dropped again right after reconnecting; retrying", + self._name, + ) + self._set_link(ConnectionState.RECONNECTING) + continue + if hook_error is not None: logger.warning( "BLE %s: post-reconnect hook failed (%s); the link is up " "but the device may not be in its safe state", self._name, - e, + hook_error, ) return logger.error( "BLE %s: gave up reconnecting after %d attempts", self._name, - self.MAX_RECONNECT_ATTEMPTS, + limit, ) self._set_link(ConnectionState.ERROR) finally: self._reconnect_task = None + async def _look_for_name_first(self) -> None: + """On a reconnect, find the peripheral by name before trying its address. + + A peripheral using BLE privacy picks a fresh random address every time + it starts advertising -- which is every time a link drops -- so the + address that just went away is the one most certain to be gone, and + looking for it first cost every reconnect a full scan for nothing. The + name does not change, and a scan for it returns the moment the + peripheral is heard, at whatever address it has now. + + Only for a name this session has actually seen advertised: a + peripheral whose name never reaches this host would otherwise pay an + extra scan per attempt. Failure is not an error here; the address and + service paths in _ensure_connected() still run. + """ + if not (self._adv_name and self._name_seen): + return + try: + await self._find_by_name() + except Exception as e: # noqa: BLE001 - fall through to the other paths + logger.debug("BLE %s: name %r not heard yet (%s)", self._name, self._adv_name, e) + async def _resubscribe(self) -> None: """Restore the notify subscription on a freshly built client. @@ -566,6 +632,7 @@ async def _find_by_name(self) -> str: f"advertising -- or out of range." ) self._resolved_address = dev.address + self._name_seen = True logger.info("BLE: resolved name %r -> %s", self._adv_name, dev.address) return dev.address @@ -593,6 +660,8 @@ async def _ensure_connected(self) -> None: target = await BleakScanner.find_device_by_address(address, timeout=RESOLVE_SCAN_S) if target is None: raise RuntimeError(f"Device with address {address} was not found") + if self._adv_name and getattr(target, "name", None) == self._adv_name: + self._name_seen = True client = BleakClient(target, disconnected_callback=self._on_disconnected) await client.connect() except Exception as exc: @@ -807,11 +876,17 @@ async def _with_retry(self, op: Callable) -> Any: await self._ensure_ready() return await op() - async def write(self, *args: Any) -> None: + async def write(self, *args: Any, retry: bool = True) -> None: """Write a command to ``write_char_uuid`` (comma-joins multiple args). - Auto-detects the write mode from the characteristic and retries once - after a reconnect if the link dropped. + Auto-detects the write mode from the characteristic and, by default, + retries once after a reconnect if the link dropped. + + ``retry=False`` sends once over the link as it stands -- no connect, no + retry -- and raises ConnectionError if there is no live link. That is for + a caller that owns its own recovery: a device whose reconnect hook puts + its state back has nothing to gain from a reconnect inside a write, which + would only hold that caller (and anything waiting on it) up for seconds. """ if not args or all(a is None for a in args): raise ValueError("BLE.write: command is required") @@ -822,11 +897,19 @@ async def write(self, *args: Any) -> None: async with self._lock: if not self._initialized: raise RuntimeError(f"BLE device {self._name} is not initialized") - await self._with_retry( - lambda: self._client.write_gatt_char( + + def op(): + return self._client.write_gatt_char( self._write_char, data, response=self._effective_response() ) - ) + + if retry: + await self._with_retry(op) + else: + client = self._client + if client is None or not client.is_connected: + raise ConnectionError(f"BLE device {self._name}: link is down") + await op() logger.info("BLE: wrote %r to %s", command, self._write_char) async def read(self) -> Any: diff --git a/tests/unit/gui/shell/test_main_window_shell.py b/tests/unit/gui/shell/test_main_window_shell.py index 898b37e1..d6b802d5 100644 --- a/tests/unit/gui/shell/test_main_window_shell.py +++ b/tests/unit/gui/shell/test_main_window_shell.py @@ -658,8 +658,8 @@ def test_a_device_drop_during_a_run_notifies_without_pausing_or_the_dialog( def test_error_and_disconnected_get_different_wording(qtbot, main_window_factory, monkeypatch): - """ERROR is the reconnect loop's own terminal give-up state (12 attempts -- - see BLEDevice.MAX_RECONNECT_ATTEMPTS): retrying is over by the time it + """ERROR is the reconnect loop's own terminal give-up state (only with a + finite BLEDevice.MAX_RECONNECT_ATTEMPTS): retrying is over by the time it fires, so it must not tell the operator to sit tight the way a fresh DISCONNECTED does.""" from glider.core.experiment_session import SessionState diff --git a/tests/unit/hal/test_ble_device_full.py b/tests/unit/hal/test_ble_device_full.py index 2bdf4a3d..9e18720b 100644 --- a/tests/unit/hal/test_ble_device_full.py +++ b/tests/unit/hal/test_ble_device_full.py @@ -6,6 +6,7 @@ test_ble_device.py; this file covers the read/notify superset.) """ +import asyncio import sys import time @@ -703,3 +704,48 @@ async def _scan(timeout=8.0): assert rotating_bleak.attempts == ["BB:NEW"] assert scanned == [], "the service scan ran even though the name resolved" + + +async def _reconnected(device, timeout=5.0): + from glider.hal.base_board import ConnectionState + + deadline = time.monotonic() + timeout + while device.link_state is not ConnectionState.CONNECTED or device._reconnect_task: + assert time.monotonic() < deadline, "never reconnected" + await asyncio.sleep(0.001) + + +async def test_a_reconnect_looks_for_the_name_before_the_address_that_dropped(rotating_bleak): + """A private address re-rolls every time the peripheral re-advertises, + which is after every drop. Scanning for the address that just went away + cost every reconnect a full scan for nothing; the name finds the peripheral + at whatever address it has now.""" + device = _make_device( + settings={"address": "AA:OLD", "name": "maimu_ezurio", "write_char_uuid": "c"} + ) + await device.initialize() # the name rescued AA:OLD -> BB:NEW + rotating_bleak.lookups.clear() + rotating_bleak.old_address, rotating_bleak.new_address = "BB:NEW", "CC:NEWER" + + device._client.is_connected = False + device._on_disconnected(device._client) + await _reconnected(device) + + assert "BB:NEW" not in [a for a, _ in rotating_bleak.lookups] + assert rotating_bleak.attempts[-1] == "CC:NEWER" + assert rotating_bleak.scans == 2 + await device.shutdown() + + +async def test_a_name_never_heard_does_not_cost_a_reconnect_a_scan(fake_bleak): + """A peripheral whose name never reaches this host would pay an extra, + failing scan on every attempt.""" + _module, created = fake_bleak + device = await _initialized({"address": "AA:BB", "name": "n", "write_char_uuid": "c"}) + + device._client.is_connected = False + device._on_disconnected(device._client) + await _reconnected(device) + + assert "scanned_name" not in created + await device.shutdown() diff --git a/tests/unit/hal/test_ble_device_reconnect.py b/tests/unit/hal/test_ble_device_reconnect.py index 454b55bc..1f1443a8 100644 --- a/tests/unit/hal/test_ble_device_reconnect.py +++ b/tests/unit/hal/test_ble_device_reconnect.py @@ -96,7 +96,7 @@ def make_client(address, *a, disconnected_callback=None, **k): def instant_backoff(monkeypatch): """Collapse the backoff so the suite runs in milliseconds, not minutes. - The 5/10/20/40/60 schedule itself is asserted separately by + The 0/0.5/1/2/2 schedule itself is asserted separately by test_backoff_doubles_to_the_cap, which calls _backoff_for directly -- unbound, passing the class in for self -- and reads the computed values off undisturbed RECONNECT_BASE_S/RECONNECT_MAX_BACKOFF_S. It never lives @@ -164,7 +164,31 @@ async def test_reconnect_builds_a_fresh_client(fake_bleak): await device.shutdown() -async def test_giving_up_lands_in_error(fake_bleak): +async def test_by_default_it_never_gives_up(fake_bleak): + """A limit gave up mid-experiment and left an animal's stimulator dead until + someone noticed. Keep retrying for as long as the device is in use, and + take the link back the moment the peripheral answers again.""" + _module, created = fake_bleak + device = await _initialized() + created["connect_error"] = OSError("peripheral is out of range") + before = len(created["clients"]) + created["client"].drop() + + deadline = time.monotonic() + 5 + while len(created["clients"]) - before < 20: + assert time.monotonic() < deadline, "the loop stopped retrying" + await asyncio.sleep(0.001) + assert device.link_state is ConnectionState.RECONNECTING + assert not device._reconnect_task.done() + + created["connect_error"] = None # back in range + await _settle(device) + assert device.link_state is ConnectionState.CONNECTED + await device.shutdown() + + +async def test_a_finite_limit_still_lands_in_error(fake_bleak, monkeypatch): + monkeypatch.setattr(BLEDevice, "MAX_RECONNECT_ATTEMPTS", 12) _module, created = fake_bleak device = await _initialized() created["connect_error"] = OSError("peripheral is gone") @@ -175,7 +199,8 @@ async def test_giving_up_lands_in_error(fake_bleak): await device.shutdown() -async def test_attempts_are_bounded(fake_bleak): +async def test_a_finite_limit_bounds_the_attempts(fake_bleak, monkeypatch): + monkeypatch.setattr(BLEDevice, "MAX_RECONNECT_ATTEMPTS", 12) _module, created = fake_bleak device = await _initialized() created["connect_error"] = OSError("gone") @@ -184,16 +209,23 @@ async def test_attempts_are_bounded(fake_bleak): task = device._reconnect_task await asyncio.wait_for(task, timeout=5) attempts = len(created["clients"]) - before - assert attempts == BLEDevice.MAX_RECONNECT_ATTEMPTS + assert attempts == 12 await device.shutdown() async def test_backoff_doubles_to_the_cap(monkeypatch): - """5 -> 10 -> 20 -> 40 -> 60 -> 60, matching BaseBoard._attempt_reconnect.""" - monkeypatch.setattr(BLEDevice, "RECONNECT_BASE_S", 5.0) - monkeypatch.setattr(BLEDevice, "RECONNECT_MAX_BACKOFF_S", 60.0) + """Straight away, then 0.5 -> 1 -> 2 and 2 from there on: a dropped link + on an animal costs stimulus for every second it stays down.""" + # instant_backoff collapsed these for the rest of the suite; put them back. + monkeypatch.setattr(BLEDevice, "RECONNECT_BASE_S", 0.5) + monkeypatch.setattr(BLEDevice, "RECONNECT_MAX_BACKOFF_S", 2.0) delays = [BLEDevice._backoff_for(BLEDevice, attempt) for attempt in range(6)] - assert delays == [5.0, 10.0, 20.0, 40.0, 60.0, 60.0] + assert delays == [0.0, 0.5, 1.0, 2.0, 2.0, 2.0] + + +async def test_backoff_survives_an_endless_retry(): + """An unbounded loop reaches attempt numbers whose 2**n overflows a float.""" + assert BLEDevice._backoff_for(BLEDevice, 100_000) == BLEDevice.RECONNECT_MAX_BACKOFF_S async def test_shutdown_during_backoff_cancels_the_task(fake_bleak): @@ -231,37 +263,49 @@ async def test_no_reconnect_after_shutdown(fake_bleak): assert device.link_state is ConnectionState.DISCONNECTED -async def test_poll_link_recovers_a_drop_that_lands_mid_hook(fake_bleak): +async def test_a_drop_that_lands_mid_hook_is_retried_by_the_loop(fake_bleak): """A drop that lands while _on_reconnected() is still awaiting must not - strand the device. + strand the device -- the bench case is a USB plug that bounces. _start_reconnect() correctly no-ops while the current loop task is still - (briefly) alive, but once that loop returns and its own `finally` clears - the task handle, the device is left resting at DISCONNECTED with nothing - left to retry it -- poll_link()'s backstop is the only thing that can - still notice and re-arm it. + alive, so the drop's own callback starts nothing. The loop has to notice + the link died under the hook and keep going, and then run the hook again + on the link that finally holds. """ _module, created = fake_bleak device = await _initialized() - dropped_once = {"done": False} + hook_runs = [] async def _drop_mid_hook(): + hook_runs.append(created["client"]) await asyncio.sleep(0) # yield so the drop below lands mid-await - if not dropped_once["done"]: - dropped_once["done"] = True + if len(hook_runs) == 1: created["client"].drop() device._on_reconnected = _drop_mid_hook created["client"].drop() task = device._reconnect_task - await task # run the whole loop, including the hook's own drop, to completion + await asyncio.wait_for(task, timeout=5) - assert device.link_state is ConnectionState.DISCONNECTED + assert device.link_state is ConnectionState.CONNECTED assert device._reconnect_task is None + assert len(hook_runs) == 2, "the hook did not run again on the link that held" + assert hook_runs[1] is device._client + await device.shutdown() - await device.poll_link() - await _settle(device) - assert device.link_state is ConnectionState.CONNECTED + +async def test_a_single_shot_write_never_connects(fake_bleak): + """retry=False is for a caller that owns its recovery: no link, no write, + and no reconnect started from inside it.""" + _module, created = fake_bleak + device = await _initialized(write_char_uuid="c") + device._client.is_connected = False + before = len(created["clients"]) + + with pytest.raises(ConnectionError): + await device.write("on", retry=False) + + assert len(created["clients"]) == before await device.shutdown()