non-ending background job #22887

Closed
tflidd opened this Issue Mar 5, 2016 · 12 comments

Projects

None yet

7 participants

@tflidd
Contributor
tflidd commented Mar 5, 2016

Steps to reproduce

  1. Play around with sharing (federated sharing)
  2. Remove all shared folders (from others), remove all shared folders (to others)
  3. background job of a different setup is running crazy

Expected behaviour

Just delete the shares.

Actual behaviour

Heavy connection activity to other server (via cronjob).

Server configuration

Operating system: Debian 8

Web server: Apache

Database: Mysql

PHP version: 7.0.4 mod_php (dotdeb)

ownCloud version: 9.0.0 RC 2

Updated from an older ownCloud or fresh install: good question, I'm not sure

Where did you install ownCloud from: manual install from zip

Signing status (ownCloud 9.0 and above):

No errors have been found.

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

Are you using encryption: no

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

oc_jobs

OCA\Files\BackgroundJob\ScanFiles 
OCA\Files_Trashbin\BackgroundJob\ExpireTrash 
OCA\Files_sharing\Lib\DeleteOrphanedSharesJob   
OCA\Files_sharing\ExpireSharesJob
OCA\Federation\SyncJob      
OCA\Files\BackgroundJob\DeleteOrphanedItems
OCA\DAV\CardDAV\SyncJob
OCA\Files\BackgroundJob\CleanupFileLocks 
OC\BackgroundJob\Legacy\RegularJob
OC\BackgroundJob\Legacy\RegularJob

ownCloud log (data/owncloud.log)

{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"federation","message":"Exception: {\"Exception\":\"GuzzleHttp\\\\Exception\\\\ClientException\",\"Message\":\"Client error response [url] https:\\\/\\\/my-ip\\\/owncloud\\\/ocs\\\/v2.php\\\/apps\\\/federation\\\/api\\\/v1\\\/request-shared-secret?format=json [status code] 404 [reason phrase] Not Found\",\"Code\":404,\"Trace\":\"#0 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Subscriber\\\/HttpError.php(32): GuzzleHttp\\\\Exception\\\\RequestException::create(Object(GuzzleHttp\\\\Message\\\\Request), Object(GuzzleHttp\\\\Message\\\\Response))\\n#1 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Event\\\/Emitter.php(109): GuzzleHttp\\\\Subscriber\\\\HttpError->onComplete(Object(GuzzleHttp\\\\Event\\\\CompleteEvent), 'complete')\\n#2 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(91): GuzzleHttp\\\\Event\\\\Emitter->emit('complete', Object(GuzzleHttp\\\\Event\\\\CompleteEvent))\\n#3 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(132): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#4 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/react\\\/promise\\\/src\\\/FulfilledPromise.php(25): GuzzleHttp\\\\RequestFsm->GuzzleHttp\\\\{closure}(Array)\\n#5 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/ringphp\\\/src\\\/Future\\\/CompletedFutureValue.php(55): React\\\\Promise\\\\FulfilledPromise->then(Object(Closure), NULL, NULL)\\n#6 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Message\\\/FutureResponse.php(43): GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureValue->then(Object(Closure), NULL, NULL)\\n#7 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(134): GuzzleHttp\\\\Message\\\\FutureResponse::proxy(Object(GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureArray), Object(Closure))\\n#8 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(165): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#9 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(150): GuzzleHttp\\\\Client->send(Object(GuzzleHttp\\\\Message\\\\Request))\\n#10 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/http\\\/client\\\/client.php(191): GuzzleHttp\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#11 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(144): OC\\\\Http\\\\Client\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#12 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/job.php(52): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->run(Array)\\n#13 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/queuedjob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#14 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(125): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#15 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(116): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->parentExecute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#16 \\\/var\\\/www\\\/oc9\\\/cron.php(141): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#17 {main}\",\"File\":\"\\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Exception\\\/RequestException.php\",\"Line\":89}","level":3,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Finished job with ID 8478","level":0,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Run job with ID 8479","level":0,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"federation","message":"Exception: {\"Exception\":\"GuzzleHttp\\\\Exception\\\\ClientException\",\"Message\":\"Client error response [url] https:\\\/\\\/my-ip\\\/owncloud\\\/ocs\\\/v2.php\\\/apps\\\/federation\\\/api\\\/v1\\\/request-shared-secret?format=json [status code] 404 [reason phrase] Not Found\",\"Code\":404,\"Trace\":\"#0 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Subscriber\\\/HttpError.php(32): GuzzleHttp\\\\Exception\\\\RequestException::create(Object(GuzzleHttp\\\\Message\\\\Request), Object(GuzzleHttp\\\\Message\\\\Response))\\n#1 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Event\\\/Emitter.php(109): GuzzleHttp\\\\Subscriber\\\\HttpError->onComplete(Object(GuzzleHttp\\\\Event\\\\CompleteEvent), 'complete')\\n#2 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(91): GuzzleHttp\\\\Event\\\\Emitter->emit('complete', Object(GuzzleHttp\\\\Event\\\\CompleteEvent))\\n#3 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(132): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#4 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/react\\\/promise\\\/src\\\/FulfilledPromise.php(25): GuzzleHttp\\\\RequestFsm->GuzzleHttp\\\\{closure}(Array)\\n#5 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/ringphp\\\/src\\\/Future\\\/CompletedFutureValue.php(55): React\\\\Promise\\\\FulfilledPromise->then(Object(Closure), NULL, NULL)\\n#6 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Message\\\/FutureResponse.php(43): GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureValue->then(Object(Closure), NULL, NULL)\\n#7 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(134): GuzzleHttp\\\\Message\\\\FutureResponse::proxy(Object(GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureArray), Object(Closure))\\n#8 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(165): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#9 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(150): GuzzleHttp\\\\Client->send(Object(GuzzleHttp\\\\Message\\\\Request))\\n#10 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/http\\\/client\\\/client.php(191): GuzzleHttp\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#11 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(144): OC\\\\Http\\\\Client\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#12 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/job.php(52): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->run(Array)\\n#13 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/queuedjob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#14 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(125): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#15 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(116): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->parentExecute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#16 \\\/var\\\/www\\\/oc9\\\/cron.php(141): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#17 {main}\",\"File\":\"\\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Exception\\\/RequestException.php\",\"Line\":89}","level":3,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Finished job with ID 8479","level":0,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Run job with ID 8480","level":0,"time":"2016-03-05T21:13:26+00:00","method":"--","url":"--"}

These messages are repeated over and over again. On the second server which is queried, I got corresponding 404-errors in the logfile.

@LukasReschke
Member

Heavy connection activity to other server (via cronjob).

Can you define "heavy"? Are we talking 1 request all 15 minutes or 10000 every minute? Just so that I can judge the severity based on that.

@tflidd
Contributor
tflidd commented Mar 5, 2016

3.5 requests per second.

@LukasReschke
Member

cc @DeepDiver1975 @schiesbn

@tflidd
Contributor
tflidd commented Mar 6, 2016

I went to bed and this morning it was finished (after 200k lines in the logfile). Here is the last entry and what's following:

{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Run job with ID 63483","level":0,"time":"2016-03-06T01:31:28+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"federation","message":"Exception: {\"Exception\":\"GuzzleHttp\\\\Exception\\\\ClientException\",\"Message\":\"Client error response [url] https:\\\/\\\/my-ip\\\/owncloud\\\/ocs\\\/v2.php\\\/apps\\\/federation\\\/api\\\/v1\\\/request-shared-secret?format=json [status code] 404 [reason phrase] Not Found\",\"Code\":404,\"Trace\":\"#0 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Subscriber\\\/HttpError.php(32): GuzzleHttp\\\\Exception\\\\RequestException::create(Object(GuzzleHttp\\\\Message\\\\Request), Object(GuzzleHttp\\\\Message\\\\Response))\\n#1 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Event\\\/Emitter.php(109): GuzzleHttp\\\\Subscriber\\\\HttpError->onComplete(Object(GuzzleHttp\\\\Event\\\\CompleteEvent), 'complete')\\n#2 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(91): GuzzleHttp\\\\Event\\\\Emitter->emit('complete', Object(GuzzleHttp\\\\Event\\\\CompleteEvent))\\n#3 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(132): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#4 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/react\\\/promise\\\/src\\\/FulfilledPromise.php(25): GuzzleHttp\\\\RequestFsm->GuzzleHttp\\\\{closure}(Array)\\n#5 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/ringphp\\\/src\\\/Future\\\/CompletedFutureValue.php(55): React\\\\Promise\\\\FulfilledPromise->then(Object(Closure), NULL, NULL)\\n#6 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Message\\\/FutureResponse.php(43): GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureValue->then(Object(Closure), NULL, NULL)\\n#7 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/RequestFsm.php(134): GuzzleHttp\\\\Message\\\\FutureResponse::proxy(Object(GuzzleHttp\\\\Ring\\\\Future\\\\CompletedFutureArray), Object(Closure))\\n#8 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(165): GuzzleHttp\\\\RequestFsm->__invoke(Object(GuzzleHttp\\\\Transaction))\\n#9 \\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Client.php(150): GuzzleHttp\\\\Client->send(Object(GuzzleHttp\\\\Message\\\\Request))\\n#10 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/http\\\/client\\\/client.php(191): GuzzleHttp\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#11 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(144): OC\\\\Http\\\\Client\\\\Client->post('https:\\\/\\\/data.as...', Array)\\n#12 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/job.php(52): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->run(Array)\\n#13 \\\/var\\\/www\\\/oc9\\\/lib\\\/private\\\/backgroundjob\\\/queuedjob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#14 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(125): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#15 \\\/var\\\/www\\\/oc9\\\/apps\\\/federation\\\/backgroundjob\\\/requestsharedsecret.php(116): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->parentExecute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#16 \\\/var\\\/www\\\/oc9\\\/cron.php(141): OCA\\\\Federation\\\\BackgroundJob\\\\RequestSharedSecret->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#17 {main}\",\"File\":\"\\\/var\\\/www\\\/oc9\\\/3rdparty\\\/guzzlehttp\\\/guzzle\\\/src\\\/Exception\\\/RequestException.php\",\"Line\":89}","level":3,"time":"2016-03-06T01:31:28+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Finished job with ID 63483","level":0,"time":"2016-03-06T01:31:28+00:00","method":"--","url":"--"}
{"reqId":"U2XI+wm\/+8BOUpJREs2m","remoteAddr":"","app":"cron","message":"Run job with ID 63484","level":0,"time":"2016-03-06T01:31:28+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 1","level":0,"time":"2016-03-06T01:45:07+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 1","level":0,"time":"2016-03-06T01:45:09+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 2","level":0,"time":"2016-03-06T01:45:09+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 2","level":0,"time":"2016-03-06T01:45:10+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 3","level":0,"time":"2016-03-06T01:45:10+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"DeleteOrphanedSharesJob","message":"0 orphaned share(s) deleted","level":0,"time":"2016-03-06T01:45:11+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 3","level":0,"time":"2016-03-06T01:45:11+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 4","level":0,"time":"2016-03-06T01:45:11+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 4","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 8","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 8","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 9","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"DeleteOrphanedItems","message":"0 orphaned system tag relations deleted","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"DeleteOrphanedItems","message":"0 orphaned user tag relations deleted","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"DeleteOrphanedItems","message":"0 orphaned comments deleted","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"DeleteOrphanedItems","message":"0 orphaned comment read marks deleted","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 9","level":0,"time":"2016-03-06T01:45:12+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 10","level":0,"time":"2016-03-06T01:45:13+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 10","level":0,"time":"2016-03-06T01:45:14+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 14","level":0,"time":"2016-03-06T01:45:14+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 14","level":0,"time":"2016-03-06T01:45:14+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 20","level":0,"time":"2016-03-06T01:45:15+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 20","level":0,"time":"2016-03-06T01:45:17+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Run job with ID 328","level":0,"time":"2016-03-06T01:45:17+00:00","method":"--","url":"--"}
{"reqId":"t4Lul+oEDLWLlkKuOVk5","remoteAddr":"","app":"cron","message":"Finished job with ID 328","level":0,"time":"2016-03-06T01:45:18+00:00","method":"--","url":"--"}
{"reqId":"eoPVrAWK4B94\/M\/TiTaj","remoteAddr":"","app":"cron","message":"Run job with ID 1","level":0,"time":"2016-03-06T02:00:07+00:00","method":"--","url":"--"}
{"reqId":"eoPVrAWK4B94\/M\/TiTaj","remoteAddr":"","app":"cron","message":"Finished job with ID 1","level":0,"time":"2016-03-06T02:00:08+00:00","method":"--","url":"--"}
@PVince81
Collaborator
PVince81 commented Mar 7, 2016

It is still not clear which one of the jobs is doing many requests. In the log there are job ids, can you cross-reference it with your "oc_jobs" table to find out which job it was ?

Regarding the 404 with "federation": from your other bug reports I guess that you have existing federated shares. I suspect that the federation app is trying to sync address books between the remote server and yours. But the remote server probably doesn't have this app enabled yet or isn't upgraded, so the 404 is normal in that case.

@PVince81 PVince81 added the needs info label Mar 7, 2016
@tflidd
Contributor
tflidd commented Mar 7, 2016

The problem, there is no job with id 8478. The complete dump of my oc_jobs:

"1","OCA\Files\BackgroundJob\ScanFiles","null","1457349301"
"2","OCA\Files_Trashbin\BackgroundJob\ExpireTrash","null","1457348402"
"3","OCA\Files_sharing\Lib\DeleteOrphanedSharesJob","null","1457348402"
"4","OCA\Files_sharing\ExpireSharesJob","null","1457316003"
"8","OCA\Federation\SyncJob","null","1457316003"
"9","OCA\Files\BackgroundJob\DeleteOrphanedItems","null","1457347501"
"10","OCA\DAV\CardDAV\SyncJob","null","1457316004"
"14","OCA\Files\BackgroundJob\CleanupFileLocks","null","1457349302"
"20","OC\BackgroundJob\Legacy\RegularJob","[""OCA\\News\\Cron\\Updater"",""run""]","1457349302"
"328","OC\BackgroundJob\Legacy\RegularJob","[""OCA\\Music\\Backgroundjob\\CleanUp"",""run""]","1457349305"

As the jobs were running, there were not more entries in oc_jobs.

@PVince81
Collaborator
PVince81 commented Mar 7, 2016

Okay, then it was likely a temporary job like "expire versions for user X and file F"

@tflidd
Contributor
tflidd commented Mar 7, 2016

I don't know how to reproduce it. I created plenty of federated sharing connections (incoming & outgoing, no big folders only ~4-8 files of a few kB) that day. When I find some time to test the fix the unlimited quota (22898)-bug, it will perhaps come back again.

@wdj-ac
wdj-ac commented Mar 16, 2016

Same issue here.
Today tested federated feature with the german education cloud sciebo (owncloud fork). Just the standard folder "Documents". 5 Minutes later I deleted the folder in sciebo. After some testing I found the cronjob was working endless. I deleted trusted federation domains from backend and then the cronjob was gone.

Log:

{"reqId":"KyS5dUs7wZpCXPQkfx2V","remoteAddr":"","app":"federation","message":"Exception: {"Exception":"GuzzleHttp\Exception\ServerException","Message":"Server error response [url] https:\/\/fh-aachen.sciebo.de\/ocs\/v2.php\/apps\/federation\/api\/v1\/request-shared-secret?format=json [status code] 500 [reason phrase] Internal Server Error","Code":500,"Trace":"#0 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Subscriber\/HttpError.php(33): GuzzleHttp\Exception\RequestException::create(Object(GuzzleHttp\Message\Request), Object(GuzzleHttp\Message\Response))\n#1 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Event\/Emitter.php(109): GuzzleHttp\Subscriber\HttpError->onComplete(Object(GuzzleHttp\Event\CompleteEvent), 'complete')\n#2 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/RequestFsm.php(91): GuzzleHttp\Event\Emitter->emit('complete', Object(GuzzleHttp\Event\CompleteEvent))\n#3 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/RequestFsm.php(132): GuzzleHttp\RequestFsm->__invoke(Object(GuzzleHttp\Transaction))\n#4 \/var\/www\/owncloud\/3rdparty\/react\/promise\/src\/FulfilledPromise.php(25): GuzzleHttp\RequestFsm->GuzzleHttp\{closure}(Array)\n#5 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/ringphp\/src\/Future\/CompletedFutureValue.php(55): React\Promise\FulfilledPromise->then(Object(Closure), NULL, NULL)\n#6 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Message\/FutureResponse.php(43): GuzzleHttp\Ring\Future\CompletedFutureValue->then(Object(Closure), NULL, NULL)\n#7 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/RequestFsm.php(135): GuzzleHttp\Message\FutureResponse::proxy(Object(GuzzleHttp\Ring\Future\CompletedFutureArray), Object(Closure))\n#8 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Client.php(165): GuzzleHttp\RequestFsm->__invoke(Object(GuzzleHttp\Transaction))\n#9 \/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Client.php(150): GuzzleHttp\Client->send(Object(GuzzleHttp\Message\Request))\n#10 \/var\/www\/owncloud\/lib\/private\/http\/client\/client.php(191): GuzzleHttp\Client->post('https:\/\/fh-aach...', Array)\n#11 \/var\/www\/owncloud\/apps\/federation\/backgroundjob\/requestsharedsecret.php(146): OC\Http\Client\Client->post('https:\/\/fh-aach...', Array)\n#12 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/job.php(52): OCA\Federation\BackgroundJob\RequestSharedSecret->run(Array)\n#13 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/queuedjob.php(42): OC\BackgroundJob\Job->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#14 \/var\/www\/owncloud\/apps\/federation\/backgroundjob\/requestsharedsecret.php(125): OC\BackgroundJob\QueuedJob->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#15 \/var\/www\/owncloud\/apps\/federation\/backgroundjob\/requestsharedsecret.php(116): OCA\Federation\BackgroundJob\RequestSharedSecret->parentExecute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#16 \/var\/www\/owncloud\/cron.php(141): OCA\Federation\BackgroundJob\RequestSharedSecret->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#17 {main}","File":"\/var\/www\/owncloud\/3rdparty\/guzzlehttp\/guzzle\/src\/Exception\/RequestException.php","Line":89}","level":3,"time":"2016-03-16T20:42:52+00:00"}

@nickvergessen
Contributor

Okay, understood the situation. The problem is, that we can not request a token, because sciebo is not on 9.0 yet. So we receive an error. For error handling the background job adds a new background job into the queue so we "try again later".

However we had the problem with the background job initialisation (#21987), so we made it "get the next job" until we get a job we already had.
The problem now is, that the "re-queued" job is returned and results in the same problem.

Possible solutions:

  1. Ignore the job when the target server does not have the endpoint
  2. Background job redesign to trigger the background job at a later point in time, and not immediate.

Will create a patch for 1, while 2 is way too much for a backport.

@nickvergessen nickvergessen self-assigned this Mar 18, 2016
@PVince81 PVince81 added this to the 9.0.1-current-maintenance milestone Mar 18, 2016
@schiessle
Member
  1. Background job redesign to trigger the background job at a later point in time, and not immediate.

Yes, if a job gets re-queued we should add it to the end of the list and don't try it again in the current run. Probably to much for a backport but we should definitely look into this for 9.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment