Can't get cache-handler to work #1062

mmjurov · 2024-10-04T13:14:19Z

What happened?

I want to do some HTTP caching to make API faster. My final point is to use 103 Early Hints + HTTP cache on reverse proxy side with invalidation via Souin API.

According to the docs, i need to rebiuld FrankenPHP Docker image to include cache-handler module there, and one of available storage drivers. Then I need to do some configuration in Caddy and api_platform and then it should work.

What i've made:

Changed Dockerfile. Created additional stage, where Caddy built with xcaddy, and then copied into another stage:

ARG PHP_VERSION=8.3

FROM dunglas/frankenphp:latest-builder-php$PHP_VERSION AS builder
COPY --from=caddy:builder /usr/bin/xcaddy /usr/bin/xcaddy
RUN --mount=target=/var/lib/apt/lists,type=cache,sharing=locked \
	--mount=target=/var/cache/apt,type=cache,sharing=locked \
		apt-get update && apt-get install --no-install-recommends -y \
		git

ENV CGO_ENABLED=1 XCADDY_SETCAP=1 XCADDY_GO_BUILD_FLAGS="-ldflags \"-w -s -extldflags '-Wl,-z,stack-size=0x80000'\""
RUN xcaddy build \
	--output /usr/local/bin/frankenphp \
	--with github.com/dunglas/frankenphp=./ \
	--with github.com/dunglas/frankenphp/caddy=./caddy/ \
	--with github.com/dunglas/mercure/caddy \
	--with github.com/dunglas/vulcain/caddy \
	--with github.com/dunglas/caddy-cbrotli \
	--with github.com/darkweak/souin/plugins/caddy@65cb24114d76a7de3f4e8c7b8ef7df3efd028899 \
	--with github.com/darkweak/souin@65cb24114d76a7de3f4e8c7b8ef7df3efd028899 \
        --with github.com/darkweak/storages/otter/caddy


FROM dunglas/frankenphp:1-php$PHP_VERSION AS upstream
COPY --from=builder --link /usr/local/bin/frankenphp /usr/local/bin/frankenphp

# .... 
# Dockerfile continues

One difference from the docs is additional Otter storage module.

Caddyfile updated. Added global option cache with some config and cache option in my application config. My full featured, minimal config here:

{

	cache {
		otter
		api {
			souin
		}
		log_level debug
	}

	order vulcain after reverse_proxy
	order php_server before file_server
}

# API Platform application
api.{$DOMAIN}, http://localhost {

	cache
	vulcain

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

	php_server
}

# Frontend web application on React behind proxy
{$DOMAIN} {
	reverse_proxy http://web:3000
}

The only one thing here, not highlighted in docs - is otter storage configured. I believe, that it's zero-config in-memory storage, which just should work.

API Platform config updated. Added configuration for cache purger:

api_platform:
  http_cache:
    invalidation:
      urls: [ 'http://localhost/souin-api/souin' ]
      purger: api_platform.http_cache.purger.souin

Added cache headers for one of my ApiResource's operation:

#[ORM\Entity(repositoryClass: IconRepository::class)]
#[ApiResource(
    operations: [
        new Get(
            cacheHeaders: [
                'public' => true,
                'max_age' => 30,
                'shared_max_age' => 60,
                'stale_while_revalidate' => 100,
                'vary' => ['Content-Type', 'Accept', 'Origin']
            ],
        ),
        new GetCollection(),
        new Post(),
        new Patch(
            denormalizationContext: ['groups' => ['Icon:update']]
        ),
    ]
)]
class Icon
{
// ...
}

After that, http caching started to work. Cache headers are present in responses from reverse proxy and seems to be ok. On the first hit by operation it shows cache miss, and declares cache lifetime, status 200 Ok

On the second hit it shows cache ttl, cache storage, etc. Statud 304 Not Modified.

Quite ok .... but ... there are some symptoms showing it not work properly:

I can't see s-maxage in response (I don't really know, maybe i shouldn't). My Vary headers in config differs from Vary headers in response.
In Caddy (FrankenPHP) logs i can see some strange stuff:

On the first hit by operation after Caddy startup i see error, that key cannot be found in Otter:

api-1            | 2024/10/04 12:24:12.128	ERROR	storages.cache.otter	Impossible to get the mapping key IDX_GET-https-api.****.***-/icons/1 in Otter
api-1            | 2024/10/04 12:24:13.920	ERROR	storages.cache.otter	Impossible to get the key SURROGATE_https://api.****.***/icons/1 in Otter
api-1            | 2024/10/04 12:24:13.920	ERROR	storages.cache.otter	Impossible to get the key SURROGATE_/icons/1 in Otter

On every 304 response logs not producing any output.

On every cache miss (200 Ok) i can see the following error from FrankenPHP:

api-1            | 2024/10/04 12:25:04.863	ERROR	the current responseWriter is not a flusher	{"error": "feature not supported"}

According to Souin documentation, there is a way to check all cached keys via API. It metioned here

I'm expecting, that when i calling GET http://localhost/souin-api/souin or GET http://localhost/souin-api/souin/surrogate_keys, it will respond me the list of stored cache keys.
Calling this request with curl from inside a container returns empty list with 200 Ok:

root@40efb759dfd5:/app# curl -v http://localhost/souin-api/souin
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /souin-api/souin HTTP/1.1
> Host: localhost
> User-Agent: curl/7.88.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Type: application/json
< Permissions-Policy: browsing-topics=()
< Server: Caddy
< Date: Fri, 04 Oct 2024 11:55:10 GMT
< Content-Length: 2
<
* Connection #0 to host localhost left intact
[]

The most important part for me - Invalidation API seems not working. I modify an icon ApiResource with PATCH query, or create the new one. ApiPlatform really call the souin api PURGE http://localhost/souin-api/souin, but it has no effect, as i see. Cache isn't invalidated, and reverse proxy continues to respond with 304 Not Modified after invalidation request from purger.

I tried to call curl requests to PURGE by myself:

root@40efb759dfd5:/app# curl -v -X PURGE http://localhost/souin-api/souin/IDX_GET-https-api.****.***-/icons/1
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> PURGE /souin-api/souin/IDX_GET-https-api.****.***-/icons/1 HTTP/1.1
> Host: localhost
> User-Agent: curl/7.88.1
> Accept: */*
>
< HTTP/1.1 204 No Content
< Permissions-Policy: browsing-topics=()
< Server: Caddy
< Date: Fri, 04 Oct 2024 12:29:50 GMT
<
* Connection #0 to host localhost left intact

Same result with all my surrogate keys for that operation.

Also i tried to change cache storage to badger instead of otter:

{
	cache {
		badger {
			path /data/badger
		}
		api {
			souin
		}
		log_level debug
	}
}

It behaves similarly except it not spam in logs with message "Impossible to get the mapping key", like Otter. Badger storage creates configured folder inside docker container, there are some database file in there.

Souin API GET http://localhost/souin-api/souin gets some data from it:

root@4c566d2e930b:/app# curl -v -X GET http://localhost/souin-api/souin
Note: Unnecessary use of -X or --request, GET is already inferred.

Trying 127.0.0.1:80...
Connected to localhost (127.0.0.1) port 80 (#0)

GET /souin-api/souin HTTP/1.1
Host: localhost
User-Agent: curl/7.88.1
Accept: /

< HTTP/1.1 200 OK
< Content-Type: application/json
< Permissions-Policy: browsing-topics=()
< Server: Caddy
< Date: Fri, 04 Oct 2024 12:44:06 GMT
< Content-Length: 279
<

Connection #0 to host localhost left intact
["GET-https-api.*.-/icons/1{-VARY-}Accept:text%2Fhtml%2Capplication%2Fxhtml%2Bxml%2Capplication%2Fxml%3Bq%3D0.9%2Cimage%2Favif%2Cimage%2Fwebp%2Cimage%2Fapng%2C%2A%2F%2A%3Bq%3D0.8%2Capplication%2Fsigned-exchange%3Bv%3Db3%3Bq%3D0.7;Content-Type:;Authorization:;Origin:"]


BTW. If i call PURGE after that and GET /souin-api/souin again, the key is still exists. Maybe i use PURGE request not very properly.

And again, i see FrenkenPHP errors on every cache miss response

api-1 | 2024/10/04 12:44:04.798 ERROR the current responseWriter is not a flusher {"error": "feature not supported"}

Relevant log output

api-1            | 2024/10/04 12:44:04.798	ERROR	the current responseWriter is not a flusher	{"error": "feature not supported"}

The text was updated successfully, but these errors were encountered:

mmjurov · 2024-10-04T14:29:13Z

Tried to call /flush method, which clears all keys from storage, and seems it correctly works.

curl -v -X PURGE http://localhost/souin-api/souin/flush
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> PURGE /souin-api/souin/flush HTTP/1.1
> Host: localhost
> User-Agent: curl/7.88.1
> Accept: */*
>
< HTTP/1.1 204 No Content
< Permissions-Policy: browsing-topics=()
< Server: Caddy
< Date: Fri, 04 Oct 2024 14:13:56 GMT
<
* Connection #0 to host localhost left intact

FrankenPHP posts to log:

api-1            | Successfully clear the cache and the surrogate keys storage.

calling GET http://localhost/souin-api/souin after that shows, that keys are really cleared.

Invalidation in that case works as expected. Calling GET operation on /icons/1 receive 200 Ok with cache miss, because there are no cache in storage.

Tried to call curl -v -X PURGE -H "Surrogate-Key: /icons" http://localhost/souin-api/souin, like ApiPlatform does - no effect and no log entries on that.

nickdnk · 2024-10-04T18:33:25Z

Just FYI it looks like you're dumping an app secret. Not sure if important, just in case you missed it.

mmjurov · 2024-10-04T20:34:00Z

@nickdnk Thank you for your notice! It's okay, it's a dev environment on my local workstation behind NAT, not available from internet directly.

mmjurov · 2024-10-07T21:36:28Z

I went deeper and it seems that lots of previous info are not related to FrankenPHP, but related to ApiPlatform. My fault was in misunderstanding cache key generation and flushing mechanism. ApiPlatform do not flush cache of item when new item was created in a collection (i was expected it is). Also my saving mechanism for my ApiResource was broken, so cache flushing on PATCH request was not working, and cache was not flushed because of this. So pardon, it's not an issue anymore. My bad

The only one bug, possibly related to FrankenPHP - is an error message on cache miss with any cache storage, mentioned here, and error messages for otter storage. But probably it's not interfere application at all in my case. A can't figure out if this have any effect or not. I see, that cache is storing and flushing correctly now.

mmjurov added the bug Something isn't working label Oct 4, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Can't get cache-handler to work #1062

Can't get cache-handler to work #1062

mmjurov commented Oct 4, 2024

mmjurov commented Oct 4, 2024

nickdnk commented Oct 4, 2024

mmjurov commented Oct 4, 2024

mmjurov commented Oct 7, 2024

Can't get cache-handler to work #1062

Can't get cache-handler to work #1062

Comments

mmjurov commented Oct 4, 2024

What happened?

Relevant log output

mmjurov commented Oct 4, 2024

nickdnk commented Oct 4, 2024

mmjurov commented Oct 4, 2024

mmjurov commented Oct 7, 2024