Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Setting ENABLE_GZIP=true makes swagger API URL 500 (NPE panic) #19839

Closed
wxiaoguang opened this issue May 30, 2022 · 3 comments · Fixed by #19843
Closed

Setting ENABLE_GZIP=true makes swagger API URL 500 (NPE panic) #19839

wxiaoguang opened this issue May 30, 2022 · 3 comments · Fixed by #19843
Labels
issue/confirmed Issue has been reviewed and confirmed to be present or accepted to be implemented type/bug
Milestone

Comments

@wxiaoguang
Copy link
Contributor

Steps:

  1. set server.ENABLE_GZIP=true
  2. visit http://localhost:3000/api/swagger
  3. panic
PANIC: interface conversion: interface {} is nil, not *context.Context
/usr/local/go/src/runtime/iface.go:262 (0x400eae9)
	panicdottypeE: panic(&TypeAssertionError{iface, have, want, ""})
/Users/user/work/gitea/modules/context/context.go:622 (0x61204b1)
	GetContext: return req.Context().Value(contextKey).(*Context)
/Users/user/work/gitea/modules/web/wrap_convert.go:43 (0x6882ac4)
	convertHandler.func3: ctx := context.GetContext(req)
/Users/user/work/gitea/modules/web/wrap.go:41 (0x688068e)
	wrapInternal.func1: done, deferrable := handler(resp, req, others...)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/!n!y!times/gziphandler@v1.1.1/gzip.go:338 (0x6bf25da)
	GzipHandlerWithOpts.func1.1: h.ServeHTTP(gw, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/modules/web/wrap_convert.go:95 (0x6882390)
	convertHandler.func9: t(next).ServeHTTP(resp, req)
/Users/user/work/gitea/modules/web/wrap.go:41 (0x688068e)
	wrapInternal.func1: done, deferrable := handler(resp, req, others...)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/mux.go:442 (0x5b175fd)
	(*Mux).routeHTTP: h.ServeHTTP(w, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/routers/web/base.go:173 (0x6bf6997)
	Recovery.func1.1: next.ServeHTTP(w, req)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/gitea.com/go-chi/session@v0.0.0-20211218221615-e3605d8b28b8/session.go:257 (0x58bb116)
	Sessioner.func1.1: next.ServeHTTP(w, req)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/modules/web/wrap.go:110 (0x6881827)
	WrapWithPrefix.func1.1: next.ServeHTTP(resp, req)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/mux.go:71 (0x5b14799)
	(*Mux).ServeHTTP: mx.handler.ServeHTTP(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/mux.go:314 (0x5b16b23)
	(*Mux).Mount.func1: handler.ServeHTTP(w, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/mux.go:442 (0x5b175fd)
	(*Mux).routeHTTP: h.ServeHTTP(w, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/routers/common/middleware.go:79 (0x69286d7)
	Middlewares.func2.1: next.ServeHTTP(resp, req)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/modules/web/routing/logger_manager.go:123 (0x687c61e)
	(*requestRecordsManager).handler.func1: next.ServeHTTP(w, req)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/middleware/strip.go:30 (0x6923aa1)
	StripSlashes.func1: next.ServeHTTP(w, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/chi-middleware/proxy@v1.1.1/middleware.go:37 (0x691e29b)
	ForwardedHeaders.func1.1: h.ServeHTTP(w, r)
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/work/gitea/routers/common/middleware.go:32 (0x69284b1)
	Middlewares.func1.1: next.ServeHTTP(context.NewResponse(resp), req.WithContext(ctx))
/usr/local/go/src/net/http/server.go:2084 (0x47f7c62)
	HandlerFunc.ServeHTTP: f(w, r)
/Users/user/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.7/mux.go:88 (0x5b14927)
	(*Mux).ServeHTTP: mx.handler.ServeHTTP(w, r)
/Users/user/work/gitea/modules/web/route.go:200 (0x687f3c5)
	(*Route).ServeHTTP: r.R.ServeHTTP(w, req)
/usr/local/go/src/net/http/server.go:2916 (0x47fca93)
	serverHandler.ServeHTTP: handler.ServeHTTP(rw, req)
/usr/local/go/src/net/http/server.go:1966 (0x47f6abb)
	(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)
/usr/local/go/src/runtime/asm_amd64.s:1571 (0x4074080)
	goexit: BYTE	$0x90	// NOP
@wxiaoguang wxiaoguang added type/bug issue/confirmed Issue has been reviewed and confirmed to be present or accepted to be implemented labels May 30, 2022
@wxiaoguang wxiaoguang added this to the 1.17.0 milestone May 30, 2022
@zeripath
Copy link
Contributor

zeripath commented May 30, 2022

The next log line tells you where/which handler is causing this:

2022/05/30 21:15:17 [629525d5] router: failed    GET /api/swagger for 127.0.0.1:45120, panic in 349.6ms @ context/context.go:652(context.Auth), err=interface conversion: interface {} is nil, not *context.Context

@zeripath
Copy link
Contributor

Now if I add some tracing into web wrap I see:


2022/05/30 21:45:46 .../web/wrap_convert.go:105:func9() [I] [62952cfa] gziphandler/gzip.go:320(gziphandler.GzipHandlerWithOpts)
2022/05/30 21:45:46 .../web/wrap_convert.go:105:func9() [I] [62952cfa] context/context.go:682(context.Contexter)
2022/05/30 21:45:46 .../web/wrap_convert.go:47:func3() [I] [62952cfa] context/context.go:652(context.Auth)
2022/05/30 21:45:46 .../web/wrap_convert.go:105:func9() [I] [62952cfa] middleware/get_head.go:10(middleware.GetHead)
2022/05/30 21:45:46 .../web/wrap_convert.go:47:func3() [I] [62952cfa] misc/swagger.go:18(misc.Swagger)
2022/05/30 21:45:46 ...s/context/context.go:218:HTML() [D] [62952cfa] Template: swagger/ui
2022/05/30 21:45:47 .../web/wrap_convert.go:47:func3() [I] [62952cfa] context/context.go:652(context.Auth)
PANIC

This double context.Auth check is interesting...

@zeripath
Copy link
Contributor

In fact it gets more interesting if we add some logging in to check the done status within that function

Patch
diff --git a/modules/context/context.go b/modules/context/context.go
index dcc43973c..d851ac875 100644
--- a/modules/context/context.go
+++ b/modules/context/context.go
@@ -230,6 +230,7 @@ func (ctx *Context) HTML(status int, name base.TplName) {
 		}
 		ctx.ServerError("Render failed", err)
 	}
+	ctx.Resp.Flush()
 }
 
 // RenderToString renders the template content to a string
diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go
index 8dc4e6d62..42e203263 100644
--- a/modules/web/wrap_convert.go
+++ b/modules/web/wrap_convert.go
@@ -10,6 +10,7 @@ import (
 	"net/http"
 
 	"code.gitea.io/gitea/modules/context"
+	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/web/routing"
 )
 
@@ -17,72 +18,90 @@ type wrappedHandlerFunc func(resp http.ResponseWriter, req *http.Request, others
 
 func convertHandler(handler interface{}) wrappedHandlerFunc {
 	funcInfo := routing.GetFuncInfo(handler)
+
 	switch t := handler.(type) {
 	case http.HandlerFunc:
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			t(resp, req)
 			if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
 				done = true
 			}
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(http.ResponseWriter, *http.Request):
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			t(resp, req)
 			if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
 				done = true
 			}
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 
 	case func(ctx *context.Context):
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetContext(req)
 			t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(ctx *context.Context) goctx.CancelFunc:
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetContext(req)
 			deferrable = t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(*context.APIContext):
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetAPIContext(req)
 			t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(*context.APIContext) goctx.CancelFunc:
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetAPIContext(req)
 			deferrable = t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(*context.PrivateContext):
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetPrivateContext(req)
 			t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
 			return
 		}
 	case func(*context.PrivateContext) goctx.CancelFunc:
 		return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			ctx := context.GetPrivateContext(req)
 			deferrable = t(ctx)
 			done = ctx.Written()
+			log.Info("%v:%t", funcInfo, done)
+
 			return
 		}
 	case func(http.Handler) http.Handler:
@@ -92,10 +111,13 @@ func convertHandler(handler interface{}) wrappedHandlerFunc {
 				next = wrapInternal(others)
 			}
 			routing.UpdateFuncInfo(req.Context(), funcInfo)
+			log.Info("%v", funcInfo)
 			t(next).ServeHTTP(resp, req)
 			if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
 				done = true
 			}
+			log.Info("%v:%t", funcInfo, done)
+
 			return
 		}
 	default:

Produces logs like this:

2022/05/30 22:15:20 .../web/wrap_convert.go:114:func9() [I] [629533e8] gziphandler/gzip.go:320(gziphandler.GzipHandlerWithOpts)
2022/05/30 22:15:20 .../web/wrap_convert.go:114:func9() [I] [629533e8] context/context.go:683(context.Contexter)
2022/05/30 22:15:20 .../web/wrap_convert.go:49:func3() [I] [629533e8] context/context.go:653(context.Auth)
2022/05/30 22:15:20 .../web/wrap_convert.go:53:func3() [I] [629533e8] context/context.go:653(context.Auth):false
2022/05/30 22:15:20 .../web/wrap_convert.go:114:func9() [I] [629533e8] middleware/get_head.go:10(middleware.GetHead)
2022/05/30 22:15:20 .../web/wrap_convert.go:49:func3() [I] [629533e8] misc/swagger.go:18(misc.Swagger)
2022/05/30 22:15:20 ...s/context/context.go:218:HTML() [D] [629533e8] Template: swagger/ui
2022/05/30 22:15:20 .../web/wrap_convert.go:53:func3() [I] [629533e8] misc/swagger.go:18(misc.Swagger):true
2022/05/30 22:15:20 .../web/wrap_convert.go:119:func9() [I] [629533e8] middleware/get_head.go:10(middleware.GetHead):true
2022/05/30 22:15:20 .../web/wrap_convert.go:119:func9() [I] [629533e8] context/context.go:683(context.Contexter):false
2022/05/30 22:15:20 .../web/wrap_convert.go:49:func3() [I] [629533e8] context/context.go:653(context.Auth)
PANIC

Now the interesting thing lines is context/context.go:683(context.Contexter):false

Here this is saying that the response wasn't written to.

But it should have been ...

And if we look a bit higher we see:

			if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
				done = true
			}

