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.

Sign up for GitHub

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

Jump to bottom

do-client download fails #32

Closed
Voxel07 opened this issue Apr 23, 2021 · 9 comments
Closed

do-client download fails #32

Voxel07 opened this issue Apr 23, 2021 · 9 comments

Comments

@Voxel07
Copy link

Voxel07 commented Apr 23, 2021

When an update is deployed, the download starts and then fails with an exception.
When looking into the do log files at /var/cache/deliveryoptimization-agent/log the first line states:

2021-04-22T13:23:18.4603502Z 821   821   info     {Run} Started, DU;deliveryoptimization-agent/v0.4.0+20210422.071111.b40eeac (HEAD)
2021-04-23T10:19:26.8281728Z 821   903   trace    {_TryRefresh} json file not found at /etc/deliveryoptimization-agent/admin-config.json

What should this file contain ? The sdk-config.json is present and just contains the connection string.

Complete log:
matthias@matthias-VirtualBox:~/Desktop/azure/iot-hub-device-update$ sudo AducIotAgent --log-level 0

2021-04-21T14:20:23.0557Z [I] Agent (linux; 0.6.0-public-preview) starting. [main]

2021-04-21T14:20:23.0557Z [I] Git Info: main:55abcef [main]

2021-04-21T14:20:23.0557Z [I] Agent built with handlers: microsoft/swupdate. [main]

2021-04-21T14:20:23.0559Z [I] Initalizing PnP components. [ADUC_PnP_Components_Create]

2021-04-21T14:20:23.0560Z [I] ADUC agent started. Using IoT Hub Client SDK 1.6.0 [AzureDeviceUpdateCoreInterface_Create]

2021-04-21T14:20:23.0560Z [I] Calling ADUC_Register [ADUC_MethodCall_Register]

2021-04-21T14:20:23.0561Z [I] IoTHub Device Twin callback registered. [ADUC_DeviceClient_Create]

2021-04-21T14:20:23.0564Z [I] Agent running. [main]

2021-04-21T14:20:23.4168Z [D] IotHub connection status: 0, reason:6 [ADUC_ConnectionStatus_Callback]

2021-04-21T14:20:23.8656Z [D] ComponentName:azureDeviceUpdateAgent, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback]

2021-04-21T14:20:23.8657Z [D] OrchestratorUpdateCallback received property JSON string ({"action":255,"updateManifest":"","updateManifestSignature":""}), property version (7) [OrchestratorUpdateCallback]

2021-04-21T14:20:23.8662Z [I] Performing startup tasks. [ADUC_Workflow_HandleStartupWorkflowData]

2021-04-21T14:20:23.8663Z [I] Calling IsInstalledCallback to check if content is installed. [ADUC_MethodCall_IsInstalled]

2021-04-21T14:20:23.8664Z [I] IsInstalledCallback called [IsInstalledCallback]

2021-04-21T14:20:23.8664Z [I] IsInstalled called workflowId: , installed criteria: (null) [IsInstalled]

2021-04-21T14:20:23.8667Z [E] Failed to create content handler, updateType:(null) [IsInstalled]

2021-04-21T14:20:23.8668Z [W] IsInstalled call failed. ExtendedResultCode: -536870781 - setting state to Idle [ADUC_Workflow_HandleStartupWorkflowData]

2021-04-21T14:20:23.8668Z [I] Setting UpdateState to Idle [ADUC_SetUpdateStateHelper]

2021-04-21T14:20:23.8669Z [I] Reporting state: 0, Idle (0); HTTP 200; result 1, 0 [AzureDeviceUpdateCoreInterface_ReportStateAndResultAsync]

2021-04-21T14:20:23.8670Z [I] UpdateAction: Idle. WorkflowId: 210421142023 [ADUC_MethodCall_Idle]

2021-04-21T14:20:23.8670Z [I] Calling IdleCallback [ADUC_MethodCall_Idle]

2021-04-21T14:20:23.8670Z [I] Now idle. workflowId: 210421142023 [Idle]

2021-04-21T14:20:23.8674Z [I] Processing existing Device Twin data after agent started. [ADUC_PnPDeviceTwin_Callback]

2021-04-21T14:20:23.8674Z [D] Notifies components that all callback are subscribed. [ADUC_PnPDeviceTwin_Callback]

2021-04-21T14:20:23.8674Z [I] DeviceInformation component is ready - reporting properties [DeviceInfoInterface_Connected]

2021-04-21T14:20:23.8676Z [I] Property manufacturer changed to FuS [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8677Z [I] Property model changed to imx8mm [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8677Z [I] Property osName changed to Linux [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8679Z [I] Property swVersion changed to 5.4.0-72-generic [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8679Z [I] Property processorArchitecture changed to x86-64 [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8912Z [I] Property processorManufacturer changed to GenuineIntel [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8914Z [I] Property totalMemory changed to 4030200 [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:23.8915Z [I] Property totalStorage changed to 20509264 [RefreshDeviceInfoInterfaceData]

2021-04-21T14:20:38.3766Z [D] ComponentName:azureDeviceUpdateAgent, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback]

2021-04-21T14:20:38.3772Z [D] OrchestratorUpdateCallback received property JSON string ({"action":0,"updateManifest":"{"manifestVersion":"2.0","updateId":{"provider":"Schneider","name":"newDeviceModel","version":"2.0.0"},"updateType":"microsoft/swupdate:1","installedCriteria":"test","files":{"00000":{"fileName":"workingUpdate","sizeInBytes":144549945,"hashes":{"sha256":"eNUL10t04ThmJ0l49987SZLuFvFzhYkIq/pxoQXgtdI="}}},"createdDateTime":"2021-04-19T10:11:10.4149069Z"}","updateManifestSignature":"eyJhbGciOiJSUzI1NiIsInNqd2siOiJleUpoYkdjaU9pSlNVekkxTmlJc0ltdHBaQ0k2SWtGRVZTNHlNREEzTURJdVVpSjkuZXlKcmRIa2lPaUpTVTBFaUxDSnVJam9pY2toV1FrVkdTMUl4ZG5Ob1p5dEJhRWxuTDFORVVVOHplRFJyYWpORFZWUTNaa2R1U21oQmJYVkVhSFpJWm1velowaDZhVEJVTWtsQmNVTXhlREpDUTFka1QyODFkamgwZFcxeFVtb3ZibGx3WnprM2FtcFFRMHQxWTJSUE5tMHpOMlJqVDIxaE5EWm9OMDh3YTBod2Qwd3pibFZJUjBWeVNqVkVRUzloY0ZsdWQwVmxjMlY0VkdwVU9GTndMeXRpVkhGWFJXMTZaMFF6TjNCbVpFdGhjV3AwU0V4SFZtbFpkMVpJVUhwMFFtRmlkM2RxYUVGMmVubFNXUzk1T1U5bWJYcEVabGh0Y2xreGNtOHZLekpvUlhGRmVXdDFhbmRSUlZscmFHcEtZU3RDTkRjMkt6QnRkVWQ1VjBrMVpVbDJMMjlzZERKU1pWaDRUV0k1VFd4c1dFNTViMUF6WVU1TFNVcHBZbHBOY3pkMVMyTnBkMnQ1YVZWSllWbGpUV3B6T1drdlVrVjVLMnhOT1haSlduRnlabkJEVlZoMU0zUnVNVXRuWXpKUmN5OVVaRGgwVGxSRFIxWTJkM1JXWVhGcFNYQlVaRlEwVW5KRFpFMXZUelZUVG1WbVprUjVZekpzUXpkMU9EVXJiMjFVYTJOcVVHcHRObVpoY0dSSmVVWXljV1Z0ZGxOQ1JHWkNOMk5oYWpWRVNVa3lOVmQzTlVWS1kyRjJabmxRTlRSdGNVNVJVVE5IWTAxUllqSmtaMmhwWTJ4d2FsbHZLelF6V21kWlEyUkhkR0ZhWkRKRlpreGFkMGd6VVdjeWNrUnNabXN2YVdFd0x6RjVjV2xyTDFoYU1XNXpXbFJwTUVKak5VTndUMDFGY1daT1NrWlJhek5DVjI5Qk1EVnlRMW9pTENKbElqb2lRVkZCUWlJc0ltRnNaeUk2SWxKVE1qVTJJaXdpYTJsa0lqb2lRVVJWTGpJd01EY3dNaTVTTGxNaWZRLmlTVGdBRUJYc2Q3QUFOa1FNa2FHLUZBVjZRT0dVRXV4dUhnMllmU3VXaHRZWHFicE0takk1UlZMS2VzU0xDZWhLLWxSQzl4Ni1fTGV5eE5oMURPRmMtRmE2b0NFR3dVajh6aU9GX0FUNnM2RU9tY2txUHJ4dXZDV3R5WWtrRFJGNzRkdGFLMWpOQTdTZFhyWnp2V0NzTXFPVU1OejBnQ29WUjBDczEyNTRrRk1SbVJQVmZFY2pnVDdqNGxDcHlEdVdncjlTZW5TZXFnS0xZeGphYUcwc1JoOWNkaTJkS3J3Z2FOYXFBYkhtQ3JyaHhTUENUQnpXTUV4WnJMWXp1ZEVvZnlZSGlWVlJoU0pwajBPUTE4ZWN1NERQWFYxVGN0MXkzazdMTGlvN244aXpLdXEybTNUeEY5dlBkcWI5TlA2U2M5LW15YXB0cGJGcEhlRmtVTC1GNXl0bF9VQkZLcHdOOUNMNHdwNnlaLWpkWE5hZ3JtVV9xTDFDeVh3MW9tTkNnVG1KRjNHZDNseXFLSEhEZXJEcy1NUnBtS2p3U3dwWkNRSkdEUmNSb3ZXeUwxMnZqdzNMQkpNaG1VeHNFZEJhWlA1d0dkc2ZEOGxkS1lGVkZFY1owb3JNTnJVa1NNQWw2cEl4dGVmRVhpeTVscW1pUHpxX0xKMWVSSXJxWTBfIn0.eyJzaGEyNTYiOiJHVUtvUElvWXlScGxqTC9wR2lDS2RBUmw3cWFPZ1JqMm1qbDk5SXFhZXc0PSJ9.aYxRm-eXMYXUJfd0E-QgjWkyhwh75izHnhbNz7YznFhLc46AI00YjGSZy8McjzHhpnlg4-sHN-PMqdSvU9Kl2TT9jRFSFm2Ot5YiGLwkEj5p1ehrQvgGLb9TnzQkM751iSU_RxQbV0Qpx7oFeSvbAuqfXsjmEO7OnbPrZ4eXcphSoJJoyjxo04tTjEzr7Xs4UYSCeytV6NEzMcme1iKDGgqcWImxfh6wvuqdNQE3cUTqg_rpTFQsZ9pKQ6Lu4XpJmvZvPg9gvRdlwdEhhaoesCSByS5NSPIY-59lNU0sOYn1ZLxZDLChbmAhDh6OIc1Rnliu1uhEP4m3a3u1C2bIJJ-i3wzoR3bz8QAYXY4xrnov2knBryDG7Vy-zKK4WaGC9L9rQvo6dwD2ghqbsGRXr43XcZP3pWV53_fMuXRnupCZO0_8k2P9M_v7TqvVFAyUTWjMeZFs6j2Pvy9lq6qLyRp7EacYSYWwqwl-wxnYUJfpvaMHTWr13uDJH8d0y0FS","fileUrls":{"00000":"http://fsupdateinstanz--fsdeviceupdatetest.b.nlu.dl [OrchestratorUpdateCallback]

2021-04-21T14:20:38.3814Z [I] Processing 'Download' action [ADUC_Workflow_HandleUpdateAction]

2021-04-21T14:20:38.3815Z [I] UpdateAction: Prepare - calling PrepareCallback [ADUC_MethodCall_Prepare]

2021-04-21T14:20:38.3816Z [I] {210421142023} Received Metadata, UpdateType: microsoft/swupdate:1, UpdateTypeName: microsoft/swupdate, UpdateTypeVersion: 1, FileCount: 1 [Prepare]

2021-04-21T14:20:38.3817Z [I] microsoft_swupdate_CreateFunc called. [microsoft_swupdate_CreateFunc]

2021-04-21T14:20:38.3818Z [I] Prepare succeeded. [Prepare]

2021-04-21T14:20:38.3818Z [I] UpdateAction: Download [ADUC_MethodCall_Download]

2021-04-21T14:20:38.3819Z [I] Calling SandboxCreateCallback [ADUC_MethodCall_Download]

2021-04-21T14:20:38.3821Z [I] Setting sandbox /tmp/aduc-dl-210421142023 [SandboxCreate]

2021-04-21T14:20:38.3822Z [I] Using sandbox /tmp/aduc-dl-210421142023 [ADUC_MethodCall_Download]

2021-04-21T14:20:38.3822Z [I] Setting UpdateState to DownloadStarted [ADUC_SetUpdateStateHelper]

2021-04-21T14:20:38.3824Z [I] Calling DownloadCallback [ADUC_MethodCall_Download]

2021-04-21T14:20:38.3828Z [D] Downloading 1 files to /tmp/aduc-dl-210421142023 [Download]

2021-04-21T14:20:38.3829Z [I] Downloading File 'workingUpdate' from 'http://fsupdateinstanz--fsdeviceupdatetest.b.nlu.dl.adu.microsoft.com/northeurope/FsUpdateInstanz--fsdeviceupdatetest/3444d4177cd04eec99450741d6c37d9f/workingUpdate' to '/tmp/aduc-dl-210421142023/workingUpdate' [Download]

2021-04-21T14:20:38.6892Z [I] Caught DO exception, msg: unrecognized error, code: -2147024809 [Download]

2021-04-21T14:20:38.6893Z [I] ProgressCallback: workflowId: 210421142023; Id 00000; State: Error; Bytes: 0/0 [DownloadProgressCallback]

2021-04-21T14:20:38.6893Z [I] Download resultCode: 0, extendedCode: -804847529 [Download]

2021-04-21T14:20:38.6894Z [I] Action 'Download' complete. Result: 0, -804847529 [ADUC_Workflow_WorkCompletionCallback]

2021-04-21T14:20:38.6895Z [E] Download failed. error 0, -804847529 - Expecting service to send Cancel action [ADUC_Workflow_WorkCompletionCallback]

2021-04-21T14:20:38.6896Z [I] Setting UpdateState to Failed [ADUC_SetUpdateStateHelper]

2021-04-21T14:20:38.6896Z [I] Reporting state: 255, Failed (255); HTTP 500; result 0, -804847529 [AzureDeviceUpdateCoreInterface_ReportStateAndResultAsync]

2021-04-21T14:20:40.9971Z [D] ComponentName:azureDeviceUpdateAgent, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback]

2021-04-21T14:20:40.9977Z [D] OrchestratorUpdateCallback received property JSON string ({"action":255,"updateManifest":"","updateManifestSignature":"","fileUrls":null}), property version (9) [OrchestratorUpdateCallback]

2021-04-21T14:20:40.9988Z [I] Cancel received with no operation in progress - returning to Idle state [ADUC_Workflow_HandleUpdateAction]

2021-04-21T14:20:40.9989Z [I] Setting UpdateState to Idle [ADUC_SetUpdateStateHelper]

2021-04-21T14:20:40.9990Z [I] Reporting state: 0, Idle (0); HTTP 200; result 1, 0 [AzureDeviceUpdateCoreInterface_ReportStateAndResultAsync]

2021-04-21T14:20:40.9991Z [I] Calling SandboxDestroyCallback [ADUC_MethodCall_Idle]

2021-04-21T14:20:40.9994Z [I] Destroying sandbox /tmp/aduc-dl-210421142023. workflowId: 210421142023 [SandboxDestroy]

2021-04-21T14:20:40.9999Z [I] UpdateAction: Idle. WorkflowId: 210421142040 [ADUC_MethodCall_Idle]

2021-04-21T14:20:41.0000Z [I] Calling IdleCallback [ADUC_MethodCall_Idle]

2021-04-21T14:20:41.0000Z [I] Now idle. workflowId: 210421142040 [Idle]

^C2021-04-21T14:26:05.8100Z [I] Agent exited with code 0 [main]

2021-04-21T14:26:05.8100Z [I] Agent is shutting down with signal 2. [ShutdownAgent]

2021-04-21T14:26:05.8100Z [I] ADUC agent stopping [AzureDeviceUpdateCoreInterface_Destroy]

2021-04-21T14:26:05.8101Z [I] Calling ADUC_Unregister [ADUC_MethodCall_Unregister]

Error: Time:Wed Apr 21 16:26:05 2021 File:/tmp/azure-iot-sdk-c/c-utility/adapters/tlsio_openssl.c Func:openssl_static_locks_uninstall Line:585 Locks already uninstalled
@jimson-msft
Copy link
Contributor

jimson-msft commented Apr 23, 2021 •
edited
Loading

@Voxel07 Thanks for the feedback, mind sharing the full do agent logs - or are those two lines of text the only ones appearing? The json file not being present is not a fatal error, the logging should just reflect that the file isn't there - but this shouldn't block your download. Having more logging would help.

From the adu-agent logging, that specific error code bubbling from DO is maps to E_INVALIDARG, this usually signals something wrong with the filepath or the download url. The url looks okay, so I suspect perhaps DO may not have permissions to download to that directory.

Is the DU agent running as DU user? Is DO running as DO user?
You can also try verify the file permissions of the download sandbox in /tmp/ - or feel free to share them here.
You can verify file permissions by trying to catch the sandbox when it's created and before adu agent removes it and running
'ls -l' in the /tmp/ directory.

@Voxel07
Copy link
Author

Voxel07 commented Apr 24, 2021 •
edited
Loading

I will post the whole log on Monday, but I think the rights might be the issue, because when I check with ls -l everything was root.

@jimson-msft The whole log:
please note that the IoT Hub Url changed because I had to change subscriptions.

2021-04-23T11:45:16.9965108Z 787 787 info {Run} Started, DU;deliveryoptimization-agent/v0.4.0+20210422.071111.b40eeac (HEAD)
2021-04-23T12:19:22.5082106Z 787 832 trace {_TryRefresh} json file not found at /etc/deliveryoptimization-agent/admin-config.json
2021-04-23T12:19:22.5118934Z 787 832 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:19:22.5191264Z 787 832 info {Download} 7f64b890-9001-934b-a3b6-c60df8e5770f, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate
2021-04-23T12:19:22.5191870Z 787 832 info {GetProperty} 7f64b890-9001-934b-a3b6-c60df8e5770f, key: 0
2021-04-23T12:19:22.5437531Z 787 851 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:19:22.5441508Z 787 851 info {ParseAndProcess} Download state change: 2
2021-04-23T12:19:22.5445764Z 787 827 trace {_PerformStateChange} 7f64b890-9001-934b-a3b6-c60df8e5770f, state change request 0 --> 1
2021-04-23T12:19:22.5446218Z 787 827 error {_Start} (hr:80D02200) _url.empty() [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253]
2021-04-23T12:19:22.5449496Z 787 827 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253], {_url.empty()} [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-23T12:19:22.5451611Z 787 851 error {SchedBlock} (hr:80D02200) hr [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-23T12:19:22.5453154Z 787 851 error {Process} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-23T12:19:22.5453584Z 787 851 error {operator()} (hr:80D02200) apiRequest->Process(_downloadManager, response) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-23T12:19:22.5463558Z 787 836 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(_downloadManager, response)} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]
2021-04-23T12:41:34.9512811Z 787 833 trace {_TryRefresh} json file not found at /etc/deliveryoptimization-agent/admin-config.json
2021-04-23T12:41:34.9513962Z 787 833 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:41:34.9545875Z 787 833 info {Download} 6327dc2b-390c-194e-aeaf-a6c720db6d2c, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate
2021-04-23T12:41:34.9546134Z 787 833 info {GetProperty} 6327dc2b-390c-194e-aeaf-a6c720db6d2c, key: 0
2021-04-23T12:41:34.9591989Z 787 848 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:41:34.9593639Z 787 848 info {ParseAndProcess} Download state change: 2
2021-04-23T12:41:34.9594768Z 787 827 trace {_PerformStateChange} 6327dc2b-390c-194e-aeaf-a6c720db6d2c, state change request 0 --> 1
2021-04-23T12:41:34.9595026Z 787 827 error {_Start} (hr:80D02200) _url.empty() [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253]
2021-04-23T12:41:34.9595832Z 787 827 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253], {_url.empty()} [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-23T12:41:34.9596547Z 787 848 error {SchedBlock} (hr:80D02200) hr [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-23T12:41:34.9597208Z 787 848 error {Process} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-23T12:41:34.9597400Z 787 848 error {operator()} (hr:80D02200) apiRequest->Process(_downloadManager, response) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-23T12:41:34.9599425Z 787 848 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(_downloadManager, response)} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]
2021-04-23T12:53:45.7713884Z 787 842 trace {_TryRefresh} json file not found at /etc/deliveryoptimization-agent/admin-config.json
2021-04-23T12:53:45.7715810Z 787 842 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:53:45.7783299Z 787 842 info {Download} e6747178-4481-4547-a0b0-fe33bbf4f47c, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate
2021-04-23T12:53:45.7783816Z 787 842 info {GetProperty} e6747178-4481-4547-a0b0-fe33bbf4f47c, key: 0
2021-04-23T12:53:45.7862285Z 787 831 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T12:53:45.7864594Z 787 831 info {ParseAndProcess} Download state change: 2
2021-04-23T12:53:45.7867600Z 787 827 trace {_PerformStateChange} e6747178-4481-4547-a0b0-fe33bbf4f47c, state change request 0 --> 1
2021-04-23T12:53:45.7868038Z 787 827 error {_Start} (hr:80D02200) _url.empty() [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253]
2021-04-23T12:53:45.7869412Z 787 827 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253], {_url.empty()} [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-23T12:53:45.7871218Z 787 831 error {SchedBlock} (hr:80D02200) hr [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-23T12:53:45.7873140Z 787 831 error {Process} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-23T12:53:45.7874154Z 787 831 error {operator()} (hr:80D02200) apiRequest->Process(_downloadManager, response) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-23T12:53:45.7877560Z 787 831 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(_downloadManager, response)} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]
2021-04-23T13:44:32.5899381Z 787 868 warning {_TryRefresh} Could not read json config file /etc/deliveryoptimization-agent/admin-config.json: /etc/deliveryoptimization-agent/admin-config.json(1): expected value
2021-04-23T13:44:32.5901189Z 787 868 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T13:44:32.5969194Z 787 868 info {Download} de5d13bf-8cca-9d49-be24-10424938a42b, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate
2021-04-23T13:44:32.5969709Z 787 868 info {GetProperty} de5d13bf-8cca-9d49-be24-10424938a42b, key: 0
2021-04-23T13:44:32.6041828Z 787 855 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T13:44:32.6044055Z 787 855 info {ParseAndProcess} Download state change: 2
2021-04-23T13:44:32.6046578Z 787 827 trace {_PerformStateChange} de5d13bf-8cca-9d49-be24-10424938a42b, state change request 0 --> 1
2021-04-23T13:44:32.6047014Z 787 827 error {_Start} (hr:80D02200) _url.empty() [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253]
2021-04-23T13:44:32.6048411Z 787 827 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253], {_url.empty()} [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-23T13:44:32.6050487Z 787 855 error {SchedBlock} (hr:80D02200) hr [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-23T13:44:32.6052023Z 787 855 error {Process} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-23T13:44:32.6052454Z 787 855 error {operator()} (hr:80D02200) apiRequest->Process(_downloadManager, response) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-23T13:44:32.6055622Z 787 855 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(_downloadManager, response)} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]
2021-04-23T13:45:27.7584805Z 787 843 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T13:45:27.7653800Z 787 843 info {Download} 73e1d3c7-0c61-5e42-b9ef-5ccbe2159b5b, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate
2021-04-23T13:45:27.7654332Z 787 843 info {GetProperty} 73e1d3c7-0c61-5e42-b9ef-5ccbe2159b5b, key: 0
2021-04-23T13:45:27.7729583Z 787 867 error {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-23T13:45:27.7733298Z 787 867 info {ParseAndProcess} Download state change: 2
2021-04-23T13:45:27.7735801Z 787 827 trace {_PerformStateChange} 73e1d3c7-0c61-5e42-b9ef-5ccbe2159b5b, state change request 0 --> 1
2021-04-23T13:45:27.7736240Z 787 827 error {_Start} (hr:80D02200) _url.empty() [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253]
2021-04-23T13:45:27.7738192Z 787 827 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/download/download.cpp, 253], {_url.empty()} [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-23T13:45:27.7739967Z 787 867 error {SchedBlock} (hr:80D02200) hr [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-23T13:45:27.7741475Z 787 867 error {Process} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-23T13:45:27.7741905Z 787 867 error {operator()} (hr:80D02200) apiRequest->Process(_downloadManager, response) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-23T13:45:27.7745036Z 787 867 error {operator()} (hr:80D02200) DO failure: (null) (hr:0x80D02200) [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(_downloadManager, response)} [/home/matthias/Desktop/azure/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]

@Voxel07 Voxel07 mentioned this issue Apr 26, 2021
Closed
@jimson-msft
Copy link
Contributor

jimson-msft commented Apr 26, 2021 •
edited
Loading

@Voxel07, how strange - it looks like the caller of the download_url_to_path() api is supplying an empty url, and it looks like the download path is getting supplied with respective download url.

Taking a look at logging line here:

2021-04-23T13:44:32.5969194Z 787 868 info {Download} de5d13bf-8cca-9d49-be24-10424938a42b, new download, url: , dest: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate

Notice the empty url, and the presumed download url getting supplied as the download file destination.

Did you happen to modify the source for either client?
@Nox-MSFT as an FYI

@Voxel07
Copy link
Author

Voxel07 commented Apr 27, 2021 •
edited
Loading

@jimson-msft, I compared the files with meld and could not find a relevant change. So reverted all changes and no that made no difference. To be a 100% sure I downloaded the newest releases from git (changed from 0.6.0 to 0.7.0) and ran the whole setup again. And the log changed. Now the url and dest contain the correct paths. Out of Curiosity I installed the agent with my changes and the the missing url error is gone as well. I think I had changes in the background which were overwritten by the install-deps script.

Unfortunately the E _INVALIDARG Error is still present.

Permissions

matthias@matthias-VirtualBox:/tmp$ sudo ls -la aduc-dl-210426095427/
total 8
drwxrwx--- 2 adu adu 4096 Apr 26 11:54 .
drwxrwxrwt 17 root root 4096 Apr 26 11:55 ..

matthias@matthias-VirtualBox:/tmp$ sudo -H -u adu bash -c 'mkdir aduc-dl-210426124154/test'
matthias@matthias-VirtualBox:/tmp$ sudo -H -u do bash -c 'mkdir aduc-dl-210426124154/test2'
matthias@matthias-VirtualBox:/tmp$ sudo ls -la aduc-dl-210426124154
total 16
drwxrwx--- 4 adu adu 4096 Apr 26 16:06 .
drwxrwxrwt 20 root root 4096 Apr 26 16:04 ..
drwxr-xr-x 2 adu adu 4096 Apr 26 16:06 test
drwxr-xr-x 2 do do 4096 Apr 26 16:06 test2

NewLog


2021-04-27T08:47:46.5425962Z 815   869   trace    {_TryRefresh} json file not found at /etc/deliveryoptimization-agent/admin-config.json
2021-04-27T08:47:46.5434820Z 815   869   error    {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-27T08:47:46.5503700Z 815   869   info     {Download} 1f2f1c9d-d007-664d-a539-82dd13d285ab, new download, url: http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate, dest: /tmp/aduc-dl-210427084718/workingUpdate
2021-04-27T08:47:46.5507854Z 815   869   info     {GetProperty} 1f2f1c9d-d007-664d-a539-82dd13d285ab, key: 0
2021-04-27T08:47:46.5589853Z 815   870   error    {Get} (hr:8007023E) std::exception: No such node (RestControllerValidateRemoteAddr) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/util/do_json_parser.h, 27]
2021-04-27T08:47:46.5593281Z 815   870   info     {ParseAndProcess} Download state change: 2
2021-04-27T08:47:46.5599869Z 815   864   trace    {_PerformStateChange} 1f2f1c9d-d007-664d-a539-82dd13d285ab, state change request 0 --> 1
2021-04-27T08:47:46.5601573Z 815   864   error    {_Start} (hr:80070057) Error: 1, basic_ios::clear: iostream error, file: /tmp/aduc-dl-210427084718/workingUpdate [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/download/download.cpp, 265]
2021-04-27T08:47:46.5603121Z 815   864   error    {operator()} (hr:80070057) DO failure: Error: 1, basic_ios::clear: iostream error, file: /tmp/aduc-dl-210427084718/workingUpdate (hr:0x80070057) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/download/download.cpp, 265], {E_INVALIDARG} [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/threading/task_thread.cpp, 80]
2021-04-27T08:47:46.5604769Z 815   870   error    {SchedBlock} (hr:80070057) hr [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/threading/task_thread.cpp, 96]
2021-04-27T08:47:46.5606263Z 815   870   error    {Process} (hr:80070057) DO failure: (null) (hr:0x80070057) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/threading/task_thread.cpp, 96], {hr} [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/ipc/rest_api_request.cpp, 83]
2021-04-27T08:47:46.5606696Z 815   870   error    {operator()} (hr:80070057) apiRequest->Process(*_downloadManager, response) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63]
2021-04-27T08:47:46.5609685Z 815   870   error    {operator()} (hr:80070057) DO failure: (null) (hr:0x80070057) [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/ipc/rest_http_controller.cpp, 63], {apiRequest->Process(*_downloadManager, response)} [/home/matthias/Desktop/azure/compare/do-client/client-lite/src/ipc/rest_http_controller.cpp, 76]

@jimson-msft
Copy link
Contributor

Thanks @Voxel07, In this case - the E_INVALIDARG may be the result of the DU and DO user/groups not being set up. The error specifically looks like DO does not have permissions to download to the destination path (the DU sandbox).

DU agent runs as DU user and DO runs as DO user - in our binary distributions (debian packages) - the debian control scripts handle provisioning this. If you're building from source, its possible that the DU and DO user/group is not being setup correctly. I believe I've seen this issue a couple times on the DU github issues as well - so this is great feedback for our teams to make the the provisioning of the user/group more clear.

Consider reviewing our control scripts (they're just shell scripts) to find the relevant code to setup the DO/DU users directly.
The DO control script which handles post-install and setup of the user/group can be run from here:
https://github.com/microsoft/do-client/blob/main/client-lite/build/postinst.in.sh

The DU control script which handles post-install and setup of the user/group can be run from here:
https://github.com/Azure/iot-hub-device-update/blob/main/packages/debian/postinst

@Voxel07
Copy link
Author

Voxel07 commented Apr 27, 2021

@jimson-msft I already looked into the src code to find out how it should be and wrote my own setup script. But I will take another look into this tomorrow.
@ValOlson mentioned how to set it up until the documentation is updated.
I am running the Agent with this command:

matthias@matthias-VirtualBox:~/Desktop/azure/do-client$ sudo -H -u adu bash -c AducIotAgent

And when looking at the process with "top" I can see that DU is running as du and DO as do. The only thing remaining thing is the do agent exe in /usr/local/bin

voxel@ubuntu:/usr/local/bin$ ll
total 14992
drwxr-xr-x  2 root root     4096 Apr 19 10:23 ./
drwxr-xr-x 10 root root     4096 Aug  6  2020 ../
-rwxr-xr-x  1 root root 15341520 Apr 19 10:11 deliveryoptimization-agent*

should this be

voxel@ubuntu:/usr/local/bin$ ll
total 14992
drwxr-xr-x  2 root root 4096 Apr 19 10:23 ./
drwxr-xr-x 10 root root  4096 Aug  6  2020 ../
-rwxr-xr-x  1 root do 15341520 Apr 19 10:11 deliveryoptimization-agent*

@ValOlson
Copy link

Here are the updated instructions on how to create 'adu' user and group that includes the DO agent.

@Voxel07
Copy link
Author

Voxel07 commented Apr 28, 2021 •
edited
Loading

@ValOlson @jimson-msft Thank you very much for helping with this.

  • I deleted the agent in /usr/lib. The install_prefix mentioned in build.sh is also /usr/local.

If my research is correct, then this is the folder for programs installed with a package manager. And when compiling software with cmake,... it should be placed in /user/local/lib. Pls correct me if I am wrong, because the build.sh with the --install option puts it into /usr/lib/adu.

  • Then I changed the permissions of the agent in /local/lib according to the new instructions. To me everything looks the same, but the download is now successful.
2021-04-28T07:42:30.2194Z [I] --!!--Downloading File 'workingUpdate' from 'http://iot-hub-update-instance-schneider--device-update-schneider.b.nlu.dl.adu.microsoft.com/northeurope/IoT-Hub-Update-Instance-Schneider--device-update-schneider/8761c4bc9566483a94ef012d0426f9b2/workingUpdate' to '/tmp/aduc-dl-210428074149/workingUpdate' [Download]
2021-04-28T07:42:48.6492Z [I] Validating file hash [Download]
2021-04-28T07:42:54.5827Z [I] microsoft_swupdate_CreateFunc called. [microsoft_swupdate_CreateFunc]
2021-04-28T07:42:54.5827Z [I] Download called - no-op for swupdate [Download]
2021-04-28T07:42:54.5827Z [I] Content Handler Download resultCode: 1, extendedCode: 0 [Download]
2021-04-28T07:42:54.5828Z [I] ProgressCallback: workflowId: 210428074149; Id 00000; State: Completed; Bytes: 144549945/144549945 [DownloadProgressCallback]
2021-04-28T07:42:54.5828Z [I] Download resultCode: 1, extendedCode: 0 [Download]
2021-04-28T07:42:54.5828Z [I] Action 'Download' complete. Result: 1, 0 [ADUC_Workflow_WorkCompletionCallback]
2021-04-28T07:42:54.5828Z [I] WorkCompletionCallback: Download succeeded. Going to state DownloadSucceeded [ADUC_Workflow_WorkCompletionCallback]
2021-04-28T07:42:54.5828Z [I] Setting UpdateState to DownloadSucceeded [ADUC_SetUpdateStateHelper]
2021-04-28T07:42:54.5828Z [I] Reporting state: DownloadSucceeded (2) [AzureDeviceUpdateCoreInterface_ReportStateAndResultAsync]

@cmknox
Copy link

cmknox commented May 26, 2021

@jimson-msft, @ValOlson can this issue be closed?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@cmknox @jimson-msft @ValOlson @Voxel07