[OJS-3.4.0-4] Statistic problem

shantanusingh · February 23, 2024, 11:29am

Today the log file which was stuck for three days (20-22 Feb 2024) got processed automatically without implementation of the above suggestion [OJS-3.4.0-4] Statistic problem - #81 by jonasraoni.

3-4 days let’s see what happens or what suggestions will be implemented. I will update you.

jonasraoni · February 23, 2024, 12:36pm

Ok! I’ll try to get the updates merged anyway, I think it should improve a bit the situation.

jonasraoni · February 23, 2024, 5:41pm

A new OJS version will be released today with these updates, so you can check if it’s enough. If not, there are still two things to try.

Best,
Jonas Raoni

shantanusingh · February 26, 2024, 5:01am

Hi, @jonasraoni Does this ([OJS-3.4.0-4] Performance issue OJS-3.3.0-14 to OJS-3.4.0.4 - #5 by jonasraoni) code you suggested need to be implemented in OJS-3.4.0-5?

jonasraoni · February 26, 2024, 6:48am

Yes, better to keep this temporary fix
It should be fixed as part of this issue: Improve search framework · Issue #8920 · pkp/pkp-lib · GitHub

I’ll try to work on it soon, I consider it’s the worst part of the application regarding performance, and that’s interesting for me

Best,
Jonas Raoni

jonasraoni · March 2, 2024, 6:08pm

Hi @shantanusingh ! Out of curiosity, was the problem solved? If yes, I’ll close this topic

Best,
Jonas Raoni

shantanusingh · March 3, 2024, 1:57am

Hi @jonasraoni

I’m still on 3.4.0-4 and haven’t been able to upgrade due to some technical issue in office. Maybe in 2-3 days I will upgrade to 3.4.0-5.

Right now 3.4.0-4 hangs for 2 days and gets processed automatically with some deadlock after 2 days.

shantanusingh · March 3, 2024, 4:16am

Hi @jonasraoni I have just moved to latest version OJS-3.4.0-5. Let’s see what happens in the next 3-4 days. I will update you.

shantanusingh · March 3, 2024, 11:08am

Hi @jonasraoni I checked during the process that the log file (usage_events_20240302.log) got stuck in the dispatch folder and the below mentioned error occurred. This type of error occurred on 26 and 28 February.

PDOException: SQLSTATE[23000]: Integrity constraint violation: 1452 Cannot add or update a child row: a foreign key constraint fails (`ojs4`.`metrics_submission`, CONSTRAINT `metrics_submission_representation_id_foreign` FOREIGN KEY (`representation_id`) REFERENCES `publication_galleys` (`galley_id`) ON DELETE CASCADE) in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php:570
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(570): PDOStatement->execute()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(753): Illuminate\Database\Connection->Illuminate\Database\{closure}()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#4 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3340): Illuminate\Database\Connection->affectingStatement()
#5 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(164): Illuminate\Database\Query\Builder->insertUsing()
#6 /ojs/lib/pkp/jobs/statistics/CompileSubmissionMetrics.php(45): PKP\statistics\PKPTemporaryTotalsDAO->compileSubmissionMetrics()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\CompileSubmissionMetrics->handle()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#23 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#24 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#25 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#26 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#27 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#28 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#29 {main}

Next Illuminate\Database\QueryException: SQLSTATE[23000]: Integrity constraint violation: 1452 Cannot add or update a child row: a foreign key constraint fails (`ojs4`.`metrics_submission`, CONSTRAINT `metrics_submission_representation_id_foreign` FOREIGN KEY (`representation_id`) REFERENCES `publication_galleys` (`galley_id`) ON DELETE CASCADE) (SQL: insert into `metrics_submission` (`load_id`, `context_id`, `submission_id`, `representation_id`, `submission_file_id`, `file_type`, `assoc_type`, `date`, `metric`) select load_id, context_id, submission_id, representation_id, submission_file_id, file_type, assoc_type, DATE(date) as date, count(*) as metric from `usage_stats_total_temporary_records` where `load_id` = usage_events_20240302.log and `assoc_type` = 515 group by load_id, context_id, submission_id, representation_id, submission_file_id, file_type, assoc_type, DATE(date)) in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php:760
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3340): Illuminate\Database\Connection->affectingStatement()
#3 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(164): Illuminate\Database\Query\Builder->insertUsing()
#4 /ojs/lib/pkp/jobs/statistics/CompileSubmissionMetrics.php(45): PKP\statistics\PKPTemporaryTotalsDAO->compileSubmissionMetrics()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\CompileSubmissionMetrics->handle()
#6 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#23 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#24 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#25 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#26 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#27 {main}
[03-Mar-2024 15:35:19 Asia/Kolkata] #0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3340): Illuminate\Database\Connection->affectingStatement()
#3 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(164): Illuminate\Database\Query\Builder->insertUsing()
#4 /ojs/lib/pkp/jobs/statistics/CompileSubmissionMetrics.php(45): PKP\statistics\PKPTemporaryTotalsDAO->compileSubmissionMetrics()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\CompileSubmissionMetrics->handle()
#6 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#23 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#24 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#25 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#26 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#27 {main}

I have tried to reprocess the log file of 26th and 28th February, but the above mentioned error occurred and the log file got stuck in the dispatch folder.

If this type of error is reported then only the abstract view data is generated and the download data is not generated.

shantanusingh · March 5, 2024, 10:04am

Hi @jonasraoni Now I am facing below mentioned problem. The log (20240304) was not processed and was stuck in the dispatch folder.

Illuminate\Queue\MaxAttemptsExceededException: APP\jobs\statistics\ProcessUsageStatsLogFile has been attempted too many times or run too long. The job may have previously timed out. in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:746
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(505): Illuminate\Queue\Worker->maxAttemptsExceededException()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(415): Illuminate\Queue\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#4 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#5 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#6 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#7 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#8 {main}

#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(505): Illuminate\Queue\Worker->maxAttemptsExceededException()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(415): Illuminate\Queue\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#4 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#5 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#6 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#7 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#8 {main}

Update: But I have noticed that after 2-3 hours it will be processed automatically. Let’s see for a few days.

bozana · March 5, 2024, 7:15pm

Hi all, I am partially back again.
3.4.0-5 should solve the problems of concurrent running the SQLs.
I do not know why those foreign key errors occur in your case – the not existing IDs should not be inserted into the usage stats temporary tables.
Timeout at ProcessUsagetatsLogFile job means that a log file is huge, so that the processing can not be executed during a request. Maybe to run your jobs via a Cron job or worker – your installation is huge.
I think it is best for now not to re-run a failed job, till you get it all working. It is then best to remove the failed job and re-process that log file again. Also, always double check that your usage stats temporary tables are empty after a job has failed!!! If the data accumulates there, there will be a timeout again.

shantanusingh · March 6, 2024, 4:37am

Hi @jonasraoni @bozana

Today I checked and found a failed task log 20240304. 20240304 log file has already been processed and archived so I think this type of failed task will not appear.

PKP\job\exceptions\JobException: [0] in /ojs/lib/pkp/jobs/statistics/PKPProcessUsageStatsLogFile.php (63): The file /epubs_files/usageStats/dispatch/usage_events_20240304.log does not exist.

[06-Mar-2024 09:33:24 Asia/Kolkata] #0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\PKPProcessUsageStatsLogFile->handle()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#4 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#6 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#18 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#19 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#20 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#21 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#22 {main}

Update: I have checked the DB, maybe the failed_jobs is not cleared after the log file is completed.

bozana · March 8, 2024, 4:20pm

Hi @shantanusingh

Oh, very strange things happening there…

In 3.4.0.5 a log file is first moved to dispatch folder and a chain of jobs is dispatched. Chain of jobs means that the jobs are run one after another and if one job fails all fail. That means if a job for that one file failed, no other jobs and processing should happen. The last job in the chain, when all other were processed successfully, will then move the file to folder archive. So I do not understand how comes that the files has been processed although the job chain failed

shantanusingh · March 11, 2024, 4:13am

Hi, @bozana @jonasraoni After upgrading to OJS-3.4.0-5 now the statistics log process is working normally and no deadlock status is visible.

Sometimes a failed job gets ProcessUsageStatsLogFile has been attempted too many times or run too long. The job may have previously timed out ([OJS-3.4.0-4] Statistic problem - #91 by shantanusingh). The working time may have already ended. But that’s okay.

shantanusingh · March 13, 2024, 6:29am

This error occurs most of the time and the log file is stuck in the dispatch folder.

Illuminate\Queue\MaxAttemptsExceededException: APP\jobs\statistics\ProcessUsageStatsLogFile has been attempted too many times or run too long. The job may have previously timed out. in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:746
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(505): Illuminate\Queue\Worker->maxAttemptsExceededException()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(415): Illuminate\Queue\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#4 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#5 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#6 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#7 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#8 {main}

#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(505): Illuminate\Queue\Worker->maxAttemptsExceededException()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(415): Illuminate\Queue\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#4 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#5 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#6 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#7 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#8 {main}

#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\PKPProcessUsageStatsLogFile->handle()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#4 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#6 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#18 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#19 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#20 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#21 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#22 {main}

#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): PKP\jobs\statistics\PKPProcessUsageStatsLogFile->handle()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#4 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#6 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#18 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(106): Illuminate\Queue\Worker->runNextJob()
#19 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#20 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(135): PKP\queue\JobRunner->processJobs()
#21 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#22 {main}

bozana · March 14, 2024, 4:18am

Hi @shantanusingh

The job ProcessUsageStatsLogFile reads a log file and writes the entries to the usage stats temporary tables. It seems that for some reason this task takes too long. Maybe the log file is too big. (I could eventually see if it would make sense and be possible to split even this job into several jobs).
I suppose your jobs are run in a request and a job needs to finish within the request. Your installation is very big, so it would be good if you would use a Cron job or a Worker, as described here: https://docs.pkp.sfu.ca/admin-guide/en/deploy-jobs for jobs.

If the job ProcessUsageStatsLogFile has not completed successfully, all the other jobs that process the stats further are not executed and not finished successfully, and the log file stays in the folder dispatch.

So, could you please try to use Cron job or a Worker?

shantanusingh · March 21, 2024, 3:38pm

Still facing the issue and the log file is stuck in dispatch folder since two days.

Can you please guide to set up cron job?

jonasraoni · March 21, 2024, 4:27pm

Hi!

If you setup the task php tools/runScheduledTasks.php in the CRON, then it should be working already, but it’s not going to change your situation, the jobs will keep being processed at the end of the requests (I think we need an extra option in the config to control this).

What will change is using the supervisor (see https://docs.pkp.sfu.ca/admin-guide/en/deploy-jobs), which is the best option if you’re using a Linux server. It will keep an active process waiting for jobs.

After setting up the supervisor, you need to set the [queues].job_runner in the config.inc.php to Off, then the jobs will not be processed by the CRON and at the end of the requests.

Best,
Jonas Raoni

bozana · March 22, 2024, 10:17am

@jonasraoni, @touhidur

Is it so if we use Cron job as described here https://docs.pkp.sfu.ca/admin-guide/en/deploy-jobs#cron that the jobs are executed within a request? – I thought the Cron job is avoiding it… so that the timeout will not happen (that easily)

p.s. Actually, also for scheduled tasks I thought it is a way to execute long tasks independently from the request (differently to when AcronPlugin is used)…

EDIT: But, yes, I agree that it is even better to use the Worker https://docs.pkp.sfu.ca/admin-guide/en/deploy-jobs#workers.

@shantanusingh, I will also try to separate the ProcessUsageStatsLogFile further into smaller jobs, that will process e.g. 100 lines of the log file… but I am not sure when I will finish it… S. Separate ProcessUsageStatsLogFile into several smaller jobs · Issue #9822 · pkp/pkp-lib · GitHub.

jonasraoni · March 22, 2024, 10:55am

Yep, here’s the scheduled task that run jobs:

github.com

pkp/ojs/blob/afcf02932f0a1fe6aa740444872aea107f8ed922/registry/scheduledTasks.xml#L62-L65


      
          	<task class="PKP\task\ProcessQueueJobs">
          		<descr>Process pending queue jobs in the default queue driver and queue</descr>
          		<frequency second="0"/>
          	</task>

And here’s the code that run the jobs at the end of requests:

github.com

pkp/pkp-lib/blob/c6b863d46c11ead1b6a3b6d012aa1b476a4768b5/classes/core/PKPQueueProvider.php#L116-L117


      
          if (Config::getVar('queues', 'job_runner', true)) {
              register_shutdown_function(function () {

I’ve created this issue to improve the configuration: Improve job runner configuration/execution · Issue #9823 · pkp/pkp-lib · GitHub

Best,
Jonas Raoni