Hundreds of odd oc_authtoken entries for a user slow down performance

[raid1]

This is a summary of https://help.nextcloud.com/t/hundreds-of-odd-oc-authtoken-entries-slow-down-performance-for-a-user-bug-report/117742

Expected behaviour

1 oc_authtoken per user+device

$ curl -s -X PROPFIND "https://SERVER/remote.php/webdav/Handy/DCIM/Camera/IMG_2021-0602_202145.jpg" -u user2
→ 1-2 seconds

Actual behaviour

hundreds of oc_authtoken entries:
$ mysql mycloud -B -e "select count(*) from oc_authtoken where uid='andy'"
count(*)
167

$ curl -X PROPFIND "https://SERVER/remote.php/webdav/Handy/DCIM/Camera/IMG_20210602_223758.jpg" -u andy
→ between 12-17 seconds

After "DELETE * from oc_authtoken where uid=‘andy’"
the server responds quick again. The curl command needs less than a second.

But this was not a permanent solution. 157 new(!) entries were back the next day.
Here is just a short part of it:

Questions/Doubts

• Where did all these extra DB lines come from?
• Why do they reappear after a while
• Why did they have no effect until the update to NC 21?

Server configuration

Operating system:
4.19.0-16-amd64 #1 SMP Debian 4.19.181-1 (2021-03-19) x86_64 GNU/Linux

Web server:
Apache 2.4.38-3+deb10u4

Database:
mysql Ver 15.1 Distrib 10.3.27-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

PHP version:
PHP version (eg, 7.4): 2:7.3+69

Nextcloud version: (see Nextcloud admin page)
21.0.2.1

Updated from an older Nextcloud/ownCloud or fresh install:
latest v20

Where did you install Nextcloud from:
with the internal NC updater

Signing status:

Signing status

Login as admin user into your Nextcloud and access 
http://example.com/index.php/settings/integrity/failed 
paste the results here.

No errors have been found.

List of activated apps:

App list

Enabled:
  - accessibility: 1.7.0
  - activity: 2.14.3
  - admin_audit: 1.11.0
  - apporder: 0.12.0
  - audioplayer: 3.1.0
  - bbb: 1.4.1
  - bookmarks: 4.2.2
  - bruteforcesettings: 2.2.0
  - calendar: 2.2.2
  - carnet: 0.24.1
  - cloud_federation_api: 1.4.0
  - cms_pico: 1.0.15
  - comments: 1.11.0
  - contacts: 3.5.1
  - contactsinteraction: 1.2.0
  - dashboard: 7.1.0
  - data_request: 1.8.0
  - dav: 1.17.1
  - deck: 1.4.2
  - drawio: 1.0.0
  - federatedfilesharing: 1.11.0
  - federation: 1.11.0
  - files: 1.16.0
  - files_external: 1.12.0
  - files_markdown: 2.3.3
  - files_pdfviewer: 2.1.0
  - files_retention: 1.10.1
  - files_rightclick: 1.0.0
  - files_sharing: 1.13.1
  - files_trashbin: 1.11.0
  - files_versions: 1.14.0
  - files_videoplayer: 1.10.0
  - firstrunwizard: 2.10.0
  - forms: 2.2.4
  - gpxmotion: 0.1.0
  - gpxpod: 4.2.8
  - impersonate: 1.8.0
  - integration_google: 1.0.2
  - integration_whiteboard: 0.0.14
  - integration_zammad: 1.0.1
  - keeweb: 0.6.5
  - logreader: 2.6.0
  - lookup_server_connector: 1.9.0
  - mail: 1.9.5
  - nextcloud_announcements: 1.10.0
  - notes: 4.0.4
  - notifications: 2.9.0
  - oauth2: 1.9.0
  - openhab: 0.9.5
  - password_policy: 1.11.0
  - photos: 1.3.0
  - privacy: 1.5.0
  - provisioning_api: 1.11.0
  - rainloop: 7.1.2
  - recommendations: 1.0.0
  - serverinfo: 1.11.0
  - settings: 1.3.0
  - sharebymail: 1.11.0
  - socialsharing_email: 2.2.0
  - spreed: 11.2.2
  - support: 1.4.0
  - survey_client: 1.9.0
  - systemtags: 1.11.0
  - tasks: 0.13.6
  - text: 3.2.0
  - theming: 1.12.0
  - twofactor_backupcodes: 1.10.0
  - updatenotification: 1.11.0
  - user_status: 1.1.1
  - user_usage_report: 1.5.0
  - viewer: 1.5.0
  - weather_status: 1.1.0
  - workflowengine: 2.3.0
Disabled:
  - encryption
  - passwords
  - user_ldap

Nextcloud configuration:

Config report

{
    "system": {
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "21.0.2.1",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "maintenance": false,
        "loglevel": 2,
        "theme": "",
        "trusted_domains": [
            "cloud.mydomain.de",
        ],
        "share_folder": "\/Shared",
        "defaultapp": "calendar",
        "trashbin_retention_obligation": "auto, 14",
        "versions_retention_obligation": "auto, 14",
        "default_language": "en",
        "default_phone_region": "DE",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "updater.release.channel": "stable",
        "overwrite.cli.url": "https:\/\/cloud.mydomain.de",
        "blacklisted_files": [
            "._*",
            ".DS_Store",
            ".DS_STORE",
            ".ds_store"
        ],
        "integrity.check.disabled": false,
        "mysql.utf8mb4": true,
        "mail_smtpauthtype": "LOGIN",
        "mail_sendmailmode": "smtp",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "25",
        "mail_smtpauth": 1,
        "mail_smtpsecure": "tls",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "app_install_overwrite": [
            "apporder",
            "calendar",
            "bookmarks"
        ],
        "has_rebuilt_cache": true,
        "encryption.legacy_format_support": false,
        "encryption.key_storage_migrated": false
    }
}

Are you using external storage, if yes which one: local/smb/sftp/...
No

Are you using encryption: yes/no
No

Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
No

Client configuration

irrelevant

Logs

Web server error log

Web server error log

(only irrelevant lines like:)
[Tue Jun 22 16:57:47.274268 2021] [access_compat:error] [pid 32647] [client 62.216.xx.yy:64788] AH01797: client denied by server configuration: /var/www/nextcloud/config

Nextcloud log (data/nextcloud.log)

Nextcloud log

{"reqId":"YNIMvrdbUoVOcoItzNhK1QAAAAw","level":3,"time":"2021-06-22T16:15:59+00:00","remoteAddr":"138.246.3.189","user":"andy","app":"PHP","method":"PROPFIND","url":"/remote.php/dav/files/andy/","message":"Module 'mbstring' already loaded at Unknown#0","userAgent":"Mozilla/5.0 (Linux) mirall/3.2.2-20210531.142805.04afaa1fe-1.0~focal1 (Nextcloud, ubuntu-5.4.0-74-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)","version":"21.0.2.1"}

The output of your Nextcloud log in Admin > Logging:
Error PHP Module 'mbstring' already loaded at Unknown#0
(shows up every time when I call curl)

[noseshimself]

It's actually getting exponentially worse with the number of tokens.

[raid1]

It's actually getting exponentially worse with the number of tokens.

Yes, definitely. I'd have to delete the tokens every two days.
So, you are experiencing this also?

[szaimen]

I suppose cronjobs are configured correctly and running?

[raid1]

Yes, running every 5 minutes.

But I think I have a new clue: I compared the "name" field of the oc_authtoken lines and the majority of the entries looks like this:

Mozilla/5.0 (Linux) mirall/3.2.2-20210531.142805.04afaa1fe-1.0~focal1 (nextcloudcmd, ubuntu-5.4.0-73-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)
or
CalDAV-Sync/0.4.32 (Acer; a500_emea_de; Android 4.0.3; de_DE; org.dmfs.caldav.lib/748; like iOS/5.0.1 (9A405) dataaccessd/1.0)

I do have nextcloudcmd running every 15 minutes on an ubuntu server.
And I have a pretty old Acer A500 Android (version 4.0.3) tablet synching.

Could it be that these two devices are creating the multiple new entries?
Then the problem must be a combination of NC 21 with nextcloudcmd and with (an old version of) the Android app "CardDAV Sync".

[noseshimself]

So, you are experiencing this also?

Yes, but I did it on purpose by connecting about 800 devices to the same account to see if that was a working option if creation of separate accounts was not possible.

[raid1]

I can reproduce the problem with nextcloudcmd. Every time I run it a new token is added:

$ /usr/bin/nextcloudcmd --user andy -h -n --non-interactive /PATH-TO-ownCloud-DIR https://MYCLOUDSERVER.de/

# mysql clouddb -B -e "select name from oc_authtoken where name like '%nextcloudcmd%'"

Mozilla/5.0 (Linux) mirall/3.2.2-20210531.142805.04afaa1fe-1.0~focal1 (nextcloudcmd, ubuntu-5.4.0-73-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)
Mozilla/5.0 (Linux) mirall/3.2.2-20210531.142805.04afaa1fe-1.0~focal1 (nextcloudcmd, ubuntu-5.4.0-73-generic ClientArchitecture: x86_64 OsArchitecture: x86_64)

[szaimen]

Do you use a password or app-token for authentication via nextcloudcmd?

[raid1]

I use the "-n" switch which looks for the credentials (password) in .netrc

[szaimen]

Does the same happen if you use an app-token for authentication?

[raid1]

Good idea.
But I'm having trouble authenticating for nextcloudcmd with an app-token.
Maybe I'm misunderstanding this concept? I created a new app-token "ncc" and then ran:
$ nextcloudcmd --user andy --password the-just-created-token-passwd ...

I cannot even log into the web UI with this token password. Tried it with different users and different NC servers.
Where is my mistake in thinking?

[szaimen]

It should work like this: nextcloud/desktop#1779 (comment)

[raid1]

Thanks, that's how I did it. :-)

But I found the cause why it didn't work: bruteforcesettings kicked in. I had to whitelist the IP of my test computer.
Now nextcloudcmd runs fine with an app-token AND it doesn't create extra oc_authtoken at every run anymore.

So, thanks, this is a good workaround for the problem which I still believe is a bug in NC 21.

[AlfredoCubitos]

Hi, I currently have a similar problem also discussed here
In my case it seems that the cron.php is not working correctly. Calling cron.php returns success but does not delete the old sessions from the oc_authtoken
This behavior leads to the same problem described by @raid1 first.

[rfc2822]

Hi,

I had the same problem. Hundreds of oc_authtokens have polluted the database and caused significant delays. I have now manually cleared it, but how can this be avoided?

[kesselb]

but how can this be avoided?

Usually by using an app password for caldav/carddav.

[rfc2822]

Usually by using an app password for caldav/carddav.

But do I understand it correctly that oc_authtoken entries should be removed after session_lifetime (defaulting to one day)? On my server there are oc_authtokens since 2018 (although cronjob is running regularly).
Edit: the old tokens have type=1. Tokens with type=0 seem to be deleted by the cronjob:

2021-09-28T09:21:39.214204Z      8750 Query     DELETE FROM `oc_authtoken` WHERE (`last_activity` < 1632734499) AND (`type` = 0) AND (`remember` = 0) AND (`version` = 1)
2021-09-28T09:21:39.216259Z      8750 Query     DELETE FROM `oc_authtoken` WHERE (`last_activity` < 1631524899) AND (`type` = 0) AND (`remember` = 1) AND (`version` = 1)
2021-09-28T09:21:39.218310Z      8750 Query     DELETE FROM `oc_authtoken` WHERE (`last_activity` < 1632734499) AND (`type` = 0) AND (`remember` = 0) AND (`version` = 2)
2021-09-28T09:21:39.220046Z      8750 Query     DELETE FROM `oc_authtoken` WHERE (`last_activity` < 1631524899) AND (`type` = 0) AND (`remember` = 1) AND (`version` = 2)

Seems also be related to #19247

[AlfredoCubitos]

some times the cron.php script does not work well, especially if you have an old often upgraded installation.
try running the script on the command line sudo -u www-data php cron.php in your nextcloud directory.
If it throws an error with something like "apc .." try to add apc.enable_cli=1 in you php.ini
In my case this worked. But this didn't delete the old entries in oc_authtoken. So I deleted them manually.
I will check if @rfc2822 is right, currently I have not enough entries ;-)

[AlfredoCubitos]

Hi everybody,

are you sure that your cronjob is running well?
The current version 24.0.4 shows a cronjob error on admin page if the cron.php didn't run for several days .
I had this issue. After running the cron.php manually I fixed that and I had 1 GB more space on my HD

[ckoehler]

Hi everybody,

are you sure that your cronjob is running well? The current version 24.0.4 shows a cronjob error on admin page if the cron.php didn't run for several days . I had this issue. After running the cron.php manually I fixed that and I had 1 GB more space on my HD

Yep. That was my issue a while ago, too, but the cronjob is running.

[stevleibelt]

My cronjob is also working.

How to figure it out?

• Login as admin
• Settings -> Logging
• Search for entries from App cron

[piiskop]

Clicking Logging brings up a listing for a fraction of a second and displays a white area.

[stevleibelt]

@piiskop can you open your browser debugging bar (hit F12 and select the networkstack) before clicking on "Logging".
Maybe you see some information there (check the http request code, the answer section etc.).

[piiskop]

i only see what resources are loaded - 108 resources within ! This tells me that the creators of Nextcloud have never put performance as a priority. And every now and then, a resource will be reloaded.

[kartoffelheinz]

This bug is pretty severe.

The SQL-Updates produce so much load and Logs that you easily get into hundreds of gigabytes worth of Binlogs in just a few hours. We got lucky a few times and reacted seconds before the database dataset run out of space. I do not understand why this workaround #26502 (comment) has not been implemented upstream. It's been over 1 year.

Needs to be fixed ASAP, before everybody updates to latest 24.04 (which seem to trigger this bug a lot more than versions before).

[wolframroesler]

Second that, @kartoffelheinz. The occurrence of the problem here coincides with the installation of the latest Nextcloud update (to 24.0.4). Need to "delete from oc_authtoken where ..." every couple of days to keep the problem in check (and I have only a handful of users).

No cron-related messages in the log (https://mydomain/settings/admin/logging).

[cpm1]

24.0.5 now and I just re-applied the workaround and cleaned up authtoken table once again. 🙄

[wolframroesler]

Upgrading to Nextcloud 24.0.5 improved it for me temporarily (number of rows in oc_authtoken went down from 609 to 83), but now a few days later it's back up to 224, so it's not fixed yet.

[tcitworld]

24.0.5 has the fix to reactive the cleanup of the authtokens table, not the fix to avoid creating them in the first place.

[wolframroesler]

Though not fixed, 24.0.5 has made it a lot better for me. No need to clean up the oc_authtoken every other day anymore.

[noseshimself]

Could we get a button "blast all existing entries to pieces and clean up all relevant tables" or at least an occ command doing so? Just in case...

[stevleibelt]

@noseshimself I vote +1 for the occ command.

[mristuccia]

Hello everyone.
We've tried to use Nextcloud as a storage backend for an application we're developing for an Enterprise customer.
WebDAV access is a necessary integration in such solution, and we faced this terrible slowness of the WebDAV implementation in Nextcloud.
I can assure you that even if we frequently empty the oc_authtoken table, the general slowness is still there. Emptying the table helps a bit, but we still get face many seconds durations for even storing a single file inside Nextcloud.

Unfortunately, in the end we needed to switch to the community edition of OwnCloud, which is tremendously faster as far as WebDAV is concerned.

I strongly encourage the Nextcloud team to work on this problem, which have been there for many major releases now, and it is still currently there on the 25.0.2 version.

[nachtgeist]

Confirmed present on 25.0.2, please re-open this issue (or #19247)

[juliusknorr]

I think this is partly also an issue with the desktop client when running nextcloudcmd so opening an issue in the respective repo would be highly appreciated.

We have some logic in the server that will create a session token to be returned as a cookie value so that follow up requests of clients can reuse the auth token without the need for using basic auth in follow up requests. This is done by performing a cookie check by setting a cookie on the first request. If any follow up requests contains that cookie a session token will be generated. Now the nextcloudcmd seems to persist cookies but not across multiple calls so every call of nextcloudcmd will generate a new one.

curl to reproduce:

curl -v http://nextcloud.dev.local/ocs/v1.php/cloud/user\?format=json -u admin:admin -H 'OCS-APIRequest: true' --cookie 'XDEBUG_SESSION=PHPSTORM; cookie_test=test'

From my perspective the client should now either use basic auth for all requests or persist the cookies across multiple calls. A way to avoid this is to not use the user password but generating an app password and using that for authentication.

[szaimen]

I think this is partly also an issue with the desktop client when running nextcloudcmd so opening an issue in the respective repo would be highly appreciated.

Yes, please do that here: https://github.com/nextcloud/desktop/issues/new?assignees=&labels=0.+Needs+triage&template=BUG_REPORT.yml&title=%5BBug%5D%3A+. Thanks!

[mristuccia]

Great way to manage an issue.
Thanks and good luck.
I'm out.

[kartoffelheinz]

Problem still occuring to some extent. Not as bad as before, but most definitely not solved.
Seems this has been closed prematurely.

[szaimen]

The PR that fixes this was merged but only into master which will be available with Nc26.

@juliushaertl I suppose backporting is too much of a risk?

[juliusknorr]

Not back ported on purpose because it has some risk of breaking things. Also looking at it with my above debugging comment this might be something that can not be fixed on the server and the PR was actually not targeting the root cause.

This should be fixed in the client implementation for the nextcloudcmd parts. Other clients may need to either reuse cookies or not persist cookies at all.

[DrGalvany]

Hello,
first of all, I would like to thank you for this great contribution.
I had the same problem with my database overflowing.
It was already 5.6 GB in size.
I have queried it myself with “nextcloudcmd”.
The call was made every minute with 3 queries, which in turn left 3 entries in the database.
Now I use the token that you can create in Nextcloud, and now the constant entries in the database are a thing of the past.
Thanks again for this contribution.

The text was automatically translated from German to English.

Greetings
Micha

Translated with DeepL.com (free version)

[stevleibelt]

Just for the log. I've taken a look on my database table oc_authtoken today and the table size including the content is reflecting my expected reality.
I am currently running nextcloud server 29.0.1. Somewhere in-between, it looks like the issue was solved on my side.