def _on_mqtt_disconnected(self, cause=None):
"""
Handler that gets called by the transport when the transport disconnects.
:param Exception cause: The Exception that caused the disconnection, if any (optional)
"""
if cause:
logger.error("{}: _on_mqtt_disconnect called: {}".format(self.name, cause))
else:
logger.info("{}: _on_mqtt_disconnect called".format(self.name))
# self.on_disconnected() tells other pipeilne stages that we're disconnected. Do this before
# we do anything else (in case upper stages have any "are we connected" logic.
self.on_disconnected()
if isinstance(self._pending_connection_op, pipeline_ops_base.DisconnectOperation):
logger.debug("{}: completing disconnect op".format(self.name))
op = self._pending_connection_op
self._pending_connection_op = None
# Swallow any errors, because we intended to disconnect - even if something went wrong, we
# got to the state we wanted to be in!
if cause:
handle_exceptions.swallow_unraised_exception(
cause,
log_msg="Unexpected disconnect with error while disconnecting - swallowing error",
)
self._complete_op(op)
else:
logger.warning("{}: disconnection was unexpected".format(self.name))
# Regardless of cause, it is now a ConnectionDroppedError
e = transport_exceptions.ConnectionDroppedError(cause=cause)
handle_exceptions.handle_background_exception(e)
def complete_op(stage, op):
"""
Helper function to complete an operation by calling its callback function thus
returning the result of the operation back up the pipeline. This is perferred to
calling the operation's callback directly as it provides several layers of protection
(such as a try/except wrapper) which are strongly advised.
"""
if op.error:
logger.error("{}({}): completing with error {}".format(
stage.name, op.name, op.error))
else:
logger.debug("{}({}): completing without error".format(
stage.name, op.name))
try:
op.callback(op)
except Exception as e:
_, e, _ = sys.exc_info()
logger.error(
msg=
"Unhandled error calling back inside {}.complete_op() after {} complete"
.format(stage.name, op.name),
exc_info=e,
)
handle_exceptions.handle_background_exception(e)
def _handler_callback(future):
try:
e = future.exception(timeout=0)
except Exception as raised_e:
# This shouldn't happen because cancellation or timeout shouldn't occur...
# But just in case...
new_err = HandlerManagerException(
message=
"HANDLER ({}): Unable to retrieve exception data from incomplete invocation"
.format(handler_name),
cause=raised_e,
)
handle_exceptions.handle_background_exception(new_err)
else:
if e:
new_err = HandlerManagerException(
message="HANDLER ({}): Error during invocation".format(
handler_name),
cause=e,
)
handle_exceptions.handle_background_exception(new_err)
else:
logger.debug(
"HANDLER ({}): Successfully completed invocation".
format(handler_name))
def halt_completion(self):
"""Halt the completion of an operation that is currently undergoing a completion process
as a result of a call to .complete().
Completion cannot be halted if there is no currently ongoing completion process. The only
way to successfully invoke this method is from within a callback on the Operation in
question.
This method will leave any yet-untriggered callbacks on the Operation to be triggered upon
a later completion.
This method will clear any error associated with the currently ongoing completion process
from the Operation.
"""
if not self.completing:
logger.error("{}: is not currently in the process of completion!".format(self.name))
e = pipeline_exceptions.OperationError(
"Attempting to halt completion of an operation not in the process of completion: {}".format(
self.name
)
)
handle_exceptions.handle_background_exception(e)
else:
logger.debug("{}: Halting completion...".format(self.name))
self.completing = False
self.error = None
def _handler_runner_callback(completed_future):
try:
e = completed_future.exception(timeout=0)
except Exception as raised_e:
# This shouldn't happen because cancellation or timeout shouldn't occur...
# But just in case...
new_err = HandlerManagerException(
message="HANDLER RUNNER ({}): Unable to retrieve exception data from incomplete task".format(
handler_name
),
cause=raised_e,
)
handle_exceptions.handle_background_exception(new_err)
else:
if e:
# If this branch is reached something has gone SERIOUSLY wrong.
# We must log the error, and then restart the runner so that the program
# does not enter an invalid state
new_err = HandlerManagerException(
message="HANDLER RUNNER ({}): Unexpected error during task".format(
handler_name
),
cause=e,
)
handle_exceptions.handle_background_exception(new_err)
# Clear the tracked runner, and start a new one
self._handler_runners[handler_name] = None
self._start_handler_runner(handler_name)
else:
logger.debug(
"HANDLER RUNNER ({}): Task successfully completed without exception".format(
handler_name
)
)
def _complete_op(self, op, error=None):
"""
Helper function to complete an operation by calling its callback function thus
returning the result of the operation back up the pipeline. This is perferred to
calling the operation's callback directly as it provides several layers of protection
(such as a try/except wrapper) which are strongly advised.
"""
if error:
logger.error("{}({}): completing with error {}".format(
self.name, op.name, error))
else:
logger.debug("{}({}): completing without error".format(
self.name, op.name))
if op.completed:
logger.error(
"{}({}): completing op that has already been completed!".
format(self.name, op.name))
e = PipelineError(
"Internal pipeline error: attempting to complete an already-completed operation: {}({})"
.format(self.name, op.name))
handle_exceptions.handle_background_exception(e)
else:
op.completed = True
self._send_completed_op_up(op, error)
def _on_background_exception(self, e):
"""Helper handler that is called upon an iothub pipeline background exception"""
handle_exceptions.handle_background_exception(e)
client_event_inbox = self._inbox_manager.get_client_event_inbox()
# Only add a ClientEvent to the inbox if the Handler Manager is capable of dealing with it
if self._handler_manager.handling_client_events:
event = client_event.ClientEvent(client_event.BACKGROUND_EXCEPTION,
e)
client_event_inbox.put(event)
def on_token_update_complete(op, error):
if error:
logger.error(
"{}({}): token update operation failed. Error={}".format(
self.name, op.name, error))
handle_exceptions.handle_background_exception(error)
else:
logger.debug(
"{}({}): token update operation is complete".format(
self.name, op.name))
def send_event_up(self, event):
"""
Helper function to pass an event to the previous stage of the pipeline. This is the default
behavior of events while traveling through the pipeline. They start somewhere (maybe the
bottom) and move up the pipeline until they're handled or until they error out.
"""
if self.previous:
self.previous.handle_pipeline_event(event)
else:
logger.error("{}({}): Error: unhandled event".format(self.name, event.name))
error = pipeline_exceptions.PipelineError(
"{} unhandled at {} stage with no previous stage".format(event.name, self.name)
)
handle_exceptions.handle_background_exception(error)
def on_reauthorize_complete(op, error):
this = self_weakref()
if error:
logger.error(
"{}({}): reauthorize connection operation failed. Error={}".format(
this.name, op.name, error
)
)
handle_exceptions.handle_background_exception(error)
else:
logger.debug(
"{}({}): reauthorize connection operation is complete".format(
this.name, op.name
)
)
def _on_mqtt_disconnected(self, cause=None):
"""
Handler that gets called by the transport when the transport disconnects.
:param Exception cause: The Exception that caused the disconnection, if any (optional)
"""
if cause:
logger.error("{}: _on_mqtt_disconnect called: {}".format(
self.name, cause))
else:
logger.info("{}: _on_mqtt_disconnect called".format(self.name))
# Send an event to tell other pipeilne stages that we're disconnected. Do this before
# we do anything else (in case upper stages have any "are we connected" logic.
self.send_event_up(pipeline_events_base.DisconnectedEvent())
if self._pending_connection_op:
# on_mqtt_disconnected will cause any pending connect op to complete. This is how Paho
# behaves when there is a connection error, and it also makes sense that on_mqtt_disconnected
# would cause a pending connection op to fail.
logger.debug("{}: completing pending {} op".format(
self.name, self._pending_connection_op.name))
op = self._pending_connection_op
self._pending_connection_op = None
if isinstance(op, pipeline_ops_base.DisconnectOperation):
# Swallow any errors if we intended to disconnect - even if something went wrong, we
# got to the state we wanted to be in!
if cause:
handle_exceptions.swallow_unraised_exception(
cause,
log_msg=
"Unexpected disconnect with error while disconnecting - swallowing error",
)
op.complete()
else:
if cause:
op.complete(error=cause)
else:
op.complete(
error=transport_exceptions.ConnectionDroppedError(
"transport disconnected"))
else:
logger.warning("{}: disconnection was unexpected".format(
self.name))
# Regardless of cause, it is now a ConnectionDroppedError
e = transport_exceptions.ConnectionDroppedError(cause=cause)
handle_exceptions.handle_background_exception(e)
def handle_pipeline_event(self, event):
"""
Handle a pipeline event that arrives from the stage below this stage. Derived
classes should not override this function. Any stage-specific handling of
PipelineEvent objects should be implemented by overriding the private
_handle_pipeline_event function in the derived stage.
:param PipelineEvent event: The event that is being passed back up the pipeline
"""
try:
self._handle_pipeline_event(event)
except Exception as e:
logger.error(
msg="Unexpected error in {}._handle_pipeline_event() call".format(self), exc_info=e
)
handle_exceptions.handle_background_exception(e)
def handle_pipeline_event(self, event):
"""
Handle a pipeline event that arrives from the stage below this stage. Derived
classes should not override this function. Any stage-specific handling of
PipelineEvent objects should be implemented by overriding the private
_handle_pipeline_event function in the derived stage.
:param PipelineEvent event: The event that is being passed back up the pipeline
"""
try:
self._handle_pipeline_event(event)
except Exception as e:
# Do not use exc_info parameter on logger.error. This casuses pytest to save the traceback which saves stack frames which shows up as a leak
logger.error(msg="Unexpected error in {}._handle_pipeline_event() call".format(self))
logger.error(traceback.format_exc())
handle_exceptions.handle_background_exception(e)
def pass_event_to_previous_stage(stage, event):
"""
Helper function to pass an event to the previous stage of the pipeline. This is the default
behavior of events while traveling through the pipeline. They start somewhere (maybe the
bottom) and move up the pipeline until they're handled or until they error out.
"""
if stage.previous:
logger.debug("{}({}): pushing event up to {}".format(
stage.name, event.name, stage.previous.name))
stage.previous.handle_pipeline_event(event)
else:
logger.error("{}({}): Error: unhandled event".format(
stage.name, event.name))
error = NotImplementedError(
"{} unhandled at {} stage with no previous stage".format(
event.name, stage.name))
handle_exceptions.handle_background_exception(error)
def thread_proc():
threading.current_thread().name = thread_name
try:
return func(*args, **kwargs)
except Exception as e:
if not block:
handle_exceptions.handle_background_exception(e)
else:
raise
except BaseException:
if not block:
logger.error(
"Unhandled exception in background thread")
logger.error(
"This may cause the background thread to abort and may result in system instability."
)
traceback.print_exc()
raise
def _on_mqtt_connection_failure(self, cause):
"""
Handler that gets called by the transport when a connection fails.
:param Exception cause: The Exception that caused the connection failure.
"""
logger.error("{}: _on_mqtt_connection_failure called: {}".format(self.name, cause))
if isinstance(
self._pending_connection_op, pipeline_ops_base.ConnectOperation
) or isinstance(self._pending_connection_op, pipeline_ops_base.ReconnectOperation):
logger.debug("{}: failing connect op".format(self.name))
op = self._pending_connection_op
self._pending_connection_op = None
self._complete_op(op, error=cause)
else:
logger.warning("{}: Connection failure was unexpected".format(self.name))
handle_exceptions.handle_background_exception(cause)
def _send_completed_op_up(self, op, error=None):
"""
Sends a previously-completed operation back up the pipeline, usually to the callback.
This is used by _complete_op and it's also called from code in the stage itself inside
an intercepted return (via _send_op_down_and_intercept_return).
"""
if not op.completed:
raise PipelineError(
"Internal pipeline error: attempting to send an incomplete {} op up"
.format(op.name))
try:
op.callback(op, error=error)
except Exception as e:
_, e, _ = sys.exc_info()
logger.error(
msg=
"Unhandled error calling back inside {}._complete_op() after {} complete"
.format(self.name, op.name),
exc_info=e,
)
handle_exceptions.handle_background_exception(e)
def thread_proc():
threading.current_thread().name = thread_name
try:
return func(*args, **kwargs)
except Exception as e:
if not block:
handle_exceptions.handle_background_exception(e)
else:
raise
except BaseException:
if not block:
# This is truly a logger.critical condition. Most exceptions in background threads should
# be handled inside the thread and should result in call to handle_background_exception
# if this code is hit, that means something happened which wasn't handled, therefore
# handle_background_exception wasn't called, therefore we need to log this at the highest
# level.
logger.critical(
"Unhandled exception in background thread")
logger.critical(
"This may cause the background thread to abort and may result in system instability."
)
traceback.print_exc()
raise
def complete(self, error=None):
""" Complete the operation, and trigger all callbacks in LIFO order.
The operation is completed successfully be default, or completed unsucessfully if an error
is provided.
An operation that is already fully completed, or in the process of completion cannot be
completed again.
This process can be halted if a callback for the operation invokes the .halt_completion()
method on this Operation.
:param error: Optionally provide an Exception object indicating the error that caused
the completion. Providing an error indicates that the operation was unsucessful.
"""
if error:
logger.error("{}: completing with error {}".format(self.name, error))
else:
logger.debug("{}: completing without error".format(self.name))
if self.completed or self.completing:
logger.error("{}: has already been completed!".format(self.name))
e = pipeline_exceptions.OperationError(
"Attempting to complete an already-completed operation: {}".format(self.name)
)
# This could happen in a foreground or background thread, so err on the side of caution
# and send it to the background handler.
handle_exceptions.handle_background_exception(e)
else:
# Operation is now in the process of completing
self.completing = True
self.error = error
while self.callback_stack:
if not self.completing:
logger.debug("{}: Completion halted!".format(self.name))
break
if self.completed:
# This block should never be reached - this is an invalid state.
# If this block is reached, there is a bug in the code.
logger.error(
"{}: Invalid State! Operation completed while resolving completion".format(
self.name
)
)
e = pipeline_exceptions.OperationError(
"Operation reached fully completed state while still resolving completion: {}".format(
self.name
)
)
handle_exceptions.handle_background_exception(e)
break
callback = self.callback_stack.pop()
try:
callback(op=self, error=error)
except Exception as e:
logger.error(
"Unhandled error while triggering callback for {}".format(self.name)
)
logger.error(traceback.format_exc())
# This could happen in a foreground or background thread, so err on the side of caution
# and send it to the background handler.
handle_exceptions.handle_background_exception(e)
if self.completing:
# Operation is now completed, no longer in the process of completing
self.completing = False
self.completed = True
def _start_renewal_timer(self):
"""Begin a renewal timer.
When the timer expires, and the token is renewed, a new timer will be set"""
self._cancel_token_renewal_timer()
# NOTE: The assumption here is that the SasToken has just been refreshed, so there is
# approximately 'TTL' seconds until expiration. In practice this could probably be off
# a few seconds given processing time. We could make this more accurate if SasToken
# objects had a live TTL value rather than a static one (i.e. "there are n seconds
# remaining in the lifespan of this token", rather than "this token was intended to live
# for n seconds")
seconds_until_renewal = (
self.pipeline_root.pipeline_configuration.sastoken.ttl
- self.DEFAULT_TOKEN_RENEWAL_MARGIN
)
if seconds_until_renewal < 0:
# This shouldn't happen in correct flow, but it's possible I suppose, if something goes
# horribly awry elsewhere in the stack, or if we start allowing for custom
# SasToken TTLs or custom Renewal Margins in the future
logger.error("ERROR: SasToken TTL less than Renewal Margin")
handle_exceptions.handle_background_exception(
pipeline_exceptions.PipelineError("SasToken TTL less than Renewal Margin!")
)
else:
logger.debug(
"Scheduling SAS Token renewal for {} seconds in the future".format(
seconds_until_renewal
)
)
self_weakref = weakref.ref(self)
@pipeline_thread.runs_on_pipeline_thread
def on_reauthorize_complete(op, error):
this = self_weakref()
if error:
logger.error(
"{}({}): reauthorize connection operation failed. Error={}".format(
this.name, op.name, error
)
)
handle_exceptions.handle_background_exception(error)
else:
logger.debug(
"{}({}): reauthorize connection operation is complete".format(
this.name, op.name
)
)
@pipeline_thread.invoke_on_pipeline_thread_nowait
def renew_token():
this = self_weakref()
logger.debug("Renewing SAS Token")
# Renew the token
sastoken = this.pipeline_root.pipeline_configuration.sastoken
sastoken.refresh()
# If the pipeline is already connected, send order to reauthorize the connection
# now that token has been renewed
if this.pipeline_root.connected:
this.send_op_down(
pipeline_ops_base.ReauthorizeConnectionOperation(
callback=on_reauthorize_complete
)
)
# Once again, start a renewal timer
this._start_renewal_timer()
self._token_renewal_timer = threading.Timer(seconds_until_renewal, renew_token)
self._token_renewal_timer.daemon = True
self._token_renewal_timer.start()
