OTA Demo Stuck after receiving all the data blocks

Radrud · July 22, 2020, 6:25pm

I have ported the AWS OTA demo code to B-L475E-IOT01A STM32 kit using the example implementation available inhttps://github.com/STMicroelectronics/amazon-freertos-ST

I have updated the PAL file, vector table and used the bootloader came with the ST example appropriately ,

I am using the AWS Free RTOS version 202002.00 2/18/2020.

After triggering the OTA job from the AWS console, Device gets all the data blocks properly, Once the final expected data block is received the example code gets stuck at some semaphore i don’t know the location in the code exactly, i have attached the debug output for your reference.
NOTE
1.ST OTA example uses version 201906.00 Major
2.This OTA example is working fine without any issues but when i try to port this to version 202002.00 , aforementioned issue occurs

Debug Output
1347 68461 [OTA Agent Task] [prvIngestDataBlock] Remaining: 2
1348 68467 [OTA Agent Task] [prvOTAAgentTask] Called handler. Current State [WaitingForFileBlock] Event [ReceivedFileBlock] New state [WaitingForFileBlock]
1349 68497 [OTA Agent Task] [prvIngestDataBlock] Received file block 363, size 1024
1350 68518 [OTA Agent Task] [prvIngestDataBlock] Remaining: 1
1351 68524 [OTA Agent Task] [prvOTAAgentTask] Called handler. Current State [WaitingForFileBlock] Event [ReceivedFileBlock] New state [WaitingForFileBlock]
1352 68565 [OTA Agent Task] [prvIngestDataBlock] Received file block 364, size 1024
1353 68587 [OTA Agent Task] [prvIngestDataBlock] Received final expected block of file.
1354 68595 [OTA Agent Task] [prvStopRequestTimer] Stopping request timer.
1355 68602 [OTA Agent Task] [prvPAL_CloseFile] Authenticating and closing file.
1356 68609 [OTA Agent Task] [prvPAL_CheckFileSignature] Started sig-sha256-ecdsa signature verification, file: /device/updates
1357 68621 [OTA Agent Task] [prvPAL_ReadAndAssumeCertificate] No such certificate file: /device/updates. Using aws_ota_codesigner_certificate.h.
1358 68999 [iot_thread] State: WaitingForFileBlock Received: 368 Queued: 0 Processed: 0 Dropped: 0
1359 70008 [iot_thread] State: WaitingForFileBlock Received: 368 Queued: 0 Processed: 0 Dropped: 0
1360 71017 [iot_thread] State: WaitingForFileBlock Received: 368 Queued: 0 Processed: 0 Dropped: 0
1361 72026 [iot_thread] State: WaitingForFileBlock Received: 368 Queued: 0 Processed: 0 Dropped: 0
1362 72748 [OTA Agent Task] [prvPAL_CloseFile] sig-sha256-ecdsa signature verification passed.
1363 72757 [OTA Agent Task] [prvContextUpdateImageHeaderAndTrailer] OTA Sequence Number: 40
1364 72766 [OTA Agent Task] [prvContextUpdateImageHeaderAndTrailer] Image - Start: 0x080201a0, End: 0x0807b5d8
1365 72780 [OTA Agent Task] [prvContextUpdateImageHeaderAndTrailer] Writing Trailer at: 0x080eb5d8
1366 72789 [OTA Agent Task] [prvPAL_CloseFile] Image header updated.
1367 72795 [OTA Agent Task] [prvIngestDataBlock] File receive complete and signature is valid.
1368 72804 [OTA Agent Task] [prvStopRequestTimer] Stopping request timer.
1369 72811 [OTA Agent Task] [prvUpdateJobStatus_Mqtt] Msg: {“status”:“IN_PROGRESS”,“statusDetails”:{“self_test”:“ready”,“updatedBy”:“0x90001”}}
1370 72825 [OTA Agent Task] [INFO ][MQTT][72825] (MQTT connection 0x10006920) MQTT PUBLISH operation queued.
1371 72835 [OTA Agent Task] [INFO ][MQTT][72835] (MQTT connection 0x10006920, PUBLISH operation 0x10006d70) Waiting for operation completion.
1372 73035 [iot_thread] State: WaitingForFileBlock Received: 368 Queued: 0 Processed: 0 Dropped: 0
1373 73200 [OTA Agent Task] [INFO ][MQTT][73200] (MQTT connection 0x10006920, PUBLISH operation 0x10006d70) Wait complete with result SUCCESS.
1374 73212 [OTA Agent Task] [prvUpdateJobStatus_Mqtt] ‘IN_PROGRESS’ to $aws/things/IET_iot_test/jobs/AFR_OTA-iet_ota_job_v9/update
1375 73224 [OTA Agent Task] Received eOTA_JobEvent_Activate callback from OTA Agent.
1376 73232 [OTA Agent Task] [INFO ][MQTT][73232] (MQTT connection 0x10006920) Disconnecting connection.
1377 73242 [OTA Agent Task] [INFO ][MQTT][73242] (MQTT connection 0x10006920, DISCONNECT operation 0x10006d70) Waiting for operation completion.
1378 73258 [OTA Agent Task] [INFO ][MQTT][73258] (MQTT connection 0x10006920, DISCONNECT operation 0x10006d70) Wait complete with result SUCCESS.
1379 73271 [OTA Agent Task] [INFO ][MQTT][73271] (MQTT connection 0x10006920) Connection disconnected.
1380 73281 [OTA Agent Task] [INFO ][MQTT][73281] (MQTT connection 0x10006920) Network connection closed.
1381 73291 [NetRecv] [ERROR][NET][73291] Error -128 while receiving data.
1382 73298 [NetRecv] [WARN ][NET][73298] Receive requested 94 bytes, but 0 bytes received instead.
1383 73307 [NetRecv] [ERROR][MQTT][73307] (MQTT connection 0x10006920) Error processing incoming data. Closing connection.

pvyawaha · July 23, 2020, 5:22am

Hello Rudresh,

The OTA process seems to be complete as the eOTA_JobEvent_Activate event was generated in the callback. After this the OTA demo should disconnect and call OTA_ActivateNewImage which must reset the device. From the log it seems the device is getting stuck after disconnect on network receive task. The error code -128 is for attempting to close a socket that is already closed.

I will look into the port you mentioned at https://github.com/STMicroelectronics/amazon-freertos-ST and investigate this issue further. As a workaround if you want to test if your port works you can try calling OTA_ActivateNewImage immediately after you get the eOTA_JobEvent_Activate event .

Radrud · July 23, 2020, 8:33am

Thanks for you response,

I will do as per your suggestion and update the status in this thread.

As I mentioned in my previous post, ST github example works fine, integration which I did for latest AWS free rtos version 202002.00 has some issues i think. I will also double check on my side the changes which I made(Updating PAL files, Vector table,config files) but i didn’t make any changes at the application level.

pvyawaha · August 6, 2020, 7:51pm

Hello Rudresh,

Did the solution worked for you and you could get OTA running ?

Radrud · August 7, 2020, 6:08am

Unfortunately no, it again got stuck before resetting…

Actually i was waiting for your reply on the actual fix,

Is this a problem with AWS SDK 202002.00 or might be an issue in my porting from 201906.00 Major? .

If you could tell me, what are the AWS SDK files that needs to be updated that would be helpful for me to verify

i have updated only the portion of the code responsible for programming the received data block in to flash and it is working fine. I didn’t make any changes with respect to data communication.

So kindly help me in debugging this problem

pvyawaha · September 2, 2020, 5:35pm

Hello Rudresh,

Is it possible to provide call stack?

Radrud · September 4, 2020, 4:50pm

This problem not occuring in the version 202007.00,
Still the error code -128 is printed but the code doesn’t stuck and resets properly

pvyawaha · September 8, 2020, 5:40pm

Hello Rudresh,

Thanks for sharing that it is working now.

Can you share the logs where you are getting error -128 with the working code?

Radrud · September 11, 2020, 7:46am

I have attached the log where the application resets properly but still getting the error -128OTA_log.c (5.6 KB)

1688 215926 [OTA Agent Task] [prvExecuteHandler] Called handler. Current State [WaitingForFileBlock] Event [ReceivedFileBlock] New state [WaitingForFileBlock] 1689 215966 [OTA Agent Task] [prvIngestDataBlock] Received file block 335, size 1024
1690 215975 [OTA Agent Task] [prvPAL_WriteBlock] writing block 1024
1691 215981 [OTA Agent Task] [prvIngestDataBlock] Received final expected block of file.
1692 215989 [OTA Agent Task] [prvStopRequestTimer] Stopping request timer.
1693 215996 [OTA Agent Task] [prvPAL_CloseFile] closing file
1694 216002 [OTA Agent Task] [prvIngestDataBlock] File receive complete and signature is valid.
1695 216011 [OTA Agent Task] [prvStopRequestTimer] Stopping request timer.
1696 216018 [OTA Agent Task] [prvPublishStatusMessage] Msg: {“status”:“IN_PROGRESS”,“statusDetails”:{“self_test”:“ready”,“updatedBy”:“0x90002”}}
1697 216032 [OTA Agent Task] [INFO ][MQTT][216032] (MQTT connection 0x10006830) MQTT PUBLISH operation queued.
1698 216042 [OTA Agent Task] [INFO ][MQTT][216042] (MQTT connection 0x10006830, PUBLISH operation 0x10006df0) Waiting for operation completion.
1699 216321 [iot_thread] [INFO ][DEMO][216321] State: WaitingForFileBlock Received: 353 Queued: 0 Processed: 0 Dropped: 0

1700 216371 [OTA Agent Task] [INFO ][MQTT][216371] (MQTT connection 0x10006830, PUBLISH operation 0x10006df0) Wait complete with result SUCCESS.
1701 216385 [OTA Agent Task] [prvPublishStatusMessage] ‘IN_PROGRESS’ to $aws/things/IET_iot_test/jobs/AFR_OTA-iet_ota_job_v4_0/update
1702 216397 [OTA Agent Task] [INFO ][DEMO][216397] Received eOTA_JobEvent_Activate callback from OTA Agent.

1703 216407 [OTA Agent Task] [INFO ][MQTT][216407] (MQTT connection 0x10006830) Disconnecting connection.
1704 216417 [OTA Agent Task] [INFO ][MQTT][216416] (MQTT connection 0x10006830, DISCONNECT operation 0x10006c88) Waiting for operation completion.
1705 216433 [OTA Agent Task] [INFO ][MQTT][216433] (MQTT connection 0x10006830, DISCONNECT operation 0x10006c88) Wait complete with result SUCCESS.
1706 216446 [OTA Agent Task] [INFO ][MQTT][216446] (MQTT connection 0x10006830) Connection disconnected.
1707 216456 [OTA Agent Task] [INFO ][MQTT][216456] (MQTT connection 0x10006830) Network connection closed.
1708 216466 [OTA Agent Task] [INFO ][DEMO][216465] Mqtt disconnected due to invoking diconnect function.

1709 216476 [NetRecv] [ERROR][NET][216476] Error -128 while receiving data.
1710 216483 [NetRecv] [WARN ][NET][216483] Receive requested 96 bytes, but 0 bytes received instead.
1711 216492 [NetRecv] [ERROR][MQTT][216492] (MQTT connection 0x10006830) Error processing incoming data. Closing connection.
1712 216504 [NetRecv] [INFO ][MQTT][216504] (MQTT connection 0x10006830) Network connection closed.
1713 216513 [NetRecv] [INFO ][DEMO][216513] Mqtt disconnected due to invalid packet received from the network.

1714 216529 [OTA Agent Task] [INFO ][MQTT][216529] (MQTT connection 0x10006830) Network connection destroyed.
1715 216539 [OTA Agent Task] [prvPAL_ActivateNewImage] Activating the new MCU image.
1716 216547 [OTA Agent Task] [prvPAL_ResetDevice] Resetting the device.
0 523 [Tmr Svc] WiFi module initialized.
1 1054 [Tmr Svc] Write certificate…
2 7765 [Tmr Svc] WiFi connected to AP ConfigureMe.
3 7770 [Tmr Svc] IP Address acquired 192.168.43.63