After login providing two-factor auth 5XX errors. Can't login. #5816

Closed
opened 2025-11-02 06:36:42 -06:00 by GiteaMirror · 15 comments
Owner

Originally created by @nodesocket on GitHub (Aug 1, 2020).

Description

When logging in, and after proving a correct two-factor auth token, I am shown a 5XX error. The logs don't provide a stack trace so can't see where in the code it's breaking.

[Macaron] 2020-08-01 23:10:07: Started POST /user/two_factor for 10.244.1.1
[Macaron] 2020-08-01 23:10:07: Completed POST /user/two_factor 500 Internal Server Error in 19.568867ms
Originally created by @nodesocket on GitHub (Aug 1, 2020). - **Gitea version (or commit ref):** 1.12.3 - **Git version:** 2.24.3 - **Operating system:** Docker container https://hub.docker.com/layers/gitea/gitea/1.12.3/images/sha256-38b8222941d8acffb7bb9c3fb0e9e0b657e06815a090f1fb11ed6900a3c9f384?context=explore - Database (use `[x]`): - [X] PostgreSQL - [ ] MySQL - [ ] MSSQL - [ ] SQLite - Can you reproduce the bug at https://try.gitea.io: - [ ] Yes (provide example URL) - [ ] No - [X] Not relevant ## Description When logging in, and after proving a correct two-factor auth token, I am shown a 5XX error. The logs don't provide a stack trace so can't see where in the code it's breaking. ``` [Macaron] 2020-08-01 23:10:07: Started POST /user/two_factor for 10.244.1.1 [Macaron] 2020-08-01 23:10:07: Completed POST /user/two_factor 500 Internal Server Error in 19.568867ms ```
Author
Owner

@techknowlogick commented on GitHub (Aug 1, 2020):

Here is documentation on logging that might be helpful: https://docs.gitea.io/en-us/logging-configuration/#the-xorm-logger you can enable DB logging, and you may also want to set your log level for general logs to trace as then you can get a lot more logs.

@techknowlogick commented on GitHub (Aug 1, 2020): Here is documentation on logging that might be helpful: https://docs.gitea.io/en-us/logging-configuration/#the-xorm-logger you can enable DB logging, and you may also want to set your log level for general logs to trace as then you can get a lot more logs.
Author
Owner

@nodesocket commented on GitHub (Aug 1, 2020):

@techknowlogick ok, I need to dig into the Kubernetes Helm chart and find where to update this value and how to re-deploy the pods with LEVEL = Trace.

@nodesocket commented on GitHub (Aug 1, 2020): @techknowlogick ok, I need to dig into the Kubernetes Helm chart and find where to update this value and how to re-deploy the pods with `LEVEL = Trace`.
Author
Owner

@techknowlogick commented on GitHub (Aug 1, 2020):

Which helm chart are you using? I believe that our official one uses a ConfigMap to store the app.ini

@techknowlogick commented on GitHub (Aug 1, 2020): Which helm chart are you using? I believe that our official one uses a ConfigMap to store the app.ini
Author
Owner

@nodesocket commented on GitHub (Aug 1, 2020):

# chart.yaml
name: gitea
version: 1.9.3
appVersion: 1.12.3
description: Git with a cup of tea
icon: https://docs.gitea.io/images/gitea.png
keywords:
  - git
  - issue tracker
  - code review
  - wiki
  - gitea
  - gogs
sources:
  - https://github.com/go-gitea/gitea
  - https://hub.docker.com/r/gitea/gitea/
maintainers:
  - name: John Felten
    email: john.felten@gmail.com

I went in and modified templates/gitea/gitea-config.yaml and updated to LEVEL = 'Trace'. The problem is getting the deployment to rebuild. Doing:

helm upgrade --install gitea --values gitea.yaml ./

Did not re-deploy the pods.

EDIT: It did update the configmap though, I verified in Kubernetes doing:

kubectl edit configmap gitea-gitea
@nodesocket commented on GitHub (Aug 1, 2020): ``` # chart.yaml name: gitea version: 1.9.3 appVersion: 1.12.3 description: Git with a cup of tea icon: https://docs.gitea.io/images/gitea.png keywords: - git - issue tracker - code review - wiki - gitea - gogs sources: - https://github.com/go-gitea/gitea - https://hub.docker.com/r/gitea/gitea/ maintainers: - name: John Felten email: john.felten@gmail.com ``` I went in and modified `templates/gitea/gitea-config.yaml` and updated to `LEVEL = 'Trace'`. The problem is getting the deployment to rebuild. Doing: ``` helm upgrade --install gitea --values gitea.yaml ./ ``` Did not re-deploy the pods. **EDIT:** It did update the configmap though, I verified in Kubernetes doing: ``` kubectl edit configmap gitea-gitea ```
Author
Owner

@techknowlogick commented on GitHub (Aug 2, 2020):

after updating the config map the pods won't automatically resart, there are a few things you could do, the one that is easiest is to do a kubectl rollout restart on the deployment.

@techknowlogick commented on GitHub (Aug 2, 2020): after updating the config map the pods won't automatically resart, there are a few things you could do, the one that is easiest is to do a `kubectl rollout restart` on the deployment.
Author
Owner

@nodesocket commented on GitHub (Aug 2, 2020):

@techknowlogick thanks, running kubectl rollout restart deployment gitea-gitea restarted the pods. However, when I go to login and provide two-factor auth, still seeing the 5XX error, but no details are logged other than:

[Macaron] 2020-08-02 21:07:15: Completed GET /serviceworker.js 304 Not Modified in 283.806µs
[Macaron] 2020-08-02 21:07:18: Started POST /user/two_factor for 10.244.1.0
[Macaron] 2020-08-02 21:07:18: Completed POST /user/two_factor 500 Internal Server Error in 16.046322ms
[Macaron] 2020-08-02 21:07:18: Started GET /img/500.png for 10.244.1.0
[Macaron] [Static] Serving /img/500.png

Looking at the configmap I see that [log] LEVEL = Trace is set. Am I missing something else?

[log]
ROOT_PATH =
; Either "console", "file", "conn", "smtp" or "database", default is "console"
; Use comma to separate multiple modes, e.g. "console, file"
MODE = console
; Buffer length of the channel, keep it as it is if you don't know what it is.
BUFFER_LEN = 10000
; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Trace"
LEVEL = Trace

; For "console" mode only
[log.console]
LEVEL =

; For "file" mode only
[log.file]
LEVEL =
; This enables automated log rotate(switch of following options), default is true
LOG_ROTATE = true
; Max number of lines in a single file, default is 1000000
MAX_LINES = 1000000
; Max size shift of a single file, default is 28 means 1 << 28, 256MB
MAX_SIZE_SHIFT = 28
; Segment log daily, default is true
DAILY_ROTATE = true
; delete the log file after n days, default is 7
MAX_DAYS = 3

; For "conn" mode only
[log.conn]
LEVEL =
; Reconnect host for every single message, default is false
RECONNECT_ON_MSG = false
; Try to reconnect when connection is lost, default is false
RECONNECT = false
; Either "tcp", "unix" or "udp", default is "tcp"
PROTOCOL = tcp
; Host address
ADDR =

; For "smtp" mode only
[log.smtp]
LEVEL =
; Name displayed in mail title, default is "Diagnostic message from server"
SUBJECT = Diagnostic message from server
; Mail server
HOST =
; Mailer user name and password
USER =
; Use PASSWD = `your password` for quoting if you use special characters in the password.
PASSWD =
; Receivers, can be one or more, e.g. 1@example.com,2@example.com
RECEIVERS =

; For "database" mode only
[log.database]
LEVEL =
; Either "mysql" or "postgres"
DRIVER =
; Based on xorm, e.g.: root:root@localhost/gitea?charset=utf8
CONN =
@nodesocket commented on GitHub (Aug 2, 2020): @techknowlogick thanks, running `kubectl rollout restart deployment gitea-gitea` restarted the pods. However, when I go to login and provide two-factor auth, still seeing the **5XX** error, but no details are logged other than: ``` [Macaron] 2020-08-02 21:07:15: Completed GET /serviceworker.js 304 Not Modified in 283.806µs [Macaron] 2020-08-02 21:07:18: Started POST /user/two_factor for 10.244.1.0 [Macaron] 2020-08-02 21:07:18: Completed POST /user/two_factor 500 Internal Server Error in 16.046322ms [Macaron] 2020-08-02 21:07:18: Started GET /img/500.png for 10.244.1.0 [Macaron] [Static] Serving /img/500.png ``` Looking at the configmap I see that `[log] LEVEL = Trace` is set. Am I missing something else? ``` [log] ROOT_PATH = ; Either "console", "file", "conn", "smtp" or "database", default is "console" ; Use comma to separate multiple modes, e.g. "console, file" MODE = console ; Buffer length of the channel, keep it as it is if you don't know what it is. BUFFER_LEN = 10000 ; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Trace" LEVEL = Trace ; For "console" mode only [log.console] LEVEL = ; For "file" mode only [log.file] LEVEL = ; This enables automated log rotate(switch of following options), default is true LOG_ROTATE = true ; Max number of lines in a single file, default is 1000000 MAX_LINES = 1000000 ; Max size shift of a single file, default is 28 means 1 << 28, 256MB MAX_SIZE_SHIFT = 28 ; Segment log daily, default is true DAILY_ROTATE = true ; delete the log file after n days, default is 7 MAX_DAYS = 3 ; For "conn" mode only [log.conn] LEVEL = ; Reconnect host for every single message, default is false RECONNECT_ON_MSG = false ; Try to reconnect when connection is lost, default is false RECONNECT = false ; Either "tcp", "unix" or "udp", default is "tcp" PROTOCOL = tcp ; Host address ADDR = ; For "smtp" mode only [log.smtp] LEVEL = ; Name displayed in mail title, default is "Diagnostic message from server" SUBJECT = Diagnostic message from server ; Mail server HOST = ; Mailer user name and password USER = ; Use PASSWD = `your password` for quoting if you use special characters in the password. PASSWD = ; Receivers, can be one or more, e.g. 1@example.com,2@example.com RECEIVERS = ; For "database" mode only [log.database] LEVEL = ; Either "mysql" or "postgres" DRIVER = ; Based on xorm, e.g.: root:root@localhost/gitea?charset=utf8 CONN = ```
Author
Owner

@nodesocket commented on GitHub (Aug 2, 2020):

@techknowlogick well I think I know what the problem was, I updated [log.console] LEVEL = Trace as well. However this time when I ran kubectl rollout restart deployment gitea-gitea things went horribly wrong. The pods are just erroring out, and somehow it's trying to run two instances of gitea. I tried doing kubectl delete pods gitea-gitea-66487d956f-2vx4q gitea-gitea-6d9456c44b-h4j8n but it just brings both pods back up. I even tried kubectl rollout undo gitea-gitea.

gitea-gitea-66487d956f-2vx4q                  2/3     CrashLoopBackOff   3          102s
gitea-gitea-6d9456c44b-h4j8n                  2/3     CrashLoopBackOff   3          102s

kubectl describe pod gitea-gitea-66487d956f-2vx4q

Events:
  Type     Reason     Age                    From                        Message
  ----     ------     ----                   ----                        -------
  Normal   Scheduled  <unknown>              storageos-scheduler         Successfully assigned default/gitea-gitea-66487d956f-2vx4q to kube-worker-f6q2j
  Normal   Pulling    5m42s                  kubelet, kube-worker-f6q2j  Pulling image "gitea/gitea:1.12.3"
  Normal   Pulled     5m41s                  kubelet, kube-worker-f6q2j  Successfully pulled image "gitea/gitea:1.12.3"
  Normal   Created    5m41s                  kubelet, kube-worker-f6q2j  Created container init
  Normal   Started    5m40s                  kubelet, kube-worker-f6q2j  Started container init
  Normal   Pulling    5m38s                  kubelet, kube-worker-f6q2j  Pulling image "gitea/gitea:1.12.3"
  Normal   Started    5m37s                  kubelet, kube-worker-f6q2j  Started container gitea
  Normal   Pulling    5m37s                  kubelet, kube-worker-f6q2j  Pulling image "memcached:1.6.6-alpine"
  Normal   Pulled     5m37s                  kubelet, kube-worker-f6q2j  Successfully pulled image "gitea/gitea:1.12.3"
  Normal   Created    5m37s                  kubelet, kube-worker-f6q2j  Created container gitea
  Normal   Pulled     5m36s                  kubelet, kube-worker-f6q2j  Successfully pulled image "memcached:1.6.6-alpine"
  Normal   Created    5m36s                  kubelet, kube-worker-f6q2j  Created container memcached
  Normal   Started    5m36s                  kubelet, kube-worker-f6q2j  Started container memcached
  Normal   Started    5m31s (x2 over 5m38s)  kubelet, kube-worker-f6q2j  Started container postgres
  Normal   Pulling    5m10s (x3 over 5m39s)  kubelet, kube-worker-f6q2j  Pulling image "postgres:11"
  Normal   Pulled     5m9s (x3 over 5m39s)   kubelet, kube-worker-f6q2j  Successfully pulled image "postgres:11"
  Normal   Created    5m9s (x3 over 5m38s)   kubelet, kube-worker-f6q2j  Created container postgres
  Warning  BackOff    38s (x24 over 5m25s)   kubelet, kube-worker-f6q2j  Back-off restarting failed container

Problem appears to be with PostgreSQL. Getting the PostgreSQL logs, reveals the following which makes me nervous:

kubectl logs gitea-gitea-66487d956f-2vx4q postgres

PostgreSQL Database directory appears to contain a database; Skipping initialization

