python-websockets / python-websockets/websockets

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

Abierto Apto para principiantes
#1,763 8 comentarios 0 reacciones 0 asignados Ver en GitHub

Nadie ha tomado este issue todavía.

enhancement
Lenguaje dominante
Python
Estrellas
5.7k
Forks
613
Merge medio
23 h 5 min
PR fusionados (30 d)
9

Descripción

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.

Guía de contribución

No hay ninguna guía de contribución indexada para este repositorio

Primeros pasos

  1. Lee el issue completo y luego la guía de contribución del proyecto.
  2. Comenta en el issue que vas a ocuparte — evita que dos personas hagan lo mismo.
  3. Haz un fork del repositorio y trabaja en una rama.
  4. Abre un pull request que haga referencia al número del issue.

Línea de trabajo

Comienza en Frame.str y _data_repr y, a continuación, sigue las rutas de logging DEBUG en send_frame y parse que muestra la reproducción. Usa PING_PAYLOAD determinista con un FileHandler cp1252 para verificar el cambio. Se considera terminado cuando los payloads de PING y PONG se registran de forma segura sin que el handler produzca un UnicodeEncodeError.

Escrito por el modelo de indexación a partir del texto del issue.

Evaluación

Stack tecnológico
python
Área
networking
Tipo de issue
Error
Dificultad
2/5
Tiempo estimado
1-3 horas
Estado de actividad
Activo
Claridad
Bien especificado
Aptitud para principiantes
78/100

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.