High CPU load probably related to calendar or DAV #12722

LubosKolouch · 2018-11-29T09:33:11Z

Steps to reproduce

Just wait ... symptom is error 503 reported by CalDav or NC page not loaded in browser
Apache process eats all CPU and runs indefinetely,
Apache process needs to be restarted; nothing specific in NC logs

Expected behaviour

Apache process should not hang

Actual behaviour

Apache eats all CPU and needs to be restarted. Not sure how to debug this.

Server configuration

Operating system:
Gentoo Linux

Web server:
Apache 2.4.3

Database:
MariaDB 10.3.10

PHP version:
7.2.12

Nextcloud version: (see Nextcloud admin page)
14.0.4

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

Where did you install Nextcloud from:
Gentoo

Signing status:

Signing status

core
- INVALID_HASH
  - .htaccess
  - 3rdparty/sabre/vobject/lib/Recur/RRuleIterator.php (I modified as suggested in a thread, did not help to solve the issue)
- EXTRA_FILE
  - test_old.php

List of activated apps:

App list

Enabled: - accessibility: 1.0.1 - activity: 2.7.0 - admin_audit: 1.4.0 - calendar: 1.6.4 - cloud_federation_api: 0.0.1 - contacts: 2.1.7 - dav: 1.6.0 - federatedfilesharing: 1.4.0 - files: 1.9.0 - files_external: true - files_sharing: 1.6.2 - files_texteditor: 2.6.0 - firstrunwizard: 2.3.0 - gallery: 18.1.0 - logreader: 2.0.0 - lookup_server_connector: 1.2.0 - mail: 0.11.0 - nextcloud_announcements: 1.3.0 - notifications: 2.2.1 - oauth2: 1.2.1 - provisioning_api: 1.4.0 - tasks: 0.9.8 - theming: 1.5.0 - twofactor_backupcodes: 1.3.1 - updatenotification: 1.4.1 - user_ldap: 1.4.0 - workflowengine: 1.4.0 Disabled: - bruteforcesettings - comments - dashboard - encryption - federation - files_pdfviewer - files_trashbin - files_versions - files_videoplayer - news - notes - password_policy - rainloop - serverinfo - sharebymail - support - survey_client - systemtags - user_external

Nextcloud configuration:

Config report

{
"system": {
"instanceid": "REMOVED SENSITIVE VALUE",
"passwordsalt": "REMOVED SENSITIVE VALUE",
"secret": "REMOVED SENSITIVE VALUE",
"trusted_domains": [
REMOVED SENSITIVE VALUE
],
"datadirectory": "REMOVED SENSITIVE VALUE",
"overwrite.cli.url": "REMOVED SENSITIVE VALUE",
"dbtype": "mysql",
"version": "14.0.4.2",
"logtimezone": "UTC",
"installed": true,
"mail_smtpmode": "smtp",
"mail_from_address": "REMOVED SENSITIVE VALUE",
"mail_domain": "REMOVED SENSITIVE VALUE",
"ldapIgnoreNamingRules": false,
"mail_smtphost": "REMOVED SENSITIVE VALUE",
"mail_smtpport": "25",
"maintenance": false,
"dbname": "REMOVED SENSITIVE VALUE",
"dbhost": "REMOVED SENSITIVE VALUE",
"dbuser": "REMOVED SENSITIVE VALUE",
"dbpassword": "REMOVED SENSITIVE VALUE",
"theme": "",
"loglevel": 4,
"memcache.local": "\OC\Memcache\Redis",
"redis": {
"host": "REMOVED SENSITIVE VALUE",
"port": 6379
},
"memcache.locking": "\OC\Memcache\Redis",
"appstoreenabled": true,
"appstoreurl": "https://api.owncloud.com/v1",
"appstore.experimental.enabled": true,
"filesystem_check_changes": 1,
"auth.bruteforce.protection.enabled": false,
"ldapProviderFactory": "OCA\User_LDAP\LDAPProviderFactory"
}
}

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/...

LDAP configuration (delete this part if not used)

LDAP config

Client configuration

Browser:

Operating system:

Logs

Web server error log

127.0.0.1 - [29/Nov/2018:10:30:57 +0100] "PROPFIND /nextcloud/remote.php/dav/calendars/REMOVED/personal/ HTTP/1.1" 207 563
127.0.0.1 - [29/Nov/2018:10:30:58 +0100] "PROPFIND /nextcloud/remote.php/dav/calendars/REMOVED/default/ HTTP/1.1" 207 564

error:
[Thu Nov 29 10:17:50.155393 2018] [authz_core:error] [pid 14531:tid 139819187410688] [client 127.0.0.1:40540] AH01630: client denied by server configuration: /var/www/localhost/htdocs/nextcloud/data/.ocdata
[Thu Nov 29 10:24:25.995907 2018] [authz_core:error] [pid 14530:tid 139818323388160] [client 127.0.0.1:40862] AH01630: client denied by server configuration: /var/www/localhost/htdocs/nextcloud/data/.ocdata

Nextcloud log (data/nextcloud.log)

Nextcloud log

{"reqId":"W-75nD6@nOdP1qY5ew-HEAAAAFY","level":4,"time":"2018-11-28T20:25:00+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/b07c1196-e3de-1031-8c02-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":["*** sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-76Uj6@nOdP1qY5ew-HEgAAAFQ","level":4,"time":"2018-11-28T20:28:02+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/afb63a04-e3c3-1031-8c00-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-78YWv6tPBSza-npZBo8gAAAEw","level":4,"time":"2018-11-28T20:36:49+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/b07c1196-e3de-1031-8c02-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-78u2v6tPBSza-npZBo9gAAAFU","level":4,"time":"2018-11-28T20:38:20+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/b07c1196-e3de-1031-8c02-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-79Ymv6tPBSza-npZBo@wAAAEc","level":4,"time":"2018-11-28T20:41:10+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/b07c1196-e3de-1031-8c02-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-7@LWv6tPBSza-npZBpAQAAAFI","level":4,"time":"2018-11-28T20:44:30+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"PROPFIND","url":"/nextcloud/remote.php/dav/calendars/b07c1196-e3de-1031-8c02-eb343894e484/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}
{"reqId":"W-9PgyFATd1Cz63oX@aowgAAAFU","level":4,"time":"2018-11-29T02:31:31+00:00","remoteAddr":"127.0.0.1","user":"--","app":"webdav","method":"REPORT","url":"/nextcloud/remote.php/dav/addressbooks/users/afb63a04-e3c3-1031-8c00-eb343894e484/default/","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":[" sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced ***"]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}

Browser log

Insert your browser log here, this could for example include:

a) The javascript console log
b) The network log
c) ...

The text was updated successfully, but these errors were encountered:

nextcloud-bot · 2018-11-29T09:46:10Z

GitMate.io thinks possibly related issues are #11179 (Safari shows high CPU load), #12505 (External storage, high CPU load on NAS), #11747 (NC 14.0.1.1 - high CPU load through tons of csrftoken requests), #2853 (Since N11 Ubuntu touch cannot connect to dav calendar), and #2126 (Calendars not loading 500 in Browser Console ).

ChristophWurst · 2018-11-29T22:02:02Z

Steps to reproduce
1. Just wait

This doesn't really help. How did you set up the instance? How do you run your cron jobs? Do you have the web interface open during that? Are there any clients connected? If so, which ones?

LubosKolouch · 2018-11-30T07:46:42Z

I understand it is not too much helpful. It's difficult for me to tell what triggers the action but it happens "quite frequently" - several times per day.

Web interface is NOT open, no clients are cliented.

Only 2 iphones and occasionaly 1 android (davdroid) syncing contacts and callendars.

Cron jobs are run via cron, but it is the apache job hanging, not the cron.php.

ChristophWurst · 2018-11-30T09:12:10Z

If you don't kill apache, will it eventually stop its heavy load? Are the log entries you posted appear when the issue occurs or were they logged before?

LubosKolouch · 2018-11-30T09:41:35Z

If I don't kill apache, the process will keep running, increasing the load dramatically. After some time (not clear pattern) new threads will start also adding to the load.

LubosKolouch · 2018-11-30T09:43:33Z

I will post the logs when it appears. But I did not see anything strange in the logs that could relate to the problem. Is there a way to debug what the apache process is exactly doing?

LubosKolouch · 2018-11-30T09:44:41Z

Also when that happens the server returns status 503

LubosKolouch · 2018-11-30T19:09:08Z

OK the issue is happening now:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11789 apache 20 0 2578828 38704 23304 S 382.7 1.0 443:56.14 apache2

