Closed mschwan-phytec closed 3 years ago
dmolokanov
commented
3 years ago hello @mschwan-phytec! could you please update iotedge package to the latest version 1.0.10.3 and send over updated logs? This way we will have a consistent versions across all components.
dmolokanov
commented
3 years ago in order to make make a request to iothub edge agent will generate SAS token. this is where you see Error calling SignAsync exception. this exception caused by 404 response from iotedged.
"POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-)it made me think that api-version is incorrect.
mschwan-phytec
commented
3 years ago Thanks for the suggestion, @dmolokanov. I created recipes for building iotedge 1.0.10.3 in our Yocto BSP. Unfortunately, this did not change anything. The issue still remains (logs are the same).
Any other ideas?
dmolokanov
commented
3 years ago Could you please share the new logs for iotedged?
dmolokanov
commented
3 years ago in addition, lets collect debug logs for iotedged and edgeAgent. you can find step to do that here https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2018-06#check-the-status-of-the-iot-edge-security-manager-and-its-logs
mschwan-phytec
commented
3 years ago iotedged 1.0.10.3 logs with debug information:
edgeAgent 1.0.10.3 logs:
dmolokanov
commented
3 years ago I made some code research and iotedged responds with 404 in 2 cases:
Lets verify the first one:
# get list of container
curl --silent --unix-socket /var/run/docker.sock -X GET "http:/v1.34/containers/json" | jq
# find an edgeAgent container Id and check the PID and PPID of the agent
curl --silent --unix-socket /var/run/docker.sock -X GET "http:/v1.34/containers/{EDGEAGENT_CONTAINER_ID}/top" | jqthere is a response on my machine
{
"Processes": [
[
"user",
"140908",
"140911",
"0",
"17:14",
"pts/0",
"00:00:00",
"/usr/bin/dotnet Microsoft.Azure.Devices.Edge.Agent.Service.dll"
]
],
"Titles": [
"UID",
"PID",
"PPID",
"C",
"STIME",
"TTY",
"TIME",
"CMD"
]
}Thanks, @dmolokanov! This returned an error message that ps could not be run with the option -e. It turns out that our system had a version of ps installed (busybox that is), that does not allow for calling ps with any options. I solved this by installing procps which comes with a full version of ps.
I found the following issue, which dealt with the same problem: https://github.com/Azure/iotedge/issues/1330
Thanks again for the immediate help!
Expected Behavior
The edgeAgent module should run without error and an edgeHub module should be created. The IoT Edge modules should report their status successfully.
Current Behavior
The edgeAgent module runs (does not exit with an error) but fails with
Error creating a device-to-cloud connectionandError calling SignAsync: Module not found, StatusCode: 404, as well asEmpty edge agent config was received.(see full logs below). As a result, the edgeHub module is not being created and the status of the Edge device is not being reported to the Azure service.Steps to Reproduce
Provide a detailed set of steps to reproduce the bug.
Context (Environment)
Output of
iotedge checkClick here
``` root@myhostname:~# iotedge check Configuration checks -------------------- √ config.yaml is well-formed - OK √ config.yaml has well-formed connection string - OK √ container engine is installed and functional - OK √ config.yaml has correct hostname - OK √ config.yaml has correct URIs for daemon mgmt endpoint - OK ‼ latest security daemon - Warning Installed IoT Edge daemon has version 1.0.9.4 but 1.0.10.2 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ host time is close to real time - OK √ container time is close to host time - OK ‼ DNS server - Warning Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub. Please see https://aka.ms/iotedge-prod-checklist-dns for best practices. You can ignore this warning if you are setting DNS server per module in the Edge deployment. ‼ production readiness: certificates - Warning The Edge device is using self-signed automatically-generated development certificates. They will expire in 89 days (at 2021-02-24 14:45:45 UTC) causing module-to-module and downstream device communication to fail on an active deployment. After the certs have expired, restarting the IoT Edge daemon will trigger it to generate new development certs. Please consider using production certificates instead. See https://aka.ms/iotedge-prod-checklist-certs for best practices. ‼ production readiness: container engine - Warning Device is not using a production-supported container engine (moby-engine). Please see https://aka.ms/iotedge-prod-checklist-moby for details. ‼ production readiness: logs policy - Warning Container engine is not configured to rotate module logs which may cause it run out of disk space. Please see https://aka.ms/iotedge-prod-checklist-logs for best practices. You can ignore this warning if you are setting log policy per module in the Edge deployment. ‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. × production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error Could not check current state of edgeHub container Connectivity checks ------------------- √ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK √ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK √ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK √ container on the default network can connect to IoT Hub AMQP port - OK √ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the default network can connect to IoT Hub MQTT port - OK √ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK √ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK 16 check(s) succeeded. 6 check(s) raised warnings. Re-run with --verbose for more details. 1 check(s) raised errors. Re-run with --verbose for more details. ```Device Information
Runtime Versions
Click here
Logs
iotedged logs
``` -- Logs begin at Fri 2020-11-27 11:03:33 UTC. -- Nov 27 11:03:58 myhostname iotedged[520]: 2020-11-27T11:03:58Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. Nov 27 11:03:58 myhostname iotedged[520]: 2020-11-27T11:03:58Z [INFO] - Checking edge runtime status Nov 27 11:03:58 myhostname iotedged[520]: 2020-11-27T11:03:58Z [INFO] - Edge runtime status is stopped, starting module now... Nov 27 11:03:58 myhostname iotedged[520]: 2020-11-27T11:03:58Z [INFO] - Starting module edgeAgent... Nov 27 11:03:59 myhostname iotedged[520]: 2020-11-27T11:03:59Z [INFO] - Successfully started module edgeAgent Nov 27 11:04:02 myhostname iotedged[520]: 2020-11-27T11:04:02Z [INFO] - [work] - - - [2020-11-27 11:04:02.966011151 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Nov 27 11:04:04 myhostname iotedged[520]: 2020-11-27T11:04:04Z [INFO] - Querying system info... Nov 27 11:04:04 myhostname iotedged[520]: 2020-11-27T11:04:04Z [INFO] - Successfully queried system info Nov 27 11:04:04 myhostname iotedged[520]: 2020-11-27T11:04:04Z [INFO] - [mgmt] - - - [2020-11-27 11:04:04.980611526 UTC] "GET /systeminfo?api-version=2019-11-05 HTTP/1.1" 200 OK 63 "-" "-" auth_id(-) Nov 27 11:04:09 myhostname iotedged[520]: 2020-11-27T11:04:09Z [INFO] - [work] - - - [2020-11-27 11:04:09.528707026 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:10 myhostname iotedged[520]: 2020-11-27T11:04:10Z [INFO] - Querying system info... Nov 27 11:04:10 myhostname iotedged[520]: 2020-11-27T11:04:10Z [INFO] - Successfully queried system info Nov 27 11:04:10 myhostname iotedged[520]: 2020-11-27T11:04:10Z [INFO] - [mgmt] - - - [2020-11-27 11:04:10.842426026 UTC] "GET /systeminfo?api-version=2019-11-05 HTTP/1.1" 200 OK 63 "-" "-" auth_id(-) Nov 27 11:04:11 myhostname iotedged[520]: 2020-11-27T11:04:11Z [INFO] - [work] - - - [2020-11-27 11:04:11.355282526 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:11 myhostname iotedged[520]: 2020-11-27T11:04:11Z [INFO] - [mgmt] - - - [2020-11-27 11:04:11.688949776 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:04:12 myhostname iotedged[520]: 2020-11-27T11:04:12Z [INFO] - [work] - - - [2020-11-27 11:04:12.281000901 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:12 myhostname iotedged[520]: 2020-11-27T11:04:12Z [INFO] - [work] - - - [2020-11-27 11:04:12.658453776 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:19 myhostname iotedged[520]: 2020-11-27T11:04:19Z [INFO] - [work] - - - [2020-11-27 11:04:19.091024401 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:19 myhostname iotedged[520]: 2020-11-27T11:04:19Z [INFO] - [work] - - - [2020-11-27 11:04:19.452966526 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:21 myhostname iotedged[520]: 2020-11-27T11:04:21Z [INFO] - [mgmt] - - - [2020-11-27 11:04:21.871364276 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:04:31 myhostname iotedged[520]: 2020-11-27T11:04:31Z [INFO] - [mgmt] - - - [2020-11-27 11:04:31.905371971 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:04:32 myhostname iotedged[520]: 2020-11-27T11:04:32Z [INFO] - [work] - - - [2020-11-27 11:04:32.731699179 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:33 myhostname iotedged[520]: 2020-11-27T11:04:33Z [INFO] - [work] - - - [2020-11-27 11:04:33.247926778 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:04:41 myhostname iotedged[520]: 2020-11-27T11:04:41Z [INFO] - [mgmt] - - - [2020-11-27 11:04:41.934999913 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:04:51 myhostname iotedged[520]: 2020-11-27T11:04:51Z [INFO] - [mgmt] - - - [2020-11-27 11:04:51.950707310 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:04:58 myhostname iotedged[520]: 2020-11-27T11:04:58Z [INFO] - Checking edge runtime status Nov 27 11:04:58 myhostname iotedged[520]: 2020-11-27T11:04:58Z [INFO] - Edge runtime is running. Nov 27 11:05:00 myhostname iotedged[520]: 2020-11-27T11:05:00Z [INFO] - [work] - - - [2020-11-27 11:05:00.970940535 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:05:01 myhostname iotedged[520]: 2020-11-27T11:05:01Z [INFO] - [work] - - - [2020-11-27 11:05:01.470702891 UTC] "POST /modules/%24edgeAgent/genid/637419891249342856/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" auth_id(-) Nov 27 11:05:01 myhostname iotedged[520]: 2020-11-27T11:05:01Z [INFO] - [mgmt] - - - [2020-11-27 11:05:01.969808294 UTC] "GET /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 530 "-" "-" auth_id(-) Nov 27 11:05:04 myhostname iotedged[520]: 2020-11-27T11:05:04Z [INFO] - Querying system resources... Nov 27 11:05:06 myhostname iotedged[520]: 2020-11-27T11:05:06Z [INFO] - [mgmt] - - - [2020-11-27 11:05:06.320158126 UTC] "GET /systeminfo/resources?api-version=2019-11-05 HTTP/1.1" 200 OK 3109 "-" "-" auth_id(-) ```edge-agent logs
``` 2020-11-27 11:03:59 +00:00 Starting Edge Agent 2020-11-27 11:03:59 +00:00 Changing ownership of storage folder: /tmp/edgeAgent to 1000 2020-11-27 11:03:59 +00:00 Changing ownership of management socket: /var/run/iotedge/mgmt.sock 2020-11-27 11:04:00.327 +00:00 Edge Agent Main() <6> 2020-11-27 11:04:01.548 +00:00 [INF] - Initializing Edge Agent. <6> 2020-11-27 11:04:02.446 +00:00 [INF] - Version - 1.0.10.3.36904102 (95aa3cb67f16386be6c76e83feeb6538f6e040b9) <6> 2020-11-27 11:04:02.449 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2020-11-27 11:04:02.669 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false} <6> 2020-11-27 11:04:03.282 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:02/24/2021 14:45:45] to Root <6> 2020-11-27 11:04:03.970 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics <6> 2020-11-27 11:04:04.796 +00:00 [INF] - Updating performance metrics every 05m:00s <6> 2020-11-27 11:04:04.818 +00:00 [INF] - Started operation Get system resources <6> 2020-11-27 11:04:04.827 +00:00 [INF] - Collecting metadata metrics <6> 2020-11-27 11:04:05.143 +00:00 [INF] - Set metadata metrics: 1.0.10.3.36904102 (95aa3cb67f16386be6c76e83feeb6538f6e040b9), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","A rchitecture":"aarch64","Version":"1.0.9.4","Provisioning":{"Type":"","DynamicReprovisioning":false},"ServerVersion":"","KernelVersion":"","OperatingSystem":"","NumCpus":0,"Virtualized":""}, True <6> 2020-11-27 11:04:05.247 +00:00 [INF] - Started operation Checkpoint Availability <6> 2020-11-27 11:04:05.275 +00:00 [INF] - Started operation refresh twin config <6> 2020-11-27 11:04:05.442 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only... <6> 2020-11-27 11:04:08.108 +00:00 [INF] - Created persistent store at /tmp/edgeAgent <6> 2020-11-27 11:04:08.587 +00:00 [INF] - Started operation Metrics Scrape <6> 2020-11-27 11:04:08.593 +00:00 [INF] - Started operation Metrics Upload Scraping frequency: 01:00:00 Upload Frequency: 1.00:00:00 <6> 2020-11-27 11:04:10.020 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only... <6> 2020-11-27 11:04:11.107 +00:00 [INF] - Registering request handler UploadModuleLogs <6> 2020-11-27 11:04:11.108 +00:00 [INF] - Registering request handler GetModuleLogs <6> 2020-11-27 11:04:11.113 +00:00 [INF] - Registering request handler UploadSupportBundle <6> 2020-11-27 11:04:11.114 +00:00 [INF] - Registering request handler RestartModule <4> 2020-11-27 11:04:11.407 +00:00 [WRN] - Error creating a device-to-cloud connection System.AggregateException: One or more errors occurred. (Error calling SignAsync: Module not found, StatusCode: 404) (Error calling SignAsync: Module not found, StatusCode: 404) ---> Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmComunicationException: Error calling SignAsync: Module not found, StatusCode: 404 at Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmSignatureProvider.SignAsync(String moduleId, String generationId, String data) at Microsoft.Azure.Devices.Client.HsmAuthentication.ModuleAuthenticationWithHsm.SafeCreateNewToken(String iotHub, Int32 suggestedTimeToLive) at Microsoft.Azure.Devices.Client.AuthenticationWithTokenRefresh.GetTokenAsync(String iotHub) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsTokenProvider.GetTokenAsync(Uri namespaceAddress, String appliesTo, String[] requiredClaims) at Microsoft.Azure.Amqp.TaskHelpers.EndAsyncResult(IAsyncResult asyncResult) at Microsoft.Azure.Amqp.IteratorAsyncResult`1.<>c.edge-hub logs
``` n.a. because edgeHub does not start ```iotedge config
``` ############################################################################### # IoT Edge Daemon configuration ############################################################################### # # This file configures the IoT Edge daemon. The daemon must be restarted to # pick up any configuration changes. # # Note - this file is yaml. Learn more here: http://yaml.org/refcard.html # ############################################################################### ############################################################################### # Provisioning mode and settings ############################################################################### # # Configures the identity provisioning mode of the daemon. # # Supported modes: # manual - using an iothub connection string # dps - using dps for provisioning # external - the device has been provisioned externally. # Uses an external provisioning endpoint to get device specific information. # # DPS Settings # scope_id - Required. Value of a specific DPS instance's ID scope # registration_id - Required for TPM and symmetric key provisioning flows. # Optional for X.509 provisioning. Registration ID of a # specific device in DPS. # For more information regarding DPS registration ids # please see https://docs.microsoft.com/en-us/azure/iot-dps/concepts-device#registration-id # symmetric_key - Optional. This entry should only be specified when # provisioning devices configured for symmetric key # attestation. Device specific symmetric key. # identity_cert - Optional. The Edge device identity X.509 certificate # entry should only be specified when provisioning # an Edge device configured for X.509 attestation. # The value should be specified as a URI. # Ex. when specifying a PEM encoded certificate file, the URI # should be specified as file:///path/identity_certificate.pem # identity_pk - Optional. The Edge device identity private key # entry should only be specified when provisioning # an Edge device configured for X.509 attestation. # The value should be specified as a URI. # Ex. when specifying a PEM encoded private key file, the URI # should be specified as file:///path/identity_key.pem # # External Settings # endpoint - Required. Value of the endpoint used to retrieve device specific # information such as its IoT hub connection information. ############################################################################### # Manual provisioning configuration provisioning: source: "manual" device_connection_string: "HostName=**********.azure-devices.net;DeviceId=*********;SharedAccessKey=***********************************************" # DPS TPM provisioning configuration # provisioning: # source: "dps" # global_endpoint: "https://global.azure-devices-provisioning.net" # scope_id: "