Ongoing PHP errors in /lib/FilesHooks.php during files upload about activity HOT 6 CLOSED

Fix is in #157

from activity.

@nickvergessen
Fix worked great for me and never saw this error again. But another user reported this now on NC 12.0.1 and he checked that the fix (line 141) is applied:
https://help.nextcloud.com/t/nc12-beta2-activity-error-php-undefined-offset-3-at-path-to-nextcloud-apps-activity-lib-fileshooks-php-620/12461/15

Probably during WebDAV + Windows + Excel file change or collabora online.

Any idea if there is maybe another invalid $path variable that needs to be excluded? Maybe via WebDAV (without nextcloud client) excluding ms office temporary files does not work fine or something?

from activity.

Same problem.. Still with Nextcloud 12.0.3rc2.
Using Nginx v1.12.1. OS: Debian Jessie. PHP 7.1 FPM.

Activity App v2.5.2.

Undefined offset: 3 at \/var\/www\/nextcloud\/apps\/activity\/lib\/FilesHooks.php#620

"app":"PHP","method":"MO
VE","url":"\/remote.php\/webdav\/<SECRET>","message":"Undefined offset: 3 at \/var\/www\/nextcloud\/apps\/activity\/lib\/FilesHooks.php#620"
,"userAgent":"Mozilla\/5.0 (X11; Ubuntu; Linux x86_64; rv:55.0) Gecko\/20100101 Firefox\/55.0","version":"12.0.3.1"}                               
{"reqId":"5FdAEvO2j7CiT7Phrp8N","level":3,"time":"2017-09-17T15:15:22+00:00","remoteAddr":"","user":"--","app":"appstoreFetcher","method":"--","url
":"--","message":"Exception: {\"Exception\":\"GuzzleHttp\\\\Exception\\\\ConnectException\",\"Message\":\"cURL error 28: Operation timed out after 
10000 milliseconds with 0 bytes received\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Requ
estFsm.php(103): GuzzleHttp\\\\Exception\\\\RequestException::wrapException(Object(GuzzleHttp\\\\Message\\\\Request), Object(GuzzleHttp\\\\Ring\\\\
Exception\\\\ConnectException))\\n#1 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(132): GuzzleHttp\\\\R
equestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#2 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/react\\\/promise\\\/src\\\/FulfilledPromise.
php(25): GuzzleHttp\\\\RequestFsm->GuzzleHttp\\\\{closure}(Array)\\n#3 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/guzzlehttp\\\/ringphp\\\/src\\\/F
uture\\\/CompletedFutureValue.php(55): React\\\\Promise\\\\FulfilledPromise->then(Object(Closure), NULL, NULL)\\n#4 \\\/var\\\/www\\\/nextcloud\\\/
3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Message\\\/FutureResponse.php(43): GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureValue->then(Object(Clo
sure), NULL, NULL)\\n#5 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(134): GuzzleHttp\\\\Message\\\\Fut
ureResponse::proxy(Object(GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureArray), Object(Closure))\\n#6 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/g
uzzlehttp\\\/guzzle\\\/src\\\/Client.php(165): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#7 \\\/var\\\/www\\\/nextclo
ud\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(125): GuzzleHttp\\\\Client->send(Object(GuzzleHttp\\\\Message\\\\Request))\\n#8 \\\/var
\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Http\\\/Client\\\/Client.php(138): GuzzleHttp\\\\Client->get('https:\\\/\\\/apps.ne...', Array)\\n#9 \\\/
var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/App\\\/AppStore\\\/Fetcher\\\/Fetcher.php(99): OC\\\\Http\\\\Client\\\\Client->get('https:\\\/\\\/apps
.ne...', Array)\\n#10 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/App\\\/AppStore\\\/Fetcher\\\/AppFetcher.php(66): OC\\\\App\\\\AppStore\\\\F
etcher\\\\Fetcher->fetch('\\\"2017-09-14 12:...', '[{\\\"id\\\":\\\"registr...')\\n#11 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/App\\\/AppS
tore\\\/Fetcher\\\/Fetcher.php(162): OC\\\\App\\\\AppStore\\\\Fetcher\\\\AppFetcher->fetch('\\\"2017-09-14 12:...', '[{\\\"id\\\":\\\"registr...')\
\n#12 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Installer.php(394): OC\\\\App\\\\AppStore\\\\Fetcher\\\\Fetcher->get()\\n#13 \\\/var\\\/www\
\\/nextcloud\\\/apps\\\/updatenotification\\\/lib\\\/Notification\\\/BackgroundJob.php(258): OC\\\\Installer::isUpdateAvailable('activity', Object(
OC\\\\App\\\\AppStore\\\\Fetcher\\\\AppFetcher))\\n#14 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/updatenotification\\\/lib\\\/Notification\\\/Backgrou
ndJob.php(155): OCA\\\\UpdateNotification\\\\Notification\\\\BackgroundJob->isUpdateAvailable('activity')\\n#15 \\\/var\\\/www\\\/nextcloud\\\/apps
\\\/updatenotification\\\/lib\\\/Notification\\\/BackgroundJob.php(79): OCA\\\\UpdateNotification\\\\Notification\\\\BackgroundJob->checkAppUpdates
()\\n#16 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/BackgroundJob\\\/Job.php(59): OCA\\\\UpdateNotification\\\\Notification\\\\BackgroundJob-
>run(NULL)\\n#17 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/BackgroundJob\\\/TimedJob.php(54): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\
\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#18 \\\/var\\\/www\\\/nextcloud\\\/cron.php(124): OC\\\\BackgroundJob\\\\TimedJob->execute(Objec
t(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#19 {main}\",\"File\":\"\\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/
src\\\/Exception\\\/RequestException.php\",\"Line\":49}","userAgent":"--","version":"12.0.3.1"}                     

Error location (I'm not a Nextcloud developer, but I guess):
https://github.com/nextcloud/activity/blob/v12.0.3RC2/lib/FilesHooks.php#L620

My Cronjob went crazy!!! High CPU & memory usage! 10Gb memory!! 100% CPU... ;(

Line in crontab: */15 * * * * php -f /var/www/nextcloud/cron.php.

Please, reopen issue.. URGENT.

Ps. killing the cron.php job, the system goes back to normal operation (both memory usage as well as CPU and disk IO).

Statistics are publicly available:
https://monitor.melroy.org/ (incident started previous week, slowly grows over time, crashing my server almost)

from activity.

Well the Exception from your log as well as the cron misbehaviour are not caused by this issue here, so no need to panic 😉

If this still happens for you, please add the following lines before the following code in line 618:

		$path = $node->getPath();
		$sections = explode('/', $path, 4);
		$accessList['ownerPath'] = '/' . $sections[3];

before add:

		if (substr_count($node->getPath(), '/') < 3) {
			\OC::$server->getLogger()->logException(new \RuntimeException('Error creating activity for path ' . $path), [
				'app' => 'activity',
			]);
		}

Then wait until the error happens again and provide me with that log entry.

from activity.

Hi @nickvergessen,

I have applied the patch #157 to NC 12 and can confirm that it doesn't fix the problem when renaming files (seems the error occurs whenever a file is renamed). I have added the suggested debugging lines to the code and this is the output:

{"reqId":"WktAj6hGTj52wKAGJYqeuAAAAAg","level":3,"time":"2018-01-02T08:19:28+00:00","remoteAddr":"xxx.xxx.xxx.xxx","user":"testuser1","app":"activity","method":"MOVE","url":"\/server\/remote.php\/webdav\/testfile1.txt","message":"Exception: {\"Exception\":\"RuntimeException\",\"Message\":\"Error creating activity for path \\\/\",\"Code\":0,\"Trace\":\"#0 \\\/www\\\/nextcloud\\\/apps\\\/activity\\\/lib\\\/FilesHooks.php(367): OCA\\\\Activity\\\\FilesHooks->getUserPathsFromPath('\\\/', 'testuser1')\\n#1 \\\/www\\\/nextcloud\\\/apps\\\/activity\\\/lib\\\/FilesHooks.php(337): OCA\\\\Activity\\\\FilesHooks->fileRenaming('\\\/testfile1.txt', '\\\/testfile2.txt')\\n#2 \\\/www\\\/nextcloud\\\/apps\\\/activity\\\/lib\\\/FilesHooksStatic.php(79): OCA\\\\Activity\\\\FilesHooks->fileMovePost('\\\/testfile1.txt', '\\\/testfile2.txt')\\n#3 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/legacy\\\/hook.php(106): OCA\\\\Activity\\\\FilesHooksStatic::fileMovePost(Array)\\n#4 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/View.php(829): OC_Hook::emit('OC_Filesystem', 'post_rename', Array)\\n#5 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(137): OC\\\\Files\\\\View->rename('\\\/testfile1.txt', '\\\/testfile2.txt')\\n#6 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Tree.php(151): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Node->setName('testfile2.txt')\\n#7 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(642): Sabre\\\\DAV\\\\Tree->move('testfile1.txt', 'testfile2.txt')\\n#8 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpMove(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#10 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:MOVE', Array)\\n#11 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#12 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(71): Sabre\\\\DAV\\\\Server->exec()\\n#13 \\\/www\\\/nextcloud\\\/remote.php(162): require_once('\\\/www\\\/nextcloud\\\/...')\\n#14 {main}\",\"File\":\"\\\/www\\\/nextcloud\\\/apps\\\/activity\\\/lib\\\/FilesHooks.php\",\"Line\":618}","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"12.0.0.29"} {"reqId":"WktAj6hGTj52wKAGJYqeuAAAAAg","level":3,"time":"2018-01-02T08:19:28+00:00","remoteAddr":"xxx.xxx.xxx.xxx","user":"testuser1","app":"PHP","method":"MOVE","url":"\/server\/remote.php\/webdav\/testfile1.txt","message":"Undefined offset: 3 at \/www\/nextcloud\/apps\/activity\/lib\/FilesHooks.php#624","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"12.0.0.29"} {"reqId":"WktAj6hGTj52wKAGJYqeuAAAAAg","level":1,"time":"2018-01-02T08:19:28+00:00","remoteAddr":"xxx.xxx.xxx.xxx","user":"testuser1","app":"admin_audit","method":"MOVE","url":"\/server\/remote.php\/webdav\/testfile1.txt","message":"File renamed: \"\/testfile1.txt\" to \"\/testfile2.txt\"","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko\/20100101 Firefox\/57.0","version":"12.0.0.29"}

Thanks!

from activity.

Fixed with #226

from activity.