Skip to content

Commit 45536bb

Browse files
author
emmanuel
committed
fix: MQTT reconnection and reliability hardening
- Widen reconnection backoff loop exception handling: auth and MQTT errors (Nwp500Error) now count as failed attempts and are retried instead of silently killing the reconnect task; only InvalidCredentialsError is fatal and emits reconnection_failed - Make disconnect() effective while the connection is interrupted: always disable automatic reconnection and stop periodic tasks, and close the SDK connection even when not connected - Flush the command queue after active/deep reconnection; the SDK's on_connection_resumed callback never fires for a rebuilt connection, so queued commands were silently lost - Log exceptions from thread-scheduled coroutines instead of dropping the run_coroutine_threadsafe future - Widen periodic request loop exception handling so MQTT publish failures no longer permanently kill polling tasks - Re-raise CancelledError in reconnection and periodic loops so cancelled tasks are actually marked cancelled - Add operation_timeout (default 30s) for MQTT connect/publish/ subscribe/unsubscribe/disconnect acknowledgements to prevent hangs on half-open TCP connections - Add +/-50% jitter to reconnect backoff to avoid synchronized fleet-wide reconnect storms
1 parent 5e116c6 commit 45536bb

8 files changed

Lines changed: 822 additions & 103 deletions

File tree

CHANGELOG.rst

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,59 @@ Changelog
55
Unreleased
66
==========
77

8+
Bug Fixes
9+
---------
10+
- **Fix reconnection loop dying on authentication errors**: the backoff
11+
loop caught only ``AwsCrtError`` and ``RuntimeError``, so
12+
``TokenRefreshError``, ``AuthenticationError``, and
13+
``MqttCredentialsError`` raised during quick/deep reconnection escaped
14+
and silently killed the reconnect task. A routine outage coinciding
15+
with token expiry left the client permanently offline despite unlimited
16+
retries. All library errors (``Nwp500Error``) and operation timeouts
17+
are now treated as failed attempts and retried; only
18+
``InvalidCredentialsError`` is fatal and stops the loop with a
19+
``reconnection_failed`` event.
20+
- **Fix disconnect() being a no-op while the connection is interrupted**:
21+
calling ``disconnect()`` during an interruption returned early without
22+
disabling automatic reconnection or stopping periodic tasks, so the
23+
backoff loop would resurrect the connection after the application shut
24+
the client down. ``disconnect()`` now always disables reconnection and
25+
stops periodic tasks, and tears down the SDK connection even when not
26+
connected.
27+
- **Fix queued commands being lost after active/deep reconnection**: the
28+
command queue was only flushed from the SDK's ``on_connection_resumed``
29+
callback, which never fires for the new connection built by
30+
active/deep reconnection. Commands queued while offline were silently
31+
dropped. Both reconnect paths now flush the queue after subscriptions
32+
are restored.
33+
- **Fix periodic request tasks dying on MQTT errors**: the periodic loop
34+
caught only ``AwsCrtError`` and ``RuntimeError``;
35+
``MqttNotConnectedError``/``MqttPublishError`` raised by a publish
36+
racing a disconnection permanently killed the polling task while it
37+
still appeared active. The loop now survives all library errors.
38+
- **Fix silent failures in thread-scheduled coroutines**: futures
39+
returned by ``run_coroutine_threadsafe`` were discarded, so exceptions
40+
from scheduled work (e.g. a failed resubscribe after a clean-session
41+
resume, leaving the client connected but deaf) vanished. A done
42+
callback now logs them.
43+
- **Fix CancelledError being swallowed in reconnection and periodic
44+
loops**: both loops caught ``asyncio.CancelledError`` and ``break``-ed,
45+
so cancelled tasks ended "successfully" (and the reconnection loop
46+
could emit ``reconnection_failed`` during a manual disconnect).
47+
Cancellation now propagates correctly.
48+
49+
Improvements
50+
------------
51+
- **MQTT operation acknowledgement timeouts**: connect, publish,
52+
subscribe, unsubscribe, and disconnect acknowledgements are now awaited
53+
with a timeout (``MqttConnectionConfig.operation_timeout``, default 30
54+
seconds). Previously a half-open TCP connection could hang callers
55+
until the 20-minute keep-alive expired.
56+
- **Reconnection backoff jitter**: reconnect delays are now randomized
57+
(±50%, capped at ``max_reconnect_delay``) so fleets of clients
58+
disconnected simultaneously (e.g. the AWS IoT 24-hour disconnect) no
59+
longer reconnect in synchronized waves.
60+
861
Version 8.1.3 (2026-06-15)
962
==========================
1063

