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

[TrevinAvery]

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.

[aaugustin]

I saw the PR and closed it before the issue description. Let me think about this more.

I agree in principle; it's kinda stupid for websockets to log ping payloads as text when it generated them itself as random binary.
However, even if we solved that side, we wouldn't solve solve pings or pongs received on the connection. That's not the right fix.

Also, I care about providing helpful logs, but there's a limit to how much code I'm willing to maintain for this purpose.

IMO the next step is to check the logging API and determine what constraints it enforces on inputs.

[aaugustin]

Intuitively, I still feel like it should be the logging handler's responsibility to deal with what it cannot represent i.e. .encode(errors="...").

[TrevinAvery]

I agree that sometimes it is not worth supporting a fix, so maybe this is too small to worry about. But I think it could confuse other developers in the future if left as is. I turned on debug logging trying to fix something else, and found this error as a red herring. I didn't lose a ton of time on it, but it is a little annoying.

I realize that checking the logger handlers may be overkill, and ultimately the developer using the package controls the loggers, so they should just configure things correctly. And maybe it is overly complex to track if the ping message was randomly generated. How about instead, we limit the generated ping message to ASCII values? Then it will always convert to a string just fine.

[aaugustin]

we limit the generated ping message to ASCII values

This doesn't work in general because we can also receive pings or pongs generated by the other side of the connection, and we don't control these.

Also, I would like to have one method that works for all types of frames and payloads, in order to keep complexity manageable.

---

The "red herring" argument is convincing.

Potential options:

1. treat as text if ASCII, else binary: solves the problem fully as all charsets are a superset of ASCII; but non-ASCII UTF-8 text in text frames will be displayed as binary, which sucks e.g. for chinese/japanese/etc. text
2. treat text frames as UTF-8, ignoring errors; use option 1. for other kinds of frames (binary and control frames): this solves your problem because you encountered it only for control frames. If you're receiving and logging text that your logging system doesn't support, I feel like it's defensible to say that it's your problem. Non-western encodings can still be displayed "natively" in logs in general.