Error 810549253 (0x30500005) handler script

marcelo-luna commented 3 weeks ago

I've been trying to run a script for testing purposes that creates a folder and then a file in this folder with ADU, and I'm getting the error: 810549253 (0x30500005).

"ADUC_ERC_SCRIPT_HANDLER_MISSING_SCRIPTFILENAME_PROPERTY MAKE_ADUC_EXTENDEDRESULTCODE_FOR_COMPONENT_ADUC_CONTENT_HANDLER_SCRIPT(5)" from result.h

Files:

script_test.importmanifest.json:

{
  "updateId": {
    "name": "script",
    "provider": "me",
    "version": "7.0.0"
  },
  "compatibility": [
    {
      "manufacturer": "hp",
      "model": "elite"
    }
  ],
  "createdDateTime": "2024-10-23T09:33:11Z",
  "files": [
    {
      "filename": "script_test.sh",
      "hashes": {
        "sha256": "lHKs3UsbWJAE3Svz3KwPCWibEofSPisKfB2rsbyIM4E="
      },
      "sizeInBytes": 328
    }
  ],
  "instructions": {
    "steps": [
      {
        "files": [
          "script_test.sh"
        ],
        "handler": "microsoft/script:1",
        "handlerProperties": {
        "installedCriteria": "1.0",
        },
        "type": "inline"
      }
    ]
  },
  "manifestVersion": "5.0"
}

script_test.sh:


#!/bin/bash

# Create a directory
mkdir -p /home/azureuser/this_was_create_by_adu

# Create a text file with specified content inside the directory
echo "this file was generated by adu" > /home/azureuser/this_was_create_by_adu/generated_file.txt

# Confirmation message
echo "Directory and file have been created successfully."

Log:

2024-11-05T15:39:52.8789Z 5742[5742] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ====
Sending D2C message:
{"deviceUpdate":{"__t":"c","service":{"value":{"fileUrls":null,"rootKeyPackageUrl":"http:\/\/*****.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json","updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"me\",\"name\":\"script\",\"version\":\"7.0.0\"},\"compatibility\":[{\"manufacturer\":\"hp\",\"model\":\"elite\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/script:1\",\"files\":[\"f5fd8ef249bdfb6bc\"],\"handlerProperties\":{\"installedCriteria\":\"1.0\",\"scriptFileName\":\"script_test.sh\"}}]},\"files\":{\"f5fd8ef249bdfb6bc\":{\"fileName\":\"script_test.sh\",\"sizeInBytes\":328,\"hashes\":{\"sha256\":\"lHKs3UsbWJAE3Svz3KwPCWibEofSPisKfB2rsbyIM4E=\"}}},\"createdDateTime\":\"2024-10-23T09:33:11Z\"}","updateManifestSignature":null,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}},"ac":200,"ad":"","av":5}}}2024-11-05T15:39:52.8789Z 5742[5742] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-05T15:39:52.8793Z 5742[7981] [I] Try to load a handler for current update manifest version 5 (handler: 'microsoft/update-manifest:5') [GetUpdateManifestHandler:114]
2024-11-05T15:39:52.8793Z 5742[7981] [I] Loading handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:208]
2024-11-05T15:39:52.8794Z 5742[7981] [I] Loading extension 'microsoft/update-manifest:5'. Reg file : /var/lib/adu/extensions/update_content_handlers/microsoft_update-manifest_5/content_handler.json [LoadExtensionLibrary:85]
2024-11-05T15:39:52.8794Z 5742[7981] [D] Determining contract version for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:303]
2024-11-05T15:39:52.8794Z 5742[7981] [D] Got 1.0 contract version for 'microsoft/update-manifest:5' handler [LoadUpdateContentHandlerExtension:331]
2024-11-05T15:39:52.8794Z 5742[7981] [D] Caching new handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:340]
2024-11-05T15:39:52.8797Z 5742[7981] [I] Action 'Download' complete. Result: 0 (failed), 810549253 (0x30500005) [ADUC_Workflow_WorkCompletionCallback:890]
2024-11-05T15:39:52.8797Z 5742[7981] [I] WorkCompletionCallback: Download failed. Going to state Failed [ADUC_Workflow_WorkCompletionCallback:1016]
2024-11-05T15:39:52.8797Z 5742[7981] [I] Setting UpdateState to Failed [ADUC_Workflow_SetUpdateStateHelper:1088]

2024-11-05T15:39:52.8797Z 5742[7981] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ====
Queueing message (t:0, c:0x64006e50, m:{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":{"step_0":{"resultCode":0,"extendedResultCodes":"00000000","resultDetails":null}},"resultCode":0,"extendedResultCodes":"30500005,A0000FFF","resultDetails":""},"state":255,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}})2024-11-05T15:39:52.8797Z 5742[7981] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-05T15:39:52.8815Z 5742[7981] [I] Workflow is Complete. [ADUC_Workflow_AutoTransitionWorkflow:758]
2024-11-05T15:39:53.2803Z 5742[5742] [D] context:0xb6b015a0 [DefaultIoTHubSendReportedStateCompletedCallback:205]
2024-11-05T15:39:53.2803Z 5742[5742] [D] D2C message processed successfully (t:0, r:0, content:0xb8465da0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
2024-11-05T15:39:53.2803Z 5742[5742] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]
2024-11-05T15:39:53.2804Z 5742[5742] [D] context:0xb6b01640 [DefaultIoTHubSendReportedStateCompletedCallback:205]
2024-11-05T15:39:53.2804Z 5742[5742] [D] D2C message processed successfully (t:1, r:0, content:0xb843b8c0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233]
2024-11-05T15:39:53.2804Z 5742[5742] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]
2024-11-05T15:39:53.2804Z 5742[5742] [D] Sending D2C message (t:0, retries:0). [ProcessMessage:390]

2024-11-05T15:39:53.2804Z 5742[5742] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ====
Sending D2C message:
{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":{"step_0":{"resultCode":0,"extendedResultCodes":"00000000","resultDetails":null}},"resultCode":0,"extendedResultCodes":"30500005,A0000FFF","resultDetails":""},"state":255,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}}2024-11-05T15:39:53.2804Z 5742[5742] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

I also tried to add "scriptFileName" inside handlerProperties:

    "handlerProperties": {
        "installedCriteria": "1.0",
    "scriptFileName": "script_test.sh"
    },

I tried an update with the apt handler and it worked fine.

OS: Ubuntu 22.04 with iot edge

marcelo-luna commented 3 weeks ago

Update:

I'm really confused about what's happening here. Today, I turned on the Azure VM that I'm using for testing, and I noticed that the folder and file were created by ADU during its last initialization.

However, in the Azure portal, the deployment showed "Deployment Status: Failed," as you can see:

Result code: 0

Extended result code: 810549765

Description:

The install script doesn't create a result file '/var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8/action_download_aduc_result.json'.

script-handler.20241108-151428.log

2024-11-08T15:14:28.4728Z 564[564] [I] Instantiating an Step Handler for 'microsoft/script:1' update type. [CreateUpdateContentHandlerExtension:52] 2024-11-08T15:14:28.4769Z 564[564] [I] Loading extension 'Content Downloader'. Reg file : /var/lib/adu/extensions/content_downloader/extension.json [LoadExtensionLibrary:85] 2024-11-08T15:14:28.4882Z 564[564] [I] Downloading full target update payload to '/var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8/script_test.sh' [Download:943] 2024-11-08T15:14:29.9928Z 564[564] [I] Action (is-installed) begin [ScriptHandler_PerformAction:527] 2024-11-08T15:14:29.9929Z 564[564] [I] Script workflow doesn't contain 'arguments' property. This is unusual, but not an error... [PrepareScriptArguments:362] 2024-11-08T15:14:29.9929Z 564[564] [I] Parsing script arguments: [PrepareScriptArguments:367]

2024-11-08T15:14:30.0115Z 564[564] [I] [ScriptHandler_PerformAction:655] ==== MULTI-LINE LOG BEGIN ==== 2024-11-08T15:14:30.0051Z 788[788] [I] Run as uid(0), defaultUid(114), effectiveUid(0), effectiveGid(124) [main:367] 2024-11-08T15:14:30.0052Z 788[788] [I] Executing script. Path: /var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8/script_test.sh [Execute:37] 2024-11-08T15:14:30.0113Z 788[788] [I] ########## Begin Child's Logs ########## [ShowChildProcessLogs:231] 2024-11-08T15:14:30.0113Z 788[788] [I] # Directory and file have been created successfully. [ShowChildProcessLogs:234] 2024-11-08T15:14:30.0113Z 788[788] [I] ########## End Child's Logs ########## [ShowChildProcessLogs:236] 2024-11-08T15:14:30.0113Z 788[788] [I] Uninitializing config info. [ADUC_ConfigInfo_UnInit:525] 2024-11-08T15:14:30.0115Z 564[564] [I] [ScriptHandler_PerformAction:655] ==== MULTI-LINE LOG END ====

du-agent.log

2024-11-08T15:14:26.6053Z 564[564] [D] Log file created: /var/log/adu/du-agent.20241108-151426.log [zlog_init:185] 2024-11-08T15:14:26.6482Z 564[564] [I] Agent (linux; 1.1.0) starting. [main:1024] 2024-11-08T15:14:26.6482Z 564[564] [I] Supported Update Manifest version: min: 4, max: 5 [main:1028] 2024-11-08T15:14:26.6997Z 564[564] [I] Health check passed. [HealthCheck:632] 2024-11-08T15:14:26.7548Z 564[564] [I] Initializing PnP components. [ADUC_PnP_Components_Create:496] 2024-11-08T15:14:26.7581Z 564[564] [I] ADUC agent started. Using IoT Hub Client SDK 1.11.0 [AzureDeviceUpdateCoreInterface_Create:263] 2024-11-08T15:14:26.7581Z 564[564] [I] Calling ADUC_RegisterPlatformLayer [ADUC_MethodCall_Register:62] 2024-11-08T15:14:26.7588Z 564[564] [I] Loading extension 'Content Downloader'. Reg file : /var/lib/adu/extensions/content_downloader/extension.json [LoadExtensionLibrary:85] 2024-11-08T15:14:26.8108Z 564[564] [D] Determining contract version for content downloader. [LoadContentDownloaderLibrary:468] 2024-11-08T15:14:26.8108Z 564[564] [D] Got Contract 1.0 for content downloader [LoadContentDownloaderLibrary:483] 2024-11-08T15:14:26.8108Z 564[564] [I] Initializing command listener thread [InitializeCommandListenerThread:380] 2024-11-08T15:14:26.8108Z 564[564] [I] Command register at slot#0 [RegisterCommand:62] 2024-11-08T15:14:26.8108Z 564[564] [I] Agent running. [main:1075] 2024-11-08T15:14:26.8109Z 564[564] [I] Attempting to create connection to IotHub using type: ADUC_ConnType_Device [ADUC_DeviceClient_Create:315] 2024-11-08T15:14:26.8109Z 564[564] [I] IotHub Protocol: MQTT [GetIotHubProtocolFromConfig:253] 2024-11-08T15:14:26.8109Z 564[564] [I] IoTHub Device Twin callback registered. [ADUC_DeviceClient_Create:418] 2024-11-08T15:14:26.8109Z 564[564] [I] Refreshing the handle for the PnP channels. [ADUC_PnP_Components_HandleRefresh:474] 2024-11-08T15:14:26.8109Z 564[564] [I] Successfully re-authenticated the IoT Hub connection. [ADUC_Refresh_IotHub_Connection_SAS_Token:678] 2024-11-08T15:14:26.8152Z 564[659] [I] Command FIFO file created successfully. [TryCreateFIFOPipe:159] 2024-11-08T15:14:26.9454Z 564[564] [I] The connection is currently broken. Will try to authenticate in 17 seconds. [Connection_Maintenance:769] 2024-11-08T15:14:27.2016Z 564[564] [D] IotHub connection status: 0, reason: 6 [IoTHub_CommunicationManager_ConnectionStatus_Callback:212] 2024-11-08T15:14:27.6080Z 564[564] [D] ComponentName:deviceUpdate, propertyName:service [ADUC_PnP_ComponentClient_PropertyUpdate_Callback:536]

2024-11-08T15:14:27.6081Z 564[564] [D] [OrchestratorUpdateCallback:433] ==== MULTI-LINE LOG BEGIN ==== Update Action info string ({"fileUrls":null,"rootKeyPackageUrl":"http:\/\/***.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json","updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"me\",\"name\":\"script\",\"version\":\"7.0.0\"},\"compatibility\":[{\"manufacturer\":\"hp\",\"model\":\"elite\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/script:1\",\"files\":[\"f5fd8ef249bdfb6bc\"],\"handlerProperties\":{\"installedCriteria\":\"1.0\",\"scriptFileName\":\"script_test.sh\"}}]},\"files\":{\"f5fd8ef249bdfb6bc\":{\"fileName\":\"script_test.sh\",\"sizeInBytes\":328,\"hashes\":{\"sha256\":\"lHKs3UsbWJAE3Svz3KwPCWibEofSPisKfB2rsbyIM4E=\"}}},\"createdDateTime\":\"2024-10-23T09:33:11Z\"}","updateManifestSignature":null,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}), property version (5)2024-11-08T15:14:27.6081Z 564[564] [D] [OrchestratorUpdateCallback:433] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:27.6082Z 564[564] [D] Processing deployment aebe0066-67ba-4d78-a247-2656d91dd7c8 ... [OrchestratorUpdateCallback:446]

2024-11-08T15:14:27.6082Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ==== Queueing message (t:0, c:0xa0f86140, m:{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}})2024-11-08T15:14:27.6082Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:27.6111Z 564[564] [W] rootkey package 'rootkeypackage-1.json' in sandbox. Try deletion... [ADUC_RootKeyPackageUtils_DownloadPackage:97] 2024-11-08T15:14:27.6112Z 564[564] [D] Attempting download of '***' using 'DO' [ADUC_RootKeyPackageUtils_DownloadPackage:109]

2024-11-08T15:14:27.6112Z 564[564] [I] [DownloadRootKeyPkg_DO:22] ==== MULTI-LINE LOG BEGIN ==== Downloading File '****' 2024-11-08T15:14:27.6112Z 564[564] [I] [DownloadRootKeyPkg_DO:22] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:28.3750Z 564[564] [I] Download rc: 1, erc: 0x00000000 [DownloadRootKeyPkg_DO:51] 2024-11-08T15:14:28.3800Z 564[564] [D] No root key change. [RootKeyWorkflow_UpdateRootKeys:172] 2024-11-08T15:14:28.3814Z 564[564] [D] set prop '_workFolder' to '/var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8' [workflow_set_string_property:1683] 2024-11-08T15:14:28.3814Z 564[564] [I] Perform startup tasks. [ADUC_Workflow_HandleStartupWorkflowData:355] 2024-11-08T15:14:28.3814Z 564[564] [I] Calling IsInstalledCallback to check if content is installed. [ADUC_Workflow_MethodCall_IsInstalled:1721] 2024-11-08T15:14:28.3814Z 564[564] [I] IsInstalledCallback called [IsInstalledCallback:329] 2024-11-08T15:14:28.3814Z 564[564] [I] Try to load a handler for current update manifest version 5 (handler: 'microsoft/update-manifest:5') [GetUpdateManifestHandler:114] 2024-11-08T15:14:28.3814Z 564[564] [I] Loading handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:208] 2024-11-08T15:14:28.3814Z 564[564] [I] Loading extension 'microsoft/update-manifest:5'. Reg file : /var/lib/adu/extensions/update_content_handlers/microsoft_update-manifest_5/content_handler.json [LoadExtensionLibrary:85] 2024-11-08T15:14:28.4070Z 564[564] [D] Determining contract version for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:303] 2024-11-08T15:14:28.4071Z 564[564] [D] Got 1.0 contract version for 'microsoft/update-manifest:5' handler [LoadUpdateContentHandlerExtension:331] 2024-11-08T15:14:28.4071Z 564[564] [D] Caching new handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:340] 2024-11-08T15:14:30.0137Z 564[564] [I] There's a pending 'ProcessDeployment' action [ADUC_Workflow_HandleStartupWorkflowData:398] 2024-11-08T15:14:30.0137Z 564[564] [D] cancellationType(0) => None [ADUC_Workflow_HandleUpdateAction:628] 2024-11-08T15:14:30.0137Z 564[564] [I] Calling IsInstalledCallback to check if content is installed. [ADUC_Workflow_MethodCall_IsInstalled:1721] 2024-11-08T15:14:30.0137Z 564[564] [I] IsInstalledCallback called [IsInstalledCallback:329] 2024-11-08T15:14:30.0137Z 564[564] [I] Try to load a handler for current update manifest version 5 (handler: 'microsoft/update-manifest:5') [GetUpdateManifestHandler:114] 2024-11-08T15:14:30.0137Z 564[564] [I] Loading handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:208] 2024-11-08T15:14:30.0137Z 564[564] [I] Loading extension 'microsoft/update-manifest:5'. Reg file : /var/lib/adu/extensions/update_content_handlers/microsoft_update-manifest_5/content_handler.json [LoadExtensionLibrary:85] 2024-11-08T15:14:30.0138Z 564[564] [D] Determining contract version for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:303] 2024-11-08T15:14:30.0138Z 564[564] [D] Got 1.0 contract version for 'microsoft/update-manifest:5' handler [LoadUpdateContentHandlerExtension:331] 2024-11-08T15:14:30.0138Z 564[564] [D] Caching new handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:340] 2024-11-08T15:14:30.0303Z 564[564] [D] Processing 'Download' step [ADUC_Workflow_TransitionWorkflow:811] 2024-11-08T15:14:30.0303Z 564[564] [D] Setting operation_in_progress => true [ADUC_Workflow_TransitionWorkflow:828] 2024-11-08T15:14:30.0303Z 564[564] [D] Property '_workFolder' not NULL - returning cached workfolder '/var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8' [workflow_get_workfolder:1908] 2024-11-08T15:14:30.0303Z 564[564] [I] Workflow step: Download [ADUC_Workflow_MethodCall_Download:1347] 2024-11-08T15:14:30.0303Z 564[564] [I] Calling SandboxCreateCallback [ADUC_Workflow_MethodCall_Download:1358] 2024-11-08T15:14:30.0305Z 564[564] [I] Setting sandbox /var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8 [SandboxCreate:391] 2024-11-08T15:14:30.0305Z 564[564] [I] Using sandbox /var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8 [ADUC_Workflow_MethodCall_Download:1370] 2024-11-08T15:14:30.0305Z 564[564] [I] Setting UpdateState to DownloadStarted [ADUC_Workflow_SetUpdateStateHelper:1088] 2024-11-08T15:14:30.0305Z 564[564] [D] Skipping report of state 'DownloadStarted' [AzureDeviceUpdateCoreInterface_ReportStateAndResultAsync:954] 2024-11-08T15:14:30.0305Z 564[564] [I] Download thread started. [DownloadCallback:72] 2024-11-08T15:14:30.0306Z 564[564] [D] PropertyUpdated event handler completed. [ADUC_Workflow_HandlePropertyUpdate:599]

