python-websockets / python-websockets/websockets

Ping/pong frame logging can produce text that crashes non-UTF-8 log handlers (UnicodeEncodeError)

Open Beginner friendly
#1,763 8 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

enhancement
Dominant language
Python
Stars
5.7k
Forks
613
Avg merge
23h 5m
Merged PRs (30d)
9

Description

Description

Frame.__str__ (used when rendering a frame for DEBUG-level logging) tries to guess whether a payload is "text" by attempting a strict UTF-8 decode, even for PING/PONG control frames. But a ping/pong payload is not user data — per Connection.ping's docstring, "If data is None, the payload is four random bytes" — it's an opaque nonce with no textual meaning, generated by websockets itself purely to match a pong to its ping.

When that random nonce happens to be valid UTF-8 (a fraction of random byte sequences will be), _data_repr renders it as decoded text instead of hex, e.g.:

PING 'F֊}' [text, 4 bytes]

The decoded character can land outside whatever encoding the caller's log handler happens to use. logging.FileHandler / TimedRotatingFileHandler default to the platform's locale encoding unless the caller explicitly passes encoding="utf-8" — on Windows that's commonly cp1252. When the nonce decodes to a character outside that encoding (here, U+058A, produced by the 2-byte sequence \xd6\x8a), the logging module's own stream.write() call raises UnicodeEncodeError.

websockets itself never raises here — Frame.__str__ returns a perfectly valid str. The error surfaces entirely inside logging.Handler.emit(), which by default catches it and prints a --- Logging error --- traceback to stderr rather than propagating it. So it's non-fatal, but it's directly provoked by the string websockets chose to log, for a payload that was never meant to be interpreted as text.

This is a different failure mode than #1695 (fixed in 16.0), which was a UnicodeDecodeError raised inside websockets for fragmented text frames. This one is a UnicodeEncodeError raised by the caller's handler, from a control-frame payload that decoded cleanly.

Reproduction

Deterministic, no Windows required — it forces encoding="cp1252" explicitly on the log handler so it reproduces on any OS (that's the part that's Windows-specific in practice, not the crash itself):

import logging
import threading
from pathlib import Path

from websockets.sync.client import connect
from websockets.sync.server import serve

PING_PAYLOAD = b"F\xd6\x8a}"  # decodes to 'F֊}' -- U+058A not in cp1252
LOG_FILE = Path(__file__).with_name("repro.log")

# Mirrors how many apps configure logging: a rotating/plain FileHandler with
# no explicit encoding, so it defaults to the platform's locale encoding
# (cp1252 on Windows; forced here so this reproduces on any OS).
logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    handlers=[logging.FileHandler(LOG_FILE, mode="w", encoding="cp1252")],
)


def handler(websocket):
    for _ in websocket:
        pass


def main():
    print(f"payload {PING_PAYLOAD!r} decodes to {PING_PAYLOAD.decode()!r}", flush=True)

    with serve(handler, "localhost", 0) as server:
        threading.Thread(target=server.serve_forever, daemon=True).start()
        host, port = server.socket.getsockname()
        with connect(f"ws://{host}:{port}") as ws:
            pong_received = ws.ping(PING_PAYLOAD)
            if not pong_received.wait(timeout=5):
                raise TimeoutError("no pong received")
        server.shutdown()

    print("done -- check stderr above for '--- Logging error ---'", flush=True)


if __name__ == "__main__":
    main()
Output 

uv run python src/repro_websockets_logging.py
payload b'F\xd6\x8a}' decodes to 'F֊}'
--- Logging error ---
Traceback (most recent call last):
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/encodings/cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeEncodeError: 'charmap' codec can't encode character '\u058a' in position 58: character maps to <undefined>
Call stack:
  File "/Users/trevinavery/Workspace/websockets_bug/src/repro_websockets_logging.py", line 65, in <module>
    pong_received = ws.ping(PING_PAYLOAD)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/connection.py", line 675, in ping
    self.protocol.send_ping(data)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 414, in send_ping
    self.send_frame(Frame(PING, data))
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 755, in send_frame
    self.logger.debug("> %s", frame)
Message: '> %s'
Arguments: (Frame(opcode=<Opcode.PING: 9>, data=b'F\xd6\x8a}', fin=True, rsv1=False, rsv2=False, rsv3=False),)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/encodings/cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeEncodeError: 'charmap' codec can't encode character '\u058a' in position 58: character maps to <undefined>
Call stack:
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1032, in _bootstrap
    self._bootstrap_inner()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/server.py", line 229, in recv_events
    super().recv_events()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/connection.py", line 870, in recv_events
    self.protocol.receive_data(data)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 271, in receive_data
    next(self.parser)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/server.py", line 635, in parse
    yield from super().parse()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 609, in parse
    self.logger.debug("< %s", frame)
Message: '< %s'
Arguments: (Frame(opcode=<Opcode.PING: 9>, data=b'F\xd6\x8a}', fin=True, rsv1=False, rsv2=False, rsv3=False),)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/encodings/cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeEncodeError: 'charmap' codec can't encode character '\u058a' in position 58: character maps to <undefined>
Call stack:
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1032, in _bootstrap
    self._bootstrap_inner()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/server.py", line 229, in recv_events
    super().recv_events()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/connection.py", line 870, in recv_events
    self.protocol.receive_data(data)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 271, in receive_data
    next(self.parser)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/server.py", line 635, in parse
    yield from super().parse()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 611, in parse
    self.recv_frame(frame)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 694, in recv_frame
    self.send_frame(pong_frame)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 755, in send_frame
    self.logger.debug("> %s", frame)
Message: '> %s'
Arguments: (Frame(opcode=<Opcode.PONG: 10>, data=b'F\xd6\x8a}', fin=True, rsv1=False, rsv2=False, rsv3=False),)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/encodings/cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeEncodeError: 'charmap' codec can't encode character '\u058a' in position 58: character maps to <undefined>
Call stack:
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1032, in _bootstrap
    self._bootstrap_inner()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/Users/trevinavery/.local/share/uv/python/cpython-3.12.14-macos-aarch64-none/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/client.py", line 154, in recv_events
    super().recv_events()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/sync/connection.py", line 870, in recv_events
    self.protocol.receive_data(data)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 271, in receive_data
    next(self.parser)
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/client.py", line 348, in parse
    yield from super().parse()
  File "/Users/trevinavery/Workspace/websockets_bug/.venv/lib/python3.12/site-packages/websockets/protocol.py", line 609, in parse
    self.logger.debug("< %s", frame)
Message: '< %s'
Arguments: (Frame(opcode=<Opcode.PONG: 10>, data=bytearray(b'F\xd6\x8a}'), fin=True, rsv1=False, rsv2=False, rsv3=False),)

Running it prints, to stderr, four --- Logging error --- / UnicodeEncodeError: 'charmap' codec can't encode character '֊'... tracebacks — one for each place send_frame/parse logs the ping (client send, server recv) and pong (server send, client recv).

Why it looks intermittent in practice

Most random 4-byte payloads either aren't valid UTF-8 at all (then _data_repr falls back to a hex dump, which is always safe to log) or decode to characters that happen to exist in the caller's encoding. It only breaks on the subset that decode cleanly and land on a code point outside that encoding — which is why, for a client pinging once a second, it can look like it happens "at random" every so often rather than consistently.

Environment
  • websockets 17.1 (latest on PyPI at time of filing)
  • Python 3.12
  • Reproduced on macOS by forcing encoding="cp1252"; originally observed on Windows via a TimedRotatingFileHandler created without an explicit encoding=
Possible directions

I don't think this is entirely clear-cut — Frame.__str__ is documented as a best-effort guess for logging/debugging, and the crash itself happens in the caller's own logging configuration (we've resolved it on our end by pinning our handler to UTF-8 and raising the websockets logger to INFO). But a couple of things seem worth considering upstream:

  1. For PING/PONG frames whose payload wasn't supplied by the caller as str (i.e. the auto-generated random nonce), there doesn't seem to be a good reason to guess it might be text — it's always opaque bytes with no semantic meaning, so a hex dump seems like the more honest representation regardless of whether it happens to decode.
  2. More generally, _data_repr can hand back arbitrary Unicode, and it's easy for a library or application to end up with a non-UTF-8 log destination (this is the default for file handlers on Windows). Before logging the result of _data_repr, we could check if all handlers for the logger supports UTF-8 encoding. If not, then it logs the hex dump instead. This would prevent the logger from throwing an error, but it would not be very obvious behavior, and it could be inefficient if there are many logs or many handlers. If this is the chosen path, we should consider caching the result. 
    def has_non_utf8_handler(logger: logging.Logger | None):
	while logger:
		for h in logger.handlers:
			# FileHandler exposes .encoding directly; plain StreamHandler doesn't --
			# fall back to the underlying stream's .encoding either way.
			# NOTE: Other handlers may set the encoding in a different way, all buitin handlers should be checked
			enc = getattr(h, 'encoding', None) or getattr(getattr(h, 'stream', None), 'encoding', None)
			if enc != 'utf-8':
				return True
		if not logger.propagate:
			break
		logger = logger.parent
	return False

I think option 1 makes the most sense to ensure the nonce is never the reason there is an error. This means, if the logger does error, it is because of some data passed by the user, not internally in the library, which is much more clear to debug.

Worth noting that I used AI to diagnose and research this issue, but I verified the reproduction and other details myself.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at Frame.str and _data_repr, then trace the DEBUG logging paths in send_frame and parse shown by the reproduction. Use the deterministic PING_PAYLOAD with a cp1252 FileHandler to verify the change. Done means PING and PONG payloads are logged safely without UnicodeEncodeError from the handler.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
networking
Issue type
Bug
Difficulty
2/5
Estimated time
1-3 hours
Activity status
Active
Clarity
Clearly specified
Newbie friendliness
78/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.