superfluous response.WriteHeader error messages in the API server logs

[redmikhail]

We are running Observatorium API server version quay.io/observatorium/observatorium:master-2021-01-29-v0.1.1-195-gfde740a in our test environment. It seems that application intermittently generates following errors(see below) . Unfortunately it is not clear what kind of request has caused this error or if it had any impact on the clients (Observatorium is being accessed from multiple applications). I do apologize for limited information but hope that it will provide some clues .

2021/03/15 12:51:36 http: superfluous response.WriteHeader call from github.com/go-chi/chi/middleware.Recoverer.func1.1 (recoverer.go:31)
Panic: net/http: abort Handler
goroutine 586073 [running]:
runtime/debug.Stack(0x1f, 0x0, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9f
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x25
github.com/go-chi/chi/middleware.Recoverer.func1.1(0xc00020e300, 0xee88a0, 0xc000358000)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/recoverer.go:28 +0x1bf
panic(0xcb75c0, 0xc00018a890)
	/usr/local/go/src/runtime/panic.go:969 +0x175
net/http/httputil.(*ReverseProxy).ServeHTTP(0xc00007b590, 0x7f402fc84538, 0xc0000aee80, 0xc00020e700)
	/usr/local/go/src/net/http/httputil/reverseproxy.go:338 +0x163d
github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerResponseSize.func1(0x7f402fc84538, 0xc0000aee40, 0xc00020e700)
	/go/pkg/mod/github.com/prometheus/client_golang@v1.5.1/prometheus/promhttp/instrument_server.go:196 +0xe9
net/http.HandlerFunc.ServeHTTP(0xc000327440, 0x7f402fc84538, 0xc0000aee40, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func1(0x7f402fc84538, 0xc0000aed80, 0xc00020e700)
	/go/pkg/mod/github.com/prometheus/client_golang@v1.5.1/prometheus/promhttp/instrument_server.go:68 +0x11c
net/http.HandlerFunc.ServeHTTP(0xc000327710, 0x7f402fc84538, 0xc0000aed80, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerRequestSize.func1(0x7f402fc84538, 0xc0000aed40, 0xc00020e700)
	/go/pkg/mod/github.com/prometheus/client_golang@v1.5.1/prometheus/promhttp/instrument_server.go:163 +0xe9
net/http.HandlerFunc.ServeHTTP(0xc0003279e0, 0x7f402fc84538, 0xc0000aed40, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerCounter.func1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/go/pkg/mod/github.com/prometheus/client_golang@v1.5.1/prometheus/promhttp/instrument_server.go:100 +0xda
net/http.HandlerFunc.ServeHTTP(0xc000327bf0, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/authorization.WithAuthorizers.func1.1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/opt/authorization/http.go:39 +0x346
net/http.HandlerFunc.ServeHTTP(0xc00032c300, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi.(*ChainHandler).ServeHTTP(0xc00032c340, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/chain.go:31 +0x52
github.com/go-chi/chi.(*Mux).routeHTTP(0xc000071d40, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/mux.go:425 +0x28b
net/http.HandlerFunc.ServeHTTP(0xc0002c5cb0, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc000071d40, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e700)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/mux.go:70 +0x50c
net/http.StripPrefix.func1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2081 +0x1a2
net/http.HandlerFunc.ServeHTTP(0xc000327320, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2042 +0x44
main.stripTenantPrefix.func1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/opt/main.go:736 +0x182
net/http.HandlerFunc.ServeHTTP(0xc000333740, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi.(*Mux).Mount.func1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/mux.go:292 +0x122
net/http.HandlerFunc.ServeHTTP(0xc000330ba0, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/ratelimit.combine.func1.1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/opt/ratelimit/http.go:84 +0x2ae
net/http.HandlerFunc.ServeHTTP(0xc000330d00, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/authentication.WithTenantHeader.func1.1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/opt/authentication/http.go:44 +0x197
net/http.HandlerFunc.ServeHTTP(0xc000333830, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e600)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/authentication.(*OIDCProvider).Middleware.func1.1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e500)
	/opt/authentication/oidc.go:269 +0x6cf
net/http.HandlerFunc.ServeHTTP(0xc000194520, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e500)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/authentication.WithTenantMiddlewares.func1.1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e500)
	/opt/authentication/http.go:97 +0x115
net/http.HandlerFunc.ServeHTTP(0xc000330d20, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e500)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/authentication.WithTenant.func1(0x7f402fa4e088, 0xc0000aed00, 0xc00020e400)
	/opt/authentication/http.go:32 +0x1e7
net/http.HandlerFunc.ServeHTTP(0xc000330d40, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi.(*ChainHandler).ServeHTTP(0xc00032d480, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e400)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/chain.go:31 +0x52
github.com/go-chi/chi.(*Mux).routeHTTP(0xc000095560, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e400)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/mux.go:425 +0x28b
net/http.HandlerFunc.ServeHTTP(0xc0004322e0, 0x7f402fa4e088, 0xc0000aed00, 0xc00020e400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/observatorium/observatorium/server.Logger.func1.1(0xee88a0, 0xc000358000, 0xc00020e400)
	/opt/server/instrumentation.go:19 +0x20e
net/http.HandlerFunc.ServeHTTP(0xc00041cf30, 0xee88a0, 0xc000358000, 0xc00020e400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi/middleware.(*throttler).ServeHTTP(0xc00041ccc0, 0xee88a0, 0xc000358000, 0xc00020e400)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/throttle.go:94 +0x350
github.com/go-chi/chi/middleware.Timeout.func1.1(0xee88a0, 0xc000358000, 0xc00020e300)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/timeout.go:45 +0x1cf
net/http.HandlerFunc.ServeHTTP(0xc00043a760, 0xee88a0, 0xc000358000, 0xc00020e300)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi/middleware.StripSlashes.func1(0xee88a0, 0xc000358000, 0xc00020e300)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/strip.go:25 +0xee
net/http.HandlerFunc.ServeHTTP(0xc00043a780, 0xee88a0, 0xc000358000, 0xc00020e300)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi/middleware.Recoverer.func1(0xee88a0, 0xc000358000, 0xc00020e300)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/recoverer.go:35 +0x83
net/http.HandlerFunc.ServeHTTP(0xc00043a7a0, 0xee88a0, 0xc000358000, 0xc00020e300)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi/middleware.RealIP.func1(0xee88a0, 0xc000358000, 0xc00020e300)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/realip.go:34 +0x9d
net/http.HandlerFunc.ServeHTTP(0xc00043a7c0, 0xee88a0, 0xc000358000, 0xc00020e300)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi/middleware.RequestID.func1(0xee88a0, 0xc000358000, 0xc00020e200)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/middleware/request_id.go:72 +0x1e8
net/http.HandlerFunc.ServeHTTP(0xc00043a7e0, 0xee88a0, 0xc000358000, 0xc00020e200)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc000095560, 0xee88a0, 0xc000358000, 0xc00020e100)
	/go/pkg/mod/github.com/go-chi/chi@v4.0.2+incompatible/mux.go:82 +0x2d1
net/http.serverHandler.ServeHTTP(0xc0003721c0, 0xee88a0, 0xc000358000, 0xc00020e100)
	/usr/local/go/src/net/http/server.go:2843 +0xa3
net/http.(*conn).serve(0xc000390640, 0xeeb0a0, 0xc0000ae980)
	/usr/local/go/src/net/http/server.go:1925 +0x8ad
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2969 +0x36c

[squat]

Thanks for reporting this, we occasionally see it too. Can you please provide some info: that may help us narrow down the suspects:

• are you using rate limits? If so, could you share your config?
• are your clients remote writing? If so, is it metrics or logs?
• are your clients reading data? If so, are they reading metrics or logs?

Thanks for your help!

[redmikhail]

Hello,

Here are the answers to questions from above

• We don't explicitly set anything related to rate limit (not sure if there are default rate limits)
• Yes, clients are ultimately Prometheus servers that use remote_write , I believe version that we recently upgraded to is 2.22.2. We are sending metrics using remote_write from prometheus, logs are being shipped using promtail
• Yes , mostly through grafana and also api calls from the application to retrieve certain metrics . API calls done from golang applications using prometheus golang libraries. We read both metrics and logs (although logs are not extensively utilized). Logs retrieved using Grafana datasource

Hope it will help

[squat]

Thanks! This is very helpful :)