search

espressif / esp-aws-iot

AWS IoT SDK for ESP32 based chipsets
Apache License 2.0
256 stars 153 forks source link

"Factory" partition and "otadata partition is invalid, factory/ota_0 is boot partition" - OTA fails (CA-302) #191

Closed iandaintith closed 11 months ago

iandaintith commented 11 months ago

**Platform : ESP32

Branch : https://github.com/espressif/esp-aws-iot/tree/release/202210.01-LTS

ESP_IDF : esp-idf-v4.4.4**

Problem :
OTA Agent fails to boot the downloaded image if partition csv contains 'factory' partition. If 'factory' partition is removed from csv then the OTA agent works OK.

Partition table that FAILS

# Name,   Type, SubType, Offset,  Size, Flags
# Note: if you have increased the bootloader size, make sure to update the offsets to avoid overlap
nvs,      data, nvs,     0x9000,   16k,
otadata,  data, ota,     0xd000,   8K,
phy_init, data, phy,     0xf000,   4k,
factory,  app,  factory, 0x10000,  2M,
ota_0,    app,  ota_0,   0x210000, 2M,
ota_1,    app,  ota_1,   0x410000, 2M,
storage,  data, spiffs,          , 1M,

Partition table that SUCCEEDS

# Name,   Type, SubType, Offset,  Size, Flags
# Note: if you have increased the bootloader size, make sure to update the offsets to avoid overlap,,,,
nvs,      data, nvs,     0x9000,   16k,
otadata,  data, ota,     0xd000,   8K,
phy_init, data, phy,     0xf000,   4k,
ota_0,    app,  ota_0,   0x210000, 2M,
ota_1,    app,  ota_1,   0x410000, 2M,
storage,  data, spiffs,          , 1M,

Debug

On initialising the OTA agent we get this warning 

I (49719) mqtt-agent: establishing a TLS session to a14vwue44pf12r-ats.iot.eu-west-2.amazonaws.com:8883 ...
I (51179) mqtt-agent: establishing a MQTT connection for client: 78218443E4AC ...
I (51579) coreMQTT: MQTT connection established with the broker.
I (51579) mqtt-agent: session present: 0
I (51579) mqtt-agent: connected to AWS endpoint
I (52739) zappi: set rssi:-72
I (53139) AWS_OTA: otaPal_GetPlatformImageState
**I (53139) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
W (53149) esp_ota_ops: otadata partition is invalid, factory/ota_0 is boot partition**

This warning is traced to line 77 of aws_esp_ota_ops.c in _esp_get_otadata_partition().

Call stack appears to be _esp_get_otadata_partition() -> ota_select_valid() ->

On the reboot after the download 

 (21094) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
I (21094) coreMQTT: State record updated. New state=MQTTPublishDone.
I (21094) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (21104) coreMQTT: State record updated. New state=MQTTPublishDone.
I (21114) mqtt-agent: incoming publish passed to subscription manager
I (21104) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V003-3/update to broker
I (21124) AWS_OTA: Job parsing success: OtaJobParseErr_t=OtaJobParseErrNone, Job name=AFR_OTA-78218443E4AC-V003-3
I (21144) AWS_OTA: otaPal_GetPlatformImageState
**I (21144) esp_ota_ops: aws_esp_ota_get_boot_flags: 1**
**I (21174) esp_ota_ops: [0] aflags/seq:0xffffffff/0x1, pflags/seq:0xffffffff/0x0**
I (21174) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent.
I (21174) AWS_OTA: Current State=[CreatingFile], Event=[ReceivedJobDocument], New state=[CreatingFile]
I (21184) AWS_OTA: Beginning self-test.
I (21184) AWS_OTA: otaPal_GetPlatformImageState
I (21194) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
**I (21214) esp_ota_ops: [0] aflags/seq:0xffffffff/0x1, pflags/seq:0xffffffff/0x0**
W (21214) AWS_OTA: Rejecting new image and rebooting:The job is in the self-test state while the platform is not.
I (21214) AWS_OTA: otaPal_SetPlatformImageState, 3
W (21224) AWS_OTA: Set image as invalid!
I (21224) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (21254) esp_ota_ops: [0] aflags/seq:0xffffffff/0x1, pflags/seq:0xffffffff/0x0
W (21254) AWS_OTA: Image not in self test mode 4294967295
I (21254) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (21264) esp_ota_ops: [0] aflags/seq:0xffffffff/0x1, pflags/seq:0xffffffff/0x0
I (21264) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V003-3/update
I (22114) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V003-3/update.

