Middlewares executed in a wrong order

[mirfilip]

I'm using version 6.2.3 and frankkessler/guzzle-oauth2-middleware for Oauth2 client credentials flow, but that is not important here.

EDIT: I've edited the example to be easily reproducible and not have oauth2 related stuff.

$handler = HandlerStack::create();

$handler->push(Middleware::mapRequest(function(RequestInterface $request) use ($logger) {
    $logger->debug('Adding foo:bar headers');
    return $request->withHeader(
        'foo',
        'bar'
    );
}), 'add_headers');

$handler->push(Middleware::log(
    $logger,
    new MessageFormatter('[{ts}] - Request: {method} {uri}. Foo header value: {req_header_foo}'),
    LogLevel::DEBUG
), 'log_request_details');

$handler->push(Middleware::mapRequest(function (RequestInterface $r) use ($logger) {
    $logger->debug('### Request ###');
    return $r;
}), 'log_request_fact');

$handler->push(Middleware::log(
    $logger,
    new MessageFormatter('[{ts}] - Response: {code} "{res_body}". Errors: {error}'),
    LogLevel::DEBUG
), 'log_response');

$handler->push(Middleware::mapResponse(function(\Psr\Http\Message\ResponseInterface $response) use ($logger) {
    $newResponse = \GuzzleHttp\json_encode([
        'usedId' => 1,
        'id' => 1,
        'title' => 'This is a test',
    ], JSON_UNESCAPED_SLASHES);
    $newBody = \GuzzleHttp\Psr7\stream_for($newResponse);
    $logger->debug('Changed response body to: ' . $newResponse);

    return $response->withBody($newBody);
}), 'transform_body');

$client = new \GuzzleHttp\Client(
    [
        'handler' => $handler,
    ]
);

$response = $client->get('https://jsonplaceholder.typicode.com/posts/1');

Expected middlewares order:

1. add_headers
2. log_request_details
3. log_request_fact
4. log_response
5. transform_body

Actual order:

1. add_headers
2. log_request_fact
3. transform_body
4. log_response
5. log_request_details

Why is the order not correct?

[gregurco]

@mirfilip order is correct. You should understand the difference between logging directly in middleware and in promise. So, let's see next example:

$handler->push(function(callable $handler) use ($logger) {
    return function (RequestInterface $request, array $options) use ($handler, $logger) {
        // nothing here

        return $handler($request, $options)->then(
            function ($response) use ($logger) {
                $logger->notice('case #1');

                return $response;
            }
        );
    };
}, 'first_middleware');

$handler->push(function(callable $handler) use ($logger) {
    return function (RequestInterface $request, array $options) use ($handler, $logger) {
        $logger->notice('case #2');

        return $handler($request, $options)->then(
            function ($response) use ($logger) {
                // nothing here

                return $response;
            }
        );
    };
}, 'second_middleware');

What will you expect to see? Probably case 1 and after that case 2, because first_middleware is defined before second_middleware, but it will be it will be vice versa. But why? Because case 2 is written when middleware is triggered (as I understood it's before request) but case 1 is triggered in promise, after request is performed.
Related to your example: add_headers and log_request_fact - are triggered before request, log_request_details - is triggered after request (in promise).

So, it's very powerful tool and you can read more about it here: http://docs.guzzlephp.org/en/stable/handlers-and-middleware.html

[gregurco]

@Nyholm could you please close this issue. I think I gave full explanation to author and issue was opened 7 months ago.

[mirfilip]

@gregurco First of all, thx for the explanation.

I admit, this is quite a hard concept to grasp correctly, as apart from middleware & handlers design, one has to deal with Promises.

I now get it that using Middleware::log logs inside a promise. Now, I moved logging of request / response to Middleware::mapRequest and Middleware::mapResponse.

Now, I get the correct order for request logging.

Still, response middlewares (the ones pushed with Middleware::mapResponse) fire in opposite order than they get pushed to the stack. Let's change my example to:

$stack = HandlerStack::create();
$stack->push(Middleware::mapRequest(function(RequestInterface $request) use ($logger) {
    $logger->debug('Adding foo:bar headers');
    return $request->withHeader(
        'foo',
        'bar'
    );
}), 'add_headers');
$stack->push(Middleware::mapRequest(function (RequestInterface $request) use ($logger) {
    $logger->debug('### Request ###');
    return $request;
}), 'log_request_fact');
$stack->push(Middleware::mapRequest(function (RequestInterface $request) use ($logger) {
    $message = 'Request: ' . $request->getMethod() . ' ' . (string) $request->getUri() . ' Headers: ' . json_encode($request->getHeaders());
    $logger->debug($message);
    return $request;
}), 'log_request_details');

$stack->push(Middleware::mapResponse(function(ResponseInterface $response) use ($logger) {
    $logger->debug('### Response ###');
    return $response;
}), 'log_response_fact');
$stack->push(Middleware::mapResponse(function(ResponseInterface $response) use ($logger) {
    $message = 'Response body: ' . (string) $response->getBody();
    $logger->debug($message);
    return $response;
}), 'log_response_details');
$stack->push(Middleware::mapResponse(function(ResponseInterface $response) use ($logger) {
    $newResponse = \GuzzleHttp\json_encode([
        'usedId' => 1,
        'id' => 1,
        'title' => 'This is a test',
    ], JSON_UNESCAPED_SLASHES);
    $newBody = \GuzzleHttp\Psr7\stream_for($newResponse);
    $logger->debug('Changed response body to: ' . $newResponse);

    return $response->withBody($newBody);
}), 'transform_response_body');

In that case, the order is: add_headers -> log_request_fact -> log_request_details -> transform_response_body -> log_response_details -> log_response_fact - response stuff is still reversed.
I know mapResponse fires the $fn you pass when it resolves the promise. I haven't found any reference in the docs to the fact it fires in reverse. The only thing to that is:

When the stack is resolved, the handler is pushed onto the stack. Each value is then popped off of the stack, wrapping the previous value popped off of the stack.

Of course, I can replace push with unshift for response stuff and easily achieve what I want. Nevertheless, Is that by design and just undocumented or is my example still flawed?

[bert-w]

id also like an answer to this. Why are response middlewares executed in reverse?

[gmponos]

Is that by design

Yes this is by design:

        $h = new MockHandler();
        $stack = new HandlerStack($h);
        $stack->push(Middleware::mapResponse(function (ResponseInterface $response) {
            return $response->withHeader('Bar1', 'foo1');
        }), 'response1');

        $stack->push(Middleware::mapResponse(function (ResponseInterface $response) {
            return $response->withHeader('Bar2', 'foo2');
        }), 'response2');

        echo $stack->__toString();

Prints:

> 2) Name: 'response1', Function: callable(000000000bde07cc0000000043023cc7)
> 1) Name: 'response2', Function: callable(000000000bde07d20000000043023cc7)
< 0) Handler: callable(000000000bde06510000000043023cc7)
< 1) Name: 'response2', Function: callable(000000000bde07d20000000043023cc7)
< 2) Name: 'response1', Function: callable(000000000bde07cc0000000043023cc7)

but because we have the mapResponse only the following will actual take affect:

< 1) Name: 'response2', Function: callable(000000000bde07d20000000043023cc7)
< 2) Name: 'response1', Function: callable(000000000bde07cc0000000043023cc7)