Bug/"goroutine crowdsec/controllersV1/StreamDecision crashed"

[OcelotNat]

last log lines

time="14-12-2020 00:01:13" level=info msg="pull top: added 80 entries"
time="14-12-2020 00:01:13" level=error msg="crowdsec - goroutine crowdsec/controllersV1/StreamDecision crashed : write tcp 127.0.0.1:8080->127.0.0.1:38396: write: broken pipe"
time="14-12-2020 00:01:13" level=error msg="please report this error to https://github.com/crowdsecurity/crowdsec/"
time="14-12-2020 00:01:13" level=error msg="stacktrace/report is written to /tmp/crowdsec-crash.561334833.txt : please join it to your issue"
time="14-12-2020 00:01:13" level=fatal msg="crowdsec stopped"

/tmp/crowdsec-crash.561334833.txt

version: v1.0.0-da5ca5f0baa4f67ab39051e424eb5cd17ca29dfc
Codename: beta
BuildDate: 2020-12-07_11:56:10
GoVersion: 1.13.15
goroutine 73 [running]:
runtime/debug.Stack(0xc0000b40f8, 0xc000244d80, 0x7a)
/opt/hostedtoolcache/go/1.13.15/x64/src/runtime/debug/stack.go:24 +0x9d
github.com/crowdsecurity/crowdsec/pkg/types.CatchPanic(0x1571bef, 0x25)
/home/runner/work/crowdsec/crowdsec/pkg/types/utils.go:127 +0x1d3
panic(0x1447080, 0xc0011b0a50)
/opt/hostedtoolcache/go/1.13.15/x64/src/runtime/panic.go:679 +0x1b2
github.com/gin-gonic/gin/render.JSON.Render(...)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/render/json.go:59
github.com/gin-gonic/gin.(*Context).Render(0xc0001c80f0, 0xc8, 0x16dae00, 0xc001026240)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:841 +0x146
github.com/gin-gonic/gin.(*Context).JSON(...)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:884
github.com/crowdsecurity/crowdsec/pkg/apiserver/controllers/v1.(*Controller).StreamDecision(0xc000035450, 0xc0001c80f0)
/home/runner/work/crowdsec/crowdsec/pkg/apiserver/controllers/v1/decisions.go:215 +0x12db
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/crowdsecurity/crowdsec/pkg/apiserver/controllers/v1.PrometheusBouncersMiddleware.func1(0xc0001c80f0)
/home/runner/work/crowdsec/crowdsec/pkg/apiserver/controllers/v1/metrics.go:96 +0x63
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/crowdsecurity/crowdsec/pkg/apiserver/middlewares/v1.(*APIKey).MiddlewareFunc.func1(0xc0001c80f0)
/home/runner/work/crowdsec/crowdsec/pkg/apiserver/middlewares/v1/api_key.go:112 +0x6e9
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/crowdsecurity/crowdsec/pkg/apiserver/controllers/v1.PrometheusMiddleware.func1(0xc0001c80f0)
/home/runner/work/crowdsec/crowdsec/pkg/apiserver/controllers/v1/metrics.go:105 +0x13f
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/gin-gonic/gin.RecoveryWithWriter.func1(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/recovery.go:83 +0x64
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/gin-gonic/gin.LoggerWithConfig.func1(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/logger.go:241 +0xe1
github.com/gin-gonic/gin.(*Context).Next(0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 +0x3b
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc0000d6a00, 0xc0001c80f0)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/gin.go:409 +0x66d
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc0000d6a00, 0x16e6f00, 0xc0002862a0, 0xc000216d00)
/home/runner/go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/gin.go:367 +0x14e
net/http.serverHandler.ServeHTTP(0xc0002861c0, 0x16e6f00, 0xc0002862a0, 0xc000216d00)
/opt/hostedtoolcache/go/1.13.15/x64/src/net/http/server.go:2831 +0xa4
net/http.(*conn).serve(0xc0007565a0, 0x16ea380, 0xc00063da00)
/opt/hostedtoolcache/go/1.13.15/x64/src/net/http/server.go:1919 +0x875
created by net/http.(*Server).Serve
/opt/hostedtoolcache/go/1.13.15/x64/src/net/http/server.go:2957 +0x384

Technical Information :

• OS: Debian 10
• Crowdsec 1.0.0 (new install after uninstall 0.0.6)
• cs-firewall-bouncer 0.0.6 (upgraded from 0.0.5)
• logrotate with service restart at 0:00

[OcelotNat]

syslog

Dec 14 00:01:05 [server] systemd[1]: Started Rotate log files.
Dec 14 00:01:13 [server] crowdsec[15349]: 127.0.0.1 - [Mon, 14 Dec 2020 00:01:13 CET] "GET /v1/decisions/stream?startup=true HTTP/1.1 200 14.931875159s "cs-firewall-bouncer/v0.0.6-1fe80ecbe9397d4f556df43ba75a8457ad30646e" "
Dec 14 00:01:13 [server] cs-firewall-bouncer[15369]: 2020/12/14 00:01:13 Get http://localhost:8080/v1/decisions/stream?startup=false: EOF
Dec 14 00:01:13 [server] systemd[1]: crowdsec.service: Main process exited, code=exited, status=1/FAILURE
Dec 14 00:01:13 [server] systemd[1]: crowdsec.service: Failed with result 'exit-code'.
Dec 14 00:01:13 [server] systemd[1]: cs-firewall-bouncer.service: Main process exited, code=exited, status=1/FAILURE
Dec 14 00:01:13 [server] systemd[1]: cs-firewall-bouncer.service: Failed with result 'exit-code'.

[buixor]

Hello,

Nice spot, it seems that we didn't properly deal with the broken pipe error (client disconnects while we're sending the response).
(We can find references in gin here, but we setup our own recovery handle without accounting this case).

By any chance, do you have a way for us to reproduce the bug easily? (If it's not the case, don't bother too much)

Thanks,

[OcelotNat]

Sorry, no, force logrotate or many services stop|start|restart don't have the same result.

[buixor]

fixed in #538