Bilal
Reputation: 1054
IoT-Edge edgeHub module back-off state
i am trying to deploy a module into iot-edge device, for that i am following these Official Documentation.
- Have an IoTHub subscription Created Edge Device in it Installed IoTEdge Runtime on my local machine (to act it like as a simulated device)
- Docker for windows is installed, up and running
(Everything works well till here, as i checked the status of
Get-Service iotedgecommand) - Set up the Device module and used this
mcr.microsoft.com/azureiotedge-simulated-temperature-sensor:1.0as an image
after setting up the module on Microsoft Azure portal, edgeHub Module goes into back-off state. i have seen this issue IOT-Edge Hub back-off state and tried to restart docker as some of the comments suggested, but all in vain.
i have also run the docker logs edgeAgent command to show you some logs, which are attached with this post.
Edit: Attached are the statuses from Azure
And this one is the status of iotedgeruntime
EDIT 2
I have recreated iotedge device on azure and then reinstall iotedgeruntime on my windows machine. without creating a module. following are the logs
> iotedge logs edgeAgent
[09/03/2018 10:22:32.855 AM] Edge Agent Main()
2018-09-03 15:22:33.043 +05:00 [INF] - Starting module management agent.
2018-09-03 15:22:33.182 +05:00 [INF] - Version - 1.0.1.15962126 (6e5e86dcf0c9a3732fc72a64d9ec9b0fcb2d6fad)
2018-09-03 15:22:33.298 +05:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...
2018-09-03 15:22:34.360 +05:00 [INF] - Created persistent store at C:\Users\ContainerAdministrator\AppData\Local\Temp\edgeAgent
2018-09-03 15:22:39.749 +05:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup file (backup.json) instead
2018-09-03 15:22:39.751 +05:00 [INF] - Edge agent config backup file does not exist - backup.json
2018-09-03 15:22:43.239 +05:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only.
2018-09-03 15:22:46.031 +05:00 [INF] - Deployment config in edge agent's desired properties is empty.
2018-09-03 15:22:46.050 +05:00 [ERR] - Error refreshing edge agent configuration from twin.
Microsoft.Azure.Devices.Edge.Agent.Core.ConfigSources.ConfigEmptyException: This device has an empty configuration for the edge agent. Please set a deployment manifest.
at Microsoft.Azure.Devices.Edge.Agent.IoTHub.EdgeAgentConnection.UpdateDeploymentConfig() in C:\agent\_work\1\s\edge-agent\src\Microsoft.Azure.Devices.Edge.Agent.IoTHub\EdgeAgentConnection.cs:line 187
at Microsoft.Azure.Devices.Edge.Agent.IoTHub.EdgeAgentConnection.RefreshTwinAsync() in C:\agent\_work\1\s\edge-agent\src\Microsoft.Azure.Devices.Edge.Agent.IoTHub\EdgeAgentConnection.cs:line 148
This log shows EdgeAgent is started but had an issue to work with empty deployment configurations. so i created an empty configuration. mentioned here https://github.com/Azure/iot-edge-v1/issues/441#issuecomment-350824433. Then the same issue came up. Showing the log of following command.
> Get-WinEvent -ea SilentlyContinue `-FilterHashtable @{ProviderName="iotedged"; LogName = "application"; StartTime = [datetime]::Today} |select TimeCreated, Message |sort-object @{Expression="TimeCreated";Descending=$false} |format-table -autosize -wrap
Logs file
TimeCreated Message
----------- -------
9/3/2018 3:22:07 PM info: iotedged::app -- Starting Azure IoT Edge Security Daemon
9/3/2018 3:22:07 PM info: iotedged -- Initializing the module runtime...
9/3/2018 3:22:07 PM info: iotedged -- Using runtime network id nat
9/3/2018 3:22:07 PM info: iotedged::app -- Version - 1.0.0 (52ef77db24126bf473265fc09c53d35290a2dd6b)
9/3/2018 3:22:07 PM info: iotedged::app -- Using config file: C:\ProgramData\iotedge\config.yaml
9/3/2018 3:22:07 PM info: iotedged::windows -- Starting iotedged service.
9/3/2018 3:22:07 PM info: iotedged -- Configuring C:\ProgramData\iotedge as the home directory.
9/3/2018 3:22:07 PM info: iotedged -- Finished initializing the module runtime.
9/3/2018 3:22:07 PM info: iotedged -- Transparent gateway certificates not found, operating in quick start mode...
9/3/2018 3:22:07 PM info: iotedged -- Finished configuring certificates.
9/3/2018 3:22:07 PM info: iotedged -- Initializing hsm...
9/3/2018 3:22:07 PM info: iotedged -- Configuring certificates...
9/3/2018 3:22:08 PM info: iotedged -- Finished initializing hsm.
9/3/2018 3:22:08 PM info: iotedged -- Detecting if configuration file has changed...
9/3/2018 3:22:08 PM info: iotedged -- Change to configuration file detected.
9/3/2018 3:22:08 PM info: iotedged -- Removing all modules...
9/3/2018 3:22:09 PM info: iotedged -- Finished removing modules.
9/3/2018 3:22:09 PM info: iotedged -- Provisioning edge device...
9/3/2018 3:28:09 PM info: edgelet_core::watchdog -- Checking edge runtime status
9/3/2018 3:28:09 PM info: edgelet_core::watchdog -- Edge runtime is running.
9/3/2018 3:28:12 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:12.431950 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:17 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:17.442486300 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:22 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:22.448494200 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:27 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:27.469429300 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:32 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:32.471719400 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:37 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:37.485219700 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:42 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:42.500957700 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:47 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:47.511517800 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:52 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:52.517649100 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:28:57 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:28:57.533708400 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:02 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:02.543274600 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:07 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:07.554093 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:09 PM info: edgelet_core::watchdog -- Checking edge runtime status
9/3/2018 3:29:09 PM info: edgelet_core::watchdog -- Edge runtime is running.
9/3/2018 3:29:12 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:12.567305200 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:17 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:17.575885700 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:22 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:22.590898700 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:27 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:27.599495900 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:32 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:32.611798600 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:37 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:37.620460100 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:42 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:42.621030200 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 449 "-" "-" pid(any)
9/3/2018 3:29:42 PM info: edgelet_http::logging -- [work] - - - [2018-09-03 10:29:42.745729500 UTC] "POST /modules/%24edgeAgent/genid/636715662943777437/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 985 "-" "-" pid(any)
9/3/2018 3:29:43 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:43.740061700 UTC] "GET /identities/?api-version=2018-06-28 HTTP/1.1" 200 OK 210 "-" "-" pid(any)
9/3/2018 3:29:44 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:44.067628900 UTC] "PUT /identities/%24edgeHub?api-version=2018-06-28 HTTP/1.1" 200 OK 98 "-" "-" pid(any)
9/3/2018 3:29:46 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:46.999173700 UTC] "POST /modules?api-version=2018-06-28 HTTP/1.1" 201 Created 908 "-" "-" pid(any)
9/3/2018 3:29:47 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:29:47 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:47.247618 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:29:47 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:29:47 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:47.460481300 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:29:52 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:52.039166500 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:29:52 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:29:58 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:29:58.058868200 UTC] "GET /modules/edgeAgent/logs?api-version=2018-06-28&follow=false&tail=all HTTP/1.1" 200 OK - "-" "iotedge/0.1.0" pid(any)
9/3/2018 3:30:03 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:30:03 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:03.261676500 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:30:03 PM info: edgelet_http::logging -- [work] - - - [2018-09-03 10:30:03.317280 UTC] "POST /modules/%24edgeAgent/genid/636715662943777437/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 985 "-" "-" pid(any)
9/3/2018 3:30:08 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:08.632153200 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 831 "-" "-" pid(any)
9/3/2018 3:30:08 PM info: edgelet_http::logging -- [work] - - - [2018-09-03 10:30:08.633152900 UTC] "POST /modules/%24edgeAgent/genid/636715662943777437/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 985 "-" "-" pid(any)
9/3/2018 3:30:08 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:08.802696300 UTC] "POST /modules/edgeHub/stop?api-version=2018-06-28 HTTP/1.1" 304 Not Modified - "-" "-" pid(any)
9/3/2018 3:30:08 PM warn: edgelet_utils::logging -- Container already in this state
9/3/2018 3:30:08 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:30:08 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:08.929044700 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:30:09 PM info: edgelet_core::watchdog -- Checking edge runtime status
9/3/2018 3:30:09 PM info: edgelet_core::watchdog -- Edge runtime is running.
9/3/2018 3:30:09 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:30:09 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:09.086215200 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
9/3/2018 3:30:14 PM warn: edgelet_utils::logging -- Container runtime error - ApiError(ApiError { code: InternalServerError, content: Some(Object({"message": String("failed to create endpoint edgeHub on network nat: HNS failed with error : The process
cannot access the file because it is being used by another process. ")})) })
9/3/2018 3:30:14 PM info: edgelet_http::logging -- [mgmt] - - - [2018-09-03 10:30:14.661189 UTC] "POST /modules/edgeHub/start?api-version=2018-06-28 HTTP/1.1" 500 Internal Server Error 294 "-" "-" pid(any)
it shows initially edgeAgent started, but as soon as a deploy a module, then its showing the same error as i have mentioned above.
Upvotes: 0
Views: 2714
Answers (1)
Angelo Ribeiro
Reputation: 111
Unfortunately, from your logs, looks like you are having a docker for windows issue. I've found some github issues with very similar problems.
There are a couple of things you can do: Some people resolver by resetting docker (removing all existing docker images) or by doing this: - Uninstall Docker - Remove Containers windows feature - Reboot - Enable Containers windows feature - Install Docker
I understand the other option is awful and time consuming, I'm just forwarding what helped others.
Upvotes: 0
Related Questions
- IoT Edge offline capabilities in VM
- Azure iot edge modules development autoreload
- Azure IoT Edge Module: Docker Container Run Time Options in VS Code Deployment Template
- Ubuntu IoT Edge edgeHub module fails with error (139) Access to the path '/tmp/edgeHub/edgeHub' is denied
- One of the IoT Edge Module is in Backoff state Raspberry Pi 4 with Raspbian OS
- Need to run microsoft azure IOT edge runtime as container
- Azure IoT Edge Module : Error while Build and Push IoT Edge Solution
- Azure IoT Edge edgeHub module can't start
- How to debug edgeHub module in Azure IoT Edge
- Azure IoT Edge setup completes successfully but does not start the edgeAgent docker image