diff --git a/custom_components/nvidia_shield/connection.py b/custom_components/nvidia_shield/connection.py index 924b8c2..0251c3a 100644 --- a/custom_components/nvidia_shield/connection.py +++ b/custom_components/nvidia_shield/connection.py @@ -330,6 +330,10 @@ class ShieldConnectionManager: PROTOCOL_NEVER_CONNECTED if self._protocol is not None else PROTOCOL_OFF ) self._protocol_last_error: str | None = None + # t20/O5: the connect ATTEMPT's task. Held so a second start recognises a + # live attempt instead of orphaning it; it is also tracked in ``_tasks`` so + # ``async_stop`` cancels it (t20/O4). + self._protocol_connect_task: asyncio.Task | None = None self._protocol_ever_authenticated = False self._protocol_failures = 0 @@ -403,6 +407,8 @@ class ShieldConnectionManager: watchdog is built here. Push callbacks write straight into the StateStore and ping registered listeners. """ + if self._stopping: + return # a stopped manager must not restart itself (t20/O4/O5) if self._protocol is None: if self._protocol_factory is None: if self._protocol_settings is None: @@ -412,6 +418,27 @@ class ShieldConnectionManager: client = self._protocol if client is None: return + # t20/O5: A SECOND START IS DETERMINISTIC. A live attempt is reused and an + # established session is left alone, so nothing is ever orphaned — and the + # guard sits BEFORE the push callbacks below, so a second call cannot + # register them twice either (which would double every device push). + attempt = self._protocol_connect_task + if attempt is not None and not attempt.done(): + _LOGGER.debug( + "Shield remote-protocol connect attempt already in flight — reusing it" + ) + return + if self._protocol_state in (PROTOCOL_CONNECTED, PROTOCOL_DISCONNECTED): + # A session exists (or existed and is being maintained): the LIBRARY's own + # keep-reconnecting loop owns it from here, and calling keep_reconnecting + # a second time would put a second loop over the same session — so a + # second start never builds one. + _LOGGER.debug( + "Shield remote-protocol session already handed to the library's " + "keep-reconnecting loop (state: %s) — no second attempt", + self._protocol_state, + ) + return # Real client: make sure local certificate material exists before it # connects (fails soft — pair flows can regenerate). generate_cert = getattr(client, "async_generate_cert_if_missing", None) @@ -444,6 +471,11 @@ class ShieldConnectionManager: self._protocol_connect_task = self._create_task( self._protocol_connect_loop(client), "shield_protocol_connect" ) + # t20/O4: TRACKED. Cancelling only the tasks the manager holds is what makes + # an unload complete: an untracked connect attempt kept retrying after its + # entry was gone, and since every options save reloads the entry those loops + # could accumulate across saves. + self._tasks.append(self._protocol_connect_task) async def _protocol_connect_loop(self, client) -> None: """Open the protocol session, then let the library keep it open (t15). @@ -489,9 +521,19 @@ class ShieldConnectionManager: # Connected: remember it as an authenticated session and hand the # socket to the library's own reconnect task (one owner per # transport — the stop path closes the client, which tears it down). + # t20/O2: the banner says only what THIS attempt proved. A + # successful async_connect() cannot know the device stays reachable, + # so it must not claim liveliness — that is the transport's own + # business from here (its availability push and the library's + # keep-reconnecting loop). The state announcement that follows is the + # log's last word on the transport, and it is the state the entity + # publishes: that is what keeps the two from contradicting. _LOGGER.info( - "Shield remote-protocol transport connected to %s", + "Shield remote-protocol session opened on %s — what this proves: " + "the client accepted a session; what maintains it from here: the " + "transport's own availability push (state: %s)", getattr(client, "host", self.entry.title if self.entry else "?"), + PROTOCOL_CONNECTED, ) self._protocol_ever_authenticated = True self._note_protocol_state(PROTOCOL_CONNECTED, None) @@ -555,8 +597,11 @@ class ShieldConnectionManager: """ self._protocol_ever_authenticated = True if field == FIELD_IS_AVAILABLE: - self._protocol_state = ( - PROTOCOL_CONNECTED if value else PROTOCOL_DISCONNECTED + # t20/O1: the transport's own availability report is the OTHER place a + # session becomes provable, so it takes the same route — a healthy push + # clears a recovered failure exactly as a successful connect does. + self._apply_protocol_state( + PROTOCOL_CONNECTED if value else PROTOCOL_DISCONNECTED, None ) self.store.set(field, value) loop = self._protocol_loop @@ -645,13 +690,78 @@ class ShieldConnectionManager: return self._protocol_failures - def _note_protocol_state(self, state: str, error: str | None) -> None: - """Record the transport state (and an error when there is one) + notify.""" - changed = state != self._protocol_state + def _apply_protocol_state(self, state: str, error: str | None) -> bool: + """Set the published pair and announce a TRANSITION; True if it changed. + + One place decides what the pair MEANS (``_note_protocol_state`` documents + it) and one place decides when a change is announced, so a connect attempt + and a device push cannot publish two different stories. + """ + previous = self._protocol_state + state_changed = state != previous self._protocol_state = state - if error is not None: + error_changed = False + if state == PROTOCOL_CONNECTED: + # t20/O1: a proven session ENDS the failure episode. The recovery stays + # visible in ``protocol_failures`` (history), never as a stale message + # published next to ``protocol_connected: true``. + error_changed = self._forget_protocol_error() + elif error is not None: + error_changed = error != self._protocol_last_error self._protocol_last_error = error - if changed: + if state_changed: + self._announce_protocol_state(previous, state) + return state_changed or error_changed + + def _forget_protocol_error(self) -> bool: + """Drop a failure the transport has since recovered from (t20/O1). + + Returns True when there WAS one, so the caller knows listeners must be + told that a published attribute changed. + """ + if self._protocol_last_error is None: + return False + self._protocol_last_error = None + return True + + def _announce_protocol_state(self, previous: str, state: str) -> None: + """Announce a transport TRANSITION — this is what keeps banners honest. + + t20/O2 defines a STALE banner as one whose transport claim later state + changes never followed up on: the log's last word would then contradict what + the entity publishes. Every transition therefore logs one line naming both + states, at INFO for the two states a user acts on (a session came up, a + session went down) and at DEBUG otherwise (``never_connected`` repeats per + retry, and the auth rejection is already logged with its reason by + ``_on_invalid_auth``). + """ + _LOGGER.log( + logging.INFO + if state in (PROTOCOL_CONNECTED, PROTOCOL_DISCONNECTED) + else logging.DEBUG, + "Shield remote-protocol transport state: %s → %s", + previous, + state, + ) + + def _note_protocol_state(self, state: str, error: str | None) -> None: + """Record the transport state (and an error when there is one) + notify. + + WHAT THE PUBLISHED PAIR MEANS (t20/O1): ``protocol_state`` — and its + boolean twin ``protocol_connected`` — is the transport's CURRENT condition, + while ``protocol_last_error`` is the failure the current state has NOT + recovered from. A session becoming proven (a successful connect, or the + transport's own availability push) therefore CLEARS it, so an error can + never be published beside a healthy ``protocol_connected``. A failure that + happens AFTER the session came up is kept — that one is current, not stale. + Before this, ``_note_protocol_state(PROTOCOL_CONNECTED, None)`` left the + previous failure in place and the entity published ``protocol_last_error == + "connect: Net: boom"`` beside ``protocol_connected: true`` — on the very + attributes a user is told to read to answer "is the protocol working?" + (t19 review, O1). ``protocol_failures`` still counts, so a recovery remains + visible as history instead of as a stale message. + """ + if self._apply_protocol_state(state, error): self._notify() def _note_protocol_send_failure(self, what: str, err) -> None: @@ -1802,6 +1912,12 @@ class ShieldConnectionManager: tasks, self._tasks = self._tasks, [] for task in tasks: task.cancel() + # t20/O4: cancel() only SCHEDULES the cancellation, and an unload that + # returns while a connect attempt is still running is exactly how a loop + # outlived its entry. Await them: their exceptions (CancelledError included) + # are results here, not failures — being cancelled IS how a manager task ends. + if tasks: + await asyncio.gather(*tasks, return_exceptions=True) self._listeners.clear() self._last_known.clear() self._app_labels.clear() diff --git a/custom_components/nvidia_shield/remote.py b/custom_components/nvidia_shield/remote.py index 7a0f068..0c989fa 100644 --- a/custom_components/nvidia_shield/remote.py +++ b/custom_components/nvidia_shield/remote.py @@ -238,7 +238,14 @@ class NvidiaShieldRemoteEntity(RemoteEntity): * ``protocol_current_app_seen`` / ``protocol_is_on_seen`` / ``protocol_volume_seen`` — whether each device push has EVER arrived. * ``protocol_last_error`` / ``protocol_failures`` — a send that could not - run is recorded here and logged, never swallowed into a debug line. + run is recorded here and logged, never swallowed into a debug line. The + ERROR is the failure the CURRENT state has not recovered from (t20/O1): + it is cleared as soon as a session is proven again — the next connect or + the transport's own availability push — so it can never read as a + problem beside ``protocol_connected: true``, and a failure that happened + AFTER the session came up is kept because that one is still current. + ``protocol_failures`` keeps counting, so a recovery stays visible as + history instead of as a stale message. * ``protocol_certificate`` — the setup pairing's shared ``client.pem`` is still on disk, which is exactly why enabling the transport asks for no new PIN (the other Android TV integration pairs its own client). diff --git a/tests/ha_api_drift.py b/tests/ha_api_drift.py index 41b3494..cab59fb 100644 --- a/tests/ha_api_drift.py +++ b/tests/ha_api_drift.py @@ -143,8 +143,38 @@ HA_CALL_OWNERS: dict[str, tuple[str, str]] = { #: Non-vacuity floors — the ONE source of truth for the standalone entry point #: and the pytest wrapper (t39 F1). They sit below the current walk (26 modules, #: 77 imports, 282 relative imports, 65 checked arguments, 6 awaited HA calls, -#: 1637 statement blocks) so a broken or mis-targeted walk fails loudly instead of +#: 1648 statement blocks) so a broken or mis-targeted walk fails loudly instead of #: printing zeros and exiting 0. +#: +#: THE MARGIN POLICY (t20/O3 — the t19 review asked for this in writing). A floor +#: is a VACUITY-AND-BLINDNESS alarm, not a size ratchet: it must fail when the walk +#: stops COVERING something (a broken glob, a regex that stopped matching, a module +#: that stopped being parsed), and it must not fail because a legitimate change +#: removed code. The margins follow from that, per counter: +#: +#: * counters where ONE unit is one API OWNER (modules, imports, call_args): 2. +#: One owner may be refactored away; a whole CLASS of owners going unseen (the +#: t62 F2 case, where deleting `async_show_menu` from HA_CALL_OWNERS left the +#: sweep green) is what the 2 catches. This is the project's long-standing +#: canary (t62 wrote it as "two below the count"), now stated once instead of +#: being implied by each raise. +#: * relative_imports: ~2.5%, currently 7. The count is dominated by package- +#: relative imports that legitimately churn when files move; a collapse (an +#: unparsed module, a stale glob) is orders of magnitude, not 7. +#: * statement_blocks: ~2%, currently 28. This counter moves in BULK with every +#: edit, which is exactly why a fixed small margin would be wrong here (the +#: t19 complaint: at 1300 vs 1322 a 23-statement refactor tripped it). A 2% +#: band leaves a normal refactor alone while a parse failure still shows up as +#: a large drop. +#: * awaited_calls: 1 (5 vs 6). Stated plainly: with six awaited HA calls a +#: percentage margin is meaningless, so this floor is the weakest one here. It +#: is still worth having — a walk that stopped visiting `await` sites at all +#: trips it — but a deliberate removal of an awaited call MUST lower this floor +#: in the same commit, and that is the reviewable act the gate exists for. +#: +#: The rule for changing any of them: lower a floor in the SAME commit that removes +#: the code it counts, and never raise one without re-running the sweep first (a +#: floor above the walk is a gate that can never pass). FLOORS: dict[str, int] = { # t41: the sweep is recursive, so the floor sits above the top-level-only # count (13) — a regression to the shallow glob trips it. @@ -198,7 +228,10 @@ FLOORS: dict[str, int] = { # validator, the command builder and the button are new statement blocks, and # the unreachable pass is what keeps covering them — which is the point of the # floor: a pass that silently stopped parsing must not look green. - "statement_blocks": 1620, + # t20: the walk is 1648 after the protocol lifecycle fixes (the tracked + # attempt, the cancel-and-await stop and the transition banner are new blocks), + # so the floor is re-derived from the CURRENT walk at the 2% band above. + "statement_blocks": 1615, } #: The interpreter floor Home Assistant itself declares: PyPI metadata for diff --git a/tests/test_command_routing.py b/tests/test_command_routing.py index 393657a..9424561 100644 --- a/tests/test_command_routing.py +++ b/tests/test_command_routing.py @@ -531,6 +531,39 @@ class TestRemoteActivityContract: assert attrs["protocol_failures"] == 0 assert attrs["power_on_route"] == "protocol" + def test_a_recovered_transport_is_not_published_as_broken(self, modules): + """t20/O1 at the ENTITY: the pair a user reads cannot contradict itself. + + The review measured ``protocol_last_error == "connect: Net: boom"`` beside + ``protocol_connected: true``. Both halves are driven here through the + manager's own paths — a send that could not run while the transport was + absent, then the transport reporting a session — and read back from the + attributes a user is told to look at. + """ + entity = _remote_entity(modules) + manager = entity._manager + client = manager._protocol + + manager._protocol = None # the transport is gone + assert asyncio.run(manager.send_protocol_key("POWER")) is False + entity._refresh_state() + assert entity.extra_state_attributes["protocol_last_error"], ( + "a failure that still describes the transport is recorded" + ) + + manager._protocol = client # ...and the transport comes back + manager._on_is_available(True) # its own proof of a session + entity._refresh_state() + + attrs = entity.extra_state_attributes + assert attrs["protocol_state"] == "connected" + assert attrs["protocol_connected"] is True + assert attrs["protocol_last_error"] is None, ( + "a recovered failure must not be published beside protocol_connected: " + "true (t20/O1)" + ) + assert attrs["protocol_failures"] == 1, "the history stays in the counter" + def test_no_protocol_reads_as_off_not_as_unpaired(self, modules): entity = _remote_entity(modules) entity._manager._protocol = None diff --git a/tests/test_protocol_transport.py b/tests/test_protocol_transport.py index bbf3a5b..6be6144 100644 --- a/tests/test_protocol_transport.py +++ b/tests/test_protocol_transport.py @@ -23,6 +23,7 @@ from nsh.connection import ( FIELD_RUNNING_APPS, FIELD_SESSIONS, FIELD_VOLUME_INFO, + PROTOCOL_CONNECTED, ShieldConnectionManager, StateStore, volume_tuple, @@ -740,3 +741,345 @@ class TestVolumeTuple: androidtvremote2 = pytest.importorskip("androidtvremote2") info = androidtvremote2.VolumeInfo(level=3, max=15, muted=True) assert volume_tuple(info) == (3.0, 15.0, True) + + +# ── t20: the t19 review's protocol findings ── + + +class HangingProtocolClient(FakeProtocolClient): + """``async_connect()`` that never returns until the test says so (t20). + + The lifecycle findings are about what happens WHILE an attempt is in flight, + so the fake has to be able to sit inside ``async_connect``: it parks on an + event, records how many times it was cancelled, and only then - if it is ever + released - becomes a session. + """ + + def __init__(self): + super().__init__() + self.entered = asyncio.Event() + self.release = asyncio.Event() + self.cancelled = 0 + + async def async_connect(self): + self.connect_calls += 1 + self.entered.set() + try: + await self.release.wait() + except asyncio.CancelledError: + self.cancelled += 1 + raise + self._remote_message_protocol = object() + + +class OnceFailingProtocolClient(FakeProtocolClient): + """Fails its first attempts, then connects - the RECOVERY sequence (t20/O1).""" + + def __init__(self, failures: int = 1, error: Exception | None = None): + super().__init__() + self._failures_left = failures + self._error = error or CannotConnect("Net: boom") + + async def async_connect(self): + self.connect_calls += 1 + if self._failures_left > 0: + self._failures_left -= 1 + raise self._error + self._remote_message_protocol = object() + + +class TestRecoveredErrorsAreNotStale: + """t20/O1: the published pair can never contradict itself. + + ``protocol_state``/``protocol_connected`` is the transport's CURRENT + condition; ``protocol_last_error`` is the failure the CURRENT state has not + recovered from. It is cleared whenever a session becomes proven and kept while + the transport is still down (and, deliberately, kept for a failure that + happened AFTER the session came up - that one is current, not stale). + """ + + async def test_failure_then_recovery_publishes_no_stale_error(self): + """The measured defect: 'connect: Net: boom' beside connected: true.""" + client = OnceFailingProtocolClient() + manager = _protocol_manager(client) + _fast_backoff(manager) + await manager._start_protocol() + + for _ in range(200): # the failure is recorded while it is still down + if manager.protocol_last_error: + break + await asyncio.sleep(0.005) + assert manager.protocol_state == "never_connected" + assert manager.protocol_connected is False + assert "CannotConnect" in (manager.protocol_last_error or "") + + for _ in range(400): # the retry succeeds + if manager.protocol_connected: + break + await asyncio.sleep(0.005) + + assert manager.protocol_connected is True + assert manager.protocol_last_error is None, ( + "a recovered failure must not be published beside connected: true" + ) + assert manager.protocol_failures == 0, "a connect failure is not a SEND failure" + await manager.async_stop() + + async def test_failure_then_still_disconnected_keeps_the_error(self): + """The other direction: a failure that still describes the transport stays.""" + client = FakeProtocolClient(connect_error=CannotConnect("Net: boom")) + manager = _protocol_manager(client) + manager._jitter = lambda delay: 60.0 # one attempt, then sleep past the test + await manager._start_protocol() + await _connect(manager, client) + + assert manager.protocol_state == "never_connected" + assert manager.protocol_connected is False + assert "Net: boom" in (manager.protocol_last_error or "") + await manager.async_stop() + + async def test_a_send_failure_before_a_session_is_cleared_by_the_connect(self): + """The review's exact sequence, driven through public calls.""" + client = FakeProtocolClient() + manager = _protocol_manager(client) + + assert await manager.send_protocol_key("POWER") is False # no session yet + assert manager.protocol_last_error, "the current failure is recorded" + + await manager._start_protocol() + await _connect(manager, client) + + assert manager.protocol_connected is True + assert manager.protocol_last_error is None, "recovery clears it" + assert manager.protocol_failures == 1, "history stays in the counter" + await manager.async_stop() + + async def test_an_availability_push_also_clears_a_recovered_error(self): + """A push is the OTHER proof of a live session, so it clears it too.""" + client = FakeProtocolClient(connect_error=CannotConnect("Net: boom")) + manager = _protocol_manager(client) + manager._jitter = lambda delay: 60.0 # the retry cannot race this assertion + await manager._start_protocol() + await _connect(manager, client) + assert manager.protocol_last_error + + client.push_is_available(True) + await _drain_loop() + + assert manager.protocol_state == "connected" + assert manager.protocol_last_error is None + await manager.async_stop() + + async def test_a_send_failure_after_the_session_came_up_is_current(self): + """Not the same thing as stale: the session failed just now.""" + client = FakeProtocolClient() + manager = _protocol_manager(client) + await manager._start_protocol() + await _connect(manager, client) + assert manager.protocol_last_error is None + + client._remote_message_protocol = None # the session is gone + assert await manager.send_protocol_key("POWER") is False + assert "POWER" in (manager.protocol_last_error or "") + + # ...and a session proven again clears it + client._remote_message_protocol = object() + client.push_is_available(True) + await _drain_loop() + assert manager.protocol_last_error is None + await manager.async_stop() + + async def test_recovery_notifies_listeners_because_a_published_value_changed(self): + """The error is an attribute: clearing it is a state change to publish.""" + manager = _protocol_manager(FakeProtocolClient()) + notified = [] + manager.register_listener(lambda: notified.append(manager.protocol_last_error)) + + await manager.send_protocol_key("POWER") # records an error + assert manager.protocol_last_error + before = len(notified) + + manager._note_protocol_state(PROTOCOL_CONNECTED, None) + + assert len(notified) > before, "listeners were told the error went away" + assert manager.protocol_last_error is None + + +class TestConnectAttemptLifecycle: + """t20/O4 + O5: the connect attempt is tracked, and a second start is defined. + + Both findings interact with the options UI: every save reloads the entry, so an + attempt that survives its entry (or a start that orphans an earlier one) can + accumulate reconnect loops across saves. + """ + + async def test_unload_during_a_connect_attempt_cancels_and_awaits_it(self): + """The proof for O4: no live task, and no further connect attempts.""" + client = HangingProtocolClient() + manager = _protocol_manager(client) + _fast_backoff(manager) + await manager._start_protocol() + await asyncio.wait_for(client.entered.wait(), 1) + + task = manager._protocol_connect_task + assert task is not None and not task.done() + assert task in manager._tasks, "tracked, so unload can cancel it (O4)" + assert client.connect_calls == 1 + + await manager.async_stop() + + assert task.done(), "the unload AWAITED the attempt" + assert task.cancelled() + assert client.cancelled == 1, "the in-flight connect was cancelled" + assert manager._tasks == [], "nothing is left to leak into the next reload" + + calls = client.connect_calls + for _ in range(20): + await asyncio.sleep(0.01) + assert client.connect_calls == calls, "no attempt survives the entry" + + async def test_async_start_tracks_every_loop_and_stop_reaps_them(self): + client = HangingProtocolClient() + manager = _protocol_manager(client) + _fast_backoff(manager) + + await manager.async_start() # the watchdog (passive here) + the connect + await asyncio.wait_for(client.entered.wait(), 1) + tracked = list(manager._tasks) + assert len(tracked) == 2, [t.get_name() for t in tracked] + + await manager.async_stop() + + assert manager._tasks == [] + assert all(task.done() for task in tracked), "both were awaited" + + async def test_a_second_start_reuses_the_live_attempt(self): + """The proof for O5: starting twice leaves exactly ONE live attempt.""" + client = HangingProtocolClient() + manager = _protocol_manager(client) + await manager._start_protocol() + await asyncio.wait_for(client.entered.wait(), 1) + first = manager._protocol_connect_task + + await manager._start_protocol() + + assert manager._protocol_connect_task is first, "reused, never orphaned" + assert client.connect_calls == 1, "exactly one attempt was made" + assert [t for t in manager._tasks if not t.done()] == [first] + assert manager._tasks.count(first) == 1, "registered once, not once per start" + assert client._is_on_callbacks == [manager._on_is_on], ( + "the push callbacks are not registered twice either" + ) + await manager.async_stop() + + async def test_a_second_start_after_a_session_does_not_build_a_second_loop(self): + """The library owns the session; a second keep_reconnecting would be a leak.""" + client = FakeProtocolClient() + manager = _protocol_manager(client) + await manager._start_protocol() + await _connect(manager, client) + first = manager._protocol_connect_task + assert manager.protocol_connected is True + + await manager._start_protocol() + + assert manager._protocol_connect_task is first + assert client.connect_calls == 1 + assert client.keep_reconnecting_calls == 1, "one owner for the session" + await manager.async_stop() + + async def test_a_second_start_after_a_terminal_failure_tries_again(self): + """Deterministic in BOTH directions: a finished attempt may be replaced.""" + client = FakeProtocolClient(connect_error=InvalidAuth("Need to pair")) + manager = _protocol_manager(client, invalid_auth_callback=lambda: None) + await manager._start_protocol() + await _connect(manager, client) + first = manager._protocol_connect_task + assert first.done(), "the auth path is terminal: the loop returned" + assert manager.protocol_state == "auth_rejected" + + await manager._start_protocol() + + assert manager._protocol_connect_task is not first, "a FRESH attempt replaces it" + for _ in range(200): # the fresh task needs a turn to make its attempt + if client.connect_calls == 2: + break + await asyncio.sleep(0.005) + assert client.connect_calls == 2, "a restart really retries" + await manager.async_stop() + + async def test_a_stopped_manager_is_not_restarted_by_a_late_call(self): + client = FakeProtocolClient() + manager = _protocol_manager(client) + await manager.async_stop() + + await manager._start_protocol() + + assert manager._protocol_connect_task is None + assert manager._tasks == [] + + +class TestTransportBannersAreNotStale: + """t20/O2: define stale, then make it impossible. + + A STALE banner is one whose transport claim a later state change never followed + up on, so the log's last word contradicts the entity. The rules that remove it: + the affirmative banner states only what the attempt proved, and EVERY state + change announces itself with both the old and the new state. + """ + + @staticmethod + def _state_lines(records): + return [r for r in records if "transport state:" in r.getMessage()] + + async def test_the_connected_banner_claims_no_liveliness(self, caplog): + client = FakeProtocolClient() + manager = _protocol_manager(client) + + with caplog.at_level("INFO"): + await manager._start_protocol() + await _connect(manager, client) + + opened = [r for r in caplog.records if "session opened" in r.getMessage()] + assert opened, "connecting is announced" + text = opened[0].getMessage() + assert "what this proves" in text, "it names its own limit" + assert "availability push" in text, "and who maintains the session from there" + assert "paired" not in text.lower(), "a connect attempt cannot prove pairing" + + lines = self._state_lines(caplog.records) + assert lines, "the transition is announced" + assert lines[-1].getMessage().endswith(manager.protocol_state) + await manager.async_stop() + + async def test_a_later_state_change_announces_itself(self, caplog): + client = FakeProtocolClient() + manager = _protocol_manager(client) + await manager._start_protocol() + await _connect(manager, client) + + with caplog.at_level("INFO"): + client.push_is_available(False) # the device reports the session down + await _drain_loop() + + lines = self._state_lines(caplog.records) + assert lines, "a session going down is announced" + assert lines[-1].getMessage().endswith("disconnected") + assert manager.protocol_state == "disconnected", "the banner matches the entity" + await manager.async_stop() + + async def test_the_open_banner_and_the_transition_agree(self, caplog): + """No two lines about the same moment may name different states.""" + client = FakeProtocolClient() + manager = _protocol_manager(client) + + with caplog.at_level("INFO"): + await manager._start_protocol() + await _connect(manager, client) + + opened = [r for r in caplog.records if "session opened" in r.getMessage()] + lines = self._state_lines(caplog.records) + assert opened and lines + assert "connected" in opened[0].getMessage() + assert lines[-1].getMessage().endswith("connected") + await manager.async_stop()