2020-08-02 21:40:37.665 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-08-02 21:40:37.665 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2020-08-02 21:40:37.672 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-08-02 21:40:38.297 UTC [26] LOG:  database system was shut down at 2020-08-02 21:14:38 UTC
2020-08-02 21:40:38.310 UTC [26] LOG:  invalid resource manager ID in primary checkpoint record
2020-08-02 21:40:38.310 UTC [26] PANIC:  could not locate a valid checkpoint record
2020-08-02 21:40:38.584 UTC [1] LOG:  startup process (PID 26) was terminated by signal 6: Aborted
2020-08-02 21:40:38.584 UTC [1] LOG:  aborting startup due to startup process failure
2020-08-02 21:40:38.589 UTC [1] LOG:  database system is shut down

Any ideas? Sorry for the tangent, still just trying to get y'all a stack trace of the two-factor auth 5XX.

@nodesocket commented on GitHub (Aug 2, 2020): @techknowlogick well I think I know what the problem was, I updated `[log.console] LEVEL = Trace` as well. However this time when I ran `kubectl rollout restart deployment gitea-gitea` things went horribly wrong. The pods are just erroring out, and somehow it's trying to run two instances of gitea. I tried doing `kubectl delete pods gitea-gitea-66487d956f-2vx4q gitea-gitea-6d9456c44b-h4j8n` but it just brings both pods back up. I even tried `kubectl rollout undo gitea-gitea`. ``` gitea-gitea-66487d956f-2vx4q 2/3 CrashLoopBackOff 3 102s gitea-gitea-6d9456c44b-h4j8n 2/3 CrashLoopBackOff 3 102s ``` > kubectl describe pod gitea-gitea-66487d956f-2vx4q ``` Events: Type Reason Age From Message ---- ------ ---- ---- ------- Normal Scheduled <unknown> storageos-scheduler Successfully assigned default/gitea-gitea-66487d956f-2vx4q to kube-worker-f6q2j Normal Pulling 5m42s kubelet, kube-worker-f6q2j Pulling image "gitea/gitea:1.12.3" Normal Pulled 5m41s kubelet, kube-worker-f6q2j Successfully pulled image "gitea/gitea:1.12.3" Normal Created 5m41s kubelet, kube-worker-f6q2j Created container init Normal Started 5m40s kubelet, kube-worker-f6q2j Started container init Normal Pulling 5m38s kubelet, kube-worker-f6q2j Pulling image "gitea/gitea:1.12.3" Normal Started 5m37s kubelet, kube-worker-f6q2j Started container gitea Normal Pulling 5m37s kubelet, kube-worker-f6q2j Pulling image "memcached:1.6.6-alpine" Normal Pulled 5m37s kubelet, kube-worker-f6q2j Successfully pulled image "gitea/gitea:1.12.3" Normal Created 5m37s kubelet, kube-worker-f6q2j Created container gitea Normal Pulled 5m36s kubelet, kube-worker-f6q2j Successfully pulled image "memcached:1.6.6-alpine" Normal Created 5m36s kubelet, kube-worker-f6q2j Created container memcached Normal Started 5m36s kubelet, kube-worker-f6q2j Started container memcached Normal Started 5m31s (x2 over 5m38s) kubelet, kube-worker-f6q2j Started container postgres Normal Pulling 5m10s (x3 over 5m39s) kubelet, kube-worker-f6q2j Pulling image "postgres:11" Normal Pulled 5m9s (x3 over 5m39s) kubelet, kube-worker-f6q2j Successfully pulled image "postgres:11" Normal Created 5m9s (x3 over 5m38s) kubelet, kube-worker-f6q2j Created container postgres Warning BackOff 38s (x24 over 5m25s) kubelet, kube-worker-f6q2j Back-off restarting failed container ``` Problem appears to be with PostgreSQL. Getting the PostgreSQL logs, reveals the following which makes me nervous: > kubectl logs gitea-gitea-66487d956f-2vx4q postgres ``` PostgreSQL Database directory appears to contain a database; Skipping initialization 2020-08-02 21:40:37.665 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432 2020-08-02 21:40:37.665 UTC [1] LOG: listening on IPv6 address "::", port 5432 2020-08-02 21:40:37.672 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" 2020-08-02 21:40:38.297 UTC [26] LOG: database system was shut down at 2020-08-02 21:14:38 UTC 2020-08-02 21:40:38.310 UTC [26] LOG: invalid resource manager ID in primary checkpoint record 2020-08-02 21:40:38.310 UTC [26] PANIC: could not locate a valid checkpoint record 2020-08-02 21:40:38.584 UTC [1] LOG: startup process (PID 26) was terminated by signal 6: Aborted 2020-08-02 21:40:38.584 UTC [1] LOG: aborting startup due to startup process failure 2020-08-02 21:40:38.589 UTC [1] LOG: database system is shut down ``` Any ideas? Sorry for the tangent, still just trying to get y'all a stack trace of the two-factor auth **5XX**.
Author
Owner

@zeripath commented on GitHub (Aug 2, 2020):

Why have you put [log.console], [log.smtp] etc sections in?