I have seen references to this issue here https://github.com/aws/amazon-freertos/issues/1429 dating to 2019 but was supposedly fixed?

I would be grateful if you would look into this. Thanks.

iandaintith commented 11 months ago

Further information. When factory partition is removed the boot flags appear valid.

Before the OTA job runs

I (51397) mqtt-agent: connected to AWS endpoint I (52737) zappi: set rssi:-78 I (53157) AWS_OTA: otaPal_GetPlatformImageState I (53157) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (53167) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0 I (53177) AWS_OTA: Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob] I (53177) mqtt-ota: subscribing.... to topic $aws/things/78218443E4AC/jobs/notify-next with broker I (54187) mqtt-ota: resume OK I (54427) mqtt-ota: registering topic $aws/things/78218443E4AC/jobs/notify-next I (54427) mqtt-ota: [0] isMatch:1 with $aws/things/+/jobs/notify-next I (54427) mqtt-ota: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/jobs/notify-next I (54437) mqtt-ota: [1] isMatch:0 with $aws/things/+/streams/# I (54447) mqtt-ota: [2] isMatch:1 with $aws/things/+/jobs/# I (54457) mqtt-ota: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/jobs/notify-next I (54477) mqtt-ota: SUBSCRIBED to topic $aws/things/78218443E4AC/jobs/notify-next to broker I (54477) AWS_OTA: Subscribed to MQTT topic: $aws/things/78218443E4AC/jobs/notify-next I (54487) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/$next/get I (55467) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/$next/get.

I (56487) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (56487) coreMQTT: State record updated. New state=MQTTPublishDone. I (56487) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (56497) coreMQTT: State record updated. New state=MQTTPublishDone. I (56507) mqtt-agent: incoming publish passed to subscription manager I (56507) mqtt-ota: received job message callback, size 54 I (56507) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/$next/get to broker I (56537) AWS_OTA: Current State=[WaitingForJob], Event=[RequestJobDocument], New state=[WaitingForJob] I (56537) AWS_OTA: No active job available in received job document: OtaJobParseErr_t=OtaJobParseErrNoActiveJobs I (56547) AWS_OTA: otaPal_GetPlatformImageState I (56557) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (56577) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0 I (56577) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (56577) AWS_OTA: Current State=[WaitingForJob], Event=[ReceivedJobDocument], New state=[CreatingFile] I (158517) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (158517) coreMQTT: State record updated. New state=MQTTPubAckSend. I (158517) mqtt-agent: incoming publish passed to subscription manager I (158527) mqtt-ota: received job message callback, size 494 I (158547) AWS_OTA: Extracted parameter: [key: value]=[execution.jobId: AFR_OTA-78218443E4AC-V004-2] I (158547) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.streamname: AFR_OTA-71165c7f-ec65-4faa-a0ba-dc6a085c6217] I (158557) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.protocols: ["MQTT"]] I (158577) AWS_OTA: Extracted parameter: [key: value]=[filepath: /] I (158577) AWS_OTA: Extracted parameter: [key: value]=[filesize: 1019952] I (158587) AWS_OTA: Extracted parameter: [key: value]=[fileid: 0] I (158587) AWS_OTA: Extracted parameter: [key: value]=[certfile: Code Verify Key] I (158597) AWS_OTA: Extracted parameter [ sig-sha256-ecdsa: MEUCIGX4QTMzjvOK2IethxyJCiboL+Rm... ] I (158617) AWS_OTA: Job document was accepted. Attempting to begin the update. I (158617) AWS_OTA: Job parsing success: OtaJobParseErr_t=OtaJobParseErrNone, Job name=AFR_OTA-78218443E4AC-V004-2 I (158627) AWS_OTA: otaPal_GetPlatformImageState I (158627) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (158647) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0 I (158647) AWS_OTA: Writing to partition subtype 17 at offset 0x410000

