"Module not found" When running arm32v7 image

mortslhawmit commented 6 years ago

I've upgraded from preview to GA and have run in to an issue with running iotedge images on my RPI3, the solution works fine if I run on a local repo with the amd64.debug images on my windows machine but when I try to run my arm32v7 images on my RPI I get an error as soon as one of my custom modules run OpenAsync on the ModuleClient.

Steps to Reproduce

I build the solution with arm32v7 images in the deployment template, with azure container registry credentials.
I deploy to IoTEdge device (RPI3).
Wait for IoTEdge device to get images.
Getting the error when the image starts and tries to OpenAsync.

Context (Environment)

Device (Host) Operating System

RPI3 rasbian

Architecture

arm32

Container Operating System

linux containers

Runtime Versions

iotedged

1.0.0

Edge Agent

mcr.microsoft.com/azureiotedge-agent:1.0

Edge Hub

mcr.microsoft.com/azureiotedge-hub:1.0

Docker

Docker version 18.02.0-ce, build fc4de44

Logs

Error recevied when image starts, this is revieved as soon as "OpenAsync" is called on my ModuleClient.

Unhandled Exception: System.AggregateException: One or more errors occurred. (Error calling SignAsync: Module not found, StatusCode: 404) ---> Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmComunicationException: Error calling SignAsync: Module not found, StatusCode: 404

Additional Information

I'm using AMQP as mentioned here

var amqpSetting = new AmqpTransportSettings(TransportType.Amqp_Tcp_Only);
ITransportSettings[] settings = { amqpSetting };

var moduleClient = await ModuleClient.CreateFromEnvironmentAsync(settings);
await moduleClient.OpenAsync();

varunpuranik commented 6 years ago

This typically indicates that the Iotedged was not able to identify your custom module. Can you copy the iotedged logs here? That should tell us more. You can get them using $>journalctl -u iotedge -f My guess is your module might have multiple processes in it. The iotedged requires the first process in the container to communicate with it (as a security feature).

mortslhawmit commented 6 years ago

Here are the logs from iotedged, this is from when i restarded my custom modules.

Jul 30 05:59:17 raspberrypi iotedged[402]: 2018-07-30T05:59:17Z [INFO] - [mgmt] - - - [2018-07-30 05:59:17.811326764 UTC] "POST /modules/BLECommunicatorModule/start?api-version=2018-06-28 HTTP/1.1" 204 No Content - "-" "-" pid(16848)
> Jul 30 05:59:17 raspberrypi iotedged[402]: 2018-07-30T05:59:17Z [INFO] - [work] - - - [2018-07-30 05:59:17.867710523 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 05:59:23 raspberrypi iotedged[402]: 2018-07-30T05:59:23Z [INFO] - [work] - - - [2018-07-30 05:59:23.026990117 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1774 "-" "-" pid(583)
> Jul 30 05:59:23 raspberrypi iotedged[402]: 2018-07-30T05:59:23Z [INFO] - [mgmt] - - - [2018-07-30 05:59:23.116099229 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 1450 "-" "-" pid(16848)
> Jul 30 05:59:23 raspberrypi iotedged[402]: 2018-07-30T05:59:23Z [INFO] - [work] - - - [2018-07-30 05:59:23.121407960 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 05:59:23 raspberrypi iotedged[402]: 2018-07-30T05:59:23Z [INFO] - [mgmt] - - - [2018-07-30 05:59:23.473652134 UTC] "GET /identities/?api-version=2018-06-28 HTTP/1.1" 200 OK 429 "-" "-" pid(16848)
> Jul 30 05:59:23 raspberrypi iotedged[402]: 2018-07-30T05:59:23Z [INFO] - [mgmt] - - - [2018-07-30 05:59:23.652183743 UTC] "PUT /identities/NodeHandlerModule?api-version=2018-06-28 HTTP/1.1" 200 OK 107 "-" "-" pid(16848)
> Jul 30 05:59:25 raspberrypi iotedged[402]: 2018-07-30T05:59:25Z [INFO] - [mgmt] - - - [2018-07-30 05:59:25.641730054 UTC] "POST /modules?api-version=2018-06-28 HTTP/1.1" 201 Created 1068 "-" "-" pid(16848)
> Jul 30 05:59:28 raspberrypi iotedged[402]: 2018-07-30T05:59:28Z [INFO] - [mgmt] - - - [2018-07-30 05:59:28.048898590 UTC] "POST /modules/NodeHandlerModule/start?api-version=2018-06-28 HTTP/1.1" 204 No Content - "-" "-" pid(16848)
> Jul 30 05:59:28 raspberrypi iotedged[402]: 2018-07-30T05:59:28Z [INFO] - [work] - - - [2018-07-30 05:59:28.123514577 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 05:59:31 raspberrypi iotedged[402]: 2018-07-30T05:59:31Z [INFO] - Request not authorized - expected caller pid: 443, actual caller pid: 583
> Jul 30 05:59:31 raspberrypi iotedged[402]: 2018-07-30T05:59:31Z [INFO] - [work] - - - [2018-07-30 05:59:31.435976954 UTC] "POST /modules/BLECommunicatorModule/genid/636682081543458064/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" pid(583)
> Jul 30 05:59:33 raspberrypi iotedged[402]: 2018-07-30T05:59:33Z [INFO] - [work] - - - [2018-07-30 05:59:33.427846492 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 05:59:33 raspberrypi iotedged[402]: 2018-07-30T05:59:33Z [INFO] - [mgmt] - - - [2018-07-30 05:59:33.439073692 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 1930 "-" "-" pid(16848)
> Jul 30 05:59:35 raspberrypi iotedged[402]: 2018-07-30T05:59:35Z [INFO] - [work] - - - [2018-07-30 05:59:35.102793399 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1774 "-" "-" pid(747)
> Jul 30 05:59:42 raspberrypi iotedged[402]: 2018-07-30T05:59:42Z [INFO] - Checking edge runtime status
> Jul 30 05:59:44 raspberrypi iotedged[402]: 2018-07-30T05:59:44Z [INFO] - Edge runtime is running.
> Jul 30 05:59:48 raspberrypi iotedged[402]: 2018-07-30T05:59:48Z [INFO] - Request not authorized - expected caller pid: 651, actual caller pid: 747
> Jul 30 05:59:48 raspberrypi iotedged[402]: 2018-07-30T05:59:48Z [INFO] - [work] - - - [2018-07-30 05:59:48.594893678 UTC] "POST /modules/NodeHandlerModule/genid/636682081542364062/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 30 "-" "-" pid(747)
> Jul 30 06:00:01 raspberrypi iotedged[402]: 2018-07-30T06:00:01Z [INFO] - [work] - - - [2018-07-30 06:00:01.372754608 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 06:00:13 raspberrypi iotedged[402]: 2018-07-30T06:00:13Z [INFO] - [mgmt] - - - [2018-07-30 06:00:13.194393696 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 2092 "-" "-" pid(16848)
> Jul 30 06:00:18 raspberrypi iotedged[402]: 2018-07-30T06:00:18Z [INFO] - [mgmt] - - - [2018-07-30 06:00:18.476259268 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 2092 "-" "-" pid(16848)
> Jul 30 06:00:18 raspberrypi iotedged[402]: 2018-07-30T06:00:18Z [INFO] - [work] - - - [2018-07-30 06:00:18.479197487 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 06:00:23 raspberrypi iotedged[402]: 2018-07-30T06:00:23Z [INFO] - [mgmt] - - - [2018-07-30 06:00:23.619191379 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 2092 "-" "-" pid(16848)
> Jul 30 06:00:23 raspberrypi iotedged[402]: 2018-07-30T06:00:23Z [INFO] - [work] - - - [2018-07-30 06:00:23.622035119 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)
> Jul 30 06:00:28 raspberrypi iotedged[402]: 2018-07-30T06:00:28Z [INFO] - [mgmt] - - - [2018-07-30 06:00:28.767799833 UTC] "GET /modules?api-version=2018-06-28 HTTP/1.1" 200 OK 2092 "-" "-" pid(16848)
> Jul 30 06:00:28 raspberrypi iotedged[402]: 2018-07-30T06:00:28Z [INFO] - [work] - - - [2018-07-30 06:00:28.791279647 UTC] "POST /modules/%24edgeAgent/genid/636679315929178312/encrypt?api-version=2018-06-28 HTTP/1.1" 200 OK 1581 "-" "-" pid(16848)

("Sidenote" I validated that my azure container registry credential worked by pushing a amd64 image to the registry and running the solution locally, this all worked fine.)

But even if I strip down both my modules to only to only contain the main class that only handles OpenAsync on ModuleClient I still get the error module not found.

mortslhawmit commented 6 years ago

I spoke to soon, i forgot that i ran a bashscript to start my .dll file because i want to start some services before i run the module, so I just added "exec" before my "dotnet mycostommodule.dll" and now it all works fine. Thank you for the help!

prashbv commented 5 years ago

Is this issue resolved ? I am looking for solution on the same issue.

Thanks

mortslhawmit commented 5 years ago

@prashbv It is solved for me lite i said i had a script that i ran before starting the module that led having multiple processes, so i changed my script and got it to work.

Azure / iotedge