nextcloud / server

☁️ Nextcloud server, a safe home for all your data
https://nextcloud.com
GNU Affero General Public License v3.0
27.4k stars 4.07k forks source link

[Bug]: Tried to log in "username" but could not verify token #33919

Closed AndyXheli closed 1 year ago

AndyXheli commented 2 years ago

⚠️ This issue respects the following points: ⚠️

Bug description

Not sure what's causing this the user is LDAP backend

Steps to reproduce

1.Open brower 2.go to server.domain.com 3.takes to me dashboard

Expected behavior

Should not see this error in logs

Installation method

Community Manual installation with Archive

Operating system

Debian/Ubuntu

PHP engine version

PHP 8.0

Web server

Apache (supported)

Database engine version

MySQL

Is this bug present after an update or on a fresh install?

Updated to a major version (ex. 22.2.3 to 23.0.1)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

Configuration report

No response

List of activated Apps

Enabled:
  - activity: 2.17.0
  - admin_audit: 1.15.0
  - cloud_federation_api: 1.8.0
  - comments: 1.15.0
  - contactsinteraction: 1.6.0
  - dashboard: 7.5.0
  - dav: 1.24.0
  - federatedfilesharing: 1.15.0
  - federation: 1.15.0
  - files: 1.20.0
  - files_external: 1.17.0
  - files_pdfviewer: 2.6.0
  - files_rightclick: 1.4.0
  - files_sharing: 1.17.0
  - files_trashbin: 1.15.0
  - files_versions: 1.18.0
  - files_videoplayer: 1.14.0
  - firstrunwizard: 2.14.0
  - logreader: 2.10.0
  - lookup_server_connector: 1.13.0
  - nextcloud_announcements: 1.14.0
  - notifications: 2.13.1
  - oauth2: 1.13.0
  - officeonline: 1.1.3
  - password_policy: 1.15.0
  - photos: 1.7.0
  - privacy: 1.9.0
  - provisioning_api: 1.15.0
  - recommendations: 1.4.0
  - serverinfo: 1.15.0
  - settings: 1.7.0
  - sharebymail: 1.15.0
  - spreed: 15.0.0-beta.2
  - survey_client: 1.13.0
  - suspicious_login: 4.2.0
  - systemtags: 1.15.0
  - text: 3.6.0
  - theming: 2.0.0
  - twofactor_backupcodes: 1.14.0
  - twofactor_email: 2.6.0
  - twofactor_totp: 6.4.0
  - updatenotification: 1.15.0
  - user_ldap: 1.15.0
  - user_status: 1.5.0
  - viewer: 1.9.0
  - weather_status: 1.5.0
  - workflowengine: 2.7.0
Disabled:
  - bruteforcesettings: 2.4.0
  - circles: 23.1.1
  - encryption
  - files_downloadactivity: 1.13.0
  - groupfolders: 12.0.1
  - impersonate: 1.11.0
  - notify_push: 0.4.0
  - socialsharing_email: 2.5.0
  - support: 1.8.0
  - twofactor_admin: 3.2.0

Nextcloud Signing status

No response

Nextcloud Logs

{"reqId":"RSUtKkS7Br5VdD2bT5QY","level":3,"time":"2022-09-06T13:53:34+00:00","remoteAddr":"10.0.10.90","user":"--","app":"core","method":"GET","url":"/ocs/v2.php/search/providers?from=%2Fapps%2Fdashboard%2F","message":"Tried to log in "username" but could not verify token","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36","version":"25.0.0.8","data":{"app":"core"},"id":"63175db7214f1"}

Additional info

image

szaimen commented 2 years ago

cc @ChristophWurst

ChristophWurst commented 2 years ago

Whohoo. I've rarely been so happy to see an error in the logs.

So, this is from https://github.com/nextcloud/server/pull/33772. Can you tell if this log was triggered by one (or a few) users? You could cross-check with the access logs and the IPs. That is visible from the log message. Just tell me if it always the same user ;-)

My suspicion is that this happens when the users open their browser in the morning. Over night the server's php session has expired and the user probably had more than one tab open. The browser then sends off multiple concurrent requests and each of them tries to recover the session from cookies. But then only one request actually wins because it will take the valid token. The other requests show up too late, when the valid token had already been cleared from the database.

Just a theory but curios to hear if this could have been the case for you or your users.

ChristophWurst commented 2 years ago

https://github.com/nextcloud/server/pull/33930 adds more debugging insights. If you can, apply the patch on your instance, set the log level to debug for a day and then check if Regenerating cookie login token for {uid} after successful verification shows up shortly before the first Tried to log in {uid} but could not verify token. That would confirm my theory.

AndyXheli commented 2 years ago

I think your right because I believe I did have alot of tabs open from the night and in the morning I open a few sessions and accessed the server but the other tabs where closed. Once I get in the office I will test and let you know

AndyXheli commented 2 years ago

@ChristophWurst I think we're good i applied the #33930

seen this in the debug logs

{
  "reqId": "VdFFfpQ5RgUst3jHnVid",
  "level": 0,
  "time": "2022-09-07T14:33:29+00:00",
  "remoteAddr": "1.5.5.11",
  "user": "--",
  "app": "core",
  "method": "GET",
  "url": "/",
  "message": "Regenerating cookie login token for admin after successful verification",
  "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36",
  "version": "25.0.0.8",
  "data": {
    "app": "core"
  }
}
ChristophWurst commented 2 years ago

Okay but do you see a bunch of Tried to log in admin but could not verify token logged afterwards?

One single Regenerating cookie login token for admin after successful verification is fine. It means a request revived a valid session.

AndyXheli commented 2 years ago

Just tried it and it comes up under the error level

{
  "reqId": "NZYI1iLkoFOEo6GLg6XQ",
  "level": 3,
  "time": "2022-09-07T17:45:57+00:00",
  "remoteAddr": "10.0.10.90",
  "user": "--",
  "app": "core",
  "method": "GET",
  "url": "/",
  "message": "Tried to log in admin but could not verify token",
  "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36",
  "version": "25.0.0.8",
  "data": {
    "app": "core"
  },
  "id": "6318d8f9ed60a"
}
AndyXheli commented 2 years ago

Tried it from a different pc

Debug | core | Regenerating cookie login token for admin after successful verification |   | a minute ago -- | -- | -- | -- | -- Error | core | Tried to log in admin but could not verify token |   | a minute ago Debug | core | Regenerating cookie login token for admin after successful verification |   | a minute ago

But should that error be under debug ?

ChristophWurst commented 2 years ago

We can lower to warning. Nevertheless this is an error in the auth flow and likely leads to a defunct browser window.

AndyXheli commented 2 years ago

Yea I think either warring or info since it really giving you info and technically since its not something to worry about . What do you think ? Id suggest info but what ever you think is best :)

ChristophWurst commented 2 years ago

The bigger picture is that once I have clear insight into the token verification errors and what leads up to them, I want to actually fix them. They shouldn't be part of the auth flow. A token mismatch should only be detected for malicious users, not for someone who opened their browser in the morning with Nextcloud pages open.

AndyXheli commented 2 years ago

Ahhh i see that makes a lot more sense if you need any testing from my end I'm happy to help.

Rello commented 2 years ago

having the same issue on my NC25 only additional info I find is that the php/sessions/ directory had multiple entries per attempt. dont know if relevant?

in the log i have one error

{"reqId":"Z5di2cFpYzamXLxxhgAO","level":3,"time":"2022-09-27T17:58:45+00:00","remoteAddr":"192.168.0.221","user":"--","app":"core","method":"POST","url":"/nextcloud/login","message":"Tried to log in admin but could not verify token","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36","version":"25.0.0.11","data":{"app":"core"}}
{"reqId":"8dBCwodKtjd6p3N9vSFI","level":3,"time":"2022-09-27T17:58:45+00:00","remoteAddr":"192.168.0.221","user":"--","app":"core","method":"GET","url":"/nextcloud/apps/dashboard/","message":"Tried to log in admin but could not verify token","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36","version":"25.0.0.11","data":{"app":"core"}}
{"reqId":"8dBCwodKtjd6p3N9vSFI","level":0,"time":"2022-09-27T17:58:45+00:00","remoteAddr":"192.168.0.221","user":"--","app":"no app in context","method":"GET","url":"/nextcloud/apps/dashboard/","message":"Current user is not logged in","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36","version":"25.0.0.11","exception":{"Exception":"OC\\AppFramework\\Middleware\\Security\\Exceptions\\NotLoggedInException","Message":"Current user is not logged in","Code":401,"Trace":[{"file":"/var/www/nextcloud/lib/private/AppFramework/Middleware/MiddlewareDispatcher.php","line":97,"function":"beforeController","class":"OC\\AppFramework\\Middleware\\Security\\SecurityMiddleware","type":"->"},{"file":"/var/www/nextcloud/lib/private/AppFramework/Http/Dispatcher.php","line":125,"function":"beforeController","class":"OC\\AppFramework\\Middleware\\MiddlewareDispatcher","type":"->"},{"file":"/var/www/nextcloud/lib/private/AppFramework/App.php","line":172,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"/var/www/nextcloud/lib/private/Route/Router.php","line":298,"function":"main","class":"OC\\AppFramework\\App","type":"::"},{"file":"/var/www/nextcloud/lib/base.php","line":1047,"function":"match","class":"OC\\Route\\Router","type":"->"},{"file":"/var/www/nextcloud/index.php","line":36,"function":"handleRequest","class":"OC","type":"::"}],"File":"/var/www/nextcloud/lib/private/AppFramework/Middleware/Security/SecurityMiddleware.php","Line":153,"message":"Current user is not logged in","exception":{},"CustomMessage":"Current user is not logged in"}}
{"reqId":"e2dzx8WlzlBb1oSBOZnP","level":3,"time":"2022-09-27T17:58:46+00:00","remoteAddr":"192.168.0.221","user":"--","app":"core","method":"GET","url":"/nextcloud/login?redirect_url=/nextcloud/apps/dashboard/","message":"Tried to log in admin but could not verify token","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36","version":"25.0.0.11","data":{"app":"core"}}

one solution which worked for me is to delete login_token entries in the oc_preferences table

ChristophWurst commented 2 years ago

@Rello do you have https://github.com/nextcloud/server/pull/33930 applied as well? Would be interesting to know if a token was used successfully before other requests failed to use the same.

Rello commented 2 years ago

I am on beta 6 - and this should have been merged, correct?

ChristophWurst commented 2 years ago

It is not merged. Right now this is an optional patch.

LokeYourC3PH commented 2 years ago

Just wanted to chime in that I am facing the same issue. Some accounts straight up can not login at all on their Browsers, and need to use temporary accounts to get into the drive.

ChristophWurst commented 2 years ago

Just wanted to chime in that I am facing the same issue. Some accounts straight up can not login at all on their Browsers, and need to use temporary accounts to get into the drive.

Could you ask one of the affected users to clear their cookies and see if that helps?

LokeYourC3PH commented 2 years ago

Just wanted to chime in that I am facing the same issue. Some accounts straight up can not login at all on their Browsers, and need to use temporary accounts to get into the drive.

Could you ask one of the affected users to clear their cookies and see if that helps?

Uhh, I was physically at his PC earlier, so when that happens again, I'll make sure to try that. On another note, it even happened to me on my main, super admin (owner) account. My interface sometimes opened for a quick sec before it gave me a countdown for logging me out, and when I went quickly into settings from there, it stopped and fixed it. Truly weird.

LokeYourC3PH commented 2 years ago

If you have that optional patch readily available for install, maybe you can let me know quickly how to install it so I can give it a try on our system, see if that solves it permanently. If it does, it means the patch is also fully functional.

tsipizic commented 2 years ago

Just wanted to chime in that I am facing the same issue. Some accounts straight up can not login at all on their Browsers, and need to use temporary accounts to get into the drive.

Could you ask one of the affected users to clear their cookies and see if that helps?

I am also affected by that and cookie cleaning/private window did not help. Server reboot/PHP cache clean helped though

LokeYourC3PH commented 2 years ago

Just wanted to chime in that I am facing the same issue. Some accounts straight up can not login at all on their Browsers, and need to use temporary accounts to get into the drive.

Could you ask one of the affected users to clear their cookies and see if that helps?

I am also affected by that and cookie cleaning/private window did not help. Server reboot/PHP cache clean helped though

That's what I did as well as soon as 3 accounts had that issue (and I can't create hundreds of temporary accounts as a workaround), and it solved it. But I also can't reboot the server daily really.