Last block of OTA

I (582127) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (582137) AWS_OTA: Current State=[WaitingForFileBlock], Event=[ReceivedFileBlock], New state=[WaitingForFileBlock] I (582157) AWS_OTA: Received valid file block: Block index=993, Size=1024 I (582157) AWS_OTA: Received final block of the update. I (582737) zappi: set rssi:-79 I (583497) AWS_OTA: Signature verification succeeded. I (583497) AWS_OTA: Received entire update and validated the signature. I (583497) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update I (583517) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update.

I (584527) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (584527) coreMQTT: State record updated. New state=MQTTPublishDone. I (584527) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (584537) coreMQTT: State record updated. New state=MQTTPublishDone. I (584547) mqtt-agent: incoming publish passed to subscription manager I (584547) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update to broker I (584567) mqtt-ota: received OtaJobEventActivate callback from OTA Agent I (584577) esp_image: segment 0: paddr=00410020 vaddr=3f400020 size=2883ch (165948) map I (584677) esp_image: segment 1: paddr=00438864 vaddr=3ffbdb60 size=052d4h ( 21204) I (584697) esp_image: segment 2: paddr=0043db40 vaddr=40080000 size=024d8h ( 9432) I (584717) esp_image: segment 3: paddr=00440020 vaddr=400d0020 size=b3f54h (737108) map I (585067) esp_image: segment 4: paddr=004f3f7c vaddr=400824d8 size=1508ch ( 86156) I (585137) esp_image: segment 0: paddr=00410020 vaddr=3f400020 size=2883ch (165948) map I (585227) esp_image: segment 1: paddr=00438864 vaddr=3ffbdb60 size=052d4h ( 21204) I (585257) esp_image: segment 2: paddr=0043db40 vaddr=40080000 size=024d8h ( 9432) I (585277) esp_image: segment 3: paddr=00440020 vaddr=400d0020 size=b3f54h (737108) map I (585617) esp_image: segment 4: paddr=004f3f7c vaddr=400824d8 size=1508ch ( 86156)

After reboot

I (19771) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (19781) coreMQTT: State record updated. New state=MQTTPublishDone. I (19781) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (19791) coreMQTT: State record updated. New state=MQTTPublishDone. I (19791) mqtt-agent: incoming publish passed to subscription manager I (19801) mqtt-ota: received job message callback, size 616 I (19801) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/$next/get to broker I (19821) AWS_OTA: Current State=[WaitingForJob], Event=[RequestJobDocument], New state=[WaitingForJob] I (19831) AWS_OTA: Extracted parameter: [key: value]=[execution.jobId: AFR_OTA-78218443E4AC-V004-2] I (19841) AWS_OTA: Extracted parameter: [key: value]=[execution.statusDetails.updatedBy: 3] I (19851) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.streamname: AFR_OTA-71165c7f-ec65-4faa-a0ba-dc6a085c6217] I (19871) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.protocols: ["MQTT"]] I (19871) AWS_OTA: Extracted parameter: [key: value]=[filepath: /] I (19881) AWS_OTA: Extracted parameter: [key: value]=[filesize: 1019952] I (19881) AWS_OTA: Extracted parameter: [key: value]=[fileid: 0] I (19901) AWS_OTA: Extracted parameter: [key: value]=[certfile: Code Verify Key] I (19901) AWS_OTA: Extracted parameter [ sig-sha256-ecdsa: MEUCIGX4QTMzjvOK2IethxyJCiboL+Rm... ] I (19911) AWS_OTA: In self test mode. I (19911) AWS_OTA: New image has a higher version number than the current image: New image version=0.0.4, Previous image version=0.0.3 I (19931) AWS_OTA: Image version is valid: Begin testing file: File ID=0 I (19931) AWS_OTA: otaPal_SetPlatformImageState, 1 W (19941) AWS_OTA: Set image as testing! I (19941) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update I (20811) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update.

