fatal errors are not logged about cache-handler

[mholt]

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.

[tve]

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

[PythonLinks]

how did you compile cdp-cache? Which version of go? What command?

What is your caddy file. ?

[tve]

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.

[tve]

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

[darkweak]

Can you retry with the latest release please?