Randomly amp.http.client.har.timings.complete is missing

[duronrulez]

When using RecordHarAttributes sometimes after a response completes the attribute amp.http.client.har.timings.complete is missing.

I cannot reproduce this consistently. It seems to be random.

This is what i use:

$builder = (new HttpClientBuilder)
            ->interceptNetwork(new DecompressResponse());

$client = $builder->build();

$promise = call(function () use ($client, $url) {
    $request = new Request($url);
    $request->addEventListener(new RecordHarAttributes());

    $response = yield $client->request($request);
    yield $response->getBody()->buffer();

    ///   Symfony\Component\Debug\Exception\FatalThrowableError  : The requested attribute 'amp.http.client.har.timings.complete' does not exist
     $responseTime = $response->getOriginalRequest()->getAttribute(HarAttributes::TIME_COMPLETE) - $response->getOriginalRequest()->getAttribute(HarAttributes::TIME_START);

});
$responses = wait(all([$promise]));

It is possible that its related to redirects, some of the domains i try do have redirects, but it still happens randomly

[kelunik]

You need to await the trailers promise before accessing the attribute. However, you're using an internal API without BC guarantees, so be careful. Please use your own event listener or use the LogHttpArchive interceptor directly.

[duronrulez]

ahhh, that makes perfect sense i see it in the LogHttpArchive now. I knew i was missing something. Thanks!

[duronrulez]

I seem to have celebrated prematurely. Using the example from the docs https://github.com/amphp/http-client/blob/master/examples/basic/6-customization.php (a bit adapted) i sometime get empty har files.

Loop::run(static function () {
    try {
        $client = (new HttpClientBuilder)
            ->intercept(new LogHttpArchive('/tmp/1.txt'))
            ->followRedirects(2)
            ->build();

            /** @var Response $response */
            $response = yield $client->request(new Request(XXX));

        }
     catch (\Exception $error) {
        echo $error->getMessage();
    }
});

The code is run from a php cli via artisan command, the handle body contains only the above.

Going to LogHttpArchive and adding a message to this silenced exception:

try {
    yield $response->getTrailers();
} catch (\Throwable $e) {
    echo $e->getMessage();
    // ignore, still log the remaining response times
}

reveals the following: The operation was cancelled or Socket disconnected prior to response completion no visible distinction on which will appear when.

[kelunik]

Do you consume the response body every time? Do the requests use HTTP/1.1 or HTTP/2?

[duronrulez]

I do not consume the response body in this case, the requests are HTTP/1.1 I did a few example where i did consume the body, but again randomly it was resulting in the same issue.

I assume it adds a bit of time due to the body resolution taking time itself which gives the trailers more time to resolve. (i hope that makes sense)

[kelunik]

If you don't consume the body and the body stream is GCed, the request is automatically aborted.

If that also happens if the body is consumed, I'll have to look into it.

[duronrulez]

Ok, let me give it a go with a few thousand requests with body consumption and will report if it happens again.

[duronrulez]

The combination of the body consumption yield $response->getBody()->buffer(); and a custom har interceptor in the client build process (instead of registering manually on each request) seems to work fine.

Again thanks for the help

[duronrulez]

There is something weird going on still, but this is probably due to something i do rather than the http client.

The basic example (from above) works, but when i apply the changes to my project i start getting socket disconnections and operation cancelled again. Probably my interceptor has a bug somewhere.

[kelunik]

If you share the code, I might be able to have a look.

[duronrulez]

Sure, this is my interceptor (adapted from the LogHttpArchive to include only what i need:

use Amp\CancellationToken;
use Amp\Http\Client\ApplicationInterceptor;
use Amp\Http\Client\DelegateHttpClient;
use Amp\Http\Client\EventListener\RecordHarAttributes;
use Amp\Http\Client\Request;
use Amp\Http\Client\Response;
use Amp\Promise;
use function Amp\call;
use function Amp\Promise\rethrow;

final class RecordHarAttributesApplication implements ApplicationInterceptor
{
    private $eventListener;

    /** @var \Throwable|null */
    private $error;

    public function __construct()
    {
        $this->eventListener = new RecordHarAttributes();
    }

    public function request(
        Request $request,
        CancellationToken $cancellation,
        DelegateHttpClient $httpClient
    ): Promise {
        return call(
            function () use ($request, $cancellation, $httpClient) {
                if ($this->error) {
                    throw $this->error;
                }

                $this->ensureEventListenerIsRegistered($request);

                /** @var Response $response */
                $response = yield $httpClient->request($request, $cancellation);

                rethrow(call(function () use ($response) {
                    try {
                        yield $response->getTrailers();
                    } catch (\Throwable $e) {
                        // ignore, still log the remaining response times
                    }
                }));

                return $response;
            }
        );
    }

    private function ensureEventListenerIsRegistered(Request $request): void
    {
        foreach ($request->getEventListeners() as $eventListener) {
            if ($eventListener instanceof RecordHarAttributes) {
                return; // user added it manually
            }
        }

        $request->addEventListener($this->eventListener);
    }
}

And here is a simple use case (it doesnt work unless you yield the trailers in the main app too):

Loop::run(
            static function () {
                $builder = (new HttpClientBuilder)
->followRedirects(2)
->intercept(new SetRequestTimeout(5000, 5000, 5000))
->interceptNetwork(new DecompressResponse())
->intercept(new RecordHarAttributesApplication());
                $client = $builder->build();

                $url = "XXX";

                try {
                        /**
                         * @var $response Response
                         */
                        $request = new Request($url);
                        $request->setBodySizeLimit(1024*1024*2);

                        $response = yield $client->request($request);

                        // trailers do not complete unless you get the body too
                        yield $response->getBody()->buffer();
                        // seems i must yield trailers here too?
                        yield $response->getTrailers();

                        $responseTime = $response->getRequest()->getAttribute(HarAttributes::TIME_COMPLETE) - $response->getRequest()->getAttribute(
                                HarAttributes::TIME_START
                            );
                        echo $responseTime;
                }
            }
        );

This produces various errors (from above comments) but in the end, here is the uncaught one (unless you have the yield $response->getTrailers(); in the main app too as i've given the example) The requested attribute 'amp.http.client.har.timings.complete' does not exist

[kelunik]

This is expected, because the body stream is completed first, then EventListener::completeReceivingResponse() is called and only after all those operations completed, the trailers promise is resolved. So RecordHarAttributes sets the attribute after the body is complete and it won't be reliably available if you don't await the trailers. While trailers aren't used much, they also act as a "response complete" placeholder here.

[duronrulez]

hmm, ok im a bit confused i guess. What is the reason for resolving trailers in the: RecordHarAttributesApplication::request if i have to resolve them again later in the main app?