Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update status changes to "In Progress" sometime after "Succeeded". #625

Open
mahdighorbanpourptw opened this issue May 13, 2024 · 19 comments
Labels
bug Something isn't working

Comments

@mahdighorbanpourptw
Copy link

I have an update script which is a copy of the sample scripts and some changes to adapt it to our needs. The update works perfectly fine. The state changes from not running, in progress, succeeded. Then after a while, it changes back to In Progress. I looked at the update agent logs and there, the condition check works perfectly fine, and the update is not triggered twice! Note that, when I restart the agent, it immediately shows "Succeeded". Then the same issue, after some time, goes back to in progress.
having said, the IotHub portal, updates, update-group overview, showing inconsistent data. The first two devices, are already updated successfully, which on the upper side info box, shows correctly. But in the lower side, all of them are shown "In Progress". The third device in the list is even turned off!
image

You could also see that, in the twin, it says applied.

image

Expected behavior

The first two devices should keep showing the state "Succeeded". And the last one, should be "Not Running"

Actual behavior

All the devices are shown "In Progress".

Reproduction Steps

Use the example scripts to create an update. Assign it to the devices.

Environment

Ubuntu 22.04
IotEdge 1.4.39
DeviceIpdate-Agent 1.1.0

@josephmsft
Copy link

Is this "InProgress" state persisting continuously for the online devices? What is possibly happening is that if the device remains connected for over an hour, the IoT Hub connection can be refreshed and the agent will receive the ADM configuration again and go into the deployment workflow and report InProgress, but once in the workflow it should see it has the update installed already and report Success again. I would not expect it to stay "InProgress" for an extended period of time.

Was the offline agent ever online to receive the deployment? Or has it been offline the entire time?

@mahdighorbanpourptw
Copy link
Author

The "In Progress" state remains for a longer period. As soon as I restart the agent using "sudo systemctl restart deviceupdate-agent", it will report succeeded again. But after some time, it goes back to in progress state.
Regarding the offline device, the updates are released at midnight and when in the morning the device is turned on, should receive the update. But at the time that I took the screenshot, the device was off before and after release of the update.

@mahdighorbanpourptw
Copy link
Author

mahdighorbanpourptw commented May 14, 2024

This is the last shell log file from a device that is showing in progress few minutes after success.

2024-05-14T04:40:27.1399Z 319711[319711] [I] #   [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1399Z 319711[319711] [I] #  [2024/05/14:044027] [I] (2)List workfolder directory content: total 40468 [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1399Z 319711[319711] [I] #  drwxrwx---  2 adu  adu     4096 May 14 04:36 . [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1399Z 319711[319711] [I] #  drwxrwx--- 12 adu  adu     4096 May 14 04:34 .. [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rw-r--r--  1 do   do       125 May 14 04:34 IpinConfigurationFile.json [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rwxr--r--  1 do   do  41396256 May 14 04:34 xxxInstaller [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rw-r--r--  1 root adu      155 May 14 04:34 action_download_aduc_result.json [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rw-r--r--  1 root adu      113 May 14 04:34 action_is-installed_aduc_result.json [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rwxr-x---  1 do   do     16206 May 14 04:34 xxx-adu-update-upgrade.sh [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  -rw-r--r--  1 do   do      2323 May 14 04:36 rootkeypackage-1.json [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  / [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  [2024/05/14:044027] [I] xxxInstaller succeeded. [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] #  [2024/05/14:044027] Result: {"resultCode":600, "extendedResultCode":0,"resultDetails":"InstallUpdate: xxxInstaller installation succeeded."} [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1400Z 319711[319711] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236]
2024-05-14T04:40:27.1447Z 324327[324327] [I] Run as uid(0), defaultUid(114), effectiveUid(0), effectiveGid(124) [main:367]
2024-05-14T04:40:27.1447Z 324327[324327] [I] Executing script. Path: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/xxx-adu-update-upgrade.sh [Execute:37]
2024-05-14T04:40:27.1578Z 324327[324327] [I] ########## Begin Child's Logs ########## [ShowChildProcessLogs:231]


2024-05-14T04:40:27.1579Z 324327[324327] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG BEGIN ====
#  --action-apply --work-folder /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 --result-file /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/action_apply_aduc_result.json --installed-criteria 0.77.2162024-05-14T04:40:27.1579Z 324327[324327] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG END ====

2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] Log begin: [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] Output begin: [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  Workfolder: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] [I] ApplyUpdate() [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] [I] Note: nothing to do here. [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] [I] ApplyUpdate succeeded. [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] #  [2024/05/14:044027] Result: {"resultCode":700, "extendedResultCode":0,"resultDetails":"ApplyUpdate: Nothing to apply."} [ShowChildProcessLogs:234]
2024-05-14T04:40:27.1579Z 324327[324327] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236]

Anf here you can see the content of two log files from a device that I restarted it's agent and now is showing succeeded. before and after restart.

ShowChildProcessLogs:234] ==== MULTI-LINE LOG END ====

2024-05-14T04:55:47.7712Z 2313[2313] [I] #   [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  [2024/05/14:045547] [I] (2)List workfolder directory content: total 40464 [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  drwxrwx---  2 adu  adu     4096 May 14 04:51 . [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  drwxrwx--- 12 adu  adu     4096 May 14 04:50 .. [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  -rw-r--r--  1 do   do       125 May 14 04:50 xxx.json [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  -rwxr--r--  1 do   do  41396256 May 14 04:50 xxxInstaller [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  -rw-r--r--  1 root adu      155 May 14 04:50 action_download_aduc_result.json [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  -rw-r--r--  1 root adu      113 May 14 04:50 action_is-installed_aduc_result.json [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  -rwxr-x---  1 do   do     16206 May 14 04:50 xxx-adu-update-upgrade.sh [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  / [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  [2024/05/14:045547] [I] xxxInstaller succeeded. [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] #  [2024/05/14:045547] Result: {"resultCode":600, "extendedResultCode":0,"resultDetails":"InstallUpdate: xxxInstaller installation succeeded."} [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7712Z 2313[2313] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236]
2024-05-14T04:55:47.7743Z 7514[7514] [I] Run as uid(0), defaultUid(114), effectiveUid(0), effectiveGid(124) [main:367]
2024-05-14T04:55:47.7743Z 7514[7514] [I] Executing script. Path: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/xxx-adu-update-upgrade.sh [Execute:37]
2024-05-14T04:55:47.7885Z 7514[7514] [I] ########## Begin Child's Logs ########## [ShowChildProcessLogs:231]


2024-05-14T04:55:47.7885Z 7514[7514] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG BEGIN ====
#  --action-apply --work-folder /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 --result-file /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/action_apply_aduc_result.json --installed-criteria 0.77.2162024-05-14T04:55:47.7885Z 7514[7514] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG END ====

2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] Log begin: [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] Output begin: [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  Workfolder: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] [I] ApplyUpdate() [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] [I] Note: nothing to do here. [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] [I] ApplyUpdate succeeded. [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] #  [2024/05/14:045547] Result: {"resultCode":700, "extendedResultCode":0,"resultDetails":"ApplyUpdate: Nothing to apply."} [ShowChildProcessLogs:234]
2024-05-14T04:55:47.7886Z 7514[7514] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236]
root@xxx-ubuntu2204:/var/log/adu#
root@xxx-ubuntu2204:/var/log/adu#
root@xxx-ubuntu2204:/var/log/adu#
root@xxx-ubuntu2204:/var/log/adu# cat  adu-shell.20240514-062018.log
2024-05-14T06:20:18.2931Z 14422[14422] [I] Run as uid(0), defaultUid(114), effectiveUid(0), effectiveGid(124) [main:367]
2024-05-14T06:20:18.2932Z 14422[14422] [I] Executing script. Path: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/xxx-adu-update-upgrade.sh [Execute:37]
2024-05-14T06:20:18.3143Z 14422[14422] [I] ########## Begin Child's Logs ########## [ShowChildProcessLogs:231]


2024-05-14T06:20:18.3143Z 14422[14422] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG BEGIN ====
#  --action-is-installed --work-folder /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 --result-file /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425/action_is-installed_aduc_result.json --installed-criteria 0.77.2162024-05-14T06:20:18.3143Z 14422[14422] [I] [ShowChildProcessLogs:234] ==== MULTI-LINE LOG END ====

2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] Log begin: [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] Output begin: [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  Workfolder: /var/lib/adu/downloads/deployment-xxx-0-77-216-0514043425 [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] [I] Version: 0.1.0 [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] [I] IsInstalled("0.77.216"), path:"/etc/xxx/xxxInfo.json" [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] [I] Running: grep -F "\"DeploymentSetVersion\": \"0.77.216\"" '/etc/xxx/xxxInfo.json' [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #    "DeploymentSetVersion": "0.77.216", [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] [I] grep exit code: 0 [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] #  [2024/05/14:062018] Result: {"resultCode":900, "extendedResultCode":0,"resultDetails":"IsInstalled: InstalledCriteria met: '0.77.216'."} [ShowChildProcessLogs:234]
2024-05-14T06:20:18.3144Z 14422[14422] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236]
```

@josephmsft
Copy link

Thanks, can you open a CSS ticket with your account/instance/device information and these logs and we can follow up. This doesn't sound like expected behavior.

@agreentree-dmc
Copy link

@josephmsft Will the resolution be posted in this thread as well? I am having the same issue as originally described.

@agreentree-dmc
Copy link

@mahdighorbanpourptw were you able to resolve this issue?

@mahdighorbanpourptw
Copy link
Author

@mahdighorbanpourptw were you able to resolve this issue?

I have not yet contacted the support team. I will plan it for the next week and inform you about the resolution here.

@agreentree-dmc
Copy link

@mahdighorbanpourptw Thanks!

@jw-msft
Copy link
Contributor

jw-msft commented Jun 6, 2024

Could the full agent logs be provided? e.g. sudo tar -czvf /tmp/duagentlogs.tgz /var/log/adu/*.log

@josephmsft
Copy link

After investigating, this seems like an agent issue, we are working on a fix. Providing the logs as @jw-msft mentioned here on the ticket would be helpful.

@eshashah-msft eshashah-msft added the bug Something isn't working label Jun 6, 2024
@eshashah-msft
Copy link
Contributor

@mahdighorbanpourptw Checking if you were able to get past the issue above or if you could provide the logs if support is needed?

@eshashah-msft eshashah-msft added the no new activity No activity by author for 14 days label Aug 12, 2024
@mahdighorbanpourptw
Copy link
Author

@eshashah-msft I provided the logs however, no new updates from azure update service team.

@ortogonal
Copy link

I have the same issue. I did some investigation in the source code, but since I don't fully have the understanding of the project I cannot really just write a fix for it. But at least I can document my findings here.

After an update the status of the device is "Succeeded" which is expected. But after about 40 min they go back to "In Progress"

The log of the deviceupdate-agent looks like this:

Aug 14 06:03:26 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:26.8517Z 522[522] [E] IoTHub connection is broken. [IoTHub_CommunicationManager_ConnectionStatus_Callback:222]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:15:32 SUBSCRIBE | PACKET_ID: 4 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/# | QOS: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:15:32 SUBACK | PACKET_ID: 4 | RETURN_CODE: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=5 | PAYLOAD_LEN: 400
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=6 | PAYLOAD_LEN: 1232
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=7 | PAYLOAD_LEN: 240
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/PATCH/properties/reported/?$rid=8 | PAYLOAD_LEN: 253
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/204/?$rid=5&$version=132 | PAYLOAD_LEN: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6146Z 522[522] [D] context:0xe4fafcd8 [DefaultIoTHubSendReportedStateCompletedCallback:205]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6146Z 522[522] [D] D2C message processed successfully (t:0, r:0, content:0x15ce6bf0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6146Z 522[522] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/204/?$rid=6&$version=133 | PAYLOAD_LEN: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6148Z 522[522] [D] context:0xe4fafd80 [DefaultIoTHubSendReportedStateCompletedCallback:205]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6148Z 522[522] [D] D2C message processed successfully (t:1, r:0, content:0x15d7d850 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6148Z 522[522] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/204/?$rid=8&$version=135 | PAYLOAD_LEN: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6149Z 522[522] [D] context:0xe4fb0020 [DefaultIoTHubSendReportedStateCompletedCallback:205]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6149Z 522[522] [D] D2C message processed successfully (t:5, r:0, content:0x15d41c90 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6149Z 522[522] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:15:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/204/?$rid=7&$version=134 | PAYLOAD_LEN: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6150Z 522[522] [D] context:0xe4fafe28 [DefaultIoTHubSendReportedStateCompletedCallback:205]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6150Z 522[522] [D] D2C message processed successfully (t:2, r:0, content:0x15d440a0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T05:15:32.6151Z 522[522] [D] Send message completed (status:3) [OnDeviceInfoD2CMessageCompleted:191]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:19:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:19:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:23:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:23:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:27:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:27:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:31:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:31:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:35:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:35:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:39:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:39:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:43:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:43:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:47:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:47:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:51:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:51:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:55:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:55:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 05:59:32 PINGREQ
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 05:59:32 PINGRESP
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 06:03:26 DISCONNECT
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:26.8515Z 522[522] [D] IotHub connection status: 1, reason: 0 [IoTHub_CommunicationManager_ConnectionStatus_Callback:212]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:26.9519Z 522[522] [I] Refreshing the handle for the PnP channels. [ADUC_PnP_Components_HandleRefresh:474]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1972Z 522[522] [I] Attempting to create connection to IotHub using type: ADUC_ConnType_Module  [ADUC_DeviceClient_Create:315]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1972Z 522[522] [W] Missing 'iotHubProtocol' setting from '/adu/du-config.json'. Default to MQTT. [GetIotHubProtocolFromConfig:269]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1972Z 522[522] [I] IotHub Protocol: MQTT [GetIotHubProtocolFromConfig:271]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1973Z 522[522] [I] IoTHub Device Twin callback registered. [ADUC_DeviceClient_Create:418]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1974Z 522[522] [I] Refreshing the handle for the PnP channels. [ADUC_PnP_Components_HandleRefresh:474]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.1974Z 522[522] [I] Successfully re-authenticated the IoT Hub connection. [ADUC_Refresh_IotHub_Connection_SAS_Token:678]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.3453Z 522[522] [I] The connection is currently broken. Will try to authenticate in 17 seconds. [Connection_Maintenance:769]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 06:03:27 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: HIDDEN_IOTHUB.azure-devices.net/device-erikl-sn-1/device-update/?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
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 06:03:27 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.5574Z 522[522] [D] IotHub connection status: 0, reason: 6 [IoTHub_CommunicationManager_ConnectionStatus_Callback:212]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 06:03:27 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: $iothub/twin/res/# | QOS: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 06:03:27 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: -> 06:03:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/GET/?$rid=3
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: <- 06:03:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/res/200/?$rid=3 | PAYLOAD_LEN: 6058
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9601Z 522[522] [D] ComponentName:deviceUpdate, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback:536]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9603Z 522[522] [D] Update Action info string ({"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"ITAB\",\"name\":\"CES-OS\",\"version\":\"0.1.6\"},\"compatibility\":[{\"manufacturer\":\"itab\",\"model\":\"ces-hw-v1\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"f1676c2ffd396b8a9\",\"f5d7e494a7d0b49b2\"],\"handlerProperties\":{\"scriptFileName\":\"update-executor.sh\",\"arguments\":\"\",\"installedCriteria\":\"v0.1.6\",\"swuFileName\":\"ces-image-itab-imx8mp_0.1.6.swu\"}}]},\"files\":{\"f1676c2ffd396b8a9\":{\"fileName\":\"update-executor.sh\",\"sizeInBytes\":4978,\"hashes\":{\"sha256\":\"eGa7qnyrbL5HPQFvSMR+bOvt3T\/LSMa91AsvUZsZ4Ys=\"}},\"f5d7e494a7d0b49b2\":{\"fileName\":\"ces-image-itab-imx8mp_0.1.6.swu\",\"sizeInBytes\":215587840,\"hashes\":{\"sha256\":\"Q8OGI7PlpGMw3K4MBYwnlPV34JevTi1cXXTXwZWLRmQ=\"}}},\"createdDateTime\":\"2024-05-29T06:00:05.3448763Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/HIDDEN_URL.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"}), property version (12) [OrchestratorUpdateCallback:433]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9606Z 522[522] [D] Processing deployment db9955b3-05fa-4078-87fc-3ea736e04166 ... [OrchestratorUpdateCallback:446]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9607Z 522[522] [D] Queueing message (t:0, c:0x15d43d70, m:{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"}}}}) [ADUC_D2C_Message_SendAsync:526]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9612Z 522[522] [E] stat path '/var/lib/adu/downloads/db9955b3-05fa-4078-87fc-3ea736e04166/rootkeypackage-1.json' failed: 2 [SystemUtils_IsFile:734]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9612Z 522[522] [D] Attempting download of 'http://HIDDEN_URL.b.nlu.dl.adu.microsoft.com/WestEurope/rootkeypackages/rootkeypackage-1.json' using 'DO' [ADUC_RootKeyPackageUtils_DownloadPackage:109]
Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9612Z 522[522] [I] Downloading File 'http://HIDDEN_URL.b.nlu.dl.adu.microsoft.com/WestEurope/rootkeypackages/rootkeypackage-1.json' to '/var/lib/adu/downloads/db9955b3-05fa-4078-87fc-3ea736e04166/rootkeypackage-1.json' [DownloadRootKeyPkg_DO:22]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9928Z 522[522] [I] Download rc: 1, erc: 0x00000000 [DownloadRootKeyPkg_DO:51]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9956Z 522[522] [D] No root key change. [RootKeyWorkflow_UpdateRootKeys:172]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9983Z 522[522] [D] set prop '_workFolder' to '/var/lib/adu/downloads/db9955b3-05fa-4078-87fc-3ea736e04166' [workflow_set_string_property:1683]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9983Z 522[522] [D] cancellationType(0) => None [ADUC_Workflow_HandleUpdateAction:628]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9984Z 522[522] [D] Ignoring duplicate deployment db9955b3-05fa-4078-87fc-3ea736e04166, action 3 [ADUC_Workflow_HandleUpdateAction:675]
Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9984Z 522[522] [D] PropertyUpdated event handler completed. [ADUC_Workflow_HandlePropertyUpdate:599]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9984Z 522[522] [D] Queueing message (t:1, c:0x15d797f0, m:{"deviceUpdate":{"__t":"c","service":{"value":{"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"ITAB\",\"name\":\"CES-OS\",\"version\":\"0.1.6\"},\"compatibility\":[{\"manufacturer\":\"itab\",\"model\":\"ces-hw-v1\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"f1676c2ffd396b8a9\",\"f5d7e494a7d0b49b2\"],\"handlerProperties\":{\"scriptFileName\":\"update-executor.sh\",\"arguments\":\"\",\"installedCriteria\":\"v0.1.6\",\"swuFileName\":\"ces-image-itab-imx8mp_0.1.6.swu\"}}]},\"files\":{\"f1676c2ffd396b8a9\":{\"fileName\":\"update-executor.sh\",\"sizeInBytes\":4978,\"hashes\":{\"sha256\":\"eGa7qnyrbL5HPQFvSMR+bOvt3T\/LSMa91AsvUZsZ4Ys=\"}},\"f5d7e494a7d0b49b2\":{\"fileName\":\"ces-image-itab-imx8mp_0.1.6.swu\",\"sizeInBytes\":215587840,\"hashes\":{\"sha256\":\"Q8OGI7PlpGMw3K4MBYwnlPV34JevTi1cXXTXwZWLRmQ=\"}}},\"createdDateTime\":\"2024-05-29T06:00:05.3448763Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/HIDDEN_URL.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"},"ac":200,"ad":"","av":12}}}) [ADUC_D2C_Message_SendAsync:526]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9987Z 522[522] [I] OrchestratorPropertyUpdateCallback ended [OrchestratorUpdateCallback:517]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9988Z 522[522] [D] Sending D2C message (t:0, retries:0). [ProcessMessage:390]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9988Z 522[522] [D] Sending D2C message:
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"}}}} [ADUC_D2C_Default_Message_Transport_Function:580]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9988Z 522[522] [D] Sending D2C message (t:1, retries:0). [ProcessMessage:390]
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9989Z 522[522] [D] Sending D2C message:
Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: {"deviceUpdate":{"__t":"c","service":{"value":{"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"},"updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"ITAB\",\"name\":\"CES-OS\",\"version\":\"0.1.6\"},\"compatibility\":[{\"manufacturer\":\"itab\",\"model\":\"ces-hw-v1\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/swupdate:2\",\"files\":[\"f1676c2ffd396b8a9\",\"f5d7e494a7d0b49b2\"],\"handlerProperties\":{\"scriptFileName\":\"update-executor.sh\",\"arguments\":\"\",\"installedCriteria\":\"v0.1.6\",\"swuFileName\":\"ces-image-itab-imx8mp_0.1.6.swu\"}}]},\"files\":{\"f1676c2ffd396b8a9\":{\"fileName\":\"update-executor.sh\",\"sizeInBytes\":4978,\"hashes\":{\"sha256\":\"eGa7qnyrbL5HPQFvSMR+bOvt3T\/LSMa91AsvUZsZ4Ys=\"}},\"f5d7e494a7d0b49b2\":{\"fileName\":\"ces-image-itab-imx8mp_0.1.6.swu\",\"sizeInBytes\":215587840,\"hashes\":{\"sha256\":\"Q8OGI7PlpGMw3K4MBYwnlPV34JevTi1cXXTXwZWLRmQ=\"}}},\"createdDateTime\":\"2024-05-29T06:00:05.3448763Z\"}","updateManifestSignature":null,"fileUrls":null,"rootKeyPackageUrl":"http:\/\/HIDDEN_URL.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json"},"ac":200,"ad":"","av":12}}} [ADUC_D2C_Default_Message_Transport_Function:580]

The connection to the IoTHub is broken due to (I guess) an invalid token. The update agent will the reconnect to the IoTHub, and this is when it finds a "new" update.

In the log you find this line:

Aug 14 06:03:27 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:27.9606Z 522[522] [D] Processing deployment db9955b3-05fa-4078-87fc-3ea736e04166 ... [OrchestratorUpdateCallback:446]

This means we are in the function OrchestratorUpdateCallback at line 446. In line 449 the method ReportPreDeploymentProcessingState() is called with the argument ADUCITF_State_DeploymentInProgress in it. This means that the "overall" state will be changed to "In Progress" and reported to the cloud.

The log contains this line:

Aug 14 06:03:33 itab-imx8mp AducIotAgent[522]: {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"db9955b3-05fa-4078-87fc-3ea736e04166"}}}} [ADUC_D2C_Default_Message_Transport_Function:580]

This JSON-blob contains "state": 6 which is the state for "InProgress" and this data is sent to the could.

In the log you can also find this line:

Aug 14 06:03:32 itab-imx8mp AducIotAgent[522]: 2024-08-14T06:03:32.9984Z 522[522] [D] Ignoring duplicate deployment db9955b3-05fa-4078-87fc-3ea736e04166, action 3 [ADUC_Workflow_HandleUpdateAction:675]

ADUC_Workflow_HandleUpdateAction is called from OrchestratorUpdateCallback (line: 477) -> ADUC_Workflow_HandleUpdateAction which then calls ADUC_Workflow_HandleUpdateAction.

In ADUC_Workflow_HandleUpdateAction at line 671 there is an if-case checking just for this specific situation. The comment in the if-case is:

    // Ignore duplicate deployment that can be caused by token expiry connection refresh after about 40 minutes.
    if (workflow_isequal_id(workflowData->WorkflowHandle, workflowData->LastCompletedWorkflowId)
        && !workflow_get_force_update(workflowData->WorkflowHandle))
    {
        Log_Debug("Ignoring duplicate deployment %s, action %d", workflowData->LastCompletedWorkflowId, desiredAction);
        goto done;
    }

So by looking at the log we can determine that the overall state is changed it "InProgress" in OrchestratorUpdateCallback. OrchestratorUpdateCallback it self the calls ADUC_Workflow_HandleUpdateAction, through ADUC_Workflow_HandleUpdateAction, which realize it shall do nothing with this. But OrchestratorUpdateCallback has already updated the state.

@ortogonal
Copy link

Just some extra info about the above comment. All the referrals to line numbers in the comment is based on the code in commit fd69e827422f7fd8be06e04617c6cf8176bb104a

@ortogonal
Copy link

There is a pull-req (#609) that might solve the issue. Can someone please look at it.

@eshashah-msft eshashah-msft removed the no new activity No activity by author for 14 days label Aug 30, 2024
@AndreRicardo-Zoetis
Copy link
Contributor

We are seeing a similar issue.

The twin reports

                   "lastInstallResult": {
                        "extendedResultCodes": "00000000",
                        "resultCode": 1
                    },

Azure portal reports "In Progress"

image

But on the same twin

    "configurations": {
        "adu-381b7431-f2d1-45f0-861c-35f060efec48-13176c5bda16dce39043c3c585d14f471ee0d645": {
            "status": "Applied"
        },
        "adu-nodeployment": {
            "status": "Applied"
        }
    },

The device is running the latest version, the OTA has been done.

We are running a modified version of the ADU based on release 1.1.0.

"deviceUpdate": {
                "__t": "c",
                "agent": {
                    "compatPropertyNames": "manufacturer,model",
                    "deviceProperties": {
                        "aduVer": "DU;agent/1.1.0",
                        "contractModelId": "dtmi:azure:iot:deviceUpdateContractModel;3",
                        "manufacturer": "Zoetis",
                        "model": "Hub"
                    },
                    "installedUpdateId": "{\"provider\":\"Zoetis\",\"name\":\"Hub\",\"version\":\"2024.5.13\"}",
                    "lastInstallResult": {
                        "extendedResultCodes": "00000000",
                        "resultCode": 1
                    },
                    "state": 6,
                    "workflow": {
                        "action": 3,
                        "id": "381b7431-f2d1-45f0-861c-35f060efec48"
                    }
                }

@mahdighorbanpourptw
Copy link
Author

@josephmsft , @jw-msft , @eshashah-msft
Do you have any updates on this bug report? Could you possibly accept the PR from @ortogonal?
Thank you

@jw-msft
Copy link
Contributor

jw-msft commented Oct 22, 2024

@mahdighorbanpourptw and @ortogonal, could you test out PR #659 to see if it resolves your issue? This is the proper fix of root issue that was introduced with the rootkey work (which sets it to in-progress before update processing actually starts)--#659 sets in-progress state only once processing of the update metadata begins such that updates that have been either been installed before do not lead to reporting of in-progress unless IsInstalled says it is not installed.

The PR #610 does get it to set the state to a terminal state by reporting it every 35-40 minute token expiry, but that is fixing a symptom and not fixing the root issue. It has a negative side-effect of consuming large amounts of message quota to compensate for in-progress state being set too early (consumes one message every ~35-40 minutes when token expires).

Therefore, I recommend closing PR #610 in favor of PR #659. We are working to address the blocking PR comment and merging it to develop branch soon but predicated on relative prioritization with other tasks.

@ortogonal
Copy link

@jw-msft I've tested PR #659 but get into trouble. I get this log message

Invalid desired update action data. Update data: .......

When looking into the PR in commit 50b6ef3 there is a change that checks the return code of rootkeyErc. I guess that is failing for me.

Without this patch I can run the update, but still with the original issue. But the PR makes it impossible to update :(

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

7 participants