Unable to suppress traceback when opening handshake fails

[aseiger]

While implementing an Asyncio server (with the new API) - I am unable to catch the InvalidMessage exception that can occur. It is correctly logged as an error, but then a traceback occurs which, as far as I can tell, there is no way to suppress.

[ERROR][websockets.server] 2025-01-30 10:30:45,468 opening handshake failed
Traceback (most recent call last):
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/http11.py", line 138, in parse
    request_line = yield from parse_line(read_line)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/http11.py", line 305, in parse_line
    line = yield from read_line(MAX_LINE_LENGTH)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/streams.py", line 46, in read_line
    raise EOFError(f"stream ends after {p} bytes, before end of line")
EOFError: stream ends after 0 bytes, before end of line

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/server.py", line 562, in parse
    request = yield from Request.parse(
              ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/http11.py", line 140, in parse
    raise EOFError("connection closed while reading HTTP request line") from exc
EOFError: connection closed while reading HTTP request line

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/asyncio/server.py", line 354, in conn_handler
    await connection.handshake(
  File "/home/alex/development/arcbridge/.venv/lib/python3.11/site-packages/websockets/asyncio/server.py", line 205, in handshake
    raise self.protocol.handshake_exc
websockets.exceptions.InvalidMessage: did not receive a valid HTTP request

As seen in the trace above - the conn_handler() function is properly logging the error... but then the traceback print occurs, due to exc_info=True on line 363 of server.py:

async with asyncio_timeout(self.open_timeout):
    try:
        await connection.handshake(
            self.process_request,
            self.process_response,
            self.server_header,
        )
    except asyncio.CancelledError:
        connection.transport.abort()
        raise
    except Exception:
        connection.logger.error("opening handshake failed", exc_info=True)
        connection.transport.abort()
        return

My suggestion is to have exc_info tied to a particular debug flag passed into the serve() call, as this clutters up the logs otherwise.

[aaugustin]

Does of of these option work for you?

https://websockets.readthedocs.io/en/stable/topics/logging.html#disable-logging

[aaugustin]

Probably you want: logging.getLogger("websockets").setLevel(logging.CRITICAL)

[aaugustin]

Closing the issue for now — but feel free to comment if my answers above don't really solve your problem.

[aseiger]

They do solve my problems, technically - thank you!

The issue I have is with the traceback included in the log output - It's nice to have websockets set to "warning", but having the full traceback included in the log printout is behavior that feels like a different log level. It's very disconcerting to see tracebacks in production logs, as usually for our code you only see tracebacks when there's an unhandled exception.

[char101]

This handshake exception always happens with firefox which always opens two connections to the websocket server and immediately close the 2nd connection, thus the handshake failure.

Although setting the log level to CRITICAL works, I'd prefer that these handshake error is not logged at WARNING level because they are part of normal browser behavior.

[aaugustin]

That's an interesting behavior that I wasn't aware of. Let me reconsider.

[breathe]

+1 to this not being an error log level but something much lower like debug or trace ...

Another real world example of where this behavior is problematic is when integrating with systems like google cloud run which allow configuration of a startup_probe. The startup_probe can be a tcp connection which connects, writes no bytes and then disconnects. Such probes lead to error logs here.

I can turn off websockets logging entirely -- but that seems undesirable to me as I would like to know if errors occur during other points of the websocket lifecycle.

Can repro this easily with something like:

run_server_process.py --port 8080

nc localhost 8080
<ctrl-c>

[aaugustin]

On Google Cloud Run, using an HTTP probe is cleaner:

• https://cloud.google.com/run/docs/samples/cloudrun-healthchecks-liveness-probe-http
• https://websockets.readthedocs.io/en/stable/faq/server.html#how-do-i-implement-a-health-check

[breathe]

That works ok -- better for my use case than shutting off all logging from the websockets/websockets.server stdlib logging modules I think.

Thanks!