I (21001) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (21001) coreMQTT: State record updated. New state=MQTTPublishDone. I (21001) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (21011) coreMQTT: State record updated. New state=MQTTPublishDone. I (21021) mqtt-agent: incoming publish passed to subscription manager I (21021) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update to broker I (21041) AWS_OTA: Job parsing success: OtaJobParseErr_t=OtaJobParseErrNone, Job name=AFR_OTA-78218443E4AC-V004-2 I (21051) AWS_OTA: otaPal_GetPlatformImageState I (21051) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (21081) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (21081) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (21081) AWS_OTA: Current State=[CreatingFile], Event=[ReceivedJobDocument], New state=[CreatingFile] I (21091) AWS_OTA: Beginning self-test. I (21091) AWS_OTA: otaPal_GetPlatformImageState I (21101) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (21121) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (21121) mqtt-ota: received OtaJobEventStartTest callback from OTA Agent I (21121) AWS_OTA: otaPal_SetPlatformImageState, 2 I (21131) AWS_OTA: Set image as valid one! I (21131) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (21151) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (21151) esp_ota_ops: aws_esp_ota_set_boot_flags: 2 1 I (21161) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (21221) AWS_OTA: Disabling RTC hardware watchdog timer I (21221) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (21231) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0x2/0x1 I (21231) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update I (22021) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update.

I (22221) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (22221) coreMQTT: State record updated. New state=MQTTPublishDone. I (22231) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (22241) coreMQTT: State record updated. New state=MQTTPublishDone. I (22241) mqtt-agent: incoming publish passed to subscription manager I (22231) mqtt-ota: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V004-2/update to broker I (22281) ota_pal: Running partition type 0 subtype 17 (offset 0x00410000) I (22281) ota_pal: Configured partition type 0 subtype 17 (offset 0x00410000) I (22281) ota_pal: Current running firmware is: ota_1

SolidStateLEDLighting commented 11 months ago

I strongly suspect that you have the wrong offsets in your partition table. Both tables above can't be correct.

Delete the offsets and allow the tools to calculate them for you.

iandaintith commented 11 months ago

Thanks but the 2nd partition table works fine. Nothing wrong with offsets.

SolidStateLEDLighting commented 11 months ago

Table 2 has a lot of empty space in it. But, the offsets may be ok...

SolidStateLEDLighting commented 11 months ago

Do a full clean on the project and rebuild? I don't place manual offsets in my partition table. I allow the system to automatically calculate those offsets.

iandaintith commented 11 months ago

Thanks. Ive done many clean builds with full ota process using table 1 and table 2. I believe the problem is related to the number of bootable partitions and that the library is expecting to see ota1 and ota2 not factory when it enumerates. There was a previously problem in 2019 (see link) which was the same symptom. By means of explanation this is existing code thats been in the field for years upgrading using esp https ota. The only thing I changed was adding in the aws iot ota lib. Thanks for your comments.

SolidStateLEDLighting commented 11 months ago

I use a table that is slightly more complex than this one and I never have a problem with it -- but I don't call an agent in my AWS IOT project.

The formatting doesn't hold here so the columns are not nice to look at. What you are seeing here are sizes -- but NOT offsets.

Name, Type, SubType, Offset, Size, Flags nvs, data, nvs, , 0x006000, nvs_key, data, nvs_keys, , 0x001000, encrypted phy_init, data, phy, , 0x001000, encrypted otadata, data, ota, , 0x002000, factory, app, factory, , 0x271000, ota_0, app, ota_0, , 0x67D000, ota_1, app, ota_1, , 0x67D000,

iandaintith commented 11 months ago

Thanks. Ill try this when back in the office.

iandaintith commented 11 months ago

Hi I tried the the partitions.csv without offsets and received the same error.

I (53252) AWS_OTA: otaPal_GetPlatformImageState I (53252) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 W (53262) esp_ota_ops: otadata partition is invalid, factory/ota_0 is boot partition

SolidStateLEDLighting commented 11 months ago

I don't know why they make things so complicated. Almost everything is subscribe, publish, handle the publish-out response, and unsubscribe.

iandaintith commented 11 months ago

Despite that warning the OTA succeeded. Just an error erasing the old partition?

I (23578) mqtt-agent: incoming publish passed to subscription manager I (23578) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V006-1521/update to broker I (23598) AWS_OTA: Job parsing success: OtaJobParseErr_t=OtaJobParseErrNone, Job name=AFR_OTA-78218443E4AC-V006-1521 I (23608) AWS_OTA: otaPal_GetPlatformImageState I (23618) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (23628) esp_ota_ops: [0] aflags/seq:0x1/0x1, pflags/seq:0xffffffff/0x0 I (23628) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (23638) AWS_OTA: Current State=[CreatingFile], Event=[ReceivedJobDocument], New state=[CreatingFile] I (23648) AWS_OTA: Beginning self-test. I (23648) AWS_OTA: otaPal_GetPlatformImageState I (23658) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (23668) esp_ota_ops: [0] aflags/seq:0x1/0x1, pflags/seq:0xffffffff/0x0 I (23668) mqtt-ota: received OtaJobEventStartTest callback from OTA Agent I (23678) AWS_OTA: otaPal_SetPlatformImageState, 2 I (23688) AWS_OTA: Set image as valid one! I (23688) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (23698) esp_ota_ops: [0] aflags/seq:0x1/0x1, pflags/seq:0xffffffff/0x0 I (23698) esp_ota_ops: aws_esp_ota_set_boot_flags: 2 1 I (23718) esp_ota_ops: [0] aflags/seq:0x1/0x1, pflags/seq:0xffffffff/0x0 I (23778) AWS_OTA: Disabling RTC hardware watchdog timer I (23778) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (23788) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0 I (23788) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V006-1521/update I (24798) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected I (24818) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected to broker I (24818) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected I (24828) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta with broker I (25808) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V006-1521/update.

I (26008) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (26008) coreMQTT: State record updated. New state=MQTTPublishDone. I (26018) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (26018) coreMQTT: State record updated. New state=MQTTPublishDone. I (26028) mqtt-agent: incoming publish passed to subscription manager I (26028) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V006-1521/update to broker I (26058) ota_pal: Running partition type 0 subtype 16 (offset 0x00210000) I (26058) ota_pal: Configured partition type 0 subtype 16 (offset 0x00210000) I (26068) ota_pal: Current running firmware is: ota_0 E (26088) mqtt-ota: failed to erase last boot partition! (-1) I (26098) AWS_OTA: Current State=[WaitingForJob], Event=[StartSelfTest], New state=[WaitingForJob] I (26898) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (26898) coreMQTT: State record updated. New state=MQTTPubAckSend.

SolidStateLEDLighting commented 11 months ago

I believe that in my process, I erase the target partition just before I receive the new update. Its a slow process for a large partition.

iandaintith commented 11 months ago

Just tried a subsequent OTA and it has worked again with no warning.

I think we have cracked it. Thank you.

