From a3dfe00120f7b0a5200848921477cbe8845397c8 Mon Sep 17 00:00:00 2001 From: Aymeric Augustin Date: Sun, 3 Nov 2024 09:47:51 +0100 Subject: [PATCH] Clean up prefixes of debug log messages. All debug messages and only debug messages should have them. --- docs/topics/logging.rst | 8 ++++++-- src/websockets/asyncio/client.py | 2 +- src/websockets/asyncio/connection.py | 6 +++--- src/websockets/legacy/client.py | 4 ++-- src/websockets/legacy/protocol.py | 8 ++++---- src/websockets/sync/connection.py | 12 +++++++++--- 6 files changed, 25 insertions(+), 15 deletions(-) diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index be567845..ae71be26 100644 --- a/docs/topics/logging.rst +++ b/docs/topics/logging.rst @@ -218,7 +218,10 @@ Here's what websockets logs at each level. ``ERROR`` ......... -* Exceptions raised by connection handler coroutines in servers +* Exceptions raised by your code in servers + * connection handler coroutines + * ``select_subprotocol`` callbacks + * ``process_request`` and ``process_response`` callbacks * Exceptions resulting from bugs in websockets ``WARNING`` @@ -250,4 +253,5 @@ Debug messages have cute prefixes that make logs easier to scan: * ``=`` - set connection state * ``x`` - shut down connection * ``%`` - manage pings and pongs -* ``!`` - handle errors and timeouts +* ``-`` - timeout +* ``!`` - error, with a traceback diff --git a/src/websockets/asyncio/client.py b/src/websockets/asyncio/client.py index d276ac17..302d0b94 100644 --- a/src/websockets/asyncio/client.py +++ b/src/websockets/asyncio/client.py @@ -521,7 +521,7 @@ async def __aiter__(self) -> AsyncIterator[ClientConnection]: delays = backoff() delay = next(delays) self.logger.info( - "! connect failed; reconnecting in %.1f seconds", + "connect failed; reconnecting in %.1f seconds", delay, exc_info=True, ) diff --git a/src/websockets/asyncio/connection.py b/src/websockets/asyncio/connection.py index 5545632d..c4961884 100644 --- a/src/websockets/asyncio/connection.py +++ b/src/websockets/asyncio/connection.py @@ -785,7 +785,7 @@ async def keepalive(self) -> None: self.logger.debug("% received keepalive pong") except asyncio.TimeoutError: if self.debug: - self.logger.debug("! timed out waiting for keepalive pong") + self.logger.debug("- timed out waiting for keepalive pong") async with self.send_context(): self.protocol.fail( CloseCode.INTERNAL_ERROR, @@ -866,7 +866,7 @@ async def send_context( await self.drain() except Exception as exc: if self.debug: - self.logger.debug("error while sending data", exc_info=True) + self.logger.debug("! error while sending data", exc_info=True) # While the only expected exception here is OSError, # other exceptions would be treated identically. wait_for_close = False @@ -1042,7 +1042,7 @@ def data_received(self, data: bytes) -> None: self.send_data() except Exception as exc: if self.debug: - self.logger.debug("error while sending data", exc_info=True) + self.logger.debug("! error while sending data", exc_info=True) self.set_recv_exc(exc) if self.protocol.close_expected(): diff --git a/src/websockets/legacy/client.py b/src/websockets/legacy/client.py index 116445e2..a2dc0250 100644 --- a/src/websockets/legacy/client.py +++ b/src/websockets/legacy/client.py @@ -603,14 +603,14 @@ async def __aiter__(self) -> AsyncIterator[WebSocketClientProtocol]: if backoff_delay == self.BACKOFF_MIN: initial_delay = random.random() * self.BACKOFF_INITIAL self.logger.info( - "! connect failed; reconnecting in %.1f seconds", + "connect failed; reconnecting in %.1f seconds", initial_delay, exc_info=True, ) await asyncio.sleep(initial_delay) else: self.logger.info( - "! connect failed again; retrying in %d seconds", + "connect failed again; retrying in %d seconds", int(backoff_delay), exc_info=True, ) diff --git a/src/websockets/legacy/protocol.py b/src/websockets/legacy/protocol.py index cedde620..bd998dfd 100644 --- a/src/websockets/legacy/protocol.py +++ b/src/websockets/legacy/protocol.py @@ -1246,7 +1246,7 @@ async def keepalive_ping(self) -> None: self.logger.debug("% received keepalive pong") except asyncio.TimeoutError: if self.debug: - self.logger.debug("! timed out waiting for keepalive pong") + self.logger.debug("- timed out waiting for keepalive pong") self.fail_connection( CloseCode.INTERNAL_ERROR, "keepalive ping timeout", @@ -1288,7 +1288,7 @@ async def close_connection(self) -> None: if await self.wait_for_connection_lost(): return if self.debug: - self.logger.debug("! timed out waiting for TCP close") + self.logger.debug("- timed out waiting for TCP close") # Half-close the TCP connection if possible (when there's no TLS). if self.transport.can_write_eof(): @@ -1306,7 +1306,7 @@ async def close_connection(self) -> None: if await self.wait_for_connection_lost(): return if self.debug: - self.logger.debug("! timed out waiting for TCP close") + self.logger.debug("- timed out waiting for TCP close") finally: # The try/finally ensures that the transport never remains open, @@ -1332,7 +1332,7 @@ async def close_transport(self) -> None: if await self.wait_for_connection_lost(): return if self.debug: - self.logger.debug("! timed out waiting for TCP close") + self.logger.debug("- timed out waiting for TCP close") # Abort the TCP connection. Buffers are discarded. if self.debug: diff --git a/src/websockets/sync/connection.py b/src/websockets/sync/connection.py index 8d1dbcf5..c4b2c212 100644 --- a/src/websockets/sync/connection.py +++ b/src/websockets/sync/connection.py @@ -640,7 +640,7 @@ def recv_events(self) -> None: data = self.socket.recv(self.recv_bufsize) except Exception as exc: if self.debug: - self.logger.debug("error while receiving data", exc_info=True) + self.logger.debug("! error while receiving data", exc_info=True) # When the closing handshake is initiated by our side, # recv() may block until send_context() closes the socket. # In that case, send_context() already set recv_exc. @@ -665,7 +665,10 @@ def recv_events(self) -> None: self.send_data() except Exception as exc: if self.debug: - self.logger.debug("error while sending data", exc_info=True) + self.logger.debug( + "! error while sending data", + exc_info=True, + ) # Similarly to the above, avoid overriding an exception # set by send_context(), in case of a race condition # i.e. send_context() closes the socket after recv() @@ -783,7 +786,10 @@ def send_context( self.send_data() except Exception as exc: if self.debug: - self.logger.debug("error while sending data", exc_info=True) + self.logger.debug( + "! error while sending data", + exc_info=True, + ) # While the only expected exception here is OSError, # other exceptions would be treated identically. wait_for_close = False