Ignore duplicate deployment workflow not working as expected

[JoergZeidler]

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

1. Prepare device with software version "A"
2. Start an update via IotHub to software version "B"
3. 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)
4. wait at least 1h
5. 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]

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]

Any news about that topic in general?

Unfortunately, I haven't found a solution by myself for the use case(#609 (comment)) yet and need pls support here....

[agreentree-dmc]

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

[JoergZeidler]

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

@agreentree-dmc
unfortunately no.....

[ortogonal]

I guess this is the same error as seen in #625

I did some code investigations please see #625 (comment)