I (51191) mqtt-agent: establishing a MQTT connection for client: 78218443E4AC ... I (51341) coreMQTT: MQTT connection established with the broker. I (51341) mqtt-agent: session present: 0 I (51341) mqtt-agent: connected to AWS endpoint I (52791) zappi: set rssi:-66 I (53271) AWS_OTA: otaPal_GetPlatformImageState I (53271) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (53281) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (53311) AWS_OTA: Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob] I (53311) mqtt-ota: subscribing.... to topic $aws/things/78218443E4AC/jobs/notify-next with broker I (54321) mqtt-ota: resume OK I (54361) mqtt-ota: registering topic $aws/things/78218443E4AC/jobs/notify-next I (54361) mqtt-ota: [0] isMatch:1 with $aws/things/+/jobs/notify-next I (54361) mqtt-ota: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/jobs/notify-next I (54371) mqtt-ota: [1] isMatch:0 with $aws/things/+/streams/# I (54381) mqtt-ota: [2] isMatch:1 with $aws/things/+/jobs/# I (54391) mqtt-ota: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/jobs/notify-next I (54411) mqtt-ota: SUBSCRIBED to topic $aws/things/78218443E4AC/jobs/notify-next to broker I (54411) AWS_OTA: Subscribed to MQTT topic: $aws/things/78218443E4AC/jobs/notify-next I (54431) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/$next/get I (54421) mqtt-shadow: MQTT agent connected! I (54541) mqtt-shadow: subscribing ... I (54541) mqtt-common: Subscribe all. 5 topics I (54541) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/accepted with broker I (54871) mqtt-api: MQTT agent connected! I (54971) mqtt-api: subscribing ... I (54971) mqtt-common: Subscribe all. 1 topics I (54971) mqtt-common: subscribing.... to topic 78218443E4AC/hubcommand with broker I (55401) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/$next/get.

I (55461) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (55461) coreMQTT: State record updated. New state=MQTTPublishDone. I (55471) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (55471) coreMQTT: State record updated. New state=MQTTPublishDone. I (55481) mqtt-agent: incoming publish passed to subscription manager I (55491) mqtt-ota: received job message callback, size 619 I (55471) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/$next/get to broker I (55511) AWS_OTA: Current State=[WaitingForJob], Event=[RequestJobDocument], New state=[WaitingForJob] I (55511) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/accepted I (55531) AWS_OTA: Extracted parameter: [key: value]=[execution.jobId: AFR_OTA-78218443E4AC-V007-1528] I (55541) AWS_OTA: Extracted parameter: [key: value]=[execution.statusDetails.updatedBy: 6] I (55551) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.streamname: AFR_OTA-36573db5-4edf-4664-b811-c319ef1d75ab] I (55571) AWS_OTA: Extracted parameter: [key: value]=[execution.jobDocument.afr_ota.protocols: ["MQTT"]] I (55571) AWS_OTA: Extracted parameter: [key: value]=[filepath: /] I (55591) AWS_OTA: Extracted parameter: [key: value]=[filesize: 1006864] I (55541) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/accepted to broker I (55591) AWS_OTA: Extracted parameter: [key: value]=[fileid: 0] I (55611) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/accepted I (55621) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected with broker I (55611) AWS_OTA: Extracted parameter: [key: value]=[certfile: Code Verify Key] I (55641) AWS_OTA: Extracted parameter [ sig-sha256-ecdsa: MEYCIQDmurizsHkhIZwQvS/oIOt9Ennp... ] I (55661) AWS_OTA: In self test mode. I (55661) AWS_OTA: New image has a higher version number than the current image: New image version=0.0.7, Previous image version=0.0.6 I (55671) AWS_OTA: Image version is valid: Begin testing file: File ID=0 I (55681) AWS_OTA: otaPal_SetPlatformImageState, 1 W (55691) AWS_OTA: Set image as testing! I (55691) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update I (56601) mqtt-common: registered a publish callback with subscription manager for topic 78218443E4AC/hubcommand I (56621) mqtt-common: SUBSCRIBED to topic 78218443E4AC/hubcommand to broker I (56621) mqtt-common: registered a publish callback with subscription manager for topic 78218443E4AC/hubcommand I (56621) mqtt-api: subscribed OK I (56791) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected I (56811) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected to broker I (56821) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/delete/rejected I (56831) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta with broker I (57791) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update.

