search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.47k stars 462 forks source link

module start up issue with NXP yocto port of iotedge #3845

Closed dvescovi1 closed 4 years ago

dvescovi1 commented 4 years ago

2926 Expected Behavior

NoderedModule should start

Current Behavior

NoderedModule does not start with some kind of authentication issue on iMX8Mmini evk board. See documented issue here

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. see NXP iotedge port here
  2. leveraging yocto meta-iotedge here

Context (Environment)

Output of iotedge check

see attached logs here

Device Information

Runtime Versions

Note: when using Windows containers on Windows, run docker -H npipe:////./pipe/iotedge_moby_engine version instead

Logs

see attached logs here

Additional Information

Please provide any additional information that may be helpful in understanding the issue.

dvescovi1 commented 4 years ago

I suspect some of this has to do with differences in users and permissions. While the raspberry pi is a true Debian system yocto usually does not normally have "users" per se. Could this be the issue?

arsing commented 4 years ago

So if the issue is with that module and you've already opened a bug there, do you need us to do anything?

emmanuel-bv commented 4 years ago

HI @dvescovi1, i agree with @arsing that it looks like an issue with the node red module. If you confirm this, could you please close this item and track the issue in the node red github site? Thanks!

dvescovi1 commented 4 years ago

unfortunately I have not been able to narrow it down any further. Present thinking is it is showing some similar symptoms to the "stability on constrained devices" as expressed in several iotedge bug reports/Bug fixes I been reading about. Out of desperation I tried upgrading to azureiotedge-hub:1.2.0-rc1 and I noticed the hub module failing in a very similar manor (network disconnecting with Not authorized failure) this with ONLY the agent and hub module loaded. I have also verified by building yocto images for both the rasberry pi and my iMX8 device both using the exact same components. i.e. meta-iotedge, meta-rust, poky and meta-virtualization using same component build SHA hash so the only delta is the actual low level BSP code (zeus raspberry pi BSP vs. zeus freescale BSP). raspberry pi works but iMX8 fails when node red module is deployed the exact same way on both.

dvescovi1 commented 4 years ago

Is there anyone familiar with the NXP iMX IotEdge or similar device port I could converse with?

dvescovi1 commented 4 years ago

this info from the "iotedge logs NoderedModule" upon failure seems to provide the best clue:

29 Oct 22:18:38 - [info] Server now running at http://127.0.0.1:1880/
29 Oct 22:18:38 - [info] [edgeclient:982d18c.4c939e8] Module Client created.
29 Oct 22:18:38 - [info] [edgeclient:982d18c.4c939e8] Module Client open error:UnauthorizedError: mqtt.js returned Failure on first connection (Not authorized): connect ECONNREFUSED 172.18.0.2:8883 error
29 Oct 22:18:38 - [red] Uncaught Exception:
29 Oct 22:18:38 - UnauthorizedError: mqtt.js returned Failure on first connection (Not authorized): connect ECONNREFUSED 172.18.0.2:8883 error
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! node-red-docker@1.1.3 start: `node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data"`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the node-red-docker@1.1.3 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /data/.npm/_logs/2020-10-29T22_18_38_769Z-debug.log

doing the exact same on the working raspberry pi yields this log:

 29 Oct 21:03:49 - [info] Server now running at http://127.0.0.1:1880/
29 Oct 21:03:49 - [warn]

---------------------------------------------------------------------
Your flow credentials file is encrypted using a system-generated key.

If the system-generated key is lost for any reason, your credentials
file will not be recoverable, you will have to delete it and re-enter
your credentials.

You should set your own key using the 'credentialSecret' option in
your settings file. Node-RED will then re-encrypt your credentials
file using your chosen key the next time you deploy a change.
---------------------------------------------------------------------

29 Oct 21:03:49 - [info] Starting flows
29 Oct 21:03:49 - [info] Started flows
29 Oct 21:03:50 - [info] [edgeclient:c4bf0ff5.466fc] Module Client created.
29 Oct 21:03:51 - [info] [edgeclient:c4bf0ff5.466fc] Module Client connected.
29 Oct 21:03:51 - [info] [moduleoutput:c9647f34.c958d] Module Output created: output1
29 Oct 21:03:51 - [info] [modulemethod:7e44a36f.ef59fc] Direct Method created: setValue
29 Oct 21:03:51 - [info] [moduleinput:17bd1ad3.c82555] Module Input created: input1
29 Oct 21:03:51 - [info] [moduleoutput:4f5c1206.7d5eec] Module Output created: output2
dvescovi1 commented 4 years ago

