[HttpKernel] HttpCache\Store does not return response body correctly

[sgehrig]

Symfony version(s) affected: 4.4.* / 5.0.* / 5.1.* (probably others)

Description
While using Symfony\Component\HttpClient\CachingHttpClient with a Symfony\Component\HttpKernel\HttpCache\Store we found that responses returned from the cache did not yield the correct response bodies.

I checked the source and found the following snippet:

symfony/src/Symfony/Component/HttpKernel/HttpCache/Store.php

Lines 153 to 155 in 749380a

	if (file_exists($body = $this->getPath($headers['x-content-digest'][0]))) {
	return $this->restoreResponse($headers, $body);
	}

This seems rather odd to me because after executing $body = $this->getPath($headers['x-content-digest'][0]) $body contains the path to the cached response body file and not the cached response body itself. But $body (containing the path and not the response body) is then fed into Symfony\Component\HttpKernel\HttpCache\Store::restoreResponse() where it's used to populate the Symfony\Component\HttpFoundation\Response content. So the returned response contains the path to the cached response body file in its body instead of the actual response content.

How to reproduce
Just use a Symfony\Component\HttpClient\CachingHttpClient configured with a Symfony\Component\HttpKernel\HttpCache\Store and fetch the same HTTP resource twice.

Possible Solution
I might be wrong, but to me it looks like there's a file_get_contents() missing.

[zdebol]

I have the same issue after upgrade to Symfony 4.4.9. Only once get correct response and then save in cache file path instead of content. Method write in class Symfony\Component\HttpKernel\HttpCache\Store has change and maybe this change is the cause of problem.

[nicolas-grekas]

/cc @mpdude maybe?

[mpdude]

I think I've seen this once in a while when I was working on #36833... @sgehrig could you check if reverting that change fixes the issue for you?

[mpdude]

I've tried the following script on 5b719d1:

<?php

use Symfony\Component\HttpClient\CachingHttpClient;
use Symfony\Component\HttpClient\HttpClient;
use Symfony\Component\HttpKernel\HttpCache\Store;

require('vendor/autoload.php');

$httpClient = new CachingHttpClient(HttpClient::create(), new Store('store'));

$response1 = $httpClient->request('GET', 'http://httpbin.org/cache/90');
$response2 = $httpClient->request('GET', 'http://httpbin.org/cache/90');

print $response1->getContent() . PHP_EOL;
print "---" . PHP_EOL;
print $response2->getContent() . PHP_EOL;

I get the same output above and below the ---, which to me would suggest the cache is working correctly? Also note that the "X-Amzn-Trace-Id is the same, so in fact only one request was performed and the other one must be cached?

Also, find store -type f shows two files in the cache – one for the response body, one for the cache entry.

@sgehrig can you confirm that?

Also, just to gather additional data: Can you show us the response headers you get from upstream?

[zdebol]

I have this issue with Symfony\Bundle\FrameworkBundle\HttpCache\HttpCache using Symfony as Reverse Proxy. Today morning upgrade Symfony from 4.4.8 to 4.4.9 and break my page. In all places where use render_esi instead show content show paths.

[mpdude]

@sgehrig Are you using one of v5.1.0, v5.1.0-RC2, v5.0.9, v4.4.9 or v3.4.41? These are the versions that contain #36833.

[mpdude]

@zdebol So you're saying this is a regression introduced in 4.4.8 -> 4.4.9? If so, #36833 might be the culprit. Are you using the HttpClient at all (like the OP), or do you habe the problem with the HttpCache as reverse proxy only? Or are you using Symfony on both ends?

[zdebol]

Yes, after downgrade to 4.4.8 problem is gone and page work correct.

[zdebol]

I only use HttpCache as reverse proxy.

[mpdude]

@zdebol and you probably cleared the cache after the update?

[zdebol]

Yes.
First render page was correct and response save correct in cache. Next render also correct but this time in cache saved path instead content and next render is break with paths instead content.

[mpdude]

@zdebol Looks your issue is different from what @sgehrig reported.

Please try to run the application from https://github.com/webfactory/symfony-http-caching-demo/tree/symfony-issue-37174 (use that branch please!). Run composer install and then start the webserver with bin/console server:start 0.0.0.0:8000. Go to http://localhost:8000 and you should see an ESI-based page.

Does that work?

[sgehrig]

@sgehrig Are you using one of v5.1.0, v5.1.0-RC2, v5.0.9, v4.4.9 or v3.4.41? These are the versions that contain #36833.

@mpdude I’m pretty sure, we’re on 4.4.9. But I’ll check that tomorrow. Thanks for your great efforts!

[zdebol]

No, does not work. Is ok for 30sec. After max age expire in place where be Today is ... appear path to file.

If you delete setMaxAge is work exactly how I describe above. Third reload is break down.

[sgehrig]

@mpdude So, I'm still not 100% sure how I reproduced the issue but it seems to happen when a cached response becomes invalid or (less likely) it's related to revalidation.

In the application we're setting up the http client like this:

    app.idp.jwks_http_cache_store:
        class: Symfony\Component\HttpKernel\HttpCache\Store
        arguments:
            $root: '%app.jwks_http_cache_store_dir%'

    app.idp.jwks_http_client:
        class: Symfony\Component\HttpClient\CachingHttpClient
        arguments:
            $store: '@app.idp.jwks_http_cache_store'
            $defaultOptions:
                base_uri: '%env(APP_IDP_URL)%'
                verify_host: false
                verify_peer: false
                headers:
                    'X-Client': 'Application'
                    'User-Agent': 'Application'
                max_duration: 1.5
                timeout: 1.0
                allow_reload: true
                allow_revalidate: true

The response we get on an empty cache looks like this:

[
    0 =>
        [
            0 =>
                [
                    'host'            =>
                        [
                            0 => '10.0.2.2:4432',
                        ],
                    'user-agent'      =>
                        [
                            0 => 'Symfony',
                            1 => 'Application',
                        ],
                    'accept'          =>
                        [
                            0 => 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
                            1 => '*/*',
                        ],
                    'accept-language' =>
                        [
                            0 => 'en-us,en;q=0.5',
                        ],
                    'accept-charset'  =>
                        [
                            0 => 'ISO-8859-1,utf-8;q=0.7,*;q=0.7',
                        ],
                    'x-client'    =>
                        [
                            0 => 'Application',
                        ],
                ],
            1 =>
                [
                    'server'             =>
                        [
                            0 => 'nginx/1.14.0 (Ubuntu)',
                        ],
                    'content-type'       =>
                        [
                            0 => 'application/jwk-set+json',
                        ],
                    'cache-control'      =>
                        [
                            0 => 'max-age=3600, public, s-maxage=3600',
                        ],
                    'date'               =>
                        [
                            0 => 'Wed, 10 Jun 2020 04:53:01 GMT',
                        ],
                    'etag'               =>
                        [
                            0 => '"9cf06121c3cb4175724181b98a2e750ab75ebbed"',
                        ],
                    'last-modified'      =>
                        [
                            0 => 'Wed, 04 Mar 2020 11:52:55 GMT',
                        ],
                    'x-debug-token'      =>
                        [
                            0 => '...',
                        ],
                    'x-debug-token-link' =>
                        [
                            0 => 'https://10.0.2.2:4432/_profiler/...',
                        ],
                    'x-robots-tag'       =>
                        [
                            0 => 'noindex',
                        ],
                    'x-content-digest'   =>
                        [
                            0 => 'enfa6d30ccf08a1f7c08d0fe1e23d674b9386618de5abacca270840dbd655fcc48',
                        ],
                    'content-length'     =>
                        [
                            0 => 483,
                        ],
                    'X-Status'           =>
                        [
                            0 => 200,
                        ],
                ],
        ],
]

And the body yields the expected JWK set:

{"keys":[{"kty":"RSA","n":"upIOqCpx03yqmYQ1Hv7DKiYijSta_uLdOM0Yc7uE5sAVS73t4Olv3WwDgN7ZEYKfQt9NLzFUGrxA6NQqNK3tePdPiYo8guX9T0OwPvtyVMCRR6OGZ0NC9uTrNKkeGnI3pKxjfQ6igicyIwJEXwxNeCPs9F9GYLrk8tM3ZNKV7lY-eOKyxjif1aTWyj5zwsZzo7xyNRFDcmLVPHvyVsli2J-mQFZ_bCdY3mQyBASHLPdykyH24Sz8ObDQzgfcU5bh2uMp0SaeB7m3m6riyVgZavtex6-U9iCYRy3kAgaEmyqAZ7bf1XXZ4NM2MhsubHU56ob1LrRLmFBDjoIr0OI3cQ","e":"AQAB","alg":"RS256","use":"sig","kid":"3ed8d6d1b51c7af5cb4b7fe23834acd5b2d643685ce1060b36a22462c2d50fea"}]}

When the cache entry is invalidated I found the following files in the cache directory.

