cache-handler icon indicating copy to clipboard operation
cache-handler copied to clipboard

Published 20 hours ago • verified publisher icon caddyserver

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

Open digipigeon opened this issue 8 months ago • 1 comments

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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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
	}
}

digipigeon avatar Jun 17 '24 09:06 digipigeon