But the resp that we are passed here is a GzipResponseWriter which doesn't have the requisite function.

So this done never gets set.

We need to wrap the resp if it's not a ResponseWriter

zeripath added a commit to zeripath/gitea that referenced this issue May 30, 2022
In order for web.Wrap to be able to detect if a response has been written
we need to wrap any non-context.ResponseWriters as a such. Otherwise
responses will be incorrectly detected as non-written to and handlers can
double run.

In the case of GZip this handler will change the response to a non-context.RW
and this failure to correctly detect response writing causes fallthrough and
a NPE.

Fix go-gitea#19839

Signed-off-by: Andrew Thornton <art27@cantab.net>
zeripath added a commit that referenced this issue May 31, 2022
In order for web.Wrap to be able to detect if a response has been written
we need to wrap any non-context.ResponseWriters as a such. Otherwise
responses will be incorrectly detected as non-written to and handlers can
double run.

In the case of GZip this handler will change the response to a non-context.RW
and this failure to correctly detect response writing causes fallthrough and
a NPE.

Fix #19839

Signed-off-by: Andrew Thornton <art27@cantab.net>
zeripath added a commit to zeripath/gitea that referenced this issue May 31, 2022
Backport go-gitea#19843

In order for web.Wrap to be able to detect if a response has been written
we need to wrap any non-context.ResponseWriters as a such. Otherwise
responses will be incorrectly detected as non-written to and handlers can
double run.

