diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index be5678455..ae71be265 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 d276ac171..b3d50c12e 100644 --- a/src/websockets/asyncio/client.py +++ b/src/websockets/asyncio/client.py @@ -3,6 +3,7 @@ import asyncio import logging import os +import traceback import urllib.parse from collections.abc import AsyncIterator, Generator, Sequence from types import TracebackType @@ -521,9 +522,10 @@ 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: %s", delay, - exc_info=True, + # Remove first argument when dropping Python 3.9. + traceback.format_exception_only(type(exc), exc)[0].strip(), ) await asyncio.sleep(delay) continue diff --git a/src/websockets/asyncio/connection.py b/src/websockets/asyncio/connection.py index 5545632d6..186846ef3 100644 --- a/src/websockets/asyncio/connection.py +++ b/src/websockets/asyncio/connection.py @@ -7,6 +7,7 @@ import random import struct import sys +import traceback import uuid from collections.abc import AsyncIterable, AsyncIterator, Awaitable, Iterable, Mapping from types import TracebackType @@ -785,7 +786,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 +867,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 +1043,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(): @@ -1180,8 +1181,12 @@ def broadcast( exceptions.append(exception) else: connection.logger.warning( - "skipped broadcast: failed to write message", - exc_info=True, + "skipped broadcast: failed to write message: %s", + traceback.format_exception_only( + # Remove first argument when dropping Python 3.9. + type(write_exception), + write_exception, + )[0].strip(), ) if raise_exceptions and exceptions: diff --git a/src/websockets/legacy/client.py b/src/websockets/legacy/client.py index 116445e25..555069e8c 100644 --- a/src/websockets/legacy/client.py +++ b/src/websockets/legacy/client.py @@ -5,6 +5,7 @@ import logging import os import random +import traceback import urllib.parse import warnings from collections.abc import AsyncIterator, Generator, Sequence @@ -597,22 +598,24 @@ async def __aiter__(self) -> AsyncIterator[WebSocketClientProtocol]: try: async with self as protocol: yield protocol - except Exception: + except Exception as exc: # Add a random initial delay between 0 and 5 seconds. # See 7.2.3. Recovering from Abnormal Closure in RFC 6455. 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: %s", initial_delay, - exc_info=True, + # Remove first argument when dropping Python 3.9. + traceback.format_exception_only(type(exc), exc)[0].strip(), ) await asyncio.sleep(initial_delay) else: self.logger.info( - "! connect failed again; retrying in %d seconds", + "connect failed again; retrying in %d seconds: %s", int(backoff_delay), - exc_info=True, + # Remove first argument when dropping Python 3.9. + traceback.format_exception_only(type(exc), exc)[0].strip(), ) await asyncio.sleep(int(backoff_delay)) # Increase delay with truncated exponential backoff. diff --git a/src/websockets/legacy/protocol.py b/src/websockets/legacy/protocol.py index cedde6200..db126c01e 100644 --- a/src/websockets/legacy/protocol.py +++ b/src/websockets/legacy/protocol.py @@ -9,6 +9,7 @@ import struct import sys import time +import traceback import uuid import warnings from collections.abc import AsyncIterable, AsyncIterator, Awaitable, Iterable, Mapping @@ -1246,7 +1247,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 +1289,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 +1307,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 +1333,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: @@ -1624,8 +1625,12 @@ def broadcast( exceptions.append(exception) else: websocket.logger.warning( - "skipped broadcast: failed to write message", - exc_info=True, + "skipped broadcast: failed to write message: %s", + traceback.format_exception_only( + # Remove first argument when dropping Python 3.9. + type(write_exception), + write_exception, + )[0].strip(), ) if raise_exceptions and exceptions: diff --git a/src/websockets/sync/connection.py b/src/websockets/sync/connection.py index 8d1dbcf58..77f803c9b 100644 --- a/src/websockets/sync/connection.py +++ b/src/websockets/sync/connection.py @@ -640,7 +640,10 @@ 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 +668,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 +789,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 diff --git a/tests/asyncio/test_connection.py b/tests/asyncio/test_connection.py index d61798afb..902b3b847 100644 --- a/tests/asyncio/test_connection.py +++ b/tests/asyncio/test_connection.py @@ -1337,7 +1337,10 @@ async def test_broadcast_skips_connection_failing_to_send(self): self.assertEqual( [record.getMessage() for record in logs.records], - ["skipped broadcast: failed to write message"], + [ + "skipped broadcast: failed to write message: " + "RuntimeError: Cannot call write() after write_eof()" + ], ) @unittest.skipIf( diff --git a/tests/legacy/test_client_server.py b/tests/legacy/test_client_server.py index 502ab68e7..c13c6c92e 100644 --- a/tests/legacy/test_client_server.py +++ b/tests/legacy/test_client_server.py @@ -1607,6 +1607,10 @@ async def run_client(): ], ) # Iteration 3 + exc = ( + "websockets.legacy.exceptions.InvalidStatusCode: " + "server rejected WebSocket connection: HTTP 503" + ) self.assertEqual( [ re.sub(r"[0-9\.]+ seconds", "X seconds", record.getMessage()) @@ -1615,12 +1619,12 @@ async def run_client(): [ "connection rejected (503 Service Unavailable)", "connection closed", - "! connect failed; reconnecting in X seconds", + f"connect failed; reconnecting in X seconds: {exc}", ] + [ "connection rejected (503 Service Unavailable)", "connection closed", - "! connect failed again; retrying in X seconds", + f"connect failed again; retrying in X seconds: {exc}", ] * ((len(logs.records) - 8) // 3) + [ diff --git a/tests/legacy/test_protocol.py b/tests/legacy/test_protocol.py index be2910a8f..d30198934 100644 --- a/tests/legacy/test_protocol.py +++ b/tests/legacy/test_protocol.py @@ -1547,14 +1547,14 @@ def test_broadcast_reports_connection_sending_fragmented_text(self): def test_broadcast_skips_connection_failing_to_send(self): # Configure mock to raise an exception when writing to the network. - self.protocol.transport.write.side_effect = RuntimeError + self.protocol.transport.write.side_effect = RuntimeError("BOOM") with self.assertLogs("websockets", logging.WARNING) as logs: broadcast([self.protocol], "café") self.assertEqual( [record.getMessage() for record in logs.records], - ["skipped broadcast: failed to write message"], + ["skipped broadcast: failed to write message: RuntimeError: BOOM"], ) @unittest.skipIf(