solracsf commented 2 years ago

This is not a v25 thing only (as it has been backported); I get this same error on v23.0.10 (after upgrade from v23.0.9). Using SSO/SAML app. Different users logged, a few lines per user.

As far as i can see, it triggers for every user.

{
  "reqId": "dccjg6BA5aG2UhFJyBRU",
  "level": 3,
  "time": "2022-10-15T14:42:38+00:00",
  "user": "--",
  "app": "core",
  "method": "GET",
  "url": "/csrftoken",
  "message": "Tried to log in username but could not verify token",
  "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) Gecko/20100101 Firefox/105.0",
  "version": "23.0.10.1",
  "data": {
    "app": "core"
  },
  "id": "634ac795cdd29"
}
Sieboldianus commented 2 years ago

I got it on 24.0.6, too.

AndyXheli commented 2 years ago

Yes, same got the errors on 24.0.6

LokeYourC3PH commented 2 years ago

It's hella interesting honestly to see that even though this bug tracker was established a little while ago, that the issue started popping up more recently in bigger numbers and with less frequency in-between each time. Makes you wonder what the trigger for that could be 🤔

ChristophWurst commented 2 years ago

The error condition had been there for a very very long time. The only thing that changed is that we now log it and https://github.com/nextcloud/server/pull/33772 was backported to 24 and 23.

solracsf commented 2 years ago

In case of SAML, it's just spamming the logs with more than 4K entries today (less than 100 users).

AndyXheli commented 2 years ago

That's defiantly not good :( Should this be liking this meaning should we get these errors and warnings this often ?

evilaliv3 commented 2 years ago

As an update we have other evidences of this bugs on this discussion: https://github.com/nextcloud/all-in-one/discussions/1300

Here i'm testing myself a new setup on Nextcloud AIO and i'm the only user

AndyXheli commented 2 years ago

Also seems like sessions get logged off very often now on NC 25

eibex commented 2 years ago

I started getting this on 24.0.6. It wasn't happening with Chrome but it is now happening with Firefox.

The logs don't offer any information other than my IP and the action (POST login).

I am not using LDAP or other user databases. I am using the default NC backend. The only thing that comes to mind that doesn't always play nice with logins is 2FA/suspicious login (e.g. sometimes you need to login twice with IPv6).

pmlejnek commented 2 years ago

This is not a v25 thing only (as it has been backported); I get this same error on v23.0.10 (after upgrade from v23.0.9). Using SSO/SAML app. Different users logged, a few lines per user.

As far as i can see, it triggers for every user.

{
  "reqId": "dccjg6BA5aG2UhFJyBRU",
  "level": 3,
  "time": "2022-10-15T14:42:38+00:00",
  "user": "--",
  "app": "core",
  "method": "GET",
  "url": "/csrftoken",
  "message": "Tried to log in username but could not verify token",
  "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) Gecko/20100101 Firefox/105.0",
  "version": "23.0.10.1",
  "data": {
    "app": "core"
  },
  "id": "634ac795cdd29"
}

The same for me, after the same version upgrade.

mikeage commented 2 years ago

Upgraded to 25.0.0.18 about 5 days ago... hit this just now. Restarting the server container "fixed" it, but clearing cookies and localstorage did not.

DrMurx commented 2 years ago

I'm hitting this issue too when I open a browser that has been logged into my Nextcloud the day before.

My setup is Nextcloud FPM from docker library and nginx, which in turn is behind a ingress proxy.

Deleting the nc_session_id cookie in the login page helps.

Gandalf1783 commented 2 years ago

I can double this. Deleting my cookies solved my login issue. However, in my case the error message was always "Tried to log in administrator but could not....". It was always administrator, no matter which username I typed.

TheCrimsonLady commented 2 years ago

I'm having the same or very similar problem, where the error occurs occasionally when I'm trying to log in from my iPhone in Safari (iOS 16.1). For some reason, I don't have this Problem on my iMac in Safari (macOS 13.0). Edit: NC version is 24.0.6

LokeYourC3PH commented 2 years ago

I'm having the same or very similar problem, where the error occurs occasionally when I'm trying to log in from my iPhone in Safari (iOS 16.1). For some reason, I don't have this Problem on my iMac in Safari (macOS 13.0). Edit: NC version is 24.0.6

