Skip to content

Commit ff5657f

Browse files
emanemmanuel
andauthored
fix: MQTT threading model and event emitter correctness (#93)
* fix: MQTT threading model and event emitter correctness - Marshal MQTT message parse/dispatch from the AWS CRT network thread onto the asyncio event loop; keeps the SDK callback trivial, prevents blocking user callbacks from stalling MQTT processing, and eliminates the handler-registry iteration race during reconnect/resubscribe - Iterate snapshots of handler registries so handlers can subscribe/unsubscribe during dispatch - Isolate individual handler failures: catch Exception per handler with logging instead of only (TypeError, AttributeError, KeyError) - Make the unit system preference process-wide instead of a ContextVar; tasks scheduled from CRT threads never inherited the caller's context, so --unit-system was silently ignored for all MQTT-delivered data - Remove once-listeners before invoking them: raising callbacks no longer stay registered forever and concurrent emits no longer double-fire - Clean up wait_for() listeners in a finally block so cancellation does not leak them; fix wait_for docstring examples that broke user code * test: reset unit system before and after each threading-model test Addresses review feedback: the preference is process-wide, so a teardown-only reset let the first test in this module inherit values set by earlier tests in the session. --------- Co-authored-by: emmanuel <emmanuel@musta.lan>
1 parent f2281db commit ff5657f

6 files changed

Lines changed: 433 additions & 61 deletions

File tree

CHANGELOG.rst

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,44 @@ Unreleased
77

88
Bug Fixes
99
---------
10+
- **Run MQTT message dispatch on the event loop**: JSON parsing, pydantic
11+
model validation, and user callbacks all executed directly on the AWS
12+
CRT network thread. A slow or blocking callback (e.g. the CLI monitor's
13+
CSV writes) stalled all MQTT message processing, user callbacks ran on
14+
an undocumented SDK thread where asyncio operations are unsafe, and the
15+
handler registry could be mutated on the event loop while the CRT
16+
thread iterated it (``RuntimeError: dictionary changed size during
17+
iteration``, dropping the message — most likely during the
18+
reconnect/resubscribe window). The awscrt callback now only marshals
19+
the raw payload onto the event loop; parsing and dispatch run there,
20+
iterating snapshots of the handler registries.
21+
- **Stop one raising handler from aborting message delivery**: handler
22+
dispatch caught only ``(TypeError, AttributeError, KeyError)``; a user
23+
callback raising anything else (e.g. ``ValueError``) escaped into the
24+
awscrt callback machinery and skipped the remaining handlers for that
25+
message. Individual handler failures are now logged and isolated.
26+
- **Make the unit system preference process-wide**:
27+
``set_unit_system()`` stored the preference in a ``ContextVar`` set in
28+
the caller's task. Tasks scheduled from AWS CRT callback threads never
29+
inherit that context, so the preference silently reverted to
30+
auto-detect for all MQTT-delivered data — ``nwp-cli --unit-system
31+
metric monitor`` logged temperatures in the device's native unit while
32+
labeling them °C. The preference is now a process-wide setting visible
33+
from every task and thread.
34+
- **Fix once-listeners firing more than once**: ``EventEmitter.emit()``
35+
removed one-time listeners only after invoking them, so a callback
36+
that raised stayed registered forever, and two overlapping emits could
37+
both fire the same once-listener. Once-listeners are now removed
38+
before invocation.
39+
- **Fix wait_for() leaking its listener on cancellation**:
40+
``EventEmitter.wait_for()`` removed its listener only on timeout; a
41+
cancelled waiter left the listener registered until the event next
42+
fired, setting a result on a dead future. Cleanup now happens in a
43+
``finally`` block.
44+
- **Fix wait_for() docstring examples**: examples showed
45+
``args, _ = await emitter.wait_for(...)``, but ``wait_for`` returns
46+
just the args tuple — following the documented pattern raised
47+
``ValueError`` or silently mis-assigned.
1048
- **Serialize concurrent token refresh**: ``ensure_valid_token()`` and
1149
``refresh_token()`` had no lock, so concurrent callers (API 401 retry,
1250
MQTT reconnect, periodic requests) at token expiry fired parallel

src/nwp500/events.py

Lines changed: 21 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -245,7 +245,21 @@ async def emit(self, event: str, *args: Any, **kwargs: Any) -> int:
245245
listeners: list[EventListener] = self._listeners[event].copy()
246246
# Copy to allow modification during iteration
247247
called_count = 0
248-
listeners_to_remove: list[EventListener] = []
248+
249+
# Remove one-time listeners BEFORE invoking them (synchronously,
250+
# in the same event-loop slice as the snapshot):
251+
# - a raising callback must not stay registered forever
252+
# - concurrent emits each snapshot the list; deferring removal
253+
# until after (awaited) iteration double-fires once-listeners
254+
for listener in listeners:
255+
if listener.once:
256+
if listener in self._listeners.get(event, []):
257+
self._listeners[event].remove(listener)
258+
self._once_callbacks.discard((event, listener.callback))
259+
260+
# Clean up if no listeners left
261+
if event in self._listeners and not self._listeners[event]:
262+
del self._listeners[event]
249263

250264
for listener in listeners:
251265
try:
@@ -257,11 +271,6 @@ async def emit(self, event: str, *args: Any, **kwargs: Any) -> int:
257271

258272
called_count += 1
259273

260-
# Check if this is a once listener
261-
if listener.once:
262-
listeners_to_remove.append(listener)
263-
self._once_callbacks.discard((event, listener.callback))
264-
265274
except Exception as e:
266275
# Catch all exceptions from user callbacks to ensure
267276
# resilience. We intentionally catch Exception here because:
@@ -273,15 +282,6 @@ async def emit(self, event: str, *args: Any, **kwargs: Any) -> int:
273282
exc_info=True,
274283
)
275284

