Websockets requests always show 500 error in server logs

[stevenfontanella]

Hello, I noticed that when any websockets requests are made to Yesod, the logs show a 500 error. I was curious if this means I'm doing something wrong in my setup, or if this is expected behavior. I created this minimal example which can be queried either using websockets or HTTP. When I access the page with my browser, I get the expected log:

127.0.0.1 - - [28/Mar/2022:18:52:45 -0700] "GET / HTTP/1.1" 200 13 "" "<user agent>"

but when I make a websockets request using wscat -c 'localhost:3000', the log shows a 500 error:

127.0.0.1 - - [28/Mar/2022:18:58:48 -0700] "GET / HTTP/1.1" 500 - "" ""

Beyond that, everything works as expected so I'm not sure if there's a real issue here. But maybe if a 500 error is expected for websockets requests it can be documented somewhere? I wasn't able to find any existing documentation on this.

I am using stack with resolver lts-18.27, GHC 8.10.7, yesod-core 1.6.21.0 and yesod-websockets 0.3.0.3.

[snoyberg]

This isn't expected behavior, at least by me. But honestly, I haven't written a websockets server in a while, so I'm not in a position to investigate this. If there's a bug somewhere in the stack I'd be happy to review a PR to fix it.

[stevenfontanella]

Hi Michael, thanks for confirming! I found the source of the behavior but I don't see a clear fix. I can see that the websockets code calls sendRawResponseNoConduit which constructs a WAI ResponseRaw with a fallback that returns 500 error. Yesod gets the status through responseStatus in WAI, which in the case of ResponseRaw always returns the status of the fallback, 500 in our case. (I confirmed this by changing WAI to return a hardcoded status and saw it get logged in Yesod for websockets requests, and also by changing the fallback response code)

I don't see an easy way to get a meaningful response code from a ResponseRaw; it only has a function to call and a fallback. A workaround I see for websockets is to provide a fallback with status code 200 instead of 500, but of course this would always log the websocket request as successful which may not be the case. I'm inclined to say that logging 200 every time is a bit less confusing than 500 every time, but maybe there's a better way.

[snoyberg]

I don't see a call to responseStatus in the Yesod codebase. Are you sure it's Yesod generating that versus Warp? Are you able to reproduce without Yesod in the mix?

[stevenfontanella]

Apologies that it has been a while. Yes, Yesod is generating the 500 log, since it is providing the fallback with status 500. If you change the status to something else, you will see it reflected in the logs.

Since the status of the fallback always gets read in the websockets path, my suggestion is to change websockets to use a fallback that always returns 200, that way the log doesn't report errors that aren't really there.

On the other hand, I'm not sure whether a websockets request can really fail in a way that the failing fallback would be useful. i.e. I wouldn't want it to happen that a request fails and gives a 200 status. I will try to see if this is a possibility and let you know.