Azure / iot-hub-device-update

Device Update for IoT Hub agent
MIT License
51 stars 36 forks source link

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

Open mahdighorbanpourptw opened 1 month ago

mahdighorbanpourptw commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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

agreentree-dmc commented 1 month ago

@mahdighorbanpourptw were you able to resolve this issue?

mahdighorbanpourptw commented 1 month ago

@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 commented 1 month ago

@mahdighorbanpourptw Thanks!

jw-msft commented 4 weeks ago

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

josephmsft commented 4 weeks ago

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.