src/nwp500/mqtt/client.py

Lines changed: 62 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
from __future__ import annotations
1313

1414
import asyncio
15+
import concurrent.futures
1516
import json
1617
import logging
1718
import uuid
@@ -69,6 +70,23 @@
6970
_logger = logging.getLogger(__name__)
7071

7172

73+
def _log_scheduled_coroutine_result(
74+
future: concurrent.futures.Future[Any],
75+
) -> None:
76+
"""Surface exceptions from scheduled coroutines.
77+
78+
Attached to futures returned by ``run_coroutine_threadsafe``.
79+
Without this callback the returned future is discarded and any
80+
exception (e.g. resubscribe failure after a clean-session resume) is
81+
silently swallowed.
82+
"""
83+
if future.cancelled():
84+
return
85+
exc = future.exception()
86+
if exc is not None:
87+
_logger.error("Scheduled coroutine failed: %s", exc, exc_info=exc)
88+
89+
7290
class NavienMqttClient(EventEmitter):
7391
"""
7492
Async MQTT client for Navien device communication over AWS IoT.
@@ -256,10 +274,15 @@ def _schedule_coroutine(self, coro: Any) -> None:
256274

257275
# Schedule the coroutine in the stored loop using thread-safe method
258276
try:
259-
asyncio.run_coroutine_threadsafe(coro, self._loop)
277+
future = asyncio.run_coroutine_threadsafe(coro, self._loop)
260278
except RuntimeError as e:
261279
# Event loop is closed or not running
262280
_logger.error(f"Failed to schedule coroutine: {e}", exc_info=True)
281+
else:
282+
# Never drop the future: exceptions from scheduled coroutines
283+
# (e.g. a failed resubscribe after a clean-session resume) would
284+
# otherwise be stored on the discarded future and vanish.
285+
future.add_done_callback(_log_scheduled_coroutine_result)
263286

264287
def _on_connection_interrupted_internal(
265288
self, connection: mqtt.Connection, error: AwsCrtError, **kwargs: Any
@@ -476,6 +499,12 @@ async def _active_reconnect(self) -> None:
476499
)
477500
await self._subscription_manager.resubscribe_all()
478501

502+
# A brand-new connection never fires the SDK's
503+
# on_connection_resumed callback, so queued commands
504+
# must be flushed here or they would be lost.
505+
if self.config.enable_command_queue and self._command_queue:
506+
await self._send_queued_commands_internal()
507+
479508
_logger.info("Active reconnection successful")
480509
else:
481510
_logger.warning("Active reconnection failed")
@@ -587,6 +616,12 @@ async def _deep_reconnect(self) -> None:
587616
)
588617
await self._subscription_manager.resubscribe_all()
589618

619+
# A brand-new connection never fires the SDK's
620+
# on_connection_resumed callback, so queued commands must
621+
# be flushed here or they would be lost.
622+
if self.config.enable_command_queue and self._command_queue:
623+
await self._send_queued_commands_internal()
624+
590625
_logger.info(
591626
"Deep reconnection successful - fully rebuilt connection"
592627
)
@@ -673,6 +708,7 @@ async def connect(self) -> bool:
673708
event_emitter=self,
674709
schedule_coroutine=self._schedule_coroutine,
675710
device_info_cache=device_info_cache,
711+
operation_timeout=self.config.operation_timeout,
676712
)
677713

678714
# Update device controller cache
@@ -793,32 +829,46 @@ def _create_credentials_provider(self) -> Any:
793829
)
794830

795831
async def disconnect(self) -> None:
796-
"""Disconnect from AWS IoT Core and stop all periodic tasks."""
797-
if not self._connected or not self._connection_manager:
798-
_logger.warning("Not connected")
799-
return
800-
801-
_logger.info("Disconnecting from AWS IoT...")
832+
"""Disconnect from AWS IoT Core and stop all periodic tasks.
802833
803-
# Disable automatic reconnection
834+
Safe to call in any state. Even when the connection is currently
835+
interrupted (``_connected`` is False with a reconnection loop
836+
running), this method disables automatic reconnection and stops
837+
periodic tasks so a backoff loop cannot resurrect the connection
838+
after the application has shut the client down.
839+
"""
840+
# Always disable automatic reconnection first, regardless of the
841+
# current connection state.
804842
if self._reconnection_handler:
805843
self._reconnection_handler.disable()
806844
await self._reconnection_handler.cancel()
807845

808-
# Stop all periodic tasks first
846+
# Stop all periodic tasks
809847
if self._periodic_manager:
810848
await self._periodic_manager.stop_all_periodic_tasks()
811849

850+
if not self._connection_manager:
851+
_logger.warning("Not connected")
852+
return
853+
854+
_logger.info("Disconnecting from AWS IoT...")
855+
812856
try:
813-
# Delegate disconnection to connection manager
814-
await self._connection_manager.disconnect()
857+
if self._connected:
858+
# Delegate graceful disconnection to connection manager
859+
await self._connection_manager.disconnect()
860+
else:
861+
# Interrupted state: no broker session to end gracefully,
862+
# but the SDK connection object must still be torn down so
863+
# its auto-reconnect cannot fire after shutdown.
864+
await self._connection_manager.close()
815865

816866
# Clear connection state
817867
self._connected = False
818868
self._connection = None
819869

820870
_logger.info("Disconnected successfully")
821-
except (AwsCrtError, RuntimeError) as e:
871+
except (AwsCrtError, RuntimeError, TimeoutError) as e:
822872
_logger.error(f"Error during disconnect: {e}")
823873
raise
824874

src/nwp500/mqtt/connection.py

Lines changed: 50 additions & 58 deletions
Original file line numberDiff line numberDiff line change
@@ -96,6 +96,49 @@ def __init__(
9696
f"Initialized connection manager with client ID: {config.client_id}"
9797
)
9898

99+
async def _await_ack(
100+
self, future: asyncio.Future[Any], operation: str
101+
) -> Any:
102+
"""Await a broker acknowledgement future with a timeout.
103+
104+
The awscrt future is shielded so cancellation (or a timeout) never
105+
propagates into the SDK future — the underlying operation completes
106+
independently, preventing InvalidStateError in AWS CRT callbacks.
107+
108+
A timeout guards against half-open TCP connections where the
109+
acknowledgement never arrives; without it callers can hang until
110+
the keep-alive expires (20+ minutes).
111+
112+
Args:
113+
future: concurrent.futures.Future returned by the SDK
114+
operation: Human-readable operation name for error messages
115+
116+
Returns:
117+
The acknowledgement result
118+
119+
Raises:
120+
TimeoutError: If no acknowledgement within
121+
config.operation_timeout seconds
122+
asyncio.CancelledError: If the awaiting task is cancelled
123+
"""
124+
try:
125+
return await asyncio.wait_for(
126+
asyncio.shield(asyncio.wrap_future(future)),
127+
timeout=self.config.operation_timeout,
128+
)
129+
except asyncio.CancelledError:
130+
_logger.debug(
131+
"%s was cancelled but will complete in background", operation
132+
)
133+
raise
134+
except TimeoutError:
135+
_logger.error(
136+
"%s not acknowledged within %.1fs",
137+
operation,
138+
self.config.operation_timeout,
139+
)
140+
raise
141+
99142
async def connect(self) -> bool:
100143
"""
101144
Establish connection to AWS IoT Core.
@@ -151,19 +194,7 @@ async def connect(self) -> bool:
151194
connect_future = cast(
152195
asyncio.Future[Any], self._connection.connect()
153196
)
154-
try:
155-
connect_result = await asyncio.shield(
156-
asyncio.wrap_future(connect_future)
157-
)
158-
except asyncio.CancelledError:
159-
# Shield was cancelled - the underlying connect will
160-
# complete independently, preventing InvalidStateError
161-
# in AWS CRT callbacks
162-
_logger.debug(
163-
"Connect operation was cancelled but will complete "
164-
"in background"
165-
)
166-
raise
197+
connect_result = await self._await_ack(connect_future, "Connect")
167198