this log file is from same device (imx8) with ONLY hub and agent modules trying to run (1.2.0-rc1). There is no third party module at all. ,,,

<6> 2020-11-14 03:53:21.907 +00:00 [INF] - Installing certificates [CN=iotedged workload ca:02/12/2021 02:32:17],[CN=Test Edge Device CA:02/12/2021 02:32:17],[CN=Test Edge Owner CA:02/12/2021 02:32:17] to Root <6> 2020-11-14 03:53:22.041 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:02/12/2021 02:32:17] to Root <6> 2020-11-14 03:53:22.056 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2020-11-14 03:53:22.445 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableNestedEdge":false,"EnableMqttBroker":false} <6> 2020-11-14 03:53:24.088 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2020-11-14 03:53:24.252 +00:00 [INF] - Initializing Edge Hub <6> 2020-11-14 03:53:24.253 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2020-11-14 03:53:24.258 +00:00 [INF] - Version - 1.2.0-rc1.36607244 (dd8b529d67fcc0fc5adaa92ecf4d1758dfed4eaf) <6> 2020-11-14 03:53:24.259 +00:00 [INF] - OptimizeForPerformance=False <6> 2020-11-14 03:53:24.259 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2020-11-14 03:53:24.262 +00:00 [INF] - Loaded server certificate with expiration date of "2021-02-12T02:32:17.0000000+00:00" <6> 2020-11-14 03:53:24.295 +00:00 [INF] - Using Asp Net server for metrics <6> 2020-11-14 03:53:24.407 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2020-11-14 03:53:24.506 +00:00 [INF] - Created new message store <6> 2020-11-14 03:53:24.694 +00:00 [INF] - Created device scope identities cache <6> 2020-11-14 03:53:24.724 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-11-14 03:53:24.802 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2020-11-14 03:53:24.918 +00:00 [INF] - Initialized storing twin manager <6> 2020-11-14 03:53:24.960 +00:00 [INF] - Initializing configuration <6> 2020-11-14 03:53:25.021 +00:00 [INF] - New device connection for device imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:25.028 +00:00 [INF] - Client imx8mmevk-manual-2/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2020-11-14 03:53:25.177 +00:00 [INF] - Attempting to connect to IoT Hub for client imx8mmevk-manual-2/$edgeHub via AMQP... <6> 2020-11-14 03:53:25.260 +00:00 [INF] - Processing pending subscriptions for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:26.319 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2020-11-14 03:53:26.352 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableNestedEdge":false,"EnableMqttBroker":false} <6> 2020-11-14 03:53:26.490 +00:00 [INF] - No routes set in the edge hub <6> 2020-11-14 03:53:26.494 +00:00 [INF] - Updated message store TTL to 7200 seconds <6> 2020-11-14 03:53:26.496 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2020-11-14 03:53:26.603 +00:00 [INF] - Started operation Get EdgeHub config <6> 2020-11-14 03:53:26.606 +00:00 [INF] - Initialized edge hub configuration <6> 2020-11-14 03:53:26.635 +00:00 [INF] - Scheduling server certificate renewal for "2021-02-12T02:29:47.0015053Z". <6> 2020-11-14 03:53:26.641 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2020-11-14 03:53:26.652 +00:00 [INF] - Starting MQTT head <6> 2020-11-14 03:53:26.798 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2020-11-14 03:53:26.831 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2020-11-14 03:53:27.033 +00:00 [INF] - Starting AMQP head <6> 2020-11-14 03:53:27.072 +00:00 [INF] - Started MQTT head <6> 2020-11-14 03:53:27.309 +00:00 [INF] - Started AMQP head <6> 2020-11-14 03:53:27.316 +00:00 [INF] - Starting HTTP head <6> 2020-11-14 03:53:27.641 +00:00 [INF] - Exiting disconnected state <6> 2020-11-14 03:53:27.719 +00:00 [INF] - Received device connected callback <6> 2020-11-14 03:53:27.749 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2020-11-14 03:53:27.759 +00:00 [INF] - Processing subscriptions for client imx8mmevk-manual-2/$edgeHub on device connected to cloud. <6> 2020-11-14 03:53:27.760 +00:00 [INF] - Skipping imx8mmevk-manual-2/$edgeHub for subscription processing, as it is currently being processed. <6> 2020-11-14 03:53:27.770 +00:00 [INF] - Device scope identities refresh is ready because a refresh was signalled. <6> 2020-11-14 03:53:27.770 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-11-14 03:53:27.810 +00:00 [INF] - Entering connected state <6> 2020-11-14 03:53:27.834 +00:00 [INF] - Cloud connection for imx8mmevk-manual-2/$edgeHub is True <6> 2020-11-14 03:53:27.849 +00:00 [INF] - Connection status for imx8mmevk-manual-2/$edgeHub changed to ConnectionEstablished <6> 2020-11-14 03:53:27.855 +00:00 [INF] - Client imx8mmevk-manual-2/$edgeHub connected to cloud, processing existing subscriptions. <6> 2020-11-14 03:53:27.856 +00:00 [INF] - Skipping imx8mmevk-manual-2/$edgeHub for subscription processing, as it is currently being processed. <6> 2020-11-14 03:53:27.867 +00:00 [INF] - Created cloud proxy for client imx8mmevk-manual-2/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2020-11-14 03:53:27.900 +00:00 [INF] - Initialized cloud proxy 238a9aba-db6d-4068-85f6-dc19090121ea for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:27.907 +00:00 [INF] - Created cloud connection for client imx8mmevk-manual-2/$edgeHub <4> 2020-11-14 03:53:28.241 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <0> 2020-11-14 03:53:28.300 +00:00 [FTL] - Unable to start Kestrel. System.Net.Sockets.SocketException (13): Permission denied at System.Net.Sockets.Socket.UpdateStatusAfterSocketErrorAndThrowException(SocketError error, String callerName) at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Bind(EndPoint localEP) at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketConnectionListener.Bind() at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketTransportFactory.BindAsync(EndPoint endpoint, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer.<>c__DisplayClass21_0`1.<g__OnBind|0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindEndpointAsync(ListenOptions endpoint, AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.ListenOptions.BindAsync(AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.EndpointsStrategy.BindAsync(AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindAsync(IServerAddressesFeature addresses, KestrelServerOptions serverOptions, ILogger logger, Func`2 createBinding) at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer.StartAsync[TContext](IHttpApplication`1 application, CancellationToken cancellationToken) <3> 2020-11-14 03:53:28.376 +00:00 [ERR] - Error starting protocol heads: Permission denied <6> 2020-11-14 03:53:28.377 +00:00 [INF] - Stopping the protocol heads... <6> 2020-11-14 03:53:28.379 +00:00 [INF] - Closing protocol heads - (MQTT, AMQP, HTTP) <6> 2020-11-14 03:53:28.384 +00:00 [INF] - Stopping <6> 2020-11-14 03:53:28.420 +00:00 [INF] - Closing HTTP head <6> 2020-11-14 03:53:28.429 +00:00 [INF] - Closed HTTP head <6> 2020-11-14 03:53:28.481 +00:00 [INF] - Processing pending subscriptions for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:28.516 +00:00 [INF] - Updated reported properties for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:28.794 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2020-11-14 03:53:29.241 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-11-14 03:53:30.206 +00:00 [INF] - Updated reported properties for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:53:43.543 +00:00 [INF] - Stopped <6> 2020-11-14 03:53:43.545 +00:00 [INF] - Protocol heads stopped. <6> 2020-11-14 03:53:43.563 +00:00 [INF] - Stopping <6> 2020-11-14 03:53:43.564 +00:00 [INF] - Stopped <6> 2020-11-14 03:53:43.584 +00:00 [INF] - Shutdown complete. <6> 2020-11-14 03:53:43.587 +00:00 [INF] - Termination requested, initiating shutdown. <6> 2020-11-14 03:53:43.587 +00:00 [INF] - Waiting for cleanup to finish <6> 2020-11-14 03:53:43.587 +00:00 [INF] - Done with cleanup. Shutting down. Nov 14 03:53:43.792 INFO watchdog::child: Edge Hub process has stopped Nov 14 03:53:43.792 INFO watchdog: Successfully stopped Edge Hub process Nov 14 03:53:43.792 INFO watchdog: Stopped Watchdog process 2020-11-14 03:58:47 +00:00 Starting Edge Hub Nov 14 03:58:47.658 INFO watchdog: Starting Watchdog Nov 14 03:58:47.658 INFO watchdog: Registering shutdown signal listener Nov 14 03:58:47.659 INFO watchdog: MQTT broker is disabled Nov 14 03:58:47.659 INFO watchdog::child: Launched Edge Hub process with pid 10 2020-11-14 03:58:47.820 +00:00 Edge Hub Main() <6> 2020-11-14 03:58:50.757 +00:00 [INF] - Installing certificates [CN=iotedged workload ca:02/12/2021 02:32:17],[CN=Test Edge Device CA:02/12/2021 02:32:17],[CN=Test Edge Owner CA:02/12/2021 02:32:17] to Root <6> 2020-11-14 03:58:50.892 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:02/12/2021 02:32:17] to Root <6> 2020-11-14 03:58:50.907 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2020-11-14 03:58:51.299 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableNestedEdge":false,"EnableMqttBroker":false} <6> 2020-11-14 03:58:52.948 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2020-11-14 03:58:53.113 +00:00 [INF] - Initializing Edge Hub <6> 2020-11-14 03:58:53.114 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2020-11-14 03:58:53.118 +00:00 [INF] - Version - 1.2.0-rc1.36607244 (dd8b529d67fcc0fc5adaa92ecf4d1758dfed4eaf) <6> 2020-11-14 03:58:53.119 +00:00 [INF] - OptimizeForPerformance=False <6> 2020-11-14 03:58:53.119 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2020-11-14 03:58:53.122 +00:00 [INF] - Loaded server certificate with expiration date of "2021-02-12T02:32:17.0000000+00:00" <6> 2020-11-14 03:58:53.165 +00:00 [INF] - Using Asp Net server for metrics <6> 2020-11-14 03:58:53.265 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2020-11-14 03:58:53.368 +00:00 [INF] - Created new message store <6> 2020-11-14 03:58:53.559 +00:00 [INF] - Created device scope identities cache <6> 2020-11-14 03:58:53.590 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-11-14 03:58:53.666 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2020-11-14 03:58:53.773 +00:00 [INF] - Initialized storing twin manager <6> 2020-11-14 03:58:53.824 +00:00 [INF] - Initializing configuration <6> 2020-11-14 03:58:53.884 +00:00 [INF] - New device connection for device imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:58:53.893 +00:00 [INF] - Client imx8mmevk-manual-2/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2020-11-14 03:58:54.042 +00:00 [INF] - Attempting to connect to IoT Hub for client imx8mmevk-manual-2/$edgeHub via AMQP... <6> 2020-11-14 03:58:54.121 +00:00 [INF] - Processing pending subscriptions for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:58:55.172 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2020-11-14 03:58:55.205 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableNestedEdge":false,"EnableMqttBroker":false} <6> 2020-11-14 03:58:55.353 +00:00 [INF] - No routes set in the edge hub <6> 2020-11-14 03:58:55.357 +00:00 [INF] - Updated message store TTL to 7200 seconds <6> 2020-11-14 03:58:55.360 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2020-11-14 03:58:55.456 +00:00 [INF] - Started operation Get EdgeHub config <6> 2020-11-14 03:58:55.463 +00:00 [INF] - Initialized edge hub configuration <6> 2020-11-14 03:58:55.492 +00:00 [INF] - Scheduling server certificate renewal for "2021-02-12T02:29:47.0012919Z". <6> 2020-11-14 03:58:55.504 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2020-11-14 03:58:55.517 +00:00 [INF] - Starting MQTT head <6> 2020-11-14 03:58:55.699 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2020-11-14 03:58:55.702 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2020-11-14 03:58:55.925 +00:00 [INF] - Starting AMQP head <6> 2020-11-14 03:58:55.964 +00:00 [INF] - Started MQTT head <6> 2020-11-14 03:58:56.179 +00:00 [INF] - Started AMQP head <6> 2020-11-14 03:58:56.186 +00:00 [INF] - Starting HTTP head <6> 2020-11-14 03:58:56.552 +00:00 [INF] - Exiting disconnected state <6> 2020-11-14 03:58:56.629 +00:00 [INF] - Received device connected callback <6> 2020-11-14 03:58:56.660 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2020-11-14 03:58:56.670 +00:00 [INF] - Processing subscriptions for client imx8mmevk-manual-2/$edgeHub on device connected to cloud. <6> 2020-11-14 03:58:56.671 +00:00 [INF] - Skipping imx8mmevk-manual-2/$edgeHub for subscription processing, as it is currently being processed. <6> 2020-11-14 03:58:56.680 +00:00 [INF] - Device scope identities refresh is ready because a refresh was signalled. <6> 2020-11-14 03:58:56.681 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-11-14 03:58:56.720 +00:00 [INF] - Entering connected state <6> 2020-11-14 03:58:56.742 +00:00 [INF] - Cloud connection for imx8mmevk-manual-2/$edgeHub is True <6> 2020-11-14 03:58:56.761 +00:00 [INF] - Connection status for imx8mmevk-manual-2/$edgeHub changed to ConnectionEstablished <6> 2020-11-14 03:58:56.769 +00:00 [INF] - Client imx8mmevk-manual-2/$edgeHub connected to cloud, processing existing subscriptions. <6> 2020-11-14 03:58:56.770 +00:00 [INF] - Skipping imx8mmevk-manual-2/$edgeHub for subscription processing, as it is currently being processed. <6> 2020-11-14 03:58:56.784 +00:00 [INF] - Created cloud proxy for client imx8mmevk-manual-2/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2020-11-14 03:58:56.813 +00:00 [INF] - Initialized cloud proxy 0ec7eba2-9584-4f6c-af87-034bacc6afd5 for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:58:56.825 +00:00 [INF] - Created cloud connection for client imx8mmevk-manual-2/$edgeHub <4> 2020-11-14 03:58:57.142 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <0> 2020-11-14 03:58:57.200 +00:00 [FTL] - Unable to start Kestrel. System.Net.Sockets.SocketException (13): Permission denied at System.Net.Sockets.Socket.UpdateStatusAfterSocketErrorAndThrowException(SocketError error, String callerName) at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Bind(EndPoint localEP) at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketConnectionListener.Bind() at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketTransportFactory.BindAsync(EndPoint endpoint, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer.<>c__DisplayClass21_0`1.<g__OnBind|0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindEndpointAsync(ListenOptions endpoint, AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.ListenOptions.BindAsync(AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.EndpointsStrategy.BindAsync(AddressBindContext context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindAsync(IServerAddressesFeature addresses, KestrelServerOptions serverOptions, ILogger logger, Func`2 createBinding) at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer.StartAsync[TContext](IHttpApplication`1 application, CancellationToken cancellationToken) <3> 2020-11-14 03:58:57.280 +00:00 [ERR] - Error starting protocol heads: Permission denied <6> 2020-11-14 03:58:57.281 +00:00 [INF] - Stopping the protocol heads... <6> 2020-11-14 03:58:57.283 +00:00 [INF] - Closing protocol heads - (MQTT, AMQP, HTTP) <6> 2020-11-14 03:58:57.289 +00:00 [INF] - Stopping <6> 2020-11-14 03:58:57.325 +00:00 [INF] - Closing HTTP head <6> 2020-11-14 03:58:57.335 +00:00 [INF] - Closed HTTP head <6> 2020-11-14 03:58:57.400 +00:00 [INF] - Processing pending subscriptions for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:58:57.426 +00:00 [INF] - Updated reported properties for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:58:57.984 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2020-11-14 03:58:58.110 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-11-14 03:58:59.052 +00:00 [INF] - Updated reported properties for imx8mmevk-manual-2/$edgeHub <6> 2020-11-14 03:59:12.412 +00:00 [INF] - Stopped <6> 2020-11-14 03:59:12.413 +00:00 [INF] - Protocol heads stopped. <6> 2020-11-14 03:59:12.431 +00:00 [INF] - Stopping <6> 2020-11-14 03:59:12.432 +00:00 [INF] - Stopped <6> 2020-11-14 03:59:12.452 +00:00 [INF] - Shutdown complete. <6> 2020-11-14 03:59:12.456 +00:00 [INF] - Termination requested, initiating shutdown. <6> 2020-11-14 03:59:12.456 +00:00 [INF] - Waiting for cleanup to finish <6> 2020-11-14 03:59:12.456 +00:00 [INF] - Done with cleanup. Shutting down. Nov 14 03:59:12.666 INFO watchdog::child: Edge Hub process has stopped Nov 14 03:59:12.666 INFO watchdog: Successfully stopped Edge Hub process Nov 14 03:59:12.666 INFO watchdog: Stopped Watchdog process root@imx8mmevk:~# [ 5651.746819] br-a425e4d87bb3: port 2(vetha233c86) entered blocking state [ 5651.753483] br-a425e4d87bb3: port 2(vetha233c86) entered disabled state [ 5651.760614] device vetha233c86 entered promiscuous mode [ 5651.766056] kauditd_printk_skb: 20 callbacks suppressed [ 5651.766059] audit: type=1700 audit(1605326654.846:676): dev=vetha233c86 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295 [ 5651.768442] IPv6: ADDRCONF(NETDEV_UP): vetha233c86: link is not ready [ 5651.771409] audit: type=1300 audit(1605326654.846:676): arch=c00000b7 syscall=206 success=yes exit=40 a0=c a1=4001269a10 a2=28 a3=0 items=0 ppid=1 pid=3516 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" key=(null) [ 5651.786918] IPv6: ADDRCONF(NETDEV_UP): veth6f6dde4: link is not ready [ 5651.790044] audit: type=1327 audit(1605326654.846:676): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F [ 5651.816730] IPv6: ADDRCONF(NETDEV_CHANGE): veth6f6dde4: link becomes ready [ 5651.840829] IPv6: ADDRCONF(NETDEV_CHANGE): vetha233c86: link becomes ready [ 5651.847900] br-a425e4d87bb3: port 2(vetha233c86) entered blocking state [ 5651.854560] br-a425e4d87bb3: port 2(vetha233c86) entered forwarding state [ 5651.884370] audit: type=1325 audit(1605326654.982:677): table=nat family=2 entries=13 [ 5651.892659] audit: type=1300 audit(1605326654.982:677): arch=c00000b7 syscall=208 success=yes exit=0 a0=4 a1=0 a2=40 a3=aaaaeb7de360 items=0 ppid=3516 pid=20001 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" key=(null) [ 5651.921185] audit: type=1327 audit(1605326654.982:677): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4100444F434B4552002D7000746370002D6400302F30002D2D64706F72740038383833002D6A00444E4154002D2D746F2D64657374696E6174696F6E003137322E31382E302E333A383838330000002D690062722D613432356534643837 [ 5651.949728] audit: type=1325 audit(1605326655.010:678): table=filter family=2 entries=29 [ 5651.957915] audit: type=1300 audit(1605326655.010:678): arch=c00000b7 syscall=208 success=yes exit=0 a0=4 a1=0 a2=40 a3=aaaae3c65a50 items=0 ppid=3516 pid=20003 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" key=(null) [ 5651.986418] audit: type=1327 audit(1605326655.010:678): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4100444F434B45520000002D690062722D613432356534643837626233002D6F0062722D613432356534643837626233002D7000746370002D64003137322E31382E302E33002D2D64706F72740038383833002D6A004143434550 [ 5652.015021] audit: type=1325 audit(1605326655.038:679): table=nat family=2 entries=14 [ 5653.249523] br-a425e4d87bb3: port 2(vetha233c86) entered disabled state [ 5653.256753] eth0: renamed from veth6f6dde4 [ 5653.281376] IPv6: ADDRCONF(NETDEV_UP): vetha233c86: link is not ready [ 5653.288061] IPv6: ADDRCONF(NETDEV_CHANGE): vetha233c86: link becomes ready [ 5653.295154] br-a425e4d87bb3: port 2(vetha233c86) entered blocking state [ 5653.301809] br-a425e4d87bb3: port 2(vetha233c86) entered forwarding state [ 5678.670529] kauditd_printk_skb: 50 callbacks suppressed [ 5678.670534] audit: type=1325 audit(1605326681.771:696): table=nat family=2 entries=19 [ 5678.683971] audit: type=1300 audit(1605326681.771:696): arch=c00000b7 syscall=208 success=yes exit=0 a0=4 a1=0 a2=40 a3=aaaaf8c90010 items=0 ppid=3516 pid=20639 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" key=(null) [ 5678.712591] audit: type=1327 audit(1605326681.771:696): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4400444F434B4552002D7000746370002D6400302F30002D2D64706F72740038383833002D6A00444E4154002D2D746F2D64657374696E6174696F6E003137322E31382E302E333A383838330000002D690062722D613432356534643837 [ 5678.741663] audit: type=1325 audit(1605326681.799:697): table=filter family=2 entries=32 [ 5678.750487] audit: type=1300 audit(1605326681.799:697): arch=c00000b7 syscall=208 success=yes exit=0 a0=4 a1=0 a2=40 a3=aaab004030b0 items=0 ppid=3516 pid=20641 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" key=(null) [ 5678.779958] audit: type=1327 audit(1605326681.799:697): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4400444F434B45520000002D690062722D613432356534643837626233002D6F0062722D613432356534643837626233002D7000746370002D64003137322E31382E302E33002D2D64706F72740038383833002D6A004143434550 [ 5678.808712] audit: type=1325 audit(1605326681.831:698): table=nat family=2 entries=18 [ 5678.817280] audit: type=1300 audit(1605326681.831:698): arch=c00000b7 syscall=208 success=yes exit=0 a0=4 a1=0 a2=40 a3=aaaaf2cb1e10 items=0 ppid=3516 pid=20643 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-legacy-multi" key=(null) [ 5678.846119] audit: type=1327 audit(1605326681.831:698): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4400504F5354524F5554494E47002D7000746370002D73003137322E31382E302E33002D64003137322E31382E302E33002D2D64706F72740038383833002D6A004D415351554552414445 [ 5678.871375] audit: type=1325 audit(1605326681.859:699): table=nat family=2 entries=17 [ 5678.940113] br-a425e4d87bb3: port 2(vetha233c86) entered disabled state [ 5678.946943] veth6f6dde4: renamed from eth0 [ 5678.969712] IPv6: ADDRCONF(NETDEV_UP): vetha233c86: link is not ready [ 5678.998990] IPv6: ADDRCONF(NETDEV_UP): veth6f6dde4: link is not ready [ 5679.005545] IPv6: ADDRCONF(NETDEV_CHANGE): veth6f6dde4: link becomes ready [ 5679.012663] IPv6: ADDRCONF(NETDEV_CHANGE): vetha233c86: link becomes ready [ 5679.019844] br-a425e4d87bb3: port 2(vetha233c86) entered blocking state [ 5679.026499] br-a425e4d87bb3: port 2(vetha233c86) entered forwarding state [ 5679.037432] br-a425e4d87bb3: port 2(vetha233c86) entered disabled state [ 5679.049489] device vetha233c86 left promiscuous mode [ 5679.054598] br-a425e4d87bb3: port 2(vetha233c86) entered disabled state [ 5679.087048] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready [ 5679.093245] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 5679.099200] IPv6: ADDRCONF(NETDEV_UP): p2p0: link is not ready [ 5679.106077] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready [ 5679.112280] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 5679.118225] IPv6: ADDRCONF(NETDEV_UP): p2p0: link is not ready [ 5679.125075] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready [ 5679.131248] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 5679.137235] IPv6: ADDRCONF(NETDEV_UP): p2p0: link is not ready root@imx8mmevk:~# root@imx8mmevk:~# iotedge list NAME STATUS DESCRIPTION CONFIG edgeAgent running Up 2 hours mcr.microsoft.com/azureiotedge-agent:1.2.0-rc1 edgeHub stopped Stopped 3 minutes ago mcr.microsoft.com/azureiotedge-hub:1.2.0-rc1 root@imx8mmevk:~# ``` as you can see there is a similar "Permission denied" which seems to be at the root of the issue.
damonbarry commented 4 years ago

@dvescovi1 For Edge hub 1.2.0-rc1 on imx8, see #9. Edge hub runs as a non-privileged user, which would normally mean it can't bind to ports below 1024 (e.g., 443), except we build it with CAP_NET_BIND_SERVICE. So your operating system needs to support that capability.

damonbarry commented 4 years ago

Closing this issue since the 1st part is specific to a 3rd-party module, and the 2nd part was filed separately as #3974.