ssl_error_log:
[Fri Nov 30 18:25:19.514067 2018] [php7:error] [pid 11789:tid 139755677280000] [client 127.0.0.1:52296] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log/ErrorHandler.php on line 40
[Fri Nov 30 19:16:07.513292 2018] [php7:error] [pid 11789:tid 139756029802240] [client 127.0.0.1:51740] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log/ErrorHandler.php on line 86

latest log entry in nextcloud:
Fatal webdav Sabre\DAV\Exception\ServiceUnavailable: TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned

LubosKolouch · 2018-11-30T19:37:02Z

strace -p 11789
strace: Process 11789 attached
read(6,

LubosKolouch · 2018-11-30T19:41:04Z

lsof -p 11789

https://paste.pound-python.org/show/RpRhypHs1g29Sgtyi9D1/

LubosKolouch · 2018-11-30T20:19:41Z

(gdb) backtrace
#0 0x00007f1b8f8881b8 in read () from target:/lib64/libpthread.so.0
#1 0x000055add9d00117 in ap_mpm_podx_check ()
#2 0x000055add9d11d77 in ?? ()
#3 0x000055add9d1209a in ?? ()
#4 0x000055add9d12980 in ?? ()
#5 0x000055add9cd566d in ap_run_mpm ()
#6 0x000055add9cce046 in main ()

kesselb · 2018-11-30T20:56:30Z

I'm not sure if Fatal webdav Sabre\DAV\Exception\ServiceUnavailable: TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned is related to the high load.

server/lib/private/Authentication/Token/PublicKeyTokenProvider.php

Lines 254 to 257 in a51c837

    
           private function hashToken(string $token): string { 
        
           	$secret = $this->config->getSystemValue('secret'); 
        
           	return hash('sha512', $token . $secret); 
        
           }

Looks like hash returns false or true in your case. As per https://secure.php.net/manual/en/function.hash.php this is not possible but some people in the comments reported that false is returned when the hashing algorithm is not available.

Could you create a new file on your server with the content below and share the output?

<?php
print_r(hash_algos());

LubosKolouch · 2018-11-30T21:00:06Z

sure...

Array ( [0] => md2 [1] => md4 [2] => md5 [3] => sha1 [4] => sha224 [5] => sha256 [6] => sha384 [7] => sha512/224 [8] => sha512/256 [9] => sha512 [10] => sha3-224 [11] => sha3-256 [12] => sha3-384 [13] => sha3-512 [14] => ripemd128 [15] => ripemd160 [16] => ripemd256 [17] => ripemd320 [18] => whirlpool [19] => tiger128,3 [20] => tiger160,3 [21] => tiger192,3 [22] => tiger128,4 [23] => tiger160,4 [24] => tiger192,4 [25] => snefru [26] => snefru256 [27] => gost [28] => gost-crypto [29] => adler32 [30] => crc32 [31] => crc32b [32] => fnv132 [33] => fnv1a32 [34] => fnv164 [35] => fnv1a64 [36] => joaat [37] => haval128,3 [38] => haval160,3 [39] => haval192,3 [40] => haval224,3 [41] => haval256,3 [42] => haval128,4 [43] => haval160,4 [44] => haval192,4 [45] => haval224,4 [46] => haval256,4 [47] => haval128,5 [48] => haval160,5 [49] => haval192,5 [50] => haval224,5 [51] => haval256,5 )

LubosKolouch · 2018-11-30T21:08:29Z

sha512 is also in kernel

Symbol: CRYPTO_SHA512 [=y] │
│ Type : tristate │
│ Prompt: SHA384 and SHA512 digest algorithms │
│ Location: │
│ (1) -> Cryptographic API (CRYPTO [=y])

kesselb · 2018-11-30T21:34:34Z

OK. Could you change the hashToken method like below?

private function hashToken(string $token): string { 
    $secret = $this->config->getSystemValue('secret'); 
    $newHash = hash('sha512', $token . $secret); 
    $this->logger->debug('newHash: ' . print_r($newHash, true) . ', token: ' . print_r($token, true), ['app' => 'core']);
    return $newHash;
}

You should find some more information in nextcloud.log. Please share them 👍

LubosKolouch · 2018-11-30T21:39:51Z

changed

LubosKolouch · 2018-11-30T21:49:06Z

So far the line did not show in the log. Previously it seems to be caused by iPhone...
"message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned","Code":0,"Trace":[{"function":"{closure}","args":["*** sensitive parameters replaced "]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[{"class":"Closure"},[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":466,"function":"emit","class":"Sabre\Event\EventEmitter","type":"->","args":["beforeMethod",[" sensitive parameter replaced "," sensitive parameter replaced "]]},{"file":"/var/www/localhost/htdocs/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[" sensitive parameter replaced "," sensitive parameter replaced ***"]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":72,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/var/www/localhost/htdocs/nextcloud/remote.php","line":168,"function":"handleException","args":[{"class":"TypeError"}]}],"File":"/var/www/localhost/htdocs/nextcloud/remote.php","Line":70,"CustomMessage":"--"},"userAgent":"iOS/12.1 (16B92) dataaccessd/1.0","version":"14.0.4.2"}

Not sure if it is related to the CPU problem though...

kesselb · 2018-11-30T21:53:21Z

Ah. $this->logger->debug should be $this->logger->error. Another question: Does your secret value in config.php looks similiar to this one eSZBCo0E0Cu+o8dPuapgc3wdx/uVHtCQ7sn7ZkXtr7/QsL7k (letters, numbers, uppercase, etc.)?

LubosKolouch · 2018-11-30T22:03:05Z

I've changed it, still not appearing - will let you know once the error is there.

yes, secret looks like a hash...

kesselb · 2018-11-30T22:40:48Z

Could you try to describe which information do you replaced with "sensitive parameter replaced" in #12722 (comment)?

LubosKolouch · 2018-12-01T11:20:22Z

I did not, it's like this in the log :)

LubosKolouch · 2018-12-01T14:08:47Z

The problem is happening again, same log message. There is no line with "newHash" logged to nextcloud.log

kesselb · 2018-12-01T16:24:47Z

TypeError: Return value of OC\Authentication\Token\PublicKeyTokenProvider::hashToken() must be of the type string, boolean returned

Do you still see the error above?

LubosKolouch · 2018-12-01T16:42:44Z

yes...

LubosKolouch · 2018-12-21T16:59:43Z

After upgrade to Nextcloud 15 the above error still persists

LubosKolouch · 2018-12-22T09:33:49Z

It is probably related... davdroid fails from time to time with:

TTP REQUEST:
Request{method=PROPFIND, url=https://removed/nextcloud/remote.php/dav/calendars/removed/personal/, tags={}}

HTTP RESPONSE:
Response{protocol=http/1.1, code=500, message=Internal Server Error, url=https://removed/nextcloud/remote.php/dav/calendars/removed/personal/}

LubosKolouch · 2018-12-22T09:35:13Z

and in the apache log is:

PHP Fatal error: Allowed memory size of 536870912 bytes exhausted (tried to allocate 262144 bytes) in /var/www/localhost/htdocs/nextcloud/lib/private/Log.php on line 227

LubosKolouch · 2018-12-22T09:35:38Z

[Sat Dec 22 04:16:45.163439 2018] [php7:error] [pid 15439:tid 139793686042368] [client 127.0.0.1:35222] PHP Fatal error: Allowed memory size of 536870912 bytes exhausted (tried to allocate 262144 bytes) in /var/www/localhost/htdocs/nextcloud/lib/private/Config.php on line 89

kesselb · 2018-12-23T15:41:08Z

@nextcloud/server-triage

MorrisJobke · 2019-01-03T13:17:29Z

cc @georgehrke @icewind1991 @rullzer

georgehrke · 2019-01-03T13:42:56Z

My best guess is that there is some faulty recurrence rule that's not properly caught by Sabre/DAV and ends up in an infinite loop.

Any chance to correlate the error with a SQL request performed by that PHP process?

LubosKolouch · 2019-01-03T14:36:36Z

Yes, it could be. How to debug it the best way? MySQL used as database.

LubosKolouch · 2019-01-03T20:03:13Z

OK I enabled logging of all SQL queries. Will report back...

LubosKolouch · 2019-01-09T10:02:03Z

In the apache ssl_error_log there are now messages:

[Wed Jan 09 01:15:23.025888 2019] [php7:error] [pid 14369:tid 139779806627584] [client 127.0.0.1:45332] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log.php on line 269
[Wed Jan 09 01:40:25.904031 2019] [php7:error] [pid 14369:tid 139778402006784] [client 127.0.0.1:43094] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log.php on line 206
[Wed Jan 09 03:29:28.859433 2019] [php7:error] [pid 14369:tid 139779798234880] [client 127.0.0.1:43744] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/3rdparty/phpseclib/phpseclib/phpseclib/Crypt/Hash.php on line 308
[Wed Jan 09 04:40:27.217271 2019] [php7:error] [pid 14369:tid 139778410399488] [client 127.0.0.1:40070] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log.php on line 287
[Wed Jan 09 06:29:29.669525 2019] [php7:error] [pid 14369:tid 139779257636608] [client 127.0.0.1:44624] PHP Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/lib/private/Log/ErrorHandler.php on line 40

kesselb · 2019-01-09T11:55:24Z

Fatal error: Maximum execution time of 3600 seconds exceeded in /var/www/localhost/htdocs/nextcloud/3rdparty/phpseclib/phpseclib/phpseclib/Crypt/Hash.php on line 308

Another error related to the hashing 🤔 Are you running apache2 with mod_php? Not sure if this changes something but would try apache2 with php-fpm.

LubosKolouch · 2019-01-28T17:36:25Z

After upgrade to nextcloud 15 / php 7.3.1 it seems I can't reproduce it anymore...

kesselb · 2019-01-28T20:56:35Z

Thank you for reporting back 🥇

galandilias · 2019-10-02T07:52:55Z

On NextCloud 16.0.1 I have the same behaviour - the setup ot my system is nearly the same - I can provide more information - but please guide me what do you need.

galandilias · 2019-10-02T08:01:14Z

Above is what I can find in the admin log of Nextcloud and the time of occurance of above errors is exactly the time of those two heavy threads start on my server - so this should be the root cause I think.

georgehrke · 2019-10-02T08:02:34Z

@galandilias Please open a new bug report and fill out the entire issue template instead of hijacking old bug reports closed ages ago. Thx!

galandilias · 2019-10-02T08:03:17Z

Okay - excuse me! :)

nextcloud-bot added 14-beta-feedback bug labels Nov 29, 2018

ChristophWurst added needs info 0. Needs triage Pending check for reproducibility or if it fits our roadmap and removed 14-beta-feedback labels Nov 29, 2018

kesselb closed this as completed Jan 28, 2019

kesselb mentioned this issue Feb 2, 2019

Server repeatedly fill disk with infinite log messages: "hash_hmac(): Unknown hashing algorithm:sha1" #9243

Closed

kesselb mentioned this issue Mar 11, 2019

nextcloud very slow login via browser with high I/O load on the DB server #14632

Closed

galandilias mentioned this issue Oct 7, 2019

High CPU load with DAV related components #17447

Closed

High CPU load probably related to calendar or DAV #12722

High CPU load probably related to calendar or DAV #12722

Comments

LubosKolouch commented Nov 29, 2018 • edited Loading

Steps to reproduce

Expected behaviour

Actual behaviour

Server configuration

LDAP configuration (delete this part if not used)

Client configuration

Logs

Web server error log

Nextcloud log (data/nextcloud.log)

Browser log

nextcloud-bot commented Nov 29, 2018

ChristophWurst commented Nov 29, 2018

Steps to reproduce

LubosKolouch commented Nov 30, 2018

ChristophWurst commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

kesselb commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

kesselb commented Nov 30, 2018 • edited Loading

LubosKolouch commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

kesselb commented Nov 30, 2018

LubosKolouch commented Nov 30, 2018

kesselb commented Nov 30, 2018

LubosKolouch commented Dec 1, 2018

LubosKolouch commented Dec 1, 2018

kesselb commented Dec 1, 2018

LubosKolouch commented Dec 1, 2018

LubosKolouch commented Dec 21, 2018

LubosKolouch commented Dec 22, 2018

LubosKolouch commented Dec 22, 2018

LubosKolouch commented Dec 22, 2018

kesselb commented Dec 23, 2018

MorrisJobke commented Jan 3, 2019

georgehrke commented Jan 3, 2019

LubosKolouch commented Jan 3, 2019

LubosKolouch commented Jan 3, 2019

LubosKolouch commented Jan 9, 2019

kesselb commented Jan 9, 2019

LubosKolouch commented Jan 28, 2019

kesselb commented Jan 28, 2019

galandilias commented Oct 2, 2019

galandilias commented Oct 2, 2019 • edited Loading

georgehrke commented Oct 2, 2019

galandilias commented Oct 2, 2019

LubosKolouch commented Nov 29, 2018 •

edited

Loading

kesselb commented Nov 30, 2018 •

edited

Loading

galandilias commented Oct 2, 2019 •

edited

Loading