Some requests not finishing with 0.77.0?

[travisbell]

Hello,

Upon upgrading to 0.77.0, I am seeing some 303 requests that don't seem to finish (or close). I can't quite tell what's happening other than Falcon is just not letting the request complete. The request just sits there indefinitely. Not 100% of these requests do this, but in my testing a good 90% of them do. I might be lucky if 1/10 requests get the full response sent to the browser.

Downgrading to 0.76.0 fixes the issue.

I might be seeing this on other responses but I am for sure seeing this on requests that return a 303 on a POST request, like say, redirecting after a login. This is in a Sinatra app, by the way. The response bodies for these requests are 0 bytes, they just contain a location header. They are also all HTTP 1.1 requests.

Hope that's enough to help troubleshoot this. I can try to get more debug info if required.

Thanks!

[ioquatix]

Yeah I’m also seeing some bugs, I will investigate today.

[korbin]

Unsure if related, but possibly/probably:

3a5c1cc

After a few hours of debugging, I've found that in a Rails application, POST requests with specified Content-Length headers (not reading to EOF) will cause Fibers to linger/leak until the application closes.

As far as I can tell in our Rails application, nothing will actually call Finishable#read to EOF or explicitly close the request body (pretty sure this is the default behavior.)

In the above commit, I test @body.empty? in Finishable to establish an additional close condition. There's probably a cleaner way to do this.

[ioquatix]

Are you able to update to the latest versions of async-http, protocol-http*, io-stream and any dependencies, it should fix all the issues.

[ioquatix]

(Also, I'll add your reported failure as a test case to async-http so we won't have any regressions).

[korbin]

Are you able to update to the latest versions of async-http, protocol-http*, io-stream and any dependencies, it should fix all the issues.

I am seeing the above issue with:

    async (2.17.0)
    async-http (0.79.0)
    async-pool (0.8.1)
    io-endpoint (0.13.1)
    io-event (1.6.5)
    io-stream (0.4.1)
    protocol-http (0.37.0)
    protocol-http1 (0.27.0)
    protocol-http2 (0.19.2)
    protocol-rack (0.10.0)

I believe these are all the latest versions.

[ioquatix]

Okay, thanks for the report, I'll investigate it today.

[ioquatix]

I have made another round of bug fixes and performance improvements. However, I have not investigated the above issue yet. Sorry.

[ioquatix]

I'm trying to reproduce the issue here: #185

So far, I'm not having a lot of luck:

Connecting to server: Async::HTTP::Protocol::HTTP10
Finishable#initialize: #<Protocol::HTTP1::Body::Fixed length=13 remaining=13 state=open>
Finishable#read: "Hello, World!"
Finishable#read: nil
Finishable#close: nil
Got response: #<Async::HTTP::Protocol::HTTP1::Response:0xc30 status=200>
Connecting to server: Async::HTTP::Protocol::HTTP11
Finishable#initialize: #<Protocol::HTTP1::Body::Fixed length=13 remaining=13 state=open>
Finishable#read: "Hello, World!"
Finishable#read: nil
Finishable#close: nil
Got response: #<Async::HTTP::Protocol::HTTP1::Response:0xc58 status=200>
Connecting to server: Async::HTTP::Protocol::HTTP2
Got response: #<Async::HTTP::Protocol::HTTP2::Response:0xc80 status=200>

@korbin do you have a reproduction that I can use?

[ioquatix]

I also made this change fairly recently: socketry/protocol-rack@d34fabd

Can you confirm you are using the latest version of protocol-rack?

I wonder if we need to make the same change here: https://github.com/socketry/protocol-http/blob/8244dbf54d05619713140a113b76b74e49c680fd/lib/protocol/http/body/stream.rb#L298.

[ioquatix]

Maybe socketry/protocol-http#71 is sufficient to fix this issue. @korbin are you able to test it?

[korbin]

I can confirm this issue is still happening (both with and without the protocol-http branch) and have created a test repo for you, if you clone and execute:

bundle exec falcon host falcon.rb
curl -X POST http://127.0.0.1:3000/ -H 'Content-Type: application/json' --data '{}'

You should see that the log output I've added in falcon.rb indicates that the call never completes. I've removed the async block wrapping the handler for performance reasons, which I believe was masking the issue and why it's a little unobvious to reproduce. I'm of the opinion that the behavior I'm aiming for here should work and this execution should properly complete without the need for fibers to yield first.

If you uncomment my Finishable patch in falcon.rb, the one read will properly set the @closed.value when the underlying streaming body is read completely.

If we look at the underlying Rails handlers:

• raw_post calls read_body_stream

• read_body_stream calls body_stream.read(length)

  • which is a Finishable wrapping a Protocol::HTTP1::Body::Fixed created and assigned to the request.body (via Rack) in async-http

• Finishable#read delegates to Protocol::HTTP1::Body::Fixed#read

  • Protocol::HTTP1::Body::Fixed#read does actually call @connection.receive_end_stream! when @remaining == 0, but the outer Finishable never has any reason to know that his underlying @body is closed.

The issue is that if I specify a content length (which Rails does), the underlying Protocol::HTTP::Body::Stream never does an "extra" read to push past the content and into EOF (closing the body):

https://github.com/socketry/protocol-http/blob/main/lib/protocol/http/body/stream.rb#L58-L61

https://github.com/socketry/protocol-rack/blob/c65e544b9f206bdafc3b4ff6d69282cd3b05e261/lib/protocol/rack/input.rb#L88-L93

--

Possible fixes:

• My above patch - Finishable#read checks to see if the underlying body is empty? after reading and updates his internal value accordingly at read-time.
• Protocol::Rack::Input#read_next issues an extra @body.read (or ideally something like a @body.peek or @body.empty?) and then explicitly calls @body.close after reading.
• Protocol::HTTP::Body::Stream always reads an extra time, even if a length is specified (probably not correct.)

[ioquatix]

Thanks this looks really helpful. I'll work on it today.