Follow-up to #2716073: Improve cron logging ; D7 back port.
Problem/Motivation
Cron execution is tricky in Drupal, as it can fail for multiple reasons:
- One particular
hook_cron()
requires too long, so its stuck somewhere - One particular function() fatals
The first step is always to figure out, which hook_cron() implementation is the problematic one, which can be hard in the first described case,
and not easy when your logs don't show backtraces in the second case.
Proposed resolution
Add logging before each cron queue or hook implementation starts and again afterwards.
Remaining tasks
Test coverage.
User interface changes
Messages will be available in watchdog logs, e.g. Database Logging, that track when each cron queue and hook implementation starts and ends.
API changes
n/a
Data model changes
n/a
Issue fork drupal-2722453
Show commands
Start within a Git clone of the project using the version control instructions.
Or, if you do not have SSH keys set up on git.drupalcode.org:
Comments
Comment #2
moonray CreditAttribution: moonray at Chapter Three commentedD7 doesn't seem to have tests that need tweaking, unlike d8.
Comment #4
moonray CreditAttribution: moonray at Chapter Three commentedLooks like I was wrong. So now with tests.
Comment #5
DamienMcKennaRerolled for line offsets.
Comment #6
DamienMcKennaFYI in #2560361: Add more detailed watchdog messages during cron runs marbard had worked on similar functionality and should be given credit on this issue.
Comment #7
DamienMcKennaThe original patch had the wrong argument to one of the watchdog() calls.
Comment #8
DamienMcKennaI think it would be beneficial to have clean separations of when one queue starts vs another ends, rather than combining the two messages in one.
Comment #9
DamienMcKennaAn alternative - log a message before the task starts, log another after it ends, don't bother tracking the previous task as it's now unnecessary.
Comment #10
DamienMcKennaFixed a bug in #9 - wrong variable name.
Comment #11
DamienMcKennaComment #13
DamienMcKennaAll of the tests except for one passed in #10, and I don't think the test failure had anything to do with this change as it had this error:
Comment #15
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedThanks for working on this @DamienMcKenna!
Yes, there are some intermittent/random errors in D7 tests (those table xx not found errors), which appears from time to time. I have re-run the tests and it seems like that there is also one standard failure regarding the patch #10.
Comment #16
DamienMcKennaThanks for rerunning the tests. This should fix the failing test.
Comment #17
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedI have tested the patch and it seems like it is working correctly (see the attached image), thanks!
As this change would cause a fair amount of new watchdog entries to be logged on each cron run, I am thinking if we should consider adding a possibility to opt-out of this behavior (via a new variable)?
There are two small issues in the patch - unused variables:
I have also added this issue to the list of potential candidates for the next release.
Comment #18
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedSeems like I have missed a thing in this patch. I have done a second review and compared the code with the current D10 HEAD (https://git.drupalcode.org/project/drupal/-/blob/11.x/core/lib/Drupal/Co...). It looks to me, that the first part of logging is wrong, as it is logging the process of queue initialization, not the actual processing of queue items. See:
According to the comments and functions called, this part of the
drupal_cron_run()
is only initializating queues. The processing of queue items is happening later, here:Therefore I think we should remove the logging from the first part and keep it only around
module_invoke($module, 'cron');
(the second part, which looks correct to me and which is also in D10). We should also remove two unused variables and add the opt-out possibility (see #17).We can probably add logging to queues processing either, but D10 code does not have it, so it is questionable (there is probably a reason for this and I would create a follow-up issue for this if needed).
Need to say, that the D7 cron is a bit different from D10 cron in terms of processing. D7 cron is first processing all implementations of
hook_cron
and only after this is done (and cron lock released), the queues are processed independently:(https://api.drupal.org/api/drupal/modules%21system%21system.api.php/func...)
D10 cron is doing the processing together when the cron lock is still active. It was changed by this issue: #1875020: Cron queue gets processed every time cron is called, regardless of whether it's already being processed elsewhere
It is also worth considering whether we should backport this D10 change of processing queues in cron...
Comment #19
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedComment #20
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedUploading a patch with these changes:
I am open to suggestions if we should add the logging to queues as well (correctly), even if it is not in D10. But personally prefer to do it via a separate issue, which should be opened for D10 as well. Thanks!
Comment #21
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedAdding a tag for the review from another D7 maintainer before commit.
Comment #22
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedDoing another check on this issue and when compared with D10 code, I think this is not ready yet.
The latest patch/es are a bit different from the D10 code, as D10 logging has this logic (see: https://git.drupalcode.org/project/drupal/-/blob/11.x/core/lib/Drupal/Co...):
Before the execution in each cycle:
After the last execution:
This means that in D10 we get one watchdog message for each cron implementation + one last additional message. In D7 implementation, we will get two watchdog messages for each cron implementation. For performance reasons I think it would be better to align the behavior with the D10 code.
The second issue is that in D10 there is a checkbox in the cron settings to enable the detailed logging. In D7 patch I have added the opt-out variable to the
settings.php
, but this is probably wrong (as the D10 and D7 will differ, without any valid reason), so I think we should align also this with the D10 approach and use the checkbox in cron settings as well.Moving to Needs Work.
Comment #24
poker10 CreditAttribution: poker10 at ActivIT s.r.o. commentedCreated a new MR based on patch from #20 and made changes according to the #22:
- removed the settings.php configuration variable and added a checkbox to the cron settings page (to match the D10 approach)
- updated the test to reflect this new variable
- updated the logging to match the D10 approach - only log one message for each
hook_cron()
implementation (see #22)There is one difference with D10 and that is, that I have not enabled the logging by default - D10 have it enabled by default, but I think we do not need to auto-enable it in D7.
Pipeline is green: https://git.drupalcode.org/project/drupal/-/pipelines/144394 , moving to Need review.