search

caddyserver / cache-handler

Distributed HTTP caching module for Caddy
Apache License 2.0
262 stars 19 forks source link

CRASH: panic: Header called after Handler finished - /souin/pkg/middleware.(*SouinBaseHandler).Upstream.func1() #87

Closed digipigeon closed 1 month ago

digipigeon commented 3 months ago

Hello

We are experiencing an issue with (what I beleive to be) this library. We don't know what causes triggers this issue, starting the server is fine, testing routes is fine. After an unspecified amount of the server seems to crash and stops being able to serve requests.

Below is a log example.

Jun 17 04:33:34 caddy[2244740]: caddy.HomeDir=/var/lib/caddy
Jun 17 04:33:34 caddy[2244740]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Jun 17 04:33:34 caddy[2244740]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Jun 17 04:33:34 caddy[2244740]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Jun 17 04:33:34 caddy[2244740]: caddy.Version=v2.8.4 h1:q3pe0wpBj1OcHFZ3n/1nl4V4bxBrYoSoab7rL9BMYNk=
Jun 17 04:33:34 caddy[2244740]: runtime.GOOS=linux
Jun 17 04:33:34 caddy[2244740]: runtime.GOARCH=amd64
Jun 17 04:33:34 caddy[2244740]: runtime.Compiler=gc
Jun 17 04:33:34 caddy[2244740]: runtime.NumCPU=2
Jun 17 04:33:34 caddy[2244740]: runtime.GOMAXPROCS=2
Jun 17 04:33:34 caddy[2244740]: runtime.Version=go1.22.3
Jun 17 04:33:34 caddy[2244740]: os.Getwd=/
Jun 17 04:33:34 caddy[2244740]: LANG=en_US.UTF-8
Jun 17 04:33:34 caddy[2244740]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
Jun 17 04:33:34 caddy[2244740]: NOTIFY_SOCKET=/run/systemd/notify
Jun 17 04:33:34 caddy[2244740]: HOME=/var/lib/caddy
Jun 17 04:33:34 caddy[2244740]: LOGNAME=caddy
Jun 17 04:33:34 caddy[2244740]: USER=caddy
Jun 17 04:33:34 caddy[2244740]: INVOCATION_ID=81fe07d20e394253b5e5f5127c5d10dd
Jun 17 04:33:34 caddy[2244740]: JOURNAL_STREAM=8:111748102
Jun 17 04:33:34 caddy[2244740]: SYSTEMD_EXEC_PID=2244740
Jun 17 04:33:34 caddy[2244740]: {"level":"info","ts":1718598814.526974,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
Jun 17 04:33:34 caddy[2244740]: {"level":"info","ts":1718598814.532107,"msg":"adapted config to JSON","adapter":"caddyfile"}
Jun 17 04:33:34 caddy[2244740]: {"level":"warn","ts":1718598814.5322819,"msg":"Caddyfile input is not formatted; run 'caddy fmt --overwrite' to fix inconsistencies","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":13}
Jun 17 04:33:34 caddy[2244740]: {"level":"info","ts":1718598814.5344057,"msg":"redirected default logger","from":"stderr","to":"/var/log/caddy/access.log"}
Jun 17 04:33:35 systemd[1]: Started Caddy.
Jun 17 05:53:11 caddy[2244740]: panic: Header called after Handler finished [recovered]
Jun 17 05:53:11 caddy[2244740]:         panic: interface conversion: string is not error: missing method Error
Jun 17 05:53:11 caddy[2244740]: goroutine 505551 [running]:
Jun 17 05:53:11 caddy[2244740]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream.func1()
Jun 17 05:53:11 caddy[2244740]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:357 +0x77
Jun 17 05:53:11 caddy[2244740]: panic({0x1fbf800?, 0x2a9f3e0?})
Jun 17 05:53:11 caddy[2244740]:         runtime/panic.go:770 +0x132
Jun 17 05:53:11 caddy[2244740]: golang.org/x/net/http2.(*responseWriter).Header(0x2?)
Jun 17 05:53:11 caddy[2244740]:         golang.org/x/net@v0.25.0/http2/server.go:2866 +0x6d
Jun 17 05:53:11 caddy[2244740]: github.com/darkweak/souin/pkg/middleware.(*CustomWriter).Header(0xc0194ccf80?)
Jun 17 05:53:11 caddy[2244740]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/writer.go:49 +0xb8
Jun 17 05:53:11 caddy[2244740]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream(0xc00017fe00, 0xc0194ccf80, 0xc01961cea0, 0xc01953b660, 0xc0195bb0e0, {0xc01a8077c0, 0x48})
Jun 17 05:53:11 caddy[2244740]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:421 +0x608
Jun 17 05:53:11 caddy[2244740]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP.func4(0xc01961cea0, 0xc0194ccf80)
Jun 17 05:53:11 caddy[2244740]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:733 +0xf5
Jun 17 05:53:11 caddy[2244740]: created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP in goroutine 505548
Jun 17 05:53:11 caddy[2244740]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:731 +0x1410
Jun 17 05:53:11 systemd[1]: caddy.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Jun 17 05:53:11 systemd[1]: caddy.service: Failed with result 'exit-code'.
Jun 17 05:53:11 systemd[1]: caddy.service: Consumed 1min 47.348s CPU time.

Also an eariler crash with large bt:

Jun 17 03:14:06 caddy[2183077]: panic: Header called after Handler finished
Jun 17 03:14:06 caddy[2183077]: runtime/debug.Stack()
Jun 17 03:14:06 caddy[2183077]:         runtime/debug/stack.go:24 +0x5e
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.newPanicError({0x1fbf800, 0x2a9f3e0})
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:44 +0x25
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall.func2.1()
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:193 +0x34
Jun 17 03:14:06 caddy[2183077]: panic({0x1fbf800?, 0x2a9f3e0?})
Jun 17 03:14:06 caddy[2183077]:         runtime/panic.go:770 +0x132
Jun 17 03:14:06 caddy[2183077]: golang.org/x/net/http2.(*responseWriter).Header(0xc01c2e75c8?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/net@v0.25.0/http2/server.go:2866 +0x6d
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*CustomWriter).Header(0xc017e1cfc0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/writer.go:49 +0xb8
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp/headers.Handler.ServeHTTP({0x0?, 0xc0002802d0?}, {0x2ab8780, 0xc0180767c0}, 0xc0159c1680, {0x2aa8a80, 0xc017e1d230})
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/headers/headers.go:106 +0x226
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x2ab8780, 0xc0180767c0}, 0xc0159c1680)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/routes.go:333 +0xd2
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x30?, {0x2ab8780?, 0xc0180767c0?}, 0xc0183703c0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/caddyhttp.go:58 +0x29
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/cache-handler.(*SouinCaddyMiddleware).ServeHTTP.func1({0x2ab8780?, 0xc0180767c0?}, 0xc0006a1ef0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/cache-handler@v0.13.0/httpcache.go:88 +0x33
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream.func2()
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:366 +0x9a
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall.func2(0xc01c2e7b6e, 0xc015dfc9b0, 0xc000423808?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:198 +0x64
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall(0x20ce620?, 0xc0006acdb0?, {0xc000299720?, 0x48?}, 0xc01c2e7c10?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:200 +0x96
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).Do(0xc000003348, {0xc000299720, 0x48}, 0xc01c2e7ec0)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:113 +0x15a
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream(0xc000003200, 0xc0180767c0, 0xc016956000, 0xc00009ad20, 0xc017e1d4a0, {0xc000299720, 0x48})
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:365 +0x287
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP.func4(0xc016956000, 0xc0180767c0)
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:733 +0xf5
Jun 17 03:14:06 caddy[2183077]: created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP in goroutine 3690504
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:731 +0x1410
Jun 17 03:14:06 caddy[2183077]:  [recovered]
Jun 17 03:14:06 caddy[2183077]:         panic: Header called after Handler finished
Jun 17 03:14:06 caddy[2183077]: runtime/debug.Stack()
Jun 17 03:14:06 caddy[2183077]:         runtime/debug/stack.go:24 +0x5e
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.newPanicError({0x1fbf800, 0x2a9f3e0})
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:44 +0x25
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall.func2.1()
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:193 +0x34
Jun 17 03:14:06 caddy[2183077]: panic({0x1fbf800?, 0x2a9f3e0?})
Jun 17 03:14:06 caddy[2183077]:         runtime/panic.go:770 +0x132
Jun 17 03:14:06 caddy[2183077]: golang.org/x/net/http2.(*responseWriter).Header(0xc01c2e75c8?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/net@v0.25.0/http2/server.go:2866 +0x6d
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*CustomWriter).Header(0xc017e1cfc0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/writer.go:49 +0xb8
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp/headers.Handler.ServeHTTP({0x0?, 0xc0002802d0?}, {0x2ab8780, 0xc0180767c0}, 0xc0159c1680, {0x2aa8a80, 0xc017e1d230})
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/headers/headers.go:106 +0x226
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x2ab8780, 0xc0180767c0}, 0xc0159c1680)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/routes.go:333 +0xd2
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x30?, {0x2ab8780?, 0xc0180767c0?}, 0xc0183703c0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/caddyhttp.go:58 +0x29
Jun 17 03:14:06 caddy[2183077]: github.com/caddyserver/cache-handler.(*SouinCaddyMiddleware).ServeHTTP.func1({0x2ab8780?, 0xc0180767c0?}, 0xc0006a1ef0?)
Jun 17 03:14:06 caddy[2183077]:         github.com/caddyserver/cache-handler@v0.13.0/httpcache.go:88 +0x33
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream.func2()
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:366 +0x9a
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall.func2(0xc01c2e7b6e, 0xc015dfc9b0, 0xc000423808?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:198 +0x64
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall(0x20ce620?, 0xc0006acdb0?, {0xc000299720?, 0x48?}, 0xc01c2e7c10?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:200 +0x96
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).Do(0xc000003348, {0xc000299720, 0x48}, 0xc01c2e7ec0)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:113 +0x15a
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream(0xc000003200, 0xc0180767c0, 0xc016956000, 0xc00009ad20, 0xc017e1d4a0, {0xc000299720, 0x48})
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:365 +0x287
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP.func4(0xc016956000, 0xc0180767c0)
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:733 +0xf5
Jun 17 03:14:06 caddy[2183077]: created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP in goroutine 3690504
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:731 +0x1410
Jun 17 03:14:06 caddy[2183077]: goroutine 3690517 [running]:
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream.func1()
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:361 +0xf3
Jun 17 03:14:06 caddy[2183077]: panic({0x2109300?, 0xc017e1d710?})
Jun 17 03:14:06 caddy[2183077]:         runtime/panic.go:770 +0x132
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall.func1()
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:170 +0x2b3
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).doCall(0x20ce620?, 0xc0006acdb0?, {0xc000299720?, 0x48?}, 0xc01c2e7c10?)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:205 +0xb1
Jun 17 03:14:06 caddy[2183077]: golang.org/x/sync/singleflight.(*Group).Do(0xc000003348, {0xc000299720, 0x48}, 0xc01c2e7ec0)
Jun 17 03:14:06 caddy[2183077]:         golang.org/x/sync@v0.7.0/singleflight/singleflight.go:113 +0x15a
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream(0xc000003200, 0xc0180767c0, 0xc016956000, 0xc00009ad20, 0xc017e1d4a0, {0xc000299720, 0x48})
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:365 +0x287
Jun 17 03:14:06 caddy[2183077]: github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP.func4(0xc016956000, 0xc0180767c0)
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:733 +0xf5
Jun 17 03:14:06 caddy[2183077]: created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP in goroutine 3690504
Jun 17 03:14:06 caddy[2183077]:         github.com/darkweak/souin@v1.6.49/pkg/middleware/middleware.go:731 +0x1410

A redacted & reduced config looks like this...

{
    ...
    log
}

https:// http:// {
    route {
        header -Server
        cache {
            stale 1d
            ttl 1d
        }
        header Cache-Control "public, max-age=86400";
        header X-CX-Edge-Cache $upstream_cache_status;
        reverse_proxy * https://redacted.domain {
        header_up Host redacted.domain
    }
}
darkweak commented 3 months ago

Hello @digipigeon thank you for your issue.

Reading these logs, I suspect two things

I will investigate on it, but that will be tricky to reproduce.