fix: don't drop image block requests that arrive while the response is being sent - #1846
fix: don't drop image block requests that arrive while the response is being sent#1846mattlathrop wants to merge 2 commits into
Conversation
…s being sent OtaSession.commandStream() only armed the imageBlockRequest/imagePageRequest waiters at the top of its loop, i.e. after the consumer had fully sent the previous imageBlockResponse and resumed the generator. Fast devices (e.g. Philips Hue, which request with minimumBlockPeriod=0) send their next request within milliseconds of receiving a response — inside that unarmed window — so every follow-up request was dropped and the transfer only advanced on the device's ~10s retry timeout: ~9,200 blocks x ~10s = ~23 hours per Hue bulb. Arm the next pair of waiters before yielding each request so an early request is captured by an already-armed waiter, keep passive rejection handlers on the armed promises (they can settle while the generator is suspended at yield), and cancel the armed pair in a finally block when the generator closes. The OTA test harness previously fabricated the device's next request at waiter-arm time — encoding the same arm-then-request assumption this change removes. It now produces requests lazily, in arm order, gated on completion of the responses owed for the previously produced request (1 per block request, blocks-per-page per page request, 0 for frames that elicit no response), which models a real device regardless of when the controller arms its waiters. Measured on a zstack coordinator (SLZB-06) with Hue BR30 bulbs: block cadence went from 1 block per ~10.9s to ~12 blocks/s; a 458KB image completed in 10m37s instead of a projected ~23h. A subsequent 13-bulb rollout completed back-to-back with zero failures. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
We haven't heard of this behavior during testing after last big OTA refactoring, nor since. I'm not really seeing how the device could end up re-requesting before we're back in the loop; there is no logic after the "send response", so we're back in the loop immediately (far faster than serial+network come-back). Only scenario I can see this happening is if the device requests blocks without first getting the response to the previous. Was this tested against a real failure scenario (e.g. yank the device off the network during update)? Seems to be a lot error swallowing in the refactored code. I haven't dug into the behavior changes, but I think upgradeEndRequest needs to be cancelled in the By the amount of changes in the tests, this needs extensive real testing for possible regressions. |
|
Below is an excerpt from the log before I made the change and after Before (note the 10s gap between packets) After (no gap) |
…y, condensed comments Also fixes two latent issues in the OTA test mock surfaced by the review changes: the mock waitFor was missing the defaultRspCommandId parameter (so its timeout argument received the response command id), and the mock now emulates the adapter waiter's timeout so device-silence scenarios fail the same way they do live. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
Do you have the full logs (with the ZH low level stuff) so we can actually see what is happening? |
|
I'd like to see full debug-level logs as well. IIRC, I never had issues updating Hue bulbs. One thing we could try is pairing a misbehaving Hue Dimmer Switch to a Hue Bridge and capture the OTAU with Wireshark. Maybe Hue is doing something interesting? |
Are you wanting more depth in the given time range (enabling lower level logging) or a larger time range. Just want to make sure I get you what you are asking for. |
|
Mostly want to see what is going on in these 10 seconds at the lower layer. It is a curious behavior, so, would be good to know what the device is doing exactly. |
|
ct158-before-10s-unfiltered.txt I'm hoping this is fully unfiltered. Captured with z2m set to debug level. |
|
Sample is fairly limited (there's just one occurrence in the file), and no millis in the timestamps to be sure, but looks like the device may not be waiting for the response before requesting another block (as predicted)... so, race conditions ensue (sometimes it's fine, sometimes it's not, exactly as in the logs). Dangerous behavior, I'd say likely a bug in the firmware. Logic of the PR looks fine from what I can tell. Someone needs to test a real/live error (forcing error through device power off or something), to ensure errors are still propagated upstream and cleanup happens properly. |
|
I've seen reports of slow Hue updates, but never had the issue myself. Network with only one device (Telink), right next to coordinator (MG21). OTA options: 
I ran the test twice. First time the OTA was ~30% faster with this fix (241s -> 177s). 
Second time it was identical (244s). But again I don't see any of those gaps in my logs.. |
|
The estimate is always unreliable indeed (at least comparing between two runs), too many factors can affect it; differences likely have nothing to do with this specific PR. Are you able to yank a device off during update to check the error path and state afterwards are still correct? |
|
Ah I forgot, will do |
|
@mattlathrop meantime, can you look at the refactors I mentioned about the tests? |
|
Yes I powered off the device during the update. Got the timeout error in Z2M after 150s 
|
4 participants
Was having issues with OTA updates on Hue bulbs with the SLZB-06. Fable came up with the below which seems to have great results.
OtaSession.commandStream() only armed the imageBlockRequest/imagePageRequest waiters at the top of its loop, i.e. after the consumer had fully sent the previous imageBlockResponse and resumed the generator. Fast devices (e.g. Philips Hue, which request with minimumBlockPeriod=0) send their next request within milliseconds of receiving a response — inside that unarmed window — so every follow-up request was dropped and the transfer only advanced on the device's ~10s retry timeout: ~9,200 blocks x ~10s = ~23 hours per Hue bulb.
Arm the next pair of waiters before yielding each request so an early request is captured by an already-armed waiter, keep passive rejection handlers on the armed promises (they can settle while the generator is suspended at yield), and cancel the armed pair in a finally block when the generator closes.
The OTA test harness previously fabricated the device's next request at waiter-arm time — encoding the same arm-then-request assumption this change removes. It now produces requests lazily, in arm order, gated on completion of the responses owed for the previously produced request (1 per block request, blocks-per-page per page request, 0 for frames that elicit no response), which models a real device regardless of when the controller arms its waiters.
Measured on a zstack coordinator (SLZB-06) with Hue BR30 bulbs: block cadence went from 1 block per ~10.9s to ~12 blocks/s; a 458KB image completed in 10m37s instead of a projected ~23h. A subsequent 13-bulb rollout completed back-to-back with zero failures.