python-websockets / python-websockets/websockets

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

Đang mở Phù hợp với người mới
#1,763 8 bình luận 0 reaction 0 người được giao Xem trên GitHub

Chưa có ai nhận issue này.

enhancement
Ngôn ngữ chính
Python
Star
5.7k
Fork
613
Merge trung bình
23 giờ 5 phút
Pull request đã merge (30 ngày)
9

Mô tả

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.

Hướng dẫn đóng góp

Chưa lập chỉ mục được hướng dẫn đóng góp cho kho mã nguồn này

Bắt đầu từ đâu

  1. Đọc hết issue, rồi đọc hướng dẫn đóng góp của dự án.
  2. Bình luận trên issue rằng bạn sẽ nhận — tránh hai người làm cùng một việc.
  3. Fork repository và làm thay đổi trên một nhánh.
  4. Mở pull request có tham chiếu số hiệu của issue.

Hướng nghiên cứu

Bắt đầu từ Frame.str và _data_repr, sau đó lần theo các đường dẫn ghi log DEBUG trong send_frame và parse được thể hiện bởi bản tái hiện. Sử dụng PING_PAYLOAD xác định cùng với FileHandler cp1252 để xác minh thay đổi. Được coi là hoàn tất khi các payload PING và PONG được ghi log an toàn mà không phát sinh UnicodeEncodeError từ handler.

Do mô hình lập chỉ mục viết ra từ nội dung của issue.

Đánh giá

Công nghệ
python
Lĩnh vực
networking
Loại issue
Lỗi
Độ khó
2/5
Thời gian dự kiến
1-3 giờ
Mức độ hoạt động
Sôi nổi
Độ rõ ràng
Đặc tả rõ ràng
Mức phù hợp với người mới
78/100

Nhận issue mới trong hộp thư của bạn

Bản tóm tắt ngắn những issue GitHub phù hợp với người mới.