[D7] Improve cron logging

The last submitted patch, 10: drupal-n2722453-10.patch, failed testing. View results →

Thanks 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.

Thanks for rerunning the tests. This should fix the failing test.

I 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:

diff --git a/includes/common.inc b/includes/common.inc
+    $queue_name_previous = '';
+

diff --git a/includes/common.inc b/includes/common.inc
+    $module_previous = '';
+

I have also added this issue to the list of potential candidates for the next release.

Seems 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:

@@ -5538,14 +5538,36 @@ function drupal_cron_run() {
     // Make sure every queue exists. There is no harm in trying to recreate an
     // existing queue.
     foreach ($queues as $queue_name => $info) {
+      // Log a message saying that the queue started.
+      watchdog('cron', 'Starting execution of queue @queue_name.', array(
+        '@queue_name' => $queue_name,
+      ), WATCHDOG_NOTICE);
+
+      timer_start('cron_queue_' . $queue_name);
       DrupalQueue::get($queue_name)->createQueue();
+      timer_stop('cron_queue_' . $queue_name);
+
+      // Log a message saying that the queue ended.
+      watchdog('cron', 'Execution of queue @queue_name took @time.', array(
+        '@queue_name' => $queue_name,
+        '@time' => timer_read('cron_queue_' . $queue_name) . 'ms',
+      ), WATCHDOG_NOTICE);
     }

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:

  foreach ($queues as $queue_name => $info) {
    if (!empty($info['skip on cron'])) {
      // Do not run if queue wants to skip.
      continue;
    }
    $callback = $info['worker callback'];
    $end = time() + (isset($info['time']) ? $info['time'] : 15);
    $queue = DrupalQueue::get($queue_name);
    while (time() < $end && ($item = $queue->claimItem())) {
      try {
        call_user_func($callback, $item->data);
        $queue->deleteItem($item);
      }
      catch (Exception $e) {
        // In case of exception log it and leave the item in the queue
        // to be processed again later.
        watchdog_exception('cron', $e);
      }
    }
  }

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-in 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:

Short-running or non-resource-intensive tasks can be executed directly in the hook_cron() implementation.

Long-running tasks and tasks that could time out, such as retrieving remote data, sending email, and intensive file tasks, should use the queue API instead of executing the tasks directly. To do this, first define one or more queues via hook_cron_queue_info(). Then, add items that need to be processed to the defined queues.

(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: 🐛 Cron queue gets processed every time cron is called, regardless of whether it's already being processed elsewhere Fixed

It is also worth considering whether we should backport this D10 change of processing queues in cron...

Uploading a patch with these changes:

• removed two extra unused variables
• removed logging from queues (it was wrongly used, see #18)
• added a new variable with possibility to opt-out of this logging
• extended the tests to test also the new variable

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!

Adding a tag for the review from another D7 maintainer before commit.

Doing 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:

      if (!$module_previous) {
        $logger->info('Starting execution of @module_cron().', [
          '@module' => $module,
        ]);
      }
      else {
        $logger->info('Starting execution of @module_cron(), execution of @module_previous_cron() took @time.', [
          '@module' => $module,
          '@module_previous' => $module_previous,
          '@time' => Timer::read('cron_' . $module_previous) . 'ms',
        ]);
      }

After the last execution:

    if ($module_previous) {
      $logger->info('Execution of @module_previous_cron() took @time.', [
        '@module_previous' => $module_previous,
        '@time' => Timer::read('cron_' . $module_previous) . 'ms',
      ]);
    }

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.

Created 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.

Adding a tag for the final review.

This is really useful functionality; I've used a script / drush command that does something very similar many times to debug cron problems.

I definitely think that it should not be enabled by default on existing sites though, in order to avoid ballooning log volume.

It looks to me like the latest MR disables the functionality by default in the system module:

/**
 * Detailed cron logging disabled by default.
 */
define('DRUPAL_CRON_DETAILED_LOGGING', 0);

...but the comment in default.settings.php suggests that the default is the opposite way around:

/**
 * Cron logging.
 *
 * By default drupal_cron_run() will log each execution of hook_cron() together
 * with the execution time. Set this variable to FALSE in order to opt out of
 * this behaviour.
 */
# $conf['cron_logging_enabled'] = TRUE;

This should be simple to fix if we're agreed that we just need to make the settings.php stanza match (i.e. default to off).

Tweaked the default settings comments on commit, as discussed with @poker10 in chat.

Thanks everyone!

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