NC 14.0.1.1 - high CPU load through tons of csrftoken requests

[carslen]

Steps to reproduce

1. Open Nextcloud login webpage with any webbroser (tested with Chromium 69, IE 11, Edge (Windows 10 1809), nothing more, no login
2. Monitor CPU load on Webserver

Expected behaviour

CPU load shoud not significant increase

Actual behaviour

CPU load of 4/8 cores is >= 20%. In browser developer tools I can see tons of csrftoken requests (> 2000 (!) in 10 seconds). After login in browser there are messages about "lost connection to server", loading files app takes extrem long, Webinterface nearly unusable.

Server configuration

Operating system:
CentOS Linux release 7.5.1804 (Core)

Web server:
httpd-2.4.6-80.el7.centos.1.x86_64

Database:
mariadb-server-5.5.60-1.el7_5.x86_64

PHP version:
php72w-intl-7.2.10-1.w7.x86_64
php72w-pdo-7.2.10-1.w7.x86_64
php72w-gd-7.2.10-1.w7.x86_64
php72w-pecl-apcu-5.1.9-1.w7.x86_64
php72w-common-7.2.10-1.w7.x86_64
php72w-mysql-7.2.10-1.w7.x86_64
php72w-opcache-7.2.10-1.w7.x86_64
php72w-cli-7.2.10-1.w7.x86_64
php72w-mbstring-7.2.10-1.w7.x86_64
mod_php72w-7.2.10-1.w7.x86_64
php72w-pear-1.10.4-1.w7.noarch
php72w-xml-7.2.10-1.w7.x86_64
php72w-process-7.2.10-1.w7.x86_64

Nextcloud version: (see Nextcloud admin page)
14.0.1.1

Updated from an older Nextcloud/ownCloud or fresh install:
updated

Where did you install Nextcloud from:
tarball

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
  - accessibility: 1.0.1
  - activity: 2.7.0
  - admin_audit: 1.4.0
  - calendar: 1.6.2
  - cloud_federation_api: 0.0.1
  - comments: 1.4.0
  - contacts: 2.1.6
  - dav: 1.6.0
  - federatedfilesharing: 1.4.0
  - federation: 1.4.0
  - files: 1.9.0
  - files_pdfviewer: 1.3.2
  - files_sharing: 1.6.2
  - files_texteditor: 2.6.0
  - files_trashbin: 1.4.1
  - files_versions: 1.7.1
  - files_videoplayer: 1.3.0
  - firstrunwizard: 2.3.0
  - gallery: 18.1.0
  - logreader: 2.0.0
  - lookup_server_connector: 1.2.0
  - mail: 0.10.0
  - nextcloud_announcements: 1.3.0
  - notifications: 2.2.1
  - oauth2: 1.2.1
  - password_policy: 1.4.0
  - provisioning_api: 1.4.0
  - serverinfo: 1.4.0
  - sharebymail: 1.4.0
  - support: 1.0.0
  - survey_client: 1.2.0
  - systemtags: 1.4.0
  - theming: 1.5.0
  - twofactor_backupcodes: 1.3.1
  - updatenotification: 1.4.1
  - workflowengine: 1.4.0
Disabled:
  - encryption
  - files_external
  - user_external
  - user_ldap```
</details>

**Nextcloud configuration:**
<details>
<summary>Config report</summary>

{
"system": {
"instanceid": "REMOVED SENSITIVE VALUE",
"passwordsalt": "REMOVED SENSITIVE VALUE",
"secret": "REMOVED SENSITIVE VALUE",
"trusted_domains": [
"cloud.clxe.de"
],
"datadirectory": "REMOVED SENSITIVE VALUE",
"overwrite.cli.url": "https://cloud.clxe.de",
"dbtype": "mysql",
"version": "14.0.1.1",
"dbname": "REMOVED SENSITIVE VALUE",
"dbhost": "REMOVED SENSITIVE VALUE",
"dbport": "",
"dbtableprefix": "oc_",
"dbuser": "REMOVED SENSITIVE VALUE",
"dbpassword": "REMOVED SENSITIVE VALUE",
"installed": true,
"maintenance": false,
"memcache.local": "\OC\Memcache\APCu",
"loglevel": 0,
"mail_smtpmode": "smtp",
"mail_smtpauthtype": "LOGIN",
"mail_smtpauth": 1,
"mail_smtpsecure": "tls",
"mail_from_address": "REMOVED SENSITIVE VALUE",
"mail_domain": "REMOVED SENSITIVE VALUE",
"mail_smtphost": "REMOVED SENSITIVE VALUE",
"mail_smtpport": "587",
"mail_smtpname": "REMOVED SENSITIVE VALUE",
"mail_smtppassword": "REMOVED SENSITIVE VALUE",
"session_lifetime": "60604",
"session_keepalive": "true"
}
}```

Are you using external storage, if yes which one:
local

Are you using encryption:
yes

Are you using an external user-backend, if yes which one:

Client configuration

Browser:

• Chromium 69.0.3497.100
• IE 11
• Edge (Windows 10 1809)

Operating system:
Windows 10 1809

Logs

Web server error log

Web server error log

-

Nextcloud log (data/nextcloud.log)

Nextcloud log

[...]
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Files\\BackgroundJob\\CleanupFileLocks job with ID 3 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Files_Versions\\BackgroundJob\\ExpireVersions job with ID 5","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Files_Versions\\BackgroundJob\\ExpireVersions job with ID 5 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Files\\BackgroundJob\\ScanFiles job with ID 1","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Files\\BackgroundJob\\ScanFiles job with ID 1 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 269","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating session tokens older than 2018-10-10T20:44:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating remembered session tokens older than 2018-09-25T20:45:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating session tokens older than 2018-10-10T20:44:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating remembered session tokens older than 2018-09-25T20:45:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 269 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OC\\Log\\Rotate job with ID 270","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OC\\Log\\Rotate job with ID 270 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\UpdateNotification\\ResetTokenBackgroundJob job with ID 92","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\UpdateNotification\\ResetTokenBackgroundJob job with ID 92 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 94","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating session tokens older than 2018-10-10T20:44:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating remembered session tokens older than 2018-09-25T20:45:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating session tokens older than 2018-10-10T20:44:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Invalidating remembered session tokens older than 2018-09-25T20:45:02+00:00","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 94 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OC\\Preview\\BackgroundCleanupJob job with ID 381","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OC\\Preview\\BackgroundCleanupJob job with ID 381 in 0 seconds","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Support\\BackgroundJobs\\CheckSubscription job with ID 388","userAgent":"--","version":"14.0.1.1"}
{"reqId":"2HXa7kLQKuDTFsKWlerl","level":0,"time":"2018-10-10T20:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Finished OCA\\Support\\BackgroundJobs\\CheckSubscription job with ID 388 in 0 seconds","userAgent":"--","version":"14.0.1.1"}

Any help appreciated!

[nextcloud-bot]

GitMate.io thinks possibly related issues are #11736 (NC 14.0.1 Automated tags not applied), #10844 (14.0.0 RC 1), #11588 (14.0.2 RC 1), #8980 (NC 13.0.1 Theming not working), and #6617 (Nc v12.0.1 - Not possible to change the language of an user).

[MorrisJobke]

CPU load of 4/8 cores is >= 20%. In browser developer tools I can see tons of csrftoken requests (> 2000 (!) in 10 seconds). After login in browser there are messages about "lost connection to server", loading files app takes extrem long, Webinterface nearly unusable.

Looks similar to #11179

[MorrisJobke]

But on the other side, that Safari one is caused by re-renderings and requests of icons.

@rullzer @danxuliu Any idea, why the csrftoken is requested?

[danxuliu]

Any idea, why the csrftoken is requested?

Maybe the session_lifetime configuration value is a string instead of an integer?

In that case interval would end being a NaN (due to initially trying to divide the string by 2, which would drag the NaN over the other mathematical operations), which in turn would cause the csrftoken to be requested again and again, as setInterval would be in an infinite loop without pauses.

Of course it would be strange for session_lifetime to be a string, but as far as I can tell the csrftoken is requested only from initSessionHeartBeat, so other than that I have no idea, sorry :-S

[MorrisJobke]

In that case interval would end being a NaN (due to initially trying to divide the string by 2, which would drag the NaN over the other mathematical operations), which in turn would cause the csrftoken to be requested again and again, as setInterval would be in an infinite loop without pauses.

Do you have a patch to fix this and set it then to 0 or so?

[danxuliu]

In that case interval would end being a NaN (due to initially trying to divide the string by 2, which would drag the NaN over the other mathematical operations), which in turn would cause the csrftoken to be requested again and again, as setInterval would be in an infinite loop without pauses.

Do you have a patch to fix this and set it then to 0 or so?

Here you have: #11756

[MorrisJobke]

Here you have: #11756

Thanks a lot.

[MorrisJobke]

Fixed by #11756

[carslen]

OK, after fixing my 'session_lifetime' all back to normal operation. Thank you for your support! I've had configured my 'session_lifetime' as mentioned in documentation:

'session_lifetime' => 60 * 60 * 8,

Maybe documentation is misleading in this point and need rewrite?!

[MorrisJobke]

Maybe documentation is misleading in this point and need rewrite?!

But this should work. How does it look now?

[carslen]

I removed the hole session_lifetime settimg from config.php and restarted httpd (to be secure).

[MorrisJobke]

'session_lifetime' => 60 * 60 * 8,

With this setting I can't reproduce, but with 'session_lifetime' => 'abc', it triggers the same behavior.

[carslen]

OK, I'm sorry - it was my fault. My setting looked like this:

'session_lifetime' => '60 * 60 * 8',
I surrounded the value with single quotes (inspired from other settings in config.php). Without single quotes around the value is works as described (and shown in documentation!). So, I'm a fool! :)