pythonpython-3.xazureazure-iot-hubazure-iot-sdk

Microsoft Azure IoT Python SDK Can Successfully Provision but Not Connect with Same Credentials


I am using Python 3.8.2 on Linux and the azure iot python sdk version 2. I have setup device provisioning in the Azure Portal and can successfully provision my device using the following code.

Provisioning code:

# Imports for Azure
from azure.iot.device import ProvisioningDeviceClient, X509
from azure.iot.device import IoTHubDeviceClient, Message

def runAzureProvisioning(azureConfig):

    # -------------------------------------------------------------------------
    # Copyright (c) Microsoft Corporation. All rights reserved.
    # Licensed under the MIT License. See License.txt in the project root for
    # license information.
    # --------------------------------------------------------------------------

    provisioning_host = azureConfig["PROVISIONING_HOST"]
    id_scope = azureConfig["PROVISIONING_IDSCOPE"]
    registration_id = azureConfig["DPS_X509_REGISTRATION_ID"]

    x509 = X509(
        cert_file=azureConfig["X509_CERT_FILE"],
        key_file=azureConfig["X509_KEY_FILE"],
        pass_phrase=azureConfig["PASS_PHRASE"],
    )

    provisioning_device_client = ProvisioningDeviceClient.create_from_x509_certificate(
        provisioning_host=provisioning_host,
        registration_id=registration_id,
        id_scope=id_scope,
        x509=x509,
    )

    registration_result = provisioning_device_client.register()

    # The result can be directly printed to view the important details.
    app.config['LOGGER'].info(registration_result)

    if registration_result.status == "assigned":
        app.config['LOGGER'].info("Will send telemetry from the provisioned device")
        # Create device client from the above result
        device_client = IoTHubDeviceClient.create_from_x509_certificate(
            x509=x509,
            hostname=registration_result.registration_state.assigned_hub,
            device_id=registration_result.registration_state.device_id,
        )

        # Connect the client.
        device_client.connect()

        for i in range(1, 2):
            app.config['LOGGER'].info("sending message #" + str(i))
            device_client.send_message("test payload message " + str(i))
            time.sleep(1)
        return 0, f"{registration_result.registration_state.device_id}"

    else:
        app.config['LOGGER'].info("Can not send telemetry from the provisioned device")
        return 1,"Can not send telemetry from the provisioned device"

Provisioning Output:

2021-02-10 19:59:58,313 - azure.iot.device.common.mqtt_transport:137 - INFO - creating mqtt client
2021-02-10 19:59:58,317 - azure.iot.device.common.mqtt_transport:150 - INFO - Creating client for connecting using MQTT over TCP
2021-02-10 19:59:58,412 - azure.iot.device.provisioning.provisioning_device_client:70 - INFO - Registering with Provisioning Service...
2021-02-10 19:59:58,416 - azure.iot.device.provisioning.provisioning_device_client:91 - INFO - Enabling reception of response from Device Provisioning Service...
2021-02-10 19:59:58,428 - azure.iot.device.common.pipeline.pipeline_stages_base:955 - INFO - ReconnectStage(ConnectOperation): State changes LOGICALLY_DISCONNECTED->LOGICALLY_CONNECTED.  Adding to wait list and sending new connect op down
2021-02-10 19:59:58,435 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:171 - INFO - MQTTTransportStage(ConnectOperation): connecting
2021-02-10 19:59:58,443 - azure.iot.device.common.mqtt_transport:374 - INFO - connecting to mqtt broker
2021-02-10 19:59:58,447 - azure.iot.device.common.mqtt_transport:385 - INFO - Connect using port 8883 (TCP)
2021-02-10 20:00:01,583 - azure.iot.device.common.mqtt_transport:180 - INFO - connected with result code: 0
2021-02-10 20:00:01,589 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:275 - INFO - _on_mqtt_connected called
2021-02-10 20:00:01,599 - azure.iot.device.common.pipeline.pipeline_stages_base:552 - INFO - ConnectionLockStage(ConnectOperation): processing 0 items in queue
2021-02-10 20:00:01,607 - azure.iot.device.common.pipeline.pipeline_stages_base:1141 - INFO - ReconnectStage: completing waiting ops with error=None
2021-02-10 20:00:01,612 - azure.iot.device.common.pipeline.pipeline_stages_base:411 - INFO - AutoConnectStage(MQTTSubscribeOperation): Connected.  Sending down and adding callback to check result
2021-02-10 20:00:01,621 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:225 - INFO - MQTTTransportStage(MQTTSubscribeOperation): subscribing to $dps/registrations/res/#
2021-02-10 20:00:01,625 - azure.iot.device.common.mqtt_transport:474 - INFO - subscribing to $dps/registrations/res/# with qos 1
2021-02-10 20:00:01,706 - azure.iot.device.common.mqtt_transport:234 - INFO - suback received for 1
2021-02-10 20:00:01,718 - azure.iot.device.provisioning.provisioning_device_client:98 - INFO - Successfully subscribed to Device Provisioning Service to receive responses
2021-02-10 20:00:01,736 - azure.iot.device.common.pipeline.pipeline_stages_base:411 - INFO - AutoConnectStage(MQTTPublishOperation): Connected.  Sending down and adding callback to check result
2021-02-10 20:00:01,741 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:211 - INFO - MQTTTransportStage(MQTTPublishOperation): publishing on $dps/registrations/PUT/iotdps-register/?$rid=aa969347-7e41-41e4-b874-54b995f129ef
2021-02-10 20:00:01,747 - azure.iot.device.common.mqtt_transport:533 - INFO - publishing on $dps/registrations/PUT/iotdps-register/?$rid=aa969347-7e41-41e4-b874-54b995f129ef
2021-02-10 20:00:01,817 - azure.iot.device.common.mqtt_transport:248 - INFO - payload published for 2
2021-02-10 20:00:02,066 - azure.iot.device.common.mqtt_transport:255 - INFO - message received on $dps/registrations/res/202/?$rid=aa969347-7e41-41e4-b874-54b995f129ef&retry-after=3
2021-02-10 20:00:02,074 - azure.iot.device.provisioning.pipeline.pipeline_stages_provisioning_mqtt:129 - INFO - Received payload:b'{"operationId":"4.bd46492d8689531e.a04c1182-f5d8-4ea7-b2fd-4902abb2f789","status":"assigning"}' on topic:$dps/registrations/res/202/?$rid=aa969347-7e41-41e4-b874-54b995f129ef&retry-after=3
2021-02-10 20:00:02,086 - azure.iot.device.provisioning.pipeline.pipeline_stages_provisioning:399 - WARNING - RegistrationStage(RequestAndResponseOperation): Op will transition into polling after interval 2.  Setting timer.
2021-02-10 20:00:04,099 - azure.iot.device.provisioning.pipeline.pipeline_stages_provisioning:384 - INFO - RegistrationStage(RequestAndResponseOperation): polling
2021-02-10 20:00:04,111 - azure.iot.device.common.pipeline.pipeline_stages_base:411 - INFO - AutoConnectStage(MQTTPublishOperation): Connected.  Sending down and adding callback to check result
2021-02-10 20:00:04,116 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:211 - INFO - MQTTTransportStage(MQTTPublishOperation): publishing on $dps/registrations/GET/iotdps-get-operationstatus/?$rid=04db5bb9-5e70-45cf-91a6-6d9df8a34478&operationId=4.bd46492d8689531e.a04c1182-f5d8-4ea7-b2fd-4902abb2f789
2021-02-10 20:00:04,120 - azure.iot.device.common.mqtt_transport:533 - INFO - publishing on $dps/registrations/GET/iotdps-get-operationstatus/?$rid=04db5bb9-5e70-45cf-91a6-6d9df8a34478&operationId=4.bd46492d8689531e.a04c1182-f5d8-4ea7-b2fd-4902abb2f789
2021-02-10 20:00:04,190 - azure.iot.device.common.mqtt_transport:248 - INFO - payload published for 3
2021-02-10 20:00:04,206 - azure.iot.device.common.mqtt_transport:255 - INFO - message received on $dps/registrations/res/200/?$rid=04db5bb9-5e70-45cf-91a6-6d9df8a34478
2021-02-10 20:00:04,213 - azure.iot.device.provisioning.pipeline.pipeline_stages_provisioning_mqtt:129 - INFO - Received payload:b'{"operationId":"4.bd46492d8689531e.a04c1182-f5d8-4ea7-b2fd-4902abb2f789","status":"assigned","registrationState":{"x509":{"enrollmentGroupId":"New-Gateway-Jack"},"registrationId":"New-Gateway-Jack","createdDateTimeUtc":"2021-02-10T20:00:02.2501194Z","assignedHub":"New-Gateway-Test-Jack.azure-devices.net","deviceId":"New-Gateway-Jack","status":"assigned","substatus":"initialAssignment","lastUpdatedDateTimeUtc":"2021-02-10T20:00:02.4704038Z","etag":"IjM1MDA2OGJjLTAwMDAtMDEwMC0wMDAwLTYwMjQzYjQyMDAwMCI="}}' on topic:$dps/registrations/res/200/?$rid=04db5bb9-5e70-45cf-91a6-6d9df8a34478
2021-02-10 20:00:04,231 - azure.iot.device.provisioning.abstract_provisioning_device_client:221 - INFO - Successfully registered with Provisioning Service
2021-02-10 20:00:04,235 - /usr/bin/company/cloudcredentials/app.py:442 - INFO - New-Gateway-Jack
New-Gateway-Test-Jack.azure-devices.net
initialAssignment
null
assigned
2021-02-10 20:00:04,239 - /usr/bin/company/cloudcredentials/app.py:445 - INFO - Will send telemetry from the provisioned device
2021-02-10 20:00:04,273 - azure.iot.device.common.mqtt_transport:137 - INFO - creating mqtt client
2021-02-10 20:00:04,277 - azure.iot.device.common.mqtt_transport:150 - INFO - Creating client for connecting using MQTT over TCP
2021-02-10 20:00:04,303 - azure.iot.device.iothub.sync_clients:112 - INFO - Connecting to Hub...
2021-02-10 20:00:04,315 - azure.iot.device.common.pipeline.pipeline_stages_base:955 - INFO - ReconnectStage(ConnectOperation): State changes LOGICALLY_DISCONNECTED->LOGICALLY_CONNECTED.  Adding to wait list and sending new connect op down
2021-02-10 20:00:04,321 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:171 - INFO - MQTTTransportStage(ConnectOperation): connecting
2021-02-10 20:00:04,329 - azure.iot.device.common.mqtt_transport:374 - INFO - connecting to mqtt broker
2021-02-10 20:00:04,333 - azure.iot.device.common.mqtt_transport:385 - INFO - Connect using port 8883 (TCP)
2021-02-10 20:00:04,951 - azure.iot.device.common.mqtt_transport:180 - INFO - connected with result code: 0
2021-02-10 20:00:04,957 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:275 - INFO - _on_mqtt_connected called
2021-02-10 20:00:04,966 - azure.iot.device.common.pipeline.pipeline_stages_base:552 - INFO - ConnectionLockStage(ConnectOperation): processing 0 items in queue
2021-02-10 20:00:04,969 - azure.iot.device.iothub.sync_clients:86 - INFO - Connection State - Connected
2021-02-10 20:00:04,975 - azure.iot.device.common.pipeline.pipeline_stages_base:1141 - INFO - ReconnectStage: completing waiting ops with error=None
2021-02-10 20:00:04,986 - azure.iot.device.iothub.sync_clients:118 - INFO - Successfully connected to Hub
2021-02-10 20:00:04,990 - /usr/bin/company/cloudcredentials/app.py:457 - INFO - sending message #1
2021-02-10 20:00:04,995 - azure.iot.device.iothub.sync_clients:166 - INFO - Sending message to Hub...
2021-02-10 20:00:05,004 - azure.iot.device.common.pipeline.pipeline_stages_base:411 - INFO - AutoConnectStage(MQTTPublishOperation): Connected.  Sending down and adding callback to check result
2021-02-10 20:00:05,009 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:211 - INFO - MQTTTransportStage(MQTTPublishOperation): publishing on devices/New-Gateway-Jack/messages/events/
2021-02-10 20:00:05,013 - azure.iot.device.common.mqtt_transport:533 - INFO - publishing on devices/New-Gateway-Jack/messages/events/
2021-02-10 20:00:05,295 - azure.iot.device.common.mqtt_transport:248 - INFO - payload published for 1
2021-02-10 20:00:05,306 - azure.iot.device.iothub.sync_clients:172 - INFO - Successfully sent message to Hub

