From 192b7479a5995047c0aff16821c2af88588490ff Mon Sep 17 00:00:00 2001 From: Carter Tinney Date: Tue, 1 Sep 2026 13:46:34 -0700 Subject: [PATCH 1/4] fix: adopt Paho MQTT v2 callbacks Migrate transport callbacks to Paho's version 2 API and classify connection and disconnect reasons by their documented semantics. Propagate broker-rejected SUBACKs through operation tracking, including early acknowledgements, and leave reconnect timing to the SDK. Remove obsolete reconnect-delay and private thread workarounds now that Paho 2.1 is required. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../azure/iot/device/common/mqtt_transport.py | 386 ++++----- .../common/pipeline/pipeline_stages_mqtt.py | 4 +- pyproject.toml | 2 +- .../pipeline/test_pipeline_stages_mqtt.py | 25 +- tests/unit/common/test_mqtt_transport.py | 804 +++++++++--------- tests/unit/iothub/test_sync_clients.py | 11 + uv.lock | 2 +- 7 files changed, 641 insertions(+), 593 deletions(-) diff --git a/azure-iot-device/azure/iot/device/common/mqtt_transport.py b/azure-iot-device/azure/iot/device/common/mqtt_transport.py index be1f3abc9..658fd7ac0 100644 --- a/azure-iot-device/azure/iot/device/common/mqtt_transport.py +++ b/azure-iot-device/azure/iot/device/common/mqtt_transport.py @@ -16,20 +16,31 @@ logger = logging.getLogger(__name__) -# Mapping of Paho CONNACK rc codes to Error object classes -# Used for connection callbacks -paho_connack_rc_to_error = { - mqtt.CONNACK_REFUSED_PROTOCOL_VERSION: exceptions.ProtocolClientError, - mqtt.CONNACK_REFUSED_IDENTIFIER_REJECTED: exceptions.ProtocolClientError, - mqtt.CONNACK_REFUSED_SERVER_UNAVAILABLE: exceptions.ConnectionFailedError, - mqtt.CONNACK_REFUSED_BAD_USERNAME_PASSWORD: exceptions.UnauthorizedError, - mqtt.CONNACK_REFUSED_NOT_AUTHORIZED: exceptions.UnauthorizedError, +# This transport speaks MQTT 3.1.1, but Paho callback API v2 represents callback results +# with MQTT 5 ReasonCode and Properties types. For MQTT 3.1.1, Paho synthesizes these values: +# - CONNACK and SUBACK ReasonCode objects from their MQTT 3.1.1 Return Codes +# - a disconnect ReasonCode from Paho's own MQTTErrorCode +# - a successful ReasonCode for publish completion +# - empty Properties objects, and an empty reason_codes list for UNSUBACK +# These are Paho API values, not fields received in MQTT 3.1.1 Control Packets. +# Maps Paho's synthesized CONNACK reason names to SDK exception types. +paho_connack_reason_name_to_error_type = { + "Unsupported protocol version": exceptions.ProtocolClientError, + "Client identifier not valid": exceptions.ProtocolClientError, + "Server unavailable": exceptions.ConnectionFailedError, + "Bad user name or password": exceptions.UnauthorizedError, + "Not authorized": exceptions.UnauthorizedError, } -# Mapping of Paho rc codes to Error object classes -# Used for responses to Paho APIs and non-connection callbacks -paho_rc_to_error = { - mqtt.MQTT_ERR_NOMEM: exceptions.ProtocolClientError, +# Maps Paho's synthesized disconnect reason names to SDK exception types. MQTT 3.1.1 has no +# server-to-client DISCONNECT packet or disconnect reason field. +paho_disconnect_reason_name_to_error_type = { + "Unspecified error": exceptions.ConnectionDroppedError, + "Keep alive timeout": exceptions.ConnectionDroppedError, +} + +# Maps Paho library error codes to SDK exception types. +paho_error_code_to_error_type = { mqtt.MQTT_ERR_PROTOCOL: exceptions.ProtocolClientError, mqtt.MQTT_ERR_INVAL: exceptions.ProtocolClientError, mqtt.MQTT_ERR_NO_CONN: exceptions.NoConnectionError, @@ -48,34 +59,39 @@ } -def _create_error_from_connack_rc_code(rc): - """ - Given a paho CONNACK rc code, return an Exception that can be raised - """ - message = mqtt.connack_string(rc) - if rc in paho_connack_rc_to_error: - return paho_connack_rc_to_error[rc](message) +def _create_error_from_paho_connack_reason(reason_code): + """Translate Paho's synthesized CONNACK ReasonCode into an SDK transport exception.""" + paho_reason_name = str(reason_code) + if paho_reason_name in paho_connack_reason_name_to_error_type: + return paho_connack_reason_name_to_error_type[paho_reason_name](paho_reason_name) else: - return exceptions.ProtocolClientError("Unknown CONNACK rc={}".format(rc)) + return exceptions.ProtocolClientError("Unknown Paho CONNACK reason={}".format(reason_code)) -def _create_error_from_rc_code(rc): - """ - Given a paho rc code, return an Exception that can be raised - """ - if rc == 1: - # Paho returns rc=1 to mean "something went wrong. stop". We manually translate this to a ConnectionDroppedError. - return exceptions.ConnectionDroppedError("Paho returned rc==1") - elif rc in paho_rc_to_error: - message = mqtt.error_string(rc) - return paho_rc_to_error[rc](message) +def _create_error_from_paho_disconnect_reason(reason_code): + """Translate Paho's synthesized disconnect ReasonCode into an SDK transport exception.""" + paho_reason_name = str(reason_code) + if paho_reason_name in paho_disconnect_reason_name_to_error_type: + return paho_disconnect_reason_name_to_error_type[paho_reason_name](paho_reason_name) + else: + return exceptions.ProtocolClientError( + "Unknown Paho disconnect reason={}".format(reason_code) + ) + + +def _create_error_from_paho_error_code(error_code): + """Translate a Paho library error code into an SDK transport exception.""" + if error_code in paho_error_code_to_error_type: + message = mqtt.error_string(error_code) + return paho_error_code_to_error_type[error_code](message) else: - return exceptions.ProtocolClientError("Unknown rc=={}".format(rc)) + return exceptions.ProtocolClientError("Unknown Paho error code={}".format(error_code)) class MQTTTransport(object): """ - A wrapper class that provides an implementation-agnostic MQTT message broker interface. + A wrapper class that provides an implementation-agnostic MQTT Server interface. + This transport uses MQTT 3.1.1. :ivar on_mqtt_connected_handler: Event handler callback, called upon establishing a connection. :type on_mqtt_connected_handler: Function @@ -101,11 +117,11 @@ def __init__( ): """ Constructor to instantiate an MQTT protocol wrapper. - :param str client_id: The id of the client connecting to the broker. - :param str hostname: Hostname or IP address of the remote broker. - :param str username: Username for login to the remote broker. + :param str client_id: The Client Identifier used to connect to the MQTT Server. + :param str hostname: Hostname or IP address of the remote MQTT Server. + :param str username: User Name for authentication with the MQTT Server. :param str server_verification_cert: Certificate which can be used to validate a server-side TLS connection (optional). - :param x509_cert: Certificate which can be used to authenticate connection to a server in lieu of a password (optional). + :param x509_cert: Certificate which can be used to authenticate with the MQTT Server in lieu of a password (optional). :param bool websockets: Indicates whether or not to enable a websockets connection in the Transport. :param str cipher: Cipher string in OpenSSL cipher list format :param proxy_options: Options for sending traffic through proxy servers. @@ -140,20 +156,22 @@ def _create_mqtt_client(self): if self._websockets: logger.info("Creating client for connecting using MQTT over websockets") mqtt_client = mqtt.Client( - callback_api_version=mqtt.CallbackAPIVersion.VERSION1, + callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=self._client_id, clean_session=False, protocol=mqtt.MQTTv311, transport="websockets", + reconnect_on_failure=False, ) mqtt_client.ws_set_options(path="/$iothub/websocket") else: logger.info("Creating client for connecting using MQTT over TCP") mqtt_client = mqtt.Client( - callback_api_version=mqtt.CallbackAPIVersion.VERSION1, + callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=self._client_id, clean_session=False, protocol=mqtt.MQTTv311, + reconnect_on_failure=False, ) if self._proxy_options: @@ -186,17 +204,18 @@ def get_transport_from_weakref_or_stop_loop(client, callback_name): client.loop_stop() return this - def on_connect(client, userdata, flags, rc): - logger.info("connected with result code: {}".format(rc)) + def on_connect(client, userdata, flags, reason_code, properties): + # Paho synthesizes this ReasonCode from the MQTT 3.1.1 Connect Return Code. + logger.info("CONNACK received: {}".format(reason_code)) this = get_transport_from_weakref_or_stop_loop(client, "on_connect") if this is None: return - if rc: # i.e. if there is an error + if reason_code != 0: # i.e. if there is an error if this.on_mqtt_connection_failure_handler: try: this.on_mqtt_connection_failure_handler( - _create_error_from_connack_rc_code(rc) + _create_error_from_paho_connack_reason(reason_code) ) except Exception: logger.warning( @@ -216,17 +235,18 @@ def on_connect(client, userdata, flags, rc): else: logger.debug("No event handler callback set for on_mqtt_connected_handler") - def on_disconnect(client, userdata, rc): - logger.info("disconnected with result code: {}".format(rc)) + def on_disconnect(client, userdata, disconnect_flags, reason_code, properties): + # Paho synthesizes this ReasonCode from its own disconnection error code. + logger.info("Paho reported disconnection: {}".format(reason_code)) this = get_transport_from_weakref_or_stop_loop(client, "on_disconnect") if this is None: return cause = None - if rc: # i.e. if there is an error + if reason_code != 0: # i.e. if there is an error logger.debug("".join(traceback.format_stack())) - cause = _create_error_from_rc_code(rc) - this._force_transport_disconnect_and_cleanup() + cause = _create_error_from_paho_disconnect_reason(reason_code) + this._disconnect_and_stop_network_loop() if this.on_mqtt_disconnected_handler: try: @@ -237,35 +257,46 @@ def on_disconnect(client, userdata, rc): else: logger.warning("No event handler callback set for on_mqtt_disconnected_handler") - def on_subscribe(client, userdata, mid, granted_qos): - logger.info("suback received for {}".format(mid)) + def on_subscribe(client, userdata, mid, reason_codes, properties): + logger.info("SUBACK received for Packet Identifier {}".format(mid)) this = get_transport_from_weakref_or_stop_loop(client, "on_subscribe") if this is None: return - # subscribe failures are returned from the subscribe() call. This is just - # a notification that a SUBACK was received, so there is no failure case here - this._op_manager.complete_operation(mid) + # Paho synthesizes each ReasonCode from an MQTT 3.1.1 SUBACK Return Code. + failed_suback_return_codes = [ + return_code for return_code in reason_codes if return_code >= 0x80 + ] + if failed_suback_return_codes: + error = exceptions.ProtocolClientError( + "Subscription rejected by MQTT Server: {}".format( + ", ".join(str(return_code) for return_code in failed_suback_return_codes) + ) + ) + this._op_manager.complete_operation(mid, error=error) + else: + this._op_manager.complete_operation(mid) - def on_unsubscribe(client, userdata, mid): - logger.info("UNSUBACK received for {}".format(mid)) + def on_unsubscribe(client, userdata, mid, reason_codes, properties): + logger.info("UNSUBACK received for Packet Identifier {}".format(mid)) this = get_transport_from_weakref_or_stop_loop(client, "on_unsubscribe") if this is None: return - # unsubscribe failures are returned from the unsubscribe() call. This is just - # a notification that a SUBACK was received, so there is no failure case here + # MQTT 3.1.1 UNSUBACK contains only the Packet Identifier, so Paho supplies + # an empty reason_codes list. this._op_manager.complete_operation(mid) - def on_publish(client, userdata, mid): - logger.info("payload published for {}".format(mid)) + def on_publish(client, userdata, mid, reason_code, properties): + logger.info("PUBLISH completed for Paho message ID {}".format(mid)) this = get_transport_from_weakref_or_stop_loop(client, "on_publish") if this is None: return - # publish failures are returned from the publish() call. This is just - # a notification that a PUBACK was received, so there is no failure case here + # MQTT 3.1.1 has no publish-completion reason code or properties, so Paho + # synthesizes successful values. QoS 0 has no acknowledgment, QoS 1 completes + # with PUBACK, and QoS 2 with PUBCOMP. this._op_manager.complete_operation(mid) def on_message(client, userdata, mqtt_message): - logger.info("message received on {}".format(mqtt_message.topic)) + logger.info("Application Message received on Topic Name {}".format(mqtt_message.topic)) this = get_transport_from_weakref_or_stop_loop(client, "on_message") if this is None: return @@ -288,51 +319,18 @@ def on_message(client, userdata, mqtt_message): mqtt_client.on_publish = on_publish mqtt_client.on_message = on_message - # Set paho automatic-reconnect delay to 2 hours. Ideally we would turn - # paho auto-reconnect off entirely, but this is the best we can do. Without - # this, we run the risk of our auto-reconnect code and the paho auto-reconnect - # code conflicting with each other. - # The choice of 2 hours is completely arbitrary - mqtt_client.reconnect_delay_set(120 * 60) - logger.debug("Created MQTT protocol client, assigned callbacks") return mqtt_client - def _force_transport_disconnect_and_cleanup(self): - """ - After disconnecting because of an error, Paho was designed to keep the loop running and - to try reconnecting after the reconnect interval. We don't want Paho to reconnect because - we want to control the timing of the reconnect, so we force the loop to stop. - - We are relying on intimate knowledge of Paho behavior here. If this becomes a problem, - it may be necessary to write our own Paho thread and stop using thread_start()/thread_stop(). - This is certainly supported by Paho, but the thread that Paho provides works well enough - (so far) and making our own would be more complex than is currently justified. - """ + def _disconnect_and_stop_network_loop(self): + """Disconnect the Paho client and stop its network loop.""" - logger.info("Forcing paho disconnect to prevent it from automatically reconnecting") - - # Note: We are calling this inside our on_disconnect() handler, so we might be inside the - # Paho thread at this point. This is perfectly valid. Comments in Paho's client.py - # loop_forever() function re-comment calling disconnect() from a callback to exit the - # Paho thread/loop. + logger.info("Disconnecting Paho client and stopping network loop") self._mqtt_client.disconnect() - - # Calling disconnect() isn't enough. We also need to call loop_stop to make sure - # Paho is as clean as possible. Our call to disconnect() above is enough to stop the - # loop and exit the tread, but the call to loop_stop() is necessary to complete the cleanup. - self._mqtt_client.loop_stop() - # Finally, because of a bug in Paho, we need to null out the _thread pointer. This - # is necessary because the code that sets _thread to None only gets called if you - # call loop_stop from an external thread (and we're still inside the Paho thread here). - if threading.current_thread() == self._mqtt_client._thread: - logger.debug("in paho thread. nulling _thread") - self._mqtt_client._thread = None - - logger.debug("Done forcing paho disconnect") + logger.debug("Done disconnecting Paho client and stopping network loop") def _create_ssl_context(self): """ @@ -374,13 +372,13 @@ def shutdown(self): # Remove the disconnect handler from Paho. We don't want to trigger any events in response # to the shutdown and confuse the higher level layers of code. Just end it. self._mqtt_client.on_disconnect = None - # Now disconnect and do some additional cleanup. - self._force_transport_disconnect_and_cleanup() + # Now disconnect and stop the network loop. + self._disconnect_and_stop_network_loop() self._op_manager.cancel_all_operations() def connect(self, password=None): """ - Connect to the MQTT broker, using hostname and username set at instantiation. + Connect to the MQTT Server, using hostname and username set at instantiation. This method should be called as an entry point before sending any telemetry. @@ -389,7 +387,7 @@ def connect(self, password=None): If MQTT connection has been proxied, connection will take a bit longer to allow negotiation with the proxy server. Any errors in the proxy connection process will trigger exceptions - :param str password: The password for connecting with the MQTT broker (Optional). + :param str password: The password for connecting with the MQTT Server (Optional). :raises: ConnectionFailedError if connection could not be established. :raises: ConnectionDroppedError if connection is dropped during execution. @@ -399,23 +397,23 @@ def connect(self, password=None): :raises: TlsExchangeAuthError if there a failure with TLS certificate exchange :raises: ProtocolProxyError if there is a proxy-specific error """ - logger.debug("connecting to mqtt broker") + logger.debug("connecting to MQTT Server") self._mqtt_client.username_pw_set(username=self._username, password=password) try: if self._websockets: logger.info("Connect using port 443 (websockets)") - rc = self._mqtt_client.connect( + paho_error_code = self._mqtt_client.connect( host=self._hostname, port=443, keepalive=self._keep_alive ) else: logger.info("Connect using port 8883 (TCP)") - rc = self._mqtt_client.connect( + paho_error_code = self._mqtt_client.connect( host=self._hostname, port=8883, keepalive=self._keep_alive ) except socket.error as e: - self._force_transport_disconnect_and_cleanup() + self._disconnect_and_stop_network_loop() # Only this type will raise a special error # To stop it from retrying. @@ -437,18 +435,18 @@ def connect(self, password=None): raise exceptions.ConnectionFailedError() from e except Exception as e: - self._force_transport_disconnect_and_cleanup() + self._disconnect_and_stop_network_loop() raise exceptions.ProtocolClientError("Unexpected Paho failure during connect") from e - logger.debug("_mqtt_client.connect returned rc={}".format(rc)) - if rc: - raise _create_error_from_rc_code(rc) + logger.debug("Paho connect returned error code={}".format(paho_error_code)) + if paho_error_code: + raise _create_error_from_paho_error_code(paho_error_code) self._mqtt_client.loop_start() def disconnect(self, clear_inflight=False): """ - Disconnect from the MQTT broker. + Disconnect from the MQTT Server. :raises: ProtocolClientError if there is some client error. :raises: ConnectionDroppedError in unexpected cases. @@ -457,24 +455,20 @@ def disconnect(self, clear_inflight=False): """ logger.info("disconnecting MQTT client") try: - rc = self._mqtt_client.disconnect() + paho_error_code = self._mqtt_client.disconnect() except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during disconnect") from e finally: self._mqtt_client.loop_stop() - if threading.current_thread() == self._mqtt_client._thread: - logger.debug("in paho thread. nulling _thread") - self._mqtt_client._thread = None - - logger.debug("_mqtt_client.disconnect returned rc={}".format(rc)) - if rc: - # Special case: MQTT_ERR_NO_CONN (rc=4) during disconnect means the socket + logger.debug("Paho disconnect returned error code={}".format(paho_error_code)) + if paho_error_code: + # Special case: MQTT_ERR_NO_CONN during disconnect means the socket # is already closed. In Paho 2.x, this can happen even after a successful - # disconnect because the on_disconnect callback fires (with rc=0) before + # disconnect because the on_disconnect callback fires successfully before # disconnect() returns, and Paho's internal cleanup closes the socket. # Since we wanted to disconnect and we're disconnected, treat this as success. - if rc == mqtt.MQTT_ERR_NO_CONN: + if paho_error_code == mqtt.MQTT_ERR_NO_CONN: logger.debug( "disconnect returned MQTT_ERR_NO_CONN - socket already closed, treating as success" ) @@ -483,22 +477,22 @@ def disconnect(self, clear_inflight=False): self._op_manager.cancel_all_operations() else: # This could result in ConnectionDroppedError or ProtocolClientError - err = _create_error_from_rc_code(rc) + err = _create_error_from_paho_error_code(paho_error_code) raise err else: # Clear pending ops if instructed, but only if the disconnect was successful. # Technically the disconnect could still fail upon response, however that would then - # cause a force disconnect via the on_disconnect handler, thus it is safe to clear + # stop the network loop via the on_disconnect handler, thus it is safe to clear # ops here and now. if clear_inflight: self._op_manager.cancel_all_operations() def subscribe(self, topic, qos=1, callback=None): """ - This method subscribes the client to one topic from the MQTT broker. + Subscribe the Client to one Topic Filter on the MQTT Server. - :param str topic: a single string specifying the subscription topic to subscribe to - :param int qos: the desired quality of service level for the subscription. Defaults to 1. + :param str topic: A single Topic Filter to subscribe to. + :param int qos: The maximum QoS requested for the Subscription. Defaults to 1. :param callback: A callback to be triggered upon completion (Optional). :raises: ValueError if qos is not 0, 1 or 2. @@ -507,24 +501,24 @@ def subscribe(self, topic, qos=1, callback=None): :raises: ProtocolClientError if there is some other client error. :raises: NoConnectionError if the client isn't actually connected. """ - logger.info("subscribing to {} with qos {}".format(topic, qos)) + logger.info("subscribing to Topic Filter {} with QoS {}".format(topic, qos)) try: - (rc, mid) = self._mqtt_client.subscribe(topic, qos=qos) + paho_error_code, mid = self._mqtt_client.subscribe(topic, qos=qos) except ValueError: raise except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during subscribe") from e - logger.debug("_mqtt_client.subscribe returned rc={}".format(rc)) - if rc: + logger.debug("Paho subscribe returned error code={}".format(paho_error_code)) + if paho_error_code: # This could result in ConnectionDroppedError or ProtocolClientError - raise _create_error_from_rc_code(rc) + raise _create_error_from_paho_error_code(paho_error_code) self._op_manager.establish_operation(mid, callback) def unsubscribe(self, topic, callback=None): """ - Unsubscribe the client from one topic on the MQTT broker. + Unsubscribe the Client from one Topic Filter on the MQTT Server. - :param str topic: a single string which is the subscription topic to unsubscribe from. + :param str topic: A single Topic Filter to unsubscribe from. :param callback: A callback to be triggered upon completion (Optional). :raises: ValueError if topic is None or has zero string length. @@ -532,86 +526,82 @@ def unsubscribe(self, topic, callback=None): :raises: ProtocolClientError if there is some other client error. :raises: NoConnectionError if the client isn't actually connected. """ - logger.info("unsubscribing from {}".format(topic)) + logger.info("unsubscribing from Topic Filter {}".format(topic)) try: - (rc, mid) = self._mqtt_client.unsubscribe(topic) + paho_error_code, mid = self._mqtt_client.unsubscribe(topic) except ValueError: raise except Exception as e: raise exceptions.ProtocolClientError( "Unexpected Paho failure during unsubscribe" ) from e - logger.debug("_mqtt_client.unsubscribe returned rc={}".format(rc)) - if rc: + logger.debug("Paho unsubscribe returned error code={}".format(paho_error_code)) + if paho_error_code: # This could result in ConnectionDroppedError or ProtocolClientError - raise _create_error_from_rc_code(rc) + raise _create_error_from_paho_error_code(paho_error_code) self._op_manager.establish_operation(mid, callback) def publish(self, topic, payload, qos=1, callback=None): """ - Send a message via the MQTT broker. + Publish an Application Message to the MQTT Server. - :param str topic: topic: The topic that the message should be published on. - :param payload: The actual message to send. + :param str topic: The Topic Name on which to publish the Application Message. + :param payload: The Application Message payload. :type payload: str, bytes, int, float or None - :param int qos: the desired quality of service level for the subscription. Defaults to 1. + :param int qos: The QoS level for delivery of the Application Message. Defaults to 1. :param callback: A callback to be triggered upon completion (Optional). :raises: ValueError if qos is not 0, 1 or 2 :raises: ValueError if topic is None or has zero string length - :raises: ValueError if topic contains a wildcard ("+") + :raises: ValueError if the Topic Name contains a wildcard character ("+" or "#") :raises: ValueError if the length of the payload is greater than 268435455 bytes :raises: TypeError if payload is not a valid type :raises: ConnectionDroppedError if connection is dropped during execution. :raises: ProtocolClientError if there is some other client error. :raises: NoConnectionError if the client isn't actually connected. """ - logger.info("publishing on {}".format(topic)) + logger.info("publishing on Topic Name {}".format(topic)) try: - (rc, mid) = self._mqtt_client.publish(topic=topic, payload=payload, qos=qos) + paho_error_code, mid = self._mqtt_client.publish(topic=topic, payload=payload, qos=qos) except ValueError: raise except TypeError: raise except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during publish") from e - logger.debug("_mqtt_client.publish returned rc={}".format(rc)) - if rc: + logger.debug("Paho publish returned error code={}".format(paho_error_code)) + if paho_error_code: # This could result in ConnectionDroppedError or ProtocolClientError - raise _create_error_from_rc_code(rc) + raise _create_error_from_paho_error_code(paho_error_code) self._op_manager.establish_operation(mid, callback) class OperationManager(object): - """Tracks pending operations and their associated callbacks until completion.""" + """Tracks callbacks by Paho message ID, including responses received before registration.""" def __init__(self): - # Maps mid->callback for operations where a request has been sent - # but the response has not yet been received + # Maps Paho message ID to callback for operations awaiting a response. self._pending_operation_callbacks = {} - # Maps mid->mid for responses received that are NOT established in the _pending_operation_callbacks dict. - # Necessary because sometimes an operation will complete with a response before the - # Paho call returns. - # TODO: make this map mid to something more useful (result code?) - self._unknown_operation_completions = {} + # Maps Paho message ID to an optional error when a response arrives before registration. + self._early_operation_completions = {} self._lock = threading.Lock() def establish_operation(self, mid, callback=None): - """Establish a pending operation identified by MID, and store its completion callback. + """Register a pending operation and callback under its Paho message ID. If the operation has already been completed, the callback will be triggered. """ trigger_callback = False + completion_error = None with self._lock: - # Check to see if a response was already received for this MID before this method was - # able to be called due to threading shenanigans - if mid in self._unknown_operation_completions: + # Paho can invoke the response callback before its API call returns the message ID. + if mid in self._early_operation_completions: - # Clear the recorded unknown response now that it has been resolved - del self._unknown_operation_completions[mid] + # Clear the early response now that its operation has been established. + completion_error = self._early_operation_completions.pop(mid) # Since the operation has already completed, indicate callback should trigger trigger_callback = True @@ -619,35 +609,41 @@ def establish_operation(self, mid, callback=None): else: # Store the operation as pending, along with callback self._pending_operation_callbacks[mid] = callback - logger.debug("Waiting for response on MID: {}".format(mid)) + logger.debug("Waiting for response on Paho message ID: {}".format(mid)) # Now that the lock has been released, if the callback should be triggered, # go ahead and trigger it now. if trigger_callback: logger.debug( - "Response for MID: {} was received early - triggering callback".format(mid) + "Response for Paho message ID: {} was received early - triggering callback".format( + mid + ) ) if callback: try: - callback() + if completion_error is not None: + callback(error=completion_error) + else: + callback() except Exception: - logger.debug("Unexpected error calling callback for MID: {}".format(mid)) + logger.debug( + "Unexpected error calling callback for Paho message ID: {}".format(mid) + ) logger.debug(traceback.format_exc()) else: - # Not entirely unexpected because of QOS=1 - logger.debug("No callback for MID: {}".format(mid)) + # Completion callbacks are optional. + logger.debug("No callback for Paho message ID: {}".format(mid)) - def complete_operation(self, mid): - """Complete an operation identified by MID and trigger the associated completion callback. + def complete_operation(self, mid, error=None): + """Complete an operation by Paho message ID and trigger its callback. - If the operation MID is unknown, the completion status will be stored until - the operation is established. + If the operation has not been established yet, retain its completion error until it is. """ callback = None trigger_callback = False with self._lock: - # If the mid is associated with an established pending operation, trigger the associated callback + # If the Paho message ID has a pending operation, trigger its callback. if mid in self._pending_operation_callbacks: # Retrieve the callback, and clear the pending operation now that it has been completed @@ -658,30 +654,36 @@ def complete_operation(self, mid): trigger_callback = True else: - # Otherwise, store the mid as an unknown response - logger.debug("Response received for unknown MID: {}".format(mid)) - self._unknown_operation_completions[ - mid - ] = mid # TODO: set something more useful here + logger.debug( + "Response received before Paho message ID was registered: {}".format(mid) + ) + self._early_operation_completions[mid] = error # Now that the lock has been released, if the callback should be triggered, # go ahead and trigger it now. if trigger_callback: logger.debug( - "Response received for recognized MID: {} - triggering callback".format(mid) + "Response received for registered Paho message ID: {} - triggering callback".format( + mid + ) ) if callback: try: - callback() + if error is not None: + callback(error=error) + else: + callback() except Exception: - logger.debug("Unexpected error calling callback for MID: {}".format(mid)) + logger.debug( + "Unexpected error calling callback for Paho message ID: {}".format(mid) + ) logger.debug(traceback.format_exc()) else: - # fully expected. QOS=1 means we might get 2 PUBACKs - logger.debug("No callback set for MID: {}".format(mid)) + # Completion callbacks are optional. + logger.debug("No callback set for Paho message ID: {}".format(mid)) def cancel_all_operations(self): - """Complete all pending operations with cancellation, removing MID tracking""" + """Cancel pending operations and clear all Paho message ID tracking.""" logger.debug("Cancelling all pending operations") with self._lock: # Clear pending operations @@ -690,21 +692,23 @@ def cancel_all_operations(self): mid = pending_op[0] del self._pending_operation_callbacks[mid] - # Clear unknown responses - unknown_mids = [mid for mid in self._unknown_operation_completions] - for mid in unknown_mids: - del self._unknown_operation_completions[mid] + # Clear responses that arrived before their operations were established. + early_mids = list(self._early_operation_completions) + for mid in early_mids: + del self._early_operation_completions[mid] # Trigger cancel in pending operation callbacks for pending_op in pending_ops: mid = pending_op[0] callback = pending_op[1] if callback: - logger.debug("Cancelling {} - Triggering callback".format(mid)) + logger.debug("Cancelling Paho message ID {} - triggering callback".format(mid)) try: callback(cancelled=True) except Exception: - logger.debug("Unexpected error calling callback for MID: {}".format(mid)) + logger.debug( + "Unexpected error calling callback for Paho message ID: {}".format(mid) + ) logger.debug(traceback.format_exc()) else: - logger.debug("Cancelling {} - No callback set for MID".format(mid)) + logger.debug("Cancelling Paho message ID {} - no callback set".format(mid)) diff --git a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py index 236ca244b..1f6036995 100644 --- a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py +++ b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py @@ -283,13 +283,15 @@ def on_complete(cancelled=False): logger.debug("{}({}): subscribing to {}".format(self.name, op.name, op.topic)) @pipeline_thread.invoke_on_pipeline_thread_nowait - def on_complete(cancelled=False): + def on_complete(cancelled=False, error=None): if cancelled: op.complete( error=pipeline_exceptions.OperationCancelled( "Operation cancelled before SUBACK received" ) ) + elif error is not None: + op.complete(error=error) else: logger.debug( "{}({}): SUBACK received. completing op.".format(self.name, op.name) diff --git a/pyproject.toml b/pyproject.toml index ffd7676ff..21d5f62cb 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -28,7 +28,7 @@ classifiers = [ dependencies = [ "deprecation>=2.1.0,<3.0.0", "janus", - "paho-mqtt>=2.0.0,<3.0.0", + "paho-mqtt>=2.1.0,<3.0.0", "PySocks", "requests>=2.32.3,<3.0.0", "requests-unixsocket>=0.4.1", diff --git a/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py b/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py index ae65958fb..8c1c56eb5 100644 --- a/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py +++ b/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py @@ -602,7 +602,7 @@ def test_complete(self, mocker, stage, op): assert op.error is None @pytest.mark.it( - "Completes the operation with an OperationCancelled error upon cancellation of the MQTT unsubscribe by the MQTTTransport" + "Completes the operation with an OperationCancelled error upon cancellation of the MQTT publish by the MQTTTransport" ) def test_complete_with_cancel(self, mocker, stage, op): # Begin publish @@ -639,7 +639,7 @@ def op(self, mocker): ) @pytest.mark.it("Performs an MQTT subscribe via the MQTTTransport") - def test_mqtt_publish(self, mocker, stage, op): + def test_mqtt_subscribe(self, mocker, stage, op): stage.run_op(op) assert stage.transport.subscribe.call_count == 1 assert stage.transport.subscribe.call_args == mocker.call( @@ -662,10 +662,23 @@ def test_complete(self, mocker, stage, op): assert op.error is None @pytest.mark.it( - "Completes the operation with an OperationCancelled error upon cancellation of the MQTT unsubscribe by the MQTTTransport" + "Completes the operation with an error received from the MQTT subscribe callback" + ) + def test_complete_with_error(self, stage, op, arbitrary_exception): + stage.run_op(op) + + assert not op.completed + + stage.transport.subscribe.call_args[1]["callback"](error=arbitrary_exception) + + assert op.completed + assert op.error is arbitrary_exception + + @pytest.mark.it( + "Completes the operation with an OperationCancelled error upon cancellation of the MQTT subscribe by the MQTTTransport" ) def test_complete_with_cancel(self, mocker, stage, op): - # Begin unsubscribe + # Begin subscribe stage.run_op(op) assert not op.completed @@ -699,7 +712,7 @@ def op(self, mocker): ) @pytest.mark.it("Performs an MQTT unsubscribe via the MQTTTransport") - def test_mqtt_publish(self, mocker, stage, op): + def test_mqtt_unsubscribe(self, mocker, stage, op): stage.run_op(op) assert stage.transport.unsubscribe.call_count == 1 assert stage.transport.unsubscribe.call_args == mocker.call( @@ -739,7 +752,7 @@ def test_complete_with_cancel(self, mocker, stage, op): @pytest.mark.it( "Completes the operation using the exception that was raised, if an exception was raised from the MQTTTransport" ) - def test_publish_error(self, stage, op, arbitrary_exception): + def test_unsubscribe_error(self, stage, op, arbitrary_exception): stage.transport.unsubscribe.side_effect = arbitrary_exception stage.run_op(op) diff --git a/tests/unit/common/test_mqtt_transport.py b/tests/unit/common/test_mqtt_transport.py index 41d58d904..b23d7963b 100644 --- a/tests/unit/common/test_mqtt_transport.py +++ b/tests/unit/common/test_mqtt_transport.py @@ -9,6 +9,7 @@ from azure.iot.device.common import transport_exceptions as errors from azure.iot.device.common import ProxyOptions import paho.mqtt.client as mqtt +from paho.mqtt.packettypes import PacketTypes import ssl import copy import pytest @@ -32,107 +33,197 @@ fake_qos = 1 fake_mid = 52 fake_rc = 0 -fake_success_rc = 0 -fake_failed_rc = mqtt.MQTT_ERR_PROTOCOL -failed_connack_rc = mqtt.CONNACK_REFUSED_IDENTIFIER_REJECTED +successful_connack_reason_code = mqtt.convert_connack_rc_to_reason_code(mqtt.CONNACK_ACCEPTED) +failed_connack_reason_code = mqtt.convert_connack_rc_to_reason_code( + mqtt.CONNACK_REFUSED_IDENTIFIER_REJECTED +) +successful_disconnect_reason_code = mqtt.convert_disconnect_error_code_to_reason_code( + mqtt.MQTT_ERR_SUCCESS +) +failed_disconnect_reason_code = mqtt.convert_disconnect_error_code_to_reason_code( + mqtt.MQTT_ERR_CONN_LOST +) +keep_alive_disconnect_reason_code = mqtt.convert_disconnect_error_code_to_reason_code( + mqtt.MQTT_ERR_KEEPALIVE +) fake_keepalive = 1234 -# mapping of Paho connack rc codes to Error object classes -connack_return_codes = [ +# Paho-normalized CONNACK reasons and their corresponding SDK exception types +paho_connack_reason_error_cases = [ { - "name": "CONNACK_REFUSED_PROTOCOL_VERSION", - "rc": mqtt.CONNACK_REFUSED_PROTOCOL_VERSION, + "reason_code": mqtt.convert_connack_rc_to_reason_code( + mqtt.CONNACK_REFUSED_PROTOCOL_VERSION + ), "error": errors.ProtocolClientError, }, { - "name": "CONNACK_REFUSED_IDENTIFIER_REJECTED", - "rc": mqtt.CONNACK_REFUSED_IDENTIFIER_REJECTED, + "reason_code": mqtt.convert_connack_rc_to_reason_code( + mqtt.CONNACK_REFUSED_IDENTIFIER_REJECTED + ), "error": errors.ProtocolClientError, }, { - "name": "CONNACK_REFUSED_SERVER_UNAVAILABLE", - "rc": mqtt.CONNACK_REFUSED_SERVER_UNAVAILABLE, + "reason_code": mqtt.convert_connack_rc_to_reason_code( + mqtt.CONNACK_REFUSED_SERVER_UNAVAILABLE + ), "error": errors.ConnectionFailedError, }, { - "name": "CONNACK_REFUSED_BAD_USERNAME_PASSWORD", - "rc": mqtt.CONNACK_REFUSED_BAD_USERNAME_PASSWORD, + "reason_code": mqtt.convert_connack_rc_to_reason_code( + mqtt.CONNACK_REFUSED_BAD_USERNAME_PASSWORD + ), "error": errors.UnauthorizedError, }, { - "name": "CONNACK_REFUSED_NOT_AUTHORIZED", - "rc": mqtt.CONNACK_REFUSED_NOT_AUTHORIZED, + "reason_code": mqtt.convert_connack_rc_to_reason_code(mqtt.CONNACK_REFUSED_NOT_AUTHORIZED), "error": errors.UnauthorizedError, }, ] +paho_disconnect_reason_error_cases = [ + { + "reason_code": failed_disconnect_reason_code, + "error": errors.ConnectionDroppedError, + }, + { + "reason_code": keep_alive_disconnect_reason_code, + "error": errors.ConnectionDroppedError, + }, +] + + +def trigger_on_connect(mqtt_client, reason_code=successful_connack_reason_code): + mqtt_client.on_connect( + client=mqtt_client, + userdata=None, + flags=mqtt.ConnectFlags(session_present=False), + reason_code=reason_code, + properties=mqtt.Properties(PacketTypes.CONNACK), + ) + + +def trigger_on_disconnect(mqtt_client, reason_code=successful_disconnect_reason_code): + mqtt_client.on_disconnect( + client=mqtt_client, + userdata=None, + disconnect_flags=mqtt.DisconnectFlags(is_disconnect_packet_from_server=False), + reason_code=reason_code, + properties=mqtt.Properties(PacketTypes.DISCONNECT), + ) -# mapping of Paho rc codes to Error object classes -operation_return_codes = [ - {"name": "MQTT_ERR_NOMEM", "rc": mqtt.MQTT_ERR_NOMEM, "error": errors.ConnectionDroppedError}, + +def trigger_on_subscribe(mqtt_client, mid, reason_codes=None): + if reason_codes is None: + reason_codes = [mqtt.ReasonCode(PacketTypes.SUBACK, identifier=fake_qos)] + mqtt_client.on_subscribe( + client=mqtt_client, + userdata=None, + mid=mid, + reason_codes=reason_codes, + properties=mqtt.Properties(PacketTypes.SUBACK), + ) + + +def trigger_on_unsubscribe(mqtt_client, mid): + mqtt_client.on_unsubscribe( + client=mqtt_client, + userdata=None, + mid=mid, + reason_codes=[], + properties=mqtt.Properties(PacketTypes.UNSUBACK), + ) + + +def trigger_on_publish(mqtt_client, mid): + mqtt_client.on_publish( + client=mqtt_client, + userdata=None, + mid=mid, + reason_code=mqtt.ReasonCode(PacketTypes.PUBACK), + properties=mqtt.Properties(PacketTypes.PUBACK), + ) + + +# Paho library error codes and their corresponding SDK exception types +paho_error_code_cases = [ { "name": "MQTT_ERR_PROTOCOL", - "rc": mqtt.MQTT_ERR_PROTOCOL, + "error_code": mqtt.MQTT_ERR_PROTOCOL, + "error": errors.ProtocolClientError, + }, + { + "name": "MQTT_ERR_INVAL", + "error_code": mqtt.MQTT_ERR_INVAL, "error": errors.ProtocolClientError, }, - {"name": "MQTT_ERR_INVAL", "rc": mqtt.MQTT_ERR_INVAL, "error": errors.ProtocolClientError}, - {"name": "MQTT_ERR_NO_CONN", "rc": mqtt.MQTT_ERR_NO_CONN, "error": errors.NoConnectionError}, + { + "name": "MQTT_ERR_NO_CONN", + "error_code": mqtt.MQTT_ERR_NO_CONN, + "error": errors.NoConnectionError, + }, { "name": "MQTT_ERR_CONN_REFUSED", - "rc": mqtt.MQTT_ERR_CONN_REFUSED, + "error_code": mqtt.MQTT_ERR_CONN_REFUSED, "error": errors.ConnectionFailedError, }, { "name": "MQTT_ERR_NOT_FOUND", - "rc": mqtt.MQTT_ERR_NOT_FOUND, + "error_code": mqtt.MQTT_ERR_NOT_FOUND, "error": errors.ConnectionFailedError, }, { "name": "MQTT_ERR_CONN_LOST", - "rc": mqtt.MQTT_ERR_CONN_LOST, + "error_code": mqtt.MQTT_ERR_CONN_LOST, "error": errors.ConnectionDroppedError, }, - {"name": "MQTT_ERR_TLS", "rc": mqtt.MQTT_ERR_TLS, "error": errors.UnauthorizedError}, + {"name": "MQTT_ERR_TLS", "error_code": mqtt.MQTT_ERR_TLS, "error": errors.UnauthorizedError}, { "name": "MQTT_ERR_PAYLOAD_SIZE", - "rc": mqtt.MQTT_ERR_PAYLOAD_SIZE, + "error_code": mqtt.MQTT_ERR_PAYLOAD_SIZE, "error": errors.ProtocolClientError, }, { "name": "MQTT_ERR_NOT_SUPPORTED", - "rc": mqtt.MQTT_ERR_NOT_SUPPORTED, + "error_code": mqtt.MQTT_ERR_NOT_SUPPORTED, "error": errors.ProtocolClientError, }, - {"name": "MQTT_ERR_AUTH", "rc": mqtt.MQTT_ERR_AUTH, "error": errors.UnauthorizedError}, + {"name": "MQTT_ERR_AUTH", "error_code": mqtt.MQTT_ERR_AUTH, "error": errors.UnauthorizedError}, { "name": "MQTT_ERR_ACL_DENIED", - "rc": mqtt.MQTT_ERR_ACL_DENIED, + "error_code": mqtt.MQTT_ERR_ACL_DENIED, "error": errors.UnauthorizedError, }, - {"name": "MQTT_ERR_UNKNOWN", "rc": mqtt.MQTT_ERR_UNKNOWN, "error": errors.ProtocolClientError}, - {"name": "MQTT_ERR_ERRNO", "rc": mqtt.MQTT_ERR_ERRNO, "error": errors.ProtocolClientError}, + { + "name": "MQTT_ERR_UNKNOWN", + "error_code": mqtt.MQTT_ERR_UNKNOWN, + "error": errors.ProtocolClientError, + }, + { + "name": "MQTT_ERR_ERRNO", + "error_code": mqtt.MQTT_ERR_ERRNO, + "error": errors.ProtocolClientError, + }, { "name": "MQTT_ERR_QUEUE_SIZE", - "rc": mqtt.MQTT_ERR_QUEUE_SIZE, + "error_code": mqtt.MQTT_ERR_QUEUE_SIZE, "error": errors.ProtocolClientError, }, { "name": "MQTT_ERR_KEEPALIVE", - "rc": mqtt.MQTT_ERR_KEEPALIVE, + "error_code": mqtt.MQTT_ERR_KEEPALIVE, "error": errors.ConnectionDroppedError, }, ] -# For disconnect, MQTT_ERR_NO_CONN is treated as success (socket already closed) -# so we exclude it from the error return codes for disconnect tests -disconnect_operation_return_codes = [ - x for x in operation_return_codes if x["rc"] != mqtt.MQTT_ERR_NO_CONN +# During disconnect, MQTT_ERR_NO_CONN means the socket is already closed and is successful. +disconnect_error_code_cases = [ + case for case in paho_error_code_cases if case["error_code"] != mqtt.MQTT_ERR_NO_CONN ] @pytest.fixture -def mock_mqtt_client(mocker, fake_paho_thread): +def mock_mqtt_client(mocker): mock = mocker.patch.object(mqtt, "Client") mock_mqtt_client = mock.return_value mock_mqtt_client.subscribe = mocker.MagicMock(return_value=(fake_rc, fake_mid)) @@ -141,7 +232,6 @@ def mock_mqtt_client(mocker, fake_paho_thread): mock_mqtt_client.connect.return_value = 0 mock_mqtt_client.reconnect.return_value = 0 mock_mqtt_client.disconnect.return_value = 0 - mock_mqtt_client._thread = fake_paho_thread return mock_mqtt_client @@ -163,30 +253,6 @@ def collected_transport_weakref(mock_mqtt_client): return transport_weakref -@pytest.fixture -def fake_paho_thread(mocker): - thread = mocker.MagicMock(spec=threading.Thread) - thread.name = "_fake_paho_thread_" - return thread - - -@pytest.fixture -def mock_paho_thread_current(mocker, fake_paho_thread): - return mocker.patch.object(threading, "current_thread", return_value=fake_paho_thread) - - -@pytest.fixture -def fake_non_paho_thread(mocker): - thread = mocker.MagicMock(spec=threading.Thread) - thread.name = "_fake_non_paho_thread_" - return thread - - -@pytest.fixture -def mock_non_paho_thread_current(mocker, fake_non_paho_thread): - return mocker.patch.object(threading, "current_thread", return_value=fake_non_paho_thread) - - @pytest.mark.describe("MQTTTransport - Instantiation") class TestInstantiation(object): @pytest.fixture( @@ -220,10 +286,11 @@ def test_instantiates_mqtt_client(self, mocker): assert mock_mqtt_client_constructor.call_count == 1 assert mock_mqtt_client_constructor.call_args == mocker.call( - callback_api_version=mqtt.CallbackAPIVersion.VERSION1, + callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=fake_device_id, clean_session=False, protocol=mqtt.MQTTv311, + reconnect_on_failure=False, ) @pytest.mark.it( @@ -242,11 +309,12 @@ def test_configures_mqtt_websockets(self, mocker): assert mock_mqtt_client_constructor.call_count == 1 assert mock_mqtt_client_constructor.call_args == mocker.call( - callback_api_version=mqtt.CallbackAPIVersion.VERSION1, + callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=fake_device_id, clean_session=False, protocol=mqtt.MQTTv311, transport="websockets", + reconnect_on_failure=False, ) # Verify websockets options have been set @@ -402,20 +470,19 @@ def test_operation_infrastructure_set_up(self, mocker): client_id=fake_device_id, hostname=fake_hostname, username=fake_username ) assert transport._op_manager._pending_operation_callbacks == {} - assert transport._op_manager._unknown_operation_completions == {} + assert transport._op_manager._early_operation_completions == {} - @pytest.mark.it("Sets paho auto-reconnect interval to 2 hours") - def test_sets_reconnect_interval(self, mocker, transport, mock_mqtt_client): + @pytest.mark.it("Does not configure Paho's reconnect delay") + def test_does_not_set_reconnect_interval(self, transport, mock_mqtt_client): MQTTTransport(client_id=fake_device_id, hostname=fake_hostname, username=fake_username) - # called once by the mqtt_client constructor and once by mqtt_transport.py - assert mock_mqtt_client.reconnect_delay_set.call_count == 2 - assert mock_mqtt_client.reconnect_delay_set.call_args == mocker.call(120 * 60) + assert mock_mqtt_client.reconnect_delay_set.call_count == 0 + assert mock_mqtt_client.manual_ack_set.call_count == 0 @pytest.mark.describe("MQTTTransport - .shutdown()") class TestShutdown(object): - @pytest.mark.it("Force Disconnects Paho") + @pytest.mark.it("Disconnects Paho and stops its network loop") def test_disconnects(self, mocker, mock_mqtt_client, transport): transport.shutdown() @@ -581,19 +648,19 @@ def test_client_raises_base_exception( transport.connect(fake_password) assert e_info.value is arbitrary_base_exception - # NOTE: this test tests for all possible return codes, even ones that shouldn't be + # NOTE: this test tests all mapped Paho error codes, even ones that shouldn't be # possible on a connect operation. - @pytest.mark.it("Raises a custom Exception if Paho connect returns a failing rc code") + @pytest.mark.it("Raises a custom Exception if Paho connect returns an error code") @pytest.mark.parametrize( - "error_params", - operation_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in operation_return_codes], + "error_case", + paho_error_code_cases, + ids=[ + "{}->{}".format(case["name"], case["error"].__name__) for case in paho_error_code_cases + ], ) - def test_client_returns_failing_rc_code( - self, mocker, mock_mqtt_client, transport, error_params - ): - mock_mqtt_client.connect.return_value = error_params["rc"] - with pytest.raises(error_params["error"]): + def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): + mock_mqtt_client.connect.return_value = error_case["error_code"] + with pytest.raises(error_case["error"]): transport.connect(fake_password) @pytest.fixture( @@ -635,28 +702,6 @@ def test_calls_loop_stop_on_exception( transport.connect(fake_password) assert mock_mqtt_client.loop_stop.call_count == 1 - @pytest.mark.it( - "Sets Paho's _thread to None if Paho raises an exception while running in the Paho thread" - ) - def test_sets_thread_to_none_on_exception_in_paho_thread( - self, mocker, mock_mqtt_client, transport, mock_paho_thread_current, connect_exception - ): - mock_mqtt_client.connect.side_effect = connect_exception - with pytest.raises(Exception): - transport.connect(fake_password) - assert mock_mqtt_client._thread is None - - @pytest.mark.it( - "Does not sets Paho's _thread to None if Paho raises an exception running outside the Paho thread" - ) - def test_does_not_set_thread_to_none_on_exception_not_in_paho_thread( - self, mocker, mock_mqtt_client, transport, mock_non_paho_thread_current, connect_exception - ): - mock_mqtt_client.connect.side_effect = connect_exception - with pytest.raises(Exception): - transport.connect(fake_password) - assert mock_mqtt_client._thread is not None - @pytest.mark.describe("MQTTTransport - OCCURRENCE: Connect Completed") class TestEventConnectComplete(object): @@ -668,7 +713,7 @@ def test_calls_event_handler_callback(self, mocker, mock_mqtt_client, transport) transport.on_mqtt_connected_handler = callback # Manually trigger Paho on_connect event_handler - mock_mqtt_client.on_connect(client=mock_mqtt_client, userdata=None, flags=None, rc=fake_rc) + trigger_on_connect(mock_mqtt_client) # Verify transport.on_mqtt_connected_handler was called assert callback.call_count == 1 @@ -678,9 +723,7 @@ def test_calls_event_handler_callback(self, mocker, mock_mqtt_client, transport) "Stops Paho's network loop if the MQTTTransport was garbage collected before a successful connect completed" ) def test_stops_loop_after_gc(self, mocker, mock_mqtt_client, collected_transport_weakref): - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=fake_success_rc - ) + trigger_on_connect(mock_mqtt_client) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -693,7 +736,7 @@ def test_skips_none_event_handler_callback(self, mocker, mock_mqtt_client, trans transport.connect(fake_password) - mock_mqtt_client.on_connect(client=mock_mqtt_client, userdata=None, flags=None, rc=fake_rc) + trigger_on_connect(mock_mqtt_client) # No further asserts required - this is a test to show that it skips a callback. # Not raising an exception == test passed @@ -706,7 +749,7 @@ def test_event_handler_callback_raises_exception( transport.on_mqtt_connected_handler = event_cb transport.connect(fake_password) - mock_mqtt_client.on_connect(client=mock_mqtt_client, userdata=None, flags=None, rc=fake_rc) + trigger_on_connect(mock_mqtt_client) # Callback was called, but exception did not propagate assert event_cb.call_count == 1 @@ -722,24 +765,25 @@ def test_event_handler_callback_raises_base_exception( transport.connect(fake_password) with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=fake_rc - ) + trigger_on_connect(mock_mqtt_client) assert e_info.value is arbitrary_base_exception @pytest.mark.describe("MQTTTransport - OCCURRENCE: Connection Failure") class TestEventConnectionFailure(object): @pytest.mark.parametrize( - "error_params", - connack_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in connack_return_codes], + "error_case", + paho_connack_reason_error_cases, + ids=[ + "{}->{}".format(case["reason_code"], case["error"].__name__) + for case in paho_connack_reason_error_cases + ], ) @pytest.mark.it( "Triggers on_mqtt_connection_failure_handler event handler with custom Exception upon failed connect completion" ) - def test_calls_event_handler_callback_with_failed_rc( - self, mocker, mock_mqtt_client, transport, error_params + def test_calls_event_handler_callback_with_failed_reason_code( + self, mocker, mock_mqtt_client, transport, error_case ): callback = mocker.MagicMock() transport.on_mqtt_connection_failure_handler = callback @@ -748,21 +792,18 @@ def test_calls_event_handler_callback_with_failed_rc( transport.connect(fake_password) # Manually trigger Paho on_connect event_handler - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=error_params["rc"] - ) + trigger_on_connect(mock_mqtt_client, reason_code=error_case["reason_code"]) # Verify transport.on_mqtt_connection_failure_handler was called assert callback.call_count == 1 - assert isinstance(callback.call_args[0][0], error_params["error"]) + assert isinstance(callback.call_args[0][0], error_case["error"]) + assert str(callback.call_args[0][0]) == str(error_case["reason_code"]) @pytest.mark.it( "Stops Paho's network loop if the MQTTTransport was garbage collected before a failed connect completed" ) def test_stops_loop_after_gc(self, mocker, mock_mqtt_client, collected_transport_weakref): - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=failed_connack_rc - ) + trigger_on_connect(mock_mqtt_client, reason_code=failed_connack_reason_code) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -775,9 +816,7 @@ def test_skips_none_event_handler_callback(self, mocker, mock_mqtt_client, trans transport.connect(fake_password) - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=failed_connack_rc - ) + trigger_on_connect(mock_mqtt_client, reason_code=failed_connack_reason_code) # No further asserts required - this is a test to show that it skips a callback. # Not raising an exception == test passed @@ -790,9 +829,7 @@ def test_event_handler_callback_raises_exception( transport.on_mqtt_connection_failure_handler = event_cb transport.connect(fake_password) - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=failed_connack_rc - ) + trigger_on_connect(mock_mqtt_client, reason_code=failed_connack_reason_code) # Callback was called, but exception did not propagate assert event_cb.call_count == 1 @@ -808,9 +845,7 @@ def test_event_handler_callback_raises_base_exception( transport.connect(fake_password) with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_connect( - client=mock_mqtt_client, userdata=None, flags=None, rc=failed_connack_rc - ) + trigger_on_connect(mock_mqtt_client, reason_code=failed_connack_reason_code) assert e_info.value is arbitrary_base_exception @@ -843,22 +878,37 @@ def test_client_raises_base_exception( transport.disconnect() assert e_info.value is arbitrary_base_exception - @pytest.mark.it("Raises a custom Exception if Paho disconnect returns a failing rc code") + @pytest.mark.it("Raises a custom Exception if Paho disconnect returns an error code") @pytest.mark.parametrize( - "error_params", - disconnect_operation_return_codes, + "error_case", + disconnect_error_code_cases, ids=[ - "{}->{}".format(x["name"], x["error"].__name__) - for x in disconnect_operation_return_codes + "{}->{}".format(case["name"], case["error"].__name__) + for case in disconnect_error_code_cases ], ) - def test_client_returns_failing_rc_code( - self, mocker, mock_mqtt_client, transport, error_params - ): - mock_mqtt_client.disconnect.return_value = error_params["rc"] - with pytest.raises(error_params["error"]): + def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): + mock_mqtt_client.disconnect.return_value = error_case["error_code"] + with pytest.raises(error_case["error"]): transport.disconnect() + @pytest.mark.it("Treats MQTT_ERR_NO_CONN as a successful disconnect") + def test_no_connection_error_code(self, mock_mqtt_client, transport): + mock_mqtt_client.disconnect.return_value = mqtt.MQTT_ERR_NO_CONN + + transport.disconnect() + + @pytest.mark.it("Cancels pending operations after an already-completed disconnect") + def test_no_connection_error_code_clears_inflight(self, mocker, mock_mqtt_client, transport): + callback = mocker.MagicMock() + transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) + mock_mqtt_client.disconnect.return_value = mqtt.MQTT_ERR_NO_CONN + + transport.disconnect(clear_inflight=True) + + assert callback.call_count == 1 + assert callback.call_args == mocker.call(cancelled=True) + @pytest.mark.it("Cancels all pending operations if the clear_inflight parameter is True") def test_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): # Set up a pending publish @@ -965,55 +1015,14 @@ def test_calls_loop_stop_on_exception( assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() - @pytest.mark.it( - "Sets Paho's _thread to None if disconnect does not raise an exception while running in the Paho thread" - ) - def test_sets_thread_to_none_on_success_in_paho_thread( - self, mocker, mock_mqtt_client, transport, mock_paho_thread_current - ): - transport.disconnect() - assert mock_mqtt_client._thread is None - - @pytest.mark.it( - "Sets Paho's _thread to None if disconnect raises an exception while running in the Paho thread" - ) - def test_sets_thread_to_none_on_exception_in_paho_thread( - self, mocker, mock_mqtt_client, transport, arbitrary_exception, mock_paho_thread_current - ): - mock_mqtt_client.disconnect.side_effect = arbitrary_exception - - with pytest.raises(Exception): - transport.disconnect() - assert mock_mqtt_client._thread is None - - @pytest.mark.it( - "Does not set Paho's _thread to None if disconnect does not raise an exception while running outside the Paho thread" - ) - def test_does_not_set_thread_to_none_on_success_in_non_paho_thread( - self, mocker, mock_mqtt_client, transport, mock_non_paho_thread_current - ): - transport.disconnect() - assert mock_mqtt_client._thread is not None - - @pytest.mark.it( - "Does not set Paho's _thread to None if disconnect raises an exception while running outside the Paho thread" - ) - def test_does_not_set_thread_to_none_on_exception_in_non_paho_thread( - self, mocker, mock_mqtt_client, transport, arbitrary_exception, mock_non_paho_thread_current - ): - mock_mqtt_client.disconnect.side_effect = arbitrary_exception - - with pytest.raises(Exception): - transport.disconnect() - assert mock_mqtt_client._thread is not None - @pytest.mark.describe("MQTTTransport - OCCURRENCE: Disconnect Completed") class TestEventDisconnectCompleted(object): @pytest.fixture( - params=[fake_success_rc, fake_failed_rc], ids=["success rc code", "failed rc code"] + params=[successful_disconnect_reason_code, failed_disconnect_reason_code], + ids=["success reason code", "failed reason code"], ) - def rc_success_or_failure(self, request): + def reason_code_success_or_failure(self, request): return request.param @pytest.mark.it( @@ -1028,23 +1037,26 @@ def test_calls_event_handler_callback_externally_driven( # Initiate disconnect transport.disconnect() - # Manually trigger Paho on_connect event_handler - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_rc) + # Manually trigger Paho on_disconnect event_handler + trigger_on_disconnect(mock_mqtt_client) # Verify transport.on_mqtt_connected_handler was called assert callback.call_count == 1 assert callback.call_args == mocker.call(None) @pytest.mark.parametrize( - "error_params", - operation_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in operation_return_codes], + "error_case", + paho_disconnect_reason_error_cases, + ids=[ + "{}->{}".format(case["reason_code"], case["error"].__name__) + for case in paho_disconnect_reason_error_cases + ], ) @pytest.mark.it( - "Triggers on_mqtt_disconnected_handler event handler with custom Exception when an error RC is returned upon disconnect completion." + "Triggers on_mqtt_disconnected_handler with a ConnectionDroppedError for an unexpected MQTT 3.1.1 disconnect" ) - def test_calls_event_handler_callback_with_failure_user_driven( - self, mocker, mock_mqtt_client, transport, error_params + def test_calls_event_handler_callback_with_failure( + self, mocker, mock_mqtt_client, transport, error_case ): callback = mocker.MagicMock() transport.on_mqtt_disconnected_handler = callback @@ -1052,14 +1064,12 @@ def test_calls_event_handler_callback_with_failure_user_driven( # Initiate disconnect transport.disconnect() - # Manually trigger Paho on_disconnect event_handler - mock_mqtt_client.on_disconnect( - client=mock_mqtt_client, userdata=None, rc=error_params["rc"] - ) + trigger_on_disconnect(mock_mqtt_client, reason_code=error_case["reason_code"]) # Verify transport.on_mqtt_disconnected_handler was called assert callback.call_count == 1 - assert isinstance(callback.call_args[0][0], error_params["error"]) + assert isinstance(callback.call_args[0][0], error_case["error"]) + assert str(callback.call_args[0][0]) == str(error_case["reason_code"]) @pytest.mark.it( "Skips on_mqtt_disconnected_handler event handler if set to 'None' upon disconnect completion" @@ -1069,7 +1079,7 @@ def test_skips_none_event_handler_callback(self, mocker, mock_mqtt_client, trans transport.disconnect() - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_rc) + trigger_on_disconnect(mock_mqtt_client) # No further asserts required - this is a test to show that it skips a callback. # Not raising an exception == test passed @@ -1082,7 +1092,7 @@ def test_event_handler_callback_raises_exception( transport.on_mqtt_disconnected_handler = event_cb transport.disconnect() - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_rc) + trigger_on_disconnect(mock_mqtt_client) # Callback was called, but exception did not propagate assert event_cb.call_count == 1 @@ -1098,64 +1108,58 @@ def test_event_handler_callback_raises_base_exception( transport.disconnect() with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_rc) + trigger_on_disconnect(mock_mqtt_client) assert e_info.value is arbitrary_base_exception @pytest.mark.it("Calls Paho's disconnect() method if cause is not None") def test_calls_disconnect_with_cause(self, mock_mqtt_client, transport): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_failed_rc) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert mock_mqtt_client.disconnect.call_count == 1 @pytest.mark.it("Does not call Paho's disconnect() method if cause is None") def test_doesnt_call_disconnect_without_cause(self, mock_mqtt_client, transport): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_success_rc) + trigger_on_disconnect(mock_mqtt_client) assert mock_mqtt_client.disconnect.call_count == 0 @pytest.mark.it("Calls Paho's loop_stop() if cause is not None") def test_calls_loop_stop(self, mock_mqtt_client, transport): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_failed_rc) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert mock_mqtt_client.loop_stop.call_count == 1 @pytest.mark.it("Does not calls Paho's loop_stop() if cause is None") def test_does_not_call_loop_stop(self, mock_mqtt_client, transport): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_success_rc) + trigger_on_disconnect(mock_mqtt_client) assert mock_mqtt_client.loop_stop.call_count == 0 - @pytest.mark.it( - "Sets Paho's _thread to None if cause is not None while running in the Paho thread" - ) - def test_sets_thread_to_none_on_failure_in_paho_thread( - self, mock_mqtt_client, transport, mock_paho_thread_current - ): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_failed_rc) - assert mock_mqtt_client._thread is None - - @pytest.mark.it( - "Does not set Paho's _thread to None if cause is not None while running outside the paho thread" - ) - def test_sets_thread_to_none_on_failure_in_non_paho_thread( - self, mock_mqtt_client, transport, mock_non_paho_thread_current - ): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_failed_rc) - assert mock_mqtt_client._thread is not None - - @pytest.mark.it( - "Does not sets Paho's _thread to None if cause is None while running in the Paho thread" - ) - def test_does_not_set_thread_to_none_on_success_in_paho_thread( - self, mock_mqtt_client, transport, mock_paho_thread_current - ): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_success_rc) - assert mock_mqtt_client._thread is not None - - @pytest.mark.it( - "Does not sets Paho's _thread to None if cause is None while running outside the Paho thread" - ) - def test_does_not_set_thread_to_none_on_success_in_non_paho_thread( - self, mock_mqtt_client, transport, mock_non_paho_thread_current - ): - mock_mqtt_client.on_disconnect(client=mock_mqtt_client, userdata=None, rc=fake_success_rc) - assert mock_mqtt_client._thread is not None + @pytest.mark.it("Cleans up an unexpected disconnect from the Paho callback thread") + def test_cleanup_from_paho_callback_thread(self, mocker): + transport = MQTTTransport( + client_id=fake_device_id, hostname=fake_hostname, username=fake_username + ) + callback_finished = threading.Event() + callback_causes = [] + callback_errors = [] + transport.on_mqtt_disconnected_handler = callback_causes.append + + def run_callback_loop(retry_first_connection): + try: + trigger_on_disconnect( + transport._mqtt_client, reason_code=failed_disconnect_reason_code + ) + except BaseException as error: + callback_errors.append(error) + finally: + callback_finished.set() + + mocker.patch.object(transport._mqtt_client, "loop_forever", side_effect=run_callback_loop) + + assert transport._mqtt_client.loop_start() == mqtt.MQTT_ERR_SUCCESS + assert callback_finished.wait(timeout=5) + transport._mqtt_client.loop_stop() + + assert callback_errors == [] + assert len(callback_causes) == 1 + assert isinstance(callback_causes[0], errors.ConnectionDroppedError) @pytest.mark.it("Allows any Exception raised by Paho's disconnect() to propagate") def test_disconnect_raises_exception( @@ -1163,9 +1167,7 @@ def test_disconnect_raises_exception( ): mock_mqtt_client.disconnect = mocker.MagicMock(side_effect=arbitrary_exception) with pytest.raises(type(arbitrary_exception)) as e_info: - mock_mqtt_client.on_disconnect( - client=mock_mqtt_client, userdata=None, rc=fake_failed_rc - ) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert e_info.value is arbitrary_exception @pytest.mark.it("Allows any BaseException raised by Paho's disconnect() to propagate") @@ -1174,9 +1176,7 @@ def test_disconnect_raises_base_exception( ): mock_mqtt_client.disconnect = mocker.MagicMock(side_effect=arbitrary_base_exception) with pytest.raises(type(arbitrary_base_exception)) as e_info: - mock_mqtt_client.on_disconnect( - client=mock_mqtt_client, userdata=None, rc=fake_failed_rc - ) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert e_info.value is arbitrary_base_exception @pytest.mark.it("Allows any Exception raised by Paho's loop_stop() to propagate") @@ -1185,9 +1185,7 @@ def test_loop_stop_raises_exception( ): mock_mqtt_client.loop_stop = mocker.MagicMock(side_effect=arbitrary_exception) with pytest.raises(type(arbitrary_exception)) as e_info: - mock_mqtt_client.on_disconnect( - client=mock_mqtt_client, userdata=None, rc=fake_failed_rc - ) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert e_info.value is arbitrary_exception @pytest.mark.it("Allows any BaseException raised by Paho's loop_stop() to propagate") @@ -1196,29 +1194,31 @@ def test_loop_stop_raises_base_exception( ): mock_mqtt_client.loop_stop = mocker.MagicMock(side_effect=arbitrary_base_exception) with pytest.raises(type(arbitrary_base_exception)) as e_info: - mock_mqtt_client.on_disconnect( - client=mock_mqtt_client, userdata=None, rc=fake_failed_rc - ) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) assert e_info.value is arbitrary_base_exception @pytest.mark.it( "Does not raise any exceptions if the MQTTTransport object was garbage collected before the disconnect completed" ) def test_no_exception_after_gc( - self, mock_mqtt_client, collected_transport_weakref, rc_success_or_failure + self, mock_mqtt_client, collected_transport_weakref, reason_code_success_or_failure ): assert mock_mqtt_client.on_disconnect - mock_mqtt_client.on_disconnect(mock_mqtt_client, None, rc_success_or_failure) + trigger_on_disconnect(mock_mqtt_client, reason_code=reason_code_success_or_failure) # lack of exception is success @pytest.mark.it( "Calls Paho's loop_stop() if the MQTTTransport object was garbage collected before the disconnect completed" ) def test_calls_loop_stop_after_gc( - self, collected_transport_weakref, mock_mqtt_client, rc_success_or_failure, mocker + self, + collected_transport_weakref, + mock_mqtt_client, + reason_code_success_or_failure, + mocker, ): assert mock_mqtt_client.loop_stop.call_count == 0 - mock_mqtt_client.on_disconnect(mock_mqtt_client, None, rc_success_or_failure) + trigger_on_disconnect(mock_mqtt_client, reason_code=reason_code_success_or_failure) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -1229,12 +1229,12 @@ def test_raises_exception_after_gc( self, collected_transport_weakref, mock_mqtt_client, - rc_success_or_failure, + reason_code_success_or_failure, arbitrary_exception, ): mock_mqtt_client.loop_stop.side_effect = arbitrary_exception with pytest.raises(type(arbitrary_exception)): - mock_mqtt_client.on_disconnect(mock_mqtt_client, None, rc_success_or_failure) + trigger_on_disconnect(mock_mqtt_client, reason_code=reason_code_success_or_failure) @pytest.mark.it( "Allows any BaseException raised by Paho's loop_stop() to propagate if the MQTTTransport object was garbage collected before the disconnect completed" @@ -1243,12 +1243,12 @@ def test_raises_base_exception_after_gc( self, collected_transport_weakref, mock_mqtt_client, - rc_success_or_failure, + reason_code_success_or_failure, arbitrary_base_exception, ): mock_mqtt_client.loop_stop.side_effect = arbitrary_base_exception with pytest.raises(type(arbitrary_base_exception)): - mock_mqtt_client.on_disconnect(mock_mqtt_client, None, rc_success_or_failure) + trigger_on_disconnect(mock_mqtt_client, reason_code=reason_code_success_or_failure) @pytest.mark.describe("MQTTTransport - .subscribe()") @@ -1298,20 +1298,28 @@ def test_triggers_callback_upon_paho_on_subscribe_event( assert callback.call_count == 0 # Manually trigger Paho on_subscribe event handler - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # Check callback has now been called assert callback.call_count == 1 + assert callback.call_args == mocker.call() + + @pytest.mark.it("Completes a rejected subscription with a ProtocolClientError") + def test_failed_suback(self, mocker, mock_mqtt_client, transport): + callback = mocker.MagicMock() + transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) + rejected = mqtt.ReasonCode(PacketTypes.SUBACK, identifier=128) + + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid, reason_codes=[rejected]) + + assert callback.call_count == 1 + assert isinstance(callback.call_args.kwargs["error"], errors.ProtocolClientError) @pytest.mark.it( "Stops Paho's network loop if the MQTTTransport was garbage collected before subscribe completed" ) def test_stops_loop_after_gc(self, mocker, mock_mqtt_client, collected_transport_weakref): - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -1327,9 +1335,7 @@ def test_triggers_callback_when_paho_on_subscribe_event_called_early( def trigger_early_on_subscribe(topic, qos): # Trigger on_subscribe before returning mid - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # Check callback not yet called assert callback.call_count == 0 @@ -1344,6 +1350,25 @@ def trigger_early_on_subscribe(topic, qos): # Check callback has now been called assert callback.call_count == 1 + @pytest.mark.it( + "Completes a rejected subscription when the SUBACK arrives before subscribe returns" + ) + def test_failed_suback_received_early(self, mocker, mock_mqtt_client, transport): + callback = mocker.MagicMock() + rejected = mqtt.ReasonCode(PacketTypes.SUBACK, identifier=128) + + def trigger_early_on_subscribe(topic, qos): + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid, reason_codes=[rejected]) + assert callback.call_count == 0 + return (fake_rc, fake_mid) + + mock_mqtt_client.subscribe.side_effect = trigger_early_on_subscribe + + transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) + + assert callback.call_count == 1 + assert isinstance(callback.call_args.kwargs["error"], errors.ProtocolClientError) + @pytest.mark.it("Skips callback that is set to 'None' upon subscribe completion") def test_none_callback_upon_paho_on_subscribe_event(self, mocker, mock_mqtt_client, transport): callback = None @@ -1353,9 +1378,7 @@ def test_none_callback_upon_paho_on_subscribe_event(self, mocker, mock_mqtt_clie transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) # Manually trigger Paho on_subscribe event handler - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # No assertions necessary - not raising an exception => success @@ -1370,9 +1393,7 @@ def test_none_callback_when_paho_on_subscribe_event_called_early( def trigger_early_on_subscribe(topic, qos): # Trigger on_subscribe before returning mid - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) return (fake_rc, fake_mid) @@ -1408,23 +1429,17 @@ def test_multiple_callbacks(self, mocker, mock_mqtt_client, transport): assert callback3.call_count == 0 # Manually trigger Paho on_subscribe event handler (2 -> 3 -> 1) - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=mid2, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=mid2) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 0 - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=mid3, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=mid3) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 1 - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=mid1, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=mid1) assert callback1.call_count == 1 assert callback2.call_count == 1 assert callback3.call_count == 1 @@ -1437,9 +1452,7 @@ def test_callback_raises_exception( mock_mqtt_client.subscribe.return_value = (fake_rc, fake_mid) transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # Callback was called, but exception did not propagate assert callback.call_count == 1 @@ -1453,9 +1466,7 @@ def test_callback_raises_base_exception( transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) assert e_info.value is arbitrary_base_exception @pytest.mark.it("Recovers from Exception in callback when Paho event handler triggered early") @@ -1465,9 +1476,7 @@ def test_callback_raises_exception_when_paho_on_subscribe_triggered_early( callback = mocker.MagicMock(side_effect=arbitrary_exception) def trigger_early_on_subscribe(topic, qos): - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # Should not have yet called callback assert callback.call_count == 0 @@ -1491,9 +1500,7 @@ def test_callback_raises_base_exception_when_paho_on_subscribe_triggered_early( callback = mocker.MagicMock(side_effect=arbitrary_base_exception) def trigger_early_on_subscribe(topic, qos): - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=fake_mid, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) # Should not have yet called callback assert callback.call_count == 0 @@ -1525,19 +1532,19 @@ def test_client_raises_base_exception( transport.subscribe(topic=fake_topic, qos=fake_qos, callback=None) assert e_info.value is arbitrary_base_exception - # NOTE: this test tests for all possible return codes, even ones that shouldn't be + # NOTE: this test tests all mapped Paho error codes, even ones that shouldn't be # possible on a subscribe operation. - @pytest.mark.it("Raises a custom Exception if Paho subscribe returns a failing rc code") + @pytest.mark.it("Raises a custom Exception if Paho subscribe returns an error code") @pytest.mark.parametrize( - "error_params", - operation_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in operation_return_codes], + "error_case", + paho_error_code_cases, + ids=[ + "{}->{}".format(case["name"], case["error"].__name__) for case in paho_error_code_cases + ], ) - def test_client_returns_failing_rc_code( - self, mocker, mock_mqtt_client, transport, error_params - ): - mock_mqtt_client.subscribe.return_value = (error_params["rc"], 0) - with pytest.raises(error_params["error"]): + def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): + mock_mqtt_client.subscribe.return_value = (error_case["error_code"], 0) + with pytest.raises(error_case["error"]): transport.subscribe(topic=fake_topic, qos=fake_qos, callback=None) @@ -1574,7 +1581,7 @@ def test_triggers_callback_upon_paho_on_unsubscribe_event( assert callback.call_count == 0 # Manually trigger Paho on_unsubscribe event handler - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # Check callback has now been called assert callback.call_count == 1 @@ -1583,7 +1590,7 @@ def test_triggers_callback_upon_paho_on_unsubscribe_event( "Stops Paho's network loop if the MQTTTransport was garbage collected before unsubscribe completed" ) def test_stops_loop_after_gc(self, mocker, mock_mqtt_client, collected_transport_weakref): - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -1599,7 +1606,7 @@ def test_triggers_callback_when_paho_on_unsubscribe_event_called_early( def trigger_early_on_unsubscribe(topic): # Trigger on_unsubscribe before returning mid - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # Check callback not yet called assert callback.call_count == 0 @@ -1625,7 +1632,7 @@ def test_none_callback_upon_paho_on_unsubscribe_event( transport.unsubscribe(topic=fake_topic, callback=callback) # Manually trigger Paho on_unsubscribe event handler - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # No assertions necessary - not raising an exception => success @@ -1640,7 +1647,7 @@ def test_none_callback_when_paho_on_unsubscribe_event_called_early( def trigger_early_on_unsubscribe(topic): # Trigger on_unsubscribe before returning mid - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) return (fake_rc, fake_mid) @@ -1680,17 +1687,17 @@ def test_multiple_callbacks(self, mocker, mock_mqtt_client, transport): assert callback3.call_count == 0 # Manually trigger Paho on_unsubscribe event handler (2 -> 3 -> 1) - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=mid2) + trigger_on_unsubscribe(mock_mqtt_client, mid=mid2) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 0 - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=mid3) + trigger_on_unsubscribe(mock_mqtt_client, mid=mid3) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 1 - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=mid1) + trigger_on_unsubscribe(mock_mqtt_client, mid=mid1) assert callback1.call_count == 1 assert callback2.call_count == 1 assert callback3.call_count == 1 @@ -1703,7 +1710,7 @@ def test_callback_raises_exception( mock_mqtt_client.unsubscribe.return_value = (fake_rc, fake_mid) transport.unsubscribe(topic=fake_topic, callback=callback) - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # Callback was called, but exception did not propagate assert callback.call_count == 1 @@ -1717,7 +1724,7 @@ def test_callback_raises_base_exception( transport.unsubscribe(topic=fake_topic, callback=callback) with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) assert e_info.value is arbitrary_base_exception @pytest.mark.it("Recovers from Exception in callback when Paho event handler triggered early") @@ -1727,7 +1734,7 @@ def test_callback_raises_exception_when_paho_on_unsubscribe_triggered_early( callback = mocker.MagicMock(side_effect=arbitrary_exception) def trigger_early_on_unsubscribe(topic): - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # Should not have yet called callback assert callback.call_count == 0 @@ -1751,7 +1758,7 @@ def test_callback_raises_base_exception_when_paho_on_unsubscribe_triggered_early callback = mocker.MagicMock(side_effect=arbitrary_base_exception) def trigger_early_on_unsubscribe(topic): - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_unsubscribe(mock_mqtt_client, mid=fake_mid) # Should not have yet called callback assert callback.call_count == 0 @@ -1785,19 +1792,19 @@ def test_client_raises_base_exception( transport.unsubscribe(topic=fake_topic, callback=None) assert e_info.value is arbitrary_base_exception - # NOTE: this test tests for all possible return codes, even ones that shouldn't be + # NOTE: this test tests all mapped Paho error codes, even ones that shouldn't be # possible on an unsubscribe operation. - @pytest.mark.it("Raises a custom Exception if Paho unsubscribe returns a failing rc code") + @pytest.mark.it("Raises a custom Exception if Paho unsubscribe returns an error code") @pytest.mark.parametrize( - "error_params", - operation_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in operation_return_codes], + "error_case", + paho_error_code_cases, + ids=[ + "{}->{}".format(case["name"], case["error"].__name__) for case in paho_error_code_cases + ], ) - def test_client_returns_failing_rc_code( - self, mocker, mock_mqtt_client, transport, error_params - ): - mock_mqtt_client.unsubscribe.return_value = (error_params["rc"], 0) - with pytest.raises(error_params["error"]): + def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): + mock_mqtt_client.unsubscribe.return_value = (error_case["error_code"], 0) + with pytest.raises(error_case["error"]): transport.unsubscribe(topic=fake_topic, callback=None) @@ -1890,7 +1897,7 @@ def test_triggers_callback_upon_paho_on_publish_event( assert callback.call_count == 0 # Manually trigger Paho on_publish event handler - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=message_info.mid) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # Check callback has now been called assert callback.call_count == 1 @@ -1899,7 +1906,7 @@ def test_triggers_callback_upon_paho_on_publish_event( "Stops Paho's network loop if the MQTTTransport was garbage collected before publish completed" ) def test_stops_loop_after_gc(self, mocker, mock_mqtt_client, collected_transport_weakref): - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=fake_mid) + trigger_on_publish(mock_mqtt_client, mid=fake_mid) assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() @@ -1915,9 +1922,7 @@ def test_triggers_callback_when_paho_on_publish_event_called_early( def trigger_early_on_publish(topic, payload, qos): # Trigger on_publish before returning message_info - mock_mqtt_client.on_publish( - client=mock_mqtt_client, userdata=None, mid=message_info.mid - ) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # Check callback not yet called assert callback.call_count == 0 @@ -1943,7 +1948,7 @@ def test_none_callback_upon_paho_on_publish_event( transport.publish(topic=fake_topic, payload=fake_payload, callback=callback) # Manually trigger Paho on_publish event handler - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=message_info.mid) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # No assertions necessary - not raising an exception => success @@ -1958,9 +1963,7 @@ def test_none_callback_when_paho_on_publish_event_called_early( def trigger_early_on_publish(topic, payload, qos): # Trigger on_publish before returning message_info - mock_mqtt_client.on_publish( - client=mock_mqtt_client, userdata=None, mid=message_info.mid - ) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) return message_info @@ -2000,17 +2003,17 @@ def test_multiple_callbacks(self, mocker, mock_mqtt_client, transport): assert callback3.call_count == 0 # Manually trigger Paho on_publish event handler (2 -> 3 -> 1) - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=mid2) + trigger_on_publish(mock_mqtt_client, mid=mid2) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 0 - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=mid3) + trigger_on_publish(mock_mqtt_client, mid=mid3) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 1 - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=mid1) + trigger_on_publish(mock_mqtt_client, mid=mid1) assert callback1.call_count == 1 assert callback2.call_count == 1 assert callback3.call_count == 1 @@ -2023,7 +2026,7 @@ def test_callback_raises_exception( mock_mqtt_client.publish.return_value = message_info transport.publish(topic=fake_topic, payload=fake_payload, callback=callback) - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=message_info.mid) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # Callback was called, but exception did not propagate assert callback.call_count == 1 @@ -2037,9 +2040,7 @@ def test_callback_raises_base_exception( transport.publish(topic=fake_topic, payload=fake_payload, callback=callback) with pytest.raises(arbitrary_base_exception.__class__) as e_info: - mock_mqtt_client.on_publish( - client=mock_mqtt_client, userdata=None, mid=message_info.mid - ) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) assert e_info.value is arbitrary_base_exception @pytest.mark.it("Recovers from Exception in callback when Paho event handler triggered early") @@ -2049,9 +2050,7 @@ def test_callback_raises_exception_when_paho_on_publish_triggered_early( callback = mocker.MagicMock(side_effect=arbitrary_exception) def trigger_early_on_publish(topic, payload, qos): - mock_mqtt_client.on_publish( - client=mock_mqtt_client, userdata=None, mid=message_info.mid - ) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # Should not have yet called callback assert callback.call_count == 0 @@ -2075,9 +2074,7 @@ def test_callback_raises_base_exception_when_paho_on_publish_triggered_early( callback = mocker.MagicMock(side_effect=arbitrary_base_exception) def trigger_early_on_publish(topic, payload, qos): - mock_mqtt_client.on_publish( - client=mock_mqtt_client, userdata=None, mid=message_info.mid - ) + trigger_on_publish(mock_mqtt_client, mid=message_info.mid) # Should not have yet called callback assert callback.call_count == 0 @@ -2109,19 +2106,19 @@ def test_client_raises_base_exception( transport.publish(topic=fake_topic, payload=fake_payload, callback=None) assert e_info.value is arbitrary_base_exception - # NOTE: this test tests for all possible return codes, even ones that shouldn't be + # NOTE: this test tests all mapped Paho error codes, even ones that shouldn't be # possible on a publish operation. - @pytest.mark.it("Raises a custom Exception if Paho publish returns a failing rc code") + @pytest.mark.it("Raises a custom Exception if Paho publish returns an error code") @pytest.mark.parametrize( - "error_params", - operation_return_codes, - ids=["{}->{}".format(x["name"], x["error"].__name__) for x in operation_return_codes], + "error_case", + paho_error_code_cases, + ids=[ + "{}->{}".format(case["name"], case["error"].__name__) for case in paho_error_code_cases + ], ) - def test_client_returns_failing_rc_code( - self, mocker, mock_mqtt_client, transport, error_params - ): - mock_mqtt_client.publish.return_value = (error_params["rc"], 0) - with pytest.raises(error_params["error"]): + def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): + mock_mqtt_client.publish.return_value = (error_case["error_code"], 0) + with pytest.raises(error_case["error"]): transport.publish(topic=fake_topic, payload=fake_payload, callback=None) @@ -2231,20 +2228,18 @@ def test_multiple_callbacks_multiple_ops(self, mocker, mock_mqtt_client, transpo assert callback2.call_count == 0 assert callback3.call_count == 0 - # Manually trigger Paho on_unsubscribe event handler (2 -> 3 -> 1) - mock_mqtt_client.on_publish(client=mock_mqtt_client, userdata=None, mid=mid2) + # Complete the operations out of order (2 -> 3 -> 1) + trigger_on_publish(mock_mqtt_client, mid=mid2) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 0 - mock_mqtt_client.on_unsubscribe(client=mock_mqtt_client, userdata=None, mid=mid3) + trigger_on_unsubscribe(mock_mqtt_client, mid=mid3) assert callback1.call_count == 0 assert callback2.call_count == 1 assert callback3.call_count == 1 - mock_mqtt_client.on_subscribe( - client=mock_mqtt_client, userdata=None, mid=mid1, granted_qos=fake_qos - ) + trigger_on_subscribe(mock_mqtt_client, mid=mid1) assert callback1.call_count == 1 assert callback2.call_count == 1 assert callback3.call_count == 1 @@ -2256,7 +2251,7 @@ class TestOperationManager(object): def test_instantiates_empty(self): manager = OperationManager() assert len(manager._pending_operation_callbacks) == 0 - assert len(manager._unknown_operation_completions) == 0 + assert len(manager._early_operation_completions) == 0 @pytest.mark.describe("OperationManager - .establish_operation()") @@ -2282,38 +2277,50 @@ def test_no_early_completion(self, optional_callback): assert len(manager._pending_operation_callbacks) == 1 assert manager._pending_operation_callbacks[mid] is optional_callback - @pytest.mark.it( - "Resolves operation tracking when MID corresponds to a previous unknown completion" - ) + @pytest.mark.it("Resolves operation tracking when the response arrived before establishment") def test_early_completion(self): manager = OperationManager() mid = 1 - # Cause early completion of an unknown operation + # Record a completion before the operation is established manager.complete_operation(mid) - assert len(manager._unknown_operation_completions) == 1 - assert manager._unknown_operation_completions[mid] + assert len(manager._early_operation_completions) == 1 + assert manager._early_operation_completions[mid] is None # Establish operation that was already completed manager.establish_operation(mid) - assert len(manager._unknown_operation_completions) == 0 + assert len(manager._early_operation_completions) == 0 @pytest.mark.it( - "Triggers the callback if provided when MID corresponds to a previous unknown completion" + "Triggers the callback if provided when the response arrived before establishment" ) def test_early_completion_with_callback(self, mocker): manager = OperationManager() mid = 1 cb_mock = mocker.MagicMock() - # Cause early completion of an unknown operation + # Record a completion before the operation is established manager.complete_operation(mid) # Establish operation that was already completed manager.establish_operation(mid, cb_mock) assert cb_mock.call_count == 1 + assert cb_mock.call_args == mocker.call() + + @pytest.mark.it("Preserves an error when the completion arrives before establishment") + def test_early_completion_with_error(self, mocker): + manager = OperationManager() + mid = 1 + callback = mocker.MagicMock() + error = errors.ProtocolClientError("subscription rejected") + + manager.complete_operation(mid, error=error) + manager.establish_operation(mid, callback) + + assert callback.call_count == 1 + assert callback.call_args == mocker.call(error=error) @pytest.mark.it("Recovers from Exception thrown in callback") def test_callback_raises_exception(self, mocker, arbitrary_exception): @@ -2321,7 +2328,7 @@ def test_callback_raises_exception(self, mocker, arbitrary_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_exception) - # Cause early completion of an unknown operation + # Record a completion before the operation is established manager.complete_operation(mid) # Establish operation that was already completed @@ -2336,7 +2343,7 @@ def test_callback_raises_base_exception(self, mocker, arbitrary_base_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_base_exception) - # Cause early completion of an unknown operation + # Record a completion before the operation is established manager.complete_operation(mid) # Establish operation that was already completed @@ -2350,7 +2357,7 @@ def test_callback_called_after_lock_release(self, mocker): mid = 1 cb_mock = mocker.MagicMock() - # Cause early completion of an unknown operation + # Record a completion before the operation is established manager.complete_operation(mid) # Set up mock tracking @@ -2384,7 +2391,7 @@ def stop_tracking_mocks(*args): @pytest.mark.describe("OperationManager - .complete_operation()") class TestOperationManagerCompleteOperation(object): - @pytest.mark.it("Resolves a operation tracking when MID corresponds to a pending operation") + @pytest.mark.it("Resolves operation tracking when MID corresponds to a pending operation") def test_complete_pending_operation(self): manager = OperationManager() mid = 1 @@ -2410,6 +2417,19 @@ def test_complete_pending_operation_callback(self, mocker): assert cb_mock.call_count == 1 assert cb_mock.call_args == mocker.call() + @pytest.mark.it("Triggers callback with an error for a failed pending operation") + def test_complete_pending_operation_callback_with_error(self, mocker): + manager = OperationManager() + mid = 1 + callback = mocker.MagicMock() + error = errors.ProtocolClientError("subscription rejected") + + manager.establish_operation(mid, callback) + manager.complete_operation(mid, error=error) + + assert callback.call_count == 1 + assert callback.call_args == mocker.call(error=error) + @pytest.mark.it("Recovers from Exception thrown in callback") def test_callback_raises_exception(self, mocker, arbitrary_exception): manager = OperationManager() @@ -2436,16 +2456,14 @@ def test_callback_raises_base_exception(self, mocker, arbitrary_base_exception): manager.complete_operation(mid) assert e_info.value is arbitrary_base_exception - @pytest.mark.it( - "Begins tracking an unknown completion if MID does not correspond to a pending operation" - ) + @pytest.mark.it("Retains an early completion if MID does not correspond to a pending operation") def test_early_completion(self): manager = OperationManager() mid = 1 manager.complete_operation(mid) - assert len(manager._unknown_operation_completions) == 1 - assert manager._unknown_operation_completions[mid] + assert len(manager._early_operation_completions) == 1 + assert manager._early_operation_completions[mid] is None @pytest.mark.it("Does not trigger the callback until after thread lock has been released") def test_callback_called_after_lock_release(self, mocker): @@ -2502,19 +2520,19 @@ def test_remove_pending_ops(self): manager.cancel_all_operations() assert len(manager._pending_operation_callbacks) == 0 - @pytest.mark.it("Removes all MID tracking for unknown operation completions") - def test_remove_unknown_completions(self): + @pytest.mark.it("Removes all MID tracking for early operation completions") + def test_remove_early_completions(self): manager = OperationManager() - # Add unknown operation completions + # Add early operation completions manager.complete_operation(mid=2111) manager.complete_operation(mid=30045) manager.complete_operation(mid=2345) - assert len(manager._unknown_operation_completions) == 3 + assert len(manager._early_operation_completions) == 3 # Cancel operations manager.cancel_all_operations() - assert len(manager._unknown_operation_completions) == 0 + assert len(manager._early_operation_completions) == 0 @pytest.mark.it("Triggers callbacks (if present) with cancel flag for each pending operation") def test_op_callback_completion(self, mocker): diff --git a/tests/unit/iothub/test_sync_clients.py b/tests/unit/iothub/test_sync_clients.py index e89922e4b..88a1c5ec3 100644 --- a/tests/unit/iothub/test_sync_clients.py +++ b/tests/unit/iothub/test_sync_clients.py @@ -10,6 +10,7 @@ import time import urllib import sys +import warnings from azure.iot.device.iothub import IoTHubDeviceClient, IoTHubModuleClient from azure.iot.device import exceptions as client_exceptions from azure.iot.device.common.auth import sastoken as st @@ -1454,6 +1455,16 @@ def test_sets_on_c2d_message_received_handler_in_pipeline( client._mqtt_pipeline.on_c2d_message_received == client._inbox_manager.route_c2d_message ) + @pytest.mark.it("Constructs a public client without Paho callback API deprecation warnings") + def test_no_paho_callback_api_deprecation_warning(self): + with warnings.catch_warnings(): + warnings.simplefilter("error", DeprecationWarning) + client = IoTHubDeviceClient.create_from_connection_string( + "HostName=hostname.azure-devices.net;DeviceId=MyDevice;SharedAccessKey=Zm9vYmFy" + ) + + client.shutdown() + @pytest.mark.describe("IoTHubDeviceClient (Synchronous) - .create_from_connection_string()") class TestIoTHubDeviceClientCreateFromConnectionString( diff --git a/uv.lock b/uv.lock index 4409fe282..91b1c43f8 100644 --- a/uv.lock +++ b/uv.lock @@ -91,7 +91,7 @@ test = [ requires-dist = [ { name = "deprecation", specifier = ">=2.1.0,<3.0.0" }, { name = "janus" }, - { name = "paho-mqtt", specifier = ">=2.0.0,<3.0.0" }, + { name = "paho-mqtt", specifier = ">=2.1.0,<3.0.0" }, { name = "pysocks" }, { name = "requests", specifier = ">=2.32.3,<3.0.0" }, { name = "requests-unixsocket", specifier = ">=0.4.1" }, From d2f43e24291014d5436d50e40e0a51ab3b6f1e5e Mon Sep 17 00:00:00 2001 From: Carter Tinney Date: Thu, 3 Sep 2026 15:42:02 -0700 Subject: [PATCH 2/4] MQTTTransport refactor --- .../azure/iot/device/common/mqtt_transport.py | 485 ++++++++++----- .../common/pipeline/pipeline_stages_base.py | 4 +- .../common/pipeline/pipeline_stages_mqtt.py | 242 +++++--- tests/e2e/iothub_e2e/aio/test_send_message.py | 8 +- tests/e2e/iothub_e2e/aio/test_twin.py | 6 +- .../iothub_e2e/sync/test_sync_send_message.py | 6 +- tests/e2e/iothub_e2e/sync/test_sync_twin.py | 4 +- .../pipeline/test_pipeline_stages_mqtt.py | 131 ++++- tests/unit/common/test_mqtt_transport.py | 553 ++++++++++++------ 9 files changed, 954 insertions(+), 485 deletions(-) diff --git a/azure-iot-device/azure/iot/device/common/mqtt_transport.py b/azure-iot-device/azure/iot/device/common/mqtt_transport.py index 658fd7ac0..a899d9ce1 100644 --- a/azure-iot-device/azure/iot/device/common/mqtt_transport.py +++ b/azure-iot-device/azure/iot/device/common/mqtt_transport.py @@ -93,6 +93,11 @@ class MQTTTransport(object): A wrapper class that provides an implementation-agnostic MQTT Server interface. This transport uses MQTT 3.1.1. + Calls to connect(), disconnect(), and shutdown() must be serialized by the caller; + overlapping connection lifecycle calls are not supported. Event handlers can run concurrently + with the calling thread. Multiple publish, subscribe, and unsubscribe operations can remain + outstanding and complete out of order; their callback tracking is synchronized internally. + :ivar on_mqtt_connected_handler: Event handler callback, called upon establishing a connection. :type on_mqtt_connected_handler: Function :ivar on_mqtt_disconnected_handler: Event handler callback, called upon a disconnection. @@ -136,6 +141,13 @@ def __init__( self._cipher = cipher self._proxy_options = proxy_options self._keep_alive = keep_alive + # Paho reports rejected CONNACK codes 0x02-0x05 through on_connect, then calls + # on_disconnect while closing the refused Network Connection. For code 0x01 it only calls + # on_disconnect, and it can also call on_disconnect more than once for one connection loss. + # Callback API v2 does not preserve this context in on_disconnect, so track the MQTT + # handshake and report one correctly classified connection termination. + self._awaiting_connack = False + self._connection_termination_reported = False self.on_mqtt_connected_handler = None self.on_mqtt_disconnected_handler = None @@ -150,11 +162,11 @@ def _create_mqtt_client(self): """ Create the MQTT client object and assign all necessary event handler callbacks. """ - logger.debug("creating mqtt client") + logger.debug("creating Paho client") # Instantiate the client if self._websockets: - logger.info("Creating client for connecting using MQTT over websockets") + logger.info("Creating Paho client for MQTT over websockets") mqtt_client = mqtt.Client( callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=self._client_id, @@ -165,7 +177,7 @@ def _create_mqtt_client(self): ) mqtt_client.ws_set_options(path="/$iothub/websocket") else: - logger.info("Creating client for connecting using MQTT over TCP") + logger.info("Creating Paho client for MQTT over TCP") mqtt_client = mqtt.Client( callback_api_version=mqtt.CallbackAPIVersion.VERSION2, client_id=self._client_id, @@ -175,7 +187,7 @@ def _create_mqtt_client(self): ) if self._proxy_options: - logger.info("Setting custom proxy options on mqtt client") + logger.info("Configuring Paho client proxy options") mqtt_client.proxy_set( proxy_type=self._proxy_options.proxy_type_socks, proxy_addr=self._proxy_options.proxy_address, @@ -193,83 +205,119 @@ def _create_mqtt_client(self): # Set event handlers. Use weak references back into this object to prevent leaks self_weakref = weakref.ref(self) - def get_transport_from_weakref_or_stop_loop(client, callback_name): + def get_transport_from_weakref_or_cleanup_client(client, callback_name): + """Acquire a strong transport reference for the duration of a Paho callback. + + The transport can be collected before a callback running on Paho's thread resolves + its weak reference. If it is already gone, disconnect the orphaned client and stop + its thread; otherwise, the returned reference keeps it alive through callback handling. + """ this = self_weakref() if this is None: logger.info( - "{} called after MQTTTransport was garbage collected; stopping Paho network loop".format( + "Paho callback {} invoked after MQTTTransport was garbage collected; disconnecting Paho Client and stopping network loop".format( callback_name ) ) - client.loop_stop() + client.on_disconnect = None + try: + client.disconnect() + finally: + # From a Paho callback, this requests the current network thread to exit + # without attempting to join itself. + client.loop_stop() return this + def report_connection_failure(this, cause): + if this.on_mqtt_connection_failure_handler: + try: + this.on_mqtt_connection_failure_handler(cause) + except Exception: + logger.warning("Unexpected error calling on_mqtt_connection_failure_handler") + logger.warning(traceback.format_exc()) + else: + logger.warning( + "MQTT connection failed, but no on_mqtt_connection_failure_handler is configured" + ) + def on_connect(client, userdata, flags, reason_code, properties): # Paho synthesizes this ReasonCode from the MQTT 3.1.1 Connect Return Code. - logger.info("CONNACK received: {}".format(reason_code)) - this = get_transport_from_weakref_or_stop_loop(client, "on_connect") + logger.info("MQTT CONNACK received; Paho synthesized ReasonCode={}".format(reason_code)) + this = get_transport_from_weakref_or_cleanup_client(client, "on_connect") if this is None: return - if reason_code != 0: # i.e. if there is an error - if this.on_mqtt_connection_failure_handler: + if reason_code.is_failure: + this._awaiting_connack = False + this._connection_termination_reported = True + report_connection_failure(this, _create_error_from_paho_connack_reason(reason_code)) + else: + this._awaiting_connack = False + this._connection_termination_reported = False + if this.on_mqtt_connected_handler: try: - this.on_mqtt_connection_failure_handler( - _create_error_from_paho_connack_reason(reason_code) - ) + this.on_mqtt_connected_handler() except Exception: - logger.warning( - "Unexpected error calling on_mqtt_connection_failure_handler" - ) + logger.warning("Unexpected error calling on_mqtt_connected_handler") logger.warning(traceback.format_exc()) else: - logger.warning( - "connection failed, but no on_mqtt_connection_failure_handler handler callback provided" - ) - elif this.on_mqtt_connected_handler: - try: - this.on_mqtt_connected_handler() - except Exception: - logger.warning("Unexpected error calling on_mqtt_connected_handler") - logger.warning(traceback.format_exc()) - else: - logger.debug("No event handler callback set for on_mqtt_connected_handler") + logger.debug("No on_mqtt_connected_handler is configured") def on_disconnect(client, userdata, disconnect_flags, reason_code, properties): # Paho synthesizes this ReasonCode from its own disconnection error code. - logger.info("Paho reported disconnection: {}".format(reason_code)) - this = get_transport_from_weakref_or_stop_loop(client, "on_disconnect") + logger.info( + "Paho reported network connection closure; synthesized ReasonCode={}".format( + reason_code + ) + ) + this = get_transport_from_weakref_or_cleanup_client(client, "on_disconnect") if this is None: return + if this._connection_termination_reported: + logger.debug("Suppressing duplicate network connection termination report") + return + + was_awaiting_connack = this._awaiting_connack + this._awaiting_connack = False + this._connection_termination_reported = True + if was_awaiting_connack and reason_code.is_failure: + report_connection_failure(this, exceptions.ConnectionFailedError(str(reason_code))) + return + cause = None - if reason_code != 0: # i.e. if there is an error + if reason_code.is_failure: logger.debug("".join(traceback.format_stack())) cause = _create_error_from_paho_disconnect_reason(reason_code) - this._disconnect_and_stop_network_loop() - if this.on_mqtt_disconnected_handler: - try: + try: + if this.on_mqtt_disconnected_handler: this.on_mqtt_disconnected_handler(cause) - except Exception: - logger.warning("Unexpected error calling on_mqtt_disconnected_handler") - logger.warning(traceback.format_exc()) - else: - logger.warning("No event handler callback set for on_mqtt_disconnected_handler") + else: + logger.warning("No on_mqtt_disconnected_handler is configured") + except Exception: + logger.warning("Unexpected error calling on_mqtt_disconnected_handler") + logger.warning(traceback.format_exc()) def on_subscribe(client, userdata, mid, reason_codes, properties): - logger.info("SUBACK received for Packet Identifier {}".format(mid)) - this = get_transport_from_weakref_or_stop_loop(client, "on_subscribe") + logger.info( + "MQTT SUBACK received for Packet Identifier {}; Paho synthesized ReasonCodes={}".format( + mid, reason_codes + ) + ) + this = get_transport_from_weakref_or_cleanup_client(client, "on_subscribe") if this is None: return # Paho synthesizes each ReasonCode from an MQTT 3.1.1 SUBACK Return Code. - failed_suback_return_codes = [ - return_code for return_code in reason_codes if return_code >= 0x80 + # This transport sends one Topic Filter per SUBSCRIBE by design, but handles Paho's + # general callback shape containing one ReasonCode for each bundled subscription. + failed_reason_codes = [ + reason_code for reason_code in reason_codes if reason_code.is_failure ] - if failed_suback_return_codes: + if failed_reason_codes: error = exceptions.ProtocolClientError( "Subscription rejected by MQTT Server: {}".format( - ", ".join(str(return_code) for return_code in failed_suback_return_codes) + ", ".join(str(reason_code) for reason_code in failed_reason_codes) ) ) this._op_manager.complete_operation(mid, error=error) @@ -277,8 +325,8 @@ def on_subscribe(client, userdata, mid, reason_codes, properties): this._op_manager.complete_operation(mid) def on_unsubscribe(client, userdata, mid, reason_codes, properties): - logger.info("UNSUBACK received for Packet Identifier {}".format(mid)) - this = get_transport_from_weakref_or_stop_loop(client, "on_unsubscribe") + logger.info("MQTT UNSUBACK received for Packet Identifier {}".format(mid)) + this = get_transport_from_weakref_or_cleanup_client(client, "on_unsubscribe") if this is None: return # MQTT 3.1.1 UNSUBACK contains only the Packet Identifier, so Paho supplies @@ -286,8 +334,12 @@ def on_unsubscribe(client, userdata, mid, reason_codes, properties): this._op_manager.complete_operation(mid) def on_publish(client, userdata, mid, reason_code, properties): - logger.info("PUBLISH completed for Paho message ID {}".format(mid)) - this = get_transport_from_weakref_or_stop_loop(client, "on_publish") + logger.info( + "Paho reported publish completion for MID {}; synthesized ReasonCode={}".format( + mid, reason_code + ) + ) + this = get_transport_from_weakref_or_cleanup_client(client, "on_publish") if this is None: return # MQTT 3.1.1 has no publish-completion reason code or properties, so Paho @@ -296,8 +348,10 @@ def on_publish(client, userdata, mid, reason_code, properties): this._op_manager.complete_operation(mid) def on_message(client, userdata, mqtt_message): - logger.info("Application Message received on Topic Name {}".format(mqtt_message.topic)) - this = get_transport_from_weakref_or_stop_loop(client, "on_message") + logger.info( + "MQTT Application Message received on Topic Name {}".format(mqtt_message.topic) + ) + this = get_transport_from_weakref_or_cleanup_client(client, "on_message") if this is None: return @@ -309,7 +363,7 @@ def on_message(client, userdata, mqtt_message): logger.warning(traceback.format_exc()) else: logger.debug( - "No event handler callback set for on_mqtt_message_received_handler - DROPPING MESSAGE" + "No on_mqtt_message_received_handler is configured; dropping Application Message" ) mqtt_client.on_connect = on_connect @@ -319,31 +373,85 @@ def on_message(client, userdata, mqtt_message): mqtt_client.on_publish = on_publish mqtt_client.on_message = on_message - logger.debug("Created MQTT protocol client, assigned callbacks") + logger.debug("Created Paho client and assigned MQTT callbacks") return mqtt_client def _disconnect_and_stop_network_loop(self): - """Disconnect the Paho client and stop its network loop.""" + """Disconnect the Paho client, then stop and join its network loop.""" logger.info("Disconnecting Paho client and stopping network loop") - self._mqtt_client.disconnect() - self._mqtt_client.loop_stop() + try: + self._mqtt_client.disconnect() + finally: + # Always stop and join the network thread, even if disconnect() fails. + self._mqtt_client.loop_stop() + + logger.debug("Finished disconnecting Paho client and stopping network loop") + + def _cleanup_failed_connect(self): + """Clean up a failed connection setup without reporting a second lifecycle result. + + connect() reports these failures synchronously by raising an exception. Suppress Paho's + disconnect callback during teardown so the same attempt is not also reported as a + disconnection, then restore it for future connection attempts. + """ + on_disconnect = self._mqtt_client.on_disconnect + self._mqtt_client.on_disconnect = None + try: + self._disconnect_and_stop_network_loop() + finally: + self._mqtt_client.on_disconnect = on_disconnect + self._awaiting_connack = False + self._connection_termination_reported = False + + def _cleanup_after_network_loop_start_failure(self): + """Clean up after Paho raises while starting its network thread. + + Paho can retain an unstarted thread if Thread.start() raises, which also causes + loop_stop() to raise rather than clean up. If normal cleanup encounters that state, + discard the unusable Paho client without mutating its private thread state. + """ + failed_client = self._mqtt_client + try: + self._cleanup_failed_connect() + except Exception: + logger.warning( + "Paho cleanup failed after network loop startup failure; replacing client" + ) + logger.warning(traceback.format_exc()) + + failed_client.on_disconnect = None + failed_socket = failed_client.socket() + if failed_socket is not None: + try: + failed_socket.close() + except Exception: + logger.warning("Unexpected error closing failed Paho client socket") + logger.warning(traceback.format_exc()) + + try: + self._mqtt_client = self._create_mqtt_client() + except Exception: + logger.warning("Unexpected error replacing failed Paho client") + logger.warning(traceback.format_exc()) - logger.debug("Done disconnecting Paho client and stopping network loop") + self._awaiting_connack = False + self._connection_termination_reported = False + self._op_manager.complete_all_tracked_operations_as_cancelled() def _create_ssl_context(self): """ This method creates the SSLContext object used by Paho to authenticate the connection. """ - logger.debug("creating a SSL context") + logger.debug("creating SSL context") ssl_context = ssl.SSLContext(protocol=ssl.PROTOCOL_TLS_CLIENT) if self._server_verification_cert: - logger.debug("configuring SSL context with custom server verification cert") + logger.debug("configuring SSL context with custom server verification certificate") ssl_context.load_verify_locations(cadata=self._server_verification_cert) else: - logger.debug("configuring SSL context with default certs") + logger.debug("configuring SSL context with default certificates") ssl_context.load_default_certs() if self._cipher: @@ -355,7 +463,7 @@ def _create_ssl_context(self): raise e if self._x509_cert is not None: - logger.debug("configuring SSL context with client-side certificate and key") + logger.debug("configuring SSL context with client certificate and key") ssl_context.load_cert_chain( self._x509_cert.certificate_file, self._x509_cert.key_file, @@ -372,9 +480,12 @@ def shutdown(self): # Remove the disconnect handler from Paho. We don't want to trigger any events in response # to the shutdown and confuse the higher level layers of code. Just end it. self._mqtt_client.on_disconnect = None - # Now disconnect and stop the network loop. - self._disconnect_and_stop_network_loop() - self._op_manager.cancel_all_operations() + try: + self._disconnect_and_stop_network_loop() + finally: + self._awaiting_connack = False + self._connection_termination_reported = False + self._op_manager.complete_all_tracked_operations_as_cancelled() def connect(self, password=None): """ @@ -399,21 +510,26 @@ def connect(self, password=None): """ logger.debug("connecting to MQTT Server") + # An unexpected disconnect callback can run just before Paho's network thread exits. + # loop_stop() blocks until that prior thread exits; before the first connect, its + # no-thread result is harmless. + self._mqtt_client.loop_stop() + self._mqtt_client.username_pw_set(username=self._username, password=password) try: if self._websockets: - logger.info("Connect using port 443 (websockets)") + logger.info("Connecting to MQTT Server over websockets on port 443") paho_error_code = self._mqtt_client.connect( host=self._hostname, port=443, keepalive=self._keep_alive ) else: - logger.info("Connect using port 8883 (TCP)") + logger.info("Connecting to MQTT Server over TCP on port 8883") paho_error_code = self._mqtt_client.connect( host=self._hostname, port=8883, keepalive=self._keep_alive ) except socket.error as e: - self._disconnect_and_stop_network_loop() + self._cleanup_failed_connect() # Only this type will raise a special error # To stop it from retrying. @@ -425,8 +541,8 @@ def connect(self, password=None): raise exceptions.TlsExchangeAuthError() from e elif isinstance(e, socks.ProxyError): if isinstance(e, socks.SOCKS5AuthError): - # TODO This is the only I felt like specializing raise exceptions.UnauthorizedError() from e + # NOTE: add other specialized error handling here as necessary else: raise exceptions.ProtocolProxyError() from e else: @@ -435,33 +551,55 @@ def connect(self, password=None): raise exceptions.ConnectionFailedError() from e except Exception as e: - self._disconnect_and_stop_network_loop() - + self._cleanup_failed_connect() raise exceptions.ProtocolClientError("Unexpected Paho failure during connect") from e - logger.debug("Paho connect returned error code={}".format(paho_error_code)) + logger.debug("Paho client.connect() returned MQTTErrorCode={}".format(paho_error_code)) + if paho_error_code: + self._cleanup_failed_connect() + raise _create_error_from_paho_error_code(paho_error_code) + + # Change state as the CONNECT was sent successfully + self._awaiting_connack = True + self._connection_termination_reported = False + + # Start the network loop to process incoming and outgoing MQTT messages + try: + paho_error_code = self._mqtt_client.loop_start() + except Exception as e: + self._cleanup_after_network_loop_start_failure() + raise exceptions.ProtocolClientError( + "Unexpected Paho failure starting network loop" + ) from e + logger.debug("Paho client.loop_start() returned MQTTErrorCode={}".format(paho_error_code)) if paho_error_code: + self._cleanup_failed_connect() raise _create_error_from_paho_error_code(paho_error_code) - self._mqtt_client.loop_start() def disconnect(self, clear_inflight=False): """ - Disconnect from the MQTT Server. + Disconnect from the MQTT Server and wait for the network loop to stop. + + Optionally, clear any inflight operation tracking if clear_inflight is True. :raises: ProtocolClientError if there is some client error. :raises: ConnectionDroppedError in unexpected cases. :raises: UnauthorizedError in unexpected cases. :raises: ConnectionFailedError in unexpected cases. """ - logger.info("disconnecting MQTT client") + logger.info("disconnecting from MQTT Server") try: paho_error_code = self._mqtt_client.disconnect() except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during disconnect") from e finally: - self._mqtt_client.loop_stop() + try: + # Always stop and join the network thread, even if disconnect() fails. + self._mqtt_client.loop_stop() + finally: + self._awaiting_connack = False - logger.debug("Paho disconnect returned error code={}".format(paho_error_code)) + logger.debug("Paho client.disconnect() returned MQTTErrorCode={}".format(paho_error_code)) if paho_error_code: # Special case: MQTT_ERR_NO_CONN during disconnect means the socket # is already closed. In Paho 2.x, this can happen even after a successful @@ -470,11 +608,11 @@ def disconnect(self, clear_inflight=False): # Since we wanted to disconnect and we're disconnected, treat this as success. if paho_error_code == mqtt.MQTT_ERR_NO_CONN: logger.debug( - "disconnect returned MQTT_ERR_NO_CONN - socket already closed, treating as success" + "Paho client.disconnect() returned MQTT_ERR_NO_CONN; network connection is already closed" ) # Still clear inflight operations since we're effectively disconnected if clear_inflight: - self._op_manager.cancel_all_operations() + self._op_manager.complete_all_tracked_operations_as_cancelled() else: # This could result in ConnectionDroppedError or ProtocolClientError err = _create_error_from_paho_error_code(paho_error_code) @@ -485,7 +623,7 @@ def disconnect(self, clear_inflight=False): # stop the network loop via the on_disconnect handler, thus it is safe to clear # ops here and now. if clear_inflight: - self._op_manager.cancel_all_operations() + self._op_manager.complete_all_tracked_operations_as_cancelled() def subscribe(self, topic, qos=1, callback=None): """ @@ -493,40 +631,44 @@ def subscribe(self, topic, qos=1, callback=None): :param str topic: A single Topic Filter to subscribe to. :param int qos: The maximum QoS requested for the Subscription. Defaults to 1. - :param callback: A callback to be triggered upon completion (Optional). + :param callback: A callback to be invoked upon completion (Optional). :raises: ValueError if qos is not 0, 1 or 2. :raises: ValueError if topic is None or has zero string length. :raises: ConnectionDroppedError if connection is dropped during execution. :raises: ProtocolClientError if there is some other client error. - :raises: NoConnectionError if the client isn't actually connected. + :raises: NoConnectionError if a QoS 0 message is published while the client is not connected. """ - logger.info("subscribing to Topic Filter {} with QoS {}".format(topic, qos)) + logger.info( + "sending MQTT SUBSCRIBE for Topic Filter {} with requested maximum QoS {}".format( + topic, qos + ) + ) try: paho_error_code, mid = self._mqtt_client.subscribe(topic, qos=qos) except ValueError: raise except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during subscribe") from e - logger.debug("Paho subscribe returned error code={}".format(paho_error_code)) + logger.debug("Paho client.subscribe() returned MQTTErrorCode={}".format(paho_error_code)) if paho_error_code: # This could result in ConnectionDroppedError or ProtocolClientError raise _create_error_from_paho_error_code(paho_error_code) - self._op_manager.establish_operation(mid, callback) + self._op_manager.register_operation(mid, callback) def unsubscribe(self, topic, callback=None): """ Unsubscribe the Client from one Topic Filter on the MQTT Server. :param str topic: A single Topic Filter to unsubscribe from. - :param callback: A callback to be triggered upon completion (Optional). + :param callback: A callback to be invoked upon completion (Optional). :raises: ValueError if topic is None or has zero string length. :raises: ConnectionDroppedError if connection is dropped during execution. :raises: ProtocolClientError if there is some other client error. :raises: NoConnectionError if the client isn't actually connected. """ - logger.info("unsubscribing from Topic Filter {}".format(topic)) + logger.info("sending MQTT UNSUBSCRIBE for Topic Filter {}".format(topic)) try: paho_error_code, mid = self._mqtt_client.unsubscribe(topic) except ValueError: @@ -535,11 +677,11 @@ def unsubscribe(self, topic, callback=None): raise exceptions.ProtocolClientError( "Unexpected Paho failure during unsubscribe" ) from e - logger.debug("Paho unsubscribe returned error code={}".format(paho_error_code)) + logger.debug("Paho client.unsubscribe() returned MQTTErrorCode={}".format(paho_error_code)) if paho_error_code: # This could result in ConnectionDroppedError or ProtocolClientError raise _create_error_from_paho_error_code(paho_error_code) - self._op_manager.establish_operation(mid, callback) + self._op_manager.register_operation(mid, callback) def publish(self, topic, payload, qos=1, callback=None): """ @@ -549,166 +691,193 @@ def publish(self, topic, payload, qos=1, callback=None): :param payload: The Application Message payload. :type payload: str, bytes, int, float or None :param int qos: The QoS level for delivery of the Application Message. Defaults to 1. - :param callback: A callback to be triggered upon completion (Optional). + :param callback: A callback to be invoked upon completion (Optional). :raises: ValueError if qos is not 0, 1 or 2 :raises: ValueError if topic is None or has zero string length - :raises: ValueError if the Topic Name contains a wildcard character ("+" or "#") + :raises: ValueError if topic contains a wildcard character ("+" or "#") :raises: ValueError if the length of the payload is greater than 268435455 bytes :raises: TypeError if payload is not a valid type :raises: ConnectionDroppedError if connection is dropped during execution. :raises: ProtocolClientError if there is some other client error. - :raises: NoConnectionError if the client isn't actually connected. + :raises: NoConnectionError if a QoS 0 message is published while the client is not connected. """ - logger.info("publishing on Topic Name {}".format(topic)) + logger.info("sending MQTT PUBLISH on Topic Name {} with QoS {}".format(topic, qos)) try: - paho_error_code, mid = self._mqtt_client.publish(topic=topic, payload=payload, qos=qos) + # NOTE: Paho MQTTMessageInfo allows you to wait upon the completion with + # `wait_for_publish()`,but that is only supported for PUBLISH. + # We don't take advantage of it in favor of a general solution (i.e. OperationManager) + # which can track SUBSCRIBE and UNSUBSCRIBE operations as well. + # Furthermore, `wait_for_publish()` is buggy when sending a message while disconnected, + # and does not accurately report the success or failure of the publish operation. + message_info = self._mqtt_client.publish(topic=topic, payload=payload, qos=qos) except ValueError: raise except TypeError: raise except Exception as e: raise exceptions.ProtocolClientError("Unexpected Paho failure during publish") from e - logger.debug("Paho publish returned error code={}".format(paho_error_code)) - if paho_error_code: + paho_error_code = message_info.rc + mid = message_info.mid + logger.debug( + "Paho client.publish() returned MQTTMessageInfo with MQTTErrorCode={}".format( + paho_error_code + ) + ) + publish_retained_for_next_connection = paho_error_code == mqtt.MQTT_ERR_NO_CONN and qos > 0 + if paho_error_code and not publish_retained_for_next_connection: # This could result in ConnectionDroppedError or ProtocolClientError raise _create_error_from_paho_error_code(paho_error_code) - self._op_manager.establish_operation(mid, callback) + if publish_retained_for_next_connection: + logger.debug( + "Paho retained QoS {} PUBLISH with MID {} for the next connection".format(qos, mid) + ) + self._op_manager.register_operation(mid, callback) class OperationManager(object): - """Tracks callbacks by Paho message ID, including responses received before registration.""" + """Tracks callbacks by Paho MID, including completions received for unknown MIDs + (For instance, responses received before a registration). + """ def __init__(self): - # Maps Paho message ID to callback for operations awaiting a response. + # Maps Paho MID to callback for operations awaiting a response. self._pending_operation_callbacks = {} - # Maps Paho message ID to an optional error when a response arrives before registration. - self._early_operation_completions = {} + # Maps Paho MIDs with no currently registered operation to optional completion errors. + # Necessary because sometimes an operation will complete with a response before the + # Paho call returns. + self._unknown_operation_completions = {} self._lock = threading.Lock() - def establish_operation(self, mid, callback=None): - """Register a pending operation and callback under its Paho message ID. + def register_operation(self, mid, callback=None): + """Register a pending operation and callback under its Paho MID, and store its completion + callback. - If the operation has already been completed, the callback will be triggered. + If a completion has already been recorded for the MID, the callback will be invoked. + Otherwise, the callback will be invoked when the completion is received. """ - trigger_callback = False + invoke_callback = False completion_error = None with self._lock: - # Paho can invoke the response callback before its API call returns the message ID. - if mid in self._early_operation_completions: + # Paho can invoke the response callback before its API call returns the MID, + # thus, the operation might have already completed. + if mid in self._unknown_operation_completions: - # Clear the early response now that its operation has been established. - completion_error = self._early_operation_completions.pop(mid) + # Claim the unknown completion now that its operation has been established. + completion_error = self._unknown_operation_completions.pop(mid) - # Since the operation has already completed, indicate callback should trigger - trigger_callback = True + # Since a completion was already recorded, indicate callback should be invoked. + invoke_callback = True else: # Store the operation as pending, along with callback self._pending_operation_callbacks[mid] = callback - logger.debug("Waiting for response on Paho message ID: {}".format(mid)) + logger.debug("Waiting for response on Paho MID {}".format(mid)) - # Now that the lock has been released, if the callback should be triggered, - # go ahead and trigger it now. - if trigger_callback: + # Invoke the callback only after releasing the lock. + if invoke_callback: logger.debug( - "Response for Paho message ID: {} was received early - triggering callback".format( + "Completion for previously unknown Paho MID {} matched registered operation; invoking callback".format( mid ) ) if callback: try: + # Not all operation callbacks accept the optional error argument. if completion_error is not None: callback(error=completion_error) else: callback() except Exception: - logger.debug( - "Unexpected error calling callback for Paho message ID: {}".format(mid) - ) + logger.debug("Unexpected error calling callback for Paho MID {}".format(mid)) logger.debug(traceback.format_exc()) else: # Completion callbacks are optional. - logger.debug("No callback for Paho message ID: {}".format(mid)) + logger.debug("No callback for Paho MID {}".format(mid)) def complete_operation(self, mid, error=None): - """Complete an operation by Paho message ID and trigger its callback. + """Complete an operation by Paho MID and invoke its callback (if any was set). - If the operation has not been established yet, retain its completion error until it is. + If the MID is unknown, retain its completion in case its operation is registered later. """ callback = None - trigger_callback = False + invoke_callback = False with self._lock: - # If the Paho message ID has a pending operation, trigger its callback. + # If the Paho MID has a pending operation, invoke its callback. if mid in self._pending_operation_callbacks: # Retrieve the callback, and clear the pending operation now that it has been completed callback = self._pending_operation_callbacks[mid] del self._pending_operation_callbacks[mid] - # Since the operation is complete, indicate the callback should be triggered - trigger_callback = True - + # Since the operation is complete, indicate the callback should be invoked. + invoke_callback = True + # Otherwise, store the mid as an unknown response else: - logger.debug( - "Response received before Paho message ID was registered: {}".format(mid) - ) - self._early_operation_completions[mid] = error + logger.debug("Completion received for unknown Paho MID {}; retaining".format(mid)) + self._unknown_operation_completions[mid] = error - # Now that the lock has been released, if the callback should be triggered, - # go ahead and trigger it now. - if trigger_callback: + # Invoke the callback only after releasing the lock. + if invoke_callback: logger.debug( - "Response received for registered Paho message ID: {} - triggering callback".format( - mid - ) + "Response received for registered Paho MID {}; invoking callback".format(mid) ) if callback: try: + # Not all operation callbacks accept the optional error argument. if error is not None: callback(error=error) else: callback() except Exception: - logger.debug( - "Unexpected error calling callback for Paho message ID: {}".format(mid) - ) + logger.debug("Unexpected error calling callback for Paho MID {}".format(mid)) logger.debug(traceback.format_exc()) else: # Completion callbacks are optional. - logger.debug("No callback set for Paho message ID: {}".format(mid)) + logger.debug("No callback set for Paho MID {}".format(mid)) - def cancel_all_operations(self): - """Cancel pending operations and clear all Paho message ID tracking.""" - logger.debug("Cancelling all pending operations") + def complete_all_tracked_operations_as_cancelled(self): + """Complete all tracked SDK operations as cancelled and clear unknown completions. + + This manager owns only local completion tracking: pending callbacks are invoked with + ``cancelled=True`` and their MIDs are forgotten. Operations already accepted by Paho are + unaffected and may still complete or take effect. + """ + logger.debug("Completing all tracked operations as cancelled") with self._lock: - # Clear pending operations + # Preserve callbacks for invocation after releasing the lock. pending_ops = list(self._pending_operation_callbacks.items()) - for pending_op in pending_ops: - mid = pending_op[0] - del self._pending_operation_callbacks[mid] - - # Clear responses that arrived before their operations were established. - early_mids = list(self._early_operation_completions) - for mid in early_mids: - del self._early_operation_completions[mid] + self._pending_operation_callbacks.clear() + self._unknown_operation_completions.clear() - # Trigger cancel in pending operation callbacks + # Invoke pending operation callbacks with cancellation. for pending_op in pending_ops: mid = pending_op[0] callback = pending_op[1] if callback: - logger.debug("Cancelling Paho message ID {} - triggering callback".format(mid)) + logger.debug( + "Completing tracked operation for Paho MID {} as cancelled; invoking callback".format( + mid + ) + ) try: callback(cancelled=True) except Exception: - logger.debug( - "Unexpected error calling callback for Paho message ID: {}".format(mid) - ) + logger.debug("Unexpected error calling callback for Paho MID {}".format(mid)) logger.debug(traceback.format_exc()) else: - logger.debug("Cancelling Paho message ID {} - no callback set".format(mid)) + logger.debug( + "Completing tracked operation for Paho MID {} as cancelled; no callback set".format( + mid + ) + ) + + +# TODO: Track operation types so disconnects can cancel pending SUBSCRIBE and UNSUBSCRIBE +# operations while preserving PUBLISH operations that Paho can complete after the next connection. +# TODO: Clarify hard-disconnect semantics because cancelling an SDK publish operation does not +# prevent Paho from delivering a retained QoS 1 or QoS 2 message after a later connection. diff --git a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_base.py b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_base.py index 26f90ffdf..78b8ca228 100644 --- a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_base.py +++ b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_base.py @@ -780,7 +780,7 @@ def __init__(self): self.timeout_intervals = { pipeline_ops_mqtt.MQTTSubscribeOperation: 10, pipeline_ops_mqtt.MQTTUnsubscribeOperation: 10, - # Only Sub and Unsub are here because MQTT auto retries pub + # Only Sub and Unsub are here because MQTT client will resend QoS 1 publishes after reconnect automatically } @pipeline_thread.runs_on_pipeline_thread @@ -838,7 +838,7 @@ def __init__(self): self.retry_intervals = { pipeline_ops_mqtt.MQTTSubscribeOperation: 20, pipeline_ops_mqtt.MQTTUnsubscribeOperation: 20, - # Only Sub and Unsub are here because MQTT auto retries pub + # Only Sub and Unsub are here because MQTT client will resend QoS 1 publishes after reconnect automatically } self.ops_waiting_to_retry = [] diff --git a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py index 1f6036995..8934b3e70 100644 --- a/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py +++ b/azure-iot-device/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py @@ -22,16 +22,17 @@ logger = logging.getLogger(__name__) -# Maximum amount of time we wait for ConnectOperation to complete +# Maximum time to wait for a ConnectOperation to complete. # TODO: This whole logic of timeout should probably be handled in the TimeoutStage -WATCHDOG_INTERVAL = 60 +CONNECTION_WATCHDOG_TIMEOUT = 60 class MQTTTransportStage(PipelineStage): """ - PipelineStage object which is responsible for interfacing with the MQTT protocol wrapper object. - This stage handles all MQTT operations and any other operations (such as ConnectOperation) which - is not in the MQTT group of operations, but can only be run at the protocol level. + PipelineStage responsible for interfacing with MQTTTransport. + + This stage handles MQTT operations and connection lifecycle operations that must run at the + transport level. """ def __init__(self): @@ -39,28 +40,29 @@ def __init__(self): # The transport will be instantiated upon receiving the InitializePipelineOperation self.transport = None - # The current in-progress op that affects connection state (Connect, Disconnect, Reauthorize) + # The pending ConnectOperation or DisconnectOperation, if any. self._pending_connection_op = None @pipeline_thread.runs_on_pipeline_thread - def _cancel_pending_connection_op(self, error=None): - """ - Cancel any running connect, disconnect or reauthorize connection op. Since our ability to "cancel" is fairly limited, - all this does (for now) is to fail the operation + def _fail_pending_connection_op(self, error=None): + """Complete the pending connection operation with an error. + + If no error is supplied, the operation is superseded by a newer connection operation and + is completed with OperationCancelled. """ - op = self._pending_connection_op - if op: + pending_op = self._pending_connection_op + if pending_op: # NOTE: This code path should NOT execute in normal flow. There should never already be a pending # connection op when another is added, due to the ConnectionLock stage. # If this block does execute, there is a bug in the codebase. - if not error: + if error is None: error = pipeline_exceptions.OperationCancelled( "Cancelling because new ConnectOperation or DisconnectOperation was issued" ) - self._cancel_connection_watchdog(op) + self._cancel_connection_watchdog(pending_op) self._pending_connection_op = None - op.complete(error=error) + pending_op.complete(error=error) @pipeline_thread.runs_on_pipeline_thread def _start_connection_watchdog(self, connection_op): @@ -72,21 +74,23 @@ def _start_connection_watchdog(self, connection_op): """ logger.debug("{}({}): Starting watchdog".format(self.name, connection_op.name)) - self_weakref = weakref.ref(self) - op_weakref = weakref.ref(connection_op) + stage_weakref = weakref.ref(self) + connection_op_weakref = weakref.ref(connection_op) @pipeline_thread.invoke_on_pipeline_thread - def watchdog_function(): - this = self_weakref() - op = op_weakref() - if this and op and this._pending_connection_op is op: + def on_connection_watchdog_expired(): + stage = stage_weakref() + connection_op = connection_op_weakref() + if stage and connection_op and stage._pending_connection_op is connection_op: logger.info( - "{}({}): Connection watchdog expired. Cancelling op".format(this.name, op.name) + "{}({}): Connection watchdog expired. Failing operation".format( + stage.name, connection_op.name + ) ) try: - this.transport.disconnect() + stage.transport.disconnect() except Exception: - # If we don't catch this, the pending connection op might not ever be cancelled. + # If we don't catch this, the pending connection op might not be completed. # Most likely, the transport isn't actually connected, but other failures are theoretically # possible. Either way, if disconnect fails, we should assume that we're disconnected. logger.info( @@ -94,15 +98,15 @@ def watchdog_function(): ) logger.info(traceback.format_exc()) - if this.nucleus.connected: + if stage.nucleus.connected: logger.info( "{}({}): Pipeline is still connected on watchdog expiration. Sending DisconnectedEvent".format( - this.name, op.name + stage.name, connection_op.name ) ) - this.send_event_up(pipeline_events_base.DisconnectedEvent()) - this._cancel_pending_connection_op( + stage.send_event_up(pipeline_events_base.DisconnectedEvent()) + stage._fail_pending_connection_op( error=pipeline_exceptions.OperationTimeout( "Transport timeout on connection operation" ) @@ -110,17 +114,19 @@ def watchdog_function(): else: logger.debug("Connection watchdog expired, but pending op is not the same op") - connection_op.watchdog_timer = threading.Timer(WATCHDOG_INTERVAL, watchdog_function) + connection_op.watchdog_timer = threading.Timer( + CONNECTION_WATCHDOG_TIMEOUT, on_connection_watchdog_expired + ) connection_op.watchdog_timer.daemon = True connection_op.watchdog_timer.start() @pipeline_thread.runs_on_pipeline_thread - def _cancel_connection_watchdog(self, op): + def _cancel_connection_watchdog(self, connection_op): try: - if op.watchdog_timer: - logger.debug("{}({}): cancelling watchdog".format(self.name, op.name)) - op.watchdog_timer.cancel() - op.watchdog_timer = None + if connection_op.watchdog_timer: + logger.debug("{}({}): cancelling watchdog".format(self.name, connection_op.name)) + connection_op.watchdog_timer.cancel() + connection_op.watchdog_timer = None except AttributeError: pass @@ -145,7 +151,7 @@ def _run_op(self, op): ) hostname = self.nucleus.pipeline_configuration.hostname - # Create the Transport object, set it's handlers + # Create the transport and set its handlers. logger.debug("{}({}): got connection args".format(self.name, op.name)) self.transport = MQTTTransport( client_id=op.client_id, @@ -163,19 +169,10 @@ def _run_op(self, op): self.transport.on_mqtt_disconnected_handler = self._on_mqtt_disconnected self.transport.on_mqtt_message_received_handler = self._on_mqtt_message_received - # There can only be one pending connection operation (Connect, Disconnect) - # at a time. The existing one must be completed or canceled before a new one is set. - - # Currently, this means that if, say, a connect operation is the pending op and is executed - # but another connection op is begins by the time the CONNACK is received, the original - # operation will be cancelled, but the CONNACK for it will still be received, and complete the - # NEW operation. This is not desirable, but it is how things currently work. - - # We are however, checking the type, so the CONNACK from a cancelled Connect, cannot successfully - # complete a Disconnect operation. - - # Note that a ReauthorizeConnectionOperation will never be pending because it will - # instead spawn separate Connect and Disconnect operations. + # Only one ConnectOperation or DisconnectOperation can be pending. Lifecycle callbacks + # snapshot its identity before entering the pipeline thread, so stale queued callbacks + # cannot affect a later operation. Reauthorization sequences worker operations and is + # never stored here directly. self._pending_connection_op = None op.complete() @@ -193,7 +190,7 @@ def _run_op(self, op): elif isinstance(op, pipeline_ops_base.ConnectOperation): logger.debug("{}({}): connecting".format(self.name, op.name)) - self._cancel_pending_connection_op() + self._fail_pending_connection_op() self._pending_connection_op = op self._start_connection_watchdog(op) # Use SasToken as password if present. If not present (e.g. using X509), @@ -214,21 +211,21 @@ def _run_op(self, op): elif isinstance(op, pipeline_ops_base.DisconnectOperation): logger.debug("{}({}): disconnecting".format(self.name, op.name)) - self._cancel_pending_connection_op() + self._fail_pending_connection_op() self._pending_connection_op = op - # We don't need a watchdog on disconnect because there's no callback to wait for - # and we respond to a watchdog timeout by calling disconnect, which is what we're - # already doing. + # No watchdog is needed because MQTTTransport.disconnect() blocks until its network + # loop stops; this stage does not wait for the queued disconnected callback. try: - # The connect after the disconnect will be triggered upon completion of the - # disconnect in the on_disconnected handler + # MQTTTransport.disconnect() blocks until the network loop has stopped. self.transport.disconnect(clear_inflight=op.hard) except Exception as e: logger.info("transport.disconnect raised error while disconnecting") logger.info(traceback.format_exc()) self._pending_connection_op = None op.complete(error=e) + else: + self._handle_disconnected_state() elif isinstance(op, pipeline_ops_base.ReauthorizeConnectionOperation): logger.debug( @@ -236,23 +233,25 @@ def _run_op(self, op): self.name, op.name ) ) - self_weakref = weakref.ref(self) - reauth_op = op # rename for clarity + stage_weakref = weakref.ref(self) + reauthorization_op = op - def on_disconnect_complete(op, error): - this = self_weakref() + def on_reauthorization_disconnect_complete(op, error): + stage = stage_weakref() if error: # Failing a disconnect should still get us disconnected, so can proceed anyway logger.debug( "Disconnect failed during reauthorization, continuing with connect" ) - connect_op = reauth_op.spawn_worker_op(pipeline_ops_base.ConnectOperation) + connect_op = reauthorization_op.spawn_worker_op(pipeline_ops_base.ConnectOperation) # NOTE: this relies on the fact that before the disconnect is completed it is # unset as the pending connection op. Otherwise there would be issues here. - this.run_op(connect_op) + stage.run_op(connect_op) - disconnect_op = pipeline_ops_base.DisconnectOperation(callback=on_disconnect_complete) + disconnect_op = pipeline_ops_base.DisconnectOperation( + callback=on_reauthorization_disconnect_complete + ) disconnect_op.hard = False self.run_op(disconnect_op) @@ -261,7 +260,7 @@ def on_disconnect_complete(op, error): logger.debug("{}({}): publishing on {}".format(self.name, op.name, op.topic)) @pipeline_thread.invoke_on_pipeline_thread_nowait - def on_complete(cancelled=False): + def on_publish_complete(cancelled=False): if cancelled: op.complete( error=pipeline_exceptions.OperationCancelled( @@ -275,7 +274,9 @@ def on_complete(cancelled=False): op.complete() try: - self.transport.publish(topic=op.topic, payload=op.payload, callback=on_complete) + self.transport.publish( + topic=op.topic, payload=op.payload, callback=on_publish_complete + ) except Exception as e: op.complete(error=e) @@ -283,7 +284,7 @@ def on_complete(cancelled=False): logger.debug("{}({}): subscribing to {}".format(self.name, op.name, op.topic)) @pipeline_thread.invoke_on_pipeline_thread_nowait - def on_complete(cancelled=False, error=None): + def on_subscribe_complete(cancelled=False, error=None): if cancelled: op.complete( error=pipeline_exceptions.OperationCancelled( @@ -299,7 +300,7 @@ def on_complete(cancelled=False, error=None): op.complete() try: - self.transport.subscribe(topic=op.topic, callback=on_complete) + self.transport.subscribe(topic=op.topic, callback=on_subscribe_complete) except Exception as e: op.complete(error=e) @@ -307,7 +308,7 @@ def on_complete(cancelled=False, error=None): logger.debug("{}({}): unsubscribing from {}".format(self.name, op.name, op.topic)) @pipeline_thread.invoke_on_pipeline_thread_nowait - def on_complete(cancelled=False): + def on_unsubscribe_complete(cancelled=False): if cancelled: op.complete( error=pipeline_exceptions.OperationCancelled( @@ -321,7 +322,7 @@ def on_complete(cancelled=False): op.complete() try: - self.transport.unsubscribe(topic=op.topic, callback=on_complete) + self.transport.unsubscribe(topic=op.topic, callback=on_unsubscribe_complete) except Exception as e: op.complete(error=e) @@ -333,7 +334,7 @@ def on_complete(cancelled=False): @pipeline_thread.invoke_on_pipeline_thread_nowait def _on_mqtt_message_received(self, topic, payload): """ - Handler that gets called by the protocol library when an incoming message arrives. + Handler that gets called by the transport when an incoming message arrives. Convert that message into a pipeline event and pass it up for someone to handle. """ logger.debug("{}: message received on topic {}".format(self.name, topic)) @@ -341,12 +342,26 @@ def _on_mqtt_message_received(self, topic, payload): pipeline_events_mqtt.IncomingMQTTMessageEvent(topic=topic, payload=payload) ) - @pipeline_thread.invoke_on_pipeline_thread_nowait + # Lifecycle callbacks must snapshot the pending operation before queueing work on the pipeline + # thread; otherwise, a delayed callback could act on a newer operation. Message callbacks can + # be queued directly because their topic and payload are already captured in the callback args. def _on_mqtt_connected(self): - """ - Handler that gets called by the transport when it connects. - """ - logger.info("_on_mqtt_connected called") + """Snapshot the pending operation and queue connected-callback processing.""" + connection_op_snapshot = self._pending_connection_op + self._process_mqtt_connected_callback(connection_op_snapshot) + + @pipeline_thread.invoke_on_pipeline_thread_nowait + def _process_mqtt_connected_callback(self, connection_op_snapshot): + """Process a connected callback on the pipeline thread.""" + if connection_op_snapshot is not self._pending_connection_op: + logger.info( + "{}: Ignoring connected callback for a connection operation that is no longer pending".format( + self.name + ) + ) + return + + logger.info("{}: MQTT connected".format(self.name)) # Send an event to tell other pipeline stages that we're connected. Do this before # we do anything else (in case upper stages have any "are we connected" logic. self.send_event_up(pipeline_events_base.ConnectedEvent()) @@ -365,15 +380,30 @@ def _on_mqtt_connected(self): "{}: Connection was unexpected (no connection op pending)".format(self.name) ) - @pipeline_thread.invoke_on_pipeline_thread_nowait + # Lifecycle callbacks must snapshot the pending operation before queueing work on the pipeline + # thread; otherwise, a delayed callback could act on a newer operation. Message callbacks can + # be queued directly because their topic and payload are already captured in the callback args. def _on_mqtt_connection_failure(self, cause): - """ - Handler that gets called by the transport when a connection fails. + """Snapshot the pending operation and queue failure-callback processing.""" + connection_op_snapshot = self._pending_connection_op + self._process_mqtt_connection_failure_callback(connection_op_snapshot, cause) + + @pipeline_thread.invoke_on_pipeline_thread_nowait + def _process_mqtt_connection_failure_callback(self, connection_op_snapshot, cause): + """Process a connection-failure callback on the pipeline thread. :param Exception cause: The Exception that caused the connection failure. """ - logger.info("{}: _on_mqtt_connection_failure called: {}".format(self.name, cause)) + if connection_op_snapshot is not self._pending_connection_op: + logger.info( + "{}: Ignoring connection failure callback for a connection operation that is no longer pending".format( + self.name + ) + ) + return + + logger.info("{}: MQTT connection failed: {}".format(self.name, cause)) if isinstance(self._pending_connection_op, pipeline_ops_base.ConnectOperation): logger.debug("{}: failing connect op".format(self.name)) @@ -389,17 +419,39 @@ def _on_mqtt_connection_failure(self, cause): log_lvl="info", ) - @pipeline_thread.invoke_on_pipeline_thread_nowait + # Lifecycle callbacks must snapshot the pending operation before queueing work on the pipeline + # thread; otherwise, a delayed callback could act on a newer operation. Message callbacks can + # be queued directly because their topic and payload are already captured in the callback args. def _on_mqtt_disconnected(self, cause=None): - """ - Handler that gets called by the transport when the transport disconnects. + """Snapshot the pending operation and queue disconnected-callback processing.""" + connection_op_snapshot = self._pending_connection_op + self._process_mqtt_disconnected_callback(connection_op_snapshot, cause) + + @pipeline_thread.invoke_on_pipeline_thread_nowait + def _process_mqtt_disconnected_callback(self, connection_op_snapshot, cause=None): + """Process a disconnected callback on the pipeline thread.""" + if connection_op_snapshot is not self._pending_connection_op: + logger.info( + "{}: Ignoring disconnected callback for a connection operation that is no longer pending".format( + self.name + ) + ) + return + + self._handle_disconnected_state(cause) + + @pipeline_thread.runs_on_pipeline_thread + def _handle_disconnected_state(self, cause=None): + """Handle disconnected-state effects on the pipeline thread. + + Called after either a transport callback or a successful blocking disconnect. :param Exception cause: The Exception that caused the disconnection, if any (optional) """ if cause: - logger.info("{}: _on_mqtt_disconnect called: {}".format(self.name, cause)) + logger.info("{}: MQTT disconnected: {}".format(self.name, cause)) else: - logger.info("{}: _on_mqtt_disconnect called".format(self.name)) + logger.info("{}: MQTT disconnected".format(self.name)) # Send an event to tell other pipeline stages that we're disconnected. Do this before # we do anything else (in case upper stages have any "are we connected" logic.) @@ -409,9 +461,9 @@ def _on_mqtt_disconnected(self, cause=None): if self._pending_connection_op: - op = self._pending_connection_op + connection_op = self._pending_connection_op - if isinstance(op, pipeline_ops_base.DisconnectOperation): + if isinstance(connection_op, pipeline_ops_base.DisconnectOperation): logger.debug( "{}: Expected disconnect - completing pending disconnect op".format(self.name) ) @@ -424,40 +476,40 @@ def _on_mqtt_disconnected(self, cause=None): ) # Disconnect complete, no longer pending self._pending_connection_op = None - op.complete() + connection_op.complete() else: logger.debug( "{}: Unexpected disconnect - completing pending {} operation".format( - self.name, op.name + self.name, connection_op.name ) ) # Cancel any potential connection watchdog, and clear the pending op - self._cancel_connection_watchdog(op) + self._cancel_connection_watchdog(connection_op) self._pending_connection_op = None # Complete if cause: - op.complete(error=cause) + connection_op.complete(error=cause) else: - op.complete( + connection_op.complete( error=transport_exceptions.ConnectionDroppedError("transport disconnected") ) else: logger.info("{}: Unexpected disconnect (no pending connection op)".format(self.name)) - # If there is no connection retry, cancel any transport operations waiting on response - # so that they do not get stuck there. + # If there is no connection retry, complete tracked MQTT operations as cancelled so + # they do not remain pending indefinitely. if not self.nucleus.pipeline_configuration.connection_retry: logger.debug( - "{}: Connection Retry disabled - cancelling in-flight operations".format( + "{}: Connection Retry disabled - completing tracked MQTT operations as cancelled".format( self.name ) ) # TODO: Remove private access to the op manager (this layer shouldn't know about it) # This is a stopgap. I didn't want to invest too much infrastructure into a cancel flow # given that future development of individual operation cancels might affect the - # approach to cancelling inflight ops waiting in the transport. - self.transport._op_manager.cancel_all_operations() + # approach to completing tracked transport operations as cancelled. + self.transport._op_manager.complete_all_tracked_operations_as_cancelled() # Regardless of cause, it is now a ConnectionDroppedError. Log it and swallow it. # Higher layers will see that we're disconnected and may reconnect as necessary. diff --git a/tests/e2e/iothub_e2e/aio/test_send_message.py b/tests/e2e/iothub_e2e/aio/test_send_message.py index 7450f8754..bc1545594 100644 --- a/tests/e2e/iothub_e2e/aio/test_send_message.py +++ b/tests/e2e/iothub_e2e/aio/test_send_message.py @@ -205,8 +205,9 @@ async def test_connects_after_automatic_disconnect_retry_disabled( @pytest.mark.it("Fails if connection disconnects before sending") @pytest.mark.uses_iptables - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. - async def test_fails_if_disconnect_before_sending(self, client, random_message, dropper): + async def test_fails_if_disconnect_before_sending( + self, client, random_message, dropper, leak_tracker + ): assert client.connected @@ -222,9 +223,8 @@ async def test_fails_if_disconnect_before_sending(self, client, random_message, @pytest.mark.it("Fails if connection drops before sending") @pytest.mark.uses_iptables - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. async def test_fails_if_drop_before_sending_retry_disabled( - self, client, random_message, dropper + self, client, random_message, dropper, leak_tracker ): assert client.connected diff --git a/tests/e2e/iothub_e2e/aio/test_twin.py b/tests/e2e/iothub_e2e/aio/test_twin.py index bef8a03a2..a368a2fe5 100644 --- a/tests/e2e/iothub_e2e/aio/test_twin.py +++ b/tests/e2e/iothub_e2e/aio/test_twin.py @@ -107,9 +107,8 @@ class TestReportedPropertiesDroppedConnection(object): # TODO: split drop tests between first and second patches @pytest.mark.it("Updates reported properties if connection drops before sending") - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. async def test_updates_reported_if_drop_before_sending( - self, client, random_reported_props, dropper, service_helper + self, client, random_reported_props, dropper, service_helper, leak_tracker ): assert client.connected @@ -138,9 +137,8 @@ async def test_updates_reported_if_drop_before_sending( ) @pytest.mark.it("Updates reported properties if connection rejects send") - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. async def test_updates_reported_if_reject_before_sending( - self, client, random_reported_props, dropper, service_helper + self, client, random_reported_props, dropper, service_helper, leak_tracker ): assert client.connected diff --git a/tests/e2e/iothub_e2e/sync/test_sync_send_message.py b/tests/e2e/iothub_e2e/sync/test_sync_send_message.py index 804dc523a..7522765fa 100644 --- a/tests/e2e/iothub_e2e/sync/test_sync_send_message.py +++ b/tests/e2e/iothub_e2e/sync/test_sync_send_message.py @@ -193,9 +193,8 @@ def test_sync_connects_after_automatic_disconnect_with_retry_disabled( @pytest.mark.it("Fails if connection disconnects before sending") @pytest.mark.uses_iptables - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. def test_sync_fails_if_disconnect_before_sending_with_retry_disabled( - self, client, random_message, dropper, run_in_daemon_thread + self, client, random_message, dropper, run_in_daemon_thread, leak_tracker ): assert client.connected @@ -210,9 +209,8 @@ def test_sync_fails_if_disconnect_before_sending_with_retry_disabled( @pytest.mark.it("Fails if connection drops before sending") @pytest.mark.uses_iptables - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. def test_sync_fails_if_drop_before_sending_with_retry_disabled( - self, client, random_message, dropper + self, client, random_message, dropper, leak_tracker ): assert client.connected diff --git a/tests/e2e/iothub_e2e/sync/test_sync_twin.py b/tests/e2e/iothub_e2e/sync/test_sync_twin.py index c7815d0ad..af4b7174e 100644 --- a/tests/e2e/iothub_e2e/sync/test_sync_twin.py +++ b/tests/e2e/iothub_e2e/sync/test_sync_twin.py @@ -106,7 +106,6 @@ class TestReportedPropertiesDroppedConnection(object): # TODO: split drop tests between first and second patches @pytest.mark.it("Updates reported properties if connection drops before sending") - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. def test_sync_updates_reported_if_drop_before_sending( self, client, @@ -114,6 +113,7 @@ def test_sync_updates_reported_if_drop_before_sending( dropper, service_helper, run_in_daemon_thread, + leak_tracker, ): assert client.connected @@ -138,7 +138,6 @@ def test_sync_updates_reported_if_drop_before_sending( ) @pytest.mark.it("Updates reported properties if connection rejects send") - # TODO: Re-enable leak tracking after the MQTT cancellation refactor. def test_sync_updates_reported_if_reject_before_sending( self, client, @@ -146,6 +145,7 @@ def test_sync_updates_reported_if_reject_before_sending( dropper, service_helper, run_in_daemon_thread, + leak_tracker, ): assert client.connected diff --git a/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py b/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py index 8c1c56eb5..68a7f7b32 100644 --- a/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py +++ b/tests/unit/common/pipeline/test_pipeline_stages_mqtt.py @@ -498,10 +498,12 @@ class TestMQTTTransportStageRunOpCalledWithDisconnectOperation( def op(self, mocker): return pipeline_ops_base.DisconnectOperation(callback=mocker.MagicMock()) - @pytest.mark.it("Sets the operation as the stage's pending connection operation") - def test_sets_pending_operation(self, stage, op): + @pytest.mark.it("Completes the operation after the transport disconnect returns") + def test_completes_operation(self, stage, op): stage.run_op(op) - assert stage._pending_connection_op is op + assert op.completed + assert op.error is None + assert stage._pending_connection_op is None @pytest.mark.it("Cancels any already pending connection operation") @pytest.mark.parametrize( @@ -529,13 +531,15 @@ def test_pending_operation_cancelled(self, mocker, stage, op, pending_connection assert pending_connection_op.completed assert type(pending_connection_op.error) is pipeline_exceptions.OperationCancelled - # New operation is now the pending operation - assert stage._pending_connection_op is op + # The new disconnect operation completed after the transport returned. + assert op.completed + assert op.error is None + assert stage._pending_connection_op is None @pytest.mark.it( "Performs an MQTT disconnect via the MQTTTransport, using the 'clear_inflight' option only if the operation is configured for a hard disconnect" ) - def test_mqtt_connect(self, mocker, stage, op): + def test_mqtt_disconnect(self, mocker, stage, op): # Hard disconnect assert op.hard is True stage.run_op(op) @@ -545,11 +549,35 @@ def test_mqtt_connect(self, mocker, stage, op): stage.transport.disconnect.reset_mock() # Soft disconnect - op.hard = False - stage.run_op(op) + soft_op = pipeline_ops_base.DisconnectOperation(callback=mocker.MagicMock()) + soft_op.hard = False + stage.run_op(soft_op) assert stage.transport.disconnect.call_count == 1 assert stage.transport.disconnect.call_args == mocker.call(clear_inflight=False) + @pytest.mark.it("Sends a DisconnectedEvent after the transport disconnect returns") + def test_sends_disconnected_event(self, stage, op): + stage.run_op(op) + + assert stage.send_event_up.call_count == 1 + assert isinstance( + stage.send_event_up.call_args.args[0], pipeline_events_base.DisconnectedEvent + ) + + @pytest.mark.it("Ignores a delayed callback after the disconnect operation completes") + def test_ignores_delayed_disconnect_callback(self, stage, op): + stage.run_op(op) + assert stage.send_event_up.call_count == 1 + + # The Paho callback captured this operation before loop_stop() joined its thread, + # but its queued pipeline work runs after the operation has completed. + stage._process_mqtt_disconnected_callback(op) + + assert op.completed + assert op.error is None + assert stage.send_event_up.call_count == 1 + assert stage.report_background_exception.call_count == 0 + @pytest.mark.it( "Completes the operation unsuccessfully if there is a failure disconnecting via the MQTTTransport, using the error raised by the MQTTTransport" ) @@ -602,7 +630,7 @@ def test_complete(self, mocker, stage, op): assert op.error is None @pytest.mark.it( - "Completes the operation with an OperationCancelled error upon cancellation of the MQTT publish by the MQTTTransport" + "Completes the operation with an OperationCancelled error when the MQTTTransport reports publish cancellation" ) def test_complete_with_cancel(self, mocker, stage, op): # Begin publish @@ -675,7 +703,7 @@ def test_complete_with_error(self, stage, op, arbitrary_exception): assert op.error is arbitrary_exception @pytest.mark.it( - "Completes the operation with an OperationCancelled error upon cancellation of the MQTT subscribe by the MQTTTransport" + "Completes the operation with an OperationCancelled error when the MQTTTransport reports subscribe cancellation" ) def test_complete_with_cancel(self, mocker, stage, op): # Begin subscribe @@ -735,7 +763,7 @@ def test_complete(self, mocker, stage, op): assert op.error is None @pytest.mark.it( - "Completes the operation with an OperationCancelled error upon cancellation of the MQTT unsubscribe by the MQTTTransport" + "Completes the operation with an OperationCancelled error when the MQTTTransport reports unsubscribe cancellation" ) def test_complete_with_cancel(self, mocker, stage, op): # Begin unsubscribe @@ -848,13 +876,25 @@ def test_completes_pending_connect_op(self, mocker, stage): assert op.error is None assert stage._pending_connection_op is None + @pytest.mark.it("Does not let a retired connection report a successful replacement connect") + def test_stale_connected(self, mocker, stage): + retired_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + replacement_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + stage._pending_connection_op = replacement_op + + stage._process_mqtt_connected_callback(retired_op) + + assert not replacement_op.completed + assert stage._pending_connection_op is replacement_op + assert stage.send_event_up.call_count == 0 + @pytest.mark.it( "Does not complete a pending DisconnectOperation when the transport connected event fires" ) def test_does_not_complete_pending_disconnect_op(self, mocker, stage): # Set a pending disconnect operation op = pipeline_ops_base.DisconnectOperation(callback=mocker.MagicMock()) - stage.run_op(op) + stage._pending_connection_op = op assert not op.completed assert stage._pending_connection_op is op @@ -890,7 +930,7 @@ def test_cancels_watchdog_on_pending_connect(self, mocker, stage, mock_timer): def test_does_not_cancel_watchdog_on_pending_disconnect(self, mocker, stage, mock_timer): # Set a pending disconnect operation op = pipeline_ops_base.DisconnectOperation(callback=mocker.MagicMock()) - stage.run_op(op) + stage._pending_connection_op = op # assert no timers are running assert mock_timer.return_value.start.call_count == 0 @@ -953,7 +993,7 @@ def test_fails_pending_connect_op(self, mocker, stage, arbitrary_exception): def test_ignores_pending_disconnect_op(self, mocker, stage, arbitrary_exception): # Create a pending DisconnectOperation op = pipeline_ops_base.DisconnectOperation(callback=mocker.MagicMock()) - stage.run_op(op) + stage._pending_connection_op = op assert not op.completed assert stage._pending_connection_op is op @@ -983,7 +1023,7 @@ def test_unexpected_connection_failure( # A connection failure is unexpected if there is not a pending Connect operation # i.e. "Why did we get a connection failure? We weren't even trying to connect!" mock_handler = mocker.patch.object(handle_exceptions, "swallow_unraised_exception") - stage._pending_connection_operation = pending_connection_op + stage._pending_connection_op = pending_connection_op # Trigger connection failure with arbitrary cause stage.transport.on_mqtt_connection_failure_handler(arbitrary_exception) @@ -1035,6 +1075,53 @@ def test_does_not_cancel_watchdog_on_pending_disconnect( assert mock_timer.return_value.start.call_count == 0 assert mock_timer.return_value.cancel.call_count == 0 + @pytest.mark.it("Ignores disconnection from a connection whose failure was already handled") + def test_connection_failure_then_disconnect(self, mocker, stage): + connect_error = transport_exceptions.UnauthorizedError("Not authorized") + disconnect_error = transport_exceptions.ConnectionDroppedError("Unspecified error") + op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + stage.run_op(op) + + stage.transport.on_mqtt_connection_failure_handler(connect_error) + + assert op.completed + assert op.error is connect_error + assert stage._pending_connection_op is None + + stage._process_mqtt_disconnected_callback(op, disconnect_error) + + assert op.error is connect_error + assert stage.send_event_up.call_count == 0 + assert stage.report_background_exception.call_count == 0 + + @pytest.mark.it("Does not let a retired connection failure complete a replacement connect") + def test_stale_connection_failure(self, mocker, stage): + retired_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + replacement_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + stage._pending_connection_op = replacement_op + + stage._process_mqtt_connection_failure_callback( + retired_op, transport_exceptions.UnauthorizedError("Not authorized") + ) + + assert not replacement_op.completed + assert stage._pending_connection_op is replacement_op + + @pytest.mark.it("Does not let a retired disconnection complete a replacement connect") + def test_stale_disconnection(self, mocker, stage): + retired_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + replacement_op = pipeline_ops_base.ConnectOperation(callback=mocker.MagicMock()) + stage._pending_connection_op = replacement_op + + stage._process_mqtt_disconnected_callback( + retired_op, transport_exceptions.ConnectionDroppedError("Old connection") + ) + + assert not replacement_op.completed + assert stage._pending_connection_op is replacement_op + assert stage.send_event_up.call_count == 0 + assert stage.report_background_exception.call_count == 0 + @pytest.mark.describe("MQTTTransportStage - OCCURRENCE: MQTT disconnected (Expected)") class TestMQTTTransportStageOnDisconnectedExpected(MQTTTransportStageTestConfigComplex): @@ -1179,11 +1266,11 @@ def cause(self, request, arbitrary_exception): return None @pytest.mark.it( - "Cancels all in-flight operations in the transport, if connection retry has been disabled" + "Completes all tracked MQTT operations as cancelled if connection retry is disabled" ) - def test_inflight_no_retry(self, mocker, stage, cause): + def test_completes_tracked_operations_without_retry(self, mocker, stage, cause): stage.transport._op_manager = mocker.MagicMock() - mock_cancel = stage.transport._op_manager.cancel_all_operations + mock_cancel = stage.transport._op_manager.complete_all_tracked_operations_as_cancelled stage.nucleus.pipeline_configuration.connection_retry = False assert stage._pending_connection_op is None assert mock_cancel.call_count == 0 @@ -1194,12 +1281,10 @@ def test_inflight_no_retry(self, mocker, stage, cause): assert mock_cancel.call_count == 1 assert mock_cancel.call_args == mocker.call() - @pytest.mark.it( - "Does not cancel any in-flight operations in the transport if connection retry has been enabled" - ) - def test_inflight_unexpected_with_retry(self, mocker, stage, cause): + @pytest.mark.it("Does not complete tracked MQTT operations if connection retry is enabled") + def test_preserves_tracked_operations_with_retry(self, mocker, stage, cause): stage.transport._op_manager = mocker.MagicMock() - mock_cancel = stage.transport._op_manager.cancel_all_operations + mock_cancel = stage.transport._op_manager.complete_all_tracked_operations_as_cancelled stage.nucleus.pipeline_configuration.connection_retry = True assert stage._pending_connection_op is None assert mock_cancel.call_count == 0 diff --git a/tests/unit/common/test_mqtt_transport.py b/tests/unit/common/test_mqtt_transport.py index b23d7963b..b846f8c1a 100644 --- a/tests/unit/common/test_mqtt_transport.py +++ b/tests/unit/common/test_mqtt_transport.py @@ -221,6 +221,11 @@ def trigger_on_publish(mqtt_client, mid): case for case in paho_error_code_cases if case["error_code"] != mqtt.MQTT_ERR_NO_CONN ] +# For QoS 1 and QoS 2, Paho retains a publish that returns MQTT_ERR_NO_CONN. +publish_failure_code_cases = [ + case for case in paho_error_code_cases if case["error_code"] != mqtt.MQTT_ERR_NO_CONN +] + @pytest.fixture def mock_mqtt_client(mocker): @@ -228,10 +233,14 @@ def mock_mqtt_client(mocker): mock_mqtt_client = mock.return_value mock_mqtt_client.subscribe = mocker.MagicMock(return_value=(fake_rc, fake_mid)) mock_mqtt_client.unsubscribe = mocker.MagicMock(return_value=(fake_rc, fake_mid)) - mock_mqtt_client.publish = mocker.MagicMock(return_value=(fake_rc, fake_mid)) + message_info = mqtt.MQTTMessageInfo(fake_mid) + message_info.rc = fake_rc + mock_mqtt_client.publish = mocker.MagicMock(return_value=message_info) mock_mqtt_client.connect.return_value = 0 mock_mqtt_client.reconnect.return_value = 0 mock_mqtt_client.disconnect.return_value = 0 + mock_mqtt_client.loop_start.return_value = 0 + mock_mqtt_client.loop_stop.return_value = 0 return mock_mqtt_client @@ -470,12 +479,10 @@ def test_operation_infrastructure_set_up(self, mocker): client_id=fake_device_id, hostname=fake_hostname, username=fake_username ) assert transport._op_manager._pending_operation_callbacks == {} - assert transport._op_manager._early_operation_completions == {} + assert transport._op_manager._unknown_operation_completions == {} - @pytest.mark.it("Does not configure Paho's reconnect delay") + @pytest.mark.it("Does not configure Paho reconnect delay or manual acknowledgements") def test_does_not_set_reconnect_interval(self, transport, mock_mqtt_client): - MQTTTransport(client_id=fake_device_id, hostname=fake_hostname, username=fake_username) - assert mock_mqtt_client.reconnect_delay_set.call_count == 0 assert mock_mqtt_client.manual_ack_set.call_count == 0 @@ -483,7 +490,7 @@ def test_does_not_set_reconnect_interval(self, transport, mock_mqtt_client): @pytest.mark.describe("MQTTTransport - .shutdown()") class TestShutdown(object): @pytest.mark.it("Disconnects Paho and stops its network loop") - def test_disconnects(self, mocker, mock_mqtt_client, transport): + def test_disconnects_and_stops_network_loop(self, mocker, mock_mqtt_client, transport): transport.shutdown() assert mock_mqtt_client.disconnect.call_count == 1 @@ -499,6 +506,34 @@ def test_does_not_trigger_handler(self, mocker, mock_mqtt_client, transport): assert mock_mqtt_client.on_disconnect is None assert mock_disconnect_handler.call_count == 0 + @pytest.mark.it("Stops the network loop and allows any Exception from disconnect to propagate") + def test_stops_loop_if_disconnect_raises( + self, mock_mqtt_client, transport, arbitrary_exception + ): + mock_mqtt_client.disconnect.side_effect = arbitrary_exception + + with pytest.raises(type(arbitrary_exception)) as e_info: + transport.shutdown() + + assert e_info.value is arbitrary_exception + assert mock_mqtt_client.loop_stop.call_count == 1 + + @pytest.mark.it( + "Completes tracked operations as cancelled and allows any Exception from teardown to propagate" + ) + def test_completes_tracked_operations_if_teardown_raises( + self, mocker, mock_mqtt_client, transport, arbitrary_exception + ): + callback = mocker.MagicMock() + transport.subscribe(fake_topic, callback=callback) + mock_mqtt_client.disconnect.side_effect = arbitrary_exception + + with pytest.raises(type(arbitrary_exception)): + transport.shutdown() + + assert callback.call_count == 1 + assert callback.call_args == mocker.call(cancelled=True) + class ArbitraryConnectException(Exception): pass @@ -575,6 +610,80 @@ def test_calls_loop_start(self, mocker, mock_mqtt_client, transport, password): assert mock_mqtt_client.loop_start.call_count == 1 assert mock_mqtt_client.loop_start.call_args == mocker.call() + @pytest.mark.it("Joins a previously started network loop before connecting") + def test_joins_prior_network_loop_before_connect(self, mocker, mock_mqtt_client, transport): + call_order = mocker.MagicMock() + call_order.attach_mock(mock_mqtt_client.loop_stop, "loop_stop") + call_order.attach_mock(mock_mqtt_client.connect, "connect") + + transport.connect(fake_password) + + assert call_order.mock_calls[:2] == [ + mocker.call.loop_stop(), + mocker.call.connect(host=fake_hostname, port=8883, keepalive=None), + ] + + @pytest.mark.it( + "Raises a ProtocolClientError and cleans up if Paho loop_start() returns an error code" + ) + def test_loop_start_returns_error(self, mock_mqtt_client, transport): + mock_mqtt_client.loop_start.return_value = mqtt.MQTT_ERR_INVAL + + with pytest.raises(errors.ProtocolClientError): + transport.connect(fake_password) + + assert mock_mqtt_client.disconnect.call_count == 1 + assert mock_mqtt_client.loop_stop.call_count == 2 + + @pytest.mark.it( + "Raises a ProtocolClientError and cleans up if Paho loop_start() raises an Exception" + ) + def test_loop_start_raises(self, mock_mqtt_client, transport, arbitrary_exception): + mock_mqtt_client.loop_start.side_effect = arbitrary_exception + + with pytest.raises(errors.ProtocolClientError) as e_info: + transport.connect(fake_password) + + assert e_info.value.__cause__ is arbitrary_exception + assert mock_mqtt_client.disconnect.call_count == 1 + assert mock_mqtt_client.loop_stop.call_count == 2 + assert mock_mqtt_client.on_disconnect is not None + + @pytest.mark.it( + "Raises a ProtocolClientError and replaces a Paho client left unusable by a network-thread start failure" + ) + def test_loop_start_thread_failure_replaces_client(self, mocker): + transport = MQTTTransport( + client_id=fake_device_id, + hostname=fake_hostname, + username=fake_username, + keep_alive=fake_keepalive, + ) + failed_client = transport._mqtt_client + publish_callback = mocker.MagicMock() + transport.publish(fake_topic, fake_payload, qos=1, callback=publish_callback) + failed_client_socket, failed_server_socket = socket.socketpair() + mocker.patch.object(failed_client, "_create_socket", return_value=failed_client_socket) + start_error = RuntimeError("cannot start network thread") + mocker.patch.object(threading.Thread, "start", side_effect=start_error) + + try: + with pytest.raises(errors.ProtocolClientError) as e_info: + transport.connect(fake_password) + finally: + failed_server_socket.close() + + assert e_info.value.__cause__ is start_error + assert failed_client_socket.fileno() == -1 + assert transport._mqtt_client is not failed_client + assert transport._mqtt_client.on_connect is not None + assert transport._mqtt_client.on_disconnect is not None + assert publish_callback.call_count == 1 + assert publish_callback.call_args == mocker.call(cancelled=True) + assert transport._op_manager._pending_operation_callbacks == {} + assert transport._awaiting_connack is False + assert transport._connection_termination_reported is False + @pytest.mark.it("Raises a ProtocolClientError if Paho connect raises an unexpected Exception") def test_client_raises_unexpected_error( self, mocker, mock_mqtt_client, transport, arbitrary_exception @@ -662,6 +771,7 @@ def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, er mock_mqtt_client.connect.return_value = error_case["error_code"] with pytest.raises(error_case["error"]): transport.connect(fake_password) + assert mock_mqtt_client.disconnect.call_count == 1 @pytest.fixture( params=[ @@ -684,23 +794,13 @@ def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, er def connect_exception(self, request): return request.param - @pytest.mark.it("Calls _mqtt_client.disconnect if Paho raises an exception") - def test_calls_disconnect_on_exception( - self, mocker, mock_mqtt_client, transport, connect_exception - ): + @pytest.mark.it("Disconnects Paho and stops its network loop if connect raises an Exception") + def test_cleans_up_on_exception(self, mock_mqtt_client, transport, connect_exception): mock_mqtt_client.connect.side_effect = connect_exception with pytest.raises(Exception): transport.connect(fake_password) assert mock_mqtt_client.disconnect.call_count == 1 - - @pytest.mark.it("Calls _mqtt_client.loop_stop if Paho raises an exception") - def test_calls_loop_stop_on_exception( - self, mocker, mock_mqtt_client, transport, connect_exception - ): - mock_mqtt_client.connect.side_effect = connect_exception - with pytest.raises(Exception): - transport.connect(fake_password) - assert mock_mqtt_client.loop_stop.call_count == 1 + assert mock_mqtt_client.loop_stop.call_count == 2 @pytest.mark.describe("MQTTTransport - OCCURRENCE: Connect Completed") @@ -799,6 +899,43 @@ def test_calls_event_handler_callback_with_failed_reason_code( assert isinstance(callback.call_args[0][0], error_case["error"]) assert str(callback.call_args[0][0]) == str(error_case["reason_code"]) + @pytest.mark.it("Does not report a second disconnect after a failed CONNACK") + def test_suppresses_disconnect_after_connection_failure( + self, mocker, mock_mqtt_client, transport + ): + connection_failure_callback = mocker.MagicMock() + disconnected_callback = mocker.MagicMock() + transport.on_mqtt_connection_failure_handler = connection_failure_callback + transport.on_mqtt_disconnected_handler = disconnected_callback + transport.connect(fake_password) + + trigger_on_connect(mock_mqtt_client, reason_code=failed_connack_reason_code) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) + + assert connection_failure_callback.call_count == 1 + assert disconnected_callback.call_count == 0 + + @pytest.mark.it( + "Reports a failing disconnect before CONNACK acceptance as a ConnectionFailedError" + ) + def test_disconnect_before_connack_is_connection_failure( + self, mocker, mock_mqtt_client, transport + ): + connection_failure_callback = mocker.MagicMock() + disconnected_callback = mocker.MagicMock() + transport.on_mqtt_connection_failure_handler = connection_failure_callback + transport.on_mqtt_disconnected_handler = disconnected_callback + transport.connect(fake_password) + + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) + + assert connection_failure_callback.call_count == 1 + assert isinstance( + connection_failure_callback.call_args.args[0], errors.ConnectionFailedError + ) + assert disconnected_callback.call_count == 0 + assert transport._awaiting_connack is False + @pytest.mark.it( "Stops Paho's network loop if the MQTTTransport was garbage collected before a failed connect completed" ) @@ -898,7 +1035,9 @@ def test_no_connection_error_code(self, mock_mqtt_client, transport): transport.disconnect() - @pytest.mark.it("Cancels pending operations after an already-completed disconnect") + @pytest.mark.it( + "Completes tracked operations as cancelled after an already-completed disconnect" + ) def test_no_connection_error_code_clears_inflight(self, mocker, mock_mqtt_client, transport): callback = mocker.MagicMock() transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) @@ -909,8 +1048,10 @@ def test_no_connection_error_code_clears_inflight(self, mocker, mock_mqtt_client assert callback.call_count == 1 assert callback.call_args == mocker.call(cancelled=True) - @pytest.mark.it("Cancels all pending operations if the clear_inflight parameter is True") - def test_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): + @pytest.mark.it( + "Completes tracked operations as cancelled if the clear_inflight parameter is True" + ) + def test_clear_inflight_completes_tracked_operations(self, mocker, mock_mqtt_client, transport): # Set up a pending publish pub_callback = mocker.MagicMock(name="pub cb") pub_mid = "1" @@ -929,19 +1070,19 @@ def test_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): assert pub_callback.call_count == 0 assert sub_callback.call_count == 0 - # Disconnect and clear pending ops + # Disconnect and clear tracked operations transport.disconnect(clear_inflight=True) - # Pending operations were cancelled + # Tracked operations were completed as cancelled assert pub_callback.call_count == 1 assert pub_callback.call_args == mocker.call(cancelled=True) assert sub_callback.call_count == 1 assert sub_callback.call_args == mocker.call(cancelled=True) - @pytest.mark.it( - "Does not cancel any pending operations if the clear_inflight parameter is False" - ) - def test_no_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): + @pytest.mark.it("Does not complete tracked operations if the clear_inflight parameter is False") + def test_clear_inflight_false_preserves_tracked_operations( + self, mocker, mock_mqtt_client, transport + ): # Set up a pending publish pub_callback = mocker.MagicMock(name="pub cb") pub_mid = "1" @@ -963,14 +1104,14 @@ def test_no_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): # Disconnect transport.disconnect(clear_inflight=False) - # No pending operations were cancelled + # Tracked operations remain pending assert pub_callback.call_count == 0 assert sub_callback.call_count == 0 @pytest.mark.it( - "Does not cancel any pending operations if the clear_inflight parameter is not provided" + "Does not complete tracked operations if the clear_inflight parameter is not provided" ) - def test_default_no_pending_op_cancellation(self, mocker, mock_mqtt_client, transport): + def test_default_preserves_tracked_operations(self, mocker, mock_mqtt_client, transport): # Set up a pending publish pub_callback = mocker.MagicMock(name="pub cb") pub_mid = "1" @@ -992,7 +1133,7 @@ def test_default_no_pending_op_cancellation(self, mocker, mock_mqtt_client, tran # Disconnect transport.disconnect() - # No pending operations were cancelled + # Tracked operations remain pending assert pub_callback.call_count == 0 assert sub_callback.call_count == 0 @@ -1015,6 +1156,20 @@ def test_calls_loop_stop_on_exception( assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() + @pytest.mark.it("Clears CONNACK wait state if Paho loop_stop() raises an Exception") + def test_loop_stop_error_clears_connack_wait( + self, mock_mqtt_client, transport, arbitrary_exception + ): + transport._awaiting_connack = True + transport._connection_termination_reported = False + mock_mqtt_client.loop_stop.side_effect = arbitrary_exception + + with pytest.raises(type(arbitrary_exception)): + transport.disconnect() + + assert transport._awaiting_connack is False + assert transport._connection_termination_reported is False + @pytest.mark.describe("MQTTTransport - OCCURRENCE: Disconnect Completed") class TestEventDisconnectCompleted(object): @@ -1071,6 +1226,25 @@ def test_calls_event_handler_callback_with_failure( assert isinstance(callback.call_args[0][0], error_case["error"]) assert str(callback.call_args[0][0]) == str(error_case["reason_code"]) + @pytest.mark.it("Reports one disconnection when Paho invokes on_disconnect more than once") + def test_reports_one_disconnection_for_duplicate_paho_callbacks( + self, mocker, mock_mqtt_client, transport + ): + callback = mocker.MagicMock() + transport.on_mqtt_disconnected_handler = callback + + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) + + assert callback.call_count == 1 + assert transport._connection_termination_reported is True + + trigger_on_connect(mock_mqtt_client) + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) + + assert callback.call_count == 2 + assert transport._connection_termination_reported is True + @pytest.mark.it( "Skips on_mqtt_disconnected_handler event handler if set to 'None' upon disconnect completion" ) @@ -1111,91 +1285,23 @@ def test_event_handler_callback_raises_base_exception( trigger_on_disconnect(mock_mqtt_client) assert e_info.value is arbitrary_base_exception - @pytest.mark.it("Calls Paho's disconnect() method if cause is not None") - def test_calls_disconnect_with_cause(self, mock_mqtt_client, transport): - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert mock_mqtt_client.disconnect.call_count == 1 - @pytest.mark.it("Does not call Paho's disconnect() method if cause is None") def test_doesnt_call_disconnect_without_cause(self, mock_mqtt_client, transport): trigger_on_disconnect(mock_mqtt_client) assert mock_mqtt_client.disconnect.call_count == 0 - @pytest.mark.it("Calls Paho's loop_stop() if cause is not None") - def test_calls_loop_stop(self, mock_mqtt_client, transport): - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert mock_mqtt_client.loop_stop.call_count == 1 - - @pytest.mark.it("Does not calls Paho's loop_stop() if cause is None") + @pytest.mark.it("Does not call Paho's loop_stop() if cause is None") def test_does_not_call_loop_stop(self, mock_mqtt_client, transport): trigger_on_disconnect(mock_mqtt_client) assert mock_mqtt_client.loop_stop.call_count == 0 - @pytest.mark.it("Cleans up an unexpected disconnect from the Paho callback thread") - def test_cleanup_from_paho_callback_thread(self, mocker): - transport = MQTTTransport( - client_id=fake_device_id, hostname=fake_hostname, username=fake_username - ) - callback_finished = threading.Event() - callback_causes = [] - callback_errors = [] - transport.on_mqtt_disconnected_handler = callback_causes.append - - def run_callback_loop(retry_first_connection): - try: - trigger_on_disconnect( - transport._mqtt_client, reason_code=failed_disconnect_reason_code - ) - except BaseException as error: - callback_errors.append(error) - finally: - callback_finished.set() - - mocker.patch.object(transport._mqtt_client, "loop_forever", side_effect=run_callback_loop) - - assert transport._mqtt_client.loop_start() == mqtt.MQTT_ERR_SUCCESS - assert callback_finished.wait(timeout=5) - transport._mqtt_client.loop_stop() - - assert callback_errors == [] - assert len(callback_causes) == 1 - assert isinstance(callback_causes[0], errors.ConnectionDroppedError) - - @pytest.mark.it("Allows any Exception raised by Paho's disconnect() to propagate") - def test_disconnect_raises_exception( - self, mock_mqtt_client, transport, mocker, arbitrary_exception - ): - mock_mqtt_client.disconnect = mocker.MagicMock(side_effect=arbitrary_exception) - with pytest.raises(type(arbitrary_exception)) as e_info: - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert e_info.value is arbitrary_exception - - @pytest.mark.it("Allows any BaseException raised by Paho's disconnect() to propagate") - def test_disconnect_raises_base_exception( - self, mock_mqtt_client, transport, mocker, arbitrary_base_exception - ): - mock_mqtt_client.disconnect = mocker.MagicMock(side_effect=arbitrary_base_exception) - with pytest.raises(type(arbitrary_base_exception)) as e_info: - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert e_info.value is arbitrary_base_exception - - @pytest.mark.it("Allows any Exception raised by Paho's loop_stop() to propagate") - def test_loop_stop_raises_exception( - self, mock_mqtt_client, transport, mocker, arbitrary_exception - ): - mock_mqtt_client.loop_stop = mocker.MagicMock(side_effect=arbitrary_exception) - with pytest.raises(type(arbitrary_exception)) as e_info: - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert e_info.value is arbitrary_exception + @pytest.mark.it("Does not stop or reconnect Paho after an unexpected disconnection") + def test_does_not_stop_or_reconnect_paho_after_failure(self, mock_mqtt_client, transport): + trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - @pytest.mark.it("Allows any BaseException raised by Paho's loop_stop() to propagate") - def test_loop_stop_raises_base_exception( - self, mock_mqtt_client, transport, mocker, arbitrary_base_exception - ): - mock_mqtt_client.loop_stop = mocker.MagicMock(side_effect=arbitrary_base_exception) - with pytest.raises(type(arbitrary_base_exception)) as e_info: - trigger_on_disconnect(mock_mqtt_client, reason_code=failed_disconnect_reason_code) - assert e_info.value is arbitrary_base_exception + assert mock_mqtt_client.disconnect.call_count == 0 + assert mock_mqtt_client.loop_stop.call_count == 0 + assert mock_mqtt_client.reconnect.call_count == 0 @pytest.mark.it( "Does not raise any exceptions if the MQTTTransport object was garbage collected before the disconnect completed" @@ -1285,8 +1391,16 @@ def test_raises_value_error_invalid_topic(self, topic): transport.subscribe(topic, qos=fake_qos) @pytest.mark.it("Triggers callback upon subscribe completion") + @pytest.mark.parametrize( + "suback_return_code", + [ + pytest.param(0x00, id="Maximum QoS 0"), + pytest.param(0x01, id="Maximum QoS 1"), + pytest.param(0x02, id="Maximum QoS 2"), + ], + ) def test_triggers_callback_upon_paho_on_subscribe_event( - self, mocker, mock_mqtt_client, transport + self, mocker, mock_mqtt_client, transport, suback_return_code ): callback = mocker.MagicMock() mock_mqtt_client.subscribe.return_value = (fake_rc, fake_mid) @@ -1298,19 +1412,21 @@ def test_triggers_callback_upon_paho_on_subscribe_event( assert callback.call_count == 0 # Manually trigger Paho on_subscribe event handler - trigger_on_subscribe(mock_mqtt_client, mid=fake_mid) + granted_qos = mqtt.ReasonCode(PacketTypes.SUBACK, identifier=suback_return_code) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid, reason_codes=[granted_qos]) # Check callback has now been called assert callback.call_count == 1 assert callback.call_args == mocker.call() - @pytest.mark.it("Completes a rejected subscription with a ProtocolClientError") + @pytest.mark.it("Completes a subscription with ProtocolClientError if any reason fails") def test_failed_suback(self, mocker, mock_mqtt_client, transport): callback = mocker.MagicMock() transport.subscribe(topic=fake_topic, qos=fake_qos, callback=callback) + granted = mqtt.ReasonCode(PacketTypes.SUBACK, identifier=1) rejected = mqtt.ReasonCode(PacketTypes.SUBACK, identifier=128) - trigger_on_subscribe(mock_mqtt_client, mid=fake_mid, reason_codes=[rejected]) + trigger_on_subscribe(mock_mqtt_client, mid=fake_mid, reason_codes=[granted, rejected]) assert callback.call_count == 1 assert isinstance(callback.call_args.kwargs["error"], errors.ProtocolClientError) @@ -2106,18 +2222,49 @@ def test_client_raises_base_exception( transport.publish(topic=fake_topic, payload=fake_payload, callback=None) assert e_info.value is arbitrary_base_exception + @pytest.mark.it("Completes a QoS publish retained after Paho reports no connection") + @pytest.mark.parametrize("qos", [pytest.param(1, id="QoS 1"), pytest.param(2, id="QoS 2")]) + def test_no_connection_qos_publish_completes_later( + self, mocker, mock_mqtt_client, transport, qos + ): + callback = mocker.MagicMock() + message_info = mqtt.MQTTMessageInfo(fake_mid) + message_info.rc = mqtt.MQTT_ERR_NO_CONN + mock_mqtt_client.publish.return_value = message_info + + transport.publish(fake_topic, fake_payload, qos=qos, callback=callback) + + assert callback.call_count == 0 + trigger_on_publish(mock_mqtt_client, mid=fake_mid) + assert callback.call_count == 1 + assert callback.call_args == mocker.call() + + @pytest.mark.it("Raises NoConnectionError for a disconnected QoS 0 publish") + def test_no_connection_qos_zero(self, mock_mqtt_client, transport): + message_info = mqtt.MQTTMessageInfo(fake_mid) + message_info.rc = mqtt.MQTT_ERR_NO_CONN + mock_mqtt_client.publish.return_value = message_info + + with pytest.raises(errors.NoConnectionError): + transport.publish(fake_topic, fake_payload, qos=0) + # NOTE: this test tests all mapped Paho error codes, even ones that shouldn't be # possible on a publish operation. - @pytest.mark.it("Raises a custom Exception if Paho publish returns an error code") + @pytest.mark.it("Raises a custom Exception if MQTTMessageInfo contains a failure code") @pytest.mark.parametrize( "error_case", - paho_error_code_cases, + publish_failure_code_cases, ids=[ - "{}->{}".format(case["name"], case["error"].__name__) for case in paho_error_code_cases + "{}->{}".format(case["name"], case["error"].__name__) + for case in publish_failure_code_cases ], ) - def test_client_returns_error_code(self, mocker, mock_mqtt_client, transport, error_case): - mock_mqtt_client.publish.return_value = (error_case["error_code"], 0) + def test_message_info_contains_failure_code( + self, mocker, mock_mqtt_client, transport, error_case + ): + message_info = mqtt.MQTTMessageInfo(0) + message_info.rc = error_case["error_code"] + mock_mqtt_client.publish.return_value = message_info with pytest.raises(error_case["error"]): transport.publish(topic=fake_topic, payload=fake_payload, callback=None) @@ -2156,6 +2303,26 @@ def test_stops_loop_after_gc( assert mock_mqtt_client.loop_stop.call_count == 1 assert mock_mqtt_client.loop_stop.call_args == mocker.call() + @pytest.mark.it( + "Stops Paho's network loop and allows any Exception from disconnect after GC to propagate" + ) + def test_stops_loop_after_gc_if_disconnect_raises( + self, + mock_mqtt_client, + collected_transport_weakref, + message, + arbitrary_exception, + ): + mock_mqtt_client.disconnect.side_effect = arbitrary_exception + + with pytest.raises(type(arbitrary_exception)) as e_info: + mock_mqtt_client.on_message( + client=mock_mqtt_client, userdata=None, mqtt_message=message + ) + + assert e_info.value is arbitrary_exception + assert mock_mqtt_client.loop_stop.call_count == 1 + @pytest.mark.it( "Skips on_mqtt_message_received_handler event handler if set to 'None' upon receiving message" ) @@ -2251,11 +2418,11 @@ class TestOperationManager(object): def test_instantiates_empty(self): manager = OperationManager() assert len(manager._pending_operation_callbacks) == 0 - assert len(manager._early_operation_completions) == 0 + assert len(manager._unknown_operation_completions) == 0 -@pytest.mark.describe("OperationManager - .establish_operation()") -class TestOperationManagerEstablishOperation(object): +@pytest.mark.describe("OperationManager - .register_operation()") +class TestOperationManagerRegisterOperation(object): @pytest.fixture(params=[True, False]) def optional_callback(self, mocker, request): if request.param: @@ -2269,47 +2436,47 @@ def optional_callback(self, mocker, request): [pytest.param(True, id="With callback"), pytest.param(False, id="No callback")], indirect=True, ) - def test_no_early_completion(self, optional_callback): + def test_no_unknown_completion(self, optional_callback): manager = OperationManager() mid = 1 - manager.establish_operation(mid, optional_callback) + manager.register_operation(mid, optional_callback) assert len(manager._pending_operation_callbacks) == 1 assert manager._pending_operation_callbacks[mid] is optional_callback - @pytest.mark.it("Resolves operation tracking when the response arrived before establishment") + @pytest.mark.it("Resolves operation tracking when the response arrived before registration") def test_early_completion(self): manager = OperationManager() mid = 1 - # Record a completion before the operation is established + # Record a completion before the operation is registered manager.complete_operation(mid) - assert len(manager._early_operation_completions) == 1 - assert manager._early_operation_completions[mid] is None + assert len(manager._unknown_operation_completions) == 1 + assert manager._unknown_operation_completions[mid] is None - # Establish operation that was already completed - manager.establish_operation(mid) + # Register operation that was already completed + manager.register_operation(mid) - assert len(manager._early_operation_completions) == 0 + assert len(manager._unknown_operation_completions) == 0 @pytest.mark.it( - "Triggers the callback if provided when the response arrived before establishment" + "Invokes the callback if provided when the response arrived before registration" ) def test_early_completion_with_callback(self, mocker): manager = OperationManager() mid = 1 cb_mock = mocker.MagicMock() - # Record a completion before the operation is established + # Record a completion before the operation is registered manager.complete_operation(mid) - # Establish operation that was already completed - manager.establish_operation(mid, cb_mock) + # Register operation that was already completed + manager.register_operation(mid, cb_mock) assert cb_mock.call_count == 1 assert cb_mock.call_args == mocker.call() - @pytest.mark.it("Preserves an error when the completion arrives before establishment") + @pytest.mark.it("Preserves an error when the completion arrives before registration") def test_early_completion_with_error(self, mocker): manager = OperationManager() mid = 1 @@ -2317,7 +2484,7 @@ def test_early_completion_with_error(self, mocker): error = errors.ProtocolClientError("subscription rejected") manager.complete_operation(mid, error=error) - manager.establish_operation(mid, callback) + manager.register_operation(mid, callback) assert callback.call_count == 1 assert callback.call_args == mocker.call(error=error) @@ -2328,11 +2495,11 @@ def test_callback_raises_exception(self, mocker, arbitrary_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_exception) - # Record a completion before the operation is established + # Record a completion before the operation is registered manager.complete_operation(mid) - # Establish operation that was already completed - manager.establish_operation(mid, cb_mock) + # Register operation that was already completed + manager.register_operation(mid, cb_mock) # Callback was called, but exception did not propagate assert cb_mock.call_count == 1 @@ -2343,21 +2510,21 @@ def test_callback_raises_base_exception(self, mocker, arbitrary_base_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_base_exception) - # Record a completion before the operation is established + # Record a completion before the operation is registered manager.complete_operation(mid) - # Establish operation that was already completed + # Register operation that was already completed with pytest.raises(arbitrary_base_exception.__class__) as e_info: - manager.establish_operation(mid, cb_mock) + manager.register_operation(mid, cb_mock) assert e_info.value is arbitrary_base_exception - @pytest.mark.it("Does not trigger the callback until after thread lock has been released") + @pytest.mark.it("Does not invoke the callback until after thread lock has been released") def test_callback_called_after_lock_release(self, mocker): manager = OperationManager() mid = 1 cb_mock = mocker.MagicMock() - # Record a completion before the operation is established + # Record a completion before the operation is registered manager.complete_operation(mid) # Set up mock tracking @@ -2379,8 +2546,8 @@ def stop_tracking_mocks(*args): lock_spy.__enter__.side_effect = track_mocks lock_spy.__exit__.side_effect = stop_tracking_mocks - # Establish operation that was already completed - manager.establish_operation(mid, cb_mock) + # Register operation that was already completed + manager.register_operation(mid, cb_mock) # Callback WAS called, but... assert cb_mock.call_count == 1 @@ -2396,35 +2563,35 @@ def test_complete_pending_operation(self): manager = OperationManager() mid = 1 - # Establish a pending operation - manager.establish_operation(mid) + # Register a pending operation + manager.register_operation(mid) assert len(manager._pending_operation_callbacks) == 1 # Complete pending operation manager.complete_operation(mid) assert len(manager._pending_operation_callbacks) == 0 - @pytest.mark.it("Triggers callback for a pending operation when resolving") + @pytest.mark.it("Invokes callback for a pending operation when resolving") def test_complete_pending_operation_callback(self, mocker): manager = OperationManager() mid = 1 cb_mock = mocker.MagicMock() - manager.establish_operation(mid, cb_mock) + manager.register_operation(mid, cb_mock) assert cb_mock.call_count == 0 manager.complete_operation(mid) assert cb_mock.call_count == 1 assert cb_mock.call_args == mocker.call() - @pytest.mark.it("Triggers callback with an error for a failed pending operation") + @pytest.mark.it("Invokes callback with an error for a failed pending operation") def test_complete_pending_operation_callback_with_error(self, mocker): manager = OperationManager() mid = 1 callback = mocker.MagicMock() error = errors.ProtocolClientError("subscription rejected") - manager.establish_operation(mid, callback) + manager.register_operation(mid, callback) manager.complete_operation(mid, error=error) assert callback.call_count == 1 @@ -2436,7 +2603,7 @@ def test_callback_raises_exception(self, mocker, arbitrary_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_exception) - manager.establish_operation(mid, cb_mock) + manager.register_operation(mid, cb_mock) assert cb_mock.call_count == 0 manager.complete_operation(mid) @@ -2449,30 +2616,30 @@ def test_callback_raises_base_exception(self, mocker, arbitrary_base_exception): mid = 1 cb_mock = mocker.MagicMock(side_effect=arbitrary_base_exception) - manager.establish_operation(mid, cb_mock) + manager.register_operation(mid, cb_mock) assert cb_mock.call_count == 0 with pytest.raises(arbitrary_base_exception.__class__) as e_info: manager.complete_operation(mid) assert e_info.value is arbitrary_base_exception - @pytest.mark.it("Retains an early completion if MID does not correspond to a pending operation") - def test_early_completion(self): + @pytest.mark.it("Retains a completion if MID does not correspond to a pending operation") + def test_unknown_completion(self): manager = OperationManager() mid = 1 manager.complete_operation(mid) - assert len(manager._early_operation_completions) == 1 - assert manager._early_operation_completions[mid] is None + assert len(manager._unknown_operation_completions) == 1 + assert manager._unknown_operation_completions[mid] is None - @pytest.mark.it("Does not trigger the callback until after thread lock has been released") + @pytest.mark.it("Does not invoke the callback until after thread lock has been released") def test_callback_called_after_lock_release(self, mocker): manager = OperationManager() mid = 1 cb_mock = mocker.MagicMock() # Set up an operation and save the callback - manager.establish_operation(mid, cb_mock) + manager.register_operation(mid, cb_mock) # Set up mock tracking lock_spy = mocker.spy(manager, "_lock") @@ -2504,51 +2671,51 @@ def stop_tracking_mocks(*args): assert mocker.call.cb() not in calls_during_lock -@pytest.mark.describe("OperationManager - .cancel_all_operations()") -class TestOperationManagerCancelAllOperations(object): +@pytest.mark.describe("OperationManager - .complete_all_tracked_operations_as_cancelled()") +class TestOperationManagerCompleteAllTrackedOperationsAsCancelled(object): @pytest.mark.it("Removes all MID tracking for all pending operations") def test_remove_pending_ops(self): manager = OperationManager() - # Establish pending operations - manager.establish_operation(mid=1) - manager.establish_operation(mid=2) - manager.establish_operation(mid=3) + # Register pending operations + manager.register_operation(mid=1) + manager.register_operation(mid=2) + manager.register_operation(mid=3) assert len(manager._pending_operation_callbacks) == 3 - # Cancel operations - manager.cancel_all_operations() + # Complete tracked operations as cancelled + manager.complete_all_tracked_operations_as_cancelled() assert len(manager._pending_operation_callbacks) == 0 - @pytest.mark.it("Removes all MID tracking for early operation completions") - def test_remove_early_completions(self): + @pytest.mark.it("Removes all MID tracking for unknown operation completions") + def test_remove_unknown_completions(self): manager = OperationManager() - # Add early operation completions + # Add unknown operation completions manager.complete_operation(mid=2111) manager.complete_operation(mid=30045) manager.complete_operation(mid=2345) - assert len(manager._early_operation_completions) == 3 + assert len(manager._unknown_operation_completions) == 3 - # Cancel operations - manager.cancel_all_operations() - assert len(manager._early_operation_completions) == 0 + # Complete tracked operations as cancelled + manager.complete_all_tracked_operations_as_cancelled() + assert len(manager._unknown_operation_completions) == 0 - @pytest.mark.it("Triggers callbacks (if present) with cancel flag for each pending operation") + @pytest.mark.it("Invokes callbacks with cancelled=True for each tracked operation") def test_op_callback_completion(self, mocker): manager = OperationManager() - # Establish pending operations + # Register pending operations cb_mock1 = mocker.MagicMock() - manager.establish_operation(mid=1, callback=cb_mock1) + manager.register_operation(mid=1, callback=cb_mock1) cb_mock2 = mocker.MagicMock() - manager.establish_operation(mid=2, callback=cb_mock2) - manager.establish_operation(mid=3, callback=None) + manager.register_operation(mid=2, callback=cb_mock2) + manager.register_operation(mid=3, callback=None) assert cb_mock1.call_count == 0 assert cb_mock2.call_count == 0 - # Cancel operations - manager.cancel_all_operations() + # Complete tracked operations as cancelled + manager.complete_all_tracked_operations_as_cancelled() assert cb_mock1.call_count == 1 assert cb_mock1.call_args == mocker.call(cancelled=True) assert cb_mock2.call_count == 1 @@ -2558,13 +2725,13 @@ def test_op_callback_completion(self, mocker): def test_callback_raises_exception(self, mocker, arbitrary_exception): manager = OperationManager() - # Establish pending operation + # Register pending operation cb_mock = mocker.MagicMock(side_effect=arbitrary_exception) - manager.establish_operation(mid=1, callback=cb_mock) + manager.register_operation(mid=1, callback=cb_mock) assert cb_mock.call_count == 0 - # Cancel operations - manager.cancel_all_operations() + # Complete tracked operations as cancelled + manager.complete_all_tracked_operations_as_cancelled() # Callback was called but exception did not propagate assert cb_mock.call_count == 1 @@ -2573,25 +2740,25 @@ def test_callback_raises_exception(self, mocker, arbitrary_exception): def test_callback_raises_base_exception(self, mocker, arbitrary_base_exception): manager = OperationManager() - # Establish pending operation + # Register pending operation cb_mock = mocker.MagicMock(side_effect=arbitrary_base_exception) - manager.establish_operation(mid=1, callback=cb_mock) + manager.register_operation(mid=1, callback=cb_mock) assert cb_mock.call_count == 0 - # When cancelling operations, Base Exception propagates + # When completing operations, Base Exception propagates with pytest.raises(arbitrary_base_exception.__class__) as e_info: - manager.cancel_all_operations() + manager.complete_all_tracked_operations_as_cancelled() assert e_info.value is arbitrary_base_exception - @pytest.mark.it("Does not trigger callbacks until after thread lock has been released") + @pytest.mark.it("Does not invoke callbacks until after thread lock has been released") def test_callback_called_after_lock_release(self, mocker): manager = OperationManager() cb_mock1 = mocker.MagicMock() cb_mock2 = mocker.MagicMock() # Set up operations and save the callback - manager.establish_operation(mid=1, callback=cb_mock1) - manager.establish_operation(mid=2, callback=cb_mock2) + manager.register_operation(mid=1, callback=cb_mock1) + manager.register_operation(mid=2, callback=cb_mock2) # Set up mock tracking lock_spy = mocker.spy(manager, "_lock") @@ -2613,8 +2780,8 @@ def stop_tracking_mocks(*args): lock_spy.__enter__.side_effect = track_mocks lock_spy.__exit__.side_effect = stop_tracking_mocks - # Cancel operations - manager.cancel_all_operations() + # Complete tracked operations as cancelled + manager.complete_all_tracked_operations_as_cancelled() # Callbacks WERE called, but... assert cb_mock1.call_count == 1 From ee3e217b5b26c873a8298a31b26e6b5959fcaa2b Mon Sep 17 00:00:00 2001 From: Carter Tinney Date: Thu, 3 Sep 2026 15:55:38 -0700 Subject: [PATCH 3/4] e2e: complete IoT Hub leak check coverage --- tests/e2e/iothub_e2e/aio/test_infrastructure.py | 2 +- tests/e2e/iothub_e2e/sync/test_sync_infrastructure.py | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/e2e/iothub_e2e/aio/test_infrastructure.py b/tests/e2e/iothub_e2e/aio/test_infrastructure.py index 1587d5c71..691a6f2d4 100644 --- a/tests/e2e/iothub_e2e/aio/test_infrastructure.py +++ b/tests/e2e/iothub_e2e/aio/test_infrastructure.py @@ -9,7 +9,7 @@ class TestServiceHelper(object): @pytest.mark.it("returns None when wait_for_event_arrival times out") async def test_validate_wait_for_eventhub_arrival_timeout( - self, client, random_message, service_helper + self, client, random_message, service_helper, leak_tracker ): # Because we have to support py27, we can't use `threading.Condition.wait_for`. # make sure our stand-in functionality behaves the same way when dealing with diff --git a/tests/e2e/iothub_e2e/sync/test_sync_infrastructure.py b/tests/e2e/iothub_e2e/sync/test_sync_infrastructure.py index 0919ad392..e3df018d9 100644 --- a/tests/e2e/iothub_e2e/sync/test_sync_infrastructure.py +++ b/tests/e2e/iothub_e2e/sync/test_sync_infrastructure.py @@ -8,7 +8,9 @@ @pytest.mark.describe("ServiceHelper object") class TestServiceHelper(object): @pytest.mark.it("returns None when wait_for_event_arrival times out") - def test_sync_wait_for_event_arrival(self, client, random_message, service_helper): + def test_sync_wait_for_event_arrival( + self, client, random_message, service_helper, leak_tracker + ): event = service_helper.wait_for_eventhub_arrival(uuid.uuid4(), timeout=2) assert event is None From f4b47928e6182358f2a3d1d383322b7bac680d35 Mon Sep 17 00:00:00 2001 From: Carter Tinney Date: Thu, 3 Sep 2026 16:17:40 -0700 Subject: [PATCH 4/4] fix: discard late MQTT operation completions --- .../azure/iot/device/common/mqtt_transport.py | 22 ++++++++--- tests/unit/common/test_mqtt_transport.py | 39 ++++++++++++++++++- 2 files changed, 53 insertions(+), 8 deletions(-) diff --git a/azure-iot-device/azure/iot/device/common/mqtt_transport.py b/azure-iot-device/azure/iot/device/common/mqtt_transport.py index a899d9ce1..6bd9bd9ff 100644 --- a/azure-iot-device/azure/iot/device/common/mqtt_transport.py +++ b/azure-iot-device/azure/iot/device/common/mqtt_transport.py @@ -736,9 +736,7 @@ def publish(self, topic, payload, qos=1, callback=None): class OperationManager(object): - """Tracks callbacks by Paho MID, including completions received for unknown MIDs - (For instance, responses received before a registration). - """ + """Tracks operation callbacks, unmatched completions, and cancellations by Paho MID.""" def __init__(self): # Maps Paho MID to callback for operations awaiting a response. @@ -749,6 +747,9 @@ def __init__(self): # Paho call returns. self._unknown_operation_completions = {} + # Tracks cancelled MIDs whose Paho operations may still complete. + self._cancelled_operation_mids = set() + self._lock = threading.Lock() def register_operation(self, mid, callback=None): @@ -762,6 +763,10 @@ def register_operation(self, mid, callback=None): completion_error = None with self._lock: + # If Paho reuses a cancelled MID without completing its previous operation, its next + # completion belongs to the newly registered operation. + self._cancelled_operation_mids.discard(mid) + # Paho can invoke the response callback before its API call returns the MID, # thus, the operation might have already completed. if mid in self._unknown_operation_completions: @@ -807,8 +812,12 @@ def complete_operation(self, mid, error=None): invoke_callback = False with self._lock: + if mid in self._cancelled_operation_mids: + logger.debug("Discarding completion for cancelled Paho MID {}".format(mid)) + self._cancelled_operation_mids.remove(mid) + # If the Paho MID has a pending operation, invoke its callback. - if mid in self._pending_operation_callbacks: + elif mid in self._pending_operation_callbacks: # Retrieve the callback, and clear the pending operation now that it has been completed callback = self._pending_operation_callbacks[mid] @@ -844,13 +853,14 @@ def complete_all_tracked_operations_as_cancelled(self): """Complete all tracked SDK operations as cancelled and clear unknown completions. This manager owns only local completion tracking: pending callbacks are invoked with - ``cancelled=True`` and their MIDs are forgotten. Operations already accepted by Paho are - unaffected and may still complete or take effect. + ``cancelled=True``. Their MIDs remain as tombstones so later Paho completions can be + discarded. Operations already accepted by Paho are unaffected and may still take effect. """ logger.debug("Completing all tracked operations as cancelled") with self._lock: # Preserve callbacks for invocation after releasing the lock. pending_ops = list(self._pending_operation_callbacks.items()) + self._cancelled_operation_mids.update(self._pending_operation_callbacks) self._pending_operation_callbacks.clear() self._unknown_operation_completions.clear() diff --git a/tests/unit/common/test_mqtt_transport.py b/tests/unit/common/test_mqtt_transport.py index b846f8c1a..f61a5f35a 100644 --- a/tests/unit/common/test_mqtt_transport.py +++ b/tests/unit/common/test_mqtt_transport.py @@ -2419,6 +2419,7 @@ def test_instantiates_empty(self): manager = OperationManager() assert len(manager._pending_operation_callbacks) == 0 assert len(manager._unknown_operation_completions) == 0 + assert len(manager._cancelled_operation_mids) == 0 @pytest.mark.describe("OperationManager - .register_operation()") @@ -2444,6 +2445,21 @@ def test_no_unknown_completion(self, optional_callback): assert len(manager._pending_operation_callbacks) == 1 assert manager._pending_operation_callbacks[mid] is optional_callback + @pytest.mark.it("Allows a cancelled MID without a late completion to be reused") + def test_cancelled_mid_reused_without_late_completion(self, mocker): + manager = OperationManager() + mid = 1 + reused_mid_callback = mocker.MagicMock() + + manager.register_operation(mid) + manager.complete_all_tracked_operations_as_cancelled() + manager.register_operation(mid, callback=reused_mid_callback) + + assert reused_mid_callback.call_count == 0 + + manager.complete_operation(mid) + assert reused_mid_callback.call_args == mocker.call() + @pytest.mark.it("Resolves operation tracking when the response arrived before registration") def test_early_completion(self): manager = OperationManager() @@ -2632,6 +2648,24 @@ def test_unknown_completion(self): assert len(manager._unknown_operation_completions) == 1 assert manager._unknown_operation_completions[mid] is None + @pytest.mark.it("Discards a late completion for a cancelled MID") + def test_late_completion_for_cancelled_mid(self, mocker): + manager = OperationManager() + mid = 1 + cancelled_callback = mocker.MagicMock() + reused_mid_callback = mocker.MagicMock() + + manager.register_operation(mid, callback=cancelled_callback) + manager.complete_all_tracked_operations_as_cancelled() + manager.complete_operation(mid) + manager.register_operation(mid, callback=reused_mid_callback) + + assert cancelled_callback.call_args == mocker.call(cancelled=True) + assert reused_mid_callback.call_count == 0 + + manager.complete_operation(mid) + assert reused_mid_callback.call_args == mocker.call() + @pytest.mark.it("Does not invoke the callback until after thread lock has been released") def test_callback_called_after_lock_release(self, mocker): manager = OperationManager() @@ -2673,8 +2707,8 @@ def stop_tracking_mocks(*args): @pytest.mark.describe("OperationManager - .complete_all_tracked_operations_as_cancelled()") class TestOperationManagerCompleteAllTrackedOperationsAsCancelled(object): - @pytest.mark.it("Removes all MID tracking for all pending operations") - def test_remove_pending_ops(self): + @pytest.mark.it("Removes pending callbacks and retains their MIDs as cancelled") + def test_cancel_pending_ops(self): manager = OperationManager() # Register pending operations @@ -2686,6 +2720,7 @@ def test_remove_pending_ops(self): # Complete tracked operations as cancelled manager.complete_all_tracked_operations_as_cancelled() assert len(manager._pending_operation_callbacks) == 0 + assert manager._cancelled_operation_mids == {1, 2, 3} @pytest.mark.it("Removes all MID tracking for unknown operation completions") def test_remove_unknown_completions(self):