socketry
Async::HTTP::Internet yielding blank Response
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
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}
Hey, im observed a similar problem when playing with https://github.com/socketry/async-http-faraday. I was also able to reproduce it with plain async-http. It happens randomly and i was not able to correlate it to anything.
Happens like 10 times in 18 minutes
ruby 3.4.3 (2025-04-14 revision d0b7e5b6a0) +PRISM [arm64-darwin24]
async (2.27.2)
async-http (0.90.1)
async-pool (0.11.0)
io-endpoint (0.15.2)
io-stream (0.10.0)
protocol-hpack (1.5.1)
protocol-http (0.51.0)
protocol-http1 (0.34.1)
protocol-http2 (0.22.1)
Sync do
$internet = Async::HTTP::Internet.new
loop do
response = $internet.get('...')
pp st: response.status, hdr: response.headers, bdy: response.body
end
end
Logs:
Details
{st: 200,
hdr:
#<Protocol::HTTP::Headers [["server", "nginx"], ["date", "Thu, 07 Aug 2025 10:59:09 GMT"], ["content-type", "application/json; charset=utf-8"], ["cache-control", "max-age=10800, public"], ["x-whom", "fs"], ["x-cache-status", "HIT"], ["x-lb", "nginx-lb-with-sg-internal-2"], ["x-clustername", "web4-production"], ["reporting-endpoints", "csp-default=\"xxx\""]]>,
bdy: #<Async::HTTP::Protocol::HTTP2::Input 1 chunks written, closing>}
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:09 +0200]
| Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{st: 200,
hdr:
#<Protocol::HTTP::Headers [["server", "nginx"], ["date", "Thu, 07 Aug 2025 10:59:09 GMT"], ["content-type", "application/json; charset=utf-8"], ["cache-control", "max-age=10800, public"], ["x-whom", "fs"], ["x-cache-status", "HIT"], ["x-lb", "nginx-lb-with-sg-internal-2"], ["x-clustername", "web4-production"], ["reporting-endpoints", "csp-default=\"xxx\""]]>,
bdy: #<Async::HTTP::Protocol::HTTP2::Input 1 chunks written, closing>}
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:09 +0200]
| Retire #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{st: nil, hdr: nil, bdy: nil}
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:09 +0200]
| No available resources, allocating new one...
8m debug: Async::HTTP::Client [oid=0x90f0] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:09 +0200]
| Making connection to #<Async::HTTP::Endpoint xxx {}>
8m debug: Async::HTTP::Protocol::HTTPS [oid=0x3f10] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:10 +0200]
| Negotiating protocol "h2"...
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:10 +0200]
| Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{st: 200,
hdr:
#<Protocol::HTTP::Headers [["server", "nginx"], ["date", "Thu, 07 Aug 2025 10:59:10 GMT"], ["content-type", "application/json; charset=utf-8"], ["cache-control", "max-age=10800, public"], ["x-whom", "fs], ["x-cache-status", "HIT"], ["x-lb", "nginx-lb-with-sg-internal-0"], ["x-clustername", "web4-production"], ["reporting-endpoints", "csp-default=\"xxx\""]]>,
bdy: #<Async::HTTP::Protocol::HTTP2::Input 1 chunks written, closing>}
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:10 +0200]
| Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
{st: 200,
hdr:
#<Protocol::HTTP::Headers [["server", "nginx"], ["date", "Thu, 07 Aug 2025 10:59:10 GMT"], ["content-type", "application/json; charset=utf-8"], ["cache-control", "max-age=10800, public"], ["x-whom", "fs"], ["x-cache-status", "HIT"], ["x-lb", "nginx-lb-with-sg-internal-0"], ["x-clustername", "web4-production"], ["reporting-endpoints", "csp-default=\"xxx\""]]>,
bdy: #<Async::HTTP::Protocol::HTTP2::Input 1 chunks written, closing>}
8m debug: Async::Pool::Controller [oid=0x90e8] [ec=0x83e8] [pid=57821] [2025-08-07 12:59:10 +0200]
| Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
</p>
</details>