It's Browser indifferent, and is entirely random when it happens actually. I had it first happen to Chromium only users (Chrome, Brave, all that dreck), and then GeckoEngine (Firefox) users, and then all others here and there.

Gandalf1783 commented 2 years ago

I had reverted my Nextcloud VM using a backup, and what seemed to fix it permanently was to rerun the update, so it would update the database.

What also helped, was a new install with a new database, and then changing the database credentials back to the old ones. Had no issues since.

Since even on new installations using the old database resulted in the same issues above, it could be a table that was not updated correctly?

ChristophWurst commented 2 years ago

There will always be concurrent requests where one of the requests takes the valid token and causes the other requests to fail. This is bad in isolation but unavoidable. We need to find a way to retry those failed requests with the then valid cookie and session.

Until then I suggest to lower the log level of this "error" to info: https://github.com/nextcloud/server/pull/35007. That is because it's not really an application error but rather a bad authentication state. The admins can't fix this, as we have seen above. So there is also no need to alarm them with log spams.

szaimen commented 2 years ago

Honestly, I guess this is a bit more important than thought because the failed login attempts seem to trigger the brute-force protection IIRC...

ChristophWurst commented 2 years ago

That would be new for me. Do you have any proof for that claim?

ChristophWurst commented 2 years ago

I can only repeat that this is not a new error or condition. This same token mismatch happened in the past. But it happened silently.

Ra72xx commented 2 years ago

I can only repeat that this is not a new error or condition. This same token mismatch happened in the past. But it happened silently.

In previous versions, I also noticed that you could get logged out randomly/occasionally. But you could always re-log in (sometimes two attempts were needed). But currently I get logged out and am no longer able to log before I clear the cookies of the site. This is a major inconvenience, unfortunately.

fuomag9 commented 2 years ago

So it was not only me then! I get logged out a lot and need two attempts to relogin.

I've also noticed that requests to /remote.php/dav/calendars/$MYUSERNAME/ get a 401 but the calendar works fine somehow?:

PROPFIND /remote.php/dav/calendars/$MYUSERNAME/ HTTP/2.0
host: $MYHOST
prefer: return=minimal
content-type: text/xml
accept: */*
brief: t
accept-language: en-GB,en;q=0.9
content-length: 2293
accept-encoding: gzip, deflate, br
depth: 1
user-agent: macOS/13.0 (22A380) dataaccessd/1.0
DasMuelli commented 2 years ago

Have the same on NC 25.01

{"reqId":"EUOVMHQPYMxoAB3ZCKgf","level":3,"time":"2022-11-13T18:40:06+00:00","remoteAddr":"2003:f9:5716:8000:4e0:7588:2dc7:5c75","user":"--","app":"core","method":"GET","url":"/login","message":"Tried to log in lars but could not verify token","userAgent":"Mozilla/5.0 (Linux; Android 13; Pixel 6 Pro) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Mobile Safari/537.36","version":"25.0.1.1","data":{"app":"core"}}

What can I do?

Gandalf1783 commented 2 years ago

Why isnt the cookie then just cleared? If the Webserver responds with that, cant the JS in the Browser just clear the cookie and the user just can "relogin"?

It could also simply display a error-message that you have to re-login in order to use the Nextcloud instance again.

Ra72xx commented 1 year ago

Why isnt the cookie then just cleared? If the Webserver responds with that, cant the JS in the Browser just clear the cookie and the user just can "relogin"?

It could also simply display a error-message that you have to re-login in order to use the Nextcloud instance again.

Please consider this at least as workaround. In the current situation I can only re-login after clearing the cookies, which fpr means that any other cookie for my domain will also be deleted and I loose settings and logins for any other web service hosted there (or is there any more fine grained cookie control method in Firefox than the domain name?). EDIT: I found out that you can delete specific cookies for a site with the developper tools, however this is even less a viable alternative for the average user.

Gandalf1783 commented 1 year ago

I didnt mean to clear all of them, but if Nextcloud only deletes cookies of itself, e.g. that nextcloud account cookie.

ChristophWurst commented 1 year ago

A login loop also seems to happen when Redis is restarted while used for session storage