cache-handler: Panic if abort directive is used

/etc/caddy/Caddyfile:

{
        order cache before rewrite
        cache
}

:80 {
        cache
        abort
}

Start caddy, then do curl http://127.0.0.1. Result: Caddy dies.

Feb 13 12:40:18 desrv systemd[1]: Started Caddy.
Feb 13 12:40:18 desrv caddy[4509]: {"level":"info","ts":1676320818.3576553,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00057b5e0"}
Feb 13 12:40:18 desrv caddy[4509]: {"level":"info","ts":1676320818.3577983,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Feb 13 12:40:18 desrv caddy[4509]: {"level":"info","ts":1676320818.3579395,"logger":"tls","msg":"finished cleaning storage units"}
Feb 13 12:40:18 desrv caddy[4509]: {"level":"info","ts":1676320818.3581178,"msg":"serving initial configuration"}
Feb 13 12:40:43 desrv caddy[4509]: panic: net/http: abort Handler
Feb 13 12:40:43 desrv caddy[4509]: goroutine 50 [running]:
Feb 13 12:40:43 desrv caddy[4509]: github.com/caddyserver/caddy/v2/modules/caddyhttp.StaticResponse.ServeHTTP({{0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0, 0x1}, {0x24f43a0?, 0xc0001f6780?}, 0xc0000b8300, ...)
Feb 13 12:40:43 desrv caddy[4509]:         github.com/caddyserver/caddy/v2@v2.6.3/modules/caddyhttp/staticresp.go:184 +0xa38
Feb 13 12:40:43 desrv caddy[4509]: github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x24f43a0?, 0xc0001f6780?}, 0xc0006f0070?)
Feb 13 12:40:43 desrv caddy[4509]:         github.com/caddyserver/caddy/v2@v2.6.3/modules/caddyhttp/routes.go:290 +0x42
Feb 13 12:40:43 desrv caddy[4509]: github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x4487b9?, {0x24f43a0?, 0xc0001f6780?}, 0xffffffffffffffff?)
Feb 13 12:40:43 desrv caddy[4509]:         github.com/caddyserver/caddy/v2@v2.6.3/modules/caddyhttp/caddyhttp.go:58 +0x2f
Feb 13 12:40:43 desrv caddy[4509]: github.com/caddyserver/cache-handler.(*SouinCaddyPlugin).ServeHTTP.func1({0x0?, 0x185f960?}, 0xc0006f0070?)
Feb 13 12:40:43 desrv caddy[4509]:         github.com/caddyserver/cache-handler@v0.4.0/httpcache.go:129 +0x62
Feb 13 12:40:43 desrv caddy[4509]: github.com/darkweak/souin/plugins.DefaultSouinPluginCallback.func2({0x24f43a0?, 0xc0001f6780?}, 0xf?)
Feb 13 12:40:43 desrv caddy[4509]:         github.com/darkweak/souin@v1.6.27/plugins/base.go:210 +0x7a
Feb 13 12:40:43 desrv caddy[4509]: created by github.com/darkweak/souin/plugins.DefaultSouinPluginCallback
Feb 13 12:40:43 desrv caddy[4509]:         github.com/darkweak/souin@v1.6.27/plugins/base.go:206 +0x81b
Feb 13 12:40:43 desrv systemd[1]: caddy.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Feb 13 12:40:43 desrv systemd[1]: caddy.service: Failed with result 'exit-code'.
$ /usr/bin/caddy version
v2.6.3 h1:QRVBNIqfpqZ1eJacY44I6eUC1OcxQ8D04EKImzpj7S8=

Built about 15 minutes ago with xcaddy build --with github.com/caddyserver/cache-handler

This is a minimal repro. I have a service that only approved IPs are able to access, otherwise Caddy aborts the request, and when I hit it from an unapproved IP after adding caching it killed Caddy.

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 20 (2 by maintainers)

Most upvoted comments

It appears to be working, I can’t find any further issue. Thanks!

@AlyoshaVasilieva Can you try with xcaddy build --with github.com/darkweak/souin@f05fcc6808b9ba8cc61833b329b0b2b4697a2ad7 --with github.com/darkweak/souin/plugins/caddy@f05fcc6808b9ba8cc61833b329b0b2b4697a2ad7?

I’ll have a look at that and try to fix this weird behavior. I will add some e2e test cases to ensure redis works well.

It no longer panics! However, when trying to use redis requests hang forever.

{
        order cache before rewrite
        cache {
                timeout {
                        backend 2s
                        cache 30ms
                }
        }
}

:80 {
        cache {
                redis {
                        configuration {
                                Addr 127.0.0.1:6379
                                DialTimeout 2s
                                ReadTimeout 5s
                                WriteTimeout 5s
                                PoolTimeout 10s
                        }
                }
        }
        respond "Hello"
}

I’ve set all those timeouts in an attempt to make it timeout and issue an HTTP error, but it doesn’t:

