Reduce noise in logs when process_request returns an HTTP response

[aaugustin]

Whenever the opening handshake ends with a code other than 101, an error is logged.

While this behavior was already present in the legacy implementation (I believe), it's less than ideal. EDIT: it wasn't present.

Probably it should be an info or a warning, except when the code is 5xx?

This was raised in #1419 (comment)

[stalkerg]

In legacy we never saw this behavior. If the response process returns something we should ignore any errors here.

[stalkerg]

Hmm seems like any normal HTTP response with 200 code is closed as exception.
We set exception to the protocol during send response - https://github.com/python-websockets/websockets/blob/main/src/websockets/asyncio/server.py#L193
inside response here:
https://github.com/python-websockets/websockets/blob/main/src/websockets/server.py#L543

after we rise it at the end of handshake function and show it in conn_handler function:
https://github.com/python-websockets/websockets/blob/main/src/websockets/asyncio/server.py#L359

we also do a few close functions.

The main question - do we need to start websocket pipeline if we want just return small HTTP response for health check or metrics?

Probably will be ok if we do return before this assert if response is 200 and close only transport (should we support HTTP 1.1?). https://github.com/python-websockets/websockets/blob/main/src/websockets/asyncio/server.py#L363 without any close

Seems like we create frames assembler and other staff even before request process - https://github.com/python-websockets/websockets/blob/main/src/websockets/asyncio/server.py#L218

I think will be better to go process_request before WebSocket protocol init.

[davidavdav]

In websockets==13.0 I do not get the server side error for the example health check (that needs "OK\n" instead of b"OK\n"), but in websockets==13.1 I do get this error

[Javrd]

I've a similar issue that could be related with this. I've errors shown bellow in my logs. The problem is I can't silent/catch/handle this errors. They seems to be print in console from websockets lib and I can't do anything with them. Downgrading to 13.0 instead of using 13.1 works to silent it.

opening handshake failed
Traceback (most recent call last):
  File "/home/user/test/.venv/lib/python3.12/site-packages/websockets/http11.py", line 133, in parse
    request_line = yield from parse_line(read_line)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/test/.venv/lib/python3.12/site-packages/websockets/http11.py", line 379, in parse_line
    line = yield from read_line(MAX_LINE_LENGTH)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/test/.venv/lib/python3.12/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/user/test/.venv/lib/python3.12/site-packages/websockets/asyncio/server.py", line 358, in conn_handler
    await connection.handshake(
  File "/home/user/test/.venv/lib/python3.12/site-packages/websockets/asyncio/server.py", line 209, in handshake
    raise self.protocol.handshake_exc
  File "/home/user/test/.venv/lib/python3.12/site-packages/websockets/server.py", line 561, in parse
    request = yield from Request.parse(
              ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/test/.venv/lib/python3.12/site-packages/websockets/http11.py", line 135, in parse
    raise EOFError("connection closed while reading HTTP request line") from exc
EOFError: connection closed while reading HTTP request line

I can reproduce this by having a server listening and with this script as client:

import socket

# Create a socket connection to your WebSocket server
host = 'localhost'  # or the actual host
port = 8000         # or the actual port

sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)

try:
    # Connect to the server
    sock.connect((host, port))
    
    # Immediately close the connection without sending any data
    sock.shutdown(socket.SHUT_RDWR)
    sock.close()

except Exception as e:
    print(f"Error: {e}")

[stalkerg]

I found one workaround: before return response form process_response you should do connection.logger.setLevel(logging.CRITICAL) because it's usually needed for health check or metrics it's fine to do it, we can catch any anomalies outside.

[aaugustin]

In the legacy implementation, when process_request returned a response, nothing was logged.

[aaugustin]

The problem happens because:

1. the Sans-I/O layer unconditionally sets protocol.handshake_exc , when the response status code isn't 101, including when that response is returned normally by process_request or process_response;
2. the asyncio layer raises that exception and logs it.

[aaugustin]

The current code relies on the fact that these four conditions are either all true or all false:

• opening handshake completes successfully
• response contains a 101 status code
• connection.protocol.handshake_exc is None
• connection.handshake() returns without an exception

Either we break that invariant, or we had a dedicated exception type for "process_request/response returned this response" (which the legacy implementation had).

[aaugustin]

I'll try to separate the first two conditions from the last two conditions. Then process_request/response can return a non-101 response without an exception.

[aaugustin]

98f236f paved that way.