search

owncloud / core

:cloud: ownCloud web server core (Files, DAV, etc.)
https://owncloud.com
GNU Affero General Public License v3.0
8.36k stars 2.06k forks source link

non-ending background job #22887

Closed tflidd closed 8 years ago

tflidd commented 8 years ago

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 commented 8 years ago

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 commented 8 years ago

3.5 requests per second.

LukasReschke commented 8 years ago

cc @DeepDiver1975 @schiesbn

tflidd commented 8 years ago

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 commented 8 years ago

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.

tflidd commented 8 years ago

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 commented 8 years ago

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

tflidd commented 8 years ago

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.

nightillusions commented 8 years ago

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"}

PVince81 commented 8 years ago

@MorrisJobke @nickvergessen

nickvergessen commented 8 years ago

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 (https://github.com/owncloud/core/pull/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.

schiessle commented 8 years ago
  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

lock[bot] commented 5 years ago

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.