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

[AndyXheli]

⚠️ This issue respects the following points: ⚠️

• This is a bug, not a question or a configuration/webserver/proxy issue.
• This issue is not already reported on Github (I've searched it).
• Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
• Nextcloud Server is running on 64bit capable CPU, PHP and OS.
• I agree to follow Nextcloud's Code of Conduct.

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?

• Default user-backend (database)
• LDAP/ Active Directory
• SSO - SAML
• Other

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

[szaimen]

cc @ChristophWurst

[ChristophWurst]

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

So, this is from #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]

#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]

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]

@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]

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]

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]

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]

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

[AndyXheli]

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]

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.