Receiving the response headers for ** closed early

[PNixx]

In high load http send data to server I see errors in log:

[2021-05-06T13:24:25.112194+03:00] Amp\Http\Client\SocketException: Receiving the response headers for 'https://cache.example.com/1515915625626368448-6093c3ad148e9.html.gz' failed, because the socket to 'cache.example.com' @ '???' closed early with 0 bytes received within 29557 milliseconds

But in nginx log I see 201 response code:

12.3.4.10 - [06/May/2021:13:23:55 +0300] "PUT /1515915625626368448-6093c3ad148e9.html.gz HTTP/1.1" 201 0 "-" "User Cacher 2.0" "-" 0.001

Response time 0.001 sec.

[kelunik]

Which event loop backend do you use? How many concurrent connections are high load?

[PNixx]

I use rabbit with Prefetch count = 30. All received messages uploading html cache to server. And I see similar error:

Amp\Http\Client\TimeoutException, Inactivity timeout exceeded, more than 5000 ms elapsed from last data received /project/vendor/amphp/http-client/src/Connection/Internal/Http2ConnectionProcessor.php:1767

But file is correctly upload to server. For now, I just ignore these errors to keep the code running. But this is very bad behavior.

[kelunik]

Please report what var_dump(get_class(Loop::get())) says. Did you try to write a smaller script doing something similar to reproduce the issue?

[PNixx]

Amp\\Loop\\UvDriver, but I see this error on NativeDriver and EvDriver

[PNixx]

Amp\Http\Client\TimeoutException, Inactivity timeout exceeded, more than 5000 ms elapsed from last data received Stack trace error:

[{"file":"/shared/vendor/amphp/amp/lib/Loop/UvDriver.php","line":108,"function":"Amp\\Http\\Client\\Connection\\Internal\\{closure}","class":"Amp\\Http\\Client\\Connection\\Internal\\Http2ConnectionProcessor","type":"->"},
{"function":"Amp\\Loop\\{closure}","class":"Amp\\Loop\\UvDriver","type":"->"},
{"file":"/shared/vendor/amphp/amp/lib/Loop/UvDriver.php","line":215,"function":"uv_run"},
{"file":"/shared/vendor/amphp/amp/lib/Loop/Driver.php","line":138,"function":"dispatch","class":"Amp\\Loop\\UvDriver","type":"->"},
{"file":"/shared/vendor/amphp/amp/lib/Loop/Driver.php","line":72,"function":"tick","class":"Amp\\Loop\\Driver","type":"->"},
{"file":"/shared/vendor/amphp/amp/lib/Loop.php","line":95,"function":"run","class":"Amp\\Loop\\Driver","type":"->"},
{"file":"/shared/vendor/project/core/src/Worker/WorkerTrait.php","line":102,"function":"run","class":"Amp\\Loop","type":"::"},
{"file":"/current/bin/server.php","line":12,"function":"onWorkerStarted","class":"Project\\Worker","type":"->"},
{"file":"/shared/vendor/amphp/cluster/src/Internal/cluster-runner.php","line":59,"args":["/current/bin/server.php"],"function":"require"},
{"file":"/shared/vendor/amphp/cluster/src/Internal/cluster-runner.php","line":60,"function":"Amp\\Cluster\\Internal\\{closure}"},
{"function":"Amp\\Cluster\\Internal\\{closure}"},
{"file":"/shared/vendor/amphp/amp/lib/Coroutine.php","line":67,"function":"current","class":"Generator","type":"->"},
{"file":"/shared/vendor/amphp/amp/lib/functions.php","line":96,"function":"__construct","class":"Amp\\Coroutine","type":"->"},
{"file":"/shared/vendor/amphp/parallel/lib/Context/Internal/process-runner.php","line":105,"function":"Amp\\call"},
{"file":"/shared/vendor/amphp/parallel/lib/Context/Internal/process-runner.php","line":123,"function":"Amp\\Parallel\\Context\\Internal\\{closure}"}]

[kelunik]

I'm confused. Is this a different setup? The original report says HTTP/1.1 in the nginx log, while the stack trace now points to HTTP/2.

[PNixx]

Yes, this is different endpoint. Current stack trace from web push request with endpoint https://fcm.googleapis.com/fcm/send/***. I catch a similar errors with different endpoint requests.

[kelunik]

I'm aware of issues with older Nginx instances not closing HTTP/2 connections correctly, which results in similar behavior, but I'm not aware of any such issues with HTTP/1.1. Without further information such as reproduction steps, it'll be hard to reproduce this issue, so I'm closing this until there's further information.

[xpader]

I saw this error everyday in logs:

Amp\Http\Client\SocketException: Receiving the response headers for 'https://api.example.com/xxx?access_token=xxx' failed, because the socket to 'api.example.com' @ '1.2.3.4:443' closed early with 0 bytes received within 0 milliseconds in /home/web/apps/t-task-wind/releases/94/vendor/amphp/http-client/src/Connection/Http1Connection.php:494
Stack trace:
#0 /home/web/apps/t-task-wind/releases/94/vendor/amphp/http-client/src/Connection/Http1Connection.php(235): Amp\Http\Client\Connection\Http1Connection->readResponse()^M
#1 [internal function]: Amp\Http\Client\Connection\Http1Connection->Amp\Http\Client\Connection\{closure}()
#2 /home/web/apps/t-task-wind/releases/94/vendor/amphp/amp/lib/Coroutine.php(118): Generator->send()
#3 /home/web/apps/t-task-wind/releases/94/vendor/amphp/amp/lib/Internal/Placeholder.php(46): Amp\Coroutine->Amp\{closure}()
#4 /home/web/apps/t-task-wind/releases/94/vendor/amphp/amp/lib/Coroutine.php(151): Amp\Coroutine->onResolve()

[xpader]

I think this is strange. The request to https://api.example.com we test in browser is always http2 connection, but the reported exception was from Http1Connection.

[kelunik]

@xpader In that case you'll need to debug why the connection isn't upgraded. Does it work with HTTP 1.1 with other clients?

[xpader]

@kelunik May be it cause I have use http proxy by http-client-tunnel, target host is http2, but proxy server is http1.1?