Now, I am trying to connect ( not provision ) with the credentials I used to successfully provision and connect above using the following code.

Upon successful provisioning, I save the following data ( keys, certs, and strings ):

        # Now use the credentials to provision this device
        # NOTE: If the credentials were accepted by Azure, the message returned here is the 'device id'
        (status, message) = runAzureProvisioning(azureConfig)
        if status != 0:

            responseJson = {"response": f"error: Could not Run Azure provisioning script: {message}"}
            return make_response(jsonify(responseJson), 550)

        else:

            # Write the meta information out to a JSON file as well
            metaData = {}
            metaData['provisioning_host'] = f"{provisioninghost}"
            metaData['provisioning_id_scope'] = f"{provisioningidscope}"
            metaData['x509_registration_id'] = f"{x509registrationid}"
            metaData['device_id'] = f"{message}"
            metaData['key'] = f"{path.join(app.config['AZURE_CREDS_UPLOAD_PATH'], azureConfig['X509_KEY_FILE'])}"
            metaData['cert'] = f"{path.join(app.config['AZURE_CREDS_UPLOAD_PATH'], azureConfig['X509_CERT_FILE'])}"
            with open(f"{app.config['AZURE_CREDS_UPLOAD_PATH']}/meta.json", 'w') as outfile:
                json.dump(metaData, outfile)

            responseJson = {"response": f"success"}
            return make_response(jsonify(responseJson), 200)

Then, later I read that saved information, and try to connect:

            # Ensure we have everything we need to connect
            if not metaData.get("provisioning_host") or not metaData.get("provisioning_id_scope") \
                    or not metaData.get("x509_registration_id") or not metaData.get("key") or not metaData.get("cert") \
                    or not metaData.get("device_id"):
                responseJson = {"response": f"error: Could not find all required meta data in JSON store: {metaData}"}
                return make_response(jsonify(responseJson), 550)

            # Define the required credentials to establish a connection
            # Get the x.509 certificate path from the meta information
            x509 = X509(
                cert_file=metaData.get("cert"),
                key_file=metaData.get("key"),
                pass_phrase=None
            )

            # TODO: Get a proper hostname here
            client = IoTHubDeviceClient.create_from_x509_certificate(hostname=metaData.get("provisioning_host"), device_id=metaData.get("device_id"), x509=x509)

            # Try to connect
            try:

                # Attempt to connect
                app.config['LOGGER'].info(
                    f"Connecting with: {metaData.get('x509_registration_id')} | {metaData.get('key')} | {metaData.get('cert')}")
                client.connect()
                client.disconnect()

                responseJson = {"response": f"success"}
                return make_response(jsonify(responseJson), 200)

            except Exception as err:

                responseJson = {"response": f"error: Could not connect to AWS: {err}"}
                return make_response(jsonify(responseJson), 550)

But I get 'Unauthorised' and 'Connection Refused' errors as shown below:

2021-02-10 20:00:13,073 - azure.iot.device.common.mqtt_transport:137 - INFO - creating mqtt client
2021-02-10 20:00:13,078 - azure.iot.device.common.mqtt_transport:150 - INFO - Creating client for connecting using MQTT over TCP
2021-02-10 20:00:13,109 - /usr/bin/company/cloudcredentials/app.py:1190 - INFO - Connecting with: New-Gateway-Jack | /persistent-storage/azure-creds/device.key | /persistent-storage/azure-creds/device.crt
2021-02-10 20:00:13,114 - azure.iot.device.iothub.sync_clients:112 - INFO - Connecting to Hub...
2021-02-10 20:00:13,122 - azure.iot.device.common.pipeline.pipeline_stages_base:955 - INFO - ReconnectStage(ConnectOperation): State changes LOGICALLY_DISCONNECTED->LOGICALLY_CONNECTED.  Adding to wait list and sending new connect op down
2021-02-10 20:00:13,128 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:171 - INFO - MQTTTransportStage(ConnectOperation): connecting
2021-02-10 20:00:13,139 - azure.iot.device.common.mqtt_transport:374 - INFO - connecting to mqtt broker
2021-02-10 20:00:13,143 - azure.iot.device.common.mqtt_transport:385 - INFO - Connect using port 8883 (TCP)
2021-02-10 20:00:16,240 - azure.iot.device.common.mqtt_transport:180 - INFO - connected with result code: 5
2021-02-10 20:00:16,248 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:300 - INFO - MQTTTransportStage: _on_mqtt_connection_failure called: UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,254 - azure.iot.device.common.pipeline.pipeline_ops_base:107 - ERROR - ConnectOperation: completing with error UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,258 - azure.iot.device.common.mqtt_transport:206 - INFO - disconnected with result code: 5
2021-02-10 20:00:16,262 - azure.iot.device.common.pipeline.pipeline_stages_base:518 - ERROR - ConnectionLockStage(ConnectOperation): op failed.  Unblocking queue with error: UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,274 - azure.iot.device.common.pipeline.pipeline_stages_base:552 - INFO - ConnectionLockStage(ConnectOperation): processing 0 items in queue
2021-02-10 20:00:16,279 - azure.iot.device.common.pipeline.pipeline_stages_base:1141 - INFO - ReconnectStage: completing waiting ops with error=UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,283 - azure.iot.device.common.pipeline.pipeline_ops_base:107 - ERROR - ConnectOperation: completing with error UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,290 - azure.iot.device.common.evented_callback:48 - ERROR - Callback completed with error UnauthorizedError('Connection Refused: not authorised.')
2021-02-10 20:00:16,295 - azure.iot.device.common.evented_callback:49 - ERROR - NoneType: None

2021-02-10 20:00:16,383 - azure.iot.device.common.mqtt_transport:297 - INFO - Forcing paho disconnect to prevent it from automatically reconnecting
2021-02-10 20:00:16,390 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:322 - INFO - MQTTTransportStage: _on_mqtt_disconnect called: ConnectionFailedError('The connection was refused.')
2021-02-10 20:00:16,398 - azure.iot.device.common.pipeline.pipeline_stages_mqtt:360 - INFO - MQTTTransportStage: disconnection was unexpected
2021-02-10 20:00:16,400 - azure.iot.device.iothub.sync_clients:90 - INFO - Connection State - Disconnected
2021-02-10 20:00:16,409 - azure.iot.device.iothub.sync_clients:92 - INFO - Cleared all pending method requests due to disconnect
2021-02-10 20:00:16,404 - azure.iot.device.common.handle_exceptions:52 - INFO - Unexpected disconnection.  Safe to ignore since other stages will reconnect.
2021-02-10 20:00:16,422 - azure.iot.device.common.handle_exceptions:53 - INFO - azure.iot.device.common.transport_exceptions.ConnectionFailedError: ConnectionFailedError('The connection was refused.')

So, how come I can provision successfully, but cannot used those same credentials to connect with later?


Solution

  • The answer is that MS does not know how to solve this issue. There are two tickets on the same issue as you are having on github and microsoft docs.

    First it is important to know exact version of your azure-iot-sdk-python. The reporter had these:

    Software versions: Python==3.7.8 azure-iot-device==2.3.0

    I presume there is an regression in the azure-iot-sdk-python. Currently Microsoft does not know the cause of the issue.

    What to do?

    I would report it to Microsoft:

    Hello @VarunVenkatesh-7647, Could you please send us an email attaching your python app code. Please remove your IoT Central's ID scope, Device ID, and Primary key from the .py file before attaching it to the email.

    Please send an email to azcommunity@microsoft.com with the below details, so that we can work on this matter.

    Thread URL: Link to this thread. Subject : Attn Satish Boddu Attachment: your environmental_sensor.py file.

    Next to try is to downgrade your azure-iot-sdk-python gradually and see if the problem is resolved. You could then do a diff of the changes and send it to Microsoft too.