search

nextcloud / server

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

Having to log in twice #32538

Open aronmal opened 2 years ago

aronmal commented 2 years ago

⚠️ This issue respects the following points: ⚠️

Bug description

I am running my own server. I am usually logged in. Since a long time, I am getting auto locked out. Should be always after about a week I think, which I do not like, but for security reasons it hasn't bothered so far. But what bothered me is, I need to login twice. I also have 2FA enabled and thought it might be because of that and when I visit:

https://mydomain.com/apps/calendar/ -> redirects to: https://mydomain.com/login?redirect_url=/apps/calendar/

So I thought it was a problem with the '?redirect_url=' part, but can't reproduce this in incognito.

I login, have to login again, 2FA code, and then being logged in. But when I do this in a incognito tab, I only have to login once plus the 2FA code. This must mean, I seem not to be fully auto logged out (?), because I only have a page refresh the first time which maybe clears my login cookies or something in that direction, so it recognizes the second login attempt?

Steps to reproduce

  1. Having TOTP 2FA enabled
  2. Being not logged in any more after some days due to auto logout or so
  3. Try to login
  4. Need to login again
  5. Enter 2FA code
  6. Being logged in

Expected behavior

Only having to login once and enter the 2FA code.

Installation method

Manual installation

Operating system

Debian/Ubuntu

PHP engine version

PHP 7.4

Web server

Nginx

Database engine version

MariaDB

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

No response

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

Configuration report

{
    "system": {
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "filelocking.enabled": "true",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 6379,
            "timeout": 0
        },
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "next.mal-noh.de",
            "next.limited-dev.de"
        ],
        "dbtype": "mysql",
        "version": "23.0.4.1",
        "trusted_proxies": "***REMOVED SENSITIVE VALUE***",
        "overwriteprotocol": "https",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "updatechecker": true,
        "updater.release.channel": "stable",
        "maintenance": false,
        "theme": "",
        "loglevel": 0,
        "default_language": "de",
        "default_locale": "de",
        "default_phone_region": "DE",
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "tls",
        "mail_sendmailmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "mail_smtpauth": 1,
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "trashbin_retention_obligation": "auto, 30",
        "versions_retention_obligation": "auto, 60",
        "overwrite.cli.url": "https:\/\/next.mal-noh.de"
    }
}

List of activated Apps

Enabled:
  - accessibility: 1.9.0
  - activity: 2.15.0
  - breezedark: 23.2.1
  - bruteforcesettings: 2.4.0
  - calendar: 3.2.2
  - camerarawpreviews: 0.7.15
  - circles: 23.1.1
  - cloud_federation_api: 1.6.0
  - comments: 1.13.0
  - contacts: 4.1.0
  - contactsinteraction: 1.4.0
  - cookbook: 0.9.11
  - dashboard: 7.3.0
  - dav: 1.21.0
  - external: 3.10.2
  - federatedfilesharing: 1.13.0
  - federation: 1.13.0
  - files: 1.18.0
  - files_pdfviewer: 2.4.0
  - files_rightclick: 1.2.0
  - files_sharing: 1.15.0
  - files_trashbin: 1.13.0
  - files_versions: 1.16.0
  - files_videoplayer: 1.12.0
  - integration_github: 1.0.2
  - logreader: 2.8.0
  - lookup_server_connector: 1.11.0
  - mail: 1.12.0
  - notes: 4.3.1
  - notifications: 2.11.1
  - oauth2: 1.11.0
  - onlyoffice: 7.3.2
  - password_policy: 1.13.0
  - passwords: 2022.4.10
  - photos: 1.5.0
  - privacy: 1.7.0
  - provisioning_api: 1.13.0
  - serverinfo: 1.13.0
  - settings: 1.5.0
  - sharebymail: 1.13.0
  - spreed: 13.0.5
  - support: 1.6.0
  - systemtags: 1.13.0
  - tasks: 0.14.4
  - text: 3.4.1
  - theming: 1.14.0
  - twofactor_admin: 3.2.0
  - twofactor_backupcodes: 1.12.0
  - twofactor_totp: 6.3.0
  - updatenotification: 1.13.0
  - user_status: 1.3.1
  - viewer: 1.7.0
  - weather_status: 1.3.0
  - workflowengine: 2.5.0
Disabled:
  - admin_audit
  - apporder: 0.15.0
  - encryption
  - files_external
  - firstrunwizard: 2.10.0
  - music: 1.5.1
  - nextcloud_announcements: 1.10.0
  - recommendations: 1.0.0
  - survey_client: 1.9.0
  - user_ldap

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

Getting "There was an error creating your issue: body is too long (maximum is 65536 characters). " when I paste it in here. If you should really need the file I can upload it in a comment.

Additional info

No response

ChristophWurst commented 2 years ago

Related: https://github.com/nextcloud/server/pull/33769. See my analysis.

ChristophWurst commented 2 years ago

If you can, please try https://github.com/nextcloud/server/pull/33772 with the instructions from https://docs.nextcloud.com/server/latest/admin_manual/issues/applying_patch.html and report back if the added errors logs show up in your nextcloud.log.

aronmal commented 2 years ago

I just applied the patch and I will reach back when this bug happen again.

aronmal commented 2 years ago

Hey, I just actively noticed I had the bug again. I could not find a error message in my log. Here are the last 300 lines from my nextcloud.log. My login attempt was around 15:09, but since the log shows 13:05 - 13:12 I guess the time zone UTC and shifted by 2 hours.

last-log.txt

ChristophWurst commented 2 years ago

Please apply https://github.com/nextcloud/server/pull/33930 as well and sen your logs after you reproduce this issue the next time.

aronmal commented 2 years ago

I just had it happen again, here are the latest log events:

last-log.txt

But no incidence of Regenerating cookie login token for {uid} after successful verification. I thought I might need to change the log level, but it is already set to 0 (debug).

ChristophWurst commented 2 years ago

Restart your web server to flush the opcache

aronmal commented 2 years ago

OK, I restarted the container now and also the Redis container. I will let you know about the next incident.

ChristophWurst commented 1 year ago

Any update?

aronmal commented 1 year ago

Not so far.

aronmal commented 1 year ago

Just happen again.

last-log.txt

ChristophWurst commented 1 year ago

Regenerating cookie login token for is still not logged. Hmm.

nursoda commented 1 year ago

This double (or triple!) need to login sometimes happens to me aswell.

szaimen commented 1 year ago

Hi, please update to 24.0.8 or better 25.0.2 and report back if it fixes the issue. Thank you!

nursoda commented 1 year ago

I currently cannot reproduce on 25.0.2

aronmal commented 1 year ago

I also haven't noticed this bug so far. I will close this issue.

aronmal commented 1 year ago

Bug is still present

szaimen commented 1 year ago

In which nc version did you test?

aronmal commented 1 year ago

Version

Nextcloud Hub 3 (25.0.2)

ChristophWurst commented 11 months ago

See https://github.com/nextcloud/server/pull/40799 for a small improvement of the error handling. Double login most likely means the PHP session vanished.

ChristophWurst commented 11 months ago

I don't get an error, just like a page reload when hitting log in but have to paste the credentials again

(re)read https://github.com/nextcloud/server/pull/40799.

sclu1034 commented 8 months ago

My instance is effectively unusable. Attempting to log in produces a long loop of #40799 messages until suddenly I do seem to get logged in. Except either immediately, or shortly after, I'll get popups the likes of "Failed to fetch weather information" on the dashboard or "Problem loading the page, reloading in X" in the files app, and eventually I'm kicked out of my session and the login loop starts again.

Looking at the log for such a "successful, but actually not" login, the session token stays valid for about three requests out of the couple dozen that are needed to load the UI. Then I get a Remember-me token replaced, after which every request will produce both a Tried to log in but could not verify token and a Current user is not logged in line. And after the first Session token replaced, CSRF validation starts failing, too. And all four of those log lines will flood the log until I'm kicked out.

(I did apply a few of the additional log info patches, hence why the messages below don't exactly match the code for v27.1.5) (Newest line at the top)

2023-12-21 13:59:01.705 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:59:01.705 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:58:55.682 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:58:55.682 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:58:53.425 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:58:53.425 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:58:53.425 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:58:53.424 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:58:31.606 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:58:31.606 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:58:23.330 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:58:23.330 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:58:01.761 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:58:01.761 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:57:49.725 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:57:49.725 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:57:31.666 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:57:31.666 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:57:17.369 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:57:17.369 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:57:01.569 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:57:01.569 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:56:43.767 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:56:43.767 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:56:31.726 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:56:31.726 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:56:29.467 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/theming/theme/opendyslexic.css?plain=0&v=da4b9237"
2023-12-21 13:56:29.467 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/unsplash/api/login.css"
2023-12-21 13:56:25.455 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/notifications/api/v2/notifications"
2023-12-21 13:56:25.455 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/notifications/api/v2/notifications"
2023-12-21 13:56:22.697 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:56:20.441 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/login?redirect_url=/index.php/apps/files/?dir%3D%252FLedger%252Fimport%26fileid%3D849526"
2023-12-21 13:56:20.190 Current user is not logged in app="no app in context" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:56:20.190 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:56:13.420 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/login?redirect_url=/index.php/apps/files/?dir%3D%252FLedger%252Fimport%26fileid%3D849526"
2023-12-21 13:56:13.169 Current user is not logged in app="no app in context" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:56:13.169 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:56:11.413 Session token replaced app="core" url="/index.php/apps/theming/theme/dark.css?plain=0&v=bf3af591"
2023-12-21 13:56:11.163 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/login?redirect_url=/index.php/apps/files/?dir%3D/<<path>>%26fileid%3D849526"
2023-12-21 13:56:11.163 Cannot authenticate over ajax calls app="webdav" url="/remote.php/dav/files/<<uid>>/<<path>>"
2023-12-21 13:56:11.163 Validating CSRF token: nIRgBpiK1JEWbIbAtd6KODDlxE+l0ql5 == cBDciwFcL12ExAB7gz34rsVop8D5+SDi app="core" url="/remote.php/dav/files/<<uid>>/<<path>>"
2023-12-21 13:56:11.163 Current user is not logged in app="no app in context" url="/ocs/v2.php/core/whatsnew?format=json"
2023-12-21 13:56:11.163 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/core/whatsnew?format=json"
2023-12-21 13:56:11.163 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>"
2023-12-21 13:56:10.912 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>"
2023-12-21 13:56:10.912 Current user is not logged in app="no app in context" url="/index.php/apps/files/?dir=/<<path>>&fileid=849526"
2023-12-21 13:56:10.912 Current user is not logged in app="no app in context" url="/ocs/v2.php/search/providers?from=%2Fapps%2Ffiles%2F%3Fdir%3D%252FLedger%252Fimport%26fileid%3D849526"
2023-12-21 13:56:10.912 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/files/?dir=/<<path>>&fileid=849526"
2023-12-21 13:56:10.912 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/search/providers?from=%2Fapps%2Ffiles%2F%3Fdir%3D%252FLedger%252Fimport%26fileid%3D849526"
2023-12-21 13:56:10.661 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:56:10.661 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:56:10.411 Current user is not logged in app="no app in context" url="/index.php/apps/unsplash/api/dashboard.css"
2023-12-21 13:56:10.411 Remember-me token RjZqEOOCSjCD/3Xo1H4eMHUYCP/iNORn replaced for <<uid>> by w/o9yrEDMBCE5tQPB7XAn+pIjJdwhROj app="core" url="/index.php/apps/theming/theme/dark.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.411 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/theming/theme/light-highcontrast.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Logging out app="no app in context" url="/index.php/apps/theming/theme/light.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Session token invalidated before logout app="no app in context" url="/index.php/apps/theming/theme/light.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Logging out app="no app in context" url="/index.php/apps/theming/theme/dark-highcontrast.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Session token is invalid because it does not exist app="core" url="/index.php/apps/theming/theme/light.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Session token invalidated before logout app="no app in context" url="/index.php/apps/theming/theme/dark-highcontrast.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Session token is invalid because it does not exist app="core" url="/index.php/apps/theming/theme/dark-highcontrast.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Logging out app="no app in context" url="/index.php/apps/theming/theme/light.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Logging out app="no app in context" url="/index.php/apps/theming/theme/default.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Logging out app="no app in context" url="/index.php/apps/unsplash/api/dashboard.css"
2023-12-21 13:56:10.410 Session token invalidated before logout app="no app in context" url="/index.php/apps/unsplash/api/dashboard.css"
2023-12-21 13:56:10.410 Session token invalidated before logout app="no app in context" url="/index.php/apps/theming/theme/default.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Session token invalidated before logout app="no app in context" url="/index.php/apps/theming/theme/light.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Session token is invalid because it does not exist app="core" url="/index.php/apps/theming/theme/light.css?plain=0&v=bf3af591"
2023-12-21 13:56:10.410 Session token is invalid because it does not exist app="core" url="/index.php/apps/theming/theme/default.css?plain=1&v=bf3af591"
2023-12-21 13:56:10.410 Session token is invalid because it does not exist app="core" url="/index.php/apps/unsplash/api/dashboard.css"
2023-12-21 13:55:58.121 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:55:56.114 Session token replaced app="core" url="/ocs/v2.php/apps/notifications/api/v2/notifications"
2023-12-21 13:55:55.362 Remember-me token O9TfiEmr9+HGQohEMFmZlDHaB3To2I4s replaced for <<uid>> by RjZqEOOCSjCD/3Xo1H4eMHUYCP/iNORn app="core" url="/ocs/v2.php/apps/notifications/api/v2/notifications"
2023-12-21 13:55:52.102 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:55:51.098 Deprecated event type for OCA\Files::loadAdditionalScripts: Symfony\Component\EventDispatcher\GenericEvent is used app="no app in context" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:55:51.098 Deprecated event type for \OCP\Collaboration\Resources::loadAdditionalScripts: null app="no app in context" url="/index.php/apps/files/?dir=%2FLedger%2Fimport&fileid=849526"
2023-12-21 13:55:25.269 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:55:22.260 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:54:36.619 Deprecated event type for OCP\IPreview:PreviewRequested: Symfony\Component\EventDispatcher\GenericEvent is used app="no app in context" url="/index.php/core/preview?x=256&y=256&fileId=1026285&c=f4e24f6e704abae4b82ad577d9266601"
2023-12-21 13:54:35.366 Deprecated event type for OCP\IPreview:PreviewRequested: Symfony\Component\EventDispatcher\GenericEvent is used app="no app in context" url="/index.php/core/preview?x=256&y=256&fileId=1026660&c=cbd7c139228850b4f98f2862cc4628e9"
2023-12-21 13:54:35.366 Deprecated event type for OCP\IPreview:PreviewRequested: Symfony\Component\EventDispatcher\GenericEvent is used app="no app in context" url="/index.php/core/preview?x=256&y=256&fileId=1026135&c=d864c4dfd2755c504ab6f26041b9f24f"
2023-12-21 13:54:35.366 Deprecated event type for OCP\IPreview:PreviewRequested: Symfony\Component\EventDispatcher\GenericEvent is used app="no app in context" url="/index.php/core/preview?x=256&y=256&fileId=1026144&c=344c34240a2911c0a3614e6aa17cd8ee"
2023-12-21 13:54:30.854 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=calendar"
2023-12-21 13:54:30.854 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=activity"
2023-12-21 13:54:30.603 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=collectives-recent-pages"
2023-12-21 13:54:30.603 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v2/widget-items?widgets%5B%5D=recommendations"
2023-12-21 13:54:09.791 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/ocs/v2.php/apps/dashboard/api/v1/widgets"
2023-12-21 13:53:58.508 CSRF check failed app="no app in context" url="/ocs/v2.php/apps/weather_status/api/v1/favorites"
2023-12-21 13:53:58.508 Validating CSRF token: cBDciwFcL12ExAB7gz34rsVop8D5+SDi == nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl app="core" url="/ocs/v2.php/apps/weather_status/api/v1/favorites"
2023-12-21 13:53:58.508 Session token replaced app="core" url="/ocs/v2.php/apps/weather_status/api/v1/favorites"
2023-12-21 13:53:58.508 Validating CSRF token: nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl == nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl app="core" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:53:58.006 Current user is not logged in app="no app in context" url="/ocs/v2.php/apps/weather_status/api/v1/forecast"
2023-12-21 13:53:58.006 Tried to log in <<uid>> but could not verify token app="core" url="/ocs/v2.php/apps/weather_status/api/v1/forecast"
2023-12-21 13:53:57.756 Remember-me token RADRSHyeVP1zmy1PyhKrtv5js8IiUgZL replaced for <<uid>> by O9TfiEmr9+HGQohEMFmZlDHaB3To2I4s app="core" url="/ocs/v2.php/apps/weather_status/api/v1/favorites"
2023-12-21 13:53:57.756 Validating CSRF token: nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl == nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl app="core" url="/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>"
2023-12-21 13:53:57.506 Validating CSRF token: nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl == nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl app="core" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-21 13:53:57.506 Validating CSRF token: nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl == nBlX+4GB50PQ/bfI8Wb+iDZ5+8Ct8tVl app="core" url="/ocs/v2.php/apps/weather_status/api/v1/location"
2023-12-21 13:53:38.699 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app="no app in context" url="/index.php/apps/dashboard/"
2023-12-21 13:52:56.569 Validating CSRF token: iEBHtI/3cQA/iuXMrnTzSMSZspTn5KKw == iEBHtI/3cQA/iuXMrnTzSMSZspTn5KKw app="core" url="/index.php/login"
ChristophWurst commented 8 months ago

@sclu1034 is it a clustered setup?

sclu1034 commented 8 months ago

No, just a single Docker container on my home NAS.

sclu1034 commented 8 months ago

Another observation:

When logging like this in CsrfTokenManager.php:

    public function isTokenValid(CsrfToken $token): bool {
        if (!$this->sessionStorage->hasToken()) {
            return false;
        }

        $sessionToken = $this->sessionStorage->getToken();
        $token = $token->getDecryptedValue();

        $isEqual = hash_equals(
            $sessionToken,
            $token
        );

        \OC::$server->getLogger()->debug('Validating CSRF token: {sessionToken} == {token}', [
            'app' => 'core',
            'user' => $uid,
            'sessionToken' => $sessionToken,
            'token' => $token
        ]);

        return $isEqual;
    }

The resulting log for a chain of failed logins will look like this:

Validating CSRF token: A == B
Validating CSRF token: B == C
Validating CSRF token: C == D

I.e. the token that failed to validate on the first request will be the one checked against on the next request, and so on.

sclu1034 commented 8 months ago

So I just caught one of the "kicked out after the session timed out over night":

(Read bottom up)

2023-12-22 09:06:29.398 CSRF check failed app=no app in context url=/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>
2023-12-22 09:06:29.398 Validating CSRF token: 7qoR2Vtln6WwZAJgw+Wut1Y4Y8kPfy6C == 1IooGKZ6/1FGRXJTxm+VLkgT2II8NXTN (+D/V/krFxcg/kksNvQU3FST4g2Y+rDlX0kxpJrHJIDA=:yXa6kQ2On/4Qow1K7119QVyVqDByx14D4AUgHv+RdH4=) app=core url=/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>
2023-12-22 09:06:29.398 CSRF check failed app=no app in context url=/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json
2023-12-22 09:06:29.398 Validating CSRF token: 7qoR2Vtln6WwZAJgw+Wut1Y4Y8kPfy6C == 1IooGKZ6/1FGRXJTxm+VLkgT2II8NXTN (+D/V/krFxcg/kksNvQU3FST4g2Y+rDlX0kxpJrHJIDA=:yXa6kQ2On/4Qow1K7119QVyVqDByx14D4AUgHv+RdH4=) app=core url=/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json
2023-12-22 09:06:29.148 CSRF check failed app=no app in context url=/ocs/v2.php/apps/weather_status/api/v1/location
2023-12-22 09:06:29.148 Validating CSRF token: 7qoR2Vtln6WwZAJgw+Wut1Y4Y8kPfy6C == 1IooGKZ6/1FGRXJTxm+VLkgT2II8NXTN (+D/V/krFxcg/kksNvQU3FST4g2Y+rDlX0kxpJrHJIDA=:yXa6kQ2On/4Qow1K7119QVyVqDByx14D4AUgHv+RdH4=) app=core url=/ocs/v2.php/apps/weather_status/api/v1/location
2023-12-22 09:06:29.148 CSRF check failed app=no app in context url=/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json
2023-12-22 09:06:29.148 Validating CSRF token: 7qoR2Vtln6WwZAJgw+Wut1Y4Y8kPfy6C == 1IooGKZ6/1FGRXJTxm+VLkgT2II8NXTN (+D/V/krFxcg/kksNvQU3FST4g2Y+rDlX0kxpJrHJIDA=:yXa6kQ2On/4Qow1K7119QVyVqDByx14D4AUgHv+RdH4=) app=core url=/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json
2023-12-22 09:06:28.145 Session token replaced app=core url=/index.php/js/core/merged-template-prepend.js?v=c1f52e0e-2
2023-12-22 09:06:27.895 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/light-highcontrast.css?plain=1&v=bf3af591
2023-12-22 09:06:27.895 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/dark-highcontrast.css?plain=1&v=bf3af591
2023-12-22 09:06:27.895 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/dark.css?plain=1&v=bf3af591
2023-12-22 09:06:27.644 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/opendyslexic.css?plain=0&v=bf3af591
2023-12-22 09:06:27.644 Current user is not logged in app=no app in context url=/index.php/apps/unsplash/api/dashboard.css
2023-12-22 09:06:27.644 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/unsplash/api/dashboard.css
2023-12-22 09:06:27.644 Generated CSRF token CzsusCe9sol8sRpId0tTgIA4seWprKRT from getToken app=core url=/index.php/apps/theming/theme/opendyslexic.css?plain=0&v=bf3af591
2023-12-22 09:06:27.644 Generated CSRF token 9QobetADACP+cKGfm1hBUL3lUzo0OvHf from getToken app=core url=/index.php/apps/unsplash/api/dashboard.css
2023-12-22 09:06:27.644 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/dark-highcontrast.css?plain=0&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/light-highcontrast.css?plain=0&v=bf3af591
2023-12-22 09:06:27.402 Generated CSRF token 4tiCZBCEUf4UtIWk7krbtQgtw1CEmsb2 from getToken app=core url=/index.php/apps/theming/theme/dark-highcontrast.css?plain=0&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/dark.css?plain=0&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/light.css?plain=1&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/light.css?plain=0&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/side_menu/css/stylesheet?v=1
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/theming/theme/default.css?plain=1&v=bf3af591
2023-12-22 09:06:27.402 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/side_menu/js/script?v=1
2023-12-22 09:06:27.402 Generated CSRF token +0AO8/Z14FsEUf35a/n/941Tx6qc5UQi from getToken app=core url=/index.php/apps/theming/theme/light-highcontrast.css?plain=0&v=bf3af591
2023-12-22 09:06:27.401 Generated CSRF token Pd3CJCqELr53qXZNi+Z4Hur1KCLGwVGt from getToken app=core url=/index.php/apps/theming/theme/dark.css?plain=0&v=bf3af591
2023-12-22 09:06:27.401 Generated CSRF token 7Lc2DyV05JSu4AphiIIvlYXYjCyh4pQ0 from getToken app=core url=/index.php/apps/theming/theme/light.css?plain=0&v=bf3af591
2023-12-22 09:06:27.394 Generated CSRF token f4RkiXLGYh99KxjDbVTnp28L22vjGY8a from getToken app=core url=/index.php/apps/theming/theme/light.css?plain=1&v=bf3af591
2023-12-22 09:06:27.393 Generated CSRF token HP8GGhOXhX5GKcgyuESVXqZmpuhDJokR from getToken app=core url=/index.php/apps/theming/theme/default.css?plain=1&v=bf3af591
2023-12-22 09:06:27.393 Generated CSRF token 1m/hKI2yhw8Bi8GXigw9xky6pxZL7GhU from getToken app=core url=/index.php/apps/side_menu/js/script?v=1
2023-12-22 09:06:27.393 Generated CSRF token 6vCfPwxFNYmj4qZ6QmaYbTGqUcXy9uP7 from getToken app=core url=/index.php/apps/side_menu/css/stylesheet?v=1
2023-12-22 09:06:27.143 Remember-me token PpW+JRTTL7AkWpRBlye4mQftfJ2xaz+B replaced for <<uid>> by pBCjMje5d2BpxCRVNcW+5NniseJoVmsm app=core url=/index.php/js/core/merged-template-prepend.js?v=c1f52e0e-2
2023-12-22 09:06:26.390 Error during dashboard widget loading: OCA\HassIntegration\Dashboard\TemplateWidget app=no app in context url=/index.php/apps/dashboard/
2023-12-22 09:06:09.839 Current user is not logged in app=no app in context url=/index.php/apps/files/preview-service-worker.js
2023-12-22 09:06:09.839 Tried to log in <<uid>> but could not verify token app=core url=/index.php/apps/files/preview-service-worker.js
2023-12-22 09:06:09.839 Generated CSRF token 7qoR2Vtln6WwZAJgw+Wut1Y4Y8kPfy6C from getToken app=core url=/index.php/apps/files/preview-service-worker.js
2023-12-22 09:06:09.588 Session token replaced app=core url=/
2023-12-22 09:06:08.836 Remember-me token S9EyEjjo2ne6mG9bXWGi3jaWyw5Z8FFb replaced for <<uid>> by PpW+JRTTL7AkWpRBlye4mQftfJ2xaz+B app=core url=/
2023-12-22 09:06:08.836 Generated CSRF token 1IooGKZ6/1FGRXJTxm+VLkgT2II8NXTN from getToken app=core url=/

Navigating to url=/ generates a new CSRF token, and replaces the expired login token. Makes sense.

But then for every subsequent request another CSRF token is generated at https://github.com/nextcloud/server/blob/81ed6d6afd051b9d90bac1eaaaf29e781c49fd74/lib/private/Security/CSRF/CsrfTokenManager.php#L58-L59 And they also all fail at https://github.com/nextcloud/server/blob/81ed6d6afd051b9d90bac1eaaaf29e781c49fd74/lib/private/User/Session.php#L897-L902 Evidently they didn't share the session from the initial url=/ request.

Which is then confirmed by the eventual CSRF validations. The right token is the one from the page, and it properly matches the one generated for url=/. But the left one, from session storage, matches the one from the url=/index.php/apps/files/preview-service-worker.js request. This would suggest that all these requests are all running in the session from url=/index.php/apps/files/preview-service-worker.js, not from url=/, where the re-authentication happened.

ChristophWurst commented 8 months ago

this would suggest that all these requests are all running in the session from url=/index.php/apps/files/preview-service-worker.js

that matches observations of @juliushaertl. he had auth issues on CI which went away once the service worker was blocked

sclu1034 commented 8 months ago

Is that confirmed to be the actual cause, though, or just correlation? E.g. if the underlying issue is a race condition, the service worker might simply be the only request fast enough to trigger it.

sclu1034 commented 8 months ago

Here's another case:

2023-12-22 11:01:05.279 Validating CSRF token: qzozd9kbZGnR801q/4u90LaxHc1dKJYc == qzozd9kbZGnR801q/4u90LaxHc1dKJYc (TjtnNheHd+HdSHB6d63mwXjbO3CLgaKuAFzXxQJ3EMI=:P0EITHO+HIOHDx4oT53XsFfvTkm7zcPWSD/moUk9SaE=) app="core" url="/index.php/settings/apps/categories"
2023-12-22 11:01:05.279 Remember-me token JQEcx1h1EjEjpJZwnJgJwDxawGpbdE0d replaced for <<uid>> by HQ54Yl47a6uOBnymOJdqxwsod8RksE0G app="core" url="/index.php/apps/side_menu/js/config"
2023-12-22 11:01:05.279 Validating CSRF token: qzozd9kbZGnR801q/4u90LaxHc1dKJYc == qzozd9kbZGnR801q/4u90LaxHc1dKJYc (TjtnNheHd+HdSHB6d63mwXjbO3CLgaKuAFzXxQJ3EMI=:P0EITHO+HIOHDx4oT53XsFfvTkm7zcPWSD/moUk9SaE=) app="core" url="/index.php/settings/apps/list"
2023-12-22 11:01:05.028 Validating CSRF token: qzozd9kbZGnR801q/4u90LaxHc1dKJYc == qzozd9kbZGnR801q/4u90LaxHc1dKJYc (TjtnNheHd+HdSHB6d63mwXjbO3CLgaKuAFzXxQJ3EMI=:P0EITHO+HIOHDx4oT53XsFfvTkm7zcPWSD/moUk9SaE=) app="core" url="/ocs/v2.php/apps/user_status/api/v1/heartbeat?format=json"
2023-12-22 11:01:05.028 Validating CSRF token: qzozd9kbZGnR801q/4u90LaxHc1dKJYc == qzozd9kbZGnR801q/4u90LaxHc1dKJYc (TjtnNheHd+HdSHB6d63mwXjbO3CLgaKuAFzXxQJ3EMI=:P0EITHO+HIOHDx4oT53XsFfvTkm7zcPWSD/moUk9SaE=) app="core" url="/ocs/v2.php/apps/user_status/api/v1/statuses/<<uid>>"
2023-12-22 11:00:45.212 Session token replaced app="core" url="/index.php/settings/apps"
2023-12-22 11:00:45.212 Current user is not logged in app="no app in context" url="/index.php/apps/files/preview-service-worker.js"
2023-12-22 11:00:44.962 Tried to log in <<uid>> but could not verify token app="core" url="/index.php/apps/files/preview-service-worker.js"
2023-12-22 11:00:44.962 Generated CSRF token Zo07rPb31QO63DhcpNblHEPVQq28isSx from getToken app="core" url="/index.php/apps/files/preview-service-worker.js"
2023-12-22 11:00:44.461 Remember-me token urtID9FeiV+Ap17uqvJE0Ggwq8Gsi62P replaced for <<uid>> by JQEcx1h1EjEjpJZwnJgJwDxawGpbdE0d app="core" url="/index.php/settings/apps"
2023-12-22 11:00:44.461 Generated CSRF token qzozd9kbZGnR801q/4u90LaxHc1dKJYc from getToken app="core" url="/index.php/settings/apps"

This time, the Session token replaced comes after the service worker, and now CSRF validation on the following requests uses the correct token, not the one from the service worker request. This does look like a race condition to me, where the service worker request starts before the main request is able to save its session, thereby not having a session to work with, and overall authentication depends on which request finishes last to overwrite the other one's session.

sclu1034 commented 8 months ago

Even weirder case, now the flow for url=/index.php/login itself can't find a session and generates a new token during the login attempt. The log that created that token earlier is there as well, so maybe the failure to log in then also blocked the code path that would store the session.

2023-12-28 12:00:13.871 Validating CSRF token: KoCr2qx23xCwAhkPmWqlWYXiUzp7lYaK == vx9vClbF8dQcvKx1yrTURvSPrgkZlLLQ (7zd89FNW7il/GVlN6lrMS2gaChRTHtQehDhlcM58NnI=:mU9FghA6jG9HfQgunBG0ehFoXkEBaIdO9l8OKqIweiM=) app="core" url=/index.php/login
2023-12-28 12:00:13.370 Generated CSRF token KoCr2qx23xCwAhkPmWqlWYXiUzp7lYaK from getToken app="core" url=/index.php/login
2023-12-28 12:00:02.590 Generated CSRF token w9g97fWDIxSC4Zo5KgiePxfwxKBTGl0E from getToken app="core" url=--   
2023-12-28 12:00:02.339 Generated CSRF token m5ty4tYn+Bizs8sJlOxrI8v5hwF79duS from getToken app="core" url=/index.php/login?redirect_url=/index.php/apps/files/&direct=1&user=<<uid>>
2023-12-28 11:59:12.437 Generated CSRF token owGPUhpfJuW1CxzyPlYDOe6NeayWoqqy from getToken app="core" url=/index.php/apps/side_menu/js/config
2023-12-28 11:59:12.437 Generated CSRF token bst+Z2zDQ0D5BcORALoTC/lLVat+1aex from getToken app="core" url=/index.php/apps/side_menu/nav/items
2023-12-28 11:59:10.433 Validating CSRF token: vx9vClbF8dQcvKx1yrTURvSPrgkZlLLQ == +qOnRAOjUIx8apLBWqLC6wC5ERaAFspN (Jmt1quhCYj2ONOlGuQ7yC9gCx/M6j3oGUCnNWIrdtTQ=:DRo6xLoDLVfbfZF+2H6+SY9zi7AM+DkzFXusGcyuxXo=) app="core" url=/index.php/login
2023-12-28 11:59:10.433 Generated CSRF token vx9vClbF8dQcvKx1yrTURvSPrgkZlLLQ from getToken app="core" url=/index.php/login

Or in this instance, where I first reload the page, which creates a new token for the form. Then I submit the form, and it creates a new token before validating the login.

2023-12-28 12:12:20.599 Validating CSRF token: jIeexla6KhYy70A1ndRIHWxAdC3+7Kfk == XorgnbtAYCVnK7j4qn5gr5eIZE1/9OvM (F76W1w8D57D15t3/CK9jlkTXuwysCO7wV7ie2BRp3y4=:T9HksGFhk/GspYuRQ5gJojW5jmvePYu5Df2v9y0mqWM=) app="core" url=/index.php/login
2023-12-28 12:12:20.599 Generated CSRF token jIeexla6KhYy70A1ndRIHWxAdC3+7Kfk from getToken app="core" url=/index.php/login
2023-12-28 12:09:57.661 Generated CSRF token XorgnbtAYCVnK7j4qn5gr5eIZE1/9OvM from getToken app="core" url=/index.php/login?redirect_url=/index.php/apps/files/&direct=1&user=<<uid>>
Babalion commented 7 months ago

I can confirm this bug. My instance is nearly unusable. Has anyone already found a workaround?

joshtrichards commented 7 months ago

My instance is effectively unusable. Attempting to log in produces a long loop of #40799 messages until suddenly I do seem to get logged in. Except either immediately, or shortly after, I'll get popups the likes of "Failed to fetch weather information" on the dashboard or "Problem loading the page, reloading in X" in the files app, and eventually I'm kicked out of my session and the login loop starts again.

Do any of you have a reverse proxy in front? Make sure any caching/caching manipulation is completely off.