Async::HTTP::Internet yielding blank Response

[zarqman]

Seeing an issue where this block yields a Response with all nil values:

Async::HTTP::Internet.post(metrics_url, headers:, body:) do |response|
  pp st: response.status, hdr: response.headers, bdy: response.body
  # => {st: nil, hdr: nil, bdy: nil}
end

The POST is being sent every 60 seconds, with the interval managed by a separate task and an Async::Notification to the http task. As such, it's a nearly perfect 60 second interval every time. The server runs nginx (as a proxy) and connections are using h2.

The empty Response reliably happens every 61 minutes. So, it works fine 61 times and then fails on the 62nd time. Then works for another 61, and fails on the 62nd again.

When the client yields the empty Response, the nginx logs still show the request and the normal, expected 204 response. The backend behind nginx correctly shows the post'd data from the request as well. So, it appears to be an issue on the client, or perhaps something between the client and nginx.

It feels like a race condition in combination with a maximum h2 session length, but I'm not sure a max session timeout even exists, so that could be way off. Thoughts on what this might be or how to debug it further?

async-http 0.87.0
async-pool 0.10.3
async 2.23.1
ruby 3.3.6
nginx 1.27.3

[ioquatix]

Thanks for your report, this is surprising. I will investigate the issue.

[ioquatix]

Are you able to capture logs using CONSOLE_LEVEL=debug?

[zarqman]

Thanks for looking into this. Here they are.

I don't see much except that the connection is recognized by as non-reusable by async-pool. Perhaps you'll notice something I don't though.

FWIW, also tried with the client locked to http/1.1 to see what would happen. No errors in that case, so this might be specific to h2 somehow.

Logs

  0.0s    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x6cfc] [pid=96255] [2025-03-17 09:14:01 -0600]
               | No available resources, allocating new one...
  0.0s    debug: Async::HTTP::Client [oid=0x6d10] [ec=0x6cfc] [pid=96255] [2025-03-17 09:14:01 -0600]
               | Making connection to #<Async::HTTP::Endpoint https://metrics-host/api/v1/import/prometheus {}>
 0.17s    debug: Async::HTTP::Protocol::HTTPS [oid=0x6d24] [ec=0x6cfc] [pid=96255] [2025-03-17 09:14:01 -0600]
               | Negotiating protocol "h2"...
 0.27s    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x6cfc] [pid=96255] [2025-03-17 09:14:02 -0600]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{:st=>204}

59.89s    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x6d4c] [pid=96255] [2025-03-17 09:15:01 -0600]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{:st=>204}

[...]

   59m    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x71e8] [pid=96255] [2025-03-17 10:14:01 -0600]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{:st=>204}

    1h    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x71fc] [pid=96255] [2025-03-17 10:15:01 -0600]
               | Retire #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{:st=>nil}
Error sending to metrics-host (id: 1742228101638, attempt=1, retry_in=0.5): #<App::ServerError: Server error: status=, body=, hdr=>
    1h    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x71fc] [pid=96255] [2025-03-17 10:15:02 -0600]
               | No available resources, allocating new one...
    1h    debug: Async::HTTP::Client [oid=0x6d10] [ec=0x71fc] [pid=96255] [2025-03-17 10:15:02 -0600]
               | Making connection to #<Async::HTTP::Endpoint https://metrics-host/api/v1/import/prometheus {}>
    1h    debug: Async::HTTP::Protocol::HTTPS [oid=0x6d24] [ec=0x71fc] [pid=96255] [2025-03-17 10:15:02 -0600]
               | Negotiating protocol "h2"...
    1h    debug: Async::Pool::Controller [oid=0x6ce8] [ec=0x71fc] [pid=96255] [2025-03-17 10:15:02 -0600]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{:st=>204}