HEAD Request HTTP/2 content-length error

[alistairjevans]

I've seen fairly easily reproducible behaviour with HEAD requests where if caching is enabled on HEAD requests I get a HTTP/2 stream error:

* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
* http2 error: Invalid HTTP header field was received: frame type: 1, stream: 1, name: [content-length], value: []
* HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)
* stopped the pause stream!

If I turn off HEAD caching with allowed_http_verbs GET, requests go through fine.

No errors in the caddy logs themselves. Any chance this handler is duplicating content-length headers?

[darkweak]

Hey @alistairjevans thank you for your feedback. Do you have a configuration to reproduce that? I'm trying with the given configuration without any issue.

# Caddyfile
{
    debug
    cache {
        ttl 1000s
    }
}

localhost {
    route {
        cache
        respond "Hello world!"
    }
}

> curl https://localhost/default --head
HTTP/2 200 
alt-svc: h3=":443"; ma=2592000
cache-control: 
cache-status: Souin; fwd=uri-miss; stored; key=HEAD-https-localhost-/default
content-type: text/plain; charset=utf-8
server: Caddy
content-length: 12
date: Thu, 14 Nov 2024 20:29:55 GMT

> curl https://localhost/default --head
HTTP/2 200 
age: 1
alt-svc: h3=":443"; ma=2592000
cache-control: 
cache-status: Souin; hit; ttl=999; key=HEAD-https-localhost-/default; detail=DEFAULT
content-type: text/plain; charset=utf-8
date: Thu, 14 Nov 2024 20:29:55 GMT
server: Caddy
content-length: 12

[alistairjevans]

Hi @darkweak; some details adjusted for privacy, but this is basically the config; nothing too complicated:

{
    on_demand_tls
    servers {
        metrics
    }
    cache {
        cache_name sc
    }
}

# Catch-all for any domain
:443 {
    tls {
        on_demand
    }

    cache {
      key {
       hide
       headers Accept-Language
      }
      mode bypass_request
    }

    # Reverse proxy to our app
    reverse_proxy https://myhost.example.com {
        header_up Host {upstream_hostport}
        header_up X-Real-IP {http.request.remote.host}
    }
}

This is proxying to a Rails app, running on Rack. Interestingly, when I perform a HEAD request directly to our app, I get a content-length header of '0' returned; with a GET this page would return content. Again some details omitted:

curl --head https://myhost.example.com
HTTP/2 200
alt-svc: h3=":443"; ma=2592000
cache-control: max-age=0, public, s-maxage=3, stale-while-revalidate=3
content-type: text/html; charset=utf-8
date: Thu, 14 Nov 2024 20:39:02 GMT
referrer-policy: strict-origin-when-cross-origin
server: Caddy
server: nginx
strict-transport-security: max-age=63113904; includeSubDomains; preload
vary: Accept
x-content-type-options: nosniff
x-download-options: noopen
x-permitted-cross-domain-policies: none
x-request-id: 42767e6f-8191-4eca-849f-ece005894173
x-runtime: 0.172931
x-xss-protection: 0
content-length: 0

Is it related to the 0 content-length response possibly?

[darkweak]

@alistairjevans Thanks, I tries to reproduce but unfortunately it worked well during my tests. I checked more about Rack and RoR (I'm not a RoR dev so that's new to me) and I think that's the streaming response (or something related to RoR/Rack).

FYI: I DM'ed you on Twitter/X if you don't want to send some sensitive data here if needed.

Thank you for your time for answering to my questions.

[imlonghao]

This issue looks exactly like my previous issue #104

Which version of souin are you using?

[alistairjevans]

Hi @imlonghao, I'm on 0.15.0 of cache-handler; does that pull in the right Souin version to include your fix?

RUN xcaddy build \
    --with github.com/pberkel/caddy-storage-redis@v1.3.0 \
    --with github.com/caddyserver/cache-handler@v0.15.0 \
    --with github.com/darkweak/storages/go-redis/caddy \
    --with github.com/aksdb/caddy-cgi@v2.2.3

[imlonghao]

I tried your build command with my previous example, works well in my cases.

github.com/caddyserver/cache-handler@v0.15.0 included my fix as it required github.com/darkweak/souin v1.7.5

I don't mean to be offense, but how did you manage your image version?
Did you just change the Dockerfile then run docker compose up -d, forgot running docker compose build? Maybe?

[alistairjevans]

This container is deployed into production via CI docker builds and pulled onto each host before the docker swarm deploy.

Not saying it's impossible something has broken here, just that it's unlikely. When I get a chance I'll manually check the build versions on the running container to double check.

[alistairjevans]

Can confirm both 0.15.0 of cache-handler and 1.7.5 of souin are running in that container, care of caddy build-info.

If you're confident there's no other path that can cause this failure @imlonghao, I'll try enabling HEAD caching again in case the container got updated correctly since I last checked.

[darkweak]

@alistairjevans can you run with verbose and paste the logs? Did you find time to work on a reproducible repository?

[alistairjevans]

Apologies, I haven't found time to get back to this issue; will try to do so in the coming weeks. The issue may be moot though if #114 isn't fixed, because we'll have to change caching proxy entirely.