$ curl http://127.0.0.1:80 -v --max-time 60
*   Trying 127.0.0.1:80...
* Connected to 127.0.0.1 (127.0.0.1) port 80 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1
> User-Agent: curl/7.74.0
> Accept: */*
>
* Operation timed out after 60000 milliseconds with 0 bytes received
* Closing connection 0
curl: (28) Operation timed out after 60000 milliseconds with 0 bytes received

I’m not actually sure I’ve set it up correctly, but I’m not getting any error messages.

After attempting to enable logging*, this is all I see in the logs:

Mar 01 09:16:26 desrv systemd[1]: Starting Caddy...
Mar 01 09:16:26 desrv caddy[21809]: caddy.HomeDir=/var/lib/caddy
Mar 01 09:16:26 desrv caddy[21809]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Mar 01 09:16:26 desrv caddy[21809]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Mar 01 09:16:26 desrv caddy[21809]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Mar 01 09:16:26 desrv caddy[21809]: caddy.Version=v2.6.4 h1:2hwYqiRwk1tf3VruhMpLcYTg+11fCdr8S3jhNAdnPy8=
Mar 01 09:16:26 desrv caddy[21809]: runtime.GOOS=linux
Mar 01 09:16:26 desrv caddy[21809]: runtime.GOARCH=amd64
Mar 01 09:16:26 desrv caddy[21809]: runtime.Compiler=gc
Mar 01 09:16:26 desrv caddy[21809]: runtime.NumCPU=1
Mar 01 09:16:26 desrv caddy[21809]: runtime.GOMAXPROCS=1
Mar 01 09:16:26 desrv caddy[21809]: runtime.Version=go1.20
Mar 01 09:16:26 desrv caddy[21809]: os.Getwd=/
Mar 01 09:16:26 desrv caddy[21809]: LANG=en_US.UTF-8
Mar 01 09:16:26 desrv caddy[21809]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
Mar 01 09:16:26 desrv caddy[21809]: NOTIFY_SOCKET=/run/systemd/notify
Mar 01 09:16:26 desrv caddy[21809]: HOME=/var/lib/caddy
Mar 01 09:16:26 desrv caddy[21809]: LOGNAME=caddy
Mar 01 09:16:26 desrv caddy[21809]: USER=caddy
Mar 01 09:16:26 desrv caddy[21809]: INVOCATION_ID=69251e0770554977adcd78ca4994c93f
Mar 01 09:16:26 desrv caddy[21809]: JOURNAL_STREAM=8:365012
Mar 01 09:16:26 desrv caddy[21809]: {"level":"info","ts":1677690986.5054333,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.509        INFO        admin        admin endpoint started        {"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.509        WARN        http        server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server        {"server_name": "srv0", "http_port": 80}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        DEBUG        http.handlers.cache        Storer initialized.
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        DEBUG        http.handlers.cache        Surrogate storage initialized.
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        DEBUG        http.handlers.cache        Set Souin as Cache-Status name
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        DEBUG        http.handlers.cache        Allow 2 method(s). [GET HEAD].
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        INFO        http.handlers.cache        Set backend timeout to 2s
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        INFO        http.handlers.cache        Set cache timeout to 2s
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.510        INFO        http.handlers.cache        Souin configuration is now loaded.
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.511        DEBUG        http        starting server loop        {"address": "[::]:80", "tls": false, "http3": false}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.511        INFO        http.log        server running        {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.511        INFO        autosaved config (load with --resume flag)        {"file": "/var/lib/caddy/.config/caddy/autosave.json"}
Mar 01 09:16:26 desrv systemd[1]: Started Caddy.
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.514        INFO        serving initial configuration
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.514        INFO        tls.cache.maintenance        started background certificate maintenance        {"cache": "0xc00056b880"}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.514        INFO        tls        cleaning storage unit        {"description": "FileStorage:/var/lib/caddy/.local/share/caddy"}
Mar 01 09:16:26 desrv caddy[21809]: 2023/03/01 17:16:26.514        INFO        tls        finished cleaning storage units

* caddyfile:

{
        debug
        log {
                level debug
                format console
                output stderr
        }
        order cache before rewrite
        cache {
                timeout {
                        backend 2s
                        cache 30ms
                }
        }
}

:80 {
        log {
                level debug
                format console
                output stderr
        }
        cache {
                redis {
                        configuration {
                                Addr 127.0.0.1:6379
                                DialTimeout 2s
                                ReadTimeout 5s
                                WriteTimeout 5s
                                PoolTimeout 10s
                        }
                }
        }
        respond "Hello"
}

Well, it’s a different issue now, the original one seems solved. This is a huge improvement over panicking, so thank you!

It’s now available using xcaddy build --with github.com/darkweak/souin/plugins/caddy

The release is currently running 🤞

Correct - but more specifically, go get does not respect replace.

I think xcaddy doesn’t fetch packages respecting the replace directive. I think you’ll have to fetch the repository, go to the feat/chore/refactoring-to-middleware-philosophy branch and run the xcaddy build in the souin/plugins/caddy directory.

git clone https://github.com/darkweak/souin
cd souin
git checkout feat/chore/refactoring-to-middleware-philosophy
cd plugins/caddy
xcaddy build --with github.com/darkweak/souin/plugins/caddy=./ --with github.com/darkweak/souin=../..

I’ll try to release that asap to avoid these build constaints.

It seems the next minor version I’m working on patch that behavior and prevent the panic (https://github.com/darkweak/souin/compare/master...feat/chore/refactoring-to-middleware-philosophy) and I plan to release that on the next week. Can you wait for that?

Hello @AlyoshaVasilieva thanks for this report, I’ll try to fix that. Thank you for the minimal reproductible example.