[
    0 =>
        [
            0 =>
                [
                    'host'            =>
                        [
                            0 => '10.0.2.2:4432',
                        ],
                    'user-agent'      =>
                        [
                            0 => 'Symfony',
                            1 => 'Application',
                        ],
                    'accept'          =>
                        [
                            0 => 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
                            1 => '*/*',
                        ],
                    'accept-language' =>
                        [
                            0 => 'en-us,en;q=0.5',
                        ],
                    'accept-charset'  =>
                        [
                            0 => 'ISO-8859-1,utf-8;q=0.7,*;q=0.7',
                        ],
                    'x-client'    =>
                        [
                            0 => 'Application',
                        ],
                ],
            1 =>
                [
                    'server'             =>
                        [
                            0 => 'nginx/1.14.0 (Ubuntu)',
                        ],
                    'content-type'       =>
                        [
                            0 => 'application/jwk-set+json',
                        ],
                    'cache-control'      =>
                        [
                            0 => 'max-age=3600, public, s-maxage=3600',
                        ],
                    'etag'               =>
                        [
                            0 => '"9cf06121c3cb4175724181b98a2e750ab75ebbed"',
                        ],
                    'last-modified'      =>
                        [
                            0 => 'Wed, 04 Mar 2020 11:52:55 GMT',
                        ],
                    'x-debug-token'      =>
                        [
                            0 => '26fb39',
                        ],
                    'x-debug-token-link' =>
                        [
                            0 => 'https://10.0.2.2:4432/_profiler/26fb39',
                        ],
                    'x-robots-tag'       =>
                        [
                            0 => 'noindex',
                        ],
                    'x-content-digest'   =>
                        [
                            0 => 'en3785f7245b2c14984ad3689c2608861a102e9545c07630fe366416cdfbc674c1',
                        ],
                    'content-length'     =>
                        [
                            0 => 100,
                        ],
                    'x-body-file'        =>
                        [
                            0 => '/dev/shm/app/cache/dev/http/en/70/74/0edad0d2a9927c454a236d798b7e64d9af6a61c5699e0f50ffbf1bb6aeb6',
                        ],
                    'date'               =>
                        [
                            0 => 'Wed, 10 Jun 2020 05:10:14 GMT',
                        ],
                    'X-Status'           =>
                        [
                            0 => 200,
                        ],
                ],
        ],
]

And the response body file contains

/dev/shm/app/cache/dev/http/en/3a/cd/b913c2a41f11d0a2e892d3ffdae68df9f1522740dab8ae06edb27f04a6dc

And yes, we're on Symfony 4.4.9 components.

And that's the raw HTTP response we get from the requested URL:

HTTP/1.1 200 OK
Cache-Control: max-age=3600, public, s-maxage=3600
Connection: keep-alive
Content-Type: application/jwk-set+json
Date: Wed, 10 Jun 2020 05:30:25 GMT
ETag: "9cf06121c3cb4175724181b98a2e750ab75ebbed"
Last-Modified: Wed, 04 Mar 2020 11:52:55 GMT
Server: nginx/1.14.0 (Ubuntu)
Transfer-Encoding: chunked
X-Debug-Token: ...
X-Debug-Token-Link: https://xxx.test:4432/_profiler/...
X-Robots-Tag: noindex

{
    "keys": [
        {
            "alg": "RS256",
            "e": "AQAB",
            "kid": "3ed8d6d1b51c7af5cb4b7fe23834acd5b2d643685ce1060b36a22462c2d50fea",
            "kty": "RSA",
            "n": "upIOqCpx03yqmYQ1Hv7DKiYijSta_uLdOM0Yc7uE5sAVS73t4Olv3WwDgN7ZEYKfQt9NLzFUGrxA6NQqNK3tePdPiYo8guX9T0OwPvtyVMCRR6OGZ0NC9uTrNKkeGnI3pKxjfQ6igicyIwJEXwxNeCPs9F9GYLrk8tM3ZNKV7lY-eOKyxjif1aTWyj5zwsZzo7xyNRFDcmLVPHvyVsli2J-mQFZ_bCdY3mQyBASHLPdykyH24Sz8ObDQzgfcU5bh2uMp0SaeB7m3m6riyVgZavtex6-U9iCYRy3kAgaEmyqAZ7bf1XXZ4NM2MhsubHU56ob1LrRLmFBDjoIr0OI3cQ",
            "use": "sig"
        }
    ]
}

[mpdude]

#37182 might be a fix. I believe both situations reported here (CachingHttpClient and using the Symfony HttpCache) share a common cause in the Store class. They are triggered when a cached response is validated and then fetched from cache once again.

[mpdude]

@sgehrig if you can confirm the fix works for you, you could close this issue.

[sgehrig]

@sgehrig if you can confirm the fix works for you, you could close this issue.

@mpdude Will check that tomorrow! Thanks a lot for your efforts!

[sgehrig]

@mpdude Just updates to Symfony 4.4.10 and the problem seems to be solved. Thanks for your quick action!