Getting constant misses using API Platform

[derTuca]

Hi,

I am tying to setup this module with an API Platform setup (not running in Docker, but standard PHP-FPM). I have configured Caddy as can be seen below, but I am getting constant misses (I do not get any hits).

Here is my Caddyfile:

{
        order cache before rewrite
        cache {
                cache_keys {
                        headers Authorization Content-Type
                }
                key {
                        headers Authorization Content-Type
                }
                log_level debug
        }
        log {
                level debug
        }
}
(cors) {
        @origin header Origin {args.0}
        header @origin Access-Control-Allow-Origin "{args.0}"
        header @origin Access-Control-Allow-Methods "OPTIONS,HEAD,GET,POST,PUT,PATCH,DELETE"
}

app.example {
        route {
                cache
                root * /var/www/app/api/public
                vulcain

                push
                header ?Permissions-Policy "browsing-topics=()"

                php_fastcgi unix//var/run/php/php-fpm.sock
                encode zstd gzip
                file_server
        }
}

other_host {
        other_not_cached_stuff
}

Here are my request headers:

GET /users/7 HTTP/2
Host: REDACTED_APP_DOMAIN
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0
Accept: */*
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate, br
Authorization: Bearer TOKEN
Origin: https://REDACTED_APP_DOMAIN
Connection: keep-alive
Referer: https://REDACTED_APP_DOMAIN
Sec-Fetch-Dest: empty
Sec-Fetch-Mode: cors
Sec-Fetch-Site: same-site
TE: trailers

Here are my response headers:

HTTP/2 200 OK
accept-patch: application/merge-patch+json
access-control-allow-credentials: true
access-control-allow-origin: https://REDACTED_APP_DOMAIN
access-control-expose-headers: link
alt-svc: h3=":443"; ma=2592000
cache-control: max-age=0, public, s-maxage=3600
cache-status: Souin; fwd=uri-miss; stored
content-type: application/ld+json; charset=utf-8
date: Sat, 04 Feb 2023 20:56:32 GMT
etag: "03407f50c18524d5cc417eaa8f0d214e"
link: <https://REDACTED_APP_DOMAIN/docs.jsonld>; rel="http://www.w3.org/ns/hydra/core#apiDocumentation"
permissions-policy: browsing-topics=()
server: Caddy
surrogate-key: /users/7
vary: Accept, Content-Type, Authorization, Origin
x-content-type-options: nosniff
x-frame-options: deny
content-length: 216
X-Firefox-Spdy: h2

Looking at the Caddy logs, all I get is:

Feb 04 20:56:32 app-dev caddy[37178]: {"level":"debug","ts":1675544192.855148,"logger":"http.handlers.cache","msg":"Incoming request: &{Method:GET URL:/users/13 Proto:HTTP/2.0 ProtoMajor:2 ProtoMinor:0 Header:map[Accept:[*/*] Accept-Encoding:[gzip, deflate, br] Accept-Language:[en-US,en;q=0.5] Authorization:[Bearer TOKEN] Date:[Sat, 04 Feb 2023 20:56:32 UTC] If-None-Match:[\"1e80b930ac97fcc265d9e68a93a5ebe5\"] Origin:[https://REDACTED_APP_DOMAIN] Referer:[https://REDACTED_APP_DOMAIN/] Sec-Fetch-Dest:[empty] Sec-Fetch-Mode:[cors] Sec-Fetch-Site:[same-site] Te:[trailers] User-Agent:[Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0]] Body:0xc00ad91860 GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:REDACTED_APP_DOMAIN Form:map[] PostForm:map[] MultipartForm:<nil> Trailer:map[] RemoteAddr:86.120.236.159:39426 RequestURI:/users/13 TLS:0xc008d5e000 Cancel:<nil> Response:<nil> ctx:0xc00b2e8f60}"}
Feb 04 20:56:32 app-dev caddy[37178]: {"level":"debug","ts":1675544192.859668,"logger":"http.handlers.cache","msg":"writeRequests called. Writing to value log"}
Feb 04 20:56:32 app-dev caddy[37178]: {"level":"debug","ts":1675544192.8601124,"logger":"http.handlers.cache","msg":"Sending updates to subscribers"}
Feb 04 20:56:32 app-dev caddy[37178]: {"level":"debug","ts":1675544192.8603485,"logger":"http.handlers.cache","msg":"Writing to memtable"}
Feb 04 20:56:32 app-dev caddy[37178]: {"level":"debug","ts":1675544192.860538,"logger":"http.handlers.cache","msg":"2 entries written"}

Is there anything I am missing here? Thank you!

[darkweak]

Hello @derTuca I'll try to find why that behavior happens. I suspect the max-age=0 that takes the lead on the storage calculation instead of the s-maxage=0

[darkweak]

@derTuca please take a look at this PR from @JacquesDurand api-platform/api-platform#2383 maybe it can help to get some hit.

[derTuca]

Thank you! The config works and I get hits, however, now I try to get cache invalidation working and I get a permanent redirect to https://localhost/souin-api/souin (I use localhost since I don't use the distribution on this machine), which errors out due to bad/no SSL certificates. Is this expected behavior?

[derTuca]

Uh oh, I spoke too soon! It seems that building with github.com/darkweak/souin/plugins/caddy I get cache hits, while I get misses with github.com/caddyserver/cache-handler using the exact same config.

[darkweak]

That's because the Souin repository is getting updated faster than the cache-handler one (because the cache-handler is supposed to be the stable version of Souin).

[derTuca]

Ok, I understand. Should I open a new issue related to the https redirect in this case and leave this issue to track merging that change into cache-handler?

[darkweak]

The scheme is not part of the key, I think we have to add it.

[darkweak]

Can you try with the latest release please?

[derTuca]

Sorry for the late response, I had to take a leave. Unfortunately I am getting constant misses once again with the latest version. What logs can I output that could help with debugging? Thanks!

[darkweak]

Hello, every logs you can paste will help to debug

[derTuca]

The response header is the following: Souin; fwd=uri-miss; stored; key=GET-https-REDACTED-ADDR-/users/7