276-
# Remove one-time listeners after iteration
277-
for listener in listeners_to_remove:
278-
if listener in self._listeners[event]:
279-
self._listeners[event].remove(listener)
280-
281-
# Clean up if no listeners left
282-
if not self._listeners[event]:
283-
del self._listeners[event]
284-
285285
# Track event count
286286
self._event_counts[event] += 1
287287

@@ -391,7 +391,7 @@ async def wait_for(
391391
await emitter.wait_for('device_ready', timeout=30)
392392
393393
# Wait for specific condition
394-
args, _ = await emitter.wait_for('temperature_changed')
394+
args = await emitter.wait_for('temperature_changed')
395395
temperature_event = args[0]
396396
current_temp = temperature_event.new_temperature
397397
"""
@@ -416,7 +416,9 @@ def handler(*args: Any, **kwargs: Any) -> None:
416416
# Return just args for simplicity (most common case)
417417
return args_tuple
418418

419-
except TimeoutError:
420-
# Remove the listener on timeout
419+
finally:
420+
# Always unregister: on timeout AND on cancellation. A leaked
421+
# once-listener would otherwise stay registered until the
422+
# event next fires (setting a result on a dead future).
423+
# No-op when the listener already fired (once() removed it).
421424
self.off(event, handler)
422-
raise

src/nwp500/mqtt/subscriptions.py

Lines changed: 44 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -122,37 +122,61 @@ def update_connection(self, connection: Any) -> None:
122122
def _on_message_received(
123123
self, topic: str, payload: bytes, **kwargs: Any
124124
) -> None:
125-
"""Handle received MQTT messages.
125+
"""Handle received MQTT messages (AWS CRT callback).
126126
127-
Parses JSON payload and routes to registered handlers.
127+
This runs on the AWS CRT network thread. It must stay trivial:
128+
JSON parsing, pydantic validation, and user callbacks are
129+
marshaled onto the asyncio event loop so that
130+
131+
- a slow or blocking user callback cannot stall all MQTT message
132+
processing,
133+
- handler registries mutated on the event loop are never iterated
134+
concurrently from this thread, and
135+
- user callbacks run where asyncio operations are safe, instead
136+
of on an undocumented SDK thread.
128137
129138
Args:
130139
topic: MQTT topic the message was received on
131140
payload: Raw message payload (JSON bytes)
132141
**kwargs: Additional MQTT metadata
133142
"""
143+
self._schedule_coroutine(self._dispatch_message(topic, payload))
144+
145+
async def _dispatch_message(self, topic: str, payload: bytes) -> None:
146+
"""Parse a message and route it to registered handlers.
147+
148+
Runs on the event loop.
149+
150+
Args:
151+
topic: MQTT topic the message was received on
152+
payload: Raw message payload (JSON bytes)
153+
"""
134154
try:
135-
# Parse JSON payload
136155
message = json.loads(payload.decode("utf-8"))
156+
except (json.JSONDecodeError, UnicodeDecodeError) as e:
157+
_logger.error(f"Failed to parse message payload: {e}")
158+
return
159+
160+
if _logger.isEnabledFor(logging.DEBUG):
137161
_logger.debug("Received message on topic: %s", redact_topic(topic))
138162

139-
# Call registered handlers that match this topic
140-
# Need to match against subscription patterns with wildcards
141-
for (
142-
subscription_pattern,
143-
handlers,
144-
) in self._message_handlers.items():
145-
if topic_matches_pattern(topic, subscription_pattern):
146-
for handler in handlers:
147-
try:
148-
handler(topic, message)
149-
except (TypeError, AttributeError, KeyError) as e:
150-
_logger.error(f"Error in message handler: {e}")
151-
152-
except json.JSONDecodeError as e:
153-
_logger.error(f"Failed to parse message payload: {e}")
154-
except (AttributeError, KeyError, TypeError) as e:
155-
_logger.error(f"Error processing message: {e}")
163+
# Call registered handlers that match this topic.
164+
# Iterate over snapshots so handlers can subscribe/unsubscribe
165+
# (mutating the registries) during dispatch.
166+
for subscription_pattern, handlers in list(
167+
self._message_handlers.items()
168+
):
169+
if topic_matches_pattern(topic, subscription_pattern):
170+
for handler in list(handlers):
171+
try:
172+
handler(topic, message)
173+
except Exception:
174+
# One bad handler must not abort delivery to the
175+
# remaining handlers for this message.
176+
_logger.exception(
177+
"Error in message handler for %s",
178+
redact_topic(topic),
179+
)
156180

157181
async def subscribe(
158182
self,

src/nwp500/mqtt_events.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -204,7 +204,7 @@ class MqttClientEvents:
204204
)
205205
206206
# Wait for a specific event
207-
args, _ = await mqtt_client.wait_for(
207+
args = await mqtt_client.wait_for(
208208
MqttClientEvents.CONNECTION_RESUMED
209209
)
210210
connection_event = args[0]

src/nwp500/unit_system.py

Lines changed: 24 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,18 @@
11
"""Unit system management for temperature, flow rate, and volume conversions.
22
3-
This module provides context-based unit system management, allowing applications
4-
to override the device's temperature_type setting and specify a preferred
5-
measurement system (Metric or Imperial).
3+
This module provides process-wide unit system management, allowing
4+
applications to override the device's temperature_type setting and specify a
5+
preferred measurement system (Metric or Imperial).
66
77
The unit system preference can be set at library initialization and is used
8-
during model validation to convert device values to the user's preferred units.
8+
during model validation to convert device values to the user's preferred
9+
units. The preference is a process-wide setting: it is visible from every
10+
task and thread, including model validation triggered by MQTT callbacks that
11+
run outside the task that configured it.
912
"""
1013

1114
from __future__ import annotations
1215

13-
import contextvars
1416
import logging
1517
from typing import Literal
1618

@@ -25,21 +27,25 @@
2527
# Type alias for unit system preference
2628
UnitSystemType = Literal["metric", "us_customary"] | None
2729

28-
# Context variable to store the preferred unit system
30+
# Process-wide preferred unit system.
2931
# None means auto-detect from device
3032
# "metric" means Celsius, "us_customary" means Fahrenheit
31-
_unit_system_context: contextvars.ContextVar[
32-
Literal["metric", "us_customary"] | None
33-
] = contextvars.ContextVar("unit_system", default=None)
33+
#
34+
# This is intentionally NOT a contextvars.ContextVar: MQTT message handling
35+
# runs in tasks scheduled from AWS CRT callback threads whose context never
36+
# inherits from the application task, so a context-local preference silently
37+
# reverted to auto-detect for all real-time data.
38+
_unit_system: Literal["metric", "us_customary"] | None = None
3439

3540

3641
def set_unit_system(
3742
unit_system: Literal["metric", "us_customary"] | None,
3843
) -> None:
3944
"""Set preferred unit system for temperature, flow, and volume conversions.
4045
41-
This setting overrides the device's temperature_type setting and applies to
42-
all subsequent model validation operations in the current async context.
46+
This setting overrides the device's temperature_type setting and applies
47+
process-wide to all subsequent model validation operations, including
48+
those triggered by MQTT callbacks running in other tasks or threads.
4349
4450
Args:
4551
unit_system: Preferred unit system:
@@ -52,12 +58,9 @@ def set_unit_system(
5258
>>> set_unit_system("us_customary")
5359
>>> # All values now in F, GPM, Gallons
5460
>>> set_unit_system(None) # Reset to auto-detect
55-
56-
Note:
57-
This is context-aware and works with async code. Each async task
58-
maintains its own unit system preference.
5961
"""
60-
_unit_system_context.set(unit_system)
62+
global _unit_system
63+
_unit_system = unit_system
6164

6265

6366
def get_unit_system() -> Literal["metric", "us_customary"] | None:
@@ -69,7 +72,7 @@ def get_unit_system() -> Literal["metric", "us_customary"] | None:
6972
- "us_customary": Fahrenheit, GPM, Gallons
7073
- None: Auto-detect from device (default)
7174
"""
72-
return _unit_system_context.get()
75+
return _unit_system
7376

7477

7578
def reset_unit_system() -> None:
@@ -78,7 +81,7 @@ def reset_unit_system() -> None:
7881
This is useful for tests or when switching between different
7982
device configurations.
8083
"""
81-
_unit_system_context.set(None)
84+
set_unit_system(None)
8285

8386

8487
def unit_system_to_temperature_type(
@@ -108,8 +111,8 @@ def is_metric_preferred(
108111
) -> bool:
109112
"""Check if metric (Celsius) is preferred.
110113
111-
Checks the override first, then falls back to the context-configured
112-
unit system. Used during validation to determine preferred units.
114+
Checks the override first, then falls back to the configured unit
115+
system. Used during validation to determine preferred units.
113116
114117
Args:
115118
override: Optional override value. If provided, this takes precedence
@@ -123,7 +126,7 @@ def is_metric_preferred(
123126
if override is not None:
124127
return override == "metric"
125128

126-
# Otherwise check context
129+
# Otherwise check the configured preference
127130
unit_system = get_unit_system()
128131
if unit_system is not None:
129132
return unit_system == "metric"

0 commit comments

Comments
 (0)