darkweak / souin

An HTTP cache system, RFC compliant, compatible with @tyktechnologies, @traefik, @caddyserver, @go-chi, @bnkamalesh, @beego, @devfeel, @labstack, @gofiber, @go-goyave, @go-kratos, @gin-gonic, @roadrunner-server, @zalando, @zeromicro, @nginx and @apache
https://docs.souin.io
MIT License
692 stars 53 forks source link

Help with debugging cache error with Redis #550

Open danielloader opened 4 days ago

danielloader commented 4 days ago

Facing an interesting issue where most of the requests I make are caching as expected, but one isn't, and I can't deduce why.

{"level":"error","ts":1726567415.6833787,"logger":"storages.cache.redis","msg":"Impossible to decode the key GET-REDACTED, proto: cannot parse invalid wire-format data"}

Which yields the expected header in the response of:

Cache-Status: "Souin; fwd=uri-miss; detail=REDIS-INSERTION-ERROR; key=GET-REDACTED"

But where do I go about debugging this further? I am using the caddy middleware approach here.

Interestingly the key is visible in Redis, with what looks to be the correct payload - hard to tell with all the non unicode characters in the value field but it looks similar to the expected json stored in the key.

Noticed that keys that work look like this:

image

Where as this misbehaving key has stored the header in the key as follows:

image

I've tried various Accept-Encoding headers wondering if it's due to compression but ultimately can't work it out - any tips where to go next would be great!

darkweak commented 3 days ago

Hello @danielloader do you have some debug logs? The value you're seeing is a protobuf encoded value FYI so that's why it's ugly. Did you try to reset the storage?

danielloader commented 3 days ago

Hello, I did enable debug log level on the cache middleware and don't actually get any additional log lines related as far as I can tell. I'll re enable it to be sure later.

I've tried deleting individual keys that seem to be poisoning the cache, setting a maximum key size (2MB) and I've done a full delete of the redis pod and pv to get a fresh cache persistence layer.

Anything else I could try?

darkweak commented 3 days ago

@danielloader what's your config?

danielloader commented 3 days ago
{
    auto_https off
    order cache before rewrite
    cache {
        allowed_http_verbs GET HEAD
        log_level info
        max_cacheable_body_bytes 2097152
        api {
            prometheus
            basepath /_admin
        }
        mode bypass_request
        ttl 86400s
        redis {
            configuration {
                Addrs {$REDIS_HOST}:{$REDIS_PORT}
                Password {$REDIS_PASSWORD}
            }
        }
    }
    log {
        output stdout
        format json
        level {$LOG_LEVEL}
    }
}

# Health checks
:80 {
    respond /healthz 200
}

# Prometheus
:9090 {
    metrics /metrics
}

# Common options for vendors
(common) {
    log
}

:80 {
    import common

    cache {
        cache_name cache
        ttl 31536000s # 1 year redis side
                default_cache_control "max-age=86400" # 1 day browser side
    }

    reverse_proxy {
        to https://example.com:443
    }
}

Hoping the slightly simplified redacted config is useful, the actual reverse proxy gets headers injected for auth at this point and points to secure service.

It's just interesting that the redis cache insertion claims to have failed yet the key with the correct TTL exists - though I have no concept of the validity of the value and I guess the response proto: cannot parse invalid wire-format data throws some doubt on that.

darkweak commented 2 days ago

I wonder if that could be related to cloudflare. Can you try to request directly your server without going through cloudflare? The cannot parse invalid wire-format data is thrown because the writer doesn’t write as many bytes as the reader reads bytes. I assume that you used the github.com/darkweak/storages/redis/caddy module right?

danielloader commented 2 days ago

I've tried go-redis and redis modules just to rule out any client implementations, I'll try direct as you suggest by port forwarding to the caddy instance directly and hitting it up with a curl. That said the upstream I am reverse proxying is hosted by cloudflare itself.

FROM caddy:2-builder AS builder
  RUN xcaddy build \
      --with github.com/caddyserver/cache-handler@v0.14.0 \
      # --with github.com/darkweak/storages/redis/caddy@v0.0.8 \
      --with github.com/darkweak/storages/go-redis/caddy@v0.0.8

FROM caddy:2
  COPY --from=builder /usr/bin/caddy /usr/bin/caddy
  COPY ./Caddyfile /etc/caddy/Caddyfile

Edit: Done the testing with port forwarding and spoofing the host header to get it proxied and cached - same behaviour for me as if I were going through it on our own cloudflare proxy route - as mentioned though the upstream service I am trying to cache is using cloudflare on their edge, but a vast majority of the keys do cache, just some don't and I can't see anything in the responses that would mark them as different, we're talking json with a few dozen kb variation between each call.