Potential problem with session #15549

Closed ndaidong closed 2 years ago

Gitea version (or commit ref): 1.14.0
Git version: 2.29.2
Operating system: Debian 10.9

This gist shows detail how we setup our gitea server:

https://gist.github.com/ndaidong/2fad09f49db27d115f6d47eba7e91cb8

Database (use [x]):
- [x] PostgreSQL
- [ ] MySQL
- [ ] MSSQL
- [ ] SQLite
Can you reproduce the bug at https://try.gitea.io:
- [ ] Yes (provide example URL)
- [x] No
Log gist:

Description

We've setup gitea for our company. After migrating from Bitbucket, here is what we have now:

Screenshot from 2021-04-20 10-51-28

There is often about 40 users online at any time. Everything work well, thank you so much for your effort to build a great platform as Gitea.

However, sometimes we found that the session suddenly closes and we have to login again. It occurs with admin accounts and normal users too.

Could you give us any idea, or conjecture about this odd phenomenon?

Just a quick note about your config, you have fully copied the app.example.ini which is for documentation purposes and not meant to be copied in full (you'll note: https://gist.github.com/ndaidong/802c8157df3771ce097a42c3c9a01b70#file-app-ini-L441 log.x doesn't actually do anything), and so you should only set settings you are confident of and leave default settings up to Gitea.

@techknowlogick yes I just modify what I need and understand. Do you mean I should remove the default parts from that .ini?

Is this folder exist with correct file permission? /storage/runtime/sessions

@lunny yes, the whole /storage directory is owned by git:git.

For more info, I separate into several parts, in which:

/storage/gitea: persistent data to backup
/storage/runtime: data generated in runtime, not saving to NAS

sysad@gitserver /storage $ tree -L 2
.
├── gitea
│   ├── repositories
│   ├── ssh
│   └── uploads
├── lfs
├── lost+found [error opening dir]
├── runtime
│   ├── indexers
│   ├── logs
│   └── sessions
└── tmp
    └── local-repo

default sessions is stored into files which should be persistent. Once the files deleted, the session will be invalid and users will be prompted to login.

Also default indexers will use bleve which will store as files. Once the files deleted, and Gitea will regenerated them when restart.

@lunny certainly, these files are persistent. And I can ensure that nothing affect to them while the system is working. Any suggestion to check?

Have you tried to upgrade to v1.14.1?

@lunny not yet. But I have plan to try. Because at least it resolves the issue superfluous response.WriteHeader.

@techknowlogick yes I just modify what I need and understand. Do you mean I should remove the default parts from that .ini?

the file you are basing your current app.ini on is documentation and provides examples, but should NOT be use as a base with just a few things updated. You should start with an empty app.ini and only add the things you need to it.

@techknowlogick I'm upgrading to v1.14.1 and refactoring the app.ini file. Hopefully that it becomes more stable. I will update the situation after few hours of monitoring.

@lunny @techknowlogick hello, I've upgraded successfully to v1.14.1 and refactored app.ini file. Now the config file is only 4.5 kb. It seems the session is more stable than earlier but the error "superfluous response.WriteHeader call" is still happening, and there is another issue.

@lunny Please look into this issue carefully. I believe that we are facing a serious problem here.

Some people in my company and I found that sometimes we get into other session. Let's says a user A login Gitea last night, and today morning, when A comes back, he found that the account he is using is B. In almost cases, he is being redirected to login page, but in the worst cases, he can even use B's account to navigate around and change personal settings.

The sessions have been stored into hard drive, as below:

[session]
PROVIDER          = file
PROVIDER_CONFIG   = /storage/runtime/sessions
COOKIE_NAME       = i_dont_like_cookie
COOKIE_SECURE     = true
SAME_SITE         = lax

Now we've changed to redis:

[session]
PROVIDER          = redis
PROVIDER_CONFIG   = network=tcp,addr=127.0.0.1:6379,db=0,pool_size=100,idle_timeout=180
COOKIE_NAME       = i_dont_like_cookie
COOKIE_SECURE     = true
SAME_SITE         = lax

Have you use a reverse proxy for your Gitea instance?