Pasting the logs from the caddy service for a GET request that should have been cached:

Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.1109374,"logger":"http.handlers.cache","msg":"Incomming request &{Method:GET URL:/users/7 Proto:HTTP/2.0 ProtoMajor:2 ProtoMinor:0 Header:map[Accept:[*/*] Authorization:[Bearer REDACTED_TOKEN] User-Agent:[insomnia/2022.7.3]] Body:0xc01afaa0c0 GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:REDACTED_ADDR Form:map[] PostForm:map[] MultipartForm:<nil> Trailer:map[] RemoteAddr:REDACTED_IP:39374 RequestURI:/users/7 TLS:0xc00049ce70 Cancel:<nil> Response:<nil> ctx:0xc01afaa2a0}"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.112016,"logger":"http.handlers.cache","msg":"Request cache-control &{MaxAge:-1 MaxStale:-1 MaxStaleSet:false MinFresh:-1 NoCache:false NoStore:false NoTransform:false OnlyIfCached:false Extensions:[]}"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.1125352,"logger":"http.handlers.cache","msg":"Request the upstream server"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.1128836,"logger":"http.handlers.rewrite","msg":"rewrote request","request":{"remote_ip":"REDACTED_IP","remote_port":"39374","proto":"HTTP/2.0","method":"GET","host":"REDACTED_ADDR","uri":"/users/7","headers":{"Date":["Sun, 19 Mar 2023 08:18:54 UTC"],"User-Agent":["insomnia/2022.7.3"],"Authorization":[],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"REDACTED_ADDR"}},"method":"GET","uri":"/index.php"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.1130939,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"/var/run/php/php-fpm.sock","total_upstreams":1}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.1133442,"logger":"http.reverse_proxy.transport.fastcgi","msg":"roundtrip","request":{"remote_ip":"REDACTED_IP","remote_port":"39374","proto":"HTTP/2.0","method":"GET","host":"REDACTED_ADDR","uri":"/index.php","headers":{"Date":["Sun, 19 Mar 2023 08:18:54 UTC"],"X-Forwarded-For":["REDACTED_IP"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["REDACTED_ADDR"],"User-Agent":["insomnia/2022.7.3"],"Authorization":[],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"REDACTED_ADDR"}},"env":{"HTTP_HOST":"REDACTED_ADDR","SCRIPT_NAME":"/index.php","CONTENT_LENGTH":"","REQUEST_SCHEME":"https","SERVER_SOFTWARE":"Caddy/v2.6.4","HTTP_X_FORWARDED_HOST":"REDACTED_ADDR","REMOTE_IDENT":"","REQUEST_METHOD":"GET","SSL_CIPHER":"TLS_AES_128_GCM_SHA256","QUERY_STRING":"","HTTP_ACCEPT":"*/*","DOCUMENT_ROOT":"/var/www/app/api/public","SCRIPT_FILENAME":"/var/www/app/api/public/index.php","SERVER_PORT":"443","HTTP_USER_AGENT":"insomnia/2022.7.3","PATH_INFO":"","REMOTE_USER":"","SERVER_PROTOCOL":"HTTP/2.0","REMOTE_HOST":"REDACTED_IP","SERVER_NAME":"REDACTED_ADDR","HTTP_DATE":"Sun, 19 Mar 2023 08:18:54 UTC","HTTP_X_FORWARDED_FOR":"REDACTED_IP","HTTP_AUTHORIZATION":"","AUTH_TYPE":"","GATEWAY_INTERFACE":"CGI/1.1","SSL_PROTOCOL":"TLSv1.3","CONTENT_TYPE":"","REMOTE_PORT":"39374","REQUEST_URI":"/users/7","HTTP_X_FORWARDED_PROTO":"https","REMOTE_ADDR":"REDACTED_IP","DOCUMENT_URI":"/index.php","HTTPS":"on"},"dial":"/var/run/php/php-fpm.sock","env":{"HTTPS":"on","HTTP_X_FORWARDED_PROTO":"https","REMOTE_ADDR":"REDACTED_IP","DOCUMENT_URI":"/index.php","SERVER_SOFTWARE":"Caddy/v2.6.4","HTTP_HOST":"REDACTED_ADDR","SCRIPT_NAME":"/index.php","CONTENT_LENGTH":"","REQUEST_SCHEME":"https","SSL_CIPHER":"TLS_AES_128_GCM_SHA256","HTTP_X_FORWARDED_HOST":"REDACTED_ADDR","REMOTE_IDENT":"","REQUEST_METHOD":"GET","QUERY_STRING":"","HTTP_ACCEPT":"*/*","SERVER_PROTOCOL":"HTTP/2.0","DOCUMENT_ROOT":"/var/www/app/api/public","SCRIPT_FILENAME":"/var/www/app/api/public/index.php","SERVER_PORT":"443","HTTP_USER_AGENT":"insomnia/2022.7.3","PATH_INFO":"","REMOTE_USER":"","HTTP_DATE":"Sun, 19 Mar 2023 08:18:54 UTC","REMOTE_HOST":"REDACTED_IP","SERVER_NAME":"REDACTED_ADDR","SSL_PROTOCOL":"TLSv1.3","HTTP_X_FORWARDED_FOR":"REDACTED_IP","HTTP_AUTHORIZATION":"","AUTH_TYPE":"","GATEWAY_INTERFACE":"CGI/1.1","REQUEST_URI":"/users/7","CONTENT_TYPE":"","REMOTE_PORT":"39374"},"request":{"remote_ip":"REDACTED_IP","remote_port":"39374","proto":"HTTP/2.0","method":"GET","host":"REDACTED_ADDR","uri":"/index.php","headers":{"Accept":["*/*"],"Date":["Sun, 19 Mar 2023 08:18:54 UTC"],"X-Forwarded-For":["REDACTED_IP"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["REDACTED_ADDR"],"User-Agent":["insomnia/2022.7.3"],"Authorization":[]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"REDACTED_ADDR"}}}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.248996,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"unix//var/run/php/php-fpm.sock","duration":0.135669121,"request":{"remote_ip":"REDACTED_IP","remote_port":"39374","proto":"HTTP/2.0","method":"GET","host":"REDACTED_ADDR","uri":"/index.php","headers":{"User-Agent":["insomnia/2022.7.3"],"Authorization":[],"Accept":["*/*"],"Date":["Sun, 19 Mar 2023 08:18:54 UTC"],"X-Forwarded-For":["REDACTED_IP"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["REDACTED_ADDR"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"REDACTED_ADDR"}},"headers":{"X-Content-Type-Options":["nosniff"],"Accept-Patch":["application/merge-patch+json"],"Date":["Sun, 19 Mar 2023 08:18:54 GMT"],"Link":["<https://REDACTED_ADDR/docs.jsonld>; rel=\"http://www.w3.org/ns/hydra/core#apiDocumentation\""],"Etag":["\"aebd2a599045685092488729e90b6140\""],"Content-Type":["application/ld+json; charset=utf-8"],"Vary":["Accept","Content-Type","Authorization","Origin"],"X-Frame-Options":["deny"],"Cache-Control":["max-age=0, public, s-maxage=3600"]},"status":200}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.24924,"logger":"http.handlers.cache","msg":"Response cache-control &{MustRevalidate:false NoCache:map[] NoCachePresent:false NoStore:false NoTransform:false Public:true Private:map[] PrivatePresent:false ProxyRevalidate:false MaxAge:0 SMaxAge:3600 Immutable:false StaleIfError:-1 StaleWhileRevalidate:-1 Extensions:[]}"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2493978,"logger":"http.handlers.cache","msg":"Store the response {Status: StatusCode:200 Proto: ProtoMajor:0 ProtoMinor:0 Header:map[Accept-Patch:[application/merge-patch+json] Alt-Svc:[h3=\":443\"; ma=2592000] Cache-Control:[max-age=0, public, s-maxage=3600] Content-Type:[application/ld+json; charset=utf-8] Date:[Sun, 19 Mar 2023 08:18:54 GMT] Etag:[\"aebd2a599045685092488729e90b6140\"] Link:[<https://REDACTED_ADDR/docs.jsonld>; rel=\"http://www.w3.org/ns/hydra/core#apiDocumentation\"] Permissions-Policy:[browsing-topics=()] Server:[Caddy] Vary:[Accept Content-Type Authorization Origin] X-Content-Type-Options:[nosniff] X-Frame-Options:[deny] X-Souin-Stored-Ttl:[16m40s]] Body:{Reader:{\"@context\":\"\\/contexts\\/User\",\"@id\":\"\\/users\\/7\",\"@type\":\"User\",\"id\":7,\"email\":\"office@example.com\",\"roles\":[\"ROLE_ADMIN\"],\"phoneNumber\":\"+4000000000\",\"streetAddresses\":[],\"firstName\":\"app\",\"lastName\":\"Admin\",\"documents\":[]}} ContentLength:0 TransferEncoding:[] Close:false Uncompressed:false Trailer:map[] Request:<nil> TLS:<nil>} with duration 16m39.750705836s"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2494767,"logger":"http.handlers.cache","msg":"writeRequests called. Writing to value log"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2495131,"logger":"http.handlers.cache","msg":"Sending updates to subscribers"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.249518,"logger":"http.handlers.cache","msg":"Writing to memtable"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2495422,"logger":"http.handlers.cache","msg":"2 entries written"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.249565,"logger":"http.handlers.cache","msg":"writeRequests called. Writing to value log"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2495685,"logger":"http.handlers.cache","msg":"Sending updates to subscribers"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.249571,"logger":"http.handlers.cache","msg":"Writing to memtable"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2495894,"logger":"http.handlers.cache","msg":"2 entries written"}
Mar 19 08:18:54 hostname caddy[274510]: {"level":"debug","ts":1679213934.2496138,"logger":"http.handlers.cache","msg":"Store the cache key GET-https-REDACTED_ADDR-/users/7{-VARY-}Accept:*/*;Content-Type:;Authorization:bearer REDACTED_TOKEN;Origin: into the surrogate keys from the following headers { 200  0 0 map[Accept-Patch:[application/merge-patch+json] Alt-Svc:[h3=\":443\"; ma=2592000] Cache-Control:[max-age=0, public, s-maxage=3600] Content-Type:[application/ld+json; charset=utf-8] Date:[Sun, 19 Mar 2023 08:18:54 GMT] Etag:[\"aebd2a599045685092488729e90b6140\"] Link:[<https://REDACTED_ADDR/docs.jsonld>; rel=\"http://www.w3.org/ns/hydra/core#apiDocumentation\"] Permissions-Policy:[browsing-topics=()] Server:[Caddy] Vary:[Accept Content-Type Authorization Origin] X-Content-Type-Options:[nosniff] X-Frame-Options:[deny] X-Souin-Stored-Ttl:[16m40s]] {{\"@context\":\"\\/contexts\\/User\",\"@id\":\"\\/users\\/7\",\"@type\":\"User\",\"id\":7,\"email\":\"office@example.com\",\"roles\":[\"ROLE_ADMIN\"],\"phoneNumber\":\"+4000000000\",\"streetAddresses\":[],\"firstName\":\"app\",\"lastName\":\"Admin\",\"documents\":[]}} 0 [] false false map[] <nil> <nil>}"}

This is my current Caddyfile:

{
        order cache before rewrite
        log {
                level debug
        }
        cache {
                allowed_http_verbs GET
                api {
                        souin
                }
                log_level debug
                ttl 1000s
                timeout {
                        backend 10s
                        cache 100ms
                }
        }
}
(cors) {
        @origin header Origin {args.0}
        header @origin Access-Control-Allow-Origin "{args.0}"
        header @origin Access-Control-Allow-Methods "OPTIONS,HEAD,GET,POST,PUT,PATCH,DELETE"
}

localhost:80 {
        @souin-api path /souin-api*
        cache @souin-api {
        }
}


api.dev.example.com {
        route {
                root * /var/www/app/api/public
                cache
                # mercure {
                #     # Transport to use (default to Bolt)
                #     transport_url {$MERCURE_TRANSPORT_URL:bolt:///data/mercure.db}
                #     # Publisher JWT key
                #     publisher_jwt {env.MERCURE_PUBLISHER_JWT_KEY} {env.MERCURE_PUBLISHER_JWT_ALG}
                #     # Subscriber JWT key
                #     subscriber_jwt {env.MERCURE_SUBSCRIBER_JWT_KEY} {env.MERCURE_SUBSCRIBER_JWT_ALG}
                #     # Allow anonymous subscribers (double-check that it's what you want)
                #     anonymous
                #     # Enable the subscription API (double-check that it's what you want)
                #     subscriptions
                #     # Extra directives
                #     {$MERCURE_EXTRA_DIRECTIVES}
                # }
                vulcain

                push
                #import cors *
                # Add links to the API docs and to the Mercure Hub if not set explicitly (e.g. the PWA)
                #header ?Link `</docs.jsonld>; rel="http://www.w3.org/ns/hydra/core#apiDocumentation", </.well-known/mercure>; rel="mercure"`
                # Disable Topics tracking if not enabled explicitly: https://github.com/jkarlin/topics
                header ?Permissions-Policy "browsing-topics=()"


                php_fastcgi unix//var/run/php/php-fpm.sock
                encode zstd gzip
                file_server
        }
}

OTHER_NONCACHED_HOSTS...

[darkweak]

Hello, thanks for the logs. Can you enable the Souin api please?

{
    # other global configuration
    cache {
        api {
            souin
        }
        # other cache configuration
    }
}

# ...

Send the first request to cache, after that go to /souin-api/souin you should see an array that contains your stored keys. If your key is present, that mean souin doesn't retrieve it and that could come from the authentication token (that would be a regression introduced in the refactoring due to a lack of test cases).

[derTuca]

Yes, the key is in the cache. I get the following response:

["GET-https-api.dev.example.com-/users/7{-VARY-}Accept:*/*;Content-Type:;Authorization:bearer REDACTED_TOKEN;Origin:","STALE_GET-https-api.dev.example.com-/users/7{-VARY-}Accept:*/*;Content-Type:;Authorization:bearer REDACTED_TOKEN;Origin:"]

[darkweak]

I found the issue, I'm storing the varied headers value as lower cases