Closed Shrunoti closed 4 years ago
yophilav
commented
4 years ago Hello @Shrunoti Thank you for the bug report! We aware of the bug and just now published a new release 1.0.9.4 to fix the exact issue that you're seeing!
Please give this a try! https://github.com/Azure/azure-iotedge/releases/tag/1.0.9.4
yophilav
commented
4 years ago @Shrunoti any updates on the issue?
Shrunoti
commented
4 years ago I tested this version on my device and it is working as expected. thank you for a quick resolution.
Expected Behavior
Module should stay connected to IotHub
Current Behavior
Custom Module shows 'Disconnected' connectionState and does not receive device/module method calls or module twin updates after an hour of being up. Needs restart of the module to start receiving method calls again.
Steps to Reproduce
Provide a detailed set of steps to reproduce the bug.
Deployed custom module using this sample of NodeJs SDK with only method name change- https://github.com/Azure/azure-iot-sdk-node/blob/master/device/samples/simple_sample_module_method.js
Invoking module method through az-cli command : az iot hub invoke-module-method --hub-name IoTHubname --device-id deviceId--module-id TestModule --method-name testMethod --mp "{'hello':'world'}" The method is invoked only within first one hour of deploying the module
Module details in the deployment manifest - "modules": { "TestModule": { "version": "1.0", "type": "docker", "status": "running", "restartPolicy": "always", "settings": { "image": containerregistry/imagename,
"createOptions": "{\"NetworkingConfig\":{\"EndpointsConfig\":{\"host\":{}}},\"HostConfig\":{\"NetworkMode\":\"host\",\"Binds\":[\"/tmp:/tmp\"]}}" } }
Checked Module Info through visual studio code
Module info: { "moduleId": "TestModule", "managedBy": "IotEdge", "deviceId": "SK_Test", "generationId": "637303930164994596", "etag": "NTI4Nzc2NjI=", "connectionState": "Disconnected", "connectionStateUpdatedTime": "2020-07-15T11:03:20.5265542Z", "lastActivityTime": "0001-01-01T00:00:00Z", "cloudToDeviceMessageCount": 0, "authentication": { "symmetricKey": { "primaryKey": "", "secondaryKey": "" }, "x509Thumbprint": { "primaryThumbprint": null, "secondaryThumbprint": null }, "type": "sas" } }
Context (Environment)
Output of
iotedge checkDeployed the module on 2 devices
Click here
``` √ config.yaml is well-formed - OK √ config.yaml has well-formed connection string - OK √ container engine is installed and functional - OK √ config.yaml has correct hostname - OK √ config.yaml has correct URIs for daemon mgmt endpoint - OK ‼ latest security daemon - Warning Installed IoT Edge daemon has version 1.0.9.2 but 1.0.9.3 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ host time is close to real time - OK √ container time is close to host time - OK ‼ DNS server - Warning Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub. Please see https://aka.ms/iotedge-prod-checklist-dns for best practices. You can ignore this warning if you are setting DNS server per module in the Edge deployment. ‼ production readiness: certificates - Warning The Edge device is using self-signed automatically-generated development certificates. They will expire in 46 days (at 2020-08-30 19:05:58 UTC) causing module-to-module and downstream device communication to fail on an active deployment. After the certs have expired, restarting the IoT Edge daemon will trigger it to generate new development certs. Please consider using production certificates instead. See https://aka.ms/iotedge-prod-checklist-certs for best practices. ‼ production readiness: container engine - Warning Device is not using a production-supported container engine (moby-engine). Please see https://aka.ms/iotedge-prod-checklist-moby for details. ‼ production readiness: logs policy - Warning Container engine is not configured to rotate module logs which may cause it run out of disk space. Please see https://aka.ms/iotedge-prod-checklist-logs for best practices. You can ignore this warning if you are setting log policy per module in the Edge deployment. ‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. ‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. Connectivity checks ------------------- √ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK √ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK √ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK √ container on the default network can connect to IoT Hub AMQP port - OK √ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the default network can connect to IoT Hub MQTT port - OK √ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK √ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK 16 check(s) succeeded. 7 check(s) raised warnings. Re-run with --verbose for more details. Configuration checks -------------------- √ config.yaml is well-formed - OK √ config.yaml has well-formed connection string - OK √ container engine is installed and functional - OK √ config.yaml has correct hostname - OK √ config.yaml has correct URIs for daemon mgmt endpoint - OK ‼ latest security daemon - Warning Installed IoT Edge daemon has version 1.0.8 but 1.0.9.3 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ host time is close to real time - OK √ container time is close to host time - OK √ DNS server - OK ‼ production readiness: certificates - Warning Device is using self-signed, automatically generated certs. Please see https://aka.ms/iotedge-prod-checklist-certs for best practices. √ production readiness: certificates expiry - OK √ production readiness: container engine - OK ‼ production readiness: logs policy - Warning Container engine is not configured to rotate module logs which may cause it run out of disk space. Please see https://aka.ms/iotedge-prod-checklist-logs for best practices. You can ignore this warning if you are setting log policy per module in the Edge deployment. Connectivity checks ------------------- √ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK √ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK √ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK √ container on the default network can connect to IoT Hub AMQP port - OK √ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the default network can connect to IoT Hub MQTT port - OK √ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK √ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK √ Edge Hub can bind to ports on host - OK 20 check(s) succeeded. 3 check(s) raised warnings. Re-run with --verbose for more details. ```Device Information
Runtime Versions
iotedge version]: iotedge 1.0.9.2docker version]: 19.03.5Note: when using Windows containers on Windows, run
docker -H npipe:////./pipe/iotedge_moby_engine versioninsteadLogs
edge-agent logs
``` 2020-07-15 06:24:01 Starting Edge Agent 2020-07-15 06:24:01.888 +00:00 Edge Agent Main() <6> 2020-07-15 06:24:02.072 +00:00 [INF] - Initializing Edge Agent. <6> 2020-07-15 06:24:02.222 +00:00 [INF] - Version - 1.0.9.3.32101608 (ad04e23b1865211913282b918263700deafdccfa) <6> 2020-07-15 06:24:02.222 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2020-07-15 06:24:02.279 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"EnableUploadLogs":false,"EnableGetLogs":false,"EnableMetrics":false} <6> 2020-07-15 06:24:02.415 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:09/14/2020 07:47:21] to Root <6> 2020-07-15 06:24:03.108 +00:00 [INF] - Created persistent store at /tmp/edgeAgent <6> 2020-07-15 06:24:03.166 +00:00 [INF] - Started operation refresh twin config <6> 2020-07-15 06:24:03.182 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Mqtt_WebSocket_Only... <6> 2020-07-15 06:24:03.259 +00:00 [INF] - Registering request handler RestartModule <6> 2020-07-15 06:24:05.855 +00:00 [INF] - Edge agent connected to IoT Hub via Mqtt_WebSocket_Only. <6> 2020-07-15 06:24:06.422 +00:00 [INF] - Initialized new module client with subscriptions enabled <6> 2020-07-15 06:24:06.779 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 1 and reported properties version 1. <6> 2020-07-15 06:24:06.783 +00:00 [INF] - Deployment config in edge agent's desired properties is empty. <3> 2020-07-15 06:24:06.785 +00:00 [ERR] - Error refreshing edge agent configuration from twin. Microsoft.Azure.Devices.Edge.Agent.Core.ConfigSources.ConfigEmptyException: This device has an empty configuration for the edge agent. Please set a deployment manifest. at Microsoft.Azure.Devices.Edge.Agent.IoTHub.EdgeAgentConnection.UpdateDeploymentConfig(TwinCollection desiredProperties) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/EdgeAgentConnection.cs:line 262 at Microsoft.Azure.Devices.Edge.Agent.IoTHub.EdgeAgentConnection.edge-hub logs
``` iotedge logs -f edgeHub 2020-07-15 06:57:18 Starting Edge Hub 2020-07-15 06:57:18.807 +00:00 Edge Hub Main() <6> 2020-07-15 06:57:19.679 +00:00 [INF] - Installing certificates [CN=iotedged workload ca:09/14/2020 07:47:21],[CN=Test Edge Device CA:09/14/2020 07:47:21],[CN=Test Edge Owner CA:09/14/2020 07:47:21] to Root <6> 2020-07-15 06:57:19.710 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:09/14/2020 07:47:21] to Root <6> 2020-07-15 06:57:20.718 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2020-07-15 06:57:20.744 +00:00 [INF] - Initializing Edge Hub <6> 2020-07-15 06:57:20.744 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2020-07-15 06:57:20.745 +00:00 [INF] - Version - 1.0.9.3.32101608 (ad04e23b1865211913282b918263700deafdccfa) <6> 2020-07-15 06:57:20.745 +00:00 [INF] - OptimizeForPerformance=True <6> 2020-07-15 06:57:20.745 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2020-07-15 06:57:20.748 +00:00 [INF] - Loaded server certificate with expiration date of "2020-09-14T07:47:21.0000000+00:00" <6> 2020-07-15 06:57:20.776 +00:00 [INF] - Created new message store <6> 2020-07-15 06:57:20.776 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2020-07-15 06:57:20.833 +00:00 [INF] - Created device scope identities cache <6> 2020-07-15 06:57:20.844 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-07-15 06:57:20.867 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2020-07-15 06:57:20.960 +00:00 [INF] - Initialized storing twin manager <6> 2020-07-15 06:57:20.973 +00:00 [INF] - Initializing configuration <6> 2020-07-15 06:57:20.992 +00:00 [INF] - New device connection for device SK_Test/$edgeHub <6> 2020-07-15 06:57:21.004 +00:00 [INF] - Processing pending subscriptions for SK_Test/$edgeHub <6> 2020-07-15 06:57:21.080 +00:00 [INF] - Attempting to connect to IoT Hub for client SK_Test/$edgeHub via MQTT over WebSockets... <4> 2020-07-15 06:57:21.145 +00:00 [WRN] - Empty edge hub configuration received. Ignoring... <6> 2020-07-15 06:57:23.492 +00:00 [INF] - Exiting disconnected state <6> 2020-07-15 06:57:23.495 +00:00 [INF] - Received device connected callback <6> 2020-07-15 06:57:23.505 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2020-07-15 06:57:23.508 +00:00 [INF] - Processing subscriptions for client SK_Test/$edgeHub on device connected. <6> 2020-07-15 06:57:23.523 +00:00 [INF] - Entering connected state <6> 2020-07-15 06:57:23.526 +00:00 [INF] - Cloud connection for SK_Test/$edgeHub is True <6> 2020-07-15 06:57:23.531 +00:00 [INF] - Connection status for SK_Test/$edgeHub changed to ConnectionEstablished <6> 2020-07-15 06:57:23.533 +00:00 [INF] - Client SK_Test/$edgeHub connected to cloud, processing existing subscriptions. <6> 2020-07-15 06:57:23.536 +00:00 [INF] - Created cloud proxy for client SK_Test/$edgeHub via MQTT over WebSockets, with client operation timeout 20 seconds. <6> 2020-07-15 06:57:23.541 +00:00 [INF] - Initialized cloud proxy 1094532f-1a67-45e4-85d5-464fe842deaa for SK_Test/$edgeHub <6> 2020-07-15 06:57:23.542 +00:00 [INF] - Created cloud connection for client SK_Test/$edgeHub <6> 2020-07-15 06:57:24.030 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 06:57:24.116 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2020-07-15 06:57:24.140 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-07-15 06:57:24.649 +00:00 [INF] - Processing pending subscriptions for SK_Test/$edgeHub <6> 2020-07-15 06:57:24.664 +00:00 [INF] - Set the following 7 route(s) in edge hub <6> 2020-07-15 06:57:24.664 +00:00 [INF] - 3rdEyeCoreToIoTHub: FROM /messages/modules/3rdEyeCore/outputs/* INTO $upstream <6> 2020-07-15 06:57:24.664 +00:00 [INF] - PpeDetectiontoIotHub: FROM /messages/modules/PeopleNet/outputs/* INTO $upstream <6> 2020-07-15 06:57:24.664 +00:00 [INF] - EdgeBackendTo3rdEyeCore: FROM /messages/modules/EdgeBackend/outputs/startStreaming INTO BrokeredEndpoint("/modules/3rdEyeCore/inputs/startStreaming") <6> 2020-07-15 06:57:24.664 +00:00 [INF] - 3rdEyeCoreToPpeDetectionStart: FROM /messages/modules/3rdEyeCore/outputs/output1 INTO BrokeredEndpoint("/modules/CustomModel/inputs/startStreaming") <6> 2020-07-15 06:57:24.664 +00:00 [INF] - EdgeBackendToCustomModel: FROM /messages/modules/EdgeBackend/outputs/stopStreaming INTO BrokeredEndpoint("/modules/CustomModel/inputs/stopStreaming") <6> 2020-07-15 06:57:24.664 +00:00 [INF] - DSModuleToBackend: FROM /messages/modules/PeopleNet/outputs/* INTO BrokeredEndpoint("/modules/EdgeBackend/inputs/dsresults") <6> 2020-07-15 06:57:24.664 +00:00 [INF] - CustomModuleToBackend: FROM /messages/modules/CustomModel/outputs/* INTO BrokeredEndpoint("/modules/EdgeBackend/inputs/dsresults") <6> 2020-07-15 06:57:24.668 +00:00 [INF] - Updated message store TTL to 7200 seconds <6> 2020-07-15 06:57:24.669 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2020-07-15 06:57:24.685 +00:00 [INF] - Started operation Get EdgeHub config <6> 2020-07-15 06:57:24.685 +00:00 [INF] - Initialized edge hub configuration <6> 2020-07-15 06:57:24.699 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2020-07-15 06:57:24.802 +00:00 [INF] - Scheduling server certificate renewal for "2020-09-14T07:44:51.0000705Z". <6> 2020-07-15 06:57:24.804 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2020-07-15 06:57:24.808 +00:00 [INF] - Starting MQTT head <6> 2020-07-15 06:57:24.822 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2020-07-15 06:57:24.845 +00:00 [INF] - Starting AMQP head <6> 2020-07-15 06:57:24.850 +00:00 [INF] - Started MQTT head <6> 2020-07-15 06:57:24.916 +00:00 [INF] - Started AMQP head <6> 2020-07-15 06:57:24.919 +00:00 [INF] - Starting HTTP head <6> 2020-07-15 06:57:25.016 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest. <6> 2020-07-15 06:57:25.043 +00:00 [INF] - Creating key {0fdd8523-791b-4f9f-a309-8cf2830fa116} with creation date 2020-07-15 06:57:25Z, activation date 2020-07-15 06:57:25Z, and expiration date 2020-10-13 06:57:25Z. <4> 2020-07-15 06:57:25.056 +00:00 [WRN] - No XML encryptor configured. Key {0fdd8523-791b-4f9f-a309-8cf2830fa116} may be persisted to storage in unencrypted form. <6> 2020-07-15 06:57:25.060 +00:00 [INF] - Writing data to file '"/home/edgehubuser/.aspnet/DataProtection-Keys/key-0fdd8523-791b-4f9f-a309-8cf2830fa116.xml"'. <6> 2020-07-15 06:57:25.292 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 06:57:25.299 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 06:57:25.304 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 3ccc7cfd <6> 2020-07-15 06:57:25.332 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 06:57:25.343 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 06:57:25.343 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 06:57:25.372 +00:00 [INF] - Processing subscriptions Methods for client SK_Test/TestModule. <6> 2020-07-15 06:57:25.372 +00:00 [INF] - Processing pending subscriptions for SK_Test/TestModule <6> 2020-07-15 06:57:25.379 +00:00 [INF] - Attempting to connect to IoT Hub for client SK_Test/TestModule via MQTT over WebSockets...<6> 2020-07-15 06:57:25.392 +00:00 [INF] - Set subscriptions from session state for SK_Test/TestModule <4> 2020-07-15 06:57:25.408 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <6> 2020-07-15 06:57:25.429 +00:00 [INF] - Started HTTP head <6> 2020-07-15 06:57:26.305 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 06:57:27.155 +00:00 [INF] - Cloud connection for SK_Test/TestModule is True <6> 2020-07-15 06:57:27.155 +00:00 [INF] - Connection status for SK_Test/TestModule changed to ConnectionEstablished <6> 2020-07-15 06:57:27.155 +00:00 [INF] - Client SK_Test/TestModule connected to cloud, processing existing subscriptions. <6> 2020-07-15 06:57:27.155 +00:00 [INF] - Created cloud proxy for client SK_Test/TestModule via MQTT over WebSockets, with client operation timeout 20 seconds. <6> 2020-07-15 06:57:27.156 +00:00 [INF] - Initialized cloud proxy 32cd6c18-ceb4-4b82-ab87-5826b922b683 for SK_Test/TestModule <6> 2020-07-15 06:57:27.156 +00:00 [INF] - Created cloud connection for client SK_Test/TestModule <6> 2020-07-15 07:02:24.718 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <4> 2020-07-15 07:04:52.093 +00:00 [WRN] - Did not receive response for method invoke call from device/module SK_Test/TestModule for SK_Test/TestModule with correlation ID 96fa046a-a0cf-4648-a9ba-ec7d3eeb7f07 <4> 2020-07-15 07:05:23.001 +00:00 [WRN] - Did not receive response for method invoke call from device/module SK_Test/TestModule for SK_Test/TestModule with correlation ID e6258981-233a-48c7-88aa-1aa2fe8a92a9 <6> 2020-07-15 07:07:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:12:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:17:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:22:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:27:20.786 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 07:27:20.794 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 07:27:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:27:50.796 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 07:27:50.797 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 07:28:20.798 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 07:28:20.799 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 07:28:50.799 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 07:28:50.799 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 07:29:20.798 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 07:29:20.799 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 07:32:24.700 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:37:24.700 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:42:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:42:25.218 +00:00 [INF] - Closing connection for device: SK_Test/TestModule, , <6> 2020-07-15 07:42:25.220 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - <6> 2020-07-15 07:42:25.224 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 07:42:25.228 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 07:42:25.246 +00:00 [INF] - Closing receiver in cloud proxy 32cd6c18-ceb4-4b82-ab87-5826b922b683 for SK_Test/TestModule <6> 2020-07-15 07:42:25.247 +00:00 [INF] - Closed cloud proxy 32cd6c18-ceb4-4b82-ab87-5826b922b683 for SK_Test/TestModule <6> 2020-07-15 07:42:25.247 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 07:42:25.250 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 07:42:25.267 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 07:42:25.267 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 07:42:25.267 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 2206cbaf <6> 2020-07-15 07:42:25.269 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 07:42:25.270 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 07:42:25.270 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 07:42:25.622 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 07:42:30.982 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 07:47:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:52:24.700 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:57:22.468 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-07-15 07:57:24.687 +00:00 [INF] - Starting periodic operation Get EdgeHub config... <6> 2020-07-15 07:57:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 07:57:24.941 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-07-15 07:57:24.951 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config <6> 2020-07-15 07:57:25.287 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 07:59:50.797 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 07:59:50.798 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 08:00:20.800 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 08:00:20.800 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 08:00:50.799 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 08:00:50.800 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 08:01:20.799 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 08:01:20.800 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 08:01:50.801 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 08:01:50.802 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 08:02:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:02:45.324 +00:00 [INF] - Exiting connected state <6> 2020-07-15 08:02:45.325 +00:00 [INF] - Entering unreachable state <6> 2020-07-15 08:02:45.701 +00:00 [INF] - Entering connected state <6> 2020-07-15 08:07:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:12:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:17:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:22:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:27:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:27:25.264 +00:00 [INF] - Closing connection for device: SK_Test/TestModule, , <6> 2020-07-15 08:27:25.264 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - <6> 2020-07-15 08:27:25.264 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 08:27:25.264 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 08:27:25.264 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 08:27:25.265 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 08:27:25.283 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 08:27:25.283 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 08:27:25.283 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 0b91775d <6> 2020-07-15 08:27:25.283 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 08:27:25.284 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 08:27:25.284 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 08:27:25.610 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 08:27:30.953 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 08:32:20.801 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 08:32:20.802 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 08:32:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:32:50.804 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 08:32:50.805 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 08:33:20.802 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 08:33:20.803 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 08:33:50.802 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 08:33:50.803 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 08:34:20.802 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 08:34:20.803 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 08:37:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:42:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:47:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:52:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:57:20.722 +00:00 [INF] - Starting compaction of stores <6> 2020-07-15 08:57:20.724 +00:00 [INF] - Starting compaction of store SK_Test/CustomModel/startStreaming <6> 2020-07-15 08:57:20.727 +00:00 [INF] - Starting compaction of store ProductInfo <6> 2020-07-15 08:57:20.728 +00:00 [INF] - Starting compaction of store sessions <6> 2020-07-15 08:57:20.728 +00:00 [INF] - Starting compaction of store checkpoints <6> 2020-07-15 08:57:20.728 +00:00 [INF] - Starting compaction of store twins <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store DeviceScopeCache <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store messages <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store default <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store SK_Test/CustomModel/stopStreaming <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store iothub <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store EdgeTwin <6> 2020-07-15 08:57:20.729 +00:00 [INF] - Starting compaction of store SK_Test/EdgeBackend/dsresults <6> 2020-07-15 08:57:23.948 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-07-15 08:57:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 08:57:24.951 +00:00 [INF] - Starting periodic operation Get EdgeHub config... <6> 2020-07-15 08:57:25.189 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-07-15 08:57:25.190 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config <6> 2020-07-15 08:57:25.650 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 09:02:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:04:50.805 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 09:04:50.806 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 09:05:20.807 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 09:05:20.807 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 09:05:50.807 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 09:05:50.808 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 09:06:20.810 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 09:06:20.810 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 09:06:50.811 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 09:06:50.811 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 09:07:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:12:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:12:25.404 +00:00 [INF] - Closing connection for device: SK_Test/TestModule, , <6> 2020-07-15 09:12:25.404 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - <6> 2020-07-15 09:12:25.404 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 09:12:25.404 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 09:12:25.404 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 09:12:25.405 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 09:12:25.432 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 09:12:25.432 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 09:12:25.432 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 7740fb92 <6> 2020-07-15 09:12:25.433 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 09:12:25.433 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 09:12:25.433 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 09:12:25.785 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 09:12:31.132 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 09:17:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:22:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:27:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:32:24.700 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:37:20.811 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 09:37:20.811 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 09:37:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:37:50.809 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 09:37:50.810 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 09:38:20.809 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 09:38:20.810 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 09:38:50.810 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 09:38:50.810 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 09:39:20.811 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 09:39:20.811 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 09:42:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <4> 2020-07-15 09:46:32.674 +00:00 [WRN] - Closing connection for device: SK_Test/TestModule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., <6> 2020-07-15 09:46:32.674 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2020-07-15 09:46:32.674 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 09:46:32.674 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 09:46:32.674 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 09:46:32.674 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 09:46:33.021 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 09:46:33.839 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 09:46:33.840 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 09:46:33.840 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 7c85e27b <6> 2020-07-15 09:46:33.840 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 09:46:33.840 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 09:46:33.840 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 09:46:33.845 +00:00 [INF] - Processing subscriptions Methods for client SK_Test/TestModule. <6> 2020-07-15 09:46:33.846 +00:00 [INF] - Processing pending subscriptions for SK_Test/TestModule <6> 2020-07-15 09:46:33.846 +00:00 [INF] - Set subscriptions from session state for SK_Test/TestModule <6> 2020-07-15 09:46:33.846 +00:00 [INF] - Attempting to connect to IoT Hub for client SK_Test/TestModule via MQTT over WebSockets...<6> 2020-07-15 09:46:35.670 +00:00 [INF] - Cloud connection for SK_Test/TestModule is True <6> 2020-07-15 09:46:35.670 +00:00 [INF] - Connection status for SK_Test/TestModule changed to ConnectionEstablished <6> 2020-07-15 09:46:35.670 +00:00 [INF] - Client SK_Test/TestModule connected to cloud, processing existing subscriptions. <6> 2020-07-15 09:46:35.670 +00:00 [INF] - Created cloud proxy for client SK_Test/TestModule via MQTT over WebSockets, with client operation timeout 20 seconds. <6> 2020-07-15 09:46:35.670 +00:00 [INF] - Initialized cloud proxy a504e926-f2f8-4735-8114-4b5d115cf28e for SK_Test/TestModule <6> 2020-07-15 09:46:35.670 +00:00 [INF] - Created cloud connection for client SK_Test/TestModule <6> 2020-07-15 09:46:38.367 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 09:47:24.700 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:52:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <4> 2020-07-15 09:52:26.938 +00:00 [WRN] - Did not receive response for method invoke call from device/module SK_Test/TestModule for SK_Test/TestModule with correlation ID e0b31cb3-8f05-4ad2-a709-292b5d484210 <4> 2020-07-15 09:52:57.881 +00:00 [WRN] - Did not receive response for method invoke call from device/module SK_Test/TestModule for SK_Test/TestModule with correlation ID c583c590-6cbb-4979-8ef4-f3b837e39edf <6> 2020-07-15 09:57:24.701 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 09:57:25.195 +00:00 [INF] - Starting periodic operation Get EdgeHub config... <6> 2020-07-15 09:57:25.432 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-07-15 09:57:25.432 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config <6> 2020-07-15 09:57:25.538 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-07-15 09:57:25.781 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:02:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <4> 2020-07-15 10:06:29.763 +00:00 [WRN] - Closing connection for device: SK_Test/TestModule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Closing receiver in cloud proxy a504e926-f2f8-4735-8114-4b5d115cf28e for SK_Test/TestModule <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Closed cloud proxy a504e926-f2f8-4735-8114-4b5d115cf28e for SK_Test/TestModule <6> 2020-07-15 10:06:29.763 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 10:06:29.764 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 10:06:30.119 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:06:52.356 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 10:06:52.356 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 10:06:52.356 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 23e51a65 <6> 2020-07-15 10:06:52.357 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 10:06:52.357 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 10:06:52.357 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 10:06:52.362 +00:00 [INF] - Processing subscriptions Methods for client SK_Test/TestModule. <6> 2020-07-15 10:06:52.362 +00:00 [INF] - Processing pending subscriptions for SK_Test/TestModule <6> 2020-07-15 10:06:52.363 +00:00 [INF] - Set subscriptions from session state for SK_Test/TestModule <6> 2020-07-15 10:06:52.363 +00:00 [INF] - Attempting to connect to IoT Hub for client SK_Test/TestModule via MQTT over WebSockets...<6> 2020-07-15 10:06:52.702 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Cloud connection for SK_Test/TestModule is True <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Connection status for SK_Test/TestModule changed to ConnectionEstablished <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Client SK_Test/TestModule connected to cloud, processing existing subscriptions. <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Created cloud proxy for client SK_Test/TestModule via MQTT over WebSockets, with client operation timeout 20 seconds. <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Initialized cloud proxy 8a8fef9a-9144-413e-9146-01404f9bf690 for SK_Test/TestModule <6> 2020-07-15 10:06:54.127 +00:00 [INF] - Created cloud connection for client SK_Test/TestModule <6> 2020-07-15 10:07:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:09:50.815 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 10:09:50.815 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 10:10:20.816 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 10:10:20.816 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 10:10:50.813 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 10:10:50.814 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 10:11:20.813 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 10:11:20.814 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 10:11:50.816 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 10:11:50.817 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 10:12:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:17:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <4> 2020-07-15 10:17:51.527 +00:00 [WRN] - Closing connection for device: SK_Test/TestModule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Closing receiver in cloud proxy 8a8fef9a-9144-413e-9146-01404f9bf690 for SK_Test/TestModule <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Closed cloud proxy 8a8fef9a-9144-413e-9146-01404f9bf690 for SK_Test/TestModule <6> 2020-07-15 10:17:51.527 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 10:17:51.528 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 10:17:52.010 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:18:19.368 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 10:18:19.368 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 10:18:19.368 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 237efdb7 <6> 2020-07-15 10:18:19.369 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 10:18:19.369 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 10:18:19.369 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 10:18:19.374 +00:00 [INF] - Processing subscriptions Methods for client SK_Test/TestModule. <6> 2020-07-15 10:18:19.374 +00:00 [INF] - Processing pending subscriptions for SK_Test/TestModule <6> 2020-07-15 10:18:19.374 +00:00 [INF] - Attempting to connect to IoT Hub for client SK_Test/TestModule via MQTT over WebSockets...<6> 2020-07-15 10:18:19.375 +00:00 [INF] - Set subscriptions from session state for SK_Test/TestModule <6> 2020-07-15 10:18:19.711 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Cloud connection for SK_Test/TestModule is True <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Connection status for SK_Test/TestModule changed to ConnectionEstablished <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Client SK_Test/TestModule connected to cloud, processing existing subscriptions. <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Created cloud proxy for client SK_Test/TestModule via MQTT over WebSockets, with client operation timeout 20 seconds. <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Initialized cloud proxy 9f19cc49-6ad4-487f-9f48-6b6a4aa10a84 for SK_Test/TestModule <6> 2020-07-15 10:18:21.203 +00:00 [INF] - Created cloud connection for client SK_Test/TestModule <6> 2020-07-15 10:22:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:27:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:32:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:37:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:42:20.820 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 10:42:20.820 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 10:42:24.697 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:42:50.824 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 10:42:50.824 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 10:43:20.822 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 10:43:20.822 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 10:43:50.822 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 10:43:50.823 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 10:44:20.822 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 10:44:20.823 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 10:47:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:52:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:57:20.721 +00:00 [INF] - Starting compaction of stores <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store SK_Test/CustomModel/startStreaming <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store ProductInfo <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store sessions <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store checkpoints <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store twins <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store DeviceScopeCache <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store messages <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store default <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store SK_Test/CustomModel/stopStreaming <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store iothub <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store EdgeTwin <6> 2020-07-15 10:57:20.722 +00:00 [INF] - Starting compaction of store SK_Test/EdgeBackend/dsresults <6> 2020-07-15 10:57:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 10:57:25.430 +00:00 [INF] - Starting periodic operation Get EdgeHub config... <6> 2020-07-15 10:57:25.665 +00:00 [INF] - Obtained edge hub config from module twin <6> 2020-07-15 10:57:25.665 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config <6> 2020-07-15 10:57:26.016 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 10:57:27.126 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2020-07-15 11:02:24.697 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 11:03:19.471 +00:00 [INF] - Closing connection for device: SK_Test/TestModule, , <6> 2020-07-15 11:03:19.471 +00:00 [INF] - Disposing MessagingServiceClient for device Id SK_Test/TestModule because of exception - <6> 2020-07-15 11:03:19.471 +00:00 [INF] - Setting device proxy inactive for device Id SK_Test/TestModule <6> 2020-07-15 11:03:19.471 +00:00 [INF] - Removing device connection for device SK_Test/TestModule with removeCloudConnection flag 'True'. <6> 2020-07-15 11:03:19.472 +00:00 [INF] - Closing receiver in cloud proxy 9f19cc49-6ad4-487f-9f48-6b6a4aa10a84 for SK_Test/TestModule <6> 2020-07-15 11:03:19.472 +00:00 [INF] - Closed cloud proxy 9f19cc49-6ad4-487f-9f48-6b6a4aa10a84 for SK_Test/TestModule <6> 2020-07-15 11:03:19.472 +00:00 [INF] - Device connection removed for device SK_Test/TestModule <6> 2020-07-15 11:03:19.472 +00:00 [INF] - Remove device connection for device SK_Test/TestModule <6> 2020-07-15 11:03:19.489 +00:00 [INF] - Client SK_Test/TestModule in device scope authenticated locally. <6> 2020-07-15 11:03:19.489 +00:00 [INF] - Successfully generated identity for clientId SK_Test/TestModule and username MobiliyaEdgeIoTHub.azure-devices.net/SK_Test/TestModule/?api-version=2019-10-01&DeviceClientType=azure-iot-device%2F1.17.0%20(node%20v10.21.0%3B%20Debian%209.12%3B%20x64) <6> 2020-07-15 11:03:19.489 +00:00 [INF] - ClientAuthenticated, SK_Test/TestModule, 7c8dd14d <6> 2020-07-15 11:03:19.489 +00:00 [INF] - New device connection for device SK_Test/TestModule <6> 2020-07-15 11:03:19.490 +00:00 [INF] - Bind device proxy for device SK_Test/TestModule <6> 2020-07-15 11:03:19.490 +00:00 [INF] - Binding message channel for device Id SK_Test/TestModule <6> 2020-07-15 11:03:19.895 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 11:03:25.246 +00:00 [INF] - Updated reported properties for SK_Test/$edgeHub <6> 2020-07-15 11:07:24.698 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 11:12:24.699 +00:00 [INF] - Entering periodic task to reauthenticate connected clients <6> 2020-07-15 11:14:50.823 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/startStreaming <6> 2020-07-15 11:14:50.823 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/startStreaming and 0 messages from message store. <6> 2020-07-15 11:15:20.822 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/3rdEyeCore/startStreaming <6> 2020-07-15 11:15:20.823 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/3rdEyeCore/startStreaming and 0 messages from message store. <6> 2020-07-15 11:15:50.824 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/CustomModel/stopStreaming <6> 2020-07-15 11:15:50.825 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/CustomModel/stopStreaming and 0 messages from message store. <6> 2020-07-15 11:16:20.825 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub <6> 2020-07-15 11:16:20.826 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. <6> 2020-07-15 11:16:50.826 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint SK_Test/EdgeBackend/dsresults <6> 2020-07-15 11:16:50.827 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint SK_Test/EdgeBackend/dsresults and 0 messages from message store. <6> 2020-07-15 11:17:24.702 +00:00 [INF] - Entering periodic task to reauthenticate connected clients ```Additional Information
The Module does is in the idle state in-between device method calls. Although there are method calls periodically, the module gets disconnected in an hour.