2024-11-08T15:14:30.0306Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ==== Queueing message (t:1, c:0xa0f20c50, m:{"deviceUpdate":{"__t":"c","service":{"value":{"fileUrls":null,"rootKeyPackageUrl":"http:\/\/***--device-update-oot.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json","updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"me\",\"name\":\"script\",\"version\":\"7.0.0\"},\"compatibility\":[{\"manufacturer\":\"hp\",\"model\":\"elite\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/script:1\",\"files\":[\"f5fd8ef249bdfb6bc\"],\"handlerProperties\":{\"installedCriteria\":\"1.0\",\"scriptFileName\":\"script_test.sh\"}}]},\"files\":{\"f5fd8ef249bdfb6bc\":{\"fileName\":\"script_test.sh\",\"sizeInBytes\":328,\"hashes\":{\"sha256\":\"lHKs3UsbWJAE3Svz3KwPCWibEofSPisKfB2rsbyIM4E=\"}}},\"createdDateTime\":\"2024-10-23T09:33:11Z\"}","updateManifestSignature":null,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}},"ac":200,"ad":"","av":5}}})2024-11-08T15:14:30.0306Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0316Z 564[564] [I] OrchestratorPropertyUpdateCallback ended [OrchestratorUpdateCallback:517] 2024-11-08T15:14:30.0316Z 564[564] [I] Processing existing Device Twin data after agent started. [ADUC_PnPDeviceTwin_Callback:647] 2024-11-08T15:14:30.0316Z 564[564] [D] Notifies components that all callback are subscribed. [ADUC_PnPDeviceTwin_Callback:650]

