Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Remove stack traces from INFO and WARNING logs. #1535

Merged
merged 2 commits into from
Nov 6, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 6 additions & 2 deletions docs/topics/logging.rst
Original file line number Diff line number Diff line change
Expand Up @@ -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``
Expand Down Expand Up @@ -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
6 changes: 4 additions & 2 deletions src/websockets/asyncio/client.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
15 changes: 10 additions & 5 deletions src/websockets/asyncio/connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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():
Expand Down Expand Up @@ -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:
Expand Down
13 changes: 8 additions & 5 deletions src/websockets/legacy/client.py
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
import logging
import os
import random
import traceback
import urllib.parse
import warnings
from collections.abc import AsyncIterator, Generator, Sequence
Expand Down Expand Up @@ -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.
Expand Down
17 changes: 11 additions & 6 deletions src/websockets/legacy/protocol.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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():
Expand All @@ -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,
Expand All @@ -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:
Expand Down Expand Up @@ -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:
Expand Down
15 changes: 12 additions & 3 deletions src/websockets/sync/connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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()
Expand Down Expand Up @@ -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
Expand Down
5 changes: 4 additions & 1 deletion tests/asyncio/test_connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down
8 changes: 6 additions & 2 deletions tests/legacy/test_client_server.py
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand All @@ -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)
+ [
Expand Down
4 changes: 2 additions & 2 deletions tests/legacy/test_protocol.py
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down