About Log Message Formatting on Reconnect

[jbdyn]

Hey Aymeric,

I noticed that by this line

https://github.com/python-websockets/websockets/blob/98f236f89529d317628fe8ee3d4d0564e675f68d/src/websockets/asyncio/client.py#L525

the full traceback of the current Exception is included in the log message, which looks confusing to me.

Example

[2024-09-13 11:18:03] [INFO] ! connect failed; reconnecting in 0.8 seconds
Traceback (most recent call last):
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 411, in __aiter__
    async with self as protocol:
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 395, in __aenter__
    return await self
           ^^^^^^^^^^
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 376, in __await_impl__
    _transport, self.connection = await self.create_connection()
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1129, in create_connection
    raise OSError('Multiple exceptions: {}'.format(
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:04] [INFO] ! connect failed; reconnecting in 3.1 seconds
Traceback (most recent call last):
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 411, in __aiter__
    async with self as protocol:
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 395, in __aenter__
    return await self
           ^^^^^^^^^^
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 376, in __await_impl__
    _transport, self.connection = await self.create_connection()
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1129, in create_connection
    raise OSError('Multiple exceptions: {}'.format(
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:07] [INFO] ! connect failed; reconnecting in 5.0 seconds
Traceback (most recent call last):
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 411, in __aiter__
    async with self as protocol:
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 395, in __aenter__
    return await self
           ^^^^^^^^^^
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 376, in __await_impl__
    _transport, self.connection = await self.create_connection()
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1129, in create_connection
    raise OSError('Multiple exceptions: {}'.format(
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:12] [INFO] ! connect failed; reconnecting in 8.1 seconds
Traceback (most recent call last):
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 411, in __aiter__
    async with self as protocol:
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 395, in __aenter__
    return await self
           ^^^^^^^^^^
  File "/▉▉▉/.venv/lib/python3.12/site-packages/websockets/asyncio/client.py", line 376, in __await_impl__
    _transport, self.connection = await self.create_connection()
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1129, in create_connection
    raise OSError('Multiple exceptions: {}'.format(
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)

Since this exception is indeed useful to get to know about failed connections or received responses, how do feel about just deleting the traceback and keeping the exception message with one of these options?

Removing Traceback

• exc_info=(type(exc), exc, None) (see Python Logging Docs and sys.exc_info())
• exc_info=exc.with_traceback(None) (see Python Docs)

Example

[2024-09-13 11:18:03] [INFO] ! connect failed; reconnecting in 0.8 seconds
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:04] [INFO] ! connect failed; reconnecting in 3.1 seconds
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:07] [INFO] ! connect failed; reconnecting in 5.0 seconds
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:12] [INFO] ! connect failed; reconnecting in 8.1 seconds
OSError: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)

Put exception into logging message

self.logger.info(
    "! connect failed; reconnecting in %.1f seconds; reason: %s",
    delay,
    exc,
)

Example

[2024-09-13 11:18:03] [INFO] ! connect failed; reconnecting in 0.8 seconds; reason: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:04] [INFO] ! connect failed; reconnecting in 3.1 seconds; reason: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:07] [INFO] ! connect failed; reconnecting in 5.0 seconds; reason: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)
[2024-09-13 11:18:12] [INFO] ! connect failed; reconnecting in 8.1 seconds; reason: Multiple exceptions: [Errno 111] Connect call failed ('::1', 8001, 0, 0), [Errno 111] Connect call failed ('127.0.0.1', 8001)

Personally, I prefer the last one.