fix(protocol): reassemble blockwise OBSERVE notifications - #40
Conversation
A notification carries only the first block of a large representation (RFC 7959 §2.6). _dispatch_coap handed that block straight to on_notification, so consumers decoded a truncated CBOR buffer. Reported twice on /mode/vs/0: #37 and mbillow/localthings#361. The recovery is a re-read from block 0 on a fresh 4-byte one-shot token, not a §2.6 continuation. §3.4 rules out reusing the observation's token, and this server drops a transfer that opens at NUM>0 under a token it has not seen, so a continuation is the one shape that cannot work here. A truncated notification is now withheld and queued to a worker thread that re-reads the resource and delivers the reassembled representation. When the re-read fails the notification is dropped at debug level and the poll tiers carry freshness, which is what they already did. The re-read has to run off the reader thread: _dispatch_coap runs there and the transfer waits on an event only that same thread can set. The worker is serialized and paces between transfers, so a notification storm stays under the firmware request ceiling. Also in the Block2 loop, now extracted and shared by both paths: - compare the response's Block2 NUM against the one requested, so a retransmitted block is no longer concatenated as if it were the next - compare ETags across blocks (§2.4) and restart once when the representation changes mid-transfer - recompute the next block number from the accumulated byte offset when the server negotiates the block size down - re-check reader liveness while waiting on a block, so a mid-transfer reader death fails fast instead of burning the whole timeout - guard the token counters and _pending with a lock, now that the session issues concurrent reads of its own Closes #39
The refetch path logged only at debug, and the bridge configures logging at INFO, so a successful re-read and a total failure produced identical output: nothing. That makes the hardware validation for #39 impossible to read. One line per refetch, promoted to INFO when DEBUG_BRIDGE=1 and left at debug otherwise, naming the href, the one-shot token, the block count, and the reassembled size. The token is the part that matters: it is what shows the re-read used a fresh 4-byte token rather than the observation's 1-byte one, which is the assumption the whole design rests on. Gating on DEBUG_BRIDGE rather than raising the logger keeps the per-block retransmit lines out of the way, and matches how the module already gates its frame dump.
|
Validated against hardware. Two independent sessions, one after a deploy and one after a process restart: Different tokens, both four bytes, so the re-read used a fresh one-shot token rather than the observation's one-byte token. The two runs reassembled byte-identically, so the block count and total are deterministic rather than dependent on how the transfer interleaved with polling. Wire dump for the first of the two, with Nine blocks at 1024 bytes plus one at 852 sums to exactly 10068. The message IDs are non-contiguous, so the transfer interleaved with ordinary polling and the token correlation held throughout. No Those two came from the initial OBSERVE registration response rather than a spontaneous push, because the appliance normally has no internet access and its cloud-gated notify dispatch is silent. That still exercises the same code: One consequence to record: the truncation therefore fires on every session start for every observed resource larger than one block, not only when the push channel is live. That is probably why it reproduced so consistently in #37 and localthings#361, and it means the fix matters on air-gapped installs too. Under a real notification burstThe appliance was then given internet access briefly, with a cook started so several observed resources changed at once. Eleven re-reads over the window: six delivered, five superseded, none failed and none dropped for a full queue. The coalescing resolves the way it should. Every run of superseded results ends in a delivery: Intermediate reassemblies are discarded because a newer notification is already queued, and the final state is the one handed to the callback. Nothing is lost at the end of a chain, which was the failure mode worth checking. End to end, on the delivery that closed the second chain: Ten blocks reassembled, decoded, and applied to the cache from the observe path. Before this change that notification was a truncated CBOR buffer. Payload size moved between 10066 and 10068 bytes across the window, so these were genuine state changes rather than the same representation re-served. Pacing held. The poll counter covers scheduled polls only, so the roughly 90 block GETs the re-reads issued in that 60-second window are extra traffic contending with it rather than part of the count. Polls in the burst window: 238 ok, 0 err, 0 timeouts, against 220 to 231 in the quiet windows either side, with a peak round trip of 1959 ms against a 1830 to 2758 ms range when idle. The added Block2 traffic cost the poll path nothing measurable. What hardware did not coverThree paths remain covered by unit tests only, all of them determined by the server rather than by the client:
Incidents, and what they wereTwo warnings during the session, neither traceable to this change. The first was a single oven poll timeout on The second was the other appliance losing its session for about 56 seconds after a container recreate, retrying with backoff until it recovered. That is the fixed source port orphan behaviour from #37. A later process restart, which does not recreate the container, did not reproduce it, which supports pinning it on the recreate. Remaining caveatThis is one firmware. Burst behaviour on a different appliance could differ, and the soak so far is short: the README notes this server sometimes closes sessions right after a Block2 GET, and no session closed during the test, but half an hour is not a long enough window to say much about that. Anyone on #37 or localthings#361 who can run the branch against their own device would be adding the coverage this cannot. |
1 participant
Closes #39.
What was wrong
_dispatch_coaphanded an OBSERVE notification's payload toon_notificationwithout looking at its Block2 option. A notification carries only the first block of a large representation (RFC 7959 §2.6), so anything past the first block was lost and the consumer decoded a partial CBOR buffer. Two reports, same path: #37 and mbillow/localthings#361, both on/mode/vs/0.Why this re-reads instead of continuing
The issue originally proposed a continuation GET at Block2 NUM=1. I corrected that on the issue before writing any of this. Two things rule it out:
_dispatch_coapresolve real notifications into the transfer's pending waiter, since_pendingis checked ahead of_observe_tokens.So a truncated notification is withheld and the resource is re-read from block 0 on a fresh 4-byte one-shot token. That is an ordinary GET, which is what §2.6 asks for. The MQTT bridge in this repo has been doing the same thing as a consumer-side workaround, triggered off CBOR-decode failure rather than off the Block2 option, so the shape is already proven against the oven.
How it is wired
get()'s reassembly loop is extracted into_blockwise_get, and the notification path reuses it. That is also the shared Block2 primitive #36 was reaching for.The re-read cannot run inline.
_dispatch_coapruns on the reader thread and the transfer waits on an event only that thread can set, so calling it there deadlocks the session. Notifications are queued to a lazily started worker instead, latest-wins per href. The worker is serialized and paces between transfers, so a notification burst cannot push the session past the 5/s ceiling. If the re-read fails for any reason the notification is dropped at debug level; the poll tiers carry freshness, which is what they already did.Also fixed in the shared loop
Five things the loop got wrong, all reachable from ordinary polling and not only from the new path:
expected to read 1 bytes, got 0shape in localthings#361.BlockwiseError. None of the tested appliances emit option 4, so this is inert on them.SessionClosedError, extending the Samsung Refrigerator (TP2X_REF_20K) will not reconnect on HA startup #37 fail-fast contract past the first block._pendingwere mutated without a lock. The refetch worker makes the session its own second concurrent reader, so that is now guarded.Behaviour change for consumers
on_notificationkeeps its signature and its contract, with one difference: a truncated notification no longer reaches it at all, and the reassembled one arrives on the worker thread rather than the reader thread. Single-block notifications are unaffected and still deliver inline.Validation
python -m pytest -qon Python 3.14: 236 passed, 13 of them new intests/test_observe_block2.py, which drives the reader through a loopback transport and covers inline delivery, refetch and reassembly, the fresh-token requirement, silent and error responses, burst coalescing, worker shutdown on bothclose()and reader death, and the four loop fixes. Ruff on the changed files reports nothing the file did not already report onmain.Not yet validated against hardware. The token shape the re-read uses is the assumption everything rests on, and it has only been observed indirectly through the bridge's existing fetchback. Do not tag a release off this until that is checked on a live appliance.