dom96 / jester

A sinatra-like web framework for Nim.
MIT License
1.56k stars 120 forks source link

Jester crashes when async sleeping #296

Closed ajusa closed 2 years ago

ajusa commented 2 years ago

As described in the title. Here is the minimized code:

import jester, asyncdispatch, random

routes:
  get "/":
    await sleepAsync(rand(2000))
    resp "hi"

and here is the stacktrace

main.nim(3)              main
jester.nim(498)          serve
httpbeast.nim(540)       run
httpbeast.nim(371)       eventLoop
httpbeast.nim(227)       processEvents
asyncdispatch.nim(1653)  poll
asyncdispatch.nim(1394)  runOnce
asyncdispatch.nim(234)   processPendingCallbacks
asyncmacro.nim(38)       handleRequestSlowNimAsyncContinue
[[reraised from:
main.nim(3)              main
jester.nim(498)          serve
httpbeast.nim(540)       run
httpbeast.nim(371)       eventLoop
httpbeast.nim(227)       processEvents
asyncdispatch.nim(1653)  poll
asyncdispatch.nim(1394)  runOnce
asyncdispatch.nim(234)   processPendingCallbacks
asyncfutures.nim(262)    :anonymous
httpbeast.nim(287)       :anonymous
httpbeast.nim(148)       onRequestFutureComplete
]]
Error: unhandled exception: Async procedure (handleRequestSlow) yielded `nil`, are you await'ing a `nil` Future? [AssertionDefect]
Nim Compiler Version 1.6.4 [Linux: amd64]
Compiled at 2022-02-09
Copyright (c) 2006-2021 by Andreas Rumpf
Fedora 35

Error goes away after disabling assertions with seemingly no side effects, though that's basically a hack. Note that this fails non-deterministically - I've been testing it with wrk, though in my non-minimized code it fails after a couple of requests from a normal web browser.

wrk -c 100 -t 4 -d 10 http://localhost:5000/

I've tested this exact code with Prologue and it didn't have any issues, though it did have me annotate the callback proc with .gcsafe. Not sure if that rules out httpbeast completely (as Prologue uses a fork).

The non-minimized code isn't actually doing an async sleep with random wait, it's doing a web request. I thought the web request was causing the issue until I realized I could replicate it with a similar wait time by using sleep. Hopefully this is enough information for at least someone else to reproduce!

ajusa commented 2 years ago

Forgot to add this: command to compile is nim r -d:ssl main.nim. I also tried patching Jester to force asynchttpserver, which doesn't seem to have this problem as far as I can tell.

dom96 commented 2 years ago

I also tried patching Jester to force asynchttpserver, which doesn't seem to have this problem as far as I can tell.

For future reference you can just use -d:useStdlib to make Jester use asynchttpserver

dom96 commented 2 years ago

Found the bug, statusContent doesn't return a future in its except branch: https://github.com/dom96/jester/blob/master/jester.nim#L124.

When reproducing I can see a few of these errors as well:

ERROR Could not send response: Protocol not available
ERROR Could not send response: Protocol not available

So the send is failing for some reason too.

dom96 commented 2 years ago

Looks like this bug was introduced in https://github.com/dom96/jester/pull/236 (not blaming anyone, just posting for reference, also important to make sure I don't break what that PR fixed).

dom96 commented 2 years ago

So this was actually two bugs. Thank you so much for reporting them! It was fun hunting them down :)

Btw prologue will have the same issue, I checked httpx's code and it has the same bug. So the fact that prologue silently worked seems like a bug in its implementation (it is likely swallowing errors).