darkweak/souin

panic in Caddy plugin

knadh opened this issue · 6 comments

knadh commented

Hi @darkweak. The following configuration runs fine and after an arbitrary time handling traffic, panics and crashes Caddy. I'm using the latest build created with xcaddy build --with github.com/darkweak/souin/plugins/caddy --with github.com/darkweak/souin

$ ./caddy --version
v2.7.6 h1:w0NymbG2m9PcvKWsrXO6EEkY9Ru4FJK8uQbYcev1p3A=
{
    order cache before rewrite
    cache {
        allowed_http_verbs GET
        ttl 86400s
        cache_name mysite
        badger {
            path /var/lib/caddy/cache
        }
        regex {
            exclude /tl/*
            exclude /atl/*
        }
    }
}

http://mysite.com {
    cache

    ### Static file downloads
    handle_path /files* {
        root * /home/site/www/files
        file_server
    }

    @r1 path_regexp params /old/path/(.*)/?
    redir @r1 /new/path/{re.params.1} permanent
    redir /open /p/open permanent
    redir /open/ /p/open permanent

    reverse_proxy /tl/* localhost:8123
    reverse_proxy /atl/* localhost:8123

    reverse_proxy localhost:9000

    encode gzip
    tls {
        on_demand
    }
}
fatal error: concurrent map writes
goroutine 11034729 [running]:
github.com/caddyserver/caddy/v2.(*Replacer).Set(...)
        github.com/caddyserver/caddy/v2@v2.7.6/replacer.go:68
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).ServeHTTP.func1()
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/reverseproxy/reverseproxy.go:433 +0x139
github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.(*Handler).ServeHTTP(0xc00020cf00, {0x25ba230, 0xc01e9613b0}, 0xc0219fdd00, {0x25ab900, 0x22f9340})
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/reverseproxy/reverseproxy.go:454 +0x44c
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x25ba230?, 0xc01e9613b0?}, 0x25ab900?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:331 +0x3a
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25ab900?, {0x25ba230?, 0xc01e9613b0?}, 0xc00067f300?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:300 +0x2c9
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x25c08c0?, {0x25ba230?, 0xc01e9613b0?}, 0xe?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp.RouteList.Compile.wrapRoute.func1.1({0x25ba230, 0xc01e9613b0}, 0xc01e061040?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:268 +0x264
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0xc02106e410?, {0x25ba230?, 0xc01e9613b0?}, 0x4?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/caddyserver/caddy/v2/modules/caddyhttp/encode.(*Encode).ServeHTTP(0xc00036a180, {0x25b9c80, 0xc0203e6940}, 0xc0219fdd00, {0x25ab900, 0xc01b19d020})
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/encode/encode.go:138 +0x283
github.com/caddyserver/caddy/v2/modules/caddyhttp.wrapMiddleware.func1.1({0x25b9c80?, 0xc0203e6940?}, 0x0?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/routes.go:331 +0x3a
github.com/caddyserver/caddy/v2/modules/caddyhttp.HandlerFunc.ServeHTTP(0x82?, {0x25b9c80?, 0xc0203e6940?}, 0xc01ee4aa70?)
        github.com/caddyserver/caddy/v2@v2.7.6/modules/caddyhttp/caddyhttp.go:58 +0x29
github.com/darkweak/souin/plugins/caddy.(*SouinCaddyMiddleware).ServeHTTP.func1({0x25b9c80?, 0xc0203e6940?}, 0x4e61c5?)
        github.com/darkweak/souin/plugins/caddy@v0.0.0-20231130105936-40a16bffcd67/httpcache.go:85 +0x33
github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream.func1()
        github.com/darkweak/souin@v1.6.44/pkg/middleware/middleware.go:300 +0x7f
golang.org/x/sync/singleflight.(*Group).doCall.func2(0xc017dc3cc6, 0xc01e961360, 0x7fc8ebf965b8?)
        golang.org/x/sync@v0.5.0/singleflight/singleflight.go:198 +0x64
golang.org/x/sync/singleflight.(*Group).doCall(0x1d47580?, 0xc00055c7e0?, {0xc01bf79180?, 0x35?}, 0x40e65a?)
        golang.org/x/sync@v0.5.0/singleflight/singleflight.go:200 +0x96
golang.org/x/sync/singleflight.(*Group).Do(0xc0006b4138, {0xc01bf79180, 0x35}, 0x15?)
        golang.org/x/sync@v0.5.0/singleflight/singleflight.go:113 +0x15a
github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Upstream(0xc0006b4000, 0xc0203e6940, 0xc0214a2500, 0xc01b19d1a0, 0xc015b15230, {0xc01bf79180, 0x35})
        github.com/darkweak/souin@v1.6.44/pkg/middleware/middleware.go:298 +0x246
github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP.func4()
        github.com/darkweak/souin@v1.6.44/pkg/middleware/middleware.go:623 +0x38
created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).ServeHTTP in goroutine 11034627
        github.com/darkweak/souin@v1.6.44/pkg/middleware/middleware.go:622 +0x114d
goroutine 1 [select (no cases), 397 minutes]:
github.com/caddyserver/caddy/v2/cmd.cmdRun({0x0?})
        github.com/caddyserver/caddy/v2@v2.7.6/cmd/commandfuncs.go:283 +0xc18
github.com/caddyserver/caddy/v2/cmd.init.1.func2.WrapCommandFuncForCobra.func1(0xc000005500, {0x20635a8?, 0x4?, 0x2063584?})
        github.com/caddyserver/caddy/v2@v2.7.6/cmd/cobra.go:137 +0x2f
github.com/spf13/cobra.(*Command).execute(0xc000005500, {0xc000559350, 0x3, 0x3})
        github.com/spf13/cobra@v1.7.0/command.go:940 +0x87c
github.com/spf13/cobra.(*Command).ExecuteC(0x3667120)
        github.com/spf13/cobra@v1.7.0/command.go:1068 +0x3a5
github.com/spf13/cobra.(*Command).Execute(...)
        github.com/spf13/cobra@v1.7.0/command.go:992
github.com/caddyserver/caddy/v2/cmd.Main()
        github.com/caddyserver/caddy/v2@v2.7.6/cmd/main.go:66 +0x5b
main.main()
        caddy/main.go:12 +0xf
goroutine 8 [select]:
github.com/golang/glog.(*fileSink).flushDaemon(0x3689038)
        github.com/golang/glog@v1.1.2/glog_file.go:351 +0xb9
created by github.com/golang/glog.init.1 in goroutine 1
        github.com/golang/glog@v1.1.2/glog_file.go:166 +0x135
goroutine 13 [select, 397 minutes]:
github.com/caddyserver/certmagic.(*RingBufferRateLimiter).permit(0xc000142500)
        github.com/caddyserver/certmagic@v0.20.0/ratelimiter.go:217 +0x86
github.com/caddyserver/certmagic.(*RingBufferRateLimiter).loop(0xc000142500)
        github.com/caddyserver/certmagic@v0.20.0/ratelimiter.go:89 +0x8b
created by github.com/caddyserver/certmagic.NewRateLimiter in goroutine 1
        github.com/caddyserver/certmagic@v0.20.0/ratelimiter.go:45 +0x13c
goroutine 14 [chan receive, 397 minutes]:
github.com/caddyserver/caddy/v2.trapSignalsCrossPlatform.func1()
        github.com/caddyserver/caddy/v2@v2.7.6/sigtrap.go:43 +0xd8
created by github.com/caddyserver/caddy/v2.trapSignalsCrossPlatform in goroutine 1
        github.com/caddyserver/caddy/v2@v2.7.6/sigtrap.go:38 +0x1a
goroutine 15 [chan receive, 397 minutes]:
github.com/caddyserver/caddy/v2.trapSignalsPosix.func1()
        github.com/caddyserver/caddy/v2@v2.7.6/sigtrap_posix.go:35 +0xfa
created by github.com/caddyserver/caddy/v2.trapSignalsPosix in goroutine 1
        github.com/caddyserver/caddy/v2@v2.7.6/sigtrap_posix.go:31 +0x1a
goroutine 19 [syscall, 397 minutes]:
os/signal.signal_recv()
        runtime/sigqueue.go:152 +0x29
os/signal.loop()
        os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 14
        os/signal/signal.go:151 +0x1f
goroutine 20 [select]:
github.com/dgraph-io/badger/v3.(*DB).updateSize(0xc00070cd80, 0xc0005420f0)
        github.com/dgraph-io/badger/v3@v3.2103.5/db.go:1171 +0x145
created by github.com/dgraph-io/badger/v3.Open in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/db.go:331 +0xe56
goroutine 36 [IO wait, 397 minutes]:
internal/poll.runtime_pollWait(0x7fc8a53c5f10, 0x72)
        runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000634b00?, 0x4161e5?, 0x0)
        internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
        internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000634b00)
        internal/poll/fd_unix.go:611 +0x2ac
net.(*netFD).accept(0xc000634b00)
        net/fd_unix.go:172 +0x29
net.(*TCPListener).accept(0xc00053d8e0)
        net/tcpsock_posix.go:152 +0x1e
net.(*TCPListener).Accept(0xc00053d8e0)
        net/tcpsock.go:315 +0x30
net/http.(*Server).Serve(0xc000364960, {0x7fc8a5131258, 0xc00053d900})
        net/http/server.go:3056 +0x364
github.com/caddyserver/caddy/v2.replaceLocalAdminServer.func2()
        github.com/caddyserver/caddy/v2@v2.7.6/admin.go:449 +0xc8
created by github.com/caddyserver/caddy/v2.replaceLocalAdminServer in goroutine 1
        github.com/caddyserver/caddy/v2@v2.7.6/admin.go:445 +0x4a6
goroutine 37 [select, 9 minutes]:
github.com/caddyserver/certmagic.(*Cache).maintainAssets(0xc000634b80, 0x0)
        github.com/caddyserver/certmagic@v0.20.0/maintain.go:69 +0x305
created by github.com/caddyserver/certmagic.NewCache in goroutine 1
        github.com/caddyserver/certmagic@v0.20.0/cache.go:127 +0x1f6
goroutine 38 [select]:
github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc00056a2d0, 0xc00056a2a0)
        github.com/dgraph-io/badger/v3@v3.2103.5/y/watermark.go:214 +0x285
created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/y/watermark.go:72 +0xa7
goroutine 39 [select]:
github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc00056a300, 0xc00056a2a0)
        github.com/dgraph-io/badger/v3@v3.2103.5/y/watermark.go:214 +0x285
created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/y/watermark.go:72 +0xa7
goroutine 40 [select]:
github.com/dgraph-io/ristretto/z.(*AllocatorPool).freeupAllocators(0xc000028120)
        github.com/dgraph-io/ristretto@v0.1.1/z/allocator.go:385 +0x11f
created by github.com/dgraph-io/ristretto/z.NewAllocatorPool in goroutine 1
        github.com/dgraph-io/ristretto@v0.1.1/z/allocator.go:324 +0xb9
goroutine 41 [select, 397 minutes]:
github.com/dgraph-io/ristretto.(*defaultPolicy).processItems(0xc00035e1c0)
        github.com/dgraph-io/ristretto@v0.1.1/policy.go:102 +0x85
created by github.com/dgraph-io/ristretto.newDefaultPolicy in goroutine 1
        github.com/dgraph-io/ristretto@v0.1.1/policy.go:86 +0x139
goroutine 42 [select]:
github.com/dgraph-io/ristretto.(*Cache).processItems(0xc000700b80)
        github.com/dgraph-io/ristretto@v0.1.1/cache.go:452 +0x149
created by github.com/dgraph-io/ristretto.NewCache in goroutine 1
        github.com/dgraph-io/ristretto@v0.1.1/cache.go:207 +0x645
goroutine 43 [select]:
github.com/dgraph-io/badger/v3.(*DB).monitorCache(0xc00070cd80, 0xc000519b90)
        github.com/dgraph-io/badger/v3@v3.2103.5/db.go:469 +0x170
created by github.com/dgraph-io/badger/v3.Open in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/db.go:311 +0xc49
goroutine 44 [select]:
github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc00027e5b0, 0x0, 0xc000519bc0)
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:508 +0x2e9
created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:354 +0x4b
goroutine 45 [select]:
github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc00027e5b0, 0x1, 0xc000519bc0)
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:508 +0x2e9
created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:354 +0x4b
goroutine 46 [select]:
github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc00027e5b0, 0x2, 0xc000519bc0)
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:508 +0x2e9
created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:354 +0x4b
goroutine 47 [select]:
github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc00027e5b0, 0x3, 0xc000519bc0)
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:508 +0x2e9
created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact in goroutine 1
        github.com/dgraph-io/badger/v3@v3.2103.5/levels.go:354 +0x4b
goroutine 48 [chan receive, 397 minutes]:
github.com/dgraph-io/badger/v3.(*DB).flushMemtable(0xc00070cd80, 0xc00056a2a0?)
        github.com/dgraph-io/badger/v3@v3.2103.5/db.go:1078 +0xa5
github.com/dgraph-io/badger/v3.Open.func5()
....

Hi @knadh thank you for your issue. The panic comes from the singleflight package, I have to check why that happens, which "map" is concurrently accessed/written. That's a high priority bugfix.

It would be great to have a reproducible test case 🙂

knadh commented

This is from a site that receives few a thousand requests per minute. Have been unable to pinpoint what triggers this, unfortunately. Sometimes it's a few seconds between crashes, sometimes it's half an hour. I've disabled caching altogether.

I will use the stress tests to debug that then.

@knadh
try changing to nutsdb or redis, crash caddy should not occur. I tested under heavy load.

With this config

cache {
        nuts {
            path /tmp/nuts-path
        }
    }