FIX: Correctly log errors during job initialisation (fixes #316)

[kinglozzer]

The alternative to this is changing the the signature of handleBrokenJobException() to make the second param optional with = null, which is technically a BC-break. This method of instantiating a job object is exactly what initialiseJob does:

silverstripe-queuedjobs/src/Services/QueuedJobService.php

Lines 676 to 683 in 84fc3e2

	// create the job class
	$impl = $jobDescriptor->Implementation;
	/** @var QueuedJob $job */
	$job = Injector::inst()->create($impl);
	/* @var $job QueuedJob */
	if (!$job) {
	throw new Exception("Implementation $impl no longer exists");
	}

[GuySartorelli]

Are there some steps I can follow to ensure a job breaks during initialisation in order to test this?
And is this something we could write unit tests for?

This method of instantiating a job object is exactly what initialiseJob does

Maybe that should be extracted into its own method so we can reuse the same code? That way if the way we instantiate these changes, we can remain consistent.

[kinglozzer]

To recreate this you just need a job to throw an exception in its setup() method.

I don’t think this fix is complete after all because if the exception shown above (Implementation $impl no longer exists) is thrown then the exception still won’t be logged properly. I wonder if a better approach would be to wrap this in its own try/catch:

silverstripe-queuedjobs/src/Services/QueuedJobService.php

Line 832 in c370b27

$job = $this->initialiseJob($jobDescriptor);

That would allow us to handle the exception-during-initialisation flow differently, so no need to adjust method signatures and break BC

[kinglozzer]

Okay I’ve pushed an alternative solution

[GuySartorelli]

Looks good from a code perspective. Will try to make some time tomorrow to test it locally just to be sure it does catch those errors.

[GuySartorelli]

Gotta love when you see a comment from yourself a week later that says "tomorrow" on it.... sorry about that.

Looks good locally except:

Doesn't log the exception to the job's messages

This does catch and mark the exception and marks the job as broken which is a big improvement on the current state of things - but it doesn't add the exception information to the job's messages like exceptions later in the lifecycle do.

Looks like that's because addJobHandlersToLogger() isn't called until later, which expects a QueuedJob instance (which we obviously don't have at this stage) to pass to QueuedJobHandler.

I don't think QueuedJobHandler should explicitly require a QueuedJob instance (messages are stored on the QueuedJobDescriptor anyway which we do have) - but since it does, we can't just add that handler to the logger.

Next steps

I think we should create a new handler (to either be replaced by QueuedJobHandler or else to be used for this specific situation - preferable the former with QueuedJobHandler being deprecated) which doesn't require a QueuedJob instance.

I don't know if that should be done as part of this PR (it could be considered part of "correctly" logging errors) or as a follow-up. If it's a follow-up, then I'm happy with this PR as-is. It is at least an improvement on the current state of things.

[GuySartorelli]

@kinglozzer do you have any thoughts about whether logging the message should be done with or after thIs PR?

[kinglozzer]

I think it’d need to be done separately - we can’t switch out QueuedJobHandler for one that doesn’t require a QueuedJob instance without breaking BC (e.g. if someone is using Injector to inject their own handler that uses the QueuedJob object)

[GuySartorelli]

Works well locally. Doesn't log these errors in the message for the job, but that can be follow-up work as discussed.
At least it logs them correctly in the logger which is an improvement over the existing behaviour.

[GuySartorelli]

I have created #384 for the follow-up work of passing the error as a message into the job to be viewed in the CMS UI.

[GuySartorelli]

Tagged as 4.10.1