Server: High CPU load probably related to calendar or DAV

[LubosKolouch]

Steps to reproduce

1. Just wait ... symptom is error 503 reported by CalDav or NC page not loaded in browser
2. Apache process eats all CPU and runs indefinetely,
3. 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

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

Browser log

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

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

[nextcloud-bot]

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

[ChristophWurst]

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]

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]

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]

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]

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]

Also when that happens the server returns status 503

[LubosKolouch]

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]

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

[LubosKolouch]

lsof -p 11789

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

[LubosKolouch]

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

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.

https://github.com/nextcloud/server/blob/a51c8377d42ba3d028b68e415b22bf47fc9cf191/lib/private/Authentication/Token/PublicKeyTokenProvider.php#L254-L257

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]

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]

sha512 is also in kernel

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

[kesselb]

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 :+1:

[LubosKolouch]

changed

[LubosKolouch]

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]

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]

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

yes, secret looks like a hash...

[kesselb]

Could you try to describe which information do you replaced with "sensitive parameter replaced" in https://github.com/nextcloud/server/issues/12722#issuecomment-443350000?

[LubosKolouch]

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

[LubosKolouch]

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

[kesselb]

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]

yes...

[LubosKolouch]

After upgrade to Nextcloud 15 the above error still persists

[LubosKolouch]

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]

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]

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

@nextcloud/server-triage

[MorrisJobke]

cc @georgehrke @icewind1991 @rullzer

[georgehrke]

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]

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

[LubosKolouch]

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

[LubosKolouch]

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]

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 :thinking: Are you running apache2 with mod_php? Not sure if this changes something but would try apache2 with php-fpm.

[LubosKolouch]

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

[kesselb]

Thank you for reporting back :1st_place_medal:

[galandilias]

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]

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]

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

Okay - excuse me! :)