Add job error logging

[shoosah]

Use a job error logger which logs all of the issues inside job messages. If job execution fails and triggers errors, all relevant information will be present in the job messages which makes the debugging process for developer that much easier.

• Add Logger class
• Add unit test for Logger class
• Update README document

Notes

Split from Feature batch as Feature 8 - Job error logging

[mfendeksilverstripe]

I think this example should be changed to reflect a more common situation where the logging is attached within the job execution. i.e. within the process() function of the job

[shoosah]

You mean something like this?

$logger = new Logger();
$logger->setJob($job);

$helper = Helper::create();
$helper->setLogger($logger)
            ->run();

[mfendeksilverstripe]

Something like this:

// within your job class

public function process(): void
{
    $logger = new Logger();
    $logger->setJob($this);

    Helper::create()
        ->setLogger($logger)
        ->run();
}

[chillu]

Given that Helper isn't defined, I still think this is quite confusing. Regardless, I'm not sure why there's a need to mix in the concept of a "helper class" with the creation of a logger, seems like unnecessary noise? It's pretty clear how a logger can be used (incl. passing it to other hypothetical dependencies) once it's created.

[chillu]

How does this relate to the logging that's already in place there? I think this might have gotten introduced after you forked off this repo? We did this in context of the "file migration task" work for 4.4.0. https://github.com/symbiote/silverstripe-queuedjobs/blob/4/src/Services/QueuedJobService.php#L875

Also, I'm improving this implementation with this PR: #310

[mfendeksilverstripe]

@chillu I think the difference is that the logger in place is for the queue runner and the logger which this PR is adding is for job execution only. This covers the case where job execution is covered by a helper and is more complex. We used this in the SS3 to SS4 migration.

[mfendeksilverstripe]

Looks good, thanks @shoosah :)

[chillu]

I don't believe a logger which handles messages directly is in keeping with the monolog library we're using. This should be deferred to handler implementations, which can then be centrally configured through monolog to only apply to certain error levels.

From what I can tell, this will also cause duplicate addMessage() calls when those "jobs with loggers" are executed through QueuedJobService, which is pretty much always the case.

And finally, I don't believe it should be up to the individual job to decide how its messages are logged, that belongs in the parent execution context (QueuedJobService, or even whatever instruments that service, e.g. ProcessJobQueueTask). A job should only use a logger, and indicate the level of the message.

So please have a read through QueuedJobService and my PR at #310. I don't believe this PR is required, or the right approach, sorry.

[mfendeksilverstripe]

Thanks for feedback, will have a look at your PR :)

[mfendeksilverstripe]

@shoosah

• The goal remains to capture any logger calls from within the execution process() method as we can't filter by level
• move the log to job messages functionality from the new logger to a new Handler (JobMessageHandler)
• add two new extension points to the QueuedJobService::runJob(): onBeforeJobProcess and onAfterJobProcess, both will be passing $job (job instance)
• update readme docs about using the new Handler: the handler should be injected into to logger of queued jobs service before the process() call and popped out after the process() call
• we should consider using this PR as a dependency as it allows you to set the logger for queued job service, the idea is to temporary override logging for the process() call
• we should have a huddle regarding this as there are multiple options on how to implement this

@chillu

Feedback for your points:

• agree on using Handler instead of Logger for this
• disagree on the duplicated message as we ran tens of thousands of jobs with this code and we haven't detected any message duplication, note that this solution separates job process() level logging and queued job service level logging
• agree on the the Handler injection point - it shouldn't be on the individual job but rather in the queued job service where process() method is called
• disagree on this PR not being required as your PR doesn't solve the problem, it makes the implementation of this solution easier though
• just reiterating the goal: I as a developer want to have full job execution log available on a job instance which covers ALL levels of log messages but only those which are coming from within the process() method so I can easily debug job execution problems without reading all the noise that is coming from the queued job service

[chillu]

The goal remains to capture any logger calls from within the execution process() method as we can't filter by level

QueuedJobService->runJob() calls Job->process(). The service has the logger dependency which takes care of logging to stdout, the database record, as well as any custom logging such as Raygun. You can adjust the logging levels through dependency injection. What you can't do is adjust them per job. If that's what you're aiming at, I would suggest that you pass down the existing logger into suitable jobs rather than applying some kind of parallel logging.

interface UsesLogger
{
  public function setLogger(LoggerInterface $logger);
  public function getLogger() : LoggerInterface;
}

class MyJob extends Job implements UsesLogger
{
  public function setLogger(LoggerInterface $logger)
  {
    $this->logger = $logger;
  }
  public function process()
  {
    $this->logger->setLevel(<new-level>);
    $this->logger->debug('...');
    $this->logger->setLevel(<old-level>);
  }
}

class QueuedJobService 
{
  public function runJob()
  {
    // ...
   if ($job instanceof UsesLogger) {
    $job->setLogger($logger);
  }
}

move the log to job messages functionality from the new logger to a new Handler (JobMessageHandler)

How is this not duplicating QueuedJobService->addJobHandlersToLogger() which adds QueuedJobHandler through my PR?

disagree on the duplicated message

Would this still hold once my PR gets merged? It fixes an inconsistency where it calls $logger->error() rather than $job->addMessage()?

just reiterating the goal: I as a developer want to have full job execution log available on a job instance which covers ALL levels of log messages but only those which are coming from within the process() method so I can easily debug job execution problems without reading all the noise that is coming from the queued job service

Thanks for spelling that out, easy to lose the forest for the trees in these discussions. It feels like my suggestion above achieves this, you could log everything debug level in your particular job, and then only look at the messages tagged with that level in the log channels (so either the database record, stdout, Raygun, etc)

[mfendeksilverstripe]

Thanks @chillu , will pick this is up next hackday but it looks like we're on the same page 👍

[Cheddam]

@shoosah @mfendeksilverstripe This pull request hasn't had any activity for a while. Are you going to be doing further work on it, or would you prefer to close it now?

[mfendeksilverstripe]

@Cheddam I believe that this PR is still useful as the error logging for jobs can be really resource heavy for larger sites. I'll add this to my TODO list as this is definitely something I would like to pick up eventually.