168199
self._connected = True
169200
_logger.info(
@@ -226,17 +257,7 @@ async def disconnect(self) -> None:
226257
disconnect_future = cast(
227258
asyncio.Future[Any], self._connection.disconnect()
228259
)
229-
try:
230-
await asyncio.shield(asyncio.wrap_future(disconnect_future))
231-
except asyncio.CancelledError:
232-
# Shield was cancelled - the underlying disconnect will
233-
# complete independently, preventing InvalidStateError
234-
# in AWS CRT callbacks
235-
_logger.debug(
236-
"Disconnect operation was cancelled but will complete "
237-
"in background"
238-
)
239-
raise
260+
await self._await_ack(disconnect_future, "Disconnect")
240261

241262
self._connected = False
242263
self._connection = None
@@ -271,9 +292,9 @@ async def close(self) -> None:
271292
disconnect_future = cast(
272293
asyncio.Future[Any], connection.disconnect()
273294
)
274-
await asyncio.shield(asyncio.wrap_future(disconnect_future))
295+
await self._await_ack(disconnect_future, "Close")
275296
_logger.debug("SDK connection closed")
276-
except (AwsCrtError, RuntimeError) as e:
297+
except (AwsCrtError, RuntimeError, TimeoutError) as e:
277298
# Expected when connection is already dead or in bad state
278299
_logger.debug(f"SDK connection close (benign): {e}")
279300
except asyncio.CancelledError:
@@ -317,17 +338,7 @@ async def subscribe(
317338
subscribe_future = cast(asyncio.Future[Any], subscribe_future_raw)
318339
packet_id = packet_id_raw
319340

320-
try:
321-
await asyncio.shield(asyncio.wrap_future(subscribe_future))
322-
except asyncio.CancelledError:
323-
# Shield was cancelled - the underlying subscribe will
324-
# complete independently, preventing InvalidStateError
325-
# in AWS CRT callbacks
326-
_logger.debug(
327-
f"Subscribe to '{topic}' was cancelled but will complete "
328-
"in background"
329-
)
330-
raise
341+
await self._await_ack(subscribe_future, f"Subscribe to '{topic}'")
331342

332343
_logger.info(f"Subscribed to '{topic}' with packet_id {packet_id}")
333344
return (subscribe_future, packet_id)
@@ -359,17 +370,7 @@ async def unsubscribe(self, topic: str) -> int:
359370
unsubscribe_future = cast(asyncio.Future[Any], unsubscribe_future_raw)
360371
packet_id = int(packet_id_raw)
361372

362-
try:
363-
await asyncio.shield(asyncio.wrap_future(unsubscribe_future))
364-
except asyncio.CancelledError:
365-
# Shield was cancelled - the underlying unsubscribe will
366-
# complete independently, preventing InvalidStateError
367-
# in AWS CRT callbacks
368-
_logger.debug(
369-
f"Unsubscribe from '{topic}' was cancelled but will "
370-
"complete in background"
371-
)
372-
raise
373+
await self._await_ack(unsubscribe_future, f"Unsubscribe from '{topic}'")
373374

374375
_logger.info(f"Unsubscribed from '{topic}' with packet_id {packet_id}")
375376
return packet_id
@@ -419,16 +420,7 @@ async def publish(
419420
# InvalidStateError when AWS CRT tries to set exception on a
420421
# cancelled future.
421422
try:
422-
await asyncio.shield(asyncio.wrap_future(publish_future))
423-
except asyncio.CancelledError:
424-
# Shield was cancelled - the underlying publish will complete
425-
# independently, preventing InvalidStateError in AWS CRT
426-
# callbacks
427-
_logger.debug(
428-
f"Publish to '{topic}' was cancelled but will complete "
429-
"in background"
430-
)
431-
raise
423+
await self._await_ack(publish_future, f"Publish to '{topic}'")
432424
except AwsCrtError as e:
433425
# Handle connection destruction during publish
434426
# This can happen when AWS IoT Core disconnects (e.g., 24-hour

src/nwp500/mqtt/periodic.py

Lines changed: 15 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919

2020
from awscrt.exceptions import AwsCrtError
2121

22+
from ..exceptions import Nwp500Error
2223
from ..models import Device
2324
from .utils import PeriodicRequestType
2425

@@ -184,13 +185,24 @@ async def periodic_request() -> None:
184185
await asyncio.sleep(period_seconds)
185186

186187
except asyncio.CancelledError:
188+
# Re-raise so the task is actually marked as cancelled
189+
# instead of ending "successfully".
187190
_logger.info(
188191
f"Periodic {request_type.value} requests cancelled "
189192
f"for {redacted_device_id}"
190193
)
191-
break
192-
except (AwsCrtError, RuntimeError) as e:
193-
# Handle known MQTT errors gracefully
194+
raise
195+
except (
196+
AwsCrtError,
197+
Nwp500Error,
198+
RuntimeError,
199+
TimeoutError,
200+
) as e:
201+
# Handle known MQTT/library errors gracefully. This must
202+
# include Nwp500Error: publish failures raise
203+
# MqttNotConnectedError/MqttPublishError (not
204+
# RuntimeError), which would otherwise silently kill
205+
# the periodic task while it still looks alive.
194206
error_name = (
195207
getattr(e, "name", None)
196208
if isinstance(e, AwsCrtError)

0 commit comments

Comments
 (0)