@lunny yes, we use nginx. And let's encrypt for SSL certificate.

@lunny @techknowlogick hello, this problem is still happening with us. Today at least 2 users reported: they have seen that they have been using the account of another user (same account, let's say X).

case 1: after weekend, A opens the homepage and clicks on the signin buton --> redirect to X's dashboard without login
case 2: B clicks on a link to an issue shared by C via Skype --> open that page under X account

IMO, the cause may not relate to the session, but SSO mechanism. I'm investigating the modules at /auth/sso, please share to me the diagrams here if any.

Which SSO system do you use?

@techknowlogick no, I mean gitea's SSO (modules/auth/sso), I don't use any SSO system outside.

Today I've switched the session store to postgres database. file and redis are failed in my case.

We support reverse proxy sso, see https://github.com/go-gitea/gitea/blob/master/modules/auth/sso/reverseproxy.go

@lunny I notice that today this problem occurs again for many accounts in our system. (Last week I've switched to postgres db, and it worked as well until now.)

At 05/May/2021:08:53:53, administor suddenly sees himself as phutv:

10.1.0.25:47790 - administor [05/May/2021:08:53:53 &#43;0700] "GET /phutv HTTP/1.1" 200 25272 "\" \"Mozilla/5.0 (X11; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0"

At this time, system logs produce many superfluous errors:

2021/05/05 08:53:18 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:22 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:22 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:22 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:22 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:22 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:53 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:53 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:53 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:53 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:53 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:57 ...les/public/public.go:165:handle() [I] [Static] Serving /js/clipboard.js
2021/05/05 08:53:57 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:57 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:57 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:57 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/05 08:53:57 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)

I'm not sure that Gitea generates the log with the user requesting: 10.1.0.25:47790 - administor [05/May/2021:08:53:53 +0700] "GET /phutv HTTP/1.1" 200 25272 "\" \"Mozilla/5.0 (X11; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0", are you sure you are not using a reverse proxy, or SSO of any kind? Where did you get that log from? That log also shows the user just accessing the profile page for that user, not that the user has switched or anything. You can see in the top right of the page the user that is requesting the page.

@techknowlogick we are using nginx as reverse proxy, no SSO of any kind. This nginx server takes responsibility for routing and let's enscrypt SSL, it serves hundreds of websites (we are technology company).

The architecture is quite simple:

Screenshot from 2021-05-06 12-32-01

@techknowlogick @lunny another serious problem may relate to this issue: non-member user can access organization/repo without permission!

One of the organization owners reported to me today. He just added 6 people to the organization eoffice-qn, but he has been seeing non-members push code to the repos there. As I've checked, this non-member can access the repos via SSH/HTTP and web GUI too.

This is people in the organization: Screenshot from 2021-05-07 09-04-07

And this is the view by non-member user: Screenshot from 2021-05-07 09-04-28

In the table org_user, there is exactly 6 users linked to this org: Screenshot from 2021-05-07 09-23-39

I'm trying to replicate this locally, however using the config you've provided I can't. Are you able to start a fresh install, and be able to provide repeatable step by step instructions on how to trigger this?

@techknowlogick I could not reproduce the issue. I have already a fresh install for mirror system. The problem does not happen here, with 3 or 4 people in the manager team.

In the past I've used gitea for several small projects, and never seen the issues as today when I deploy it to a company with more than 100 users. I can provide you a regular account for test if needed, sometimes you may see you as system admin.

Anyway to downgrate to v1.3? I would like to check if it relates to the replacement of go-chi/session.

Are these people using the same browser?

It would be useful to check their cookies and in particular the path for the cookies.

One of the things we did in 1.14 was actually formalize and rationalize our cookie paths. So if you have old cookies you may find that they're not logging out properly - delete them and they'll never come back and it will be fine. (Or even just change the name of the cookies that gitea is using.)

Could you check your config paths for cookies on the server too?

@zeripath These people each one work on their own computer, use their own account. The first version I've setup is v1.14, then upgraded to v1.14.1 to fix this issue but it's still happening.

Here is the cookie on my browser.

Screenshot from 2021-05-07 13-57-31

Could you check your app.ini and ensure that REVERSE_PROXY_AUTHENTICATION_USER and ENABLE_REVERSE_PROXY_AUTHENTICATION are not set.

@zeripath yes, they are not set. Should and how I set them?

I'm focused on the log line you gave 10.1.0.25:47790 - administor [05/May/2021:08:53:53 +0700] "GET /phutv HTTP/1.1" 200 25272 "\" \"Mozilla/5.0 (X11; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0" is this from nginx? what is putting administor into the log?

Are you using Cloudfare or some caching thing between gitea and the nginx?

@techknowlogick no, that log was generated by Gitea itself. In the app config file, I configured as below:

[log.file]
LEVEL               = info
FILE_NAME           = /storage/runtime/logs/activity.log

@zeripath no, I don't use any caching system. The architecture is exactly as I've shared in the comment 833239188

@techknowlogick - they've set up the access logger - so it's possible that's that's coming from there:

[log]
MODE                = console, file
LEVEL               = info
ROOT_PATH           = /storage/runtime/logs
ENABLE_ACCESS_LOG   = true
ACCESS_LOG_TEMPLATE = {{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"

[log.file]
LEVEL               = info
FILE_NAME           = /storage/runtime/logs/activity.log

@ndaidong Sorry that this is taking so long to sort out - this is a complex problem and we still don't have enough information to work out what is happening let alone how to solve it. I think we need to be more systematic instead of just guessing at things now.

So first I'm going to review the app.ini:

I'm a little concerned by:
```
[server]
DOMAIN           = localhost
```

HTTP_ADDR = 0.0.0.0 HTTP_PORT = 8081 ROOT_URL = http://localhost:8081/

DISABLE_SSH = false


* I don't think that this can be true at all. What is the value of `PROTOCOL` and please tell me that your ROOT_URL is not `http://localhost:8081/`?
* I also see that you're explicitly setting the cookie names - which is definitely in keeping with your use of app.example.ini in the past which may suggest that you've had the paths etc for these wrong. 
* I see you have the `[cache]` set-up which could be a difference with other users - but I'm not certain how that could cause a problem - it's just something to bear in mind.
* What I'm not seeing are things like REVERSE_PROXY headers which is a good thing. I also note that you don't have BASIC authentication disabled - (don't change this yet.)

But there's no gigantic smoking gun there (Apart from that localhost in ROOT_URL and lack of PROTOCOL)

---

Now let's think about how to solve or investigate this further. 

To me it looks like we need some more logging. We're not aware of how people are getting their IDs changed and why.

This is comment 30 on this issue and we still haven't seen any DEBUG logs - which is kinda ridiculous tbh - however looking at 1.14 and main I'm not sure there's much logging that would be gained by this - meaning that we will need to add some patches to add some logging. (I had PRs that were significantly working on rationalising this stuff but they've totally stagnated due to other pressures and lack of reviews... #15304 #15303 fyi - there is a 3rd PR that's going to refactor by moving modules/auth/sso to services/auth and then add all of this logging and but with the lack of reviews for the previous two - progress is totally stalled.) 

So are you able to compile Gitea with a few patches to attempt to add at least some TRACE logging to modules/auth/sso and elsewhere? Once those patches are in it would be possible to add a very restricted trace level logger to gitea using a simple additional config:

<details><summary>Additional Config</summary>

```ini
[log]
MODE                = console, file, tracesso
LEVEL               = info
ROOT_PATH           = /storage/runtime/logs
ENABLE_ACCESS_LOG   = true
ACCESS_LOG_TEMPLATE = {{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"

[log.file]
LEVEL               = info
FILE_NAME           = /storage/runtime/logs/activity.log

[log.tracesso]
LEVEL=trace
EXPRESSION=modules/auth/sso; This may need to be adjusted depending on how these patches turn out - this is just an example.
MODE=file
FILE_NAME           = /storage/runtime/logs/tracesso.log

Another option - just to rule out any weirdness with cookies is simply to change all of the names of the cookies - in case there are some weird issues there.
One other thing - are people using BASIC authentication to log in to Gitea using the swagger API on these machines or something else? Assuming that you're only pushing with SSH you could actually try disabling basic authentication. However, I think that would be seriously detrimental to most people's workflows.
I know that we're only creating session IDs within 16 byte character space which isn't huge - Are you having lots of sessions created and destroyed? Maybe you're genuinely hitting collisions with sessions?!

All in all I think we need more logging as we're totally in the dark. Unfortunately due to the lack of trace logging in these functions we're gonna need to have some patches compiled in.

If you would like me to write these and/or compile things I would be happy to discuss them further - drop me an email or message on discord. I'll pop up a PR to Gitea to actually add some trace logging to main/v1.15.x however, I need other maintainers to review and approve. Backporting from that PR to 1.14 would then be easier. (And paradoxically easier because of the stalled progress on #15304 & #15303 and their subsequent PRs.)

@zeripath thank you so much. I understand that the infomation is quite vague. That's not easy to guess the root cause.

For the config, I'm sorry for the missed things in the app.ini; it has been modified a few times. I've just updated it with the latest content from our server.

https://gist.github.com/ndaidong/802c8157df3771ce097a42c3c9a01b70

The ROOT_URL is actually set to https://source.greenglobal.vn.

Regarding the cookie, I've used custom name for all of them.
In my company almost people use basic authentication, so I have to enable both HTTP/SSH. However, the swagger has been disabled since the first installation.
Totally, there are only about 150 - 180 sessions at any time.

I will try to re-compile using the pr #15304 & #15303 to gather more meaningful logs first. If that doesn't help, I will ask you on discord for more steps.

Once again, thank you for your advice.

15304 & #15303 won't necessarily help this. I still need to pop up the logging PR and will refer to this issue once it's up.

15303 would rule out Basic Authentication as the cause for weird shifts so is not completely useless.

15803 is the trace logging PR

@zeripath I've tried to upgrade our main system to v1.14.2 and setup a clone using the source code based on #15803

I plan to switch the official domain to new version after a careful testing step, and that will be done at the mid-night. So I will report to you the result in the next few days unless something's wrong.

@zeripath hello, after upgrading to v1.5.x, I see nothing new in the activity logs. Does it require updated config?

Currently, it looks like below:

[log]
MODE                = console, file
LEVEL               = info
ROOT_PATH           = /storage/runtime/logs
ENABLE_ACCESS_LOG   = true
ACCESS_LOG_TEMPLATE = {{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"

[log.file]
LEVEL               = info
FILE_NAME           = /storage/runtime/logs/activity.log

And the output:

2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:27 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /vendor/plugins/codemirror/mode/meta.js
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /js/easymde.js
2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /vendor/plugins/codemirror/addon/mode/loadmode.js
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /css/easymde.css
2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /fonts/icons.woff2
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /js/dropzone.js
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /css/dropzone.css
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /js/tribute.js
2021/05/12 14:48:31 ...les/public/public.go:164:handle() [I] [Static] Serving /js/clipboard.js

Hi!

As I wrote above you'd need to add some additional config to your app.ini to add a trace logger to modules/auth/sso.

Change your app.ini log sections to

[log]
MODE                = console, file, tracesso
LEVEL               = info
ROOT_PATH           = /storage/runtime/logs
ENABLE_ACCESS_LOG   = true

[log.file]
LEVEL               = info
FILE_NAME           = /storage/runtime/logs/activity.log

[log.tracesso]
LEVEL=trace
EXPRESSION=modules/auth/sso
MODE=file
FILE_NAME           = /storage/runtime/logs/tracesso.log

It looks like your ACCESS_LOG_TEMPLATE is just the default so you don't need to set that.

What version exactly did you upgrade to? These log lines:

2021/05/12 14:48:31 ...c/net/http/server.go:3139:logf() [I] http: superfluous response.WriteHeader call from code.gitea.io/gitea/modules/context.(*Response).WriteHeader (response.go:67)

Shouldn't be present in main - so I'm confused as to how you're getting them.

@zeripath thank you, I've updated config.

go-gitea / gitea