Non-websocket responses created with process_response log "connection rejected (200 OK)"

[sminnee]

Scenario

I have a /healthz endpoint on my websocket server, used as a kubernetes health check.

What I expected to happen

If the websocket connection upgrade headers aren't present, then no "connection rejection" message needs be send.

Connection: upgrade
Upgrade: websocket

Relevant code

This code from ServerProtocol.send_response() seems to be the source.

        if response.status_code == 101:
            assert self.state is CONNECTING
            self.state = OPEN
            self.logger.info("connection open")

        else:
            self.logger.info(
                "connection rejected (%d %s)",
                response.status_code,
                response.reason_phrase,
            )

            self.send_eof()
            self.parser = self.discard()
            next(self.parser)  # start coroutine

I expect we could change the second block to only send a message if a boolean websocket_requested parameter was true. That would mean change the method signature, which is a bit of a pain.

Alternatively, we could avoid showing a rejection message for any 200-399 response.

Should I raise a PR?

[sminnee]

I'm happy to do a PR for this; is there a particular approach you'd prefer me to take with it?

[aaugustin]

I've been thinking about this and still don't have a good plan to achieve what you'd like that also works for everyone else :-(

Logging at the INFO level when websockets opens or rejects the WebSocket connection is uncontroversial. The question here is about what to log when a user-provided process_request or process_response callback sends a HTTP response.

Currently websockets logs a line at the INFO level for any WebSocket handshake or HTTP request that receives a WebSocket handshake or HTTP response without error, regardless of where the response comes from. That's a consistent behavior.

I understand that you don't feel the need to log requests to your health check endpoint. However, I can also imagine someone being confused by not getting logs for requests to their health check endpoint. Furthermore, I don't think it's possible to draw a line between "process_request sent an HTTP response; no need to log" and "process_request intended to continue the WebSocket handshake but that didn't go as planned; must log to make debugging possible". In both cases we're just calling the user-provided process_request and getting a HTTP response back; we cannot guess what the user's intent was and if things went according to that intent — and logs are useful only when things don't go according to the user's intent — no one looks at their logs when everything works as intended!

If we stick to logging one line for each request/response, then we can use more generic wording to avoid logging "connection rejected" for successful health checks. Ideally we find a wording that covers all these cases and rely on the HTTP code to help the user figure out what's happening:

• websockets fails to open the WebSocket connection (the current wording)
• a user-provided process_request or process_response sent a HTTP response that is considered successful (your case)
• a user-provided process_request or process_response sent a HTTP response that is considered a failure (also possible)

[sminnee]

Furthermore, I don't think it's possible to draw a line between "process_request sent an HTTP response; no need to log" and "process_request intended to continue the WebSocket handshake but that didn't go as planned; must log to make debugging possible".

If the response is considered a failure, why wouldn't it be a 4xx response?

If we stick to logging one line for each request/response, then we can use more generic wording to avoid logging "connection rejected" for successful health checks.

It could be something like:

        else:
            log_message = "connection rejected (%s %s)" if response.status_code > 399 else "non-websocket response (%s %s)"
            self.logger.info(
                log_message,
                response.status_code,
                response.reason_phrase,
            )

Related: we could potentially tidy up this log to be more like an access log, with timestamp, path, IP, status_code, and an indication of whether a websocket connection was initiated.