I (57791) zappi: set rssi:-67 I (57851) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (57851) coreMQTT: State record updated. New state=MQTTPublishDone. I (57851) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (57861) coreMQTT: State record updated. New state=MQTTPublishDone. I (57861) mqtt-agent: incoming publish passed to subscription manager I (57861) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update to broker I (57881) AWS_OTA: Job parsing success: OtaJobParseErr_t=OtaJobParseErrNone, Job name=AFR_OTA-78218443E4AC-V007-1528 I (57891) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta I (57911) AWS_OTA: otaPal_GetPlatformImageState I (57921) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (57911) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta to broker I (57931) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta I (57951) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/accepted with broker I (57941) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (57981) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (57981) AWS_OTA: Current State=[CreatingFile], Event=[ReceivedJobDocument], New state=[CreatingFile] I (57991) AWS_OTA: Beginning self-test. I (57991) AWS_OTA: otaPal_GetPlatformImageState I (58001) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (58031) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (58031) mqtt-ota: received OtaJobEventStartTest callback from OTA Agent I (58031) AWS_OTA: otaPal_SetPlatformImageState, 2 I (58031) AWS_OTA: Set image as valid one! I (58041) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (58061) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (58061) esp_ota_ops: aws_esp_ota_set_boot_flags: 2 1 I (58071) esp_ota_ops: [1] aflags/seq:0x1/0x2, pflags/seq:0x2/0x1 I (58121) AWS_OTA: Disabling RTC hardware watchdog timer I (58121) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (58131) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0x2/0x1 I (58131) mqtt-ota: publishing.... to topic $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update I (58931) coreMQTT: Publishing message to $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update.

I (58981) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/accepted I (58991) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/accepted to broker I (59001) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/accepted I (59021) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (59021) coreMQTT: State record updated. New state=MQTTPublishDone. I (59031) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (59041) coreMQTT: State record updated. New state=MQTTPublishDone. I (59041) mqtt-agent: incoming publish passed to subscription manager I (59041) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/jobs/AFR_OTA-78218443E4AC-V007-1528/update to broker I (59011) mqtt-common: subscribing.... to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/rejected with broker I (59071) ota_pal: Running partition type 0 subtype 17 (offset 0x00410000) I (59081) ota_pal: Configured partition type 0 subtype 17 (offset 0x00410000) I (59091) ota_pal: Current running firmware is: ota_1 I (59551) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (59561) coreMQTT: State record updated. New state=MQTTPubAckSend. I (59561) mqtt-agent: incoming publish passed to subscription manager I (59571) mqtt-ota: received job message callback, size 24 I (62291) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/rejected I (62301) mqtt-common: SUBSCRIBED to topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/rejected to broker I (62521) mqtt-common: registered a publish callback with subscription manager for topic $aws/things/78218443E4AC/shadow/name/deviceConfig/update/rejected I (62521) mqtt-shadow: subscribed OK I (62761) mqtt-shadow: Report to the state change: 0 I (62991) zappi: set rssi:-67 I (63471) coreMQTT: Publishing message to $aws/things/78218443E4AC/shadow/name/deviceConfig/update.

