Some requests not finishing with 0.77.0?

Question

Some requests not finishing with 0.77.0?

travisbell opened this issue 6 months ago · 20 comments

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!

Answer 1 · 2024-09-20T20:33:18.000Z

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

Answer 2 · 2024-10-01T03:03:20.000Z

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.

Answer 3 · 2024-10-01T09:36:13.000Z

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.

Answer 4 · 2024-10-01T10:53:56.000Z

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

Answer 5 · 2024-10-01T16:15:22.000Z

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.

Answer 6 · 2024-10-01T21:24:56.000Z

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

Answer 7 · 2024-10-02T12:12:49.000Z

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

Answer 8 · 2024-10-03T01:55:45.000Z

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?

Answer 9 · 2024-10-03T02:10:26.000Z

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.

Answer 10 · 2024-10-03T02:20:22.000Z

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

Answer 11 · 2024-10-03T20:59:59.000Z

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.)

Answer 12 · 2024-10-03T21:07:45.000Z

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

Answer 13 · 2024-10-03T21:13:57.000Z

I can confirm that even without my custom stuff (leaving async where it is in upstream io-endpoint), yield socket, address never returns (no log output happens.)

Answer 14 · 2024-10-11T22:13:30.000Z

Thanks for your reproduction, I can see the issue.

Answer 15 · 2024-10-11T22:36:50.000Z

I see, so the actual issue here is that Rails will read the body, without exhausting it: https://github.com/rails/rails/blob/f86f52acab6f94c79d175f5567013b9512d50886/actionpack/lib/action_dispatch/http/request.rb#L470-L480

Your proposed solutions are reasonable, and I think:

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.

is the best option, simply because this is Rack specific semantics. In other words, it's entirely possible for the underlying request to lie about content length... in theory, it should call input.read and just read everything, even if the content length is known.

We should probably use body#empty? as #read may block. body#empty? also has the right semantics - it returns true if #read will definitely return nil.

The root cause of this problem is how Rack specifies the input stream.

In Rack 2, it was prohibited to call close on the input stream: https://github.com/rack/rack/blob/2-2-stable/SPEC.rdoc#label-The+Input+Stream as it was expected the server would close the input stream "when the request was done" (which is basically unknowable in general).
In Rack 3, I updated the semantics a bit: https://github.com/rack/rack/blob/main/SPEC.rdoc#label-The+Input+Stream

Answer 16 · 2024-10-11T22:44:56.000Z

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.

For a little more clarification on my thinking, I see this as acceptable behaviour. The underlying connection state machine is independent of the application code correctly processing the input and output. In other words, the expectation is, the input is completely read. input.read(content_length) actually doesn't guarantee that. However, I also accept that it's causing a failure condition, but that's actually because the application layer (including protocol-rack) is not following the semantics of async-http by invoking #read until it returns nil OR invoking #close/#discard etc.

Answer 17 · 2024-10-11T22:49:54.000Z

In addition, eventually it might like to think about whether we want to change Rails or Rack to clarify this behaviour. IOW, if content_length is less than the actual body length for some reason, this will still hang. The only way we could deal with it is by forcefully closing rack.input if it was read from but not completely, after the rack middleware returns a response - and that's also kind of ugly. Once Rails drops support for Rack 2, we could consider ensuring that it invokes #close, or perhaps:

content = input.read(content_length)
# discard all remaining input:
input.read

Answer 18 · 2024-10-11T22:53:08.000Z

Wicked, thanks for the extra details @ioquatix. FWIW, since I've been seeing this problem with Sinatra too, I'd imagine trying to fix this in Rack (or just async-http) makes the most sense.

Answer 19 · 2024-10-11T22:54:08.000Z

I've released protocol-rack v0.10.1 with the fix, can you please try it and let me know how it goes? Thanks :)

Answer 20 · 2024-10-11T22:59:41.000Z

By the way, let me state how grateful I am for your detailed bug reports, support and patience.