search

espressif / esp-aws-iot

AWS IoT SDK for ESP32 based chipsets
Apache License 2.0
266 stars 157 forks source link

OTA fails with larger updates (4.6MB) (CA-252) #148

Closed davidallenmann closed 1 year ago

davidallenmann commented 1 year ago

ESP32-Wroom-2 DevKit-C N32R8 ESP-IDF v4.4.2-378-g9269a536ac OTA update using MQTT fails for 4.6MB binary. factory, ota_1 and ota_2Partition is 5 MB.

Initial errors start with Receiving duplicate blocks once number of blocks exceeds 1024


I (793253) AWS_OTA: Received valid file block: Block index=1025, Size=4096
I (793273) AWS_OTA: Number of blocks remaining: 118
I (793283) coreMQTT: Packet received. ReceivedBytes=4211.
I (793283) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793283) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793293) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793313) AWS_OTA: Received data message callback, size 4122.

I (793333) coreMQTT: Packet received. ReceivedBytes=4211.
I (793333) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793333) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793343) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793363) AWS_OTA: Received data message callback, size 4122.

I (793373) coreMQTT: Packet received. ReceivedBytes=4211.
I (793383) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793383) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793393) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793413) AWS_OTA: Received data message callback, size 4122.

I (793423) coreMQTT: Packet received. ReceivedBytes=4211.
I (793423) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793433) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793443) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793453) AWS_OTA: Received data message callback, size 4122.

I (793473) coreMQTT: Packet received. ReceivedBytes=4211.
I (793473) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793483) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793483) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793503) AWS_OTA: Received data message callback, size 4122.

I (793523) coreMQTT: Packet received. ReceivedBytes=4211.
I (793523) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793533) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793533) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793553) AWS_OTA: Received data message callback, size 4122.

I (793573) coreMQTT: Packet received. ReceivedBytes=4211.
I (793573) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (793573) coreMQTT: State record updated. New state=MQTTPublishDone.
I (793583) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (793603) AWS_OTA: Received data message callback, size 4122.

I (796613) AWS_OTA: Sent PUBLISH packet to broker $aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update to broker.

I (796613) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796623) AWS_OTA: Received valid file block: Block index=1028, Size=4096
W (796633) AWS_OTA: Received a duplicate block: Block index=1028, Block size=4096
I (796633) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796653) AWS_OTA: Received valid file block: Block index=1029, Size=4096
I (796663) AWS_OTA: Number of blocks remaining: 117
I (796663) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796673) AWS_OTA: Received valid file block: Block index=1033, Size=4096
I (796683) AWS_OTA: Number of blocks remaining: 116
I (796683) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796683) AWS_OTA:  Received: 1032   Queued: 1032   Processed: 1027   Dropped: 0
I (796693) AWS_OTA: Received valid file block: Block index=1037, Size=4096
I (796723) AWS_OTA: Number of blocks remaining: 115
I (796723) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796733) AWS_OTA: Received valid file block: Block index=1041, Size=4096
W (796733) AWS_OTA: Received a duplicate block: Block index=1041, Block size=4096
I (796743) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796753) AWS_OTA: Received valid file block: Block index=1044, Size=4096
W (796763) AWS_OTA: Received a duplicate block: Block index=1044, Block size=4096
I (796773) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796783) AWS_OTA: Received valid file block: Block index=1050, Size=4096
W (796793) AWS_OTA: Received a duplicate block: Block index=1050, Block size=4096
I (796803) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (796813) coreMQTT: Packet received. ReceivedBytes=91.
I (796813) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (796823) coreMQTT: State record updated. New state=MQTTPublishDone.
I (796833) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/jobs/#, TopicName=$aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update/accepted
I (796853) AWS_OTA: Received job message $aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update/accepted{"timestamp":1667428996}ccrdyaf size 24.

After last block is received get Signature verification failed error. The same code signature works with a smaller binary.

I (924173) AWS_OTA: Received valid file block: Block index=1054, Size=4096
I (924183) AWS_OTA: Received final block of the update.
I (924413) coreMQTT: Packet received. ReceivedBytes=4211.
I (924413) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (924413) coreMQTT: State record updated. New state=MQTTPublishDone.
I (924423) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/streams/#, TopicName=$aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (924443) AWS_OTA: Received data message callback, size 4122.

E (924713) AWS_OTA: Signature verification failed.
I (927453) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (930693) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (933713) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (936903) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (939923) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (942923) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
E (944743) AWS_OTA: Failed to close the OTA file: Error=(OtaPalSignatureCheckFailed:0x000000)
E (944743) AWS_OTA: Failed to ingest data block, rejecting image: ingestDataBlock returned error: OtaErr_t=-2
I (944753) AWS_OTA: otaPal_SetPlatformImageState, 3
W (944753) AWS_OTA: Set image as invalid!
I (944763) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (944763) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0xffffffff/0x0
I (944773) esp_ota_ops: aws_esp_ota_set_boot_flags: 3 0
I (944773) esp_ota_ops: [0] aflags/seq:0xffffffff/0x0, pflags/seq:0x2/0x2
I (945923) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (946213) coreMQTT: Packet received. ReceivedBytes=2.
I (946213) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
I (946213) coreMQTT: State record updated. New state=MQTTPublishDone.
I (946223) AWS_OTA: PUBACK received for packet id 210.

I (946233) coreMQTT: Packet received. ReceivedBytes=91.
I (946233) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (946243) coreMQTT: State record updated. New state=MQTTPublishDone.
I (946253) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/jobs/#, TopicName=$aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update/accepted
I (946273) AWS_OTA: Received job message $aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update/accepted{"timestamp":1667429145}ccrdyaf size 24.

I (947173) coreMQTT: Packet received. ReceivedBytes=67.
I (947173) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (947173) coreMQTT: State record updated. New state=MQTTPublishDone.
I (947183) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/jobs/#, TopicName=$aws/things/esp32-wroom2/jobs/notify-next
I (950193) AWS_OTA: Sent PUBLISH packet to broker $aws/things/esp32-wroom2/jobs/AFR_OTA-esp32-4_6MB/update to broker.

I (950193) AWS_OTA: Received OtaJobEventFail callback from OTA Agent.
I (950193) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
E (950203) AWS_OTA: Failed to ingest data block, rejecting image: ingestDataBlock returned error: OtaErr_t=-6
I (950213) AWS_OTA: otaPal_SetPlatformImageState, 3
W (950223) AWS_OTA: Set image as invalid!
I (950223) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (950233) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0x3/0x0
I (950243) esp_ota_ops: aws_esp_ota_set_boot_flags: 3 0
I (950243) esp_ota_ops: [0] aflags/seq:0x3/0x0, pflags/seq:0x2/0x2
I (953283) AWS_OTA:  Received: 1288   Queued: 1288   Processed: 1142   Dropped: 0
I (953553) coreMQTT: Packet received. ReceivedBytes=2.
I (953563) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
I (953563) coreMQTT: State record updated. New state=MQTTPublishDone.
I (953563) AWS_OTA: PUBACK received for packet id 211.

I (953573) coreMQTT: Packet received. ReceivedBytes=174.
I (953583) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (953593) coreMQTT: State record updated. New state=MQTTPublishDone.
I (953593) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/jobs/#, TopicName=$aws/things/esp32-wroom2/jobs//update/rejected
I (953613) AWS_OTA: Received job message $aws/things/esp32-wroom2/jobs//update/rejected{"timestamp":1667429152,"code":"InvalidTopic","message":"$aws/things/esp32-wroom2/jobs//update is not a recognized job topic"}� size 126.

I (956633) AWS_OTA: Sent PUBLISH packet to broker $aws/things/esp32-wroom2/jobs//update to broker.

I (956633) AWS_OTA: Received OtaJobEventFail callback from OTA Agent.
I (956633) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock]
I (956643) AWS_OTA: otaPal_SetPlatformImageState, 4
W (956653) AWS_OTA: Set image as aborted!
I (956653) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (956663) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0x3/0x0
I (956673) esp_ota_ops: aws_esp_ota_set_boot_flags: 4 0
I (956673) esp_ota_ops: [0] aflags/seq:0x3/0x0, pflags/seq:0x2/0x2
I (959703) AWS_OTA: SUBSCRIBE topic $aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor to broker.

I (959703) AWS_OTA: Unsubscribed to MQTT topic: $aws/things/esp32-wroom2/streams/AFR_OTA-06af215c-b5e5-48e3-8950-24381ea1230f/data/cbor
I (959713) AWS_OTA: Current State=[RequestingJob], Event=[ReceivedJobDocument], New state=[RequestingJob]
E (959723) AWS_OTA: Received unexpected event: Current state=[RequestingJob], Event received=[CloseFile]
E (959733) AWS_OTA: Received unexpected event: Current state=[RequestingJob], Event received=[CloseFile]
I (959743) AWS_OTA: SUBSCRIBE topic $aws/things/esp32-wroom2/jobs/notify-next to broker.

To Reproduce

  1. Start with the OTA_MQTT example. It runs fine.

  2. Add statically defined arrays to increase the size (this is to mimic my codebase which is having the same issue).

  3. Try to run update.

Total sizes: Used static IRAM: 78282 bytes ( 283958 remain, 21.6% used) .text size: 77255 bytes .vectors size: 1027 bytes Used stat D/IRAM: 102069 bytes ( 70859 remain, 59.0% used) .data size: 18269 bytes .bss size: 83800 bytes Used Flash size : 4590362 bytes .text : 591323 bytes .rodata : 3998783 bytes Total image size: 4686913 bytes (.bin may be padded larger)

davidallenmann commented 1 year ago

sdkconfig Changed CONFIG_LOG2_FILE_BLOCK_SIZE from 12 to 13. This increases block size from 4096 to 8192. Completes successfully.

#
# AWS OTA
#
CONFIG_LOG2_FILE_BLOCK_SIZE=13
DheeranYuvaraj commented 1 year ago

@davidallenmann

OTA Example works fine. When we add this example in our Application i got the same error.

"Changed CONFIG_LOG2_FILE_BLOCK_SIZE from 12 to 13. This increases block size from 4096 to 8192." No success for us.

Any idea?

DheeranYuvaraj commented 1 year ago

Solved. There was a small mistake in the code.

anuarrozman commented 11 months ago

Hi @DheeranYuvaraj, sorry but may i know what do you mean by small mistake in the code ? because i also encounter almost identical error.