I (64881) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (64881) coreMQTT: State record updated. New state=MQTTPublishDone. I (64891) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (64891) coreMQTT: State record updated. New state=MQTTPubAckSend. I (64901) mqtt-agent: incoming publish passed to subscription manager I (65131) mqtt-shadow: incoming publish. pPublishInfo->pTopicName:$aws/things/78218443E4AC/shadow/name/deviceConfig/update/delta. I (65131) mqtt-shadow: /update/delta json payload:{"version":45,"timestamp":1690381941,"state":{"powerOn":1},"metadata":{"powerOn":{"timestamp":1689264285}},"clientToken":"062220"}:{"self_test":"ready","updatedBy":"0x00000006"},"queuedAt":1690381761,"startedAt":1690381777,"lastUpdatedAt":1690381874,"versionNumber":22,"executionNumber":1,"jobDocument":{"afr_ota":{"protocols":["MQTT"],"streamname":"AFR_OTA-36573db5-4edf-4664-b811-c319ef1d75ab","files":[{"filepath":"/","filesize":1006864,"fileid":0,"certfile":"Code Verify Key","sig-sha256-ecdsa":"MEYCIQDmurizsHkhIZwQvS/oIOt9Ennprxgq+N158aGQRXg46gIhAIpgIN723gKvJTDFQDrZomjHLDHxbHaIKNkWAV7g9Jtv"}]}}}}. I (65621) mqtt-shadow: version: 45 I (65841) mqtt-shadow: The new power on state newState:1, s_currentPowerOnState:0 I (64911) mqtt-common: sent PUBLISH packet to broker $aws/things/78218443E4AC/shadow/name/deviceConfig/update to broker I (65851) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (65861) coreMQTT: State record updated. New state=MQTTPubAckSend. I (65871) mqtt-agent: incoming publish passed to subscription manager I (66091) mqtt-shadow: incoming publish. pPublishInfo->pTopicName:$aws/things/78218443E4AC/shadow/name/deviceConfig/update/accepted. I (66091) mqtt-shadow: /update/accepted json payload:{"state":{"reported":{"powerOn":0}},"metadata":{"reported":{"powerOn":{"timestamp":1690381941}}},"version":45,"timestamp":1690381941,"clientToken":"062220"}dBy":"0x00000006"},"queuedAt":1690381761,"startedAt":1690381777,"lastUpdatedAt":1690381874,"versionNumber":22,"executionNumber":1,"jobDocument":{"afr_ota":{"protocols":["MQTT"],"streamname":"AFR_OTA-36573db5-4edf-4664-b811-c319ef1d75ab","files":[{"filepath":"/","filesize":1006864,"fileid":0,"certfile":"Code Verify Key","sig-sha256-ecdsa":"MEYCIQDmurizsHkhIZwQvS/oIOt9Ennprxgq+N158aGQRXg46gIhAIpgIN723gKvJTDFQDrZomjHLDHxbHaIKNkWAV7g9Jtv"}]}}}}. I (66571) mqtt-shadow: clientToken: 062220 I (66571) mqtt-shadow: receivedToken:62220, clientToken:62220 I (66581) mqtt-shadow: Received response from the device shadow. Previously published update with clientToken=62220 has been accepted I (66631) AWS_OTA: Current State=[WaitingForJob], Event=[StartSelfTest], New state=[WaitingForJob] I (66651) AWS_OTA: No active job available in received job document: OtaJobParseErr_t=OtaJobParseErrNoActiveJobs I (66651) AWS_OTA: otaPal_GetPlatformImageState I (66661) esp_ota_ops: aws_esp_ota_get_boot_flags: 1 I (66681) esp_ota_ops: [1] aflags/seq:0x2/0x2, pflags/seq:0xffffffff/0x0 I (66681) mqtt-ota: received OtaJobEventProcessed callback from OTA Agent. I (66681) AWS_OTA: Current State=[WaitingForJob], Event=[ReceivedJobDocument], New state=[CreatingFile]

SolidStateLEDLighting commented 11 months ago

I see here that you're using the full package. I don't use any of their demo software or that Ota agent.

I have tied everything together and I have one proccess_loop() in the whole project.

iandaintith commented 11 months ago

No I am not using their demo files but am using the OTA Agent Library and MQTT Agent.

iandaintith commented 11 months ago

Thanks for your help 👍