search

Azure / azure-sdk-for-c

This repository is for active development of the Azure SDK for Embedded C. For consumers of the SDK we recommend visiting our versioned developer docs at https://azure.github.io/azure-sdk-for-c.
MIT License
226 stars 120 forks source link

ADU Deployment failed Despite Successful Device Update #2884

Open Daphne-HU opened 3 months ago

Daphne-HU commented 3 months ago

Query/Question I am experiencing an issue where updates to my device connected to Azure IoT are being reported as failed in Azure, even though the device successfully updates. Additionally, immediately after the device has updated to the new version, Azure attempts to push the same update again, which the device correctly rejects because it's already running the updated version.

Reproduction Steps: Connect a device to Azure IoT using the azure-sdk-for-c. Deploy an update to the device via Azure IoT. Observe the device successfully applying the update. Observe device receiving same update from Azure right after initial update, which it rejects, it's already on updated version. Check the status in the Azure portal, which reports the update as failed.

Expected Behavior: The update should be reported as successful in Azure after the device successfully applies the update. Azure should not attempt to redeploy the same update to a device that is already running the updated version.

Actual Behavior: The Azure portal reports the update as failed, even though the device has successfully updated. The device receives the same update again immediately after the first successful update, which it then correctly rejects.

Why is this not a Bug or a feature Request? This issue doesn't strictly qualify as a bug because the core functionality (deploying updates) is working as designed. I don't know if I'm doing something wrong or if it is a bug. It's also not a feature request, as I'm not asking for new capabilities.

Setup (please complete the following information if applicable):

logging:

--- esp-idf-monitor 1.4.0 on /dev/ttyUSB0 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ESP-ROM:esp32c3-api1-20210207 Build:Feb 7 2021 rst:0x1 (POWERON),boot:0xf (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd5820,len:0x16d8 load:0x403cc710,len:0x94c load:0x403ce710,len:0x2fe8 entry 0x403cc710 I (30) boot: ESP-IDF v5.1.3-416-gd23b7a0361 2nd stage bootloader I (30) boot: chip revision: v0.4 I (30) boot.esp32c3: SPI Speed : 80MHz I (34) boot.esp32c3: SPI Mode : DIO I (39) boot.esp32c3: SPI Flash Size : 4MB I (44) boot: Enabling RNG early entropy source... I (49) boot: Partition Table: I (53) boot: ## Label Usage Type ST Offset Length I (60) boot: 0 storage WiFi data 01 02 00013000 00002000 I (67) boot: 1 phy_init RF data 01 01 00015000 00001000 I (75) boot: 2 otadata OTA data 01 00 00016000 00002000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00180000 I (90) boot: 4 ota_1 OTA app 00 11 001a0000 00180000 I (97) boot: 5 nvs WiFi data 01 02 00320000 00010000 I (105) boot: End of partition table I (109) boot: No factory image, trying OTA 0 I (114) esp_image: segment 0: paddr=00020020 vaddr=3c0d0020 size=35cc0h (220352) map I (158) esp_image: segment 1: paddr=00055ce8 vaddr=3fc91600 size=02e8ch ( 11916) load I (160) esp_image: segment 2: paddr=00058b7c vaddr=40380000 size=0749ch ( 29852) load I (169) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=cac40h (830528) map I (304) esp_image: segment 4: paddr=0012ac68 vaddr=4038749c size=09fdch ( 40924) load I (312) esp_image: segment 5: paddr=00134c4c vaddr=00000000 size=0b384h ( 45956) I (325) boot: Loaded app from partition at offset 0x20000 I (357) boot: Set actual ota_seq=1 in otadata[0] I (357) boot: Disabling RNG early entropy source... I (368) cpu_start: Unicore app I (369) cpu_start: Pro cpu up. I (377) cpu_start: Pro cpu start user code I (377) cpu_start: cpu freq: 160000000 Hz I (377) cpu_start: Application information: I (380) cpu_start: Project name: ProdjectName I (386) cpu_start: App version: 539427d-dirty I (391) cpu_start: Compile time:
I (395) cpu_start: ELF file SHA256: e07bd28536f83e17... I (401) cpu_start: ESP-IDF: v5.1.3-416-gd23b7a0361 I (408) cpu_start: Min chip rev: v0.3 I (412) cpu_start: Max chip rev: v1.99 I (417) cpu_start: Chip rev: v0.4 I (422) heap_init: Initializing. RAM available for dynamic allocation: I (429) heap_init: At 3FCA28A0 len 0001D760 (117 KiB): DRAM I (435) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION I (443) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK I (450) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM I (457) spi_flash: detected chip: generic I (461) spi_flash: flash io: dio I (468) sleep: Configure to isolate all GPIO pins in sleep state I (472) sleep: Enable automatic switching of GPIO sleep configuration I (479) app_start: Starting scheduler on CPU0 I (484) main_task: Started on CPU0 I (484) main_task: Calling app_main() I (484) Controller: ---------- #################### Starting up #################### ---------- I (494) Controller: Controller: Software version: 0.0.0-feature.initOTAUpdate+dirty.539427d I (504) Controller: Controller: ADU version: 1.2 I (514) Controller: Current boot partition: ota_0 I (514) Controller: ---------- Starting services---------- I (544) HMIService: Start I (544) Measurement: Start I (544) pp: pp rom version: 9387209 I (544) net80211: net80211 rom version: 9387209 I (554) wifi:wifi driver task: 3fcb1e0c, prio:23, stack:6656, core=0 I (554) wifi:wifi firmware version: 92daf4348 I (554) wifi:wifi certification version: v7.0 I (554) wifi:config NVS flash: enabled I (564) wifi:config nano formating: disabled I (564) wifi:Init data frame dynamic rx buffer num: 32 I (574) wifi:Init static rx mgmt buffer num: 5 I (574) wifi:Init management short buffer num: 32 I (584) wifi:Init dynamic tx buffer num: 32 I (584) wifi:Init static tx FG buffer num: 2 I (584) wifi:Init static rx buffer size: 1600 I (594) wifi:Init static rx buffer num: 10 I (594) wifi:Init dynamic rx buffer num: 32 I (604) wifi_init: rx ba win: 6 I (604) wifi_init: tcpip mbox: 32 I (604) wifi_init: udp mbox: 6 I (614) wifi_init: tcp mbox: 6 I (614) wifi_init: tcp tx win: 5760 I (614) wifi_init: tcp rx win: 5760 I (624) wifi_init: tcp mss: 1440 I (624) wifi_init: WiFi IRAM OP enabled I (634) wifi_init: WiFi RX IRAM OP enabled I (634) phy_init: phy_version 1150,7c3c08f,Jan 24 2024,17:32:21 I (674) wifi:mode : sta (74:4d:bd:fd:1f:b8) I (674) wifi:enable tsf I (684) WiFiDevice: WIFI STA START, connecting! I (684) wifi:Set ps type: 1, coexist: 0 I (684) ADUService: Received connection status: 1 I (684) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (694) wifi:state: init -> auth (b0) I (694) ADUService: Callback: GOT_INTERNET_CONNECTION I (704) ADUService: Waiting for time synchronization with SNTP server I (704) wifi:state: auth -> assoc (0) I (714) main_task: Returned from app_main() I (724) wifi:state: assoc -> run (10) I (744) wifi:connected with One plus, aid = 2, channel 1, BW20, bssid = ca:34:53:ff:db:4e I (744) wifi:security: WPA2-PSK, phy: bgn, rssi: -43 I (744) wifi:pm start, type: 1 I (744) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us I (754) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000 I (804) wifi:idx:0 (ifx:0, ca:34:53:ff:db:4e), tid:0, ssn:4, winSize:64 I (814) wifi:dp: 2, bi: 102400, li: 4, scale listen interval from 307200 us to 409600 us I (814) wifi:AP's beacon interval = 102400 us, DTIM period = 2 I (1764) esp_netif_handlers: sta ip: 192.168.82.82, mask: 255.255.255.0, gw: 192.168.82.190 I (1764) WiFiDevice: got ip: 192.168.82.82 I (24514) ADUService: Time synchronization done, timeVal: 1723134344 I (24614) ADUService: Callback: TIME_INITIALIZED I (24614) ADUService: Callback: CREDENTIALS_SET I (24614) ADUService: Try creating TLS connection to myiothubdevicesname.azure-devices.net:8883. I (26274) esp_tls: (Network connection 0x3fc950ec) Connection to myiothubdevicesname.azure-devices.net established. I (26284) ADUService: Callback: TLS_CONNECTION_CREATED I (26294) ADUService: Callback: IOT_CLIENTS_INITIALIZED I (26304) ADUService: Creating an MQTT connection to myiothubdevicesname.azure-devices.net. I (26304) AZ IOT: myiothubdevicesname.azure-devices.net%2Fdevices%2FmyDevice 1723137946 I (26524) MQTT: Packet received. ReceivedBytes=2. I (26534) MQTT: CONNACK session present bit not set. I (26534) MQTT: Connection accepted. I (26544) MQTT: Received MQTT CONNACK successfully from broker. I (26544) MQTT: MQTT connection established with the broker. I (26554) AZ IOT: An MQTT connection is established with myiothubdevicesname.azure-devices.net I (26564) ADUService: MQTT connection to myiothubdevicesname.azure-devices.net created. I (26744) MQTT: Packet received. ReceivedBytes=3. I (26754) AZ IOT: Suback receive context found: 0x00000001 I (26924) MQTT: Packet received. ReceivedBytes=4. I (26934) AZ IOT: Suback receive context found: 0x00000002 I (26944) ADUService: IoT Hub Client Subscribe callback functions set I (27124) ADUService: IOT Hub connected I (27124) ADUService: Callback: MQTT_CONNECTION_CREATED I (27134) ADUService: Controller: ADU version: 1.2 I (27134) ADUService: Current boot partition: ota_0 I (27364) MQTT: Packet received. ReceivedBytes=4068. I (27374) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (27384) MQTT: State record updated. New state=MQTTPublishDone. I (27384) AZ IOT: $iothub/twin/res/200/?$rid=2 I (27394) ADUService: Property document payload : {"desired":{"$version":50,"deviceUpdate":{"t":"c","service":{"fileUrls":{"fc79331bab631fda1":"http://myiothubdevicesname--myiothubdevicesname.b.nlu.dl.adu.microsoft.com/westeurope/myiothubdevicesname--myiothubdevicesname/a39180eda7cc4b32a81320717a632c30/ProdjectName.bin"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"CompayName\",\"name\":\"testupdate15\",\"version\":\"1.5\"},\"compatibility\":[{\"deviceManufacturer\":\"CompayName\",\"deviceModel\":\"mymodel\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft/swupdate:1\",\"files\":[\"fc79331bab631fda1\"],\"handlerProperties\":{\"installedCriteria\":\"1.5\"}}]},\"files\":{\"fc79331bab631fda1\":{\"fileName\":\"ProdjectName.bin\",\"sizeInBytes\":1183744,\"hashes\":{\"sha256\":\"c0Ps2wmj8GQP2MWERAus31ZHNH+JId8vVy+Xu5C62/E=\"}}},\"createdDateTime\":\"2024-08-08T15:22:12Z\"}","updateManifestSignature":"eyJhbGciOiJSUzI1NiIsInNqd2siOiJleUpoYkdjaU9pSlNVekkxTmlJc0ltdHBaQ0k2SWtGRVZTNHlNREEzTURJdVVpSjkuZXlKcmRIa2lPaUpTVTBFaUxDSnVJam9pY21OM01UVm1OMDByTm5SNGQxbzBiREl2WnpKekwycEpLM2Q0VlhwMFNWYzJkMnBqVEVrNVIxTldObkpSYzJKTUwzWjVXVXcyTTBsblZXWmxZbXgwY1hWMU1qQnhNbGROTkU1c1RHeE1RVFprWnk4ME5XSk5jbWhrYUZCb2VuSk5SVkIxV0d4Q05sSldORFZUY0dOWldHUmxVVnBYUWxvMmJtNWlWRmRTTmtRelZHVXZSaTlHSzFjeFFVRmxRbEF6YzBzd2RWQmxXbnBLTjFJd2EyVmhSbU5ZWW1OR1NrOHdZMVZ6VmpWeGJtaHZWWEpPZVc5M04wZDFXRkkwUzNSUmRHcExOMkZoY0VsWGNrcGlTMDlMU1Vsb09GRlZla0pKYlhZNWMxQkdlR2hGT1ZaSldYVjBjR1YwYkRkcE1tMVJkU3RwVHk5bFlVWkdaV0pLYWpGSlp6SnJNblV4SzFSb1kwWnZWM05GTkRkNWMxWjFUVkpRSzBWVlJtNUlVMGRCYlZSM2JHNWxOa1pXUzNSeGFYUmxSVFJJYW5saWFYRTBSa3ROYkZOQmIxQXdjMVI0UkRFNFN6TmphR2RsYWswMk1URk1NM00xWVcwMWNHZDBSMFF3VTJOc1RHaHBOVFIwY0ZGYWExRTRVSGxaY0N0T09YaDFlV04zTlU1WGJIbFhUWGxtU1VONFNGcHVMMGN5VFV4SVMzSnRiQzltTlU5VWJrdzJkRkpzVmtWTU9YbEJWVnAxVDA5dGRrdFVORlptT0dOWFpHTjBZazltTDAweEx6VlpNbEJYYkdZMFpHVTVVbTlpVm10SFVEWTNaSHBRY0ZwbFZVYzRUeTg0UWswMU56SnFhVWxpT1ZOWVZIRjBRVmxSYjJZdlZUZHNRM1JEY2xSU05ucERaM0FpTENKbElqb2lRVkZCUWlJc0ltRnNaeUk2SWxKVE1qVTJJaXdpYTJsa0lqb2lRVVJWTGpJek1EZ3dOeTVTTGxNaWZRLnpERWhCdXIxcnc4OUdpVUFGZEFTSjR5SHhVaVlSZjhSNE51YnNKSlVYRktfT2JlMEdxRWxTcGE2WXVPekppZks0a0pjUkVXMGdkY2YyaXBZSnBfaE12Ml9SNlFVY0U5SzBNZTM5MEgxczhzVHNzcGFRUGpJVUR3ZzY1N0l4TWpoNFppdVVHUm9rR1BDUENzQmFzOGpkUzE4Z2N2X1N4bmZ4d082UlpEdDlXRlBxOE5kMDdKejRpWFZzMUlSTHVXYzV2d1Q2c1ZzeTVQR0lUWHAydFRLOHgxUGpFWHp0akNoZDQ4ODhZM1NNT2JDSzM1WXBxS2hXdHVYOEl1ZjVOQXdNbFUyaXZRbnduU2cyOVBjeTJiZ01SdF8xT3FFWDQ0MU1Xa2lqXzJITVZFMnB1dld3UVQ1WExCUHZvZ2daUVM4YWk0V3NCd1I3TFpZakN5NWdsWGpub09lRzhpVklQb2k5X0dfdHJiQnpMUFZIM3pVRjdMNVBkSFhIZnVFOTd0LU0zRnYxcFV5dWtYMFNrQmRUeHE3NUpzSU5wUDQxRHlKYWh3SGMxZWRqbHc5Mjc4bkU5bHFYeHRmUkdFa2czTUFOVVktczdtVWtPVU1CdDNvTXJHU3J6a3J0UGhwb2U5eDBKVU9EOC1iVTFwTkZWRUtxRGdaVWNMUkR2VXFXUmFBIn0.eyJzaGEyNTYiOiJuNG50Y0U4ZDdRWmU1RTZKckxGQmU3RzRRT05EUllza3hSeDlHalNjTVJjPSJ9.AVUxn1Z9a65QavxBUbZxwyegciIHDUKgSa40NVqIdSiv_u_5_5hMdXUhfP_SDMx1hu9ZxZ1WUT1bFn_XoA8fr5cibk_myDa1XbdvHy30MTwsHioU2Y-pdtSSxNWk5Z7it26tbHtU-DdX8jJratObu8A0yGGr-mG19T3miHvGY31bgzQ_YgP_OtXglM4755r4L1H_lAvOdYz8rLMU2gBwwhOwlh42inCK6U-Hpn2PK78OTUYTckp80waLgcSdNqG0aKl1gg2A2zwcyky6RzcpI4nR8nzZRCTwkQWSe3YdNvGRO2ALnZBpcs-Q-G0Lg2O3xqKayd_BTBT87JjaZ4_KBvFMAiI-LqucfYGFdqzc-2OAVpi8nHPV0GU-EoKDbWZvo1t0gNR5jwaDQ6dMTT-nXi44h6bnxw9fUGP3CW1HqQMneqlW3YNIlWoQxdEqiJDPsS2BJfGEN848i_EK9Jyo59G94r1dgkm6yFUYok7mRp6zNZ2vKcrkU0XoObRINm2E","workflow":{"action":3,"id":"ef464b62-aebf-442a-99fc-11e10b8d68a5"}}}},"reported":{"$version":324,"deviceUpdate":{"t":"c","agent":{"compatPropertyNames":"manufacturer,model","deviceProperties":{"aduVer":"DU;agent/1.0.0","contractModelId":"dtmi:azure:iot:deviceUpdateContractModel;2","doVer":"1.0.0","manufacturer":"CompayName","model":"mymodel"},"installedUpdateId":"1.5","lastInstallResult":{"extendedResultCode":0,"resultCode":0,"resultDetails":"update succeeded","step_0":{"extendedResultCode":0,"resultCode":0,"resultDetails":"update succeeded"}},"state":0,"workflow":{"action":3,"id":"ef464b62-aebf-442a-99fc-11e10b8d68a5","retryTimestamp":"2024-08-07T13:14:43.9841727Z"}},"service":{"ac":406,"av":50,"value":{}}}}} I (27744) ADUService: Device property document GET received I (27754) ADUService: property version: 50 I (27764) ADUService: Properties component name: deviceUpdate I (27764) ADUService: Verifying JWS Manifest I (27864) AZ IOT: [JWS] Calculated manifest SHA matches parsed SHA I (27864) ADUService: Accepting update request I (28094) MQTT: Packet received. ReceivedBytes=43. I (28104) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (28114) MQTT: State record updated. New state=MQTTPublishDone. I (28114) AZ IOT: $iothub/twin/res/204/?$rid=1&$version=325 I (28124) ADUService: Property document payload :
I (28124) ADUService: Device reported property response received I (28574) MQTT: Packet received. ReceivedBytes=43. I (28574) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (28584) MQTT: State record updated. New state=MQTTPublishDone. I (28594) AZ IOT: $iothub/twin/res/204/?$rid=3&$version=326 I (28594) ADUService: Property document payload :
I (28604) ADUService: Device reported property response received I (34404) ADUService: Step: eAzureIoTADUUpdateStepFirmwareDownloadStarted I (34404) ADUService: Send property update. I (34524) ADUService: Connecting HTTP socket to myiothubdevicesname--myiothubdevicesname.b.nlu.dl.adu.microsoft.com I (34574) esp_sockets: (Network connection 0x3fcacb0c) Connection to myiothubdevicesname--myiothubdevicesname.b.nlu.dl.adu.microsoft.com established. I (34574) ADUService: Status: 0 I (34594) HTTP: [HTTP] Size Request Success 200 I (34604) ADUService: HTTP Range Request was successful: size 4096 bytes I (34604) ADUService: Send HTTP request. I (34634) HTTP: [HTTP] [Status 206] Received range 0 to 4096 ....... removed ........ I (51254) HTTP: [HTTP] [Status 206] Received range 1179648 to 1183744 I (51264) ADUService: Checking for ADU twin updates one more time before committing to update. I (51374) MQTT: Packet received. ReceivedBytes=43. I (51384) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (51394) MQTT: State record updated. New state=MQTTPublishDone. I (51394) AZ IOT: $iothub/twin/res/204/?$rid=5&$version=327 I (51404) ADUService: Property document payload :
I (51404) ADUService: Device reported property response received I (52424) ADUService: Image validated against hash from ADU I (52424) AZ IOT: Base64 Encoded Hash from ADU: c0Ps2wmj8GQP2MWERAus31ZHNH+JId8vVy+Xu5C62/E= I (52424) AZ IOT: Unencoded the base64 encoding I (52434) AZ IOT: Starting the mbedtls calculation: image size 4096 I (53514) AZ IOT: mbedtls calculation completed I (53514) AZ IOT: SHAs match I (53514) ADUService: Enable the update image I (53514) esp_image: segment 0: paddr=001a0020 vaddr=3c0d0020 size=35cc0h (220352) map I (53554) esp_image: segment 1: paddr=001d5ce8 vaddr=3fc91600 size=02e8ch ( 11916) I (53554) esp_image: segment 2: paddr=001d8b7c vaddr=40380000 size=0749ch ( 29852) I (53564) esp_image: segment 3: paddr=001e0020 vaddr=42000020 size=cac34h (830516) map I (53674) esp_image: segment 4: paddr=002aac5c vaddr=4038749c size=09fdch ( 40924) I (53674) esp_image: segment 5: paddr=002b4c40 vaddr=00000000 size=0b390h ( 45968) I (53684) esp_image: Verifying image signature... I (53684) secure_boot_v2: Take trusted digest key(s) from running app I (53694) secure_boot_v2: #0 app key digest == #0 trusted key digest I (53694) secure_boot_v2: Verifying with RSA-PSS... I (53754) secure_boot_v2_rsa: Signature verified successfully! I (53794) ADUService: Send property update. I (63894) ADUService: Reset the device I (63894) wifi:state: run -> init (0) I (63894) wifi:pm stop, total sleep time: 39005340 us / 63141551 us I (63894) wifi:idx:0, tid:0 I (63894) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (63904) WiFiDevice: WIFI STA DISCONNECTED, connecting again ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x3002 (ESP_ERR_WIFI_NOT_STARTED) at 0x4200f2b0 0x4200f2b0: WiFiDevice::WiFiEventHandler(void, char const, long, void) at /COMPONENT_MAIN_DIR/Application/Devices/WiFiDevice.cpp:64 (discriminator 1) file: "./main/Application/Devices/WiFiDevice.cpp" line 64 func: static void WiFiDevice::WiFiEventHandler(void, esp_event_base_t, int32_t, void*) expression: esp_wifi_connect() I (63954) wifi:flush txq I (63954) wifi:stop sw txq I (63954) wifi:lmac stop hw txq ESP-ROM:esp32c3-api1-20210207 Build:Feb 7 2021 rst:0x3 (RTC_SW_SYS_RST),boot:0xf (SPI_FAST_FLASH_BOOT) Saved PC:0x40048b82 0x40048b82: software_reset in ROM SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd5820,len:0x16d8 load:0x403cc710,len:0x94c load:0x403ce710,len:0x2fe8 entry 0x403cc710 I (35) boot: ESP-IDF v5.1.3-416-gd23b7a0361 2nd stage bootloader I (35) boot: chip revision: v0.4 I (35) boot.esp32c3: SPI Speed : 80MHz I (39) boot.esp32c3: SPI Mode : DIO I (44) boot.esp32c3: SPI Flash Size : 4MB I (49) boot: Enabling RNG early entropy source... I (54) boot: Partition Table: I (58) boot: ## Label Usage Type ST Offset Length I (65) boot: 0 storage WiFi data 01 02 00013000 00002000 I (72) boot: 1 phy_init RF data 01 01 00015000 00001000 I (80) boot: 2 otadata OTA data 01 00 00016000 00002000 I (87) boot: 3 ota_0 OTA app 00 10 00020000 00180000 I (95) boot: 4 ota_1 OTA app 00 11 001a0000 00180000 I (102) boot: 5 nvs WiFi data 01 02 00320000 00010000 I (110) boot: End of partition table I (114) esp_image: segment 0: paddr=001a0020 vaddr=3c0d0020 size=35cc0h (220352) map I (158) esp_image: segment 1: paddr=001d5ce8 vaddr=3fc91600 size=02e8ch ( 11916) load I (160) esp_image: segment 2: paddr=001d8b7c vaddr=40380000 size=0749ch ( 29852) load I (169) esp_image: segment 3: paddr=001e0020 vaddr=42000020 size=cac34h (830516) map I (304) esp_image: segment 4: paddr=002aac5c vaddr=4038749c size=09fdch ( 40924) load I (312) esp_image: segment 5: paddr=002b4c40 vaddr=00000000 size=0b390h ( 45968) I (325) boot: Loaded app from partition at offset 0x1a0000 I (325) boot: Disabling RNG early entropy source... I (337) cpu_start: Unicore app I (337) cpu_start: Pro cpu up. I (345) cpu_start: Pro cpu start user code I (346) cpu_start: cpu freq: 160000000 Hz I (346) cpu_start: Application information: I (349) cpu_start: Project name: ProdjectName I (354) cpu_start: App version: 539427d-dirty I (359) cpu_start: Compile time:
I (364) cpu_start: ELF file SHA256: 42b7574e20942795... Warning: checksum mismatch between flashed and built applications. Checksum of built application is e07bd28536f83e1774c951266856d023d5348c1efaedee4f55d894a476f00083 I (370) cpu_start: ESP-IDF: v5.1.3-416-gd23b7a0361 I (376) cpu_start: Min chip rev: v0.3 I (381) cpu_start: Max chip rev: v1.99 I (386) cpu_start: Chip rev: v0.4 I (390) heap_init: Initializing. RAM available for dynamic allocation: I (398) heap_init: At 3FCA28A0 len 0001D760 (117 KiB): DRAM I (404) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION I (411) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK I (418) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM I (425) spi_flash: detected chip: generic I (429) spi_flash: flash io: dio I (436) sleep: Configure to isolate all GPIO pins in sleep state I (440) sleep: Enable automatic switching of GPIO sleep configuration I (447) app_start: Starting scheduler on CPU0 I (452) main_task: Started on CPU0 I (452) main_task: Calling app_main() I (452) Controller: ---------- #################### Starting up #################### ---------- I (462) Controller: Controller: Software version: 0.0.0-feature.initOTAUpdate+dirty.539427d I (472) Controller: Controller: ADU version: 1.5 I (482) Controller: Current boot partition: ota_1 I (482) Controller: ---------- Starting services---------- I (512) HMIService: Start I (512) Measurement: Start I (512) pp: pp rom version: 9387209 I (512) net80211: net80211 rom version: 9387209 I (522) wifi:wifi driver task: 3fcb1e0c, prio:23, stack:6656, core=0 I (522) wifi:wifi firmware version: 92daf4348 I (522) wifi:wifi certification version: v7.0 I (522) wifi:config NVS flash: enabled I (532) wifi:config nano formating: disabled I (532) wifi:Init data frame dynamic rx buffer num: 32 I (542) wifi:Init static rx mgmt buffer num: 5 I (542) wifi:Init management short buffer num: 32 I (552) wifi:Init dynamic tx buffer num: 32 I (552) wifi:Init static tx FG buffer num: 2 I (552) wifi:Init static rx buffer size: 1600 I (562) wifi:Init static rx buffer num: 10 I (562) wifi:Init dynamic rx buffer num: 32 I (572) wifi_init: rx ba win: 6 I (572) wifi_init: tcpip mbox: 32 I (572) wifi_init: udp mbox: 6 I (582) wifi_init: tcp mbox: 6 I (582) wifi_init: tcp tx win: 5760 I (582) wifi_init: tcp rx win: 5760 I (592) wifi_init: tcp mss: 1440 I (592) wifi_init: WiFi IRAM OP enabled I (602) wifi_init: WiFi RX IRAM OP enabled I (602) phy_init: phy_version 1150,7c3c08f,Jan 24 2024,17:32:21 I (652) wifi:mode : sta (74:4d:bd:fd:1f:b8) I (652) wifi:enable tsf I (652) WiFiDevice: WIFI STA START, connecting! I (652) wifi:Set ps type: 1, coexist: 0 I (652) ADUService: Received connection status: 1 I (662) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (662) wifi:state: init -> auth (b0) I (672) ADUService: Callback: GOT_INTERNET_CONNECTION I (672) ADUService: Waiting for time synchronization with SNTP server I (682) main_task: Returned from app_main() I (682) wifi:state: auth -> assoc (0) I (712) wifi:state: assoc -> run (10) I (752) wifi:connected with One plus, aid = 2, channel 1, BW20, bssid = ca:34:53:ff:db:4e I (752) wifi:security: WPA2-PSK, phy: bgn, rssi: -43 I (762) wifi:pm start, type: 1 I (762) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us I (772) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000 I (812) wifi:idx:0 (ifx:0, ca:34:53:ff:db:4e), tid:0, ssn:4, winSize:64 I (852) wifi:dp: 2, bi: 102400, li: 4, scale listen interval from 307200 us to 409600 us I (852) wifi:AP's beacon interval = 102400 us, DTIM period = 2 I (1782) esp_netif_handlers: sta ip: 192.168.82.82, mask: 255.255.255.0, gw: 192.168.82.190 I (1782) WiFiDevice: got ip: 192.168.82.82 I (25652) ADUService: Time synchronization done, timeVal: 1723134409 I (25682) ADUService: Callback: TIME_INITIALIZED I (25682) ADUService: Callback: CREDENTIALS_SET I (25682) ADUService: Try creating TLS connection to myiothubdevicesname.azure-devices.net:8883. I (27422) esp_tls: (Network connection 0x3fc950ec) Connection to myiothubdevicesname.azure-devices.net established. I (27432) ADUService: Callback: TLS_CONNECTION_CREATED I (27442) ADUService: Callback: IOT_CLIENTS_INITIALIZED I (27442) ADUService: Creating an MQTT connection to myiothubdevicesname.azure-devices.net. I (27452) AZ IOT: myiothubdevicesname.azure-devices.net%2Fdevices%2FmyDevice 1723138011 I (27652) MQTT: Packet received. ReceivedBytes=2. I (27652) MQTT: CONNACK session present bit not set. I (27662) MQTT: Connection accepted. I (27662) MQTT: Received MQTT CONNACK successfully from broker. I (27672) MQTT: MQTT connection established with the broker. I (27672) AZ IOT: An MQTT connection is established with myiothubdevicesname.azure-devices.net I (27682) ADUService: MQTT connection to myiothubdevicesname.azure-devices.net created. I (27862) MQTT: Packet received. ReceivedBytes=3. I (27872) AZ IOT: Suback receive context found: 0x00000001 I (28052) MQTT: Packet received. ReceivedBytes=4. I (28052) AZ IOT: Suback receive context found: 0x00000002 I (28062) ADUService: IoT Hub Client Subscribe callback functions set I (28242) ADUService: IOT Hub connected I (28242) ADUService: Callback: MQTT_CONNECTION_CREATED I (28252) ADUService: Controller: ADU version: 1.5 I (28262) ADUService: Current boot partition: ota_1 I (28552) MQTT: Packet received. ReceivedBytes=4068. I (28562) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (28572) MQTT: State record updated. New state=MQTTPublishDone. I (28572) AZ IOT: $iothub/twin/res/200/?$rid=2 I (28582) ADUService: Property document payload : {"desired":{"$version":50,"deviceUpdate":{"t":"c","service":{"fileUrls":{"fc79331bab631fda1":"http://myiothubdevicesname--myiothubdevicesname.b.nlu.dl.adu.microsoft.com/westeurope/myiothubdevicesname--myiothubdevicesname/a39180eda7cc4b32a81320717a632c30/ProdjectName.bin"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"CompayName\",\"name\":\"testupdate15\",\"version\":\"1.5\"},\"compatibility\":[{\"deviceManufacturer\":\"CompayName\",\"deviceModel\":\"mymodel\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft/swupdate:1\",\"files\":[\"fc79331bab631fda1\"],\"handlerProperties\":{\"installedCriteria\":\"1.5\"}}]},\"files\":{\"fc79331bab631fda1\":{\"fileName\":\"ProdjectName.bin\",\"sizeInBytes\":1183744,\"hashes\":{\"sha256\":\"c0Ps2wmj8GQP2MWERAus31ZHNH+JId8vVy+Xu5C62/E=\"}}},\"createdDateTime\":\"2024-08-08T15:22:12Z\"}","updateManifestSignature":"eyJhbGciOiJSUzI1NiIsInNqd2siOiJleUpoYkdjaU9pSlNVekkxTmlJc0ltdHBaQ0k2SWtGRVZTNHlNREEzTURJdVVpSjkuZXlKcmRIa2lPaUpTVTBFaUxDSnVJam9pY21OM01UVm1OMDByTm5SNGQxbzBiREl2WnpKekwycEpLM2Q0VlhwMFNWYzJkMnBqVEVrNVIxTldObkpSYzJKTUwzWjVXVXcyTTBsblZXWmxZbXgwY1hWMU1qQnhNbGROTkU1c1RHeE1RVFprWnk4ME5XSk5jbWhrYUZCb2VuSk5SVkIxV0d4Q05sSldORFZUY0dOWldHUmxVVnBYUWxvMmJtNWlWRmRTTmtRelZHVXZSaTlHSzFjeFFVRmxRbEF6YzBzd2RWQmxXbnBLTjFJd2EyVmhSbU5ZWW1OR1NrOHdZMVZ6VmpWeGJtaHZWWEpPZVc5M04wZDFXRkkwUzNSUmRHcExOMkZoY0VsWGNrcGlTMDlMU1Vsb09GRlZla0pKYlhZNWMxQkdlR2hGT1ZaSldYVjBjR1YwYkRkcE1tMVJkU3RwVHk5bFlVWkdaV0pLYWpGSlp6SnJNblV4SzFSb1kwWnZWM05GTkRkNWMxWjFUVkpRSzBWVlJtNUlVMGRCYlZSM2JHNWxOa1pXUzNSeGFYUmxSVFJJYW5saWFYRTBSa3ROYkZOQmIxQXdjMVI0UkRFNFN6TmphR2RsYWswMk1URk1NM00xWVcwMWNHZDBSMFF3VTJOc1RHaHBOVFIwY0ZGYWExRTRVSGxaY0N0T09YaDFlV04zTlU1WGJIbFhUWGxtU1VONFNGcHVMMGN5VFV4SVMzSnRiQzltTlU5VWJrdzJkRkpzVmtWTU9YbEJWVnAxVDA5dGRrdFVORlptT0dOWFpHTjBZazltTDAweEx6VlpNbEJYYkdZMFpHVTVVbTlpVm10SFVEWTNaSHBRY0ZwbFZVYzRUeTg0UWswMU56SnFhVWxpT1ZOWVZIRjBRVmxSYjJZdlZUZHNRM1JEY2xSU05ucERaM0FpTENKbElqb2lRVkZCUWlJc0ltRnNaeUk2SWxKVE1qVTJJaXdpYTJsa0lqb2lRVVJWTGpJek1EZ3dOeTVTTGxNaWZRLnpERWhCdXIxcnc4OUdpVUFGZEFTSjR5SHhVaVlSZjhSNE51YnNKSlVYRktfT2JlMEdxRWxTcGE2WXVPekppZks0a0pjUkVXMGdkY2YyaXBZSnBfaE12Ml9SNlFVY0U5SzBNZTM5MEgxczhzVHNzcGFRUGpJVUR3ZzY1N0l4TWpoNFppdVVHUm9rR1BDUENzQmFzOGpkUzE4Z2N2X1N4bmZ4d082UlpEdDlXRlBxOE5kMDdKejRpWFZzMUlSTHVXYzV2d1Q2c1ZzeTVQR0lUWHAydFRLOHgxUGpFWHp0akNoZDQ4ODhZM1NNT2JDSzM1WXBxS2hXdHVYOEl1ZjVOQXdNbFUyaXZRbnduU2cyOVBjeTJiZ01SdF8xT3FFWDQ0MU1Xa2lqXzJITVZFMnB1dld3UVQ1WExCUHZvZ2daUVM4YWk0V3NCd1I3TFpZakN5NWdsWGpub09lRzhpVklQb2k5X0dfdHJiQnpMUFZIM3pVRjdMNVBkSFhIZnVFOTd0LU0zRnYxcFV5dWtYMFNrQmRUeHE3NUpzSU5wUDQxRHlKYWh3SGMxZWRqbHc5Mjc4bkU5bHFYeHRmUkdFa2czTUFOVVktczdtVWtPVU1CdDNvTXJHU3J6a3J0UGhwb2U5eDBKVU9EOC1iVTFwTkZWRUtxRGdaVWNMUkR2VXFXUmFBIn0.eyJzaGEyNTYiOiJuNG50Y0U4ZDdRWmU1RTZKckxGQmU3RzRRT05EUllza3hSeDlHalNjTVJjPSJ9.AVUxn1Z9a65QavxBUbZxwyegciIHDUKgSa40NVqIdSiv_u_5_5hMdXUhfP_SDMx1hu9ZxZ1WUT1bFn_XoA8fr5cibk_myDa1XbdvHy30MTwsHioU2Y-pdtSSxNWk5Z7it26tbHtU-DdX8jJratObu8A0yGGr-mG19T3miHvGY31bgzQ_YgP_OtXglM4755r4L1H_lAvOdYz8rLMU2gBwwhOwlh42inCK6U-Hpn2PK78OTUYTckp80waLgcSdNqG0aKl1gg2A2zwcyky6RzcpI4nR8nzZRCTwkQWSe3YdNvGRO2ALnZBpcs-Q-G0Lg2O3xqKayd_BTBT87JjaZ4_KBvFMAiI-LqucfYGFdqzc-2OAVpi8nHPV0GU-EoKDbWZvo1t0gNR5jwaDQ6dMTT-nXi44h6bnxw9fUGP3CW1HqQMneqlW3YNIlWoQxdEqiJDPsS2BJfGEN848i_EK9Jyo59G94r1dgkm6yFUYok7mRp6zNZ2vKcrkU0XoObRINm2E","workflow":{"action":3,"id":"ef464b62-aebf-442a-99fc-11e10b8d68a5"}}}},"reported":{"$version":328,"deviceUpdate":{"t":"c","agent":{"compatPropertyNames":"manufacturer,model","deviceProperties":{"aduVer":"DU;agent/1.0.0","contractModelId":"dtmi:azure:iot:deviceUpdateContractModel;2","doVer":"1.0.0","manufacturer":"CompayName","model":"mymodel"},"installedUpdateId":"1.2","lastInstallResult":{"extendedResultCode":0,"resultCode":0,"resultDetails":"update succeeded","step_0":{"extendedResultCode":0,"resultCode":0,"resultDetails":"update succeeded"}},"state":6,"workflow":{"action":3,"id":"ef464b62-aebf-442a-99fc-11e10b8d68a5","retryTimestamp":"2024-08-07T13:14:43.9841727Z"}},"service":{"ac":200,"av":50,"value":{}}}}} I (28942) ADUService: Device property document GET received I (28942) ADUService: property version: 50 I (28952) ADUService: Properties component name: deviceUpdate I (28952) ADUService: Verifying JWS Manifest I (29052) AZ IOT: [JWS] Calculated manifest SHA matches parsed SHA E (29052) ADUService: Rejecting update request (installed criteria matches current version) I (29292) MQTT: Packet received. ReceivedBytes=43. I (29292) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (29302) MQTT: State record updated. New state=MQTTPublishDone. I (29312) AZ IOT: $iothub/twin/res/204/?$rid=1&$version=329 I (29312) ADUService: Property document payload :
I (29322) ADUService: Device reported property response received I (29342) ADUService: Callback: RUN I (29342) ADUService: Controller: ADU version: 1.5 I (29342) ADUService: Current boot partition: ota_1 I (29732) MQTT: Packet received. ReceivedBytes=43. I (29742) MQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (29752) MQTT: State record updated. New state=MQTTPublishDone. I (29752) AZ IOT: $iothub/twin/res/204/?$rid=3&$version=330 I (29762) ADUService: Property document payload :
I (29762) ADUService: Device reported property response received I (30792) ADUService: Callback: RUN I (30792) ADUService: Controller: ADU version: 1.5 I (30792) ADUService: Current boot partition: ota_1 I (31812) ADUService: Callback: RUN I (31812) ADUService: Controller: ADU version: 1.5 I (31812) ADUService: Current boot partition: ota_1 I (32832) ADUService: Callback: RUN

florianhumblot commented 3 months ago

This issue is related to this: https://github.com/Azure-Samples/iot-middleware-freertos-samples/issues/394 and the problem was that the current update version being reported by the device wasn't JSON and wasn't matching what Azure was expecting.