LoggerAdapter: using request_headers in DEBUG-level logs raises: AttributeError("'WebSocketServerProtocol' object has no attribute 'request_headers'")

[rayrapetyan]

When LoggerAdapter is utilized and DEBUG-level logs are activated, it results in the generation of an AttributeError exception.

Similar to https://github.com/python-websockets/websockets/issues/1398, but on the server side.

Seems this issue is caused by this line: https://github.com/python-websockets/websockets/blob/33b20e11e86f8490770185c78ed39adab8db4560/src/websockets/legacy/protocol.py#L256 (request_headers init happens few lines below).

Possible fix would be putting request_headers initialization above the:

self.logger.debug("= connection is CONNECTING")

line. The only aspect that confuses me is how such an error could go unnoticed for a period of 2 years (https://github.com/python-websockets/websockets/blame/33b20e11e86f8490770185c78ed39adab8db4560/src/websockets/legacy/protocol.py#L256). I might be overlooking something, but I can't identify what it might be. This might be due to the fact that this error does not produce any output in the server logs; the client simply receives a connection reset error.

[aaugustin]

The documentation for request_headers says:

The following attributes are available after the opening handshake, once the WebSocket connection is open: ...

You're trying to use the attribute before it's available, which is why the AttributeError happens (in your code, not in websockets).

---

request_headers init happens few lines below

That's incorrect. It's only a type declaration, not an initiatialization. The attribute doesn't exist yet.

---

I can see how it's an easy mistake to make and a relatively hard one to debug.

Unfortunately I don't see an obvious way to fix it.

Perhaps the best fix is to remove that logging call entirely. I think it's the only logging call happening before the opening handshake (to be verified).

[aaugustin]

This can happen in other places, notably here if the handshake request or response received from the other side isn't a valid HTTP message.

One possible solution would be to initialize request_headers with an empty Headers() instance (and the same for other similar attributes). Currently, all these attributes are conceptually immutable; I can see a risk of causing more confusion by returning "wrong" values (like path = "/").

This requires further investigation.

[rayrapetyan]

...or LoggerAdapter documentation can be updated to include:

if hasattr(websocket, "request_headers"):
   ...

check (that's what I've done as a workaround).

[aaugustin]

Yes, that's the correct implementation in the current state of the library.

I'm not super excited by that option, though, because it puts the burden on every user of the library :-(

[rayrapetyan]

The other issue was swallowing of exceptions (maybe similar to https://github.com/python-websockets/websockets/issues/1415 ?). Clients just get connection reset on their side with no output in the server logs. I believe this should be also fixed...