2024-11-08T15:14:30.0316Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ==== Queueing message (t:5, c:0xa0f88480, m:{"deviceUpdate":{"__t":"c","agent":{"deviceProperties":{"manufacturer":"hp","model":"elite","interfaceId":null,"contractModelId":"dtmi:azure:iot:deviceUpdateContractModel;3","aduVer":"DU;agent\/1.1.0"},"compatPropertyNames":"manufacturer,model"}}})2024-11-08T15:14:30.0316Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0319Z 564[564] [I] DeviceInformation component is ready - reporting properties [DeviceInfoInterface_Connected:166] 2024-11-08T15:14:30.0319Z 564[564] [I] Property manufacturer changed to hp [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0319Z 564[564] [I] Property model changed to elite [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0320Z 564[564] [I] Property osName changed to Ubuntu [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0320Z 564[564] [I] Property swVersion changed to 22.04.5 LTS (Jammy Jellyfish) [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0320Z 564[564] [I] Property processorArchitecture changed to x86_64 [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0327Z 564[794] [I] Try to load a handler for current update manifest version 5 (handler: 'microsoft/update-manifest:5') [GetUpdateManifestHandler:114] 2024-11-08T15:14:30.0327Z 564[794] [I] Loading handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:208] 2024-11-08T15:14:30.0327Z 564[794] [I] Loading extension 'microsoft/update-manifest:5'. Reg file : /var/lib/adu/extensions/update_content_handlers/microsoft_update-manifest_5/content_handler.json [LoadExtensionLibrary:85] 2024-11-08T15:14:30.0328Z 564[794] [D] Determining contract version for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:303] 2024-11-08T15:14:30.0328Z 564[794] [D] Got 1.0 contract version for 'microsoft/update-manifest:5' handler [LoadUpdateContentHandlerExtension:331] 2024-11-08T15:14:30.0328Z 564[794] [D] Caching new handler for 'microsoft/update-manifest:5'. [LoadUpdateContentHandlerExtension:340] 2024-11-08T15:14:30.0406Z 564[564] [I] Property processorManufacturer changed to GenuineIntel [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0406Z 564[564] [I] Property totalMemory changed to 904832 [RefreshDeviceInfoInterfaceData:131] 2024-11-08T15:14:30.0406Z 564[564] [I] Property totalStorage changed to 30298176 [RefreshDeviceInfoInterfaceData:131]

2024-11-08T15:14:30.0406Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ==== Queueing message (t:2, c:0xa0f781c0, m:{"deviceInformation":{"__t":"c","manufacturer":"hp","model":"elite","osName":"Ubuntu","swVersion":"22.04.5 LTS (Jammy Jellyfish)","processorArchitecture":"x86_64","processorManufacturer":"GenuineIntel","totalMemory":904832,"totalStorage":30298176}})2024-11-08T15:14:30.0406Z 564[564] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0439Z 564[564] [I] DiagnosticsInterface is connected [DiagnosticsInterface_Connected:97] 2024-11-08T15:14:30.0439Z 564[564] [D] Sending D2C message (t:0, retries:0). [ProcessMessage:390]

2024-11-08T15:14:30.0439Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ==== Sending D2C message: {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":null,"resultCode":1,"extendedResultCodes":"00000000","resultDetails":null},"state":6,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}}2024-11-08T15:14:30.0439Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0442Z 564[564] [D] Sending D2C message (t:1, retries:0). [ProcessMessage:390]

2024-11-08T15:14:30.0442Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ==== Sending D2C message: {"deviceUpdate":{"__t":"c","service":{"value":{"fileUrls":null,"rootKeyPackageUrl":"http:\/\/***.b.nlu.dl.adu.microsoft.com\/WestEurope\/rootkeypackages\/rootkeypackage-1.json","updateManifest":"{\"manifestVersion\":\"5\",\"updateId\":{\"provider\":\"me\",\"name\":\"script\",\"version\":\"7.0.0\"},\"compatibility\":[{\"manufacturer\":\"hp\",\"model\":\"elite\"}],\"instructions\":{\"steps\":[{\"handler\":\"microsoft\/script:1\",\"files\":[\"f5fd8ef249bdfb6bc\"],\"handlerProperties\":{\"installedCriteria\":\"1.0\",\"scriptFileName\":\"script_test.sh\"}}]},\"files\":{\"f5fd8ef249bdfb6bc\":{\"fileName\":\"script_test.sh\",\"sizeInBytes\":328,\"hashes\":{\"sha256\":\"lHKs3UsbWJAE3Svz3KwPCWibEofSPisKfB2rsbyIM4E=\"}}},\"createdDateTime\":\"2024-10-23T09:33:11Z\"}","updateManifestSignature":null,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}},"ac":200,"ad":"","av":5}}}2024-11-08T15:14:30.0442Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0445Z 564[564] [D] Sending D2C message (t:2, retries:0). [ProcessMessage:390]

2024-11-08T15:14:30.0445Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ==== Sending D2C message: {"deviceInformation":{"__t":"c","manufacturer":"hp","model":"elite","osName":"Ubuntu","swVersion":"22.04.5 LTS (Jammy Jellyfish)","processorArchitecture":"x86_64","processorManufacturer":"GenuineIntel","totalMemory":904832,"totalStorage":30298176}}2024-11-08T15:14:30.0445Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.0447Z 564[564] [D] Sending D2C message (t:5, retries:0). [ProcessMessage:390]

2024-11-08T15:14:30.0447Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ==== Sending D2C message: {"deviceUpdate":{"__t":"c","agent":{"deviceProperties":{"manufacturer":"hp","model":"elite","interfaceId":null,"contractModelId":"dtmi:azure:iot:deviceUpdateContractModel;3","aduVer":"DU;agent\/1.1.0"},"compatPropertyNames":"manufacturer,model"}}}2024-11-08T15:14:30.0447Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.7083Z 564[794] [I] Action 'Download' complete. Result: 0 (failed), 810549765 (0x30500205) [ADUC_Workflow_WorkCompletionCallback:890] 2024-11-08T15:14:30.7083Z 564[794] [I] WorkCompletionCallback: Download failed. Going to state Failed [ADUC_Workflow_WorkCompletionCallback:1016] 2024-11-08T15:14:30.7083Z 564[794] [I] Setting UpdateState to Failed [ADUC_Workflow_SetUpdateStateHelper:1088]

2024-11-08T15:14:30.7084Z 564[794] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG BEGIN ==== Queueing message (t:0, c:0x60006850, m:{"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":{"step_0":{"resultCode":0,"extendedResultCodes":"30500205","resultDetails":"The install script doesn't create a result file '\/var\/lib\/adu\/downloads\/aebe0066-67ba-4d78-a247-2656d91dd7c8\/action_download_aduc_result.json'."}},"resultCode":0,"extendedResultCodes":"30500205,A0000FFF","resultDetails":"The install script doesn't create a result file '\/var\/lib\/adu\/downloads\/aebe0066-67ba-4d78-a247-2656d91dd7c8\/action_download_aduc_result.json'."},"state":255,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}})2024-11-08T15:14:30.7084Z 564[794] [D] [ADUC_D2C_Message_SendAsync:526] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:30.7088Z 564[794] [I] Workflow is Complete. [ADUC_Workflow_AutoTransitionWorkflow:758] 2024-11-08T15:14:30.9242Z 564[564] [D] context:0x9fbbc5a0 [DefaultIoTHubSendReportedStateCompletedCallback:205] 2024-11-08T15:14:30.9242Z 564[564] [D] D2C message processed successfully (t:0, r:0, content:0xa0f86230 ) [DefaultIoTHubSendReportedStateCompletedCallback:233] 2024-11-08T15:14:30.9242Z 564[564] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64] 2024-11-08T15:14:30.9243Z 564[564] [D] context:0x9fbbc640 [DefaultIoTHubSendReportedStateCompletedCallback:205] 2024-11-08T15:14:30.9243Z 564[564] [D] D2C message processed successfully (t:1, r:0, content:0xa0f20760 ) [DefaultIoTHubSendReportedStateCompletedCallback:233] 2024-11-08T15:14:30.9243Z 564[564] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64] 2024-11-08T15:14:30.9243Z 564[564] [D] context:0x9fbbc6e0 [DefaultIoTHubSendReportedStateCompletedCallback:205] 2024-11-08T15:14:30.9243Z 564[564] [D] D2C message processed successfully (t:2, r:0, content:0xa0f76fe0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233] 2024-11-08T15:14:30.9243Z 564[564] [D] Send message completed (status:3) [OnDeviceInfoD2CMessageCompleted:191] 2024-11-08T15:14:30.9243Z 564[564] [D] context:0x9fbbc8c0 [DefaultIoTHubSendReportedStateCompletedCallback:205] 2024-11-08T15:14:30.9243Z 564[564] [D] D2C message processed successfully (t:5, r:0, content:0xa0f7a830 ) [DefaultIoTHubSendReportedStateCompletedCallback:233] 2024-11-08T15:14:30.9243Z 564[564] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64] 2024-11-08T15:14:30.9243Z 564[564] [D] Sending D2C message (t:0, retries:0). [ProcessMessage:390]

