cache-handler
cache-handler copied to clipboard
Published
20 hours ago •
caddyserver
caddyserver
fatal errors are not logged
I'm trying to use the cache handler and it wasn't working. The symptom:
tve@cloud /h/caddy> curl -o /dev/null 'https://example.com/data/binary/tagVisits'
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- 0:00:07 --:--:-- 0
curl: (92) HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)
Only after I turned on debug logging I got:
Oct 10 09:12:24 cloud caddy[2743409]: {"level":"debug","ts":1665418344.1734848,"logger":"http.stdlib
","msg":"http2: panic serving 0.0.0.0:56316: Impossible to set value into Badger, Value with si
ze 2779485 exceeded 1048576 limit. Value:\n00000000 48 54 54 50 2f 30 2e 30 20 32 30 30 20 4f 4b 0
d |HTTP/0.0 200 OK.|\n00000010 0a 41 6c 74 2d 53 76 63 3a 20 68 33 3d 22 3a 34 |.Alt-Svc: h3=\":
- why is this error not logged without debug?
- why is there a panic?
- it looks to me like this 'badger' thing needs some config to cache >1MB? do I now need to go on a quest to figure out what badger is, why http.cache uses it, and how to configure it?
What is the full error message? It should have a stack trace.
Code somewhere is panicking -- it definitely should not be -- and the std lib is catching it. Because the Go standard library is catching it and emitting the log, the log is treated as DEBUG level, as std lib logs are usually noise in the context of Caddy.
Because the Go standard library is catching it and emitting the log, the log is treated as DEBUG level, as std lib logs are usually noise in the context of Caddy.
Maybe it would be a good idea to pattern match stack backtraces and emit some error log entry to indicate that something is gone horribly awry?
Here's the backtrace as it appears in the log:
goroutine 1500 [running]:\nnet/
http.(*http2serverConn).runHandler.func1()\n\tnet/http/h2_bundle.go:5904 +0x125\npanic({0x19dc500, 0
xc000105d60})\n\truntime/panic.go:884 +0x212\ngithub.com/darkweak/souin/cache/providers.(*Badger).Se
t(0xc000104130, {0xc00075ba10, 0x2e}, {0xc01eb84000, 0x2a695d, 0x400000}, {{0x34630b8a000}, {0x2ecbb
98, 0x0, 0x0}, ...}, ...)\n\tgithub.com/darkweak/[email protected]/cache/providers/badgerProvider.go:138
+0x229\ngithub.com/darkweak/souin/rfc.(*VaryTransport).SetCache(0xc000124bd0, {0xc00075ba10, 0x2e},
0xc000439a70)\n\tgithub.com/darkweak/[email protected]/rfc/transport.go:85 +0x263\ngithub.com/darkweak/so
uin/rfc.validateVary.func1({0x20ad6c0, 0xc009bead80})\n\tgithub.com/darkweak/[email protected]/rfc/vary.g
o:37 +0x198\ngithub.com/darkweak/souin/rfc.(*cachingReadCloser).Read(0xc000288f40, {0xc01e1e080a, 0x
46000?, 0xa37f6})\n\tgithub.com/darkweak/[email protected]/rfc/standalone.go:352 +0x177\nio.ReadAll({0x7f
b7e1063b40, 0xc000288f40})\n\tio/io.go:661 +0xfe\nio/ioutil.ReadAll(...)\n\tio/ioutil/ioutil.go:27\n
github.com/darkweak/souin/plugins.(*CustomWriter).Send(0xc00013d220)\n\tgithub.com/darkweak/souin@v1
.6.6/plugins/base.go:68 +0x20f\ngithub.com/caddyserver/cache-handler.(*SouinCaddyPlugin).ServeHTTP.f
unc1({0x1a66840?, 0xc00003a060?}, 0x1d5c566?)\n\tgithub.com/caddyserver/[email protected]/httpcac
he.go:105 +0x10f\ngithub.com/darkweak/souin/plugins.DefaultSouinPluginCallback({0x20bc5c0, 0xc00013d
220}, 0xc00053ea00, {0x20cd618, 0xc0005a87e0}, {0x0, 0x0}, 0xc00044f4f0)\n\tgithub.com/darkweak/soui
[email protected]/plugins/base.go:178 +0x6df\ngithub.com/caddyserver/cache-handler.(*SouinCaddyPlugin).ServeH
TTP(0xc00f25dd00, {0x7fb7e104cae0?, 0xc009954ae0}, 0xc00053e400, {0x20b3dc0, 0xc00013d1e0})\n\tgithu
b.com/caddyserver/[email protected]/httpcache.go:93 +0x69a\ngithub.com/caddyserver/caddy/v2/modul
es/caddyhttp.wrapMiddleware.func1.1({0x7fb7e104cae0?, 0xc009954ae0?}, 0x20b3dc0?)\n\tgithub.com/cadd
yserver/caddy/[email protected]/modules/caddyhttp/routes.go:290 +0x42\ngithub.com/caddyserver/caddy/v2/modul
es/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0x0?)\n\tgithub.com
/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f\ngithub.com/caddyserver/caddy/v
2/modules/caddyhttp.wrapRoute.func1.1({0x7fb7e104cae0, 0xc009954ae0}, 0xc00053e400)\n\tgithub.com/ca
ddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:259 +0x3a8\ngithub.com/caddyserver/caddy/v2/mo
dules/caddyhttp.HandlerFunc.ServeHTTP(0xc00010b8c0?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0x20b3dc0?)\n
\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f\ngithub.com/caddyse
rver/caddy/v2/modules/caddyhttp.(*Subroute).ServeHTTP(0xc008fe1d40, {0x7fb7e104cae0, 0xc009954ae0},
0x1?, {0x20b3dc0, 0xc00013d160})\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/subrout
e.go:74 +0x6d\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x7fb7e104c
ae0?, 0xc009954ae0?}, 0x20b3dc0?)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes
.go:290 +0x42\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {
0x7fb7e104cae0?, 0xc009954ae0?}, 0x0?)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/c
addyhttp.go:58 +0x2f\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x7fb7e10
4cae0, 0xc009954ae0}, 0xc00053e400)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/rout
es.go:259 +0x3a8\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x1a66840?
, {0x7fb7e104cae0?, 0xc009954ae0?}, 0xe?)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhtt
p/caddyhttp.go:58 +0x2f\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x7fb7
e104cae0, 0xc009954ae0}, 0xc00053e400)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/r
outes.go:227 +0x336\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc0094
05500?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0x20b3dc0?)\n\tgithub.com/caddyserver/caddy/[email protected]/modu
les/caddyhttp/caddyhttp.go:58 +0x2f\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.(*Subroute).S
erveHTTP(0xc008fe1a20, {0x7fb7e104cae0, 0xc009954ae0}, 0x19d8201?, {0x20b3dc0, 0x1e04120})\n\tgithub
.com/caddyserver/caddy/[email protected]/modules/caddyhttp/subroute.go:74 +0x6d\ngithub.com/caddyserver/cadd
y/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x7fb7e104cae0?, 0xc009954ae0?}, 0x20b3dc0?)\n\tgithu
b.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:290 +0x42\ngithub.com/caddyserver/cadd
y/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0xc0096e3
498?)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f\ngithub.com/
caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x7fb7e104cae0, 0xc009954ae0}, 0xc00053e40
0)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:259 +0x3a8\ngithub.com/cadd
yserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x2?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0x7
fb8087b85b8?)\n\tgithub.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f\ngit
hub.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).enforcementHandler(0x40dca7?, {0x7fb7e104ca
e0?, 0xc009954ae0?}, 0x1?, {0x20b3dc0?, 0xc00013c960?})\n\tgithub.com/caddyserver/caddy/[email protected]/mo
dules/caddyhttp/server.go:370 +0x252\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).wr
apPrimaryRoute.func1({0x7fb7e104cae0?, 0xc009954ae0?}, 0x4cab37?)\n\tgithub.com/caddyserver/caddy/v2
@v2.6.1/modules/caddyhttp/server.go:346 +0x3b\ngithub.com/caddyserver/caddy/v2/modules/caddyhttp.Han
dlerFunc.ServeHTTP(0xc00937f1e0?, {0x7fb7e104cae0?, 0xc009954ae0?}, 0xc00053e400?)\n\tgithub.com/cad
dyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f\ngithub.com/caddyserver/caddy/v2/mo
dules/caddyhttp.(*Server).ServeHTTP(0xc00010ab40, {0x20bfbc0, 0xc000124fe0}, 0xc00053e400)\n\tgithub
.com/caddyserver/caddy/[email protected]/modules/caddyhttp/server.go:282 +0xb55\nnet/http.serverHandler.Serv
eHTTP({0x3bf1555da0ee5502?}, {0x20bfbc0, 0xc000124fe0}, 0xc00053e200)\n\tnet/http/server.go:2947 +0x
30c\nnet/http.initALPNRequest.ServeHTTP({{0x20c1978?, 0xc009954690?}, 0xc009445c00?, {0xc0001f6f00?}
}, {0x20bfbc0, 0xc000124fe0}, 0xc00053e200)\n\tnet/http/server.go:3556 +0x245\nnet/http.(*http2serve
rConn).runHandler(0xffd60e56fcd40e?, 0x2b00000200a20000?, 0x569aaa0956020042?, 0xa42b0000a1ab09?)\n\
tnet/http/h2_bundle.go:5911 +0x78\ncreated by net/http.(*http2serverConn).processHeaders\n\tnet/http
/h2_bundle.go:5641 +0x5b9"}
how did you compile cdp-cache? Which version of go? What command?
What is your caddy file. ?
how did you compile cdp-cache? Which version of go? What command?
What is your caddy file. ?
Please ignore (I've deleted the comment I had made), I got mixed up and thought the backtraces were the same. The crash with cdp-cache was due to using caddy 2.5.1.
Caddy version, built today using website "download" by adding just the caddyserver/cache-handler module:
> /home/caddy/caddy version
v2.6.1 h1:EDqo59TyYWhXQnfde93Mmv4FJfYe00dO60zMiEt+pzo=
Caddy config file for repro:
{
log {
level debug
}
order cache before rewrite
cache {
log_level debug
}
}
www.sensorgnome.net {
bind 10.200.1.210
route /data/* {
cache {
badger {
configuration {
MemTableSize 8000000
ValueThreshold 4000000
}
}
}
reverse_proxy https://motus.org {
header_up Host motus.org
}
}
}
Command to repro:
/h/s/caddy> curl -L 'https://www.sensorgnome.net/data/binary/tagVisits'
curl: (92) HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)
Took 7s
Running caddy with error output:
tve@cloud /h/caddy [1]> sudo /home/caddy/caddy run --config /etc/caddy/Caddyfile
2022/10/10 19:11:46.725 INFO using provided configuration {"config_file": "/etc/caddy/Caddyfil
e", "config_adapter": ""}
...
2022/10/10 19:12:05.347 DEBUG http.handlers.reverse_proxy selected upstream {"dial": "mo
tus.org:443", "total_upstreams": 1}
2022/10/10 19:12:11.957 DEBUG http.handlers.reverse_proxy upstream roundtrip {"upstream":
"motus.org:443", "duration": 6.609447653, "request": {"remote_ip": "47.151.203.177", "remote_port":
"34188", "proto": "HTTP/2.0", "method": "GET", "host": "motus.org", "uri": "/data/binary/tagVisits"
, "headers": {"X-Forwarded-Proto": ["https"], "X-Forwarded-Host": ["www.sensorgnome.net"], "User-Age
nt": ["curl/7.85.0"], "Accept": ["*/*"], "Date": ["Mon, 10 Oct 2022 19:12:05 UTC"], "X-Forwarded-For
": ["47.151.203.177"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2
", "server_name": "www.sensorgnome.net"}}, "headers": {"Set-Cookie": [], "Content-Type": ["applicati
on/octet-stream"], "Server": ["Microsoft-IIS/8.5"], "Date": ["Mon, 10 Oct 2022 19:12:11 GMT"], "Cont
ent-Length": ["2779146"], "X-Powered-By": ["ASP.NET"]}, "status": 200}
2022/10/10 19:12:12.676 DEBUG http.stdlib http2: panic serving 47.151.203.177:34188: Impossibl
e to set value into Badger, Value with size 2779483 exceeded 1048576 limit. Value:
00000000 48 54 54 50 2f 30 2e 30 20 32 30 30 20 4f 4b 0d |HTTP/0.0 200 OK.|
00000010 0a 41 6c 74 2d 53 76 63 3a 20 68 33 3d 22 3a 34 |.Alt-Svc: h3=":4|
...
000003f0 45 a1 cb c0 58 48 6d c5 d6 38 86 00 00 26 7e 40 |E...XHm..8...&~@|
goroutine 74 [running]:
net/http.(*http2serverConn).runHandler.func1()
net/http/h2_bundle.go:5904 +0x125
panic({0x19dc500, 0xc00922e520})
runtime/panic.go:884 +0x212
github.com/darkweak/souin/cache/providers.(*Badger).Set(0xc0002a8130, {0xc000142e70, 0x2e}, {0xc00ba
98000, 0x2a695b, 0x400000}, {{0x1bf08eb000}, {0x2ecbb98, 0x0, 0x0}, ...}, ...)
github.com/darkweak/[email protected]/cache/providers/badgerProvider.go:138 +0x229
github.com/darkweak/souin/rfc.(*VaryTransport).SetCache(0xc0000127a0, {0xc000142e70, 0x2e}, 0xc00043
e6c0)
github.com/darkweak/[email protected]/rfc/transport.go:85 +0x263
github.com/darkweak/souin/rfc.validateVary.func1({0x20ad6c0, 0xc00923e1e0})
github.com/darkweak/[email protected]/rfc/vary.go:37 +0x198
github.com/darkweak/souin/rfc.(*cachingReadCloser).Read(0xc0091b0000, {0xc00aef480a, 0xaa000?, 0xa37
f6})
github.com/darkweak/[email protected]/rfc/standalone.go:352 +0x177
io.ReadAll({0x7fb14e07eac8, 0xc0091b0000})
io/io.go:661 +0xfe
io/ioutil.ReadAll(...)
io/ioutil/ioutil.go:27
github.com/darkweak/souin/plugins.(*CustomWriter).Send(0xc00013ea80)
github.com/darkweak/[email protected]/plugins/base.go:68 +0x20f
github.com/caddyserver/cache-handler.(*SouinCaddyPlugin).ServeHTTP.func1({0x1a66840?, 0xc000793500?}
, 0x1d5c566?)
github.com/caddyserver/[email protected]/httpcache.go:105 +0x10f
github.com/darkweak/souin/plugins.DefaultSouinPluginCallback({0x20bc5c0, 0xc00013ea80}, 0xc000715000
, {0x20cd618, 0xc0000a4360}, {0x0, 0x0}, 0xc000100910)
github.com/darkweak/[email protected]/plugins/base.go:178 +0x6df
github.com/caddyserver/cache-handler.(*SouinCaddyPlugin).ServeHTTP(0xc000714700, {0x20bfbc0?, 0xc000
012e28}, 0xc000714b00, {0x20b3dc0, 0xc00013ea40})
github.com/caddyserver/[email protected]/httpcache.go:93 +0x69a
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x20bfbc0?, 0xc000012e28?}
, 0x20b3dc0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:290 +0x42
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {0x20bfbc0?, 0xc
000012e28?}, 0x0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x20bfbc0, 0xc000012e28}, 0xc00
0714b00)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:259 +0x3a8
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc0006b2fc0?, {0x20bfbc0?,
0xc000012e28?}, 0x20b3dc0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Subroute).ServeHTTP(0xc0002d5f80, {0x20bfbc0, 0x
c000012e28}, 0x1?, {0x20b3dc0, 0x1e04120})
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/subroute.go:74 +0x6d
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x20bfbc0?, 0xc000012e28?}
, 0x20b3dc0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:290 +0x42
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {0x20bfbc0?, 0xc
000012e28?}, 0x0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x20bfbc0, 0xc000012e28}, 0xc00
0714b00)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:259 +0x3a8
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc0006b2b40?, {0x20bfbc0?,
0xc000012e28?}, 0x20b3dc0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Subroute).ServeHTTP(0xc0002d5ea0, {0x20bfbc0, 0x
c000012e28}, 0x19d8201?, {0x20b3dc0, 0x1e04120})
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/subroute.go:74 +0x6d
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x20bfbc0?, 0xc000012e28?}
, 0x20b3dc0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:290 +0x42
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x20b3dc0?, {0x20bfbc0?, 0xc
000012e28?}, 0x7ed87b?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapRoute.func1.1({0x20bfbc0, 0xc000012e28}, 0xc00
0714b00)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/routes.go:259 +0x3a8
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc0000bf400?, {0x20bfbc0?,
0xc000012e28?}, 0x1c262c0?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).enforcementHandler(0x0?, {0x20bfbc0?, 0x
c000012e28?}, 0xc00070a5b0?, {0x20b3dc0?, 0xc0001ea780?})
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/server.go:370 +0x252
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).wrapPrimaryRoute.func1({0x20bfbc0?, 0xc0
00012e28?}, 0x4cab37?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/server.go:346 +0x3b
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc0006ac9c0?, {0x20bfbc0?,
0xc000012e28?}, 0xc000714b00?)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/caddyhttp.go:58 +0x2f
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).ServeHTTP(0xc0006b2240, {0x20bfbc0, 0xc0
00012e28}, 0xc000714b00)
github.com/caddyserver/caddy/[email protected]/modules/caddyhttp/server.go:282 +0xb55
net/http.serverHandler.ServeHTTP({0x6b02a0?}, {0x20bfbc0, 0xc000012e28}, 0xc000136300)
net/http/server.go:2947 +0x30c
net/http.initALPNRequest.ServeHTTP({{0x20c1978?, 0xc00079fd70?}, 0xc008e04a80?, {0xc000122960?}}, {0
x20bfbc0, 0xc000012e28}, 0xc000136300)
net/http/server.go:3556 +0x245
net/http.(*http2serverConn).runHandler(0x20bb8a0?, 0x2ecbb98?, 0x0?, 0x0?)
net/http/h2_bundle.go:5911 +0x78
created by net/http.(*http2serverConn).processHeaders
net/http/h2_bundle.go:5641 +0x5b9
