I am referring to the https://github.com/Azure/azure-iot-sdk-node/blob/master/device/samples/simple_sample_module_method.js
link. This is my app.js:
'use strict';
var Transport = require('azure-iot-device-mqtt').Mqtt;
var Client = require('azure-iot-device').ModuleClient;
var Message = require('azure-iot-device').Message;
Client.fromEnvironment(Transport, function (err, client)
{
if (err)
{
throw err;
}
else
{
client.on('error', function (err)
{
throw err;
});
// connect to the Edge instance
client.open(function (err)
{
if (err)
{
throw err;
} else
{
console.log('IoT Hub module client initialized');
// Act on input messages to the module.
client.on('inputMessage', function (inputName, msg)
{
pipeMessage(client, inputName, msg);
});
client.onMethod('getdevices', function(request,response)
{
console.log('getdevices called');
if(request.payload)
{
console.log('Payload:');
console.dir(request.payload);
}
var responseBody =
{
message: 'list of all devices.'
};
response.send(200, responseBody, function(err)
{
if (err)
{
console.log('failed sending method response: ' + err);
}
else
{
console.log('successfully sent method response');
}
});
});
}
});
}
});
// This function just pipes the messages without any change.
function pipeMessage(client, inputName, msg) {
client.complete(msg, printResultFor('Receiving message'));
if (inputName === 'input1') {
var message = msg.getBytes().toString('utf8');
if (message) {
var outputMsg = new Message(message);
client.sendOutputEvent('output1', outputMsg, printResultFor('Sending received message'));
}
}
}
// Helper function to print results in the console
function printResultFor(op) {
return function printResult(err, res) {
if (err) {
console.log(op + ' error: ' + err.toString());
}
if (res) {
console.log(op + ' status: ' + res.constructor.name);
}
};
}
The docker images for the same is: gaurav28/nodedb:0.0.1-arm32v7
running on Raspbian Stretch Raspberry pi 3 Model B+
Whenever I try to invoke my function, I get the same response
pi@raspberrypi:~/Vanke/EdgeSolution/config $ cat deployment.arm32v7.json
{
"modulesContent": {
"$edgeAgent": {
"properties.desired": {
"schemaVersion": "1.0",
"runtime": {
"type": "docker",
"settings": {
"minDockerVersion": "v1.25",
"loggingOptions": "",
"registryCredentials": {
"docker": {
"username": "$CONTAINER_REGISTRY_USERNAME_docker",
"password": "$CONTAINER_REGISTRY_PASSWORD_docker",
"address": "docker.io"
}
}
}
},
"systemModules": {
"edgeAgent": {
"type": "docker",
"settings": {
"image": "mcr.microsoft.com/azureiotedge-agent:1.0",
"createOptions": "{}"
}
},
"edgeHub": {
"type": "docker",
"status": "running",
"restartPolicy": "always",
"settings": {
"image": "mcr.microsoft.com/azureiotedge-hub:1.0",
"createOptions": "{\"HostConfig\":{\"PortBindings\":{\"5671/tcp\":[{\"HostPort\":\"5671\"}],\"8883/tcp\":[{\"HostPort\":\"8883\"}],\"443/tcp\":[{\"HostPort\":\"443\"}]}}}"
}
}
},
"modules": {
"nodedb": {
"version": "1.0",
"type": "docker",
"status": "running",
"restartPolicy": "always",
"settings": {
"image": "gaurav28/nodedb:0.0.1-arm32v7",
"createOptions": "{}"
}
}
}
}
},
"$edgeHub": {
"properties.desired": {
"schemaVersion": "1.0",
"routes": {
"nodedbToIoTHub": "FROM /messages/modules/nodedb/outputs/* INTO $upstream"
},
"storeAndForwardConfiguration": {
"timeToLiveSecs": 7200
}
}
}
}
}
pi@raspberrypi:~ $ sudo iotedge list
NAME STATUS DESCRIPTION CONFIG
edgeAgent running Up an hour mcr.microsoft.com/azureiotedge-agent:1.0
nodedb running Up an hour gaurav28/nodedb:0.0.1-arm32v7
edgeHub running Up 7 minutes mcr.microsoft.com/azureiotedge-hub:1.0
pi@raspberrypi:~ $
pi@raspberrypi:~ $ sudo iotedge logs -f nodedb
IoT Hub module client initialized
2019-03-18 16:42:39.741 +00:00 [INF] - Obtained edge hub config patch update from module twin
2019-03-18 16:42:40.065 +00:00 [INF] - Updating edge hub configuration
2019-03-18 16:42:50.654 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-03-18 16:42:50.655 +00:00 [INF] - nodedbToIoTHub: FROM /messages/modules/nodedb/outputs/* INTO $upstream
2019-03-18 16:42:50.668 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-03-18 16:42:50.669 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-03-18 16:43:12.859 +00:00 [INF] - Closing link Events for raspberrypipune/tempSensor
2019-03-18 16:43:13.006 +00:00 [INF] - Setting proxy inactive for raspberrypipune/tempSensor.
2019-03-18 16:43:13.053 +00:00 [INF] - Device connection removed for device raspberrypipune/tempSensor
2019-03-18 16:43:13.238 +00:00 [INF] - Remove device connection for device raspberrypipune/tempSensor
2019-03-18 16:43:17.279 +00:00 [INF] - Reauthenticating connected clients
2019-03-18 16:45:56.925 +00:00 [INF] - Termination requested, initiating shutdown.
2019-03-18 16:45:56.952 +00:00 [INF] - Stopping the protocol heads...
2019-03-18 16:45:57.028 +00:00 [INF] - Closing protocol heads - (MQTT, AMQP, HTTP)
2019-03-18 16:45:57.107 +00:00 [INF] - Stopping
2019-03-18 16:45:57.360 +00:00 [INF] - Closing HTTP head
2019-03-18 16:45:58.577 +00:00 [INF] - Waiting for cleanup to finish
2019-03-18 16:45:58.693 +00:00 [INF] - Closed HTTP head
[2019-03-18 16:46:34 +00:00]: Starting Edge Hub
[03/18/2019 04:46:38.752 PM] Edge Hub Main()
[2019-03-18 16:47:27 +00:00]: Starting Edge Hub
[03/18/2019 04:47:28.434 PM] Edge Hub Main()
[03/18/2019 04:47:46.888 PM] Found intermediate certificates: [CN=iotedged workload ca:06/11/2019 13:04:41],[CN=Test Edge Device CA:06/11/2019 13:04:41],[CN=Test Edge Owner CA:06/11/2019 13:04:41]
2019-03-18 16:48:23.413 +00:00 [INF] - Created persistent store at /tmp/edgeHub
2019-03-18 16:48:24.742 +00:00 [INF] - Starting Edge Hub
2019-03-18 16:48:24.745 +00:00 [INF] -
โโโโโโ โโโโโโโโโโโ โโโโโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโ โโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโ โโโโโโโโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโ
โโโโโโโโโโโโ โโโ โโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโ
โโโ โโโโโโโ โโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
2019-03-18 16:48:24.759 +00:00 [INF] - Version - 1.0.6.19913336 (8288bc9bd6f6e15295fea506cd3f99d7f6347a6a)
2019-03-18 16:48:24.790 +00:00 [INF] - Loaded server certificate with expiration date of "2019-06-11T13:04:41.0000000+00:00"
2019-03-18 16:48:34.750 +00:00 [INF] - Created new message store
2019-03-18 16:48:34.750 +00:00 [INF] - Started task to cleanup processed and stale messages
2019-03-18 16:48:38.858 +00:00 [INF] - Created device scope identities cache
2019-03-18 16:48:38.946 +00:00 [INF] - Starting refresh of device scope identities cache
2019-03-18 16:48:39.284 +00:00 [INF] - Initialized twin manager v1.
2019-03-18 16:48:39.412 +00:00 [INF] - Initializing configuration
2019-03-18 16:48:39.746 +00:00 [INF] - New device connection for device raspberrypipune/$edgeHub
2019-03-18 16:48:40.396 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberrypipune/$edgeHub via AMQP...
2019-03-18 16:48:48.509 +00:00 [INF] - Exiting disconnected state
2019-03-18 16:48:48.538 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2019-03-18 16:48:48.563 +00:00 [INF] - Processing subscriptions for client raspberrypipune/$edgeHub.
2019-03-18 16:48:48.621 +00:00 [INF] - Cloud connection for raspberrypipune/$edgeHub is True
2019-03-18 16:48:48.690 +00:00 [INF] - Connection status for raspberrypipune/$edgeHub changed to ConnectionEstablished
2019-03-18 16:48:48.741 +00:00 [INF] - Entering connected state
2019-03-18 16:48:48.786 +00:00 [INF] - Created cloud proxy for client raspberrypipune/$edgeHub via AMQP, with client operation timeout 20 seconds.
2019-03-18 16:48:48.864 +00:00 [INF] - Initialized cloud proxy 5e535712-1107-41e5-8bd9-1b05307d7a49 for raspberrypipune/$edgeHub
2019-03-18 16:48:48.902 +00:00 [INF] - Created cloud connection for client raspberrypipune/$edgeHub
2019-03-18 16:48:49.139 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberrypipune/$edgeHub.
2019-03-18 16:48:49.263 +00:00 [INF] - Processing subscription Methods for client raspberrypipune/$edgeHub.
2019-03-18 16:48:50.445 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberrypipune/$edgeHub.
2019-03-18 16:48:50.476 +00:00 [INF] - Processing subscription Methods for client raspberrypipune/$edgeHub.
2019-03-18 16:48:56.031 +00:00 [INF] - Obtained edge hub config from module twin
2019-03-18 16:48:57.957 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-03-18 16:48:57.968 +00:00 [INF] - nodedbToIoTHub: FROM /messages/modules/nodedb/outputs/* INTO $upstream
2019-03-18 16:48:57.989 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-03-18 16:48:57.993 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-03-18 16:48:57.998 +00:00 [INF] - Initialized edge hub configuration
2019-03-18 16:48:58.167 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2019-03-18 16:48:59.161 +00:00 [INF] - Scheduling server certificate renewal for "2019-06-11T13:02:11.0010112Z".
2019-03-18 16:48:59.180 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2019-03-18 16:48:59.231 +00:00 [INF] - Starting MQTT head
2019-03-18 16:49:00.051 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2019-03-18 16:49:01.406 +00:00 [INF] - Starting AMQP head
2019-03-18 16:49:01.640 +00:00 [INF] - Started MQTT head
2019-03-18 16:49:02.766 +00:00 [INF] - Started AMQP head
2019-03-18 16:49:02.800 +00:00 [INF] - Starting HTTP head
2019-03-18 16:49:14.775 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2019-03-18 16:49:15.789 +00:00 [INF] - Client raspberrypipune/nodedb in device scope authenticated locally.
2019-03-18 16:49:15.822 +00:00 [INF] - Successfully generated identity for clientId raspberrypipune/nodedb and username vanke.azure-devices.net/raspberrypipune/nodedb/?api-version=2018-06-30&DeviceClientType=azure-iot-device%2F1.9.4%20(node%20v8.15.1%3B%20Debian%209.8%3B%20arm)
2019-03-18 16:49:15.870 +00:00 [INF] - ClientAuthenticated, raspberrypipune/nodedb, 7707d220
2019-03-18 16:49:16.715 +00:00 [INF] - New device connection for device raspberrypipune/nodedb
2019-03-18 16:49:16.878 +00:00 [INF] - Bind device proxy for device raspberrypipune/nodedb
2019-03-18 16:49:16.889 +00:00 [INF] - Binding message channel for device Id raspberrypipune/nodedb
2019-03-18 16:49:17.202 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberrypipune/nodedb via AMQP...
2019-03-18 16:49:18.130 +00:00 [INF] - Cloud connection for raspberrypipune/nodedb is True
2019-03-18 16:49:18.131 +00:00 [INF] - Connection status for raspberrypipune/nodedb changed to ConnectionEstablished
2019-03-18 16:49:18.157 +00:00 [INF] - Created cloud proxy for client raspberrypipune/nodedb via AMQP, with client operation timeout 20 seconds.
2019-03-18 16:49:18.159 +00:00 [INF] - Initialized cloud proxy 65087063-8826-4157-b43f-d25c531b1bdc for raspberrypipune/nodedb
2019-03-18 16:49:18.163 +00:00 [INF] - Created cloud connection for client raspberrypipune/nodedb
2019-03-18 16:49:18.164 +00:00 [INF] - Processing subscription Methods for client raspberrypipune/nodedb.
2019-03-18 16:49:18.449 +00:00 [INF] - Processing subscription ModuleMessages for client raspberrypipune/nodedb.
2019-03-18 16:49:18.570 +00:00 [INF] - Set subscriptions from session state for raspberrypipune/nodedb
2019-03-18 16:49:18.630 +00:00 [INF] - Processing subscription Methods for client raspberrypipune/nodedb.
2019-03-18 16:49:18.640 +00:00 [INF] - Processing subscription ModuleMessages for client raspberrypipune/nodedb.
2019-03-18 16:49:18.645 +00:00 [INF] - Set subscriptions from session state for raspberrypipune/nodedb
2019-03-18 16:49:33.636 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2019-03-18 16:49:33.906 +00:00 [INF] - Started HTTP head
Code I am using to invoke the method:
'use strict';
var Client = require('azure-iothub').Client;
var connectionString = "Cant-reveal-my-connection-string here";
var deviceId = 'raspberrypipune';
var moduleId = 'nodedb';
var methodParams = {
methodName: 'getdevices',
payload: 'hello',
responseTimeoutInSeconds: 45 // set response timeout as 15 seconds
};
var client = Client.fromConnectionString(connectionString);
client.invokeDeviceMethod(deviceId, moduleId, methodParams, function (err, result) {
if (err) {
console.error('Failed to invoke method \'' + methodParams.methodName + '\': ' + err.message);
} else {
console.log(methodParams.methodName + ' on ' + deviceId + ':');
console.log(JSON.stringify(result, null, 2));
}
});
I am using my iothubowner connectionstring from shared access policies.
Invocation from vscode or portal isn't working either.
The response is the same as mentioned in the title:
gaurav@gaurav-VirtualBox:~/testinvoke$ node app.js
getdevices on raspberrypipune:
{
"status": 500,
"payload": null
}
Hi,
Same code is working on my machine. I followed the same steps on AMD64 with Ubuntu 16.04 and It worked just fine.
@payalgaikwad42 You are right. The issues is only for Raspberry Pi.
Tried the same deployment with AMD64 images and now it works.
@gauravagarwal28 , I have noticed this exact same issue on ARM devices using very similar code. I am suspicious that direct methods do not work in the ARM SDKs.
My experience with this issue is documented @ https://github.com/Azure/iotedge/issues/98#issuecomment-415836594
@gauravagarwal28, @toolboc -
I am not able to repro this issue on a Raspberry Pi with a C# module. I am not sure if this is a node.js SDK issue or something that is reproing only in your environment.
Will you be able to provide debug logs for EdgeHub for the repro scenario? That should tell us if EdgeHub is indeed receiving the method invocation from the cloud and handling it properly.
To get debug logs for the EdgeHub, set the environment variable RuntimeLogLevel to debug.
@varunpuranik
It will take some time to do so as I am currently occupied with other work. I will get to this after that.
@gauravagarwal28
Were you able to see the status of the modules from Azure portal? Also, did you create Azure Container Registry? It seems I couldn't find it from your deployment manifest.
Below part from your deployment manifest looks a little strange to me. Can you check?
"registryCredentials": {
"docker": {
"username": "$CONTAINER_REGISTRY_USERNAME_docker",
"password": "$CONTAINER_REGISTRY_PASSWORD_docker",
"address": "docker.io"
}
@timzhan Yes, I was able to see the status of modules on Azure portal.
It even showed as connected in VScode with green font.
Method invocations from the VS code failed too.
The deployment manifest uses my docker hub creds because I make constant changes and new deployments from docker images. Only stable images are pushed to AzureCR so that other people using the same image for deployment are not affected by this.
I don't see how using AzureCR can affect this but I (or my colleague) will definitely try this since you have recommended to do so.
Currently my colleague - @payalgaikwad42 is testing the dotnet module suggested by @varunpuranik
@gauravagarwal28 / @varunpuranik, I was able to reproduce using a node.js module and have included the EdgeHub debug logs. To rule out network issues, both devices are connected to via the same router.
Method:
1.) Install IoT Edge to an AMD64 Ubuntu 16.04 machine AND Raspberry Pi running 2018-11-13-raspbian-stretch-lite
2.) Create new IoTEdge Solution with a NodeJS module (attached as DirectMethodTest.zip)
3.) Published the AMD64 and ARM32 images to public Dockerhub @ https://hub.docker.com/r/toolboc/directmethodjs/tags
4.) Deploy included deployment.amd64.json & deployment.arm32.json to AMD64 and ARM32 devices

5.) Head to Azure portal, choose IoT Hub, select the intended Edge Deice then select DirectMethodJS module and attempt to invoke payload with following:
{ "input1": "someInput", "input2": "anotherInput"}
Results:

EdgeHub Logs AMD64 (taken after restarting IoTEdge service and invoking the payload above):
[2019-04-03 17:48:57 : Starting Edge Hub
[04/03/2019 05:48:57.756 PM] Edge Hub Main()
[04/03/2019 05:48:59.185 PM] Found intermediate certificates: [CN=iotedged workload ca:07/02/2019 14:59:47],[CN=Test Edge Device CA:07/02/2019 14:59:47],[CN=Test Edge Owner CA:07/02/2019 14:59:47]
2019-04-03 17:49:00.294 +00:00 [INF] - Created persistent store at /tmp/edgeHub
2019-04-03 17:49:00.362 +00:00 [INF] - Starting Edge Hub
2019-04-03 17:49:00.363 +00:00 [INF] -
โโโโโโ โโโโโโโโโโโ โโโโโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโ โโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโ โโโโโโโโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโ
โโโโโโโโโโโโ โโโ โโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโ
โโโ โโโโโโโ โโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
2019-04-03 17:49:00.366 +00:00 [INF] - Version - 1.0.6.19913336 (8288bc9bd6f6e15295fea506cd3f99d7f6347a6a)
2019-04-03 17:49:00.373 +00:00 [INF] - Loaded server certificate with expiration date of "2019-07-02T14:59:47.0000000+00:00"
2019-04-03 17:49:00.432 +00:00 [INF] - Created new message store
2019-04-03 17:49:00.435 +00:00 [INF] - Started task to cleanup processed and stale messages
2019-04-03 17:49:00.636 +00:00 [INF] - Created device scope identities cache
2019-04-03 17:49:00.651 +00:00 [INF] - Starting refresh of device scope identities cache
2019-04-03 17:49:00.702 +00:00 [INF] - Initialized twin manager v1.
2019-04-03 17:49:00.721 +00:00 [INF] - Initializing configuration
2019-04-03 17:49:00.784 +00:00 [INF] - New device connection for device AMD64/$edgeHub
2019-04-03 17:49:00.881 +00:00 [INF] - Attempting to connect to IoT Hub for client AMD64/$edgeHub via AMQP...
2019-04-03 17:49:02.487 +00:00 [INF] - Exiting disconnected state
2019-04-03 17:49:02.498 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2019-04-03 17:49:02.505 +00:00 [INF] - Processing subscriptions for client AMD64/$edgeHub.
2019-04-03 17:49:02.526 +00:00 [INF] - Cloud connection for AMD64/$edgeHub is True
2019-04-03 17:49:02.547 +00:00 [INF] - Connection status for AMD64/$edgeHub changed to ConnectionEstablished
2019-04-03 17:49:02.565 +00:00 [INF] - Entering connected state
2019-04-03 17:49:02.577 +00:00 [INF] - Created cloud proxy for client AMD64/$edgeHub via AMQP, with client operation timeout 20 seconds.
2019-04-03 17:49:02.598 +00:00 [INF] - Initialized cloud proxy b84a5ca7-c82e-474a-8e9a-fe9bf5450930 for AMD64/$edgeHub
2019-04-03 17:49:02.606 +00:00 [INF] - Created cloud connection for client AMD64/$edgeHub
2019-04-03 17:49:02.661 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client AMD64/$edgeHub.
2019-04-03 17:49:02.714 +00:00 [INF] - Processing subscription Methods for client AMD64/$edgeHub.
2019-04-03 17:49:03.110 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client AMD64/$edgeHub.
2019-04-03 17:49:03.111 +00:00 [INF] - Processing subscription Methods for client AMD64/$edgeHub.
2019-04-03 17:49:05.453 +00:00 [INF] - Obtained edge hub config from module twin
2019-04-03 17:49:05.508 +00:00 [INF] - No routes set in the edge hub
2019-04-03 17:49:05.510 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-04-03 17:49:05.511 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-04-03 17:49:05.512 +00:00 [INF] - Initialized edge hub configuration
2019-04-03 17:49:05.565 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2019-04-03 17:49:05.815 +00:00 [INF] - Scheduling server certificate renewal for "2019-07-02T14:57:17.0002866Z".
2019-04-03 17:49:05.821 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2019-04-03 17:49:05.836 +00:00 [INF] - Starting MQTT head
2019-04-03 17:49:06.038 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2019-04-03 17:49:06.248 +00:00 [INF] - Starting AMQP head
2019-04-03 17:49:06.295 +00:00 [INF] - Started MQTT head
2019-04-03 17:49:06.375 +00:00 [INF] - Started AMQP head
2019-04-03 17:49:06.379 +00:00 [INF] - Starting HTTP head
2019-04-03 17:49:06.508 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2019-04-03 17:49:06.981 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2019-04-03 17:49:07.017 +00:00 [INF] - Started HTTP head
2019-04-03 17:49:15.037 +00:00 [INF] - Client AMD64/DirectMethodJS in device scope authenticated locally.
2019-04-03 17:49:15.040 +00:00 [INF] - Successfully generated identity for clientId AMD64/DirectMethodJS and username Johnny5IoTEdge.azure-devices.net/AMD64/DirectMethodJS/?api-version=2018-06-30&DeviceClientType=azure-iot-device%2F1.9.4%20(node%20v8.12.0%3B%20Raspbian%20undefined%3B%20x64)
2019-04-03 17:49:15.043 +00:00 [INF] - ClientAuthenticated, AMD64/DirectMethodJS, 72bbedde
2019-04-03 17:49:15.108 +00:00 [INF] - New device connection for device AMD64/DirectMethodJS
2019-04-03 17:49:15.125 +00:00 [INF] - Bind device proxy for device AMD64/DirectMethodJS
2019-04-03 17:49:15.126 +00:00 [INF] - Binding message channel for device Id AMD64/DirectMethodJS
2019-04-03 17:49:15.163 +00:00 [INF] - Attempting to connect to IoT Hub for client AMD64/DirectMethodJS via AMQP...
2019-04-03 17:49:15.301 +00:00 [INF] - Cloud connection for AMD64/DirectMethodJS is True
2019-04-03 17:49:15.301 +00:00 [INF] - Connection status for AMD64/DirectMethodJS changed to ConnectionEstablished
2019-04-03 17:49:15.301 +00:00 [INF] - Created cloud proxy for client AMD64/DirectMethodJS via AMQP, with client operation timeout 20 seconds.
2019-04-03 17:49:15.302 +00:00 [INF] - Initialized cloud proxy bf810d34-e097-4dda-b3ba-f9bbeef79a99 for AMD64/DirectMethodJS
2019-04-03 17:49:15.302 +00:00 [INF] - Created cloud connection for client AMD64/DirectMethodJS
2019-04-03 17:49:15.302 +00:00 [INF] - Processing subscription Methods for client AMD64/DirectMethodJS.
2019-04-03 17:49:15.427 +00:00 [INF] - Processing subscription ModuleMessages for client AMD64/DirectMethodJS.
2019-04-03 17:49:15.439 +00:00 [INF] - Set subscriptions from session state for AMD64/DirectMethodJS
2019-04-03 17:49:15.445 +00:00 [INF] - Processing subscription Methods for client AMD64/DirectMethodJS.
2019-04-03 17:49:15.446 +00:00 [INF] - Processing subscription ModuleMessages for client AMD64/DirectMethodJS.
2019-04-03 17:49:15.446 +00:00 [INF] - Set subscriptions from session state for AMD64/DirectMethodJS
2019-04-03 17:54:05.574 +00:00 [INF] - Reauthenticating connected clients
EdgeHub Logs ARM (taken after restarting IoTEdge service and invoking the payload above):
[2019-04-03 17:51:23 +00:00]: Starting Edge Hub
[04/03/2019 05:51:23.735 PM] Edge Hub Main()
2019-04-03 17:51:25.130 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to CreateServerCertificateAsync
2019-04-03 17:51:26.474 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:26.496 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:26.529 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/certificate/server?api-version=2018-06-28
2019-04-03 17:51:28.325 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received Created
2019-04-03 17:51:28.724 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for CreateServerCertificateAsync
[04/03/2019 05:51:30.553 PM] Found intermediate certificates: [CN=iotedged workload ca:07/02/2019 15:04:10],[CN=Test Edge Device CA:07/02/2019 15:04:10],[CN=Test Edge Owner CA:07/02/2019 15:04:10]
2019-04-03 17:51:30.578 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to TrustBundleAsync
2019-04-03 17:51:30.625 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:30.626 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:30.627 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/trust-bundle?api-version=2018-06-28
2019-04-03 17:51:30.631 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:30.663 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for TrustBundleAsync
2019-04-03 17:51:36.276 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Service.Modules.RoutingModule] - Created persistent store at /tmp/edgeHub
2019-04-03 17:51:36.573 +00:00 [INF] [EdgeHub] - Starting Edge Hub
2019-04-03 17:51:36.576 +00:00 [INF] [EdgeHub] -
โโโโโโ โโโโโโโโโโโ โโโโโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโ โโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโ โโโโโโโโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโ
โโโโโโโโโโโโ โโโ โโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโ
โโโ โโโโโโโ โโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
2019-04-03 17:51:36.584 +00:00 [INF] [EdgeHub] - Version - 1.0.6.19913336 (8288bc9bd6f6e15295fea506cd3f99d7f6347a6a)
2019-04-03 17:51:36.601 +00:00 [INF] [EdgeHub] - Loaded server certificate with expiration date of "2019-07-02T15:04:10.0000000+00:00"
2019-04-03 17:51:36.634 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt
2019-04-03 17:51:36.721 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Created new message store
2019-04-03 17:51:36.723 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages
2019-04-03 17:51:36.732 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.733 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.733 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/decrypt?api-version=2018-06-28
2019-04-03 17:51:36.757 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:36.796 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt
2019-04-03 17:51:36.970 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt
2019-04-03 17:51:36.971 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.972 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.973 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/decrypt?api-version=2018-06-28
2019-04-03 17:51:36.990 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:36.991 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt
2019-04-03 17:51:36.995 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt
2019-04-03 17:51:36.996 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.996 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:36.997 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/decrypt?api-version=2018-06-28
2019-04-03 17:51:37.022 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:37.023 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt
2019-04-03 17:51:37.024 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt
2019-04-03 17:51:37.024 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:37.025 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:37.025 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/decrypt?api-version=2018-06-28
2019-04-03 17:51:37.053 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:37.055 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt
2019-04-03 17:51:37.095 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Created device scope identities cache
2019-04-03 17:51:37.097 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Initializing device scope identities cache refresh task to run every 60 minutes.
2019-04-03 17:51:37.132 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Starting refresh of device scope identities cache
2019-04-03 17:51:37.140 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Created iterator to iterate all service identities in the scope of this IoT Edge device
2019-04-03 17:51:37.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
2019-04-03 17:51:37.399 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:37.400 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:37.400 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/sign?api-version=2018-06-28
2019-04-03 17:51:37.429 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:37.509 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Initialized twin manager v1.
2019-04-03 17:51:37.546 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - ConnectionManager provided
2019-04-03 17:51:37.566 +00:00 [INF] [EdgeHub] - Initializing configuration
2019-04-03 17:51:37.711 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device ARM32/$edgeHub
2019-04-03 17:51:37.742 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription DesiredPropertyUpdates for client ARM32/$edgeHub.
2019-04-03 17:51:37.912 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for ARM32/$edgeHub
2019-04-03 17:51:37.949 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Creating cloud connection for client ARM32/$edgeHub using EdgeHub credentials
2019-04-03 17:51:38.004 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client ARM32/$edgeHub via AMQP...
2019-04-03 17:51:39.057 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Got valid device scope result
2019-04-03 17:51:39.078 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result with 1 devices, 3 modules and null continuation link
2019-04-03 17:51:39.306 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt
2019-04-03 17:51:39.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription Methods for client ARM32/$edgeHub.
2019-04-03 17:51:39.394 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.394 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.396 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/encrypt?api-version=2018-06-28
2019-04-03 17:51:39.415 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:39.434 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt
2019-04-03 17:51:39.564 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - ARM32 is in device scope, adding to cache.
2019-04-03 17:51:39.572 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt
2019-04-03 17:51:39.573 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.575 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.576 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/encrypt?api-version=2018-06-28
2019-04-03 17:51:39.598 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:39.599 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt
2019-04-03 17:51:39.633 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - ARM32/$edgeAgent is in device scope, adding to cache.
2019-04-03 17:51:39.634 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt
2019-04-03 17:51:39.635 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.636 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.638 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/encrypt?api-version=2018-06-28
2019-04-03 17:51:39.667 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:39.668 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt
2019-04-03 17:51:39.670 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - ARM32/$edgeHub is in device scope, adding to cache.
2019-04-03 17:51:39.671 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt
2019-04-03 17:51:39.672 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.674 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:39.674 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/encrypt?api-version=2018-06-28
2019-04-03 17:51:39.707 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:39.707 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt
2019-04-03 17:51:39.708 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - ARM32/DirectMethodJS is in device scope, adding to cache.
2019-04-03 17:51:39.726 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Done refreshing device scope identities cache. Waiting for 60 minutes.
2019-04-03 17:51:40.546 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:40.547 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:40.547 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/sign?api-version=2018-06-28
2019-04-03 17:51:40.565 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:41.859 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok for ARM32/$edgeHub
2019-04-03 17:51:41.942 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:41.993 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Exiting disconnected state
2019-04-03 17:51:42.009 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Device connected to cloud, processing subscriptions for connected clients.
2019-04-03 17:51:42.023 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscriptions for client ARM32/$edgeHub.
2019-04-03 17:51:42.056 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Cloud connection for ARM32/$edgeHub is True
2019-04-03 17:51:42.089 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Connection status for ARM32/$edgeHub changed to ConnectionEstablished
2019-04-03 17:51:42.092 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Invoking cloud connection established event for ARM32/$edgeHub
2019-04-03 17:51:42.098 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for ARM32/$edgeHub
2019-04-03 17:51:42.116 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2019-04-03 17:51:42.130 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:42.134 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device ARM32/$edgeHub
2019-04-03 17:51:42.144 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud proxy for client ARM32/$edgeHub via AMQP, with client operation timeout 20 seconds.
2019-04-03 17:51:42.176 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Initialized cloud proxy f32f1839-8681-4d24-b4d5-4261a600443d for ARM32/$edgeHub
2019-04-03 17:51:42.192 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client ARM32/$edgeHub
2019-04-03 17:51:42.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:42.333 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription DesiredPropertyUpdates for client ARM32/$edgeHub.
2019-04-03 17:51:42.423 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:42.424 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription Methods for client ARM32/$edgeHub.
2019-04-03 17:51:42.721 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:42.800 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:42.851 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:42.866 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:42.872 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:42.889 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client ARM32/$edgeHub.
2019-04-03 17:51:42.916 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription DesiredPropertyUpdates for client ARM32/$edgeHub.
2019-04-03 17:51:42.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:42.931 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription Methods for client ARM32/$edgeHub.
2019-04-03 17:51:42.932 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:42.933 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:42.935 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client ARM32/$edgeHub.
2019-04-03 17:51:43.159 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:43.159 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:43.167 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device ARM32/$edgeHub
2019-04-03 17:51:43.170 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for ARM32/$edgeHub and reported properties version 0
2019-04-03 17:51:43.424 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for ARM32/$edgeHub at reported property version 16 cloudVerified True
2019-04-03 17:51:43.473 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Initialized connection for ARM32/$edgeHub
2019-04-03 17:51:43.516 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:43.533 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for ARM32/$edgeHub on ConnectionEstablished
2019-04-03 17:51:43.609 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:43.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:43.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:43.914 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device ARM32/$edgeHub
2019-04-03 17:51:43.940 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for ARM32/$edgeHub from cloud at desired version 6 reported version 19
2019-04-03 17:51:44.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updating cached twin for ARM32/$edgeHub from desired version 6 to 6 and reported version 16 to 19
2019-04-03 17:51:44.026 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Sending desired property update for ARM32/$edgeHub old desired version 6 cloud desired version 6
2019-04-03 17:51:44.098 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:44.099 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:44.099 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device ARM32/$edgeHub
2019-04-03 17:51:44.100 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for ARM32/$edgeHub from cloud at desired version 6 reported version 19
2019-04-03 17:51:44.124 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for ARM32/$edgeHub at higher or equal desired version 6 compared to cloud 6 or reported version 19 compared to cloud 19
2019-04-03 17:51:44.253 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:45.252 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:45.253 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:45.253 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device ARM32/$edgeHub
2019-04-03 17:51:45.255 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for ARM32/$edgeHub and reported properties version 0
2019-04-03 17:51:45.264 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for ARM32/$edgeHub at reported property version 19 cloudVerified True
2019-04-03 17:51:45.269 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Obtained edge hub config from module twin
2019-04-03 17:51:45.365 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - No routes set in the edge hub
2019-04-03 17:51:45.372 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Updated message store TTL to 7200 seconds
2019-04-03 17:51:45.374 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Updated the edge hub store and forward configuration
2019-04-03 17:51:45.377 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Initialized edge hub configuration
2019-04-03 17:51:45.455 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Starting timer to authenticate connections with a period of 300 seconds
2019-04-03 17:51:45.478 +00:00 [DBG] [EdgeHub] - Waiting on shutdown handler to trigger
2019-04-03 17:51:45.592 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.numHeapArenas: 8
2019-04-03 17:51:45.593 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.numDirectArenas: 8
2019-04-03 17:51:45.593 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.pageSize: 8192
2019-04-03 17:51:45.593 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxOrder: 11
2019-04-03 17:51:45.594 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.chunkSize: 16777216
2019-04-03 17:51:45.594 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.tinyCacheSize: 512
2019-04-03 17:51:45.594 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.smallCacheSize: 256
2019-04-03 17:51:45.595 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.normalCacheSize: 64
2019-04-03 17:51:45.595 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2019-04-03 17:51:45.596 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.cacheTrimInterval: 8192
2019-04-03 17:51:45.608 +00:00 [DBG] [DotNetty.Common.Internal.PlatformDependent] - -Dio.netty.noPreferDirect: True
2019-04-03 17:51:45.966 +00:00 [INF] [EdgeHub] - Scheduling server certificate renewal for "2019-07-02T15:01:40.0006072Z".
2019-04-03 17:51:45.966 +00:00 [DBG] [EdgeHub] - Scheduling server certificate renewal timer for "2019-04-28T14:23:09.6134812Z" (clamped to Int32.MaxValue).
2019-04-03 17:51:45.977 +00:00 [INF] [EdgeHub] - Starting protocol heads - (MQTT, AMQP, HTTP)
2019-04-03 17:51:46.004 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Starting MQTT head
2019-04-03 17:51:46.771 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Initializing TLS endpoint on port 8883 for MQTT head.
2019-04-03 17:51:46.841 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.processId: 2497597 (auto-detected)
2019-04-03 17:51:46.907 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.machineId: 02:42:AC:FF:FE:12:00:02 (auto-detected)
2019-04-03 17:51:46.917 +00:00 [DBG] [DotNetty.Buffers.ByteBufferUtil] - -Dio.netty.allocator.type: pooled
2019-04-03 17:51:46.937 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - -Dio.netty.leakDetection.level: simple
2019-04-03 17:51:46.938 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - -Dio.netty.leakDetection.targetRecords: 4
2019-04-03 17:51:47.119 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Amqp.AmqpProtocolHead] - Starting AMQP head
2019-04-03 17:51:47.162 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.AmqpProtocolHead] - WebSockets listener registered.
2019-04-03 17:51:47.326 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Started MQTT head
2019-04-03 17:51:47.769 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Amqp.AmqpProtocolHead] - Started AMQP head
2019-04-03 17:51:47.784 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Http.HttpProtocolHead] - Starting HTTP head
2019-04-03 17:51:47.921 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Hosting starting
2019-04-03 17:51:48.312 +00:00 [DBG] [DotNetty.Buffers.AbstractByteBuffer] - -Dio.netty.buffer.bytebuf.checkAccessible: True
2019-04-03 17:51:48.386 +00:00 [INF] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2019-04-03 17:51:48.474 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository] - Reading data from file '"/home/edgehubuser/.aspnet/DataProtection-Keys/key-40b41537-bfa4-40b3-a16a-3904b10a9430.xml"'.
2019-04-03 17:51:48.540 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] - Found key {40b41537-bfa4-40b3-a16a-3904b10a9430}.
2019-04-03 17:51:48.639 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver] - Considering key {40b41537-bfa4-40b3-a16a-3904b10a9430} with expiration date 2019-07-02 17:41:47Z as default key.
2019-04-03 17:51:48.739 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.TypeForwardingActivator] - Forwarded activator type request from "Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=2.1.1.0, Culture=neutral, PublicKeyToken=adb9793829ddae60" to "Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60"
2019-04-03 17:51:48.792 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory] - Using managed symmetric algorithm '"System.Security.Cryptography.Aes"'.
2019-04-03 17:51:48.798 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory] - Using managed keyed hash algorithm '"System.Security.Cryptography.HMACSHA256"'.
2019-04-03 17:51:48.887 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider] - Using key {40b41537-bfa4-40b3-a16a-3904b10a9430} as the default key.
2019-04-03 17:51:48.900 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.Internal.DataProtectionStartupFilter] - Key ring with default key {40b41537-bfa4-40b3-a16a-3904b10a9430} was loaded during application startup.
2019-04-03 17:51:49.178 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcJsonOptions] - Compatibility switch "AllowInputFormatterExceptionMessages" in type "MvcJsonOptions" is using default value False
2019-04-03 17:51:49.209 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for ARM32/DirectMethodJS
2019-04-03 17:51:49.287 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client ARM32/DirectMethodJS in device scope authenticated locally.
2019-04-03 17:51:49.295 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client ARM32/DirectMethodJS authenticated successfully
2019-04-03 17:51:49.301 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceIdentityProvider] - Successfully generated identity for clientId ARM32/DirectMethodJS and username Johnny5IoTEdge.azure-devices.net/ARM32/DirectMethodJS/?api-version=2018-06-30&DeviceClientType=azure-iot-device%2F1.9.4%20(node%20v8.15.1%3B%20Debian%209.8%3B%20arm)
2019-04-03 17:51:49.318 +00:00 [INF] [ProtocolGateway] - ClientAuthenticated, ARM32/DirectMethodJS, 26955a66
2019-04-03 17:51:49.399 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowCombiningAuthorizeFilters" in type "MvcOptions" is using default value False
2019-04-03 17:51:49.399 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowBindingHeaderValuesToNonStringModelTypes" in type "MvcOptions" is using default value False
2019-04-03 17:51:49.400 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowValidatingTopLevelNodes" in type "MvcOptions" is using default value False
2019-04-03 17:51:49.408 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "InputFormatterExceptionPolicy" in type "MvcOptions" is using default value AllExceptions
2019-04-03 17:51:49.408 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "SuppressBindingUndefinedValueToEnumType" in type "MvcOptions" is using default value False
2019-04-03 17:51:49.586 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device ARM32/DirectMethodJS
2019-04-03 17:51:49.589 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.RazorPages.RazorPagesOptions] - Compatibility switch "AllowAreas" in type "RazorPagesOptions" is using default value False
2019-04-03 17:51:49.590 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.RazorPages.RazorPagesOptions] - Compatibility switch "AllowMappingHeadRequestsToGetHandler" in type "RazorPagesOptions" is using default value False
2019-04-03 17:51:49.608 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device ARM32/DirectMethodJS connection status to Connected
2019-04-03 17:51:49.640 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/$edgeHub
2019-04-03 17:51:49.660 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device ARM32/DirectMethodJS
2019-04-03 17:51:49.665 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id ARM32/DirectMethodJS
2019-04-03 17:51:49.799 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription devices/ARM32/modules/DirectMethodJS/inputs/# for client ARM32/DirectMethodJS.
2019-04-03 17:51:49.803 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription ModuleMessages for client ARM32/DirectMethodJS.
2019-04-03 17:51:49.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for ARM32/DirectMethodJS
2019-04-03 17:51:49.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Creating cloud connection for client ARM32/DirectMethodJS using EdgeHub credentials
2019-04-03 17:51:49.806 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client ARM32/DirectMethodJS via AMQP...
2019-04-03 17:51:49.811 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2019-04-03 17:51:49.813 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2019-04-03 17:51:49.814 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636898994499534328/sign?api-version=2018-06-28
2019-04-03 17:51:49.835 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK
2019-04-03 17:51:49.986 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok for ARM32/DirectMethodJS
2019-04-03 17:51:49.991 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:49.992 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Cloud connection for ARM32/DirectMethodJS is True
2019-04-03 17:51:49.992 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Connection status for ARM32/DirectMethodJS changed to ConnectionEstablished
2019-04-03 17:51:49.992 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Invoking cloud connection established event for ARM32/DirectMethodJS
2019-04-03 17:51:49.993 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for ARM32/DirectMethodJS
2019-04-03 17:51:49.993 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded for ARM32/DirectMethodJS
2019-04-03 17:51:49.994 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud proxy for client ARM32/DirectMethodJS via AMQP, with client operation timeout 20 seconds.
2019-04-03 17:51:49.994 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Initialized cloud proxy 2c2b764a-9871-49ca-8cb6-c7c61cf83769 for ARM32/DirectMethodJS
2019-04-03 17:51:49.995 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client ARM32/DirectMethodJS
2019-04-03 17:51:49.995 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/DirectMethodJS
2019-04-03 17:51:49.996 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription ModuleMessages for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.002 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device ARM32/DirectMethodJS
2019-04-03 17:51:50.005 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/methods/POST/# for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.005 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription Methods for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.006 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/DirectMethodJS
2019-04-03 17:51:50.006 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription Methods for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.035 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:50.036 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for ARM32/$edgeHub
2019-04-03 17:51:50.036 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device ARM32/$edgeHub
2019-04-03 17:51:50.036 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for ARM32/$edgeHub and reported properties version 0
2019-04-03 17:51:50.043 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for ARM32/$edgeHub at reported property version 19 cloudVerified True
2019-04-03 17:51:50.046 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/DirectMethodJS
2019-04-03 17:51:50.047 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for ARM32/DirectMethodJS on ConnectionEstablished
2019-04-03 17:51:50.049 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcViewOptions] - Compatibility switch "SuppressTempDataAttributePrefix" in type "MvcViewOptions" is using default value False
2019-04-03 17:51:50.180 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:50.181 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for ARM32/DirectMethodJS
2019-04-03 17:51:50.181 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.222 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for ARM32/DirectMethodJS
2019-04-03 17:51:50.247 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription devices/ARM32/modules/DirectMethodJS/inputs/# for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.248 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription ModuleMessages for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.251 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/DirectMethodJS
2019-04-03 17:51:50.251 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription ModuleMessages for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.251 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/methods/POST/# for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.252 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription Methods for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.252 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device ARM32/DirectMethodJS
2019-04-03 17:51:50.252 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Processing subscription Methods for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.252 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:50.253 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for ARM32/DirectMethodJS
2019-04-03 17:51:50.253 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client ARM32/DirectMethodJS.
2019-04-03 17:51:50.262 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for ARM32/DirectMethodJS
2019-04-03 17:51:50.316 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2019-04-03 17:51:50.317 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for ARM32/DirectMethodJS
2019-04-03 17:51:50.317 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device ARM32/DirectMethodJS
2019-04-03 17:51:50.317 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for ARM32/DirectMethodJS from cloud at desired version 2 reported version 1
2019-04-03 17:51:50.318 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for ARM32/DirectMethodJS at higher or equal desired version 2 compared to cloud 2 or reported version 1 compared to cloud 1
2019-04-03 17:51:50.476 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory] - Registered model binder providers, in the following order: ["Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexTypeModelBinderProvider"]
2019-04-03 17:51:50.852 +00:00 [WRN] [Microsoft.AspNetCore.Server.Kestrel] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2019-04-03 17:51:50.984 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Hosting started
2019-04-03 17:51:50.984 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Loaded hosting startup assembly "Microsoft.Azure.Devices.Edge.Hub.Service"
2019-04-03 17:51:50.987 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Http.HttpProtocolHead] - Started HTTP head
2019-04-03 17:53:01.204 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Received call method from cloud for device ARM32/DirectMethodJS
2019-04-03 17:53:01.212 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received method invoke call from ARM32/DirectMethodJS for ARM32/DirectMethodJS with correlation ID eb5bea77-c3b1-4ec4-bc9c-a4aa77076b45
2019-04-03 17:53:01.220 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Invoking method getdevices on client ARM32/DirectMethodJS.
@toolboc Can you please test the same again by using the Azure Container Registry for the images instead of Docker hub?
This could also confirm the test suggested by @timzhan
@varunpuranik
I have created and deployed the dotnet module on raspberry pi 3 and I am facing the same issue while invoking the direct method on that module.
Given below folder contains all the required files for the deployement of dotnet module.
when I invoke the direct method on dotnet module the response is the same as it gives for node module:
$ dotnet run
IoT Hub Quickstarts #2 - Back-end application.
Response status: 500, payload:
null
the edgeHub logs are:
2019-04-05 10:19:27.624 +00:00 [INF] - Starting Edge Hub
2019-04-05 10:19:27.628 +00:00 [INF] -
โโโโโโ โโโโโโโโโโโ โโโโโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโโโโโโ โโโโโ โโโ โโโโโโโโโโโโโโโโโ
โโโ โโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโ
โโโ โโโโโโโโโโโ โโโโโโโ โโโ โโโโโโโโโโโ
โโโ โโโโโโโ โโโโโโโโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
โโโโโโโโโโโโโโโโโโโโโ โโโโโโโโโโโโโโโโโโโโโโโโ โโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโโ
โโโโโโ โโโ โโโ โโโโโโ โโโ โโโโโโ โโโโโโโโโ
โโโโโโโโโโโโ โโโ โโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโโ
โโโ โโโโโโโ โโโ โโโโโโโโโโโโโโโ โโโโโโโ โโโโโโโโ
2019-04-05 10:19:27.643 +00:00 [INF] - Version - 1.0.6.19913336 (8288bc9bd6f6e15295fea506cd3f99d7f6347a6a)
2019-04-05 10:19:27.673 +00:00 [INF] - Loaded server certificate with expiration date of "2019-07-04T07:25:20.0000000+00:00"
2019-04-05 10:19:27.833 +00:00 [INF] - Created new message store
2019-04-05 10:19:27.837 +00:00 [INF] - Started task to cleanup processed and stale messages
2019-04-05 10:19:29.186 +00:00 [INF] - Created device scope identities cache
2019-04-05 10:19:29.273 +00:00 [INF] - Starting refresh of device scope identities cache
2019-04-05 10:19:30.397 +00:00 [INF] - Initialized twin manager v1.
2019-04-05 10:19:30.502 +00:00 [INF] - Initializing configuration
2019-04-05 10:19:30.745 +00:00 [INF] - New device connection for device raspberrypivanke/$edgeHub
2019-04-05 10:19:31.157 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberrypivanke/$edgeHub via AMQP...
2019-04-05 10:19:37.468 +00:00 [INF] - Exiting disconnected state
2019-04-05 10:19:37.485 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2019-04-05 10:19:37.501 +00:00 [INF] - Processing subscriptions for client raspberrypivanke/$edgeHub.
2019-04-05 10:19:37.538 +00:00 [INF] - Cloud connection for raspberrypivanke/$edgeHub is True
2019-04-05 10:19:37.575 +00:00 [INF] - Connection status for raspberrypivanke/$edgeHub changed to ConnectionEstablished
2019-04-05 10:19:37.600 +00:00 [INF] - Entering connected state
2019-04-05 10:19:37.619 +00:00 [INF] - Created cloud proxy for client raspberrypivanke/$edgeHub via AMQP, with client operation timeout 20 seconds.
2019-04-05 10:19:37.652 +00:00 [INF] - Initialized cloud proxy 71507ccf-47bc-4402-8ad3-f91a5daa6583 for raspberrypivanke/$edgeHub
2019-04-05 10:19:37.667 +00:00 [INF] - Created cloud connection for client raspberrypivanke/$edgeHub
2019-04-05 10:19:37.779 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberrypivanke/$edgeHub.
2019-04-05 10:19:37.854 +00:00 [INF] - Processing subscription Methods for client raspberrypivanke/$edgeHub.
2019-04-05 10:19:38.335 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberrypivanke/$edgeHub.
2019-04-05 10:19:38.351 +00:00 [INF] - Processing subscription Methods for client raspberrypivanke/$edgeHub.
2019-04-05 10:20:12.569 +00:00 [INF] - Obtained edge hub config from module twin
2019-04-05 10:20:12.647 +00:00 [INF] - Obtained edge hub config patch update from module twin
2019-04-05 10:20:12.944 +00:00 [INF] - Updating edge hub configuration
2019-04-05 10:20:13.569 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-04-05 10:20:13.576 +00:00 [INF] - SampleModuleToIoTHub: FROM /messages/modules/SampleModule/outputs/* INTO $upstream
2019-04-05 10:20:13.588 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-04-05 10:20:13.590 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-04-05 10:20:13.593 +00:00 [INF] - Initialized edge hub configuration
2019-04-05 10:20:13.712 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2019-04-05 10:20:13.977 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-04-05 10:20:13.978 +00:00 [INF] - SampleModuleToIoTHub: FROM /messages/modules/SampleModule/outputs/* INTO $upstream
2019-04-05 10:20:13.978 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-04-05 10:20:13.979 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-04-05 10:20:32.758 +00:00 [INF] - Scheduling server certificate renewal for "2019-07-04T07:22:50.0006240Z".
2019-04-05 10:20:32.770 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2019-04-05 10:20:32.797 +00:00 [INF] - Starting MQTT head
2019-04-05 10:20:47.123 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2019-04-05 10:21:34.394 +00:00 [INF] - Starting AMQP head
2019-04-05 10:21:34.547 +00:00 [INF] - Started MQTT head
2019-04-05 10:21:39.824 +00:00 [INF] - Started AMQP head
2019-04-05 10:21:39.839 +00:00 [INF] - Starting HTTP head
2019-04-05 10:22:32.362 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted
at rest.
2019-04-05 10:23:22.552 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2019-04-05 10:23:22.696 +00:00 [INF] - Started HTTP head
2019-04-05 10:25:13.776 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:30:13.721 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:35:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:40:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:45:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:49:35.678 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2019-04-05 10:49:35.915 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store.
2019-04-05 10:50:13.716 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 10:55:13.716 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:00:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:05:13.717 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:06:20.709 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 1672046b
2019-04-05 11:06:20.709 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 508f279f
2019-04-05 11:10:13.712 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:15:13.718 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:19:35.527 +00:00 [INF] - Starting refresh of device scope identities cache
2019-04-05 11:20:05.917 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2019-04-05 11:20:05.919 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store.
2019-04-05 11:20:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:25:13.717 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:30:13.717 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:34:23.242 +00:00 [INF] - Obtained edge hub config patch update from module twin
2019-04-05 11:34:23.475 +00:00 [INF] - Updating edge hub configuration
2019-04-05 11:34:23.556 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-04-05 11:34:23.556 +00:00 [INF] - SampleModuleToIoTHub: FROM /messages/modules/SampleModule/outputs/* INTO $upstream
2019-04-05 11:34:23.556 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-04-05 11:34:23.557 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-04-05 11:35:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:35:16.429 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 14a5de58
2019-04-05 11:35:17.067 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 567f42fd
2019-04-05 11:35:18.114 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 29937267
2019-04-05 11:35:19.115 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 79c700c9
2019-04-05 11:35:20.148 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 104ac74b
2019-04-05 11:35:22.300 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 49c624c4
2019-04-05 11:35:31.893 +00:00 [INF] - Client raspberrypivanke/SampleModule in device scope authenticated locally.
2019-04-05 11:35:31.906 +00:00 [INF] - Successfully generated identity for clientId raspberrypivanke/SampleModule and username raspberrypi/raspberrypivanke/SampleModule
/?api-version=2018-06-30&DeviceClientType=.NET%2F1.19.0%20%28.NET%20Core%204.6.27414.06%3B%20Linux%204.14.98-v7%2B%20%231200%20SMP%20Tue%20Feb%2012%2020%3A27%3A48%20GMT
%202019%3B%20Arm%29
2019-04-05 11:35:31.907 +00:00 [INF] - ClientAuthenticated, raspberrypivanke/SampleModule, 5f3d5830
2019-04-05 11:35:32.141 +00:00 [INF] - New device connection for device raspberrypivanke/SampleModule
2019-04-05 11:35:32.304 +00:00 [INF] - Bind device proxy for device raspberrypivanke/SampleModule
2019-04-05 11:35:32.310 +00:00 [INF] - Binding message channel for device Id raspberrypivanke/SampleModule
2019-04-05 11:35:32.477 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberrypivanke/SampleModule via AMQP...
2019-04-05 11:35:32.776 +00:00 [INF] - Cloud connection for raspberrypivanke/SampleModule is True
2019-04-05 11:35:32.776 +00:00 [INF] - Connection status for raspberrypivanke/SampleModule changed to ConnectionEstablished
2019-04-05 11:35:32.802 +00:00 [INF] - Created cloud proxy for client raspberrypivanke/SampleModule via AMQP, with client operation timeout 20 seconds.
2019-04-05 11:35:32.802 +00:00 [INF] - Initialized cloud proxy b7952e03-8b85-415c-9cd7-3f54298a3694 for raspberrypivanke/SampleModule
2019-04-05 11:35:32.802 +00:00 [INF] - Created cloud connection for client raspberrypivanke/SampleModule
2019-04-05 11:35:32.803 +00:00 [INF] - Processing subscription TwinResponse for client raspberrypivanke/SampleModule.
2019-04-05 11:35:32.883 +00:00 [INF] - Set subscriptions from session state for raspberrypivanke/SampleModule
2019-04-05 11:35:33.229 +00:00 [INF] - Processing subscription TwinResponse for client raspberrypivanke/SampleModule.
2019-04-05 11:35:33.230 +00:00 [INF] - Processing subscription Methods for client raspberrypivanke/SampleModule.
2019-04-05 11:35:33.449 +00:00 [INF] - Set subscriptions from session state for raspberrypivanke/SampleModule
2019-04-05 11:40:13.712 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:45:13.717 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:50:13.713 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 11:50:35.932 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2019-04-05 11:50:35.934 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store.
2019-04-05 11:55:13.718 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 12:00:13.711 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 12:05:13.712 +00:00 [INF] - Reauthenticating connected clients
2019-04-05 12:10:13.713 +00:00 [INF] - Reauthenticating connected clients
@varunpuranik Based on the tests done by @payalgaikwad42
It seems that the issue encountered using dotnet SDKs too
@gauravagarwal28 it should not matter if the modules are referenced from Dockerhub or ACR as the exact same deployment produced a working response on AMD64 but failed only on ARM32. This also allows the attached sample code to be reproducible by others without ACR credentials. It appears that this issue is isolated to ARM32 platforms and that both JS and C# modules are producing the same error response on attempts to invoke Direct Methods.
@varunpuranik could you post the module code that you used which allowed you to invoke a DirectMethod on the Pi? I am getting the same response {"status":500,"payload":null} whether I use a JS or C# module. As soon as I deploy the exact same code to an AMD64 device I get a proper status:200 response. Both devices are hard-wired to the same router. This looks like an issue with the ARM32 runtime on my end.
@varunpuranik
Can you please give us some updates on this issue?
@toolboc / @gauravagarwal28 -
My test code is completely boilerplate, something similar to this -
https://github.com/Azure/iotedge/blob/master/edge-modules/DirectMethodSender/src/Program.cs
We also have tests for method invocation on the RPi that are passing.
Also, can you try updating your module code to C# SDK Version 1.20.0? That resolved some flakiness for us.
I am having the same issue. I can't invoke module direct methods. Always receiving error 500 or 501.
Any updates on this?
Thanks
This issue is being marked as stale because it has been open for 30 days with no activity.
This issue should be fixed with the latest 1.0.9 RC release. Please re-open as needed.
I can verify this was fixed on 1.0.9 on a rPI4 host.
I still experience the same problem with 1.0.9.5 on a rPi3 and rPi4.
A direct method always returns {"status":500,"payload":null} via portal and/or via code.
Most helpful comment
@gauravagarwal28 it should not matter if the modules are referenced from Dockerhub or ACR as the exact same deployment produced a working response on AMD64 but failed only on ARM32. This also allows the attached sample code to be reproducible by others without ACR credentials. It appears that this issue is isolated to ARM32 platforms and that both JS and C# modules are producing the same error response on attempts to invoke Direct Methods.
@varunpuranik could you post the module code that you used which allowed you to invoke a DirectMethod on the Pi? I am getting the same response
{"status":500,"payload":null}whether I use a JS or C# module. As soon as I deploy the exact same code to an AMD64 device I get a properstatus:200response. Both devices are hard-wired to the same router. This looks like an issue with the ARM32 runtime on my end.