search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.46k stars 459 forks source link

Module to module hub messages delayed with v1.0.8 #1512

Closed LouanDuToitS3 closed 4 years ago

LouanDuToitS3 commented 5 years ago

In our edge pipeline we have multiple modules that uses the edgeHub to communicate with each other. Since upgrading edgeAgent and edgeHub to v1.0.8 we see every other message held back by edgeHub until a second message it sent. Then both messages are delivered.

Expected Behavior

EdgeHub should deliver messages when sent.

Current Behavior

EdgeHub delays every other message until a second message is sent.

Steps to Reproduce

Using the following code, run two modules in the edge runtime, one module as a receiver, and the other as a sender.

#!/usr/bin/env python
"""This module tests the event hub."""
import json
import time
import argparse
import signal
import threading
import Queue as queue
from iothub_client import IoTHubModuleClient, IoTHubTransportProvider, IoTHubMessage, IoTHubMessageDispositionResult

def _rx_message_callback(msg, receive_queue):
    # Message received, get the data
    iothub_msg_buf = msg.get_bytearray()
    iothub_msg_str = iothub_msg_buf.decode('utf-8')

    # decode the JSON data
    iothub_msg = json.loads(iothub_msg_str)

    # push the data to the receive queue
    receive_queue.put(iothub_msg, block=False)

    print("<<< IoTHub Message received: {}".format(iothub_msg))
    return IoTHubMessageDispositionResult.ACCEPTED

def _tx_confirmation_callback(msg, result, user_context):
    # Message was sent
    map_properties = msg.properties()
    key_value_pair = map_properties.get_internals()
    print(">>> IoTHub Message sent with properties: {}, with result: {}".format(key_value_pair, result))

class HubTester(object):

    def __init__(self):
        # Init vars
        self.sender = False

        # Init termination signals
        self.terminate_main = threading.Event()
        signal.signal(signal.SIGTERM, self.shutdown)

        # Init cmdline params
        self._parser = argparse.ArgumentParser(description="Hub testing module")

        self._parser.add_argument("--sender",
                                  action="store_true",
                                  help="A flag that sets module to sending")

        self._parser.add_argument("--name",
                                  action="store",
                                  dest="module_name",
                                  default="hubtest",
                                  help="Name for the module, used in hub routing")

        # get cmdline params
        self._options = self._parser.parse_args()

        self.client = IoTHubModuleClient()
        self.client.create_from_environment(IoTHubTransportProvider.MQTT)
        self.client.set_option("messageTimeout", 10000)
        self.client.set_option("auto_url_encode_decode", True)

        # Set input message and connection callback
        self.rx_queue = queue.Queue(maxsize=1000)
        self.client.set_message_callback("input1", _rx_message_callback, self.rx_queue)

        if self._options.sender:
            print("Hub test sender")
        else:
            print("Hub test receiver")

    def shutdown(self, _signo, _stack_frame):
        print("Requesting application termination. (signal {})".format(_signo))
        self.terminate_main.set()

    def run(self):
        while not self.terminate_main.is_set():
            # if receiver, then poll for events, else sleep 2 secs, and send events
            if not self._options.sender:
                try:
                    try:
                        hub_message = self.rx_queue.get(block=True, timeout=1.1)
                    except queue.Empty:
                        hub_message = None

                    if hub_message is not None:
                        print("Hub message received: {}".format(hub_message))

                        message_age = time.time() - hub_message['time']
                        if message_age > 1.0:
                            print("Hub message is old, {}".format(message_age))

                    else:
                        print("No hub message")

                except Exception as e:
                    print("Runtime exception: {}".format(str(e)))

            else:
                try:
                    send_time = time.time()
                    hub_message = {'time': send_time, 's_time': time.strftime("%Y-%m-%dT%T", time.gmtime(send_time))}
                    self.client.send_event_async('output1', IoTHubMessage(json.dumps(hub_message).encode("utf8")), _tx_confirmation_callback, None)

                    print("Hub message sent: {}".format(hub_message))
                    time.sleep(5)
                except Exception as e:
                    print("Runtime exception: {}".format(str(e)))

Context (Environment)

Output of iotedge check

Click here ``` Configuration checks -------------------- × config.yaml is well-formed - Error Could not open file /etc/iotedge/config.yaml. You might need to run this command as root. 0 check(s) succeeded. 1 check(s) raised errors. Re-run with --verbose for more details. vagrant@edge1:~$ sudo iotedge check 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 - OK √ 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 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 - 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. 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 19 check(s) succeeded. 4 check(s) raised warnings. Re-run with --verbose for more details. ```

Device (Host) Operating System

Ubuntu 18.04

Architecture

amd64

Container Operating System

Linux containers

Runtime Versions

iotedged

iotedge 1.0.8 (208b2204fd30e856d00b280112422130c104b9f0)

Edge Agent

1.0.8.23694809 (f5186c42ebb721893c5a497c789236803de42fb7)

Edge Hub

1.0.8.23694809 (f5186c42ebb721893c5a497c789236803de42fb7)

Docker

Docker version 19.03.1, build 74b1e89

<Run `docker version` (`docker -H npipe:////./pipe/iotedge_moby_engine version` for Moby on Windows) and paste here>

Logs

The following logs are produced by the receiver when using edgeAgent and edgeHub <= v1.0.7:

2019-08-05T12:57:04.850111856Z <<< IoTHub Message received: {u'time': 1565009824.843475, u's_time': u'2019-08-05T12:57:04'}
2019-08-05T12:57:04.896309833Z Hub message received: {u'time': 1565009824.843475, u's_time': u'2019-08-05T12:57:04'}
2019-08-05T12:57:06.145316272Z No hub message
2019-08-05T12:57:07.246091882Z No hub message
2019-08-05T12:57:08.346691933Z No hub message
2019-08-05T12:57:09.447769626Z No hub message
2019-08-05T12:57:09.848989377Z <<< IoTHub Message received: {u'time': 1565009829.844609, u's_time': u'2019-08-05T12:57:09'}
2019-08-05T12:57:09.864100072Z Hub message received: {u'time': 1565009829.844609, u's_time': u'2019-08-05T12:57:09'}
2019-08-05T12:57:10.964868360Z No hub message
2019-08-05T12:57:12.066043562Z No hub message
2019-08-05T12:57:13.167572865Z No hub message
2019-08-05T12:57:14.268531430Z No hub message
2019-08-05T12:57:14.853399815Z <<< IoTHub Message received: {u'time': 1565009834.846373, u's_time': u'2019-08-05T12:57:14'}
2019-08-05T12:57:14.886301797Z Hub message received: {u'time': 1565009834.846373, u's_time': u'2019-08-05T12:57:14'}
2019-08-05T12:57:15.989659180Z No hub message
2019-08-05T12:57:17.104995055Z No hub message
2019-08-05T12:57:18.206346977Z No hub message
2019-08-05T12:57:19.307710174Z No hub message
2019-08-05T12:57:19.854726298Z <<< IoTHub Message received: {u'time': 1565009839.848628, u's_time': u'2019-08-05T12:57:19'}
2019-08-05T12:57:19.883234218Z Hub message received: {u'time': 1565009839.848628, u's_time': u'2019-08-05T12:57:19'}

But this is what can be seen in the receivers logs with edgeAgent and edgeHub >= v1.08

2019-08-05T12:59:08.655764359Z No hub message
2019-08-05T12:59:09.205327898Z <<< IoTHub Message received: {u'time': 1565009944.194676, u's_time': u'2019-08-05T12:59:04'}
2019-08-05T12:59:09.206020811Z <<< IoTHub Message received: {u'time': 1565009949.197294, u's_time': u'2019-08-05T12:59:09'}
2019-08-05T12:59:09.238286315Z Hub message received: {u'time': 1565009944.194676, u's_time': u'2019-08-05T12:59:04'}
2019-08-05T12:59:09.238340627Z Hub message is old, 5.04308509827
2019-08-05T12:59:09.238351844Z Hub message received: {u'time': 1565009949.197294, u's_time': u'2019-08-05T12:59:09'}
2019-08-05T12:59:10.338686253Z No hub message
2019-08-05T12:59:11.439003041Z No hub message
2019-08-05T12:59:12.539521795Z No hub message
2019-08-05T12:59:13.640066483Z No hub message
2019-08-05T12:59:14.740860265Z No hub message
2019-08-05T12:59:15.841557333Z No hub message
2019-08-05T12:59:16.954769770Z No hub message
2019-08-05T12:59:18.055434828Z No hub message
2019-08-05T12:59:19.156875592Z No hub message
2019-08-05T12:59:19.209116035Z <<< IoTHub Message received: {u'time': 1565009954.198587, u's_time': u'2019-08-05T12:59:14'}
2019-08-05T12:59:19.209158154Z <<< IoTHub Message received: {u'time': 1565009959.204857, u's_time': u'2019-08-05T12:59:19'}
2019-08-05T12:59:19.223020440Z Hub message received: {u'time': 1565009954.198587, u's_time': u'2019-08-05T12:59:14'}
2019-08-05T12:59:19.223099456Z Hub message is old, 5.02403616905
2019-08-05T12:59:19.223139388Z Hub message received: {u'time': 1565009959.204857, u's_time': u'2019-08-05T12:59:19'}
2019-08-05T12:59:20.324402110Z No hub message
iotedged logs ``` ```
edge-agent logs ``` 2019-08-05T12:58:00.394229036Z 2019-08-05 12:58:00 Starting Edge Agent 2019-08-05T12:58:00.814036936Z 2019-08-05 12:58:00.800 +00:00 Edge Agent Main() 2019-08-05T12:58:01.344659057Z <6> 2019-08-05 12:58:01.305 +00:00 [INF] - Initializing Edge Agent. 2019-08-05T12:58:01.666760332Z <6> 2019-08-05 12:58:01.666 +00:00 [INF] - Version - 1.0.8.23694809 (f5186c42ebb721893c5a497c789236803de42fb7) 2019-08-05T12:58:01.667456257Z <6> 2019-08-05 12:58:01.667 +00:00 [INF] - 2019-08-05T12:58:01.667568893Z █████╗ ███████╗██╗ ██╗██████╗ ███████╗ 2019-08-05T12:58:01.667575968Z ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ 2019-08-05T12:58:01.667580330Z ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ 2019-08-05T12:58:01.667584612Z ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ 2019-08-05T12:58:01.667731356Z ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ 2019-08-05T12:58:01.667749678Z ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ 2019-08-05T12:58:01.667754824Z 2019-08-05T12:58:01.667758733Z ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ 2019-08-05T12:58:01.667763202Z ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ 2019-08-05T12:58:01.667767447Z ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ 2019-08-05T12:58:01.667771582Z ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ 2019-08-05T12:58:01.667775688Z ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ 2019-08-05T12:58:01.667779870Z ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ 2019-08-05T12:58:01.667784159Z 2019-08-05T12:58:01.768016658Z <6> 2019-08-05 12:58:01.767 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"EnableUploadLogs":false} 2019-08-05T12:58:02.472937478Z <6> 2019-08-05 12:58:02.472 +00:00 [INF] - Started operation refresh twin config 2019-08-05T12:58:02.511400448Z <6> 2019-08-05 12:58:02.510 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only... 2019-08-05T12:58:03.456013363Z <6> 2019-08-05 12:58:03.455 +00:00 [INF] - Created persistent store at /tmp/edgeAgent 2019-08-05T12:58:06.498240508Z <6> 2019-08-05 12:58:06.498 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only. 2019-08-05T12:58:07.000112807Z <6> 2019-08-05 12:58:06.999 +00:00 [INF] - Initialized new module client with subscriptions enabled 2019-08-05T12:58:07.287915449Z <6> 2019-08-05 12:58:07.287 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 30 and reported properties version 292. 2019-08-05T12:58:08.813577828Z <6> 2019-08-05 12:58:08.813 +00:00 [INF] - Plan execution started for deployment 30 2019-08-05T12:58:08.829314420Z <6> 2019-08-05 12:58:08.821 +00:00 [INF] - Executing command: "Saving hubtester_receive to store" 2019-08-05T12:58:08.840726896Z <6> 2019-08-05 12:58:08.840 +00:00 [INF] - Executing command: "Saving hubtester_send to store" 2019-08-05T12:58:08.852418441Z <6> 2019-08-05 12:58:08.852 +00:00 [INF] - Executing command: "Saving edgeHub to store" 2019-08-05T12:58:08.891612160Z <6> 2019-08-05 12:58:08.891 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module hubtester_receive]\n [Stop module hubtester_receive]\n [Update module hubtester_receive]\n)]\n [Start module hubtester_receive]\n)" 2019-08-05T12:58:08.895438439Z <6> 2019-08-05 12:58:08.895 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module hubtester_receive]\n [Stop module hubtester_receive]\n [Update module hubtester_receive]\n)" 2019-08-05T12:58:10.095500310Z <6> 2019-08-05 12:58:10.095 +00:00 [INF] - Executing command: "Start module hubtester_receive" 2019-08-05T12:58:11.511738477Z <6> 2019-08-05 12:58:11.511 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module hubtester_send]\n [Stop module hubtester_send]\n [Update module hubtester_send]\n)]\n [Start module hubtester_send]\n)" 2019-08-05T12:58:11.511778215Z <6> 2019-08-05 12:58:11.511 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module hubtester_send]\n [Stop module hubtester_send]\n [Update module hubtester_send]\n)" 2019-08-05T12:58:12.635211397Z <6> 2019-08-05 12:58:12.634 +00:00 [INF] - Executing command: "Start module hubtester_send" 2019-08-05T12:58:14.029630819Z <6> 2019-08-05 12:58:14.029 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module edgeHub]\n [Stop module edgeHub]\n [Update module edgeHub]\n)]\n [Start module edgeHub]\n)" 2019-08-05T12:58:14.044407144Z <6> 2019-08-05 12:58:14.034 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module edgeHub]\n [Stop module edgeHub]\n [Update module edgeHub]\n)" 2019-08-05T12:58:30.480121892Z <6> 2019-08-05 12:58:30.478 +00:00 [INF] - Executing command: "Start module edgeHub" 2019-08-05T12:58:31.890373339Z <6> 2019-08-05 12:58:31.886 +00:00 [INF] - Plan execution ended for deployment 30 2019-08-05T12:58:32.430162670Z <6> 2019-08-05 12:58:32.429 +00:00 [INF] - Updated reported properties 2019-08-05T12:58:37.852355694Z <6> 2019-08-05 12:58:37.851 +00:00 [INF] - Updated reported properties ```
edge-hub logs ``` 2019-08-05T12:58:31.840011036Z 2019-08-05 12:58:31 Starting Edge Hub 2019-08-05T12:58:32.015463754Z 2019-08-05 12:58:32.008 +00:00 Edge Hub Main() 2019-08-05T12:58:33.592780655Z [08/05/2019 12:58:33.592 PM] Found intermediate certificates: [CN=iotedged workload ca:10/19/2019 15:46:03],[CN=Test Edge Device CA:10/19/2019 15:46:03],[CN=Test Edge Owner CA:10/19/2019 15:46:03] 2019-08-05T12:58:35.209366618Z <6> 2019-08-05 12:58:35.174 +00:00 [INF] - Created persistent store at /tmp/edgeHub 2019-08-05T12:58:35.269115555Z <6> 2019-08-05 12:58:35.268 +00:00 [INF] - Initializing Edge Hub 2019-08-05T12:58:35.270104228Z <6> 2019-08-05 12:58:35.269 +00:00 [INF] - 2019-08-05T12:58:35.270128641Z █████╗ ███████╗██╗ ██╗██████╗ ███████╗ 2019-08-05T12:58:35.270134657Z ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ 2019-08-05T12:58:35.270138892Z ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ 2019-08-05T12:58:35.270143043Z ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ 2019-08-05T12:58:35.270147074Z ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ 2019-08-05T12:58:35.270151236Z ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ 2019-08-05T12:58:35.270155307Z 2019-08-05T12:58:35.270158917Z ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ 2019-08-05T12:58:35.270163319Z ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ 2019-08-05T12:58:35.270167575Z ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ 2019-08-05T12:58:35.270171809Z ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ 2019-08-05T12:58:35.270175895Z ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ 2019-08-05T12:58:35.270180084Z ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ 2019-08-05T12:58:35.270184297Z 2019-08-05T12:58:35.272825520Z <6> 2019-08-05 12:58:35.272 +00:00 [INF] - Version - 1.0.8.23694809 (f5186c42ebb721893c5a497c789236803de42fb7) 2019-08-05T12:58:35.272855430Z <6> 2019-08-05 12:58:35.272 +00:00 [INF] - OptimizeForPerformance=True 2019-08-05T12:58:35.297490069Z <6> 2019-08-05 12:58:35.278 +00:00 [INF] - Loaded server certificate with expiration date of "2019-10-19T15:46:03.0000000+00:00" 2019-08-05T12:58:35.349609713Z <6> 2019-08-05 12:58:35.349 +00:00 [INF] - Created device scope identities cache 2019-08-05T12:58:35.349895823Z <6> 2019-08-05 12:58:35.349 +00:00 [INF] - Created new message store 2019-08-05T12:58:35.365184737Z <6> 2019-08-05 12:58:35.364 +00:00 [INF] - Starting refresh of device scope identities cache 2019-08-05T12:58:35.519023287Z <6> 2019-08-05 12:58:35.518 +00:00 [INF] - Started task to cleanup processed and stale messages 2019-08-05T12:58:35.678499421Z <6> 2019-08-05 12:58:35.678 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 2019-08-05T12:58:35.780480571Z <6> 2019-08-05 12:58:35.780 +00:00 [INF] - Initialized storing twin manager 2019-08-05T12:58:35.817755152Z <6> 2019-08-05 12:58:35.817 +00:00 [INF] - Initializing configuration 2019-08-05T12:58:35.851672623Z <6> 2019-08-05 12:58:35.851 +00:00 [INF] - New device connection for device louan-mba/$edgeHub 2019-08-05T12:58:36.115155718Z <6> 2019-08-05 12:58:36.114 +00:00 [INF] - Attempting to connect to IoT Hub for client louan-mba/$edgeHub via AMQP over WebSockets... 2019-08-05T12:58:36.268675976Z <6> 2019-08-05 12:58:36.268 +00:00 [INF] - Starting periodic operation Get EdgeHub config... 2019-08-05T12:58:36.377075423Z <6> 2019-08-05 12:58:36.376 +00:00 [INF] - Started operation Get EdgeHub config 2019-08-05T12:58:36.380476126Z <6> 2019-08-05 12:58:36.380 +00:00 [INF] - Initialized edge hub configuration 2019-08-05T12:58:36.454695441Z <6> 2019-08-05 12:58:36.454 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds 2019-08-05T12:58:36.829047909Z <6> 2019-08-05 12:58:36.828 +00:00 [INF] - Scheduling server certificate renewal for "2019-10-19T15:43:33.0004010Z". 2019-08-05T12:58:36.833875694Z <6> 2019-08-05 12:58:36.833 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) 2019-08-05T12:58:36.841647189Z <6> 2019-08-05 12:58:36.841 +00:00 [INF] - Starting MQTT head 2019-08-05T12:58:36.904025656Z <6> 2019-08-05 12:58:36.903 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. 2019-08-05T12:58:37.006398002Z <6> 2019-08-05 12:58:37.006 +00:00 [INF] - Starting AMQP head 2019-08-05T12:58:37.046867077Z <6> 2019-08-05 12:58:37.046 +00:00 [INF] - Started MQTT head 2019-08-05T12:58:37.231588987Z <6> 2019-08-05 12:58:37.230 +00:00 [INF] - Started AMQP head 2019-08-05T12:58:37.241618229Z <6> 2019-08-05 12:58:37.241 +00:00 [INF] - Starting HTTP head 2019-08-05T12:58:37.637223859Z <6> 2019-08-05 12:58:37.636 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest. 2019-08-05T12:58:37.702678460Z <6> 2019-08-05 12:58:37.702 +00:00 [INF] - Creating key {b04d66cc-8250-41b3-b191-8b318ab4d9a1} with creation date 2019-08-05 12:58:37Z, activation date 2019-08-05 12:58:37Z, and expiration date 2019-11-03 12:58:37Z. 2019-08-05T12:58:37.758813783Z <4> 2019-08-05 12:58:37.758 +00:00 [WRN] - No XML encryptor configured. Key {b04d66cc-8250-41b3-b191-8b318ab4d9a1} may be persisted to storage in unencrypted form. 2019-08-05T12:58:37.786386829Z <6> 2019-08-05 12:58:37.782 +00:00 [INF] - Writing data to file '"/home/edgehubuser/.aspnet/DataProtection-Keys/key-b04d66cc-8250-41b3-b191-8b318ab4d9a1.xml"'. 2019-08-05T12:58:38.788463167Z <4> 2019-08-05 12:58:38.788 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. 2019-08-05T12:58:38.836632596Z <6> 2019-08-05 12:58:38.836 +00:00 [INF] - Started HTTP head 2019-08-05T12:58:39.839405547Z <6> 2019-08-05 12:58:39.839 +00:00 [INF] - Exiting disconnected state 2019-08-05T12:58:39.844201198Z <6> 2019-08-05 12:58:39.843 +00:00 [INF] - Received device connected callback 2019-08-05T12:58:39.868878092Z <6> 2019-08-05 12:58:39.868 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. 2019-08-05T12:58:39.870110549Z <6> 2019-08-05 12:58:39.869 +00:00 [INF] - Processing subscriptions for client louan-mba/$edgeHub. 2019-08-05T12:58:39.883478180Z <6> 2019-08-05 12:58:39.883 +00:00 [INF] - Cloud connection for louan-mba/$edgeHub is True 2019-08-05T12:58:39.895279155Z <6> 2019-08-05 12:58:39.895 +00:00 [INF] - Connection status for louan-mba/$edgeHub changed to ConnectionEstablished 2019-08-05T12:58:39.903147478Z <6> 2019-08-05 12:58:39.902 +00:00 [INF] - Starting refresh of device scope identities cache 2019-08-05T12:58:39.924606321Z <6> 2019-08-05 12:58:39.924 +00:00 [INF] - Entering connected state 2019-08-05T12:58:39.938431340Z <6> 2019-08-05 12:58:39.937 +00:00 [INF] - Created cloud proxy for client louan-mba/$edgeHub via AMQP over WebSockets, with client operation timeout 20 seconds. 2019-08-05T12:58:39.959643887Z <6> 2019-08-05 12:58:39.958 +00:00 [INF] - Initialized cloud proxy 25ec274a-0db6-4271-ab31-a92522ed260a for louan-mba/$edgeHub 2019-08-05T12:58:39.968745017Z <6> 2019-08-05 12:58:39.963 +00:00 [INF] - Created cloud connection for client louan-mba/$edgeHub 2019-08-05T12:58:40.790236844Z <6> 2019-08-05 12:58:40.790 +00:00 [INF] - Updated reported properties for louan-mba/$edgeHub 2019-08-05T12:58:40.875802379Z <6> 2019-08-05 12:58:40.875 +00:00 [INF] - Done syncing reported properties for louan-mba/$edgeHub 2019-08-05T12:58:41.260656881Z <6> 2019-08-05 12:58:41.260 +00:00 [INF] - Obtained edge hub config from module twin 2019-08-05T12:58:41.941685485Z <6> 2019-08-05 12:58:41.941 +00:00 [INF] - Client louan-mba/hubtester_receive in device scope authenticated locally. 2019-08-05T12:58:41.942001639Z <6> 2019-08-05 12:58:41.941 +00:00 [INF] - Client louan-mba/hubtester_send in device scope authenticated locally. 2019-08-05T12:58:41.950372703Z <6> 2019-08-05 12:58:41.950 +00:00 [INF] - Successfully generated identity for clientId louan-mba/hubtester_receive and username wps-staging-hub.azure-devices.net/louan-mba/hubtester_receive/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.12%20(native%3b%20Linux%3b%20x86_64) 2019-08-05T12:58:41.975795556Z <6> 2019-08-05 12:58:41.975 +00:00 [INF] - Successfully generated identity for clientId louan-mba/hubtester_send and username wps-staging-hub.azure-devices.net/louan-mba/hubtester_send/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.12%20(native%3b%20Linux%3b%20x86_64) 2019-08-05T12:58:41.979036247Z <6> 2019-08-05 12:58:41.978 +00:00 [INF] - ClientAuthenticated, louan-mba/hubtester_receive, 79c9a381 2019-08-05T12:58:41.985720349Z <6> 2019-08-05 12:58:41.985 +00:00 [INF] - ClientAuthenticated, louan-mba/hubtester_send, 51de9f82 2019-08-05T12:58:42.043109714Z <6> 2019-08-05 12:58:42.042 +00:00 [INF] - Set the following 1 route(s) in edge hub 2019-08-05T12:58:42.043141600Z <6> 2019-08-05 12:58:42.042 +00:00 [INF] - send-to-reveive: FROM /messages/modules/hubtester_send/outputs/output1 INTO BrokeredEndpoint("/modules/hubtester_receive/inputs/input1") 2019-08-05T12:58:42.053459149Z <6> 2019-08-05 12:58:42.053 +00:00 [INF] - Updated message store TTL to 7200 seconds 2019-08-05T12:58:42.054786938Z <6> 2019-08-05 12:58:42.054 +00:00 [INF] - Updated the edge hub store and forward configuration 2019-08-05T12:58:42.062812556Z <6> 2019-08-05 12:58:42.062 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config 2019-08-05T12:58:42.091103136Z <6> 2019-08-05 12:58:42.090 +00:00 [INF] - New device connection for device louan-mba/hubtester_receive 2019-08-05T12:58:42.096304574Z <6> 2019-08-05 12:58:42.096 +00:00 [INF] - New device connection for device louan-mba/hubtester_send 2019-08-05T12:58:42.121906138Z <6> 2019-08-05 12:58:42.121 +00:00 [INF] - Bind device proxy for device louan-mba/hubtester_send 2019-08-05T12:58:42.124277669Z <6> 2019-08-05 12:58:42.124 +00:00 [INF] - Binding message channel for device Id louan-mba/hubtester_send 2019-08-05T12:58:42.124932582Z <6> 2019-08-05 12:58:42.124 +00:00 [INF] - Bind device proxy for device louan-mba/hubtester_receive 2019-08-05T12:58:42.125095225Z <6> 2019-08-05 12:58:42.125 +00:00 [INF] - Binding message channel for device Id louan-mba/hubtester_receive 2019-08-05T12:58:42.187118911Z <6> 2019-08-05 12:58:42.186 +00:00 [INF] - Processing subscriptions ModuleMessages for client louan-mba/hubtester_receive. 2019-08-05T12:58:42.198256631Z <6> 2019-08-05 12:58:42.198 +00:00 [INF] - Attempting to connect to IoT Hub for client louan-mba/hubtester_receive via AMQP over WebSockets... 2019-08-05T12:58:42.237724040Z <6> 2019-08-05 12:58:42.237 +00:00 [INF] - Set subscriptions from session state for louan-mba/hubtester_receive 2019-08-05T12:58:42.402725954Z <6> 2019-08-05 12:58:42.401 +00:00 [INF] - Processing subscriptions ModuleMessages for client louan-mba/hubtester_send. 2019-08-05T12:58:42.470491778Z <6> 2019-08-05 12:58:42.470 +00:00 [INF] - Set subscriptions from session state for louan-mba/hubtester_send 2019-08-05T12:58:42.866897397Z <6> 2019-08-05 12:58:42.864 +00:00 [INF] - Cloud connection for louan-mba/hubtester_receive is True 2019-08-05T12:58:42.866940790Z <6> 2019-08-05 12:58:42.864 +00:00 [INF] - Connection status for louan-mba/hubtester_receive changed to ConnectionEstablished 2019-08-05T12:58:42.867050229Z <6> 2019-08-05 12:58:42.864 +00:00 [INF] - Created cloud proxy for client louan-mba/hubtester_receive via AMQP over WebSockets, with client operation timeout 20 seconds. 2019-08-05T12:58:42.867060558Z <6> 2019-08-05 12:58:42.864 +00:00 [INF] - Initialized cloud proxy 9a39c082-5c63-4673-940f-06e9b9f49a81 for louan-mba/hubtester_receive 2019-08-05T12:58:42.871292689Z <6> 2019-08-05 12:58:42.870 +00:00 [INF] - Created cloud connection for client louan-mba/hubtester_receive 2019-08-05T12:58:42.873098209Z <6> 2019-08-05 12:58:42.872 +00:00 [INF] - Attempting to connect to IoT Hub for client louan-mba/hubtester_send via AMQP over WebSockets... 2019-08-05T12:58:43.487754365Z <6> 2019-08-05 12:58:43.487 +00:00 [INF] - Cloud connection for louan-mba/hubtester_send is True 2019-08-05T12:58:43.488173286Z <6> 2019-08-05 12:58:43.487 +00:00 [INF] - Connection status for louan-mba/hubtester_send changed to ConnectionEstablished 2019-08-05T12:58:43.488517912Z <6> 2019-08-05 12:58:43.488 +00:00 [INF] - Created cloud proxy for client louan-mba/hubtester_send via AMQP over WebSockets, with client operation timeout 20 seconds. 2019-08-05T12:58:43.488809294Z <6> 2019-08-05 12:58:43.488 +00:00 [INF] - Initialized cloud proxy 1da48441-9a07-4433-9b0d-4933c91c02d3 for louan-mba/hubtester_send 2019-08-05T12:58:43.489015923Z <6> 2019-08-05 12:58:43.488 +00:00 [INF] - Created cloud connection for client louan-mba/hubtester_send 2019-08-05T12:58:46.299362413Z <6> 2019-08-05 12:58:46.298 +00:00 [INF] - Updated reported properties for louan-mba/$edgeHub 2019-08-05T13:03:36.468109648Z <6> 2019-08-05 13:03:36.467 +00:00 [INF] - Reauthenticating connected clients 2019-08-05T13:08:36.454191946Z <6> 2019-08-05 13:08:36.453 +00:00 [INF] - Reauthenticating connected clients 2019-08-05T13:13:36.458514474Z <6> 2019-08-05 13:13:36.458 +00:00 [INF] - Reauthenticating connected clients 2019-08-05T13:18:36.455148123Z <6> 2019-08-05 13:18:36.454 +00:00 [INF] - Reauthenticating connected clients 2019-08-05T13:23:36.458338937Z <6> 2019-08-05 13:23:36.458 +00:00 [INF] - Reauthenticating connected clients ```

Additional Information

emmanuel-bv commented 5 years ago

Hi @LouanDuToitS3 , We released patch 1.0.8.1 to address this issue last week: https://github.com/Azure/azure-iotedge/releases/tag/1.0.8.1

Could you please give it a try to see if that fixes yoru issue?

Thanks, Emmanuel

LouanDuToitS3 commented 5 years ago

Hi @ebertrams that is great news, I'll start testing, and will let you know if it fixes my issue.

LouanDuToitS3 commented 5 years ago

Hi @ebertrams the issue is resolved. Thank you!

github-actions[bot] commented 5 years ago

This issue is being marked as stale because it has been open for 30 days with no activity.