I appreciate that the logging is complex - all logging configuration is - however:

Don't just copy stuff out of the sample ini! Those are just examples to show you how to structure things - they are absolutely not meant to be copied directly in to your app.ini. Most of it does nothing but could conflict with real configuration.

When it comes to any configuration, especially logging, you have to be clear what logging you want and to where you want it to go.

The simplest and easiest thing to do is to just output stuff to the console and therefore I recommend (at least at the start) to begin with the following:

[log]
LEVEL=Trace
MODE=console
REDIRECT_MACARON_LOG=true
MACARON=console
ROUTER=console
; XORM defaults to the same place as the main logs
; ACCESS is not relevant here

Now Xorm will by default log it's SQL which I generally find unhelpful unless I really need it.

[database]
LOG_SQL=false

An alternative is to direct the XORM logger to a file and then match that up later.

[log]
...
XORM=file

Then later you can deal with upping the level of logging to say INFO and add specific subloggers at TRACE level with EXPRESSIONs to match specific messages but let's not run before we walk first.

@zeripath commented on GitHub (Aug 2, 2020): Why have you put [log.console], [log.smtp] etc sections in? I appreciate that the logging is complex - all logging configuration is - however: Don't just copy stuff out of the sample ini! Those are just examples to show you how to structure things - they are absolutely not meant to be copied directly in to your app.ini. Most of it does nothing but could conflict with real configuration. When it comes to any configuration, especially logging, you have to be clear what logging you want and to where you want it to go. The simplest and easiest thing to do is to just output stuff to the console and therefore I recommend (at least at the start) to begin with the following: ```ini [log] LEVEL=Trace MODE=console REDIRECT_MACARON_LOG=true MACARON=console ROUTER=console ; XORM defaults to the same place as the main logs ; ACCESS is not relevant here ``` Now Xorm will by default log it's SQL which I generally find unhelpful unless I really need it. ```ini [database] LOG_SQL=false ``` An alternative is to direct the XORM logger to a file and then match that up later. ```ini [log] ... XORM=file ``` Then later you can deal with upping the level of logging to say INFO and add specific subloggers at TRACE level with EXPRESSIONs to match specific messages but let's not run before we walk first.
Author
Owner

@nodesocket commented on GitHub (Aug 2, 2020):

@zeripath appreciate the reply. All the log config was all done by the default Helm chart. Please see my reply above as this is now the main problem.

@nodesocket commented on GitHub (Aug 2, 2020): @zeripath appreciate the reply. All the log config was all done by the default Helm chart. Please see [my reply above](https://github.com/go-gitea/gitea/issues/12406#issuecomment-667727943) as this is now the main problem.
Author
Owner

@techknowlogick commented on GitHub (Aug 2, 2020):

I recommend using a tool such as https://k8slens.dev/ which will provide a GUI to help debug as this is reaching into k8s debugging territory vs debugging gitea.

@techknowlogick commented on GitHub (Aug 2, 2020): I recommend using a tool such as https://k8slens.dev/ which will provide a GUI to help debug as this is reaching into k8s debugging territory vs debugging gitea.
Author
Owner

@nodesocket commented on GitHub (Aug 3, 2020):

I am pretty sure that Trace logging it now enabled, see the following from the logs notice that is says Console(Console:trace).

kube-master - ubuntu ➜  gitea git:(master) ✗ kubectl logs gitea-gitea-556c594c4-n9vwn gitea -f
Server listening on :: port 22.
Server listening on 0.0.0.0 port 22.
2020/08/03 00:40:43 cmd/web.go:107:runWeb() [I] Starting Gitea on PID: 16
2020/08/03 00:40:43 ...dules/setting/git.go:93:newGit() [I] Git Version: 2.24.3, Wire Protocol Version 2 Enabled
2020/08/03 00:40:43 routers/init.go:118:GlobalInit() [T] AppPath: /app/gitea/gitea
2020/08/03 00:40:43 routers/init.go:119:GlobalInit() [T] AppWorkPath: /app/gitea
2020/08/03 00:40:43 routers/init.go:120:GlobalInit() [T] Custom path: /data/gitea
2020/08/03 00:40:43 routers/init.go:121:GlobalInit() [T] Log path: /app/gitea/log
2020/08/03 00:40:43 ...dules/setting/log.go:233:newLogService() [I] Gitea v1.12.3 built with GNU Make 4.2.1, go1.14.6 : bindata, sqlite, sqlite_unlock_notify
2020/08/03 00:40:43 ...dules/setting/log.go:279:newLogService() [I] Gitea Log Mode: Console(Console:trace)
2020/08/03 00:40:43 ...dules/setting/log.go:185:generateNamedLogger() [I] Macaron Log: Console(console:trace)
2020/08/03 00:40:43 ...dules/setting/log.go:185:generateNamedLogger() [I] Router Log: Console(console:trace)
2020/08/03 00:40:43 ...les/setting/cache.go:70:newCacheService() [I] Cache Service Enabled
2020/08/03 00:40:43 ...les/setting/cache.go:81:newCacheService() [I] Last Commit Cache Service Enabled
2020/08/03 00:40:43 ...s/setting/session.go:63:newSessionService() [I] Session Service Enabled
2020/08/03 00:40:43 ...es/setting/mailer.go:85:newMailService() [W] USE_SENDMAIL is deprecated, use MAILER_TYPE=sendmail
2020/08/03 00:40:43 ...es/setting/mailer.go:109:newMailService() [I] Mail Service Enabled
2020/08/03 00:40:43 ...es/setting/mailer.go:131:newNotifyMailService() [I] Notify Mail Service Enabled
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail-channel (QID: 1)
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail-level (QID: 2)
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail (QID: 3)
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service-channel (QID: 4)
2020/08/03 00:40:43 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: mail Starting
2020/08/03 00:40:43 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: mail Waiting til closed
2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 1 (for mail-channel) adding 1 workers with group id: 1
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service-level (QID: 5)
2020/08/03 00:40:43 ...ue/queue_bytefifo.go:95:Run() [D] level: mail-level Starting
2020/08/03 00:40:43 ...ue/queue_bytefifo.go:103:Run() [T] level: mail-level Waiting til closed
2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service (QID: 6)
2020/08/03 00:40:43 routers/init.go:162:GlobalInit() [I] SQLite3 Supported
2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 2 (for mail-level) adding 1 workers with group id: 1
2020/08/03 00:40:43 routers/init.go:50:checkRunMode() [I] Run Mode: Development
2020/08/03 00:40:43 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: notification-service Starting
2020/08/03 00:40:43 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: notification-service Waiting til closed
2020/08/03 00:40:43 ...ue/queue_bytefifo.go:95:Run() [D] level: notification-service-level Starting
2020/08/03 00:40:43 ...ue/queue_bytefifo.go:103:Run() [T] level: notification-service-level Waiting til closed
2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 4 (for notification-service-channel) adding 1 workers with group id: 1
2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 5 (for notification-service-level) adding 1 workers with group id: 1
2020/08/03 00:40:45 cmd/web.go:161:runWeb() [I] Listen: http://0.0.0.0:3000
2020/08/03 00:40:45 ...s/graceful/server.go:55:NewServer() [I] Starting new server: tcp:0.0.0.0:3000 on PID: 16
2020/08/03 00:40:45 ...s/graceful/server.go:66:func1() [D] Starting server on tcp:0.0.0.0:3000 (PID: 16)

However after the two-factor auth 5XX error, the logs only still only show:

... # a bunch of SQL queries above after the install screen is executed

2020/08/05 04:52:16 Completed GET /user/login?redirect_to= 200 OK in 70.330108ms
2020/08/05 04:52:16 Started GET /manifest.json for 10.244.1.1
2020/08/05 04:52:16 Completed GET /manifest.json 200 OK in 549.898µs
2020/08/05 04:52:17 Started GET /serviceworker.js for 10.244.1.1
2020/08/05 04:52:17 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /serviceworker.js
2020/08/05 04:52:17 Completed GET /serviceworker.js 304 Not Modified in 332.74µs
2020/08/05 04:52:18 Started POST /user/login for 10.244.1.1
2020/08/05 04:52:19 Completed POST /user/login 302 Found in 254.705876ms
2020/08/05 04:52:19 Started GET /user/two_factor for 10.244.1.1
2020/08/05 04:52:19 Completed GET /user/two_factor 200 OK in 4.122552ms
2020/08/05 04:52:19 Started GET /manifest.json for 10.244.1.1
2020/08/05 04:52:19 Completed GET /manifest.json 200 OK in 546.39µs
2020/08/05 04:52:21 Started GET /serviceworker.js for 10.244.1.1
2020/08/05 04:52:21 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /serviceworker.js
2020/08/05 04:52:21 Completed GET /serviceworker.js 304 Not Modified in 361.935µs
2020/08/05 04:52:36 Started POST /user/two_factor for 10.244.1.1
2020/08/05 04:52:36 Completed POST /user/two_factor 500 Internal Server Error in 19.515632ms
2020/08/05 04:52:36 Started GET /img/500.png for 10.244.1.1
2020/08/05 04:52:36 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /img/500.png
2020/08/05 04:52:36 Completed GET /img/500.png 200 OK in 1.175057ms
2020/08/05 04:52:36 Started GET /manifest.json for 10.244.1.1
2020/08/05 04:52:36 Completed GET /manifest.json 200 OK in 546.471µs
@nodesocket commented on GitHub (Aug 3, 2020): I am pretty sure that `Trace` logging it now enabled, see the following from the logs notice that is says `Console(Console:trace)`. ``` kube-master - ubuntu ➜ gitea git:(master) ✗ kubectl logs gitea-gitea-556c594c4-n9vwn gitea -f Server listening on :: port 22. Server listening on 0.0.0.0 port 22. 2020/08/03 00:40:43 cmd/web.go:107:runWeb() [I] Starting Gitea on PID: 16 2020/08/03 00:40:43 ...dules/setting/git.go:93:newGit() [I] Git Version: 2.24.3, Wire Protocol Version 2 Enabled 2020/08/03 00:40:43 routers/init.go:118:GlobalInit() [T] AppPath: /app/gitea/gitea 2020/08/03 00:40:43 routers/init.go:119:GlobalInit() [T] AppWorkPath: /app/gitea 2020/08/03 00:40:43 routers/init.go:120:GlobalInit() [T] Custom path: /data/gitea 2020/08/03 00:40:43 routers/init.go:121:GlobalInit() [T] Log path: /app/gitea/log 2020/08/03 00:40:43 ...dules/setting/log.go:233:newLogService() [I] Gitea v1.12.3 built with GNU Make 4.2.1, go1.14.6 : bindata, sqlite, sqlite_unlock_notify 2020/08/03 00:40:43 ...dules/setting/log.go:279:newLogService() [I] Gitea Log Mode: Console(Console:trace) 2020/08/03 00:40:43 ...dules/setting/log.go:185:generateNamedLogger() [I] Macaron Log: Console(console:trace) 2020/08/03 00:40:43 ...dules/setting/log.go:185:generateNamedLogger() [I] Router Log: Console(console:trace) 2020/08/03 00:40:43 ...les/setting/cache.go:70:newCacheService() [I] Cache Service Enabled 2020/08/03 00:40:43 ...les/setting/cache.go:81:newCacheService() [I] Last Commit Cache Service Enabled 2020/08/03 00:40:43 ...s/setting/session.go:63:newSessionService() [I] Session Service Enabled 2020/08/03 00:40:43 ...es/setting/mailer.go:85:newMailService() [W] USE_SENDMAIL is deprecated, use MAILER_TYPE=sendmail 2020/08/03 00:40:43 ...es/setting/mailer.go:109:newMailService() [I] Mail Service Enabled 2020/08/03 00:40:43 ...es/setting/mailer.go:131:newNotifyMailService() [I] Notify Mail Service Enabled 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail-channel (QID: 1) 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail-level (QID: 2) 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: mail (QID: 3) 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service-channel (QID: 4) 2020/08/03 00:40:43 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: mail Starting 2020/08/03 00:40:43 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: mail Waiting til closed 2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 1 (for mail-channel) adding 1 workers with group id: 1 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service-level (QID: 5) 2020/08/03 00:40:43 ...ue/queue_bytefifo.go:95:Run() [D] level: mail-level Starting 2020/08/03 00:40:43 ...ue/queue_bytefifo.go:103:Run() [T] level: mail-level Waiting til closed 2020/08/03 00:40:43 ...les/queue/manager.go:133:Add() [T] Queue Manager registered: notification-service (QID: 6) 2020/08/03 00:40:43 routers/init.go:162:GlobalInit() [I] SQLite3 Supported 2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 2 (for mail-level) adding 1 workers with group id: 1 2020/08/03 00:40:43 routers/init.go:50:checkRunMode() [I] Run Mode: Development 2020/08/03 00:40:43 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: notification-service Starting 2020/08/03 00:40:43 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: notification-service Waiting til closed 2020/08/03 00:40:43 ...ue/queue_bytefifo.go:95:Run() [D] level: notification-service-level Starting 2020/08/03 00:40:43 ...ue/queue_bytefifo.go:103:Run() [T] level: notification-service-level Waiting til closed 2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 4 (for notification-service-channel) adding 1 workers with group id: 1 2020/08/03 00:40:43 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 5 (for notification-service-level) adding 1 workers with group id: 1 2020/08/03 00:40:45 cmd/web.go:161:runWeb() [I] Listen: http://0.0.0.0:3000 2020/08/03 00:40:45 ...s/graceful/server.go:55:NewServer() [I] Starting new server: tcp:0.0.0.0:3000 on PID: 16 2020/08/03 00:40:45 ...s/graceful/server.go:66:func1() [D] Starting server on tcp:0.0.0.0:3000 (PID: 16) ``` However after the two-factor auth **5XX** error, the logs only still only show: ``` ... # a bunch of SQL queries above after the install screen is executed 2020/08/05 04:52:16 Completed GET /user/login?redirect_to= 200 OK in 70.330108ms 2020/08/05 04:52:16 Started GET /manifest.json for 10.244.1.1 2020/08/05 04:52:16 Completed GET /manifest.json 200 OK in 549.898µs 2020/08/05 04:52:17 Started GET /serviceworker.js for 10.244.1.1 2020/08/05 04:52:17 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /serviceworker.js 2020/08/05 04:52:17 Completed GET /serviceworker.js 304 Not Modified in 332.74µs 2020/08/05 04:52:18 Started POST /user/login for 10.244.1.1 2020/08/05 04:52:19 Completed POST /user/login 302 Found in 254.705876ms 2020/08/05 04:52:19 Started GET /user/two_factor for 10.244.1.1 2020/08/05 04:52:19 Completed GET /user/two_factor 200 OK in 4.122552ms 2020/08/05 04:52:19 Started GET /manifest.json for 10.244.1.1 2020/08/05 04:52:19 Completed GET /manifest.json 200 OK in 546.39µs 2020/08/05 04:52:21 Started GET /serviceworker.js for 10.244.1.1 2020/08/05 04:52:21 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /serviceworker.js 2020/08/05 04:52:21 Completed GET /serviceworker.js 304 Not Modified in 361.935µs 2020/08/05 04:52:36 Started POST /user/two_factor for 10.244.1.1 2020/08/05 04:52:36 Completed POST /user/two_factor 500 Internal Server Error in 19.515632ms 2020/08/05 04:52:36 Started GET /img/500.png for 10.244.1.1 2020/08/05 04:52:36 ...les/public/public.go:156:handle() [I] [Macaron] [Static] Serving /img/500.png 2020/08/05 04:52:36 Completed GET /img/500.png 200 OK in 1.175057ms 2020/08/05 04:52:36 Started GET /manifest.json for 10.244.1.1 2020/08/05 04:52:36 Completed GET /manifest.json 200 OK in 546.471µs ```
Author
Owner

@nodesocket commented on GitHub (Aug 5, 2020):

@zeripath @techknowlogick Is there anyway to just disable two-factor auth manually in the PostgreSQL database for my user? As I mentioned above, I believe I have Trace logging enabled, but don't see anything logged to console when I get the 5XX error after entering a valid two-factor auth token.

@nodesocket commented on GitHub (Aug 5, 2020): @zeripath @techknowlogick Is there anyway to just disable two-factor auth manually in the PostgreSQL database for my user? As I mentioned above, I believe I have `Trace` logging enabled, but don't see anything logged to console when I get the 5XX error after entering a valid two-factor auth token.
Author
Owner

@nodesocket commented on GitHub (Aug 5, 2020):

I was able to work around this by getting a shell into PostgreSQL and running:

update two_factor set uid = 111 where id = 1;

Note that uuid = 111 does not exist, but this prevented the two-factor auth screen from showing when logging in. Not sure what happened. An interesting note, is I did go enable two-factor auth again for my same user, logout, then log back in and it worked using two-factor without a 5XX error.

After that I went and deleted the old (broken) two-factor entry in PostgreSQL manually:

delete from two_factor where id = 1;
@nodesocket commented on GitHub (Aug 5, 2020): I was able to work around this by getting a shell into PostgreSQL and running: ``` update two_factor set uid = 111 where id = 1; ``` Note that `uuid = 111` does not exist, but this prevented the two-factor auth screen from showing when logging in. Not sure what happened. An interesting note, is I did go enable two-factor auth again for my same user, logout, then log back in and it worked using two-factor without a 5XX error. After that I went and deleted the old (broken) two-factor entry in PostgreSQL manually: ``` delete from two_factor where id = 1; ```
Author
Owner

@stale[bot] commented on GitHub (Oct 4, 2020):

This issue has been automatically marked as stale because it has not had recent activity. I am here to help clear issues left open even if solved or waiting for more insight. This issue will be closed if no further activity occurs during the next 2 weeks. If the issue is still valid just add a comment to keep it alive. Thank you for your contributions.

@stale[bot] commented on GitHub (Oct 4, 2020): This issue has been automatically marked as stale because it has not had recent activity. I am here to help clear issues left open even if solved or waiting for more insight. This issue will be closed if no further activity occurs during the next 2 weeks. If the issue is still valid just add a comment to keep it alive. Thank you for your contributions.
Author
Owner

@wxiaoguang commented on GitHub (Dec 12, 2021):

This problem is caused by the lost (or regenerated) SECRET_KEY in app.ini, Gitea can not decrypt the 2FA secret correctly.

@wxiaoguang commented on GitHub (Dec 12, 2021): This problem is caused by the lost (or regenerated) SECRET_KEY in `app.ini`, Gitea can not decrypt the 2FA secret correctly.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: github-starred/gitea#5816