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 for which cron implementation we started.

Suggested text:

<catch>	dawehner: 'Starting execution of foo_cron(), execution of bar_cron() took 100ms' sort of thing?

Remaining tasks

User interface changes

API changes

Data model changes

CommentFileSizeAuthor
#25 drupal-cron_logging-2716073-25.patch1.32 KBmoonray
#23 drupal-cron_logging-2716073-23.patch578 bytesmoonray
#17 drupal-cron_logging-2716073-17.patch3.37 KBmoonray
#14 drupal-cron_logging-2716073-14.patch3.42 KBmoonray
#11 drupal-cron_logging-2716073-11.patch2.65 KBmoonray
#8 drupal-cron_logging-2716073-8.patch2.62 KBmoonray
#4 drupal-cron_logging-2716073-4.patch1.48 KBmoonray
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

dawehner created an issue. See original summary.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented
Issue summary: View changes
dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented
Issue summary: View changes
moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Active » Needs review
FileSize
drupal-cron_logging-2716073-4.patch1.48 KB

Please review attached patch. It adds the necessary logging to cron in the above mentioned format.

Status: Needs review » Needs work

The last submitted patch, 4: drupal-cron_logging-2716073-4.patch, failed testing.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented

It looks like a logs related test needs tweaking.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented

Well yeah we need to tweak \Drupal\dblog\Tests\DbLogTest::verifyCron to expect one additional log entry per module, which we should get from the module handler.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Needs work » Needs review
FileSize
drupal-cron_logging-2716073-8.patch2.62 KB

This patch updates the tests.

Status: Needs review » Needs work

The last submitted patch, 8: drupal-cron_logging-2716073-8.patch, failed testing.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented

It seems to be the case that the patch files created by phpstorm are garbage. I would just recommend using git diff > foo.patch

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
FileSize
drupal-cron_logging-2716073-11.patch2.65 KB

Indeed. Re-upping patch.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 11: drupal-cron_logging-2716073-11.patch, failed testing.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Needs work » Needs review
FileSize
drupal-cron_logging-2716073-14.patch3.42 KB

The log count never seems to add up properly, because some of the oldest log entries get removed.
I changed the log check to look at the newest watchdog log ID, and then after processing compare the watchdog ID against the previously recorded one.

dagmar’s picture

dagmar
Primary language Spanish
Location Argentina
CreditAttribution: dagmar at Globant commented 
+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -114,12 +114,24 @@ private function verifyCron($row_limit) {
+    // Get the number of enabled modules. Cron adds a log entry for each module.
+    $list = \Drupal::moduleHandler()->getImplementations('cron');
+    $module_count = count($list);
+    $this->verbose(var_export($list, TRUE));

Nice! But do we need that $this->verbose()... ?

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented

I guess that verbose is only useful for debugging. It can be removed.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
FileSize
drupal-cron_logging-2716073-17.patch3.37 KB

Removed excess verbose logging.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented
Status: Needs review » Reviewed & tested by the community

Nice work @moonray!

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented
Status: Reviewed & tested by the community » Fixed

Committed ffcbce2 and pushed to 8.2.x. Thanks!

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented

  • alexpott committed ffcbce2 on 8.2.x 
    Issue #2716073 by moonray: Improve cron logging
dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented

This patch could be backported to d7.

@moonray Do you want to try it out?

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Fixed » Needs review
FileSize
drupal-cron_logging-2716073-23.patch578 bytes

Here is actually a follow-up patch. We never output the duration of the last module that ran hook_cron.
I've got the D7 patch ready to go as well, but I'll post that once we get past the D8 follow-up.

Status: Needs review » Needs work

The last submitted patch, 23: drupal-cron_logging-2716073-23.patch, failed testing.

moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented
Status: Needs work » Needs review
FileSize
drupal-cron_logging-2716073-25.patch1.32 KB

It would help if I actually included the updated test.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented
Status: Needs review » Reviewed & tested by the community

Good catch!

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented
Status: Reviewed & tested by the community » Fixed

Committed 60d994a and pushed to 8.2.x. Thanks!

As per the new backport policy D7 patches should be their own issue.

  • alexpott committed 60d994a on 8.2.x 
    Issue #2716073 by moonray, dawehner: Improve cron logging
moonray’s picture

moonray CreditAttribution: moonray at Chapter Three commented

D7 ticket is at #2722453: [D7] Improve cron logging

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.