Panic while enrolling in MFA

[dabaer]

• Gitea version (or commit ref): 1.13.0
• Git version: 2.25.1
• Operating system: Ubuntu 20.04
• Install Mode: From Binary
• Run command: gitea web -c /etc/gitea/app.ini WORK_DIRECTORY=/var/lib/gitea
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
• Log gist:

Started POST /user/settings/security/two_factor/enroll for 127.0.0.1
2020/12/24 18:18:36 ...les/context/panic.go:35:1() [E] PANIC:: interface conversion: interface {} is nil, not string
	/usr/local/go/src/runtime/iface.go:261 (0x41358e)
	/go/src/code.gitea.io/gitea/routers/user/setting/security_twofa.go:192 (0x1d87cfe)
	/usr/local/go/src/reflect/value.go:476 (0x4a5886)
	/usr/local/go/src/reflect/value.go:337 (0x4a4d78)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:177 (0xd819f9)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:137 (0xd813ca)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd82f1c)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x1665df4)
	/go/src/code.gitea.io/gitea/modules/context/panic.go:39 (0x1665de5)
	/usr/local/go/src/reflect/value.go:476 (0x4a5886)
	/usr/local/go/src/reflect/value.go:337 (0x4a4d78)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:177 (0xd819f9)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:137 (0xd813ca)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd82f1c)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x1619ac4)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/session/session.go:192 (0x1619aad)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0xd82d92)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd81714)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd814b9)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd82f1c)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0xd94aa5)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/recovery.go:161 (0xd94a98)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/logger.go:40 (0xd86ad7)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd81714)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd814b9)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd82f1c)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x21aa7c4)
	/go/src/code.gitea.io/gitea/routers/routes/routes.go:109 (0x21aa7ae)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0xd82d92)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd81714)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd814b9)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd82f1c)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/router.go:187 (0xd95cf0)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/router.go:294 (0xd8f52f)
	/go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/macaron.go:218 (0xd87e4d)
	/go/src/code.gitea.io/gitea/vendor/github.com/gorilla/context/context.go:141 (0x128ed93)
	/usr/local/go/src/net/http/server.go:2042 (0x777623)
	/usr/local/go/src/net/http/server.go:2843 (0x77ac22)
	/usr/local/go/src/net/http/server.go:1925 (0x77642c)
	/usr/local/go/src/runtime/asm_amd64.s:1374 (0x478820)
	
2020/12/24 18:18:36 Completed POST /user/settings/security/two_factor/enroll 500 Internal Server Error in 10.84602ms

Description

When attempting to enroll in MFA in a fresh install of Gitea, an HTTP 500 error is shown and the above log is emitted.

This appears to be #13149, however that was resolved on it's own. Since it's no longer isolated I figured I should post again.

Edit: This is using the Authy app for TOTP.

[lunny]

Could you find the log before these like Unable to save changes to the session: ?

[zeripath]

The panic is occuring here:

gitea/routers/user/setting/security_twofa.go

Line 192 in d551152

secret := ctx.Session.Get("twofaSecret").(string)

The error implies that ctx.Session.Get("twofaSecret") returns nil not a string.

Why might this occur?

Well it shouldn't be possible to get to this page without that twofaSecret being set within the session as it will be set in twofaGenerateSecretAndQr unless there is a log.Error("Unable to save changes to the session: %v", err)

So as @lunny suggests, could you check the preceding logs for a Unable to save changes to the session: line? That would help us to find out where the issue is.

If there is not a log line like that then we need to think again but we can't proceed further without knowing if that occurs.

[dabaer]

Apologies for the delay, Christmas and all.

I searched the log and found the error log as I had sent originally, but there was no line containing Unable to save changes to session.

Frustratingly, after coming back to it today I was able to add the factor successfully. Unfortunately nothing really changed, I started the server under the same conditions as before (in the foreground via CLI) after it had been running since as a system service (same as before).

I will close this as I can't reproduce this, and thank you for helping thus far. I will re-open if I manage to encounter it again with a full log.

[ashmckenzie]

I just hit this issue also with 1.13.1. For me, the issue only occurs when PROTOCOL = https is set within the app.ini file as when I switch back to PROTOCOL = http I don't see the error.

[zeripath]

@ashmckenzie we need the logs if we're going to progress this at all as stated #14144 (comment)

[ashmckenzie]

@zeripath this is what I see in the logs with debugging enabled:

2021/01/18 12:03:29 ...s/context/context.go:332:func1() [D] Session ID: <removed>
2021/01/18 12:03:29 ...s/context/context.go:333:func1() [D] CSRF Token: <removed>
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x166b1d4)
        /go/src/code.gitea.io/gitea/modules/context/panic.go:39 (0x166b1c5)
        /usr/local/go/src/reflect/value.go:476 (0x4a4e26)
        /usr/local/go/src/reflect/value.go:337 (0x4a4318)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:177 (0xd86739)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:137 (0xd8610a)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd87c5c)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x161eea4)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/session/session.go:192 (0x161ee8d)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0xd87ad2)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd86454)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd861f9)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd87c5c)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0xd997e5)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/recovery.go:161 (0xd997d8)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/logger.go:40 (0xd8b817)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd86454)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd861f9)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd87c5c)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x21b0f24)
        /go/src/code.gitea.io/gitea/routers/routes/routes.go:109 (0x21b0f0e)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0xd87ad2)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0xd86454)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0xd861f9)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0xd87c5c)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/router.go:187 (0xd9aa30)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/router.go:294 (0xd9426f)
        /go/src/code.gitea.io/gitea/vendor/gitea.com/macaron/macaron/macaron.go:218 (0xd8cb8d)
        /go/src/code.gitea.io/gitea/vendor/github.com/gorilla/context/context.go:141 (0x1293fd3)
        /usr/local/go/src/net/http/server.go:2042 (0x77b883)
        /usr/local/go/src/net/http/server.go:2843 (0x77ee82)
        /usr/local/go/src/net/http/server.go:1925 (0x77a68c)
        /usr/local/go/src/runtime/asm_amd64.s:1374 (0x477dc0)

2021/01/18 12:03:29 ...s/context/context.go:139:HTML() [D] Template: status/500
2021/01/18 12:03:29 Completed POST /user/settings/security/two_factor/enroll 500 Internal Server Error in 7.260135ms

After a bit of trial and error, I discovered when https://addons.mozilla.org/en-US/firefox/addon/malwarebytes/ is installed and the 'Scams' toggle is enabled, this results in the 500 being produced:

When I disable the 'Scams' toggle, everything works as expected.

So as @lunny suggests, could you check the preceding logs for a Unable to save changes to the session: line? That would help us to find out where the issue is.

I don't see anything in the logs saying Unable to save changes to the session:

[ashmckenzie]

I cloned this repo, checkout out v1.13.1 and was able to replicate:

2021/01/18 12:34:17 Started POST /user/settings/security/two_factor/enroll for 127.0.0.1
2021/01/18 12:34:17 ...s/context/context.go:332:func1() [D] Session ID: e6a55fa994ded52b
2021/01/18 12:34:17 ...s/context/context.go:333:func1() [D] CSRF Token: TP4vwFjSw2rIdrB5aTkbaODmWYM6MTYxMDkzMzY1MDEzNTczMTAwMA
2021/01/18 12:34:17 ...les/context/panic.go:35:1() [E] PANIC:: interface conversion: interface {} is nil, not string
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/runtime/iface.go:261 (0x400ff0e)
		panicdottypeE: panic(&TypeAssertionError{iface, have, want, ""})
	/Users/ash/src/personal/external/gitea/routers/user/setting/security_twofa.go:192 (0x5989e1e)
		EnrollTwoFactorPost: secret := ctx.Session.Get("twofaSecret").(string)
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/reflect/value.go:476 (0x40a1746)
		Value.call: call(frametype, fn, args, uint32(frametype.size), uint32(retOffset))
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/reflect/value.go:337 (0x40a0c38)
		Value.Call: return v.call("Call", in)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:177 (0x49831d9)
		(*injector).callInvoke: return reflect.ValueOf(f).Call(in), nil
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:137 (0x4982baa)
		(*injector).Invoke: return inj.callInvoke(f, t, t.NumIn())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0x49846fc)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x5267af4)
		(*Context).Next: c.run()
	/Users/ash/src/personal/external/gitea/modules/context/panic.go:39 (0x5267ae5)
		Recovery.func1: ctx.Next()
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/reflect/value.go:476 (0x40a1746)
		Value.call: call(frametype, fn, args, uint32(frametype.size), uint32(retOffset))
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/reflect/value.go:337 (0x40a0c38)
		Value.Call: return v.call("Call", in)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:177 (0x49831d9)
		(*injector).callInvoke: return reflect.ValueOf(f).Call(in), nil
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:137 (0x4982baa)
		(*injector).Invoke: return inj.callInvoke(f, t, t.NumIn())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0x49846fc)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x521b7c4)
		(*Context).Next: c.run()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/session/session.go:192 (0x521b7ad)
		Sessioner.func1: ctx.Next()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0x4984572)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0x4982ef4)
		(*injector).fastInvoke: return f.Invoke(in)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0x4982c99)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0x49846fc)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x4996285)
		(*Context).Next: c.run()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/recovery.go:161 (0x4996278)
		Recovery.func1: c.Next()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/logger.go:40 (0x49882b7)
		LoggerInvoker.Invoke: invoke(params[0].(*Context), params[1].(*log.Logger))
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0x4982ef4)
		(*injector).fastInvoke: return f.Invoke(in)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0x4982c99)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0x49846fc)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:112 (0x5dad724)
		(*Context).Next: c.run()
	/Users/ash/src/personal/external/gitea/routers/routes/routes.go:109 (0x5dad70e)
		RouterHandler.func1: ctx.Next()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:79 (0x4984572)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:157 (0x4982ef4)
		(*injector).fastInvoke: return f.Invoke(in)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/inject/inject.go:135 (0x4982c99)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/context.go:121 (0x49846fc)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/router.go:187 (0x49974d0)
		(*Router).Handle.func1: c.run()
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/router.go:294 (0x4990d0f)
		(*Router).ServeHTTP: leaf.handle(rw, req, nil)
	/Users/ash/src/personal/external/gitea/vendor/gitea.com/macaron/macaron/macaron.go:218 (0x498962d)
		(*Macaron).ServeHTTP: m.Router.ServeHTTP(rw, req)
	/Users/ash/src/personal/external/gitea/vendor/github.com/gorilla/context/context.go:141 (0x4e90a73)
		ClearHandler.func1: h.ServeHTTP(w, r)
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/net/http/server.go:2042 (0x43784a3)
		HandlerFunc.ServeHTTP: f(w, r)
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/net/http/server.go:2843 (0x437baa2)
		serverHandler.ServeHTTP: handler.ServeHTTP(rw, req)
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/net/http/server.go:1925 (0x43772ac)
		(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/runtime/asm_amd64.s:1374 (0x4074800)
		goexit: BYTE	$0x90	// NOP

2021/01/18 12:34:17 ...s/context/context.go:139:HTML() [D] Template: status/500
2021/01/18 12:34:17 Completed POST /user/settings/security/two_factor/enroll 500 Internal Server Error in 18.599542ms

Poking around with spew, I inspected a few things:

diff --git a/routers/user/setting/security_twofa.go b/routers/user/setting/security_twofa.go
index 4ee698e15..1f8790c80 100644
--- a/routers/user/setting/security_twofa.go
+++ b/routers/user/setting/security_twofa.go
@@ -18,6 +18,7 @@ import (
 	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/setting"
 
+	"github.com/davecgh/go-spew/spew"
 	"github.com/pquerna/otp"
 	"github.com/pquerna/otp/totp"
 )
@@ -131,6 +132,9 @@ func twofaGenerateSecretAndQr(ctx *context.Context) bool {
 		return false
 	}
 
+	secret := ctx.Session.Get("twofaSecret")
+	spew.Dump(secret)
+
 	// Here we're just going to try to release the session early
 	if err := ctx.Session.Release(); err != nil {
 		// we'll tolerate errors here as they *should* get saved elsewhere
@@ -189,7 +193,10 @@ func EnrollTwoFactorPost(ctx *context.Context, form auth.TwoFactorAuthForm) {
 		return
 	}
 
-	secret := ctx.Session.Get("twofaSecret").(string)
+	secretRaw := ctx.Session.Get("twofaSecret")
+	spew.Dump(secretRaw)
+	secret := secretRaw.(string)
+
 	if !totp.Validate(form.Passcode, secret) {
 		if !twofaGenerateSecretAndQr(ctx) {
 			return

So twofaSecret is definitely being set in twofaGenerateSecretAndQr():

2021/01/18 12:46:22 Started GET /user/settings/security/two_factor/enroll for [::1]
2021/01/18 12:46:22 ...s/context/context.go:332:func1() [D] Session ID: e4caaa2fecf66e50
2021/01/18 12:46:22 ...s/context/context.go:333:func1() [D] CSRF Token: 2DJMrG_lojPkdmUpJS6-gzHJMJM6MTYxMDkzNDM2OTY2NzY0MzAwMA
(string) (len=64) "3VB6QWMVPINC7GCBHURBZWBPTT67PJTB24CYCZJRT5PSQO5PLUV7UV23JP2SUZLP"
2021/01/18 12:46:22 ...s/context/context.go:139:HTML() [D] Template: user/settings/twofa_enroll
2021/01/18 12:46:22 Completed GET /user/settings/security/two_factor/enroll 200 OK in 38.865958ms

But is not available in EnrollTwoFactorPost():

2021/01/18 12:48:02 Started POST /user/settings/security/two_factor/enroll for [::1]
2021/01/18 12:48:02 ...s/context/context.go:332:func1() [D] Session ID: e4caaa2fecf66e50
2021/01/18 12:48:02 ...s/context/context.go:333:func1() [D] CSRF Token: 2DJMrG_lojPkdmUpJS6-gzHJMJM6MTYxMDkzNDM2OTY2NzY0MzAwMA
(interface {}) <nil>
2021/01/18 12:48:02 ...les/context/panic.go:35:1() [E] PANIC:: interface conversion: interface {} is nil, not string
	/Users/ash/.asdf/installs/golang/1.15.5/go/src/runtime/iface.go:261 (0x4010a6e)
		panicdottypeE: panic(&TypeAssertionError{iface, have, want, ""})
	/Users/ash/src/personal/external/gitea/routers/user/setting/security_twofa.go:198 (0x5993e1e)
		EnrollTwoFactorPost: secret := secretRaw.(string)
--snip--
2021/01/18 12:48:02 ...s/context/context.go:139:HTML() [D] Template: status/500
2021/01/18 12:48:02 Completed POST /user/settings/security/two_factor/enroll 500 Internal Server Error in 19.246833ms

[zeripath]

I missed the malwarebytes thing - Is there anyway we can not fall foul of this?