Unreliable OTA firmware updates

StngBo · January 18, 2024, 1:15pm

Hi All,

I am noticing that my devices are having trouble updating the firmware from a cloud flash while running my application code. Here is a Trace log from a B524SOM (OS v4.2.0) where firmware updates have failed. Sometimes it takes multiple flash attempts to be successful, sometimes it can take 10mins plus for the update to occur.

Initially I thought that it may be a signal issue, but the flash always works when the device is in safemode.

0001157446 [wiring.ble] TRACE: Disconnected
0001225436 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001225437 [comm.protocol] TRACE: message id 12 complete with code 0.00
0001225437 [comm.protocol] TRACE: rcv'd message type=13
0001593936 [comm.ota] INFO: Received UpdateStart request
0001593937 [comm.ota] INFO: File size: 44583
0001593937 [comm.ota] INFO: Chunk size: 512
0001593937 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001593938 [comm.ota] INFO: Starting firmware update
0001594445 [comm.ota] INFO: Start offset: 0
0001594445 [comm.ota] INFO: Chunk count: 88
0001594445 [comm.ota] TRACE: Window size (chunks): 256
0001594447 [comm.protocol] TRACE: rcv'd message type=17
0001594479 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001594480 [comm.ota] INFO: File size: 44583
0001594480 [comm.ota] INFO: Chunk size: 512
0001594480 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001594481 [comm.ota] INFO: Starting firmware update
0001594958 [comm.ota] INFO: Start offset: 0
0001594959 [comm.ota] INFO: Chunk count: 88
0001594959 [comm.ota] TRACE: Window size (chunks): 256
0001594960 [comm.protocol] TRACE: rcv'd message type=17
0001595130 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001595130 [comm.ota] INFO: File size: 44583
0001595131 [comm.ota] INFO: Chunk size: 512
0001595131 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001595132 [comm.ota] INFO: Starting firmware update
0001595597 [comm.ota] INFO: Start offset: 0
0001595597 [comm.ota] INFO: Chunk count: 88
0001595597 [comm.ota] TRACE: Window size (chunks): 256
0001595599 [comm.protocol] TRACE: rcv'd message type=17
0001595879 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001595879 [comm.ota] INFO: File size: 44583
0001595880 [comm.ota] INFO: Chunk size: 512
0001595880 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001595881 [comm.ota] INFO: Starting firmware update
0001596356 [comm.ota] INFO: Start offset: 0
0001596356 [comm.ota] INFO: Chunk count: 88
0001596356 [comm.ota] TRACE: Window size (chunks): 256
0001596358 [comm.protocol] TRACE: rcv'd message type=17
0001596655 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001596655 [comm.ota] INFO: File size: 44583
0001596656 [comm.ota] INFO: Chunk size: 512
0001596656 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001596657 [comm.ota] INFO: Starting firmware update
0001716866 [comm.ota] INFO: Start offset: 0
0001716866 [comm.ota] INFO: Chunk count: 88
0001716867 [comm.ota] TRACE: Window size (chunks): 256
0001716868 [comm.protocol] TRACE: rcv'd message type=17
0001717072 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001717072 [comm.ota] INFO: File size: 44583
0001717078 [comm.ota] INFO: Chunk size: 512
0001717078 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001717078 [comm.ota] INFO: Starting firmware update
0001717553 [comm.ota] INFO: Start offset: 0
0001717560 [comm.ota] INFO: Chunk count: 88
0001717560 [comm.ota] TRACE: Window size (chunks): 256
0001717561 [comm.protocol] TRACE: rcv'd message type=17
0001717563 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0001717564 [comm.ota] INFO: File size: 44583
0001717564 [comm.ota] INFO: Chunk size: 512
0001717564 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0001717565 [comm.ota] INFO: Starting firmware update
0001718026 [comm.ota] INFO: Start offset: 0
0001718027 [comm.ota] INFO: Chunk count: 88
0001718027 [comm.ota] TRACE: Window size (chunks): 256
0001718028 [comm.protocol] TRACE: rcv'd message type=17
0001718196 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001718197 [comm.protocol] TRACE: message id 13 complete with code 0.00
0001718197 [comm.protocol] TRACE: rcv'd message type=13
0001718298 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001718298 [comm.protocol] TRACE: message id 14 complete with code 0.00
0001718298 [comm.protocol] TRACE: rcv'd message type=13
0001718399 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001718399 [comm.protocol] TRACE: message id 15 complete with code 0.00
0001718399 [comm.protocol] TRACE: rcv'd message type=13
0001718500 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001718500 [comm.protocol] TRACE: message id 16 complete with code 0.00
0001718501 [comm.protocol] TRACE: rcv'd message type=13
0001718605 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001718606 [comm.protocol] TRACE: message id 17 complete with code 0.00
0001718606 [comm.protocol] TRACE: rcv'd message type=13
0001719107 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001719107 [comm.protocol] TRACE: message id 18 complete with code 0.00
0001719107 [comm.protocol] TRACE: rcv'd message type=13
0001719212 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0001719212 [comm.protocol] TRACE: message id 19 complete with code 0.00
0001719213 [comm.protocol] TRACE: rcv'd message type=13
0002085512 [comm.ota] ERROR: Transfer timeout
0002085512 [comm.protocol] ERROR: Event loop error 10
0002085513 [system] WARN: Communication loop error, closing cloud socket
0002085513 [system] INFO: Cloud: disconnecting
0002085514 [system] INFO: Cloud: disconnected
0002085514 [system] INFO: Cloud: connecting
0002085517 [system] INFO: Cloud socket connected
0002085517 [comm.protocol.handshake] INFO: Establish secure connection
0002085520 [comm.dtls] INFO: session has 0 uses
0002085533 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0002085533 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,44, next_coap_id=13
0002085534 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=19
0002085535 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
0002085851 [ncp.at] TRACE: > AT+CFUN?
0002085854 [ncp.at] TRACE: < +CFUN: 1
0002085855 [ncp.at] TRACE: < OK
0002085856 [ncp.at] TRACE: > AT+CCID
0002085858 [ncp.at] TRACE: < +CCID: 89883070000023239831
0002085858 [ncp.at] TRACE: < OK
0002085859 [ncp.at] TRACE: > AT+CGSN
0002085863 [ncp.at] TRACE: < 868986060851202
0002085864 [ncp.at] TRACE: < OK
0002085865 [ncp.at] TRACE: > AT+CGMR
0002085867 [ncp.at] TRACE: < EG91EFBR06A07M4G
0002085867 [ncp.at] TRACE: < OK
0002085868 [comm.protocol.handshake] INFO: Skipping HELLO message
0002085871 [comm.protocol] INFO: Checksum has not changed; not sending application DESCRIBE
0002085871 [comm.protocol] INFO: Checksum has not changed; not sending subscriptions
0002086113 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0002086114 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002086114 [comm.protocol] TRACE: message id 20 complete with code 0.00
0002086115 [comm.protocol] TRACE: rcv'd message type=13
0002086139 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002086140 [comm.protocol] TRACE: message id 21 complete with code 0.00
0002086140 [comm.protocol] TRACE: rcv'd message type=13
0002086241 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002086241 [comm.protocol] TRACE: message id 22 complete with code 0.00
0002086242 [comm.protocol] TRACE: rcv'd message type=13
0002086341 [system] INFO: Cloud connected
0002087301 [comm.protocol] TRACE: rcv'd message type=8
0002088338 [app.pubq] TRACE: reset or disconnect event, save files to queue
0002331164 [comm.ota] INFO: Received UpdateStart request
0002331164 [comm.ota] INFO: File size: 44583
0002331165 [comm.ota] INFO: Chunk size: 512
0002331165 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0002331166 [comm.ota] INFO: Starting firmware update
0002331629 [comm.ota] INFO: Start offset: 0
0002331630 [comm.ota] INFO: Chunk count: 88
0002331630 [comm.ota] TRACE: Window size (chunks): 256
0002331631 [comm.protocol] TRACE: rcv'd message type=17
0002331852 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0002331853 [comm.ota] INFO: File size: 44583
0002331853 [comm.ota] INFO: Chunk size: 512
0002331853 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0002331854 [comm.ota] INFO: Starting firmware update
0002332317 [comm.ota] INFO: Start offset: 0
0002332317 [comm.ota] INFO: Chunk count: 88
0002332317 [comm.ota] TRACE: Window size (chunks): 256
0002332318 [comm.protocol] TRACE: rcv'd message type=17
0002332474 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0002332475 [comm.ota] INFO: File size: 44583
0002332475 [comm.ota] INFO: Chunk size: 512
0002332476 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0002332476 [comm.ota] INFO: Starting firmware update
0002332947 [comm.ota] INFO: Start offset: 0
0002332947 [comm.ota] INFO: Chunk count: 88
0002332947 [comm.ota] TRACE: Window size (chunks): 256
0002332948 [comm.protocol] TRACE: rcv'd message type=17
0002333213 [comm.ota] WARN: Received UpdateStart request but another update is already in progress
0002333213 [comm.ota] INFO: File size: 44583
0002333214 [comm.ota] INFO: Chunk size: 512
0002333214 [comm.ota] INFO: File checksum:
7bd64459a481aa805165df94606df6285e441632527f3b292f42fa9c3256db5b
0002333214 [comm.ota] INFO: Starting firmware update
0002333680 [comm.ota] INFO: Start offset: 0
0002333680 [comm.ota] INFO: Chunk count: 88
0002333680 [comm.ota] TRACE: Window size (chunks): 256
0002333681 [comm.protocol] TRACE: rcv'd message type=17
0002333959 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002333959 [comm.protocol] TRACE: message id 23 complete with code 0.00
0002333959 [comm.protocol] TRACE: rcv'd message type=13
0002402832 [comm.ota] TRACE: Received 512 of 44583 bytes
0002402833 [comm.protocol] TRACE: rcv'd message type=19
0002402841 [comm.protocol] TRACE: rcv'd message type=19
0002402950 [comm.protocol] TRACE: rcv'd message type=19
0002403060 [comm.protocol] TRACE: rcv'd message type=19
0002403143 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002403143 [comm.protocol] TRACE: message id 24 complete with code 0.00
0002403144 [comm.protocol] TRACE: rcv'd message type=13
0002403277 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002403277 [comm.protocol] TRACE: message id 25 complete with code 0.00
0002403278 [comm.protocol] TRACE: rcv'd message type=13
0002403279 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0002403280 [comm.protocol] TRACE: message id 26 complete with code 0.00
0002403280 [comm.protocol] TRACE: rcv'd message type=13
0002403391 [comm.protocol] TRACE: rcv'd message type=19
0002403493 [comm.protocol] TRACE: rcv'd message type=19
0002403553 [comm.protocol] TRACE: rcv'd message type=19
0002403655 [comm.protocol] TRACE: rcv'd message type=19
0002403864 [comm.protocol] TRACE: rcv'd message type=19
0002403966 [comm.protocol] TRACE: rcv'd message type=19
0002404273 [comm.protocol] TRACE: rcv'd message type=19
0002404383 [comm.protocol] TRACE: rcv'd message type=19
0002404496 [comm.protocol] TRACE: rcv'd message type=19
0002404558 [comm.protocol] TRACE: rcv'd message type=19
0002404667 [comm.protocol] TRACE: rcv'd message type=19
0002404775 [comm.protocol] TRACE: rcv'd message type=19
0002404911 [comm.protocol] TRACE: rcv'd message type=19
0002405015 [comm.protocol] TRACE: rcv'd message type=19
0002405150 [comm.protocol] TRACE: rcv'd message type=19
0002405162 [comm.protocol] TRACE: rcv'd message type=19
0002405273 [comm.protocol] TRACE: rcv'd message type=19
0002405344 [comm.protocol] TRACE: rcv'd message type=19
0002405444 [comm.protocol] TRACE: rcv'd message type=19
0002405555 [comm.protocol] TRACE: rcv'd message type=19
0002405612 [comm.protocol] TRACE: rcv'd message type=19
0002405715 [comm.protocol] TRACE: rcv'd message type=19
0002454128 [comm.ota] TRACE: Received 10240 of 44583 bytes
0002454129 [comm.protocol] TRACE: rcv'd message type=19
0002454200 [comm.protocol] TRACE: rcv'd message type=19
0002454305 [comm.protocol] TRACE: rcv'd message type=19
0002454392 [comm.protocol] TRACE: rcv'd message type=19
0002454491 [comm.protocol] TRACE: rcv'd message type=19
0002454603 [comm.protocol] TRACE: rcv'd message type=19
0002454672 [comm.protocol] TRACE: rcv'd message type=19
0002454780 [comm.protocol] TRACE: rcv'd message type=19
0002454860 [comm.protocol] TRACE: rcv'd message type=19
0002454962 [comm.protocol] TRACE: rcv'd message type=19
0002455065 [comm.protocol] TRACE: rcv'd message type=19
0002455173 [comm.protocol] TRACE: rcv'd message type=19
0002455276 [comm.protocol] TRACE: rcv'd message type=19
0002455385 [comm.protocol] TRACE: rcv'd message type=19
0002455487 [comm.protocol] TRACE: rcv'd message type=19
0002455597 [comm.protocol] TRACE: rcv'd message type=19
0002455699 [comm.protocol] TRACE: rcv'd message type=19
0002455810 [comm.protocol] TRACE: rcv'd message type=19
0002455939 [comm.protocol] TRACE: rcv'd message type=19
0002455944 [comm.protocol] TRACE: rcv'd message type=19
0002456054 [comm.protocol] TRACE: rcv'd message type=19
0002456118 [comm.protocol] TRACE: rcv'd message type=19
0002456238 [comm.protocol] TRACE: rcv'd message type=19
0002456342 [comm.protocol] TRACE: rcv'd message type=19
0002456444 [comm.protocol] TRACE: rcv'd message type=19
0002456548 [comm.protocol] TRACE: rcv'd message type=19
0002456615 [comm.protocol] TRACE: rcv'd message type=19
0002456712 [comm.protocol] TRACE: rcv'd message type=19
0002456773 [comm.protocol] TRACE: rcv'd message type=19

rickkas7 · January 18, 2024, 3:11pm

Are you using SYSTEM_THREAD(ENABLED)? That is recommended.

Do you have things that block loop() from returning? That's another possibility as some things only occur between calls to loop. Ideally you want loop to be returning within a millisecond.

Do you have large delay() calls? That can also cause issues with threading disabled, because delay only services the cloud connection once per second instead of 1000 times or more per second, and that's not enough to reliably OTA.

Do you have any code that uses SINGLE_THREADED_BLOCK or turns off interrupts? That can cause problems with or without threading and it can prevent the cloud connection from being serviced.

StngBo · January 18, 2024, 5:33pm

Thanks Rick,

I am using SYSTEM_THREAD(ENABLED). It is not every loop but I do have functions that can take seconds to complete. I will rewrite these to be non blocking, I suspected that this might be the issue.

With SYSTEM_THREAD(ENABLED), does the particle not service the cloud connection during large (multi second) delay() calls?

I am not using any code for SINGLE_THREADED_BLOCK or turning off interrupts.

I suspect that I am not returning to loop() frequently enough. I will rectify this issue and report back. Thanks for the quick response.

Can I ask from the messages in the trace log, what should I be keeping an eye out for? Do any of those trace logs tip you off to the above, or are you just responding from experience? I'm just interested to learn better troubleshooting methods.

StngBo · January 20, 2024, 12:01pm

Where returning to loop within a millisecond is ideal. Do you have any idea at what length of time trouble might start to arise? After some refactoring I am down to around the 30ms mark, but this may rise slightly as I start to add in more actions.

rickkas7 · January 20, 2024, 12:16pm

That should be fine. And it's OK if sometimes it's longer. You just want to avoid situations like never returning from loop, or only returning every few seconds constantly. I know if affects functions and variables, but I'm less sure it's the cause of your OTA issue.

StngBo · January 20, 2024, 12:31pm

Thanks Rick.

I have also been seeing intermittent issues with particle functions. So the delay with returning to loop is most likely the cause of that. I will revert when the rest of the code is refactored to report if the issue has been resolved with the new lower loop return interval.

stevediaz · January 22, 2024, 2:29pm

thanks for sharing

StngBo · January 26, 2024, 8:40am

A reduced loop return time seems to have eliminated the OTA and cloud related problems. Thanks for the help

system · February 25, 2024, 6:40pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
SOLVED - OTA updates are unreliable once firmware reaches 128KB memory limit Firmware	12	2025	July 18, 2016
OTA Updates not flashing to devices Troubleshooting	9	2426	May 25, 2017
OTA Update Very Inconsistent, Solid Purple, Hard Fault Troubleshooting	1	549	July 2, 2018
OTA Repeatitly updating device when device is already at latest version Troubleshooting argon	4	995	June 20, 2019
OTA update device at version 0.6.2 shows Success but nothing uploaded Firmware	5	651	November 9, 2018

Unreliable OTA firmware updates

Related topics