Unexpected Disconnect: rc 7 - The connection was lost

Niels Vedel Favetronics.dk 5 Reputation points
2023-11-14T12:00:46.2933333+00:00

Even though the SAS token is updated, I get disconnected appr 4 minutes after expiration of ttl:

2023/11/14 12:37:01 Updating SAS Token... Updating SAS Token... 2023/11/14 12:37:01 SAS Token update succeeded SAS Token update succeeded 2023/11/14 12:37:03 Sending PINGREQ Sending PINGREQ 2023/11/14 12:37:03 Received PINGRESP Received PINGRESP 2023/11/14 12:38:01 Unexpected Disconnect: rc 7 - The connection was lost. Unexpected Disconnect: rc 7 - The connection was lost. 2023/11/14 12:38:01 Client State: DISCONNECTED Client State: DISCONNECTED

My code should be very simple:

import traceback
# Add a logging handler so we can see the raw communication data
import logging
import sys
root = logging.getLogger()
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%Y/%m/%d %H:%M:%S')
root.setLevel(logging.DEBUG)
requests_log = logging.getLogger("requests.packages.urllib3")
requests_log.setLevel(logging.DEBUG)
requests_log.propagate = True
ch = logging.StreamHandler(sys.stdout)
root.addHandler(ch)


CONNECTION_STRING = >>connectionString<<

import asyncio	
import os	
from azure.iot.device import (	
    IoTHubSession,	
    DirectMethodResponse,	
)	
	
from azure.iot.device.mqtt_client import(	
    MQTTError,	
    MQTTConnectionFailedError,	
)	


async def receive_c2d_messages(session):	
    async with session.messages() as messages:	
        print("Waiting to receive messages...")	
        async for message in messages:	
            print("Message received with payload: {}".format(message.payload))
	


async def main():	
    while True:	
        try:	
            timeToLive = 5 * 60 
            print("Connecting to IoT Hub with ttl = "+format(timeToLive)+"sec...")	
            session = IoTHubSession.from_connection_string(CONNECTION_STRING, sastoken_ttl=timeToLive)
            async with session:	
                print("Connected to IoT Hub")
                task_receive_c2d_messages = asyncio.create_task(receive_c2d_messages(session))
                await asyncio.gather(
                  task_receive_c2d_messages,	
                )	
            
        except ConnectionAbortedError:	
            print("ConnectionAbortedError.")	
            traceback.print_exc()
	
        except MQTTConnectionFailedError:	
            print("Could not connect.")	
            traceback.print_exc()
	
        except MQTTError:	
            print("MQTTError.")	
            traceback.print_exc()
            
        except Exception as e:
            print (e)
            print("Unexpected error in main().")
            traceback.print_exc()
            
        try:
          print("Ending task_receive_c2d_messages...")
          task_receive_c2d_messages.cancel()
        except:
          traceback.print_exc()
        
        await asyncio.sleep(1)
        
        


    
if __name__ == "__main__":
  exit = 0
  while exit == 0:
    try:	
        asyncio.run(main())	
    except KeyboardInterrupt:	
        # Exit application because user indicated they wish to exit.	
        # This will have cancelled `main()` implicitly.	
        print("")
        print("User initiated exit. Exiting.", flush=True)	
        exit = 1
    except:
        print('Unhandled exception - Rebooting', flush=True) # Should not happen
        traceback.print_exc()
        os.system("sudo reboot")
    finally:	
        print("Leaving program...", flush=True)

Anyone who can guide me in the right direction?

This is the full output for the code - it's started 12:28 with ttl set to 5 min.

Everything looks fine until 12:38:01 where the connection is suddenly lost.

2023/11/14 12:28:01 Using selector: EpollSelector
Using selector: EpollSelector
Connecting to IoT Hub with ttl = 300sec...
2023/11/14 12:28:01 Creating MQTTClient
Creating MQTTClient
2023/11/14 12:28:01 Using GronborgIoTHubTEST.azure-devices.net as hostname
Using GronborgIoTHubTEST.azure-devices.net as hostname
2023/11/14 12:28:01 Using IoTHub Device. Client ID is Location0032
Using IoTHub Device. Client ID is Location0032
2023/11/14 12:28:01 Using MQTT over TCP
Using MQTT over TCP
2023/11/14 12:28:01 Creating Paho client
Creating Paho client
2023/11/14 12:28:01 Configuring Paho client for connecting using MQTT over TCP
Configuring Paho client for connecting using MQTT over TCP
2023/11/14 12:28:01 Starting SasTokenProvider
Starting SasTokenProvider
2023/11/14 12:28:01 Using SASToken as password
Using SASToken as password
2023/11/14 12:28:01 Connecting to IoTHub...
Connecting to IoTHub...
2023/11/14 12:28:01 Attempting connect to host GronborgIoTHubTEST.azure-devices.net using port 8883...
Attempting connect to host GronborgIoTHubTEST.azure-devices.net using port 8883...
2023/11/14 12:28:01 Starting the 'process_twin_responses' background task
Starting the 'process_twin_responses' background task
2023/11/14 12:28:01 Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'Location0032'
Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'Location0032'
2023/11/14 12:28:01 Connect returned rc 0 - No error.
Connect returned rc 0 - No error.
2023/11/14 12:28:01 Starting Paho network loop
Starting Paho network loop
2023/11/14 12:28:01 Waiting for connect response...
Waiting for connect response...
2023/11/14 12:28:01 Received CONNACK (1, 0)
Received CONNACK (1, 0)
2023/11/14 12:28:01 Connect Response: rc 0 - Connection Accepted.
Connect Response: rc 0 - Connection Accepted.
2023/11/14 12:28:01 Client State: CONNECTED
Client State: CONNECTED
2023/11/14 12:28:01 Connect succeeded
Connect succeeded
Connected to IoT Hub
2023/11/14 12:28:01 Enabling receive for C2D messages...
Enabling receive for C2D messages...
2023/11/14 12:28:01 Attempting subscribe to topic devices/Location0032/messages/devicebound/#
Attempting subscribe to topic devices/Location0032/messages/devicebound/#
2023/11/14 12:28:01 Sending SUBSCRIBE (d0, m1) [(b'devices/Location0032/messages/devicebound/#', 1)]
Sending SUBSCRIBE (d0, m1) [(b'devices/Location0032/messages/devicebound/#', 1)]
2023/11/14 12:28:01 Subscribe returned rc 0 - No error.
Subscribe returned rc 0 - No error.
2023/11/14 12:28:01 Waiting for SUBACK for mid 1
Waiting for SUBACK for mid 1
2023/11/14 12:28:01 Received SUBACK
Received SUBACK
2023/11/14 12:28:01 SUBACK received for mid 1
SUBACK received for mid 1
2023/11/14 12:28:01 C2D message receive enabled
C2D message receive enabled
Waiting to receive messages...
2023/11/14 12:29:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:29:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:30:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:30:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:31:01 Updating SAS Token...
Updating SAS Token...
2023/11/14 12:31:01 SAS Token update succeeded
SAS Token update succeeded
2023/11/14 12:31:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:31:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:32:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:32:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:33:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:33:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:34:01 Updating SAS Token...
Updating SAS Token...
2023/11/14 12:34:01 SAS Token update succeeded
SAS Token update succeeded
2023/11/14 12:34:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:34:02 Received PINGRESP
Received PINGRESP
2023/11/14 12:35:02 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:35:03 Received PINGRESP
Received PINGRESP
2023/11/14 12:36:03 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:36:03 Received PINGRESP
Received PINGRESP
2023/11/14 12:37:01 Updating SAS Token...
Updating SAS Token...
2023/11/14 12:37:01 SAS Token update succeeded
SAS Token update succeeded
2023/11/14 12:37:03 Sending PINGREQ
Sending PINGREQ
2023/11/14 12:37:03 Received PINGRESP
Received PINGRESP
2023/11/14 12:38:01 Unexpected Disconnect: rc 7 - The connection was lost.
Unexpected Disconnect: rc 7 - The connection was lost.
2023/11/14 12:38:01 Client State: DISCONNECTED
Client State: DISCONNECTED
2023/11/14 12:38:01 Disabling receive for C2D messages...
Disabling receive for C2D messages...
2023/11/14 12:38:01 Attempting unsubscribe from topic devices/Location0032/messages/devicebound/#
Attempting unsubscribe from topic devices/Location0032/messages/devicebound/#
2023/11/14 12:38:01 Unsubscribe returned rc 4 - The client is not currently connected.
Unsubscribe returned rc 4 - The client is not currently connected.
2023/11/14 12:38:01 Disconnecting from IoTHub...
Disconnecting from IoTHub...
2023/11/14 12:38:01 Attempting disconnect
Attempting disconnect
2023/11/14 12:38:01 Disconnect returned rc 4 - The client is not currently connected.
Disconnect returned rc 4 - The client is not currently connected.
2023/11/14 12:38:01 Early disconnect return (Already disconnected)
Early disconnect return (Already disconnected)
2023/11/14 12:38:01 Clearing network loop task
Clearing network loop task
2023/11/14 12:38:01 Clearing previous disconnection cause
Clearing previous disconnection cause
2023/11/14 12:38:01 Disconnect succeeded
Disconnect succeeded
2023/11/14 12:38:01 Stopping IoTHubMQTTClient...
Stopping IoTHubMQTTClient...
2023/11/14 12:38:01 Cancelling 'process_twin_responses' background task
Cancelling 'process_twin_responses' background task
2023/11/14 12:38:01 Disconnecting from IoTHub...
Disconnecting from IoTHub...
2023/11/14 12:38:01 Already disconnected!
Already disconnected!
2023/11/14 12:38:01 Disconnect succeeded
Disconnect succeeded
2023/11/14 12:38:01 Stopping SasTokenProvider
Stopping SasTokenProvider
MQTTError.
Traceback (most recent call last):
  File "/home/comforttan/MQTTtst.py", line 47, in main
    await asyncio.gather(
  File "/home/comforttan/MQTTtst.py", line 33, in receive_c2d_messages
    async for message in messages:
  File "/usr/local/lib/python3.9/dist-packages/azure/iot/device/iothub_session.py", line 349, in wrapping_generator
    raise cause
azure.iot.device.mqtt_client.MQTTError: The connection was lost.
Ending task_receive_c2d_messages...
Connecting to IoT Hub with ttl = 300sec...
2023/11/14 12:38:02 Creating MQTTClient
Creating MQTTClient
2023/11/14 12:38:02 Using GronborgIoTHubTEST.azure-devices.net as hostname
Using GronborgIoTHubTEST.azure-devices.net as hostname
2023/11/14 12:38:02 Using IoTHub Device. Client ID is Location0032
Using IoTHub Device. Client ID is Location0032
2023/11/14 12:38:02 Using MQTT over TCP
Using MQTT over TCP
2023/11/14 12:38:02 Creating Paho client
Creating Paho client
2023/11/14 12:38:02 Configuring Paho client for connecting using MQTT over TCP
Configuring Paho client for connecting using MQTT over TCP
2023/11/14 12:38:02 Starting SasTokenProvider
Starting SasTokenProvider
2023/11/14 12:38:02 Using SASToken as password
Using SASToken as password
2023/11/14 12:38:02 Connecting to IoTHub...
Connecting to IoTHub...
2023/11/14 12:38:02 Attempting connect to host GronborgIoTHubTEST.azure-devices.net using port 8883...
Attempting connect to host GronborgIoTHubTEST.azure-devices.net using port 8883...
2023/11/14 12:38:02 Starting the 'process_twin_responses' background task
Starting the 'process_twin_responses' background task
2023/11/14 12:38:03 Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'Location0032'
Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'Location0032'
2023/11/14 12:38:03 Connect returned rc 0 - No error.
Connect returned rc 0 - No error.
2023/11/14 12:38:03 Starting Paho network loop
Starting Paho network loop
2023/11/14 12:38:03 Waiting for connect response...
Waiting for connect response...
2023/11/14 12:38:03 Received CONNACK (1, 0)
Received CONNACK (1, 0)
2023/11/14 12:38:03 Connect Response: rc 0 - Connection Accepted.
Connect Response: rc 0 - Connection Accepted.
2023/11/14 12:38:03 Client State: CONNECTED
Client State: CONNECTED
2023/11/14 12:38:03 Connect succeeded
Connect succeeded
Connected to IoT Hub
2023/11/14 12:38:03 Enabling receive for C2D messages...
Enabling receive for C2D messages...
2023/11/14 12:38:03 Attempting subscribe to topic devices/Location0032/messages/devicebound/#
Attempting subscribe to topic devices/Location0032/messages/devicebound/#
2023/11/14 12:38:03 Sending SUBSCRIBE (d0, m1) [(b'devices/Location0032/messages/devicebound/#', 1)]
Sending SUBSCRIBE (d0, m1) [(b'devices/Location0032/messages/devicebound/#', 1)]
2023/11/14 12:38:03 Subscribe returned rc 0 - No error.
Subscribe returned rc 0 - No error.
2023/11/14 12:38:03 Waiting for SUBACK for mid 1
Waiting for SUBACK for mid 1
2023/11/14 12:38:03 Received SUBACK
Received SUBACK
2023/11/14 12:38:03 SUBACK received for mid 1
SUBACK received for mid 1
2023/11/14 12:38:03 C2D message receive enabled
C2D message receive enabled
Waiting to receive messages...
Azure IoT Hub
Azure IoT Hub
An Azure service that enables bidirectional communication between internet of things (IoT) devices and applications.
1,127 questions

1 answer

Sort by: Most helpful
Most helpful Newest Oldest
  1. LeelaRajeshSayana-MSFT 13,471 Reputation points
    2023-11-15T18:30:33.28+00:00

    Hi @Niels Vedel Favetronics.dk Greetings! Welcome to Microsoft Q&A forum. Thank you for posting this question here.

    Based on the log messages you have included in the question; I could see that there are lot of ping requests happening between the client and the IoT Hub. These happen when the MQTT communication is open but there is no communication shared. The ping request timing is controlled by the keep_alive parameter of the from_connection_string method. Since there is no communication between the IoT Hub and the device, the session could likely be terminated by the IoT Hub regardless of the value of the sastoken_ttl parameter.

    If you are planning to read messages send to a device, a better way to handle this is by routing the messages to a custom end point such as Event Hub and consume the events from it. Please refer the resource Route data to Event Hub and Send or receive events from Event Hub for more details on this.

    Hope this helps. Please let us know if you have any further questions on this.

    Work around

    Setting the sastoken_ttl to 24 hours helped resolve the disconnect issue.

    If the response helped, please do click Accept Answer and Yes for the answer provided. Doing so would help other community members with similar issue identify the solution. I highly appreciate your contribution to the community.