Statistics processing is stalled

[jonasraoni]

Describe the bug
The issue #9833, highlighted another issue (refer to the linked issue before reading the rest).

Problems:

1. The skipped log file is placed back to the staging folder, which means the system will attempt to process it again on the next run (infinite loop).
2. The presence of a single bad file affects the processing of other valid files, because of this condition:
   

   pkp-lib/classes/task/PKPUsageStatsLoader.php

   Lines 109 to 112 in 11e269d

   	$processFilesResult = parent::executeActions();
   	if (!$processFilesResult) {
   	return false;
   	}

If N log files are ok, those N files will be moved to the dispatch folder, and wait for a job to process them, but this never happens, due to the failing log file that makes the process quit.

Besides coming up with a fix, I think it's good to add extra log messages, this required some debugging.

What application are you using?
OJS 3.4

---

PRs:
stable-3_4_0:

• pkp/pkp-lib9834 allow further usage log file processing for successfu… #9844
• pkp/pkp-lib#9834 submodule update ##bozana/9834-3_4_0## ojs#4227 (only submodule update)
• pkp/pkp-lib#9834 submodule update ##bozana/9834-3_4_0## omp#1539 (only submodule update)
• pkp/pkp-lib#9834 submodule update ##bozana/9834-3_4_0## ops#652 (only submodule update)

main:

• pkp/pkp-lib9834 allow further usage log file processing for successfu… #9850

[jonasraoni]

Hi @bozana! Not sure if you're too busy, if yes, I might take a look at this issue and the linked one.

[bozana]

Hi @jonasraoni, yes, this is true.
I think there is no good solution for #1 in your list above. The admin will need to see the scheduled task logs to find out the reason and solve the problem. It seems that now the log file is in the stage folder only if it is in the wrong format or if the stats for that month already exist (and only when the daily stats are not kept in the DB, so that the admin needs to re-process the whole month).
Eventually we could move that file into reject folder 🤔 Or maybe into a new/different folder to be able to differentiate those files from the other once? Hmmm... I will think about it...
And for the #2, yes, I think we can move that if (!$processFilesResult) at the end of the function (s. https://github.com/pkp/pkp-lib/blob/main/classes/task/PKPUsageStatsLoader.php#L136), together with !$processingDirError...

[jonasraoni]

• #1: I think it's ok, it's not a big deal to process it again. But it was difficult to understand what was happening without debugging the code. I saw the code has a lot of log messages, but I think we need to add more, to the remaining "escape" conditions.
• #2: Ok! Besides the problem of the bad file blocking the processing of the others, I think it's needed to avoid the condition where a file is left on the dispatch folder without a related job, I guess it will never be processed, unless the admin sees the problem and moves it manually.

[bozana]

Hi @jonasraoni, I think it is difficult to solve it fully/correctly: either we first move the file to dispatch folder and then dispatch the jobs, or the other way around. If any of these two steps goes wrong there will be the same/similar situation.
When I fix the bug here -- to return false at the end -- this actually should not happen any more (or just in a really strange situation).

And generally, it is difficult to inform admins at the moment -- there are error logs and there are scheduled logs. If something goes wrong with a scheduled task, the admin is supposed to see the scheduled task logs. Else, if something goes wrong with any other part of the code the error logs help.
In the normal situation the scheduled task log file would contain something like this:

[2024-03-27 10:10:24] http://journal.domain
[2024-03-27 10:10:24] [Notice] Task process started.
[2024-03-27 10:10:24] [Notice] File /.../usageStats/processing/usage_events_20240325.log was moved to dispatch folder.
[2024-03-27 10:10:24] [Notice] File /.../usageStats/processing/usage_events_20240326.log was moved to dispatch folder.
[2024-03-27 10:10:24] [Notice] The background jobs that will process the log files and store the statistics data have been dispatched.
[2024-03-27 10:10:24] [Notice] Task process stopped.

In case the jobs were not dispatched, the message will be missing.
This is similar for all other kinds of failures during log file processing -- the file will stay as they are (reject, stage, dispatch folder) and admin needs to see what is happening.
Maybe once we have another solution for our logging it can be better i.e. easier for admin to see what is happening.
So I am afraid this will need to stay so at the moment. When editor sees that the file is not processed (stats = 0) or if admin sees that there are old log files there, admin will need to investigate.

[bozana]

@jonasraoni, could you please take a look at the PR linked in the issue description? If OK, I will add submodule updates and then cherry-pick it to main...