Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
Tracked by #536
digipigeon opened this issue Jun 17, 2024 · 1 comment · Fixed by darkweak/souin#536

Comments

@digipigeon
Copy link

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
	}
}

@darkweak
Copy link
Collaborator

Hello @digipigeon thank you for your issue.

Reading these logs, I suspect two things

  • There were at least two coalesced requests on the same endpoint, call them clientA (first) and clientB (second), clientA canceled his request that caused the first error
  • The singleflight call doesn't handle the canceled requests because the weird thing is about the response headers that have been accessed when the request got canceled in the second error

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants