Ignore duplicate deployment workflow not working as expected

JoergZeidler commented 4 months ago

During long-term testing I encountered an issue with the deployment status.

Expected Behavior

Deployment status should not change even after a token expiry refresh.

Current Behavior

Deployment status changed from Successfully back to In Progress.

Steps to Reproduce

Prepare device with software version "A"
Start an update via IotHub to software version "B"
software version "B" successfully deployed on device 3.1. current update state is succeeded 3.2 deployment status is succeeded (module twin: reported property "state": 0)
wait at least 1h
check deployment status: 5.1. deployments status changed to "in progress" (module twin: reported property "state": 6) -> NOK 5.1. current update state still succeeded

Device Information

DU Agent Version 1.1.0

Logs

token expiry connection refresh changed deployment status to "in progress"

log.txt

cutout:

Ignoring duplicate deployment 6409ddb9d8ce39ade510df4a-20242685040, action 3

[ADUC_Workflow_HandleUpdateAction:714]
PropertyUpdated event handler completed. [ADUC_Workflow_HandlePropertyUpdate:638]
Queueing message (t:1, c:0xff3f1c40, m:{"deviceUpdate":{"__t":"c","service":{"value":{"workflow":{"action":3,"id":"6409ddb9d8ce39ade>
OrchestratorPropertyUpdateCallback ended [OrchestratorUpdateCallback:517]
Sending D2C message (t:0, retries:0). [ProcessMessage:390]
Sending D2C message:
 {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},**"state":6,"**workflow":{"acti>
 2024-03-06T09:41:32.1685Z 1276[1276] [D] Sending D2C message (t:1, retries:0). [ProcessMessage:390]

Additional Information

PR to fix the issue

JoergZeidler commented 3 months ago

I found another use case where the deployment status will be switched back to "in Progress". Use Case "consciously forcing a failed state"

agent reports in this case correct state "255"
after 1h

token expired: -> agent reports state "6" -> NOK

AducIotAgent[1016]: 2024-03-08T11:18:25.9922Z 1016[1016] [D] IotHub connection status: 1, reason: 0 [IoTHub_CommunicationManager_ConnectionStatus_Callback:219]
AducIotAgent[1016]: 2024-03-08T11:18:26.0929Z 1016[1016] [I] Refreshing the handle for the PnP channels. [ADUC_PnP_Components_HandleRefresh:474]
AducIotAgent[1016]: 2024-03-08T11:18:26.4579Z 1016[1016] [I] Attempting to create connection to IotHub using type: ADUC_ConnType_Module  [ADUC_DeviceClient_Create:327]
AducIotAgent[1016]: 2024-03-08T11:18:26.4580Z 1016[1016] [I] IotHub Protocol: MQTT [GetIotHubProtocolFromConfig:265]
AducIotAgent[1016]: 2024-03-08T11:18:26.4581Z 1016[1016] [I] IoTHub Device Twin callback registered. [ADUC_DeviceClient_Create:430]
AducIotAgent[1016]: 2024-03-08T11:18:26.4581Z 1016[1016] [I] Refreshing the handle for the PnP channels. [ADUC_PnP_Components_HandleRefresh:474]
AducIotAgent[1016]: 2024-03-08T11:18:26.4581Z 1016[1016] [I] Successfully re-authenticated the IoT Hub connection. [ADUC_Refresh_IotHub_Connection_SAS_Token:690]
AducIotAgent[1016]: 2024-03-08T11:18:26.5951Z 1016[1016] [I] The connection is currently broken. Will try to authenticate in 17 seconds. [Connection_Maintenance:781]
AducIotAgent[1016]: -> 11:18:26 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: xxx-xxx-iot-hub.azure-devices.net/xxx/AducIotAgent/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.11.0%20(native%3b%20Linux%3b%20aarch64)&model-id=dtmi%3aazure%3aiot%3adeviceUpdateModel%3b3 | PWD: XXXX | CLEAN: 0
AducIotAgent[1016]: <- 11:18:26 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
AducIotAgent[1016]: 2024-03-08T11:18:26.8061Z 1016[1016] [D] IotHub connection status: 0, reason: 6 [IoTHub_CommunicationManager_ConnectionStatus_Callback:219]
AducIotAgent[1016]: -> 11:18:26 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: $iothub/twin/res/# | QOS: 0
AducIotAgent[1016]: <- 11:18:27 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
AducIotAgent[1016]: -> 11:18:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/GET/?$rid=3
AducIotAgent[1016]: <- 11:18:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/200/?$rid=3 | PAYLOAD_LEN: 7112
AducIotAgent[1016]: 2024-03-08T11:18:27.2095Z 1016[1016] [D] ComponentName:deviceUpdate, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback:536]
AducIotAgent[1016]: 2024-03-08T11:18:27.2098Z 1016[1016] [D] Update Action info string ({"workflow":{"action":3,"id":"6409ddb9d8ce39ade510df4a-202428102525"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"xxx-xxx-AG\",\"name\":\"dobi-xxx-gateway-devel\",\"version\":\"4.0.16.1\"},\"compatibility\":[{\"compatibilityid\":\"2\",\"manufacturer\":\"xxx-xxx-ag\",\"model\":\"xxx-xxx-phygate-tauri-l-imx8mm-2\"}],\"instructions\":{\"steps\":[{\"handler\":\"xxx\/swupdate_consent:1\",\"files\":[\"fcc6974b8e3f46af3\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\"}},{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"fcc6974b8e3f46af3\",\"f15b3999ab12506f0\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\",\"swuFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"arguments\":\"\",\"scriptFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\"}}]},\"files\":{\"fcc6974b8e3f46af3\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"sizeInBytes\":197165056,\"hashes\":{\"sha256\":\"S70Ly2ScDZdUv4C8fZs2ZDSpBcBbwBn+O8C8Y\/onW1c=\"}},\"f15b3999ab12506f0\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\",\"sizeInBytes\":23832,\"hashes\":{\"sha256\":\"WKxdNOxsnQdMa0+UWBkoOu+yDXMxi1Wwj4MhSAUjDqY=\"}}},\"createdDateTime\":\"2024-03-07T10:45:39.6729275Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/xxx-xxx-instance--xxx-xxx-adu.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"}), property version (3) [OrchestratorUpdateCallback:433]
AducIotAgent[1016]: 2024-03-08T11:18:27.2101Z 1016[1016] [D] Processing deployment 6409ddb9d8ce39ade510df4a-202428102525 ... [OrchestratorUpdateCallback:446]
AducIotAgent[1016]: 2024-03-08T11:18:27.2102Z 1016[1016] [D] Queueing message (t:0, c:0x3d21ca0, m:{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"6409ddb9d8ce39ade510df4a-202428102525"}}}}) [ADUC_D2C_Message_SendAsync:526]
AducIotAgent[1016]: 2024-03-08T11:18:27.2104Z 1016[1016] [E] stat path '/var/lib/adu/downloads/6409ddb9d8ce39ade510df4a-202428102525/rootkeypackage-1.json' failed: 2 [SystemUtils_IsFile:734]
AducIotAgent[1016]: 2024-03-08T11:18:27.2104Z 1016[1016] [D] Attempting download of 'http://xxx-xxx-instance--xxx-xxx-adu.b.nlu.dl.adu.microsoft.com/WestEurope/rootkeypackages/rootkeypackage-1.json' using 'DO' [ADUC_RootKeyPackageUtils_DownloadPackage:109]
AducIotAgent[1016]: 2024-03-08T11:18:27.2105Z 1016[1016] [I] Downloading File 'http://xxx-xxx-instance--xxx-xxx-adu.b.nlu.dl.adu.microsoft.com/WestEurope/rootkeypackages/rootkeypackage-1.json' to '/var/lib/adu/downloads/6409ddb9d8ce39ade510df4a-202428102525/rootkeypackage-1.json' [DownloadRootKeyPkg_DO:22]
AducIotAgent[1016]: 2024-03-08T11:18:32.2331Z 1016[1016] [I] Download rc: 1, erc: 0x00000000 [DownloadRootKeyPkg_DO:51]
AducIotAgent[1016]: 2024-03-08T11:18:32.2358Z 1016[1016] [D] No root key change. [RootKeyWorkflow_UpdateRootKeys:172]
AducIotAgent[1016]: 2024-03-08T11:18:32.2394Z 1016[1016] [W] Ignoring Retry. currentRetryToken '(NULL)', nextRetryToken '(NULL)'. [ADUC_Workflow_HandlePropertyUpdate:485]
AducIotAgent[1016]: 2024-03-08T11:18:32.2395Z 1016[1016] [D] PropertyUpdated event handler completed. [ADUC_Workflow_HandlePropertyUpdate:605]
AducIotAgent[1016]: 2024-03-08T11:18:32.2396Z 1016[1016] [D] Queueing message (t:1, c:0x3dbd3b0, m:{"deviceUpdate":{"__t":"c","service":{"value":{"workflow":{"action":3,"id":"6409ddb9d8ce39ade510df4a-202428102525"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"xxx-xxx-AG\",\"name\":\"dobi-xxx-gateway-devel\",\"version\":\"4.0.16.1\"},\"compatibility\":[{\"compatibilityid\":\"2\",\"manufacturer\":\"xxx-xxx-ag\",\"model\":\"xxx-xxx-phygate-tauri-l-imx8mm-2\"}],\"instructions\":{\"steps\":[{\"handler\":\"xxx\/swupdate_consent:1\",\"files\":[\"fcc6974b8e3f46af3\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\"}},{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"fcc6974b8e3f46af3\",\"f15b3999ab12506f0\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\",\"swuFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"arguments\":\"\",\"scriptFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\"}}]},\"files\":{\"fcc6974b8e3f46af3\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"sizeInBytes\":197165056,\"hashes\":{\"sha256\":\"S70Ly2ScDZdUv4C8fZs2ZDSpBcBbwBn+O8C8Y\/onW1c=\"}},\"f15b3999ab12506f0\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\",\"sizeInBytes\":23832,\"hashes\":{\"sha256\":\"WKxdNOxsnQdMa0+UWBkoOu+yDXMxi1Wwj4MhSAUjDqY=\"}}},\"createdDateTime\":\"2024-03-07T10:45:39.6729275Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/xxx-xxx-instance--xxx-xxx-adu.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"},"ac":200,"ad":"","av":3}}}) [ADUC_D2C_Message_SendAsync:526]
AducIotAgent[1016]: 2024-03-08T11:18:32.2398Z 1016[1016] [I] OrchestratorPropertyUpdateCallback ended [OrchestratorUpdateCallback:517]
AducIotAgent[1016]: 2024-03-08T11:18:32.2399Z 1016[1016] [D] Sending D2C message (t:0, retries:0). [ProcessMessage:390]
AducIotAgent[1016]: 2024-03-08T11:18:32.2399Z 1016[1016] [D] Sending D2C message:
AducIotAgent[1016]: {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"6409ddb9d8ce39ade510df4a-202428102525"}}}} [ADUC_D2C_Default_Message_Transport_Function:580]
AducIotAgent[1016]: 2024-03-08T11:18:32.2400Z 1016[1016] [D] Sending D2C message (t:1, retries:0). [ProcessMessage:390]
AducIotAgent[1016]: 2024-03-08T11:18:32.2400Z 1016[1016] [D] Sending D2C message:
AducIotAgent[1016]: {"deviceUpdate":{"__t":"c","service":{"value":{"workflow":{"action":3,"id":"6409ddb9d8ce39ade510df4a-202428102525"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"xxx-xxx-AG\",\"name\":\"dobi-xxx-gateway-devel\",\"version\":\"4.0.16.1\"},\"compatibility\":[{\"compatibilityid\":\"2\",\"manufacturer\":\"xxx-xxx-ag\",\"model\":\"xxx-xxx-phygate-tauri-l-imx8mm-2\"}],\"instructions\":{\"steps\":[{\"handler\":\"xxx\/swupdate_consent:1\",\"files\":[\"fcc6974b8e3f46af3\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\"}},{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"fcc6974b8e3f46af3\",\"f15b3999ab12506f0\"],\"handlerProperties\":{\"installedCriteria\":\"dobi-xxx-gateway-devel 4.0.16.1\",\"swuFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"arguments\":\"\",\"scriptFileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\"}}]},\"files\":{\"fcc6974b8e3f46af3\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu\",\"sizeInBytes\":197165056,\"hashes\":{\"sha256\":\"S70Ly2ScDZdUv4C8fZs2ZDSpBcBbwBn+O8C8Y\/onW1c=\"}},\"f15b3999ab12506f0\":{\"fileName\":\"dobi-xxx-gateway-devel_4.0.16.1_phygate-tauri-l-imx8mm-2.swu.sh\",\"sizeInBytes\":23832,\"hashes\":{\"sha256\":\"WKxdNOxsnQdMa0+UWBkoOu+yDXMxi1Wwj4MhSAUjDqY=\"}}},\"createdDateTime\":\"2024-03-07T10:45:39.6729275Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/xxx-xxx-instance--xxx-xxx-adu.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"},"ac":200,"ad":"","av":3}}} [ADUC_D2C_Default_Message_Transport_Function:580]

Imho, the agent should not touch the last state in case he doesn't do anything... -> Ignoring Retry. currentRetryToken '(NULL)', nextRetryToken '(NULL)'

JoergZeidler commented 2 months ago

Any news about that topic in general?

Unfortunately, I haven't found a solution by myself for the use case(https://github.com/Azure/iot-hub-device-update/issues/609#issuecomment-1985562107) yet and need pls support here....

agreentree-dmc commented 1 month ago

@JoergZeidler Have you heard anything further on this topic or found a work-around? I am experiencing the same issue.

JoergZeidler commented 1 month ago

@JoergZeidler Have you heard anything further on this topic or found a work-around? I am experiencing the same issue.

@agreentree-dmc unfortunately no.....

Azure / iot-hub-device-update