In the case of GZip this handler will change the response to a non-context.RW
and this failure to correctly detect response writing causes fallthrough and
a NPE.

Fix go-gitea#19839

Signed-off-by: Andrew Thornton <art27@cantab.net>
techknowlogick added a commit that referenced this issue Jun 3, 2022
* Ensure responses are context.ResponseWriters (#19843)

Backport #19843

In order for web.Wrap to be able to detect if a response has been written
we need to wrap any non-context.ResponseWriters as a such. Otherwise
responses will be incorrectly detected as non-written to and handlers can
double run.

In the case of GZip this handler will change the response to a non-context.RW
and this failure to correctly detect response writing causes fallthrough and
a NPE.

Fix #19839

Signed-off-by: Andrew Thornton <art27@cantab.net>

* fix test

Signed-off-by: Andrew Thornton <art27@cantab.net>

Co-authored-by: Lunny Xiao <xiaolunwen@gmail.com>
Co-authored-by: techknowlogick <techknowlogick@gitea.io>
AbdulrhmnGhanem pushed a commit to kitspace/gitea that referenced this issue Aug 24, 2022
In order for web.Wrap to be able to detect if a response has been written
we need to wrap any non-context.ResponseWriters as a such. Otherwise
responses will be incorrectly detected as non-written to and handlers can
double run.

In the case of GZip this handler will change the response to a non-context.RW
and this failure to correctly detect response writing causes fallthrough and
a NPE.

Fix go-gitea#19839

Signed-off-by: Andrew Thornton <art27@cantab.net>
@go-gitea go-gitea locked and limited conversation to collaborators May 3, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
issue/confirmed Issue has been reviewed and confirmed to be present or accepted to be implemented type/bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants