Is there such bug that statistics are processed but they show wrong number?

dvtech · June 18, 2026, 3:38pm

TL;DR

Is there such a bug that that article stats are displayed, log file in archive folder but number actually incorrect and nobody knows without investigation that it is incorrect? I mean when looking at thos stats:

[domain]/[journal]/en/stats/publications/publications

Or is claude wrong?

Describe the issue or problem
A usage statistics log file is processed and ends up in the archive/ folder, so it looks like it succeeded — but according to claude - the resulting statistics are incomplete (only
about one third of the expected numbers). There is no error and nothing in the failed_jobs table.

Our stats are processed on user/web requests (the server is FTP-only, no CLI, so we rely on the built-in job runner triggered by page hits). The files are large
daily usage logs (86–230 MB each) that were stuck in usageStats/dispatch/.

I added debug logging. Based on that logging, Claude (an AI assistant) analysed it and concluded the stored stats are missing data. Its explanation:

the big ProcessUsageStatsLogFile job takes ~35 minutes to read the whole file, but the queue retry_after is 610s and the job timeout is 600s. On the web (non-daemon)
runner the timeout is never enforced, so the job keeps running; but after 610s the next web request reclaims the same job as a second/third concurrent worker.
Each reclaimed worker runs deleteByLoadId() at the start, which deletes all temp rows for that load_id — including the rows the still-running original worker
already inserted. The original worker still reaches the end of the file, so the file is archived and the month recompiled, but from a temp table that the
concurrent deletes had emptied. So the file is marked done while ~2/3 of the data is gone.

I also saw the retries myself: in the jobs table the job id kept changing and attempts increased (nothing ever landing in failed_jobs), and the temp-table row
count for the file climbed (e.g. ~23,000) then dropped back to 0.

Claude:

For one journal on that day I expected ~1,281 investigations (485 abstract views + 796 file downloads, counted from the raw non-bot log lines) and ~796 requests;
the stored values were 367 / 213 — about a third.

Is this a bug, or expected behaviour for large log files on the built-in job runner? Should the job prevent concurrent processing of the same load_id, and should
a file be archived / the month recompiled only after a verified-complete pass rather than whenever a worker reaches the end of the file?

Some values from config.inc.php :
job_runner = On

job_runner_max_jobs = 2

job_runner_max_execution_time = 3000

; job_runner_max_memory = 800 (not set)

process_jobs_at_task_scheduler (not set)

default_queue = “queue”

delete_failed_jobs_after = 10

task_runner = On

task_runner_interval = 60

scheduled_tasks_report_error_only (not set)

Steps I took leading up to the issue

Moved one file back to usageStats/stage/ from dispatch
Let the built-in job runner process it via web requests
Watched the jobs table (job id changing, attempts rising, failed_jobs empty)
The file moved to archive/ and the chart showed data for that day.
Asked claude to generate a script which would tell how much I should expect. Also asked it to clean up for sharing here.
Asked claude to search if such bug is reported - it did not find.

What application are you using?
OJS 3.5.0.3

Additional information

Cleaned up stats prediction script:

https://pastebin.com/hA9iMH2r

rcgillis · June 19, 2026, 11:26am

@bozana - might you be able to speak to this?

-Roger
PKP Team

dvtech · June 21, 2026, 2:20pm

Investigaeted the log bit more:

xxx:~/duomenys/for_claude$ grep -E "ProcessUsageStatsLogFile (loop done|done|starting)|deleteByLoadId\(\) done" vu_debug.log 
2026-06-18 16:20:28 ProcessUsageStatsLogFile starting. loadId=usage_events_20260401.log memStartMB=30
2026-06-18 16:20:39 ProcessUsageStatsLogFile deleteByLoadId() done. loadId=usage_events_20260401.log elapsedSec=10.67
2026-06-18 16:30:56 ProcessUsageStatsLogFile starting. loadId=usage_events_20260401.log memStartMB=34
2026-06-18 16:30:58 ProcessUsageStatsLogFile deleteByLoadId() done. loadId=usage_events_20260401.log elapsedSec=1.96
2026-06-18 16:49:32 ProcessUsageStatsLogFile starting. loadId=usage_events_20260401.log memStartMB=34
2026-06-18 16:49:36 ProcessUsageStatsLogFile deleteByLoadId() done. loadId=usage_events_20260401.log elapsedSec=4.48
2026-06-18 16:55:20 ProcessUsageStatsLogFile loop done. loadId=usage_events_20260401.log totalLines=228462 inserted=102883 bots=125578 invalid=0 loopSec=2080.69
2026-06-18 16:55:20 ProcessUsageStatsLogFile done. loadId=usage_events_20260401.log elapsedSec=2091.36 memPeakMB=30

I have added logging (my own logger) in lib/pkp/jobs/statistics/PKPProcessUsageStatsLogFile.php

public function handle(): void
    {
        $vuStartTime = microtime(true);
        $vuMemStart = memory_get_usage(true);
        VULogger::log('ProcessUsageStatsLogFile starting. loadId=' . $this->loadId . ' memStartMB=' . round($vuMemStart / 1048576, 1));
        $filename = $this->loadId;
        $dispatchFilePath = StatisticsHelper::getUsageStatsDirPath() . '/' . FileLoader::FILE_LOADER_PATH_DISPATCH . '/' . $filename;
        if (!file_exists($dispatchFilePath)) {
            throw new JobException(__(
                'admin.job.processLogFile.fileNotFound',
                ['file' => $dispatchFilePath]
            ));
        }
        $vuFileSize = filesize($dispatchFilePath);
        VULogger::log('ProcessUsageStatsLogFile file located. loadId=' . $this->loadId . ' sizeKB=' . round($vuFileSize / 1024, 1));
        try {
            $this->process($dispatchFilePath);
        } catch (\Throwable $e) {
            $vuElapsed = microtime(true) - $vuStartTime;
            VULogger::log('ProcessUsageStatsLogFile THREW after ' . round($vuElapsed, 2) . 's. loadId=' . $this->loadId . ' memPeakMB=' . round(memory_get_peak_usage(true) / 1048576, 1) . ' msg=' . $e->getMessage());
            throw $e;
        }
        $vuElapsed = microtime(true) - $vuStartTime;
        VULogger::log('ProcessUsageStatsLogFile done. loadId=' . $this->loadId . ' elapsedSec=' . round($vuElapsed, 2) . ' memPeakMB=' . round(memory_get_peak_usage(true) / 1048576, 1));
    }




protected function process(string $dispatchFilePath): void
    {
        try {
            $splFileObject = new SplFileObject($dispatchFilePath, 'r');
        } catch (Exception $e) {
            // reject file -- move the file from dispatch to reject folder
            $filename = $this->loadId;
            $rejectFilePath = StatisticsHelper::getUsageStatsDirPath() . '/' . FileLoader::FILE_LOADER_PATH_REJECT . '/' . $filename;
            if (!rename($dispatchFilePath, $rejectFilePath)) {
                error_log(__('admin.job.compileMetrics.returnToStaging.error', ['file' => $filename, 'dispatchFilePath' => $dispatchFilePath, 'rejectFilePath' => $rejectFilePath]));
            }
            throw new JobException(__('admin.job.processLogFile.openFileFailed', ['file' => $dispatchFilePath]), 0, $e);
        }

        // Make sure we don't have any temporary records associated
        // with the current load ID in database.
        $vuDeleteStart = microtime(true);
        $this->deleteByLoadId();
        VULogger::log('ProcessUsageStatsLogFile deleteByLoadId() done. loadId=' . $this->loadId . ' elapsedSec=' . round(microtime(true) - $vuDeleteStart, 2));

        $vuLoopStart = microtime(true);
        $vuInsertedCount = 0;
        $vuSkippedBots = 0;
        $vuSkippedInvalid = 0;
        $lineNumber = 0;
        while (!$splFileObject->eof()) {
            $lineNumber++;
            $line = $splFileObject->fgets();
            if (empty($line) || substr($line, 0, 1) === '#') {
                continue;
            } // Spacing or comment lines. This actually should not occur in the new format.

            $entryData = json_decode($line);
            if ($entryData === null) {
                // This line is not in the right format.
                $vuSkippedInvalid++;
                $message = __(
                    'admin.job.processLogFile.wrongLoglineFormat',
                    ['file' => $this->loadId, 'lineNumber' => $lineNumber]
                );
                error_log($message);
                continue;
            }

            try {
                $this->validateLogEntry($entryData);
            } catch (Exception $e) {
                $vuSkippedInvalid++;
                $message = __(
                    'admin.job.processLogFile.invalidLogEntry',
                    ['file' => $this->loadId, 'lineNumber' => $lineNumber, 'error' => $e->getMessage()]
                );
                error_log($message);
                continue;
            }

            // Avoid bots.
            if (Core::isUserAgentBot($entryData->userAgent)) {
                $vuSkippedBots++;
                continue;
            }

            $this->insertTemporaryUsageStatsData($entryData, $lineNumber);
            $vuInsertedCount++;

            // Periodic progress so we can see how far we got if the PHP process gets killed mid-job.
            if ($lineNumber % 5000 === 0) {
                VULogger::log('ProcessUsageStatsLogFile progress. loadId=' . $this->loadId . ' lines=' . $lineNumber . ' inserted=' . $vuInsertedCount . ' bots=' . $vuSkippedBots . ' invalid=' . $vuSkippedInvalid . ' loopSec=' . round(microtime(true) - $vuLoopStart, 2) . ' memMB=' . round(memory_get_usage(true) / 1048576, 1));
            }
        }
        VULogger::log('ProcessUsageStatsLogFile loop done. loadId=' . $this->loadId . ' totalLines=' . $lineNumber . ' inserted=' . $vuInsertedCount . ' bots=' . $vuSkippedBots . ' invalid=' . $vuSkippedInvalid . ' loopSec=' . round(microtime(true) - $vuLoopStart, 2));
        //explicitly assign null, so that the file can be deleted
        $splFileObject = null;
    }

So from the log it looks like while one process has not finished yet, after 10 minutes anotehr process starts same job when retrying and does everything from scratch without checking that the first job has not finished yet.

There is only one line in log “ProcessUsageStatsLogFile done”. Probably its the first job finished but with with part of deleted data it was working because other jobs where deleting in between. Right?

dvtech · June 22, 2026, 4:12pm

Tried reproducing same thing with cron jobs.

In lib/pkp/classes/core/PKPContainer.php - Set queues.retry_after = 60 (only to shorten the window).
Queue one real large daily file, e.g 140 MB. I queued 2 files because as claude said need multiple jobs or smth like that so this problem would be reproducable. But 2 files did not create 2 jobs, they were in one job record.
Added a handful of unrelated filler jobs to the queue (so a second consumer has something to pop and thus reaches pop()).

For that part as claude generated me dummy jobs slow running jobs. As I understand should work with any other unrelated job like emails or whatever jobs OJS have. Just slow ones.

<?php

/**
 * @file tools/vuDispatchDummies.php
 *
 * VU THROWAWAY TEST TOOL — delete after the reclaim/overlap reproduction 
 *
 * Dispatches N slow VuGateOpenerJob jobs onto the default queue so a second jobs.php run
 * worker has something to chew on (keeping the gate open) long enough to reclaim a
 * still-running, reservation-expired ProcessUsageStatsLogFile job.
 *
 * Usage (local Docker only):
 *   docker compose exec php php tools/vuDispatchDummies.php [count] [sleepSeconds]
 *   e.g. ... tools/vuDispatchDummies.php 15 12   -> 15 jobs, each sleeping 12s
 *
 * Not for commit.
 */

require_once dirname(__FILE__) . '/bootstrap.php';

use APP\jobs\VuGateOpenerJob;
use PKP\cliTool\CommandLineTool;

class vuDispatchDummies extends CommandLineTool
{
    public int $count = 15;
    public int $sleepSeconds = 12;

    public function execute()
    {
        for ($i = 0; $i < $this->count; $i++) {
            VuGateOpenerJob::dispatch($this->sleepSeconds);
        }
        fwrite(STDOUT, "Dispatched {$this->count} VuGateOpenerJob, each sleeping {$this->sleepSeconds}s.\n");
    }
}

$tool = new vuDispatchDummies([$argv[0] ?? 'vuDispatchDummies.php']);
$tool->count = (int) ($argv[1] ?? 15);
$tool->sleepSeconds = (int) ($argv[2] ?? 12);
$tool->execute();

classes/jobs/VuGateOpenerJob.php

<?php

/**
 * @file classes/jobs/VuGateOpenerJob.php
 *
 * VU THROWAWAY TEST JOB — delete after the reclaim/overlap reproduction 
 *
 * A deliberately slow no-op job whose only purpose is to keep the queue "gate" non-empty:
 * while one worker is busy with a long ProcessUsageStatsLogFile job, a second worker needs
 * SOME available job to walk past the gate (jobs.php run's count() check) and reach pop().
 * Once the long job's reservation expires (retry_after), that pop() reclaims it -> overlap.
 *
 * Not for commit.
 */

namespace APP\jobs;

use APP\vu\VULogger;
use PKP\jobs\BaseJob;

class VuGateOpenerJob extends BaseJob
{
    public function __construct(private int $sleepSeconds = 12)
    {
        parent::__construct();
    }

    public function handle(): void
    {
        VULogger::log('VuGateOpenerJob start sleep=' . $this->sleepSeconds . 's pid=' . getmypid());
        sleep($this->sleepSeconds);
        VULogger::log('VuGateOpenerJob done pid=' . getmypid());
    }
}

dispatch those dummy jobs (writes into jobs table):

docker compose exec php php tools/vuDispatchDummies.php 15 12

Ran two concurrent php lib/pkp/tools/jobs.php run processes — simulating two overlapping cron invocations / two concurrent web requests. In 2 terminal tabs ran those:

while true; do docker compose exec php php lib/pkp/tools/jobs.php run; echo "--- T1 retry $(date +%T) ---"; sleep 5; done

Its every 5 seconds I know its not a production thing, there was in doc for 30 seconds written I guess to set cron but still to have better chance of simulation of corruption, cause logic is the same I think.

Now logs show that both are inserting (claude generated)

Observed (pid / attempt fields below are our own instrumentation, not stock):

17:45:03 ProcessUsageStatsLogFile starting … pid=1184 attempt=1
17:45:08 ProcessUsageStatsLogFile deleteByLoadId() done pid=1184 attempt=1
… 1184 inserting …
17:46:05 ProcessUsageStatsLogFile starting … pid=1191 attempt=2 ← reclaim, ~60s (=retry_after) later
17:46:06 ProcessUsageStatsLogFile deleteByLoadId() done pid=1191 attempt=2 ← wipes 1184’s rows
… 1184 AND 1191 both inserting the same load_id concurrently for ~4.5 min …
17:50:40 ProcessUsageStatsLogFile loop done pid=1184 attempt=1
17:51:51 ProcessUsageStatsLogFile loop done pid=1191 attempt=2

And here are the logs of actual command executed:

grep -E '1191|1184' vu_debug.log  
2026-06-22 17:45:03 ProcessUsageStatsLogFile starting. loadId=usage_events_20260406.log memStartMB=8 pid=1184 attempt=1
2026-06-22 17:45:03 ProcessUsageStatsLogFile file located. loadId=usage_events_20260406.log sizeKB=142903.1 pid=1184 attempt=1
2026-06-22 17:45:05 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:45:08 ProcessUsageStatsLogFile deleteByLoadId() done. loadId=usage_events_20260406.log elapsedSec=5.29 pid=1184 attempt=1
2026-06-22 17:45:17 VuGateOpenerJob done pid=1191
2026-06-22 17:45:17 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:45:29 VuGateOpenerJob done pid=1191
2026-06-22 17:45:29 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:45:34 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=20000 inserted=6865 bots=13135 invalid=0 loopSec=25.91 memMB=10 pid=1184 attempt=1
2026-06-22 17:45:41 VuGateOpenerJob done pid=1191
2026-06-22 17:45:41 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:45:43 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=25000 inserted=9227 bots=15773 invalid=0 loopSec=34.9 memMB=10 pid=1184 attempt=1
2026-06-22 17:45:53 VuGateOpenerJob done pid=1191
2026-06-22 17:45:53 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:46:05 VuGateOpenerJob done pid=1191
2026-06-22 17:46:05 ProcessUsageStatsLogFile starting. loadId=usage_events_20260406.log memStartMB=8 pid=1191 attempt=2
2026-06-22 17:46:05 ProcessUsageStatsLogFile file located. loadId=usage_events_20260406.log sizeKB=142903.1 pid=1191 attempt=2
2026-06-22 17:46:06 ProcessUsageStatsLogFile deleteByLoadId() done. loadId=usage_events_20260406.log elapsedSec=0.62 pid=1191 attempt=2
2026-06-22 17:46:19 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=55000 inserted=19423 bots=35577 invalid=0 loopSec=70.96 memMB=10 pid=1184 attempt=1
2026-06-22 17:46:24 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=60000 inserted=20809 bots=39191 invalid=0 loopSec=75.83 memMB=10 pid=1184 attempt=1
2026-06-22 17:46:29 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=65000 inserted=22199 bots=42801 invalid=0 loopSec=80.56 memMB=10 pid=1184 attempt=1
2026-06-22 17:46:31 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=20000 inserted=6865 bots=13135 invalid=0 loopSec=25.63 memMB=10 pid=1191 attempt=2
2026-06-22 17:46:40 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=25000 inserted=9227 bots=15773 invalid=0 loopSec=34.38 memMB=10 pid=1191 attempt=2
2026-06-22 17:46:45 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=80000 inserted=26771 bots=53229 invalid=0 loopSec=96.67 memMB=10 pid=1184 attempt=1
2026-06-22 17:46:57 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=90000 inserted=30206 bots=59794 invalid=0 loopSec=108.79 memMB=10 pid=1184 attempt=1
2026-06-22 17:47:15 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=55000 inserted=19423 bots=35577 invalid=0 loopSec=69.3 memMB=10 pid=1191 attempt=2
2026-06-22 17:47:20 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=60000 inserted=20809 bots=39191 invalid=0 loopSec=73.94 memMB=10 pid=1191 attempt=2
2026-06-22 17:47:24 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=65000 inserted=22199 bots=42801 invalid=0 loopSec=78.5 memMB=10 pid=1191 attempt=2
2026-06-22 17:47:34 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=120000 inserted=40473 bots=79527 invalid=0 loopSec=145.68 memMB=10 pid=1184 attempt=1
2026-06-22 17:47:40 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=80000 inserted=26771 bots=53229 invalid=0 loopSec=94.18 memMB=10 pid=1191 attempt=2
2026-06-22 17:47:40 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=125000 inserted=42121 bots=82879 invalid=0 loopSec=151.69 memMB=10 pid=1184 attempt=1
2026-06-22 17:47:52 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=90000 inserted=30206 bots=59794 invalid=0 loopSec=106.54 memMB=10 pid=1191 attempt=2
2026-06-22 17:48:29 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=120000 inserted=40473 bots=79527 invalid=0 loopSec=143.29 memMB=10 pid=1191 attempt=2
2026-06-22 17:48:35 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=125000 inserted=42121 bots=82879 invalid=0 loopSec=149.28 memMB=10 pid=1191 attempt=2
2026-06-22 17:49:03 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=205000 inserted=66826 bots=138174 invalid=0 loopSec=234.75 memMB=10 pid=1184 attempt=1
2026-06-22 17:49:09 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=210000 inserted=68409 bots=141591 invalid=0 loopSec=240.27 memMB=10 pid=1184 attempt=1
2026-06-22 17:49:16 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=215000 inserted=70370 bots=144630 invalid=0 loopSec=247.55 memMB=10 pid=1184 attempt=1
2026-06-22 17:49:24 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=220000 inserted=72498 bots=147502 invalid=0 loopSec=255.26 memMB=10 pid=1184 attempt=1
2026-06-22 17:49:48 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=235000 inserted=79040 bots=155960 invalid=0 loopSec=279.23 memMB=10 pid=1184 attempt=1
2026-06-22 17:49:56 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=240000 inserted=81210 bots=158790 invalid=0 loopSec=287.03 memMB=10 pid=1184 attempt=1
2026-06-22 17:50:05 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=205000 inserted=66826 bots=138174 invalid=0 loopSec=239.6 memMB=10 pid=1191 attempt=2
2026-06-22 17:50:12 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=210000 inserted=68409 bots=141591 invalid=0 loopSec=245.87 memMB=10 pid=1191 attempt=2
2026-06-22 17:50:18 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=215000 inserted=70370 bots=144630 invalid=0 loopSec=252.46 memMB=10 pid=1191 attempt=2
2026-06-22 17:50:25 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=220000 inserted=72498 bots=147502 invalid=0 loopSec=259.3 memMB=10 pid=1191 attempt=2
2026-06-22 17:50:40 ProcessUsageStatsLogFile loop done. loadId=usage_events_20260406.log totalLines=261409 inserted=89711 bots=171697 invalid=0 loopSec=331.93 pid=1184 attempt=1
2026-06-22 17:50:40 ProcessUsageStatsLogFile done. loadId=usage_events_20260406.log elapsedSec=337.23 memPeakMB=10 pid=1184 attempt=1
2026-06-22 17:50:40 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:50:52 VuGateOpenerJob done pid=1184
2026-06-22 17:50:52 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:50:56 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=235000 inserted=79040 bots=155960 invalid=0 loopSec=289.93 memMB=10 pid=1191 attempt=2
2026-06-22 17:51:04 VuGateOpenerJob done pid=1184
2026-06-22 17:51:04 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:51:10 ProcessUsageStatsLogFile progress. loadId=usage_events_20260406.log lines=240000 inserted=81210 bots=158790 invalid=0 loopSec=304.36 memMB=10 pid=1191 attempt=2
2026-06-22 17:51:16 VuGateOpenerJob done pid=1184
2026-06-22 17:51:16 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:51:28 VuGateOpenerJob done pid=1184
2026-06-22 17:51:28 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:51:40 VuGateOpenerJob done pid=1184
2026-06-22 17:51:40 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:51:51 ProcessUsageStatsLogFile loop done. loadId=usage_events_20260406.log totalLines=261409 inserted=89711 bots=171697 invalid=0 loopSec=345.25 pid=1191 attempt=2
2026-06-22 17:51:51 ProcessUsageStatsLogFile done. loadId=usage_events_20260406.log elapsedSec=345.88 memPeakMB=10 pid=1191 attempt=2
2026-06-22 17:51:51 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:51:52 VuGateOpenerJob done pid=1184
2026-06-22 17:51:52 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:52:03 VuGateOpenerJob done pid=1191
2026-06-22 17:52:03 VuGateOpenerJob start sleep=12s pid=1191
2026-06-22 17:52:04 VuGateOpenerJob done pid=1184
2026-06-22 17:52:05 VuGateOpenerJob start sleep=12s pid=1184
2026-06-22 17:52:15 VuGateOpenerJob done pid=1191
2026-06-22 17:52:17 VuGateOpenerJob done pid=1184

Btw class is updated to include pid lib/pkp/jobs/statistics/PKPProcessUsageStatsLogFile.php:

public function handle(): void
    {
        $vuStartTime = microtime(true);
        $vuMemStart = memory_get_usage(true);
        // VU: per-instance tag so concurrent runs of the SAME job/file are distinguishable in the log.
        // pid = OS process (each concurrent web-runner worker is its own process); attempt = queue attempt
        // number (1 = first pop, 2 = first reclaim, 3 = second reclaim, ...). Grep one pid= to follow an
        // instance start->done; the order of 'done' lines + attempt= tells which finished 1st/2nd/3rd.
        $vuTag = ' pid=' . getmypid() . ' attempt=' . $this->attempts();
        VULogger::log('ProcessUsageStatsLogFile starting. loadId=' . $this->loadId . ' memStartMB=' . round($vuMemStart / 1048576, 1) . $vuTag);
        $filename = $this->loadId;
        $dispatchFilePath = StatisticsHelper::getUsageStatsDirPath() . '/' . FileLoader::FILE_LOADER_PATH_DISPATCH . '/' . $filename;
        if (!file_exists($dispatchFilePath)) {
            throw new JobException(__(
                'admin.job.processLogFile.fileNotFound',
                ['file' => $dispatchFilePath]
            ));
        }
        $vuFileSize = filesize($dispatchFilePath);
        VULogger::log('ProcessUsageStatsLogFile file located. loadId=' . $this->loadId . ' sizeKB=' . round($vuFileSize / 1024, 1) . $vuTag);
        try {
            $this->process($dispatchFilePath);
        } catch (\Throwable $e) {
            $vuElapsed = microtime(true) - $vuStartTime;
            VULogger::log('ProcessUsageStatsLogFile THREW after ' . round($vuElapsed, 2) . 's. loadId=' . $this->loadId . ' memPeakMB=' . round(memory_get_peak_usage(true) / 1048576, 1) . ' msg=' . $e->getMessage() . $vuTag);
            throw $e;
        }
        $vuElapsed = microtime(true) - $vuStartTime;
        VULogger::log('ProcessUsageStatsLogFile done. loadId=' . $this->loadId . ' elapsedSec=' . round($vuElapsed, 2) . ' memPeakMB=' . round(memory_get_peak_usage(true) / 1048576, 1) . $vuTag);
    }

protected function process(string $dispatchFilePath): void
    {
        $vuTag = ' pid=' . getmypid() . ' attempt=' . $this->attempts(); // VU: per-instance tag (see handle())
        try {
            $splFileObject = new SplFileObject($dispatchFilePath, 'r');
        } catch (Exception $e) {
            // reject file -- move the file from dispatch to reject folder
            $filename = $this->loadId;
            $rejectFilePath = StatisticsHelper::getUsageStatsDirPath() . '/' . FileLoader::FILE_LOADER_PATH_REJECT . '/' . $filename;
            if (!rename($dispatchFilePath, $rejectFilePath)) {
                error_log(__('admin.job.compileMetrics.returnToStaging.error', ['file' => $filename, 'dispatchFilePath' => $dispatchFilePath, 'rejectFilePath' => $rejectFilePath]));
            }
            throw new JobException(__('admin.job.processLogFile.openFileFailed', ['file' => $dispatchFilePath]), 0, $e);
        }

        // Make sure we don't have any temporary records associated
        // with the current load ID in database.
        $vuDeleteStart = microtime(true);
        $this->deleteByLoadId();
        VULogger::log('ProcessUsageStatsLogFile deleteByLoadId() done. loadId=' . $this->loadId . ' elapsedSec=' . round(microtime(true) - $vuDeleteStart, 2) . $vuTag);

        $vuLoopStart = microtime(true);
        $vuInsertedCount = 0;
        $vuSkippedBots = 0;
        $vuSkippedInvalid = 0;
        $lineNumber = 0;
        while (!$splFileObject->eof()) {
            $lineNumber++;
            $line = $splFileObject->fgets();
            if (empty($line) || substr($line, 0, 1) === '#') {
                continue;
            } // Spacing or comment lines. This actually should not occur in the new format.

            $entryData = json_decode($line);
            if ($entryData === null) {
                // This line is not in the right format.
                $vuSkippedInvalid++;
                $message = __(
                    'admin.job.processLogFile.wrongLoglineFormat',
                    ['file' => $this->loadId, 'lineNumber' => $lineNumber]
                );
                error_log($message);
                continue;
            }

            try {
                $this->validateLogEntry($entryData);
            } catch (Exception $e) {
                $vuSkippedInvalid++;
                $message = __(
                    'admin.job.processLogFile.invalidLogEntry',
                    ['file' => $this->loadId, 'lineNumber' => $lineNumber, 'error' => $e->getMessage()]
                );
                error_log($message);
                continue;
            }

            // Avoid bots.
            if (Core::isUserAgentBot($entryData->userAgent)) {
                $vuSkippedBots++;
                continue;
            }

            $this->insertTemporaryUsageStatsData($entryData, $lineNumber);
            $vuInsertedCount++;

            // Periodic progress so we can see how far we got if the PHP process gets killed mid-job.
            if ($lineNumber % 5000 === 0) {
                VULogger::log('ProcessUsageStatsLogFile progress. loadId=' . $this->loadId . ' lines=' . $lineNumber . ' inserted=' . $vuInsertedCount . ' bots=' . $vuSkippedBots . ' invalid=' . $vuSkippedInvalid . ' loopSec=' . round(microtime(true) - $vuLoopStart, 2) . ' memMB=' . round(memory_get_usage(true) / 1048576, 1) . $vuTag);
            }
        }
        VULogger::log('ProcessUsageStatsLogFile loop done. loadId=' . $this->loadId . ' totalLines=' . $lineNumber . ' inserted=' . $vuInsertedCount . ' bots=' . $vuSkippedBots . ' invalid=' . $vuSkippedInvalid . ' loopSec=' . round(microtime(true) - $vuLoopStart, 2) . $vuTag);
        //explicitly assign null, so that the file can be deleted
        $splFileObject = null;
    }

Is this known issue with cron also and cannot be trusted if job time exceeds retry_after?

dvtech · June 23, 2026, 6:46am

But really I was thinking - if on production where its job_runner, no cron is running for the day it shows 154, while locally when I got prod db dump and ran same production log with cron, which was processed in 7.5 minutes, so no overlap of processes, it shows for same day 476, it looks like no cron case is buggy - kind of simpler evidence looks like, right?