2024-11-08T15:14:30.9243Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG BEGIN ==== Sending D2C message: {"deviceUpdate":{"__t":"c","agent":{"lastInstallResult":{"stepResults":{"step_0":{"resultCode":0,"extendedResultCodes":"30500205","resultDetails":"The install script doesn't create a result file '\/var\/lib\/adu\/downloads\/aebe0066-67ba-4d78-a247-2656d91dd7c8\/action_download_aduc_result.json'."}},"resultCode":0,"extendedResultCodes":"30500205,A0000FFF","resultDetails":"The install script doesn't create a result file '\/var\/lib\/adu\/downloads\/aebe0066-67ba-4d78-a247-2656d91dd7c8\/action_download_aduc_result.json'."},"state":255,"workflow":{"action":3,"id":"aebe0066-67ba-4d78-a247-2656d91dd7c8"}}}}2024-11-08T15:14:30.9243Z 564[564] [D] [ADUC_D2C_Default_Message_Transport_Function:580] ==== MULTI-LINE LOG END ====

2024-11-08T15:14:31.3278Z 564[564] [D] context:0x9fbbc5a0 [DefaultIoTHubSendReportedStateCompletedCallback:205] 2024-11-08T15:14:31.3278Z 564[564] [D] D2C message processed successfully (t:0, r:0, content:0x60006ac0 ) [DefaultIoTHubSendReportedStateCompletedCallback:233] 2024-11-08T15:14:31.3278Z 564[564] [D] Send message completed (status:3) [OnUpdateResultD2CMessageCompleted:64]

OscarLeeMSFT commented 2 weeks ago

Hi, Thank you for reporting the issue. The team will take a look at this in the next day or two and respond further.

Nox-MSFT commented 2 weeks ago

@marcelo-luna does your script (script_test.sh) write any output to the expected result file? (/var/lib/adu/downloads/aebe0066-67ba-4d78-a247-2656d91dd7c8/action_download_aduc_result.json). The common cause for this could be an error in the script that caused the script to be terminated or exited without properly report the action result in the result file.

marcelo-luna commented 2 weeks ago

@Nox-MSFT no, the script doesn't write output to the result file, but the script does produce some outputs

script_test.sh

#!/bin/bash

# Create a directory
mkdir -p /home/azureuser/this_was_create_by_adu

# Create a text file with specified content inside the directory
echo "this file was generated by adu" > /home/azureuser/this_was_create_by_adu/generated_file.txt

# Confirmation message
echo "Directory and file have been created successfully."

I also tried a new "script_test.sh" version without the final echo statement: echo "Directory and file have been created successfully.", but I got the same error.

Nox-MSFT commented 2 weeks ago

@marcelo-luna , please take a look at the document on how to write a script for the script handler. Especially, this section : https://github.com/Azure/iot-hub-device-update/tree/develop/src/extensions/step_handlers/script_handler#communicating-the-script-execution-result-back-to-the-script-handler

The example script is provided here: https://github.com/Azure/iot-hub-device-update/blob/develop/src/extensions/step_handlers/script_handler/examples/example-installscript.sh

Note that it's a long script, but meant to demonstrate all the required implementation needed for the communication between the script and the script handler.

Please let us know you have any questions

marcelo-luna commented 1 week ago

Thank you, @Nox-MSFT! I used the script you mentioned earlier, and it worked well.

I was following the documentation on the Azure page instead of the one on GitHub. It would be helpful to have more information about the script handler, as well as a tutorial, on this page: Azure Documentation.

Azure / iot-hub-device-update