Logs in saved messages are duplicated

[matt-in-a-hat]

Logs now seem to get captured multiple times within a job's saved messages, if process is called more than once i.e. if there are more than 1 steps to run.

For example, a simple QueuedJob that has 3 steps and writes logs in each step:

public function setup () {
	$this->currentStep = 0;
	$this->totalSteps = 3;
	Injector::inst()->get(LoggerInterface::class)->info('JOB SETUP');
}

public function process() {
	Injector::inst()->get(LoggerInterface::class)->info("RUNNING PROCESS STEP {$this->currentStep})");
	sleep(1);
	$t = microtime(true);
	Injector::inst()->get(LoggerInterface::class)->info("DONE STEP {$this->currentStep} AT T: {$t}");
	$this->currentStep++;
	$this->isComplete = $this->currentStep >= $this->totalSteps;
}

This seems to log each step correctly (0-2), but then repeats logging step 1 and 2, then again repeats logging for step 2.

Output:

[2019-09-30 02:53:05][INFO] RUNNING PROCESS STEP 0)
[2019-09-30 02:53:05][INFO] DONE STEP 0 AT T: 1569811985.6635
[2019-09-30 02:53:05][INFO]
[2019-09-30 02:53:06][INFO] RUNNING PROCESS STEP 1)
[2019-09-30 02:53:06][INFO] DONE STEP 1 AT T: 1569811986.6986
[2019-09-30 02:53:06][INFO]
[2019-09-30 02:53:07][INFO] RUNNING PROCESS STEP 2)
[2019-09-30 02:53:07][INFO] DONE STEP 2 AT T: 1569811987.734
[2019-09-30 02:53:07][INFO]
[2019-09-30 02:53:07][INFO] RUNNING PROCESS STEP 1)
[2019-09-30 02:53:07][INFO] DONE STEP 1 AT T: 1569811986.6986
[2019-09-30 02:53:07][INFO] RUNNING PROCESS STEP 2)
[2019-09-30 02:53:07][INFO] DONE STEP 2 AT T: 1569811987.734
[2019-09-30 02:53:07][INFO] RUNNING PROCESS STEP 2)
[2019-09-30 02:53:07][INFO] DONE STEP 2 AT T: 1569811987.734

Not sure what the cause is, possibly related to the changes in flushing in #242 ?

An example repo with this simple test case can be found here.

Versions seen in:
symbiote/silverstripe-queuedjobs 4.4.0

[mfendeksilverstripe]

I couldn't reproduce this on 4.5 using DoormanRunner. Some feedback for you @matt-in-a-hat :

• try reproducing the issue on the symbiote/silverstripe-queuedjobs 4.5 latest
• add to your job some simple check to see how many times the process() function is actually called (this could be a simple error_log() call (I just want to confirm that this issue is related to logging and not job locking)
• which queue runner are you using to run your job? QueueRunner, DoormanRunner or some custom runner?

[matt-in-a-hat]

Must be related to the way it captures logs/output.
When I try it again on ^4.5 with both log and echo:

Injector::inst()->get(LoggerInterface::class)->error("(LOGGER) RUNNING PROCESS STEP {$this->currentStep})");
echo("(ECHO) RUNNING PROCESS STEP {$this->currentStep}");
sleep(1);
$t = microtime(true);
Injector::inst()->get(LoggerInterface::class)->error("(LOGGER) DONE STEP {$this->currentStep} AT T: {$t}");
echo ("(ECHO)DONE STEP {$this->currentStep} AT T: {$t}");

It seems that anything echo'd or logged gets captured in the QueuejobDescriptor messages straight away, but then some later time it also re-adds those messages captured by the logger (multiple times if process is called multiple times). See the latest example code.

[2020-06-15 21:49:30][ERROR] (LOGGER) RUNNING PROCESS STEP 0)
[2020-06-15 21:49:30][ERROR] (LOGGER) DONE STEP 0 AT T: 1592257770.6312
[2020-06-15 21:49:30][INFO] (ECHO) RUNNING PROCESS STEP 0(ECHO)DONE STEP 0 AT T: 1592257770.6312
[2020-06-15 21:49:31][ERROR] (LOGGER) RUNNING PROCESS STEP 1)
[2020-06-15 21:49:31][ERROR] (LOGGER) DONE STEP 1 AT T: 1592257771.6648
[2020-06-15 21:49:31][INFO] (ECHO) RUNNING PROCESS STEP 1(ECHO)DONE STEP 1 AT T: 1592257771.6648
[2020-06-15 21:49:32][ERROR] (LOGGER) RUNNING PROCESS STEP 2)
[2020-06-15 21:49:32][ERROR] (LOGGER) DONE STEP 2 AT T: 1592257772.7018
[2020-06-15 21:49:32][INFO] (ECHO) RUNNING PROCESS STEP 2(ECHO)DONE STEP 2 AT T: 1592257772.7018
[2020-06-15 21:49:32][ERROR] (LOGGER) RUNNING PROCESS STEP 1)
[2020-06-15 21:49:32][ERROR] (LOGGER) DONE STEP 1 AT T: 1592257771.6648
[2020-06-15 21:49:32][ERROR] (LOGGER) RUNNING PROCESS STEP 2)
[2020-06-15 21:49:32][ERROR] (LOGGER) DONE STEP 2 AT T: 1592257772.7018
[2020-06-15 21:49:32][ERROR] (LOGGER) RUNNING PROCESS STEP 2)
[2020-06-15 21:49:32][ERROR] (LOGGER) DONE STEP 2 AT T: 1592257772.7018

I tried both with default and doorman (assuming it would work on mac with the suggested config/as seen in the example?)

[mfendeksilverstripe]

Thanks for the new information. Echo and log are essentially the same in this case. I suggest to use the error_log() to bypass the whole logging system, so we can check the job execution separate from logging.

You can add this to your _config

ini_set("error_log", "/var/www/mysite/www/public/php-error.log");

and add this to your job:

error_log("(ECHO) RUNNING PROCESS STEP {$this->currentStep}")

Please post the output of php-error.log file here.

I also recommend running the test on latest 4 branch.

[matt-in-a-hat]

Output from your suggestion:

[15-Jun-2020 23:18:28 UTC] (error_log) RUNNING PROCESS STEP 0
[15-Jun-2020 23:18:29 UTC] (error_log) RUNNING PROCESS STEP 1
[15-Jun-2020 23:18:30 UTC] (error_log) RUNNING PROCESS STEP 2

So yeah it must be something to do with the (default?) configuration of how the LoggerInterface works, as it's only that which seems to have the issue of being captured multiple times.

[mfendeksilverstripe]

Right, the job execution looks fine, it's indeed some issue with logging. I recommend inspecting which loggers / handlers you have registered when executing the job. I also suggest to inspect job messages because some of the logs are stored in there.

[sb-relaxt-at]

I do encounter the same issue when using 4.6.0 (without Doorman).

[sb-relaxt-at]

I assume that the issue is due to the BufferHandler that wraps the QueuedJobHandler, this check is not working properly and adds a QueuedJobHandler per iteration.