From 0e76cd3a46ff141f29403ac38cfb9c5b95b613d2 Mon Sep 17 00:00:00 2001 From: Pierre-Luc Bertrand Date: Sat, 26 Mar 2022 16:02:01 -0400 Subject: [PATCH] Add exception stack traces to logging. Fixes #105 --- amqtt/broker.py | 24 +++++++++++++----------- amqtt/client.py | 4 ++-- amqtt/mqtt/protocol/client_handler.py | 4 ++-- amqtt/mqtt/protocol/handler.py | 8 ++++---- amqtt/plugins/manager.py | 10 ++++++---- amqtt/plugins/persistence.py | 10 ++++++---- amqtt/scripts/sub_script.py | 4 ++-- amqtt/utils.py | 4 ++-- docs/references/mqttclient.rst | 8 ++++---- samples/client_publish.py | 2 +- samples/client_publish_acl.py | 2 +- samples/client_subscribe.py | 4 ++-- samples/client_subscribe_acl.py | 4 ++-- 13 files changed, 47 insertions(+), 41 deletions(-) diff --git a/amqtt/broker.py b/amqtt/broker.py index 4d2442e0..76200d8a 100644 --- a/amqtt/broker.py +++ b/amqtt/broker.py @@ -250,7 +250,7 @@ async def start(self) -> None: except (MachineError, ValueError) as exc: # Backwards compat: MachineError is raised by transitions < 0.5.0. self.logger.warning( - "[WARN-0001] Invalid method call at this moment: %s" % exc + "[WARN-0001] Invalid method call at this moment", exc_info=True ) raise BrokerException("Broker instance can't be started: %s" % exc) @@ -347,7 +347,7 @@ async def start(self) -> None: self.logger.debug("Broker started") except Exception as e: - self.logger.error("Broker startup failed: %s" % e) + self.logger.error("Broker startup failed", exc_info=True) self.transitions.starting_fail() raise BrokerException("Broker instance can't be started: %s" % e) @@ -364,7 +364,7 @@ async def shutdown(self): self.transitions.shutdown() except (MachineError, ValueError) as exc: # Backwards compat: MachineError is raised by transitions < 0.5.0. - self.logger.debug("Invalid method call at this moment: %s" % exc) + self.logger.debug("Invalid method call at this moment", exc_info=True) raise BrokerException("Broker instance can't be stopped: %s" % exc) # Fire broker_shutdown event to plugins @@ -419,18 +419,20 @@ async def client_connected( handler, client_session = await BrokerProtocolHandler.init_from_connect( reader, writer, self.plugins_manager ) - except AMQTTException as exc: + except AMQTTException: self.logger.warning( - "[MQTT-3.1.0-1] %s: Can't read first packet an CONNECT: %s" - % (format_client_message(address=remote_address, port=remote_port), exc) + "[MQTT-3.1.0-1] %s: Can't read first packet an CONNECT" + % format_client_message(address=remote_address, port=remote_port), + exc_info=True, ) # await writer.close() self.logger.debug("Connection closed") return - except MQTTException as me: + except MQTTException: self.logger.error( - "Invalid connection from %s : %s" - % (format_client_message(address=remote_address, port=remote_port), me) + "Invalid connection from %s" + % format_client_message(address=remote_address, port=remote_port), + exc_info=True, ) await writer.close() self.logger.debug("Connection closed") @@ -674,8 +676,8 @@ async def _stop_handler(self, handler): """ try: await handler.stop() - except Exception as e: - self.logger.error(e) + except Exception: + self.logger.error("Failed to stop handler", exc_info=True) async def authenticate(self, session: Session, listener): """ diff --git a/amqtt/client.py b/amqtt/client.py index 3c5d1539..30e70af5 100644 --- a/amqtt/client.py +++ b/amqtt/client.py @@ -236,7 +236,7 @@ async def reconnect(self, cleansession=None): except asyncio.CancelledError: raise except Exception as e: - self.logger.warning("Reconnection attempt failed: %r" % e) + self.logger.warning("Reconnection attempt failed", exc_info=True) if reconnect_retries >= 0 and nb_attempt > reconnect_retries: self.logger.error( "Maximum number of connection attempts reached. Reconnection aborted" @@ -487,7 +487,7 @@ async def _connect_coro(self): "connection failed: invalid websocket handshake", ihs ) except (ProtocolHandlerException, ConnectionError, OSError) as e: - self.logger.warning("MQTT connection failed: %r" % e) + self.logger.warning("MQTT connection failed", exc_info=True) self.session.transitions.disconnect() raise ConnectException(e) diff --git a/amqtt/mqtt/protocol/client_handler.py b/amqtt/mqtt/protocol/client_handler.py index 3309ee7c..4fbd8f71 100644 --- a/amqtt/mqtt/protocol/client_handler.py +++ b/amqtt/mqtt/protocol/client_handler.py @@ -88,8 +88,8 @@ def handle_write_timeout(self): if not self._ping_task: self.logger.debug("Scheduling Ping") self._ping_task = asyncio.ensure_future(self.mqtt_ping()) - except Exception as e: - self.logger.debug("Exception ignored in ping task: %r" % e) + except Exception: + self.logger.debug("Exception ignored in ping task", exc_info=True) def handle_read_timeout(self): pass diff --git a/amqtt/mqtt/protocol/handler.py b/amqtt/mqtt/protocol/handler.py index e00c93f4..901896f0 100644 --- a/amqtt/mqtt/protocol/handler.py +++ b/amqtt/mqtt/protocol/handler.py @@ -150,8 +150,8 @@ async def stop(self): self.logger.debug("closing writer") try: await self.writer.close() - except Exception as e: - self.logger.debug("Handler writer close failed: %s" % e) + except Exception: + self.logger.debug("Handler writer close failed", exc_info=True) def _stop_waiters(self): self.logger.debug("Stopping %d puback waiters" % len(self._puback_waiters)) @@ -523,8 +523,8 @@ async def _send_packet(self, packet): await self.handle_connection_closed() except asyncio.CancelledError: raise - except Exception as e: - self.logger.warning("Unhandled exception: %s" % e) + except Exception: + self.logger.warning("Unhandled exception", exc_info=True) raise async def mqtt_deliver_next_message(self): diff --git a/amqtt/plugins/manager.py b/amqtt/plugins/manager.py index e424c94f..b4004e16 100644 --- a/amqtt/plugins/manager.py +++ b/amqtt/plugins/manager.py @@ -73,10 +73,12 @@ def _load_plugin(self, ep: pkg_resources.EntryPoint): plugin_context.logger = self.logger.getChild(ep.name) obj = plugin(plugin_context) return Plugin(ep.name, ep, obj) - except ImportError as ie: - self.logger.warning(f"Plugin {ep!r} import failed: {ie}") - except pkg_resources.UnknownExtra as ue: - self.logger.warning(f"Plugin {ep!r} dependencies resolution failed: {ue}") + except ImportError: + self.logger.warning(f"Plugin {ep!r} import failed", exc_info=True) + except pkg_resources.UnknownExtra: + self.logger.warning( + f"Plugin {ep!r} dependencies resolution failed", exc_info=True + ) def get_plugin(self, name): """ diff --git a/amqtt/plugins/persistence.py b/amqtt/plugins/persistence.py index 60824ff7..2941c253 100644 --- a/amqtt/plugins/persistence.py +++ b/amqtt/plugins/persistence.py @@ -28,9 +28,9 @@ def init_db(self): self.conn = sqlite3.connect(self.db_file) self.cursor = self.conn.cursor() self.context.logger.info("Database file '%s' opened" % self.db_file) - except Exception as e: + except Exception: self.context.logger.error( - f"Error while initializing database '{self.db_file}' : {e}" + f"Error while initializing database '{self.db_file}'", exc_info=True ) if self.cursor: self.cursor.execute( @@ -46,8 +46,10 @@ async def save_session(self, session): (session.client_id, dump), ) self.conn.commit() - except Exception as e: - self.context.logger.error(f"Failed saving session '{session}': {e}") + except Exception: + self.context.logger.error( + f"Failed saving session '{session}'", exc_info=True + ) async def find_session(self, client_id): if self.cursor: diff --git a/amqtt/scripts/sub_script.py b/amqtt/scripts/sub_script.py index 456f3ceb..aebc5955 100644 --- a/amqtt/scripts/sub_script.py +++ b/amqtt/scripts/sub_script.py @@ -104,8 +104,8 @@ async def do_sub(client, arguments): await client.disconnect() except KeyboardInterrupt: await client.disconnect() - except ConnectException as ce: - logger.fatal("connection to '%s' failed: %r" % (arguments["--url"], ce)) + except ConnectException: + logger.fatal("connection to '%s' failed" % (arguments["--url"]), exc_info=True) except asyncio.CancelledError: logger.fatal("Publish canceled due to previous error") diff --git a/amqtt/utils.py b/amqtt/utils.py index 08f4a715..2eacb797 100644 --- a/amqtt/utils.py +++ b/amqtt/utils.py @@ -41,6 +41,6 @@ def read_yaml_config(config_file: str) -> dict: try: with open(config_file) as stream: config = yaml.full_load(stream) - except yaml.YAMLError as exc: - logger.error("Invalid config_file %s: %r", config_file, exc) + except yaml.YAMLError: + logger.error("Invalid config_file %s", config_file, exc_info=True) return config diff --git a/docs/references/mqttclient.rst b/docs/references/mqttclient.rst index d9b49e4d..fcaeaf7b 100644 --- a/docs/references/mqttclient.rst +++ b/docs/references/mqttclient.rst @@ -38,8 +38,8 @@ The example below shows how to write a simple MQTT client which subscribes a top print("%d: %s => %s" % (i, packet.variable_header.topic_name, str(packet.payload.data))) await C.unsubscribe(['$SYS/broker/uptime', '$SYS/broker/load/#']) await C.disconnect() - except ClientException as ce: - logger.error("Client exception: %s" % ce) + except ClientException: + logger.error("Client exception", exc_info=True) if __name__ == '__main__': formatter = "[%(asctime)s] %(name)s {%(filename)s:%(lineno)d} %(levelname)s - %(message)s" @@ -93,8 +93,8 @@ This example also shows to method for publishing message asynchronously. #print(message) logger.info("messages published") await C.disconnect() - except ConnectException as ce: - logger.error("Connection failed: %s" % ce) + except ConnectException: + logger.error("Connection failed", exc_info=True) asyncio.get_event_loop().stop() diff --git a/samples/client_publish.py b/samples/client_publish.py index 5616d640..65df80ce 100644 --- a/samples/client_publish.py +++ b/samples/client_publish.py @@ -45,7 +45,7 @@ async def test_coro2(): logger.info("messages published") await C.disconnect() except ConnectException as ce: - logger.error("Connection failed: %s" % ce) + logger.error("Connection failed", exc_info=True) asyncio.get_event_loop().stop() diff --git a/samples/client_publish_acl.py b/samples/client_publish_acl.py index 54476d24..8e3df8de 100644 --- a/samples/client_publish_acl.py +++ b/samples/client_publish_acl.py @@ -26,7 +26,7 @@ async def test_coro(): logger.info("messages published") await C.disconnect() except ConnectException as ce: - logger.error("Connection failed: %s" % ce) + logger.error("Connection failed", exc_info=True) asyncio.get_event_loop().stop() diff --git a/samples/client_subscribe.py b/samples/client_subscribe.py index ba463402..96f61ce3 100644 --- a/samples/client_subscribe.py +++ b/samples/client_subscribe.py @@ -36,8 +36,8 @@ async def uptime_coro(): await C.unsubscribe(["$SYS/broker/uptime", "$SYS/broker/load/#"]) logger.info("UnSubscribed") await C.disconnect() - except ClientException as ce: - logger.error("Client exception: %s" % ce) + except ClientException: + logger.error("Client exception", exc_info=True) if __name__ == "__main__": diff --git a/samples/client_subscribe_acl.py b/samples/client_subscribe_acl.py index 7bc25e3e..4c91468a 100644 --- a/samples/client_subscribe_acl.py +++ b/samples/client_subscribe_acl.py @@ -40,8 +40,8 @@ async def uptime_coro(): await C.unsubscribe(["$SYS/broker/uptime", "$SYS/broker/load/#"]) logger.info("UnSubscribed") await C.disconnect() - except ClientException as ce: - logger.error("Client exception: %s" % ce) + except ClientException: + logger.error("Client exception", exc_info=True) if __name__ == "__main__":