In #2716073: Improve cron logging, logging was added that indicates the execution time for each cron hook. I can understand how that can be useful, when debugging cron problems. However, I'm not having any cron problems. My cron hooks are not stuck, neither are they taking too long. I do require cron to run multiple times a day. Since I have over a dozen cron hooks, I get dozens of log entries several times a day.

This type of logging appears to me to be debug logging rather than production logging. Could we consider adding an option to enable/disable this cron debug logging?

CommentFileSizeAuthor
#37 interdiff-drupal-2823543-30-36.txt547 bytesDane Powell
#37 drupal-2823543-36.patch13.78 KBDane Powell
#30 interdiff-drupal-2823543-28-30.txt2.23 KBDane Powell
#30 drupal-2823543-30.patch13.84 KBDane Powell
#28 interdiff-drupal-2823543-26-28.txt448 bytesDane Powell
#28 drupal-2823543-28.patch11.44 KBDane Powell
#26 interdiff-drupal-2823543-24-26.txt5.55 KBDane Powell
#26 drupal-2823543-26.patch11.44 KBDane Powell
#24 interdiff-drupal-2823543-20-24.txt2.03 KBDane Powell
#24 drupal-2823543-24.patch11.23 KBDane Powell
#20 interdiff-drupal-2823543-19-20.txt1.23 KBDane Powell
#20 drupal-2823543-20.patch8.13 KBDane Powell
#19 drupal-2823543-19.patch8.52 KBDane Powell
#19 interdiff-drupal-2823543-16-19.txt964 bytesDane Powell
#16 interdiff-drupal-2823543-14-16.txt431 bytesDane Powell
#16 drupal-2823543-16.patch8.57 KBDane Powell
#14 drupal-2823543-14.patch8.57 KBDane Powell
#14 interdiff-drupal-2823543-9-14.txt3.71 KBDane Powell
#9 interdiff-drupal-2823543-4-9.txt4.62 KBDane Powell
#9 drupal-2823543-9.patch6.34 KBDane Powell
#4 drupal-2823543-4.patch5.23 KBDane Powell
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

dhendriks created an issue. See original summary.

cilefen’s picture

Title: Log being spammed with cron execution times debug info » Make cron execution logging optional
Dane Powell’s picture

I agree, the cron notices that were added should really be classified as debug messages, and there should be a switch to enable/disable them. On many large scale sites, cron may run as often as every minute, and this completely obliterates anything else in the dblog.

Dane Powell’s picture

Status: Active » Needs review
FileSize
5.23 KB

This adds an option to enable or disable detailed logging (disabled by default).

This required tweaking the automated cron module a bit, since it alters the cron settings form in a pretty blind way. This whole form should really be cleaned up at some point (i.e. so that you can save the configuration without actually running cron).

Status: Needs review » Needs work

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

Dane Powell’s picture

Unsurprisingly, tests related to that cron config page and automated cron are failing. That whole integration really needs to be revisited, but I don't really feel like putting more effort into it without a commitment from a core maintainer to accept it.

dawehner’s picture

Given I was sort of involved when this feature landed, here is a comment. I think this is dramatically helpful, but yeah I can see the point/problem of log pollution.

In terms of implementation, I think we could massively simplify things, by instead of placing a good bunch of if statements around everything, we instead could
use \Psr\Log\NullLogger alternative to the injected logger. So maybe use $logger = $time_logging_enabled ? $this->logger : new NullLOgger() and then use $logger everywhere inside \Drupal\Core\Cron::invokeCronHandlers.

dawehner’s picture

but I don't really feel like putting more effort into it without a commitment from a core maintainer to accept it.

Don't be that negative about the world :)

Dane Powell’s picture

Thanks for the advice, that makes sense. The main reason I went with the conditional was to avoid running the timer at all if it's not being logged... but the overhead is probably minimal.

I made that change to the logger. Additionally, this adjusts the dblog test, which previously had to take into account the detailed logging but now actually becomes simpler. I also added a confirmation message when settings are saved (moved from the automated cron module).

I expect this to still fail tests, since I suspect the automated cron form submit callback isn't running, causing the failed test about cron threshold.

Sorry, but my negative outlook is based on empirical experience of the acceptance rate of core patches :)

Dane Powell’s picture

Status: Needs work » Needs review
dhendriks’s picture

There is a typo in the class name in the patch from #9, 'NullLOgger' should be 'NullLogger'.

Status: Needs review » Needs work

The last submitted patch, 9: drupal-2823543-9.patch, failed testing.

dawehner’s picture

Sorry, but my negative outlook is based on empirical experience of the acceptance rate of core patches :)

Attitude often changes your and others behaviour, that's kinda simple :)

Dane Powell’s picture

Status: Needs work » Needs review
FileSize
3.71 KB
8.57 KB

@dhendriks thanks for catching that.

I cleaned up the UI and fixed tests, let's see if they pass this time...

Status: Needs review » Needs work

The last submitted patch, 14: drupal-2823543-14.patch, failed testing.

Dane Powell’s picture

Status: Needs work » Needs review
FileSize
8.57 KB
431 bytes

Yowser... testbot gets very angry if you specify the wrong config schema...

dhendriks’s picture

+        $logger->notice('Starting execution of @module_cron().', [
+            '@module' => $module,
+          ]);

There is a problem with the indentation here, and in a few other places in the patch. The 3rd line doesn't have the same indentation as the first line, and the second line isn't indented 2 spaces more than the first, but instead is indented 4 spaces.

I'm not a Drupal developer, so didn't really look at the functionality...

Status: Needs review » Needs work

The last submitted patch, 16: drupal-2823543-16.patch, failed testing.

Dane Powell’s picture

Status: Needs work » Needs review
FileSize
964 bytes
8.52 KB

Thanks. I'm not a huge fan of passing arrays as function arguments like that anyway, but now's probably not the time for a refactor.

Dane Powell’s picture

Actually the spacing of the array elements is different too. Grr.

The last submitted patch, 16: drupal-2823543-16.patch, failed testing.

The last submitted patch, 19: drupal-2823543-19.patch, failed testing.

Status: Needs review » Needs work

The last submitted patch, 20: drupal-2823543-20.patch, failed testing.

Dane Powell’s picture

Status: Needs work » Needs review
FileSize
11.23 KB
2.03 KB
dawehner’s picture

  1. +++ b/core/modules/config/src/Tests/ConfigInstallProfileOverrideTest.php
    index e4a27dc..1ef9578 100644
    --- a/core/modules/config/tests/config_override_test/config/install/system.cron.yml
    
    --- a/core/modules/config/tests/config_override_test/config/install/system.cron.yml
    +++ b/core/modules/config/tests/config_override_test/config/install/system.cron.yml
    
    +++ b/core/modules/config/tests/config_override_test/config/install/system.cron.yml
    +++ b/core/modules/config/tests/config_override_test/config/install/system.cron.yml
    @@ -1,4 +1,4 @@
    
    @@ -1,4 +1,4 @@
     threshold:
       requirements_warning: 172800
       requirements_error: 1209600
    -
    +logging: 0
    
    +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    index e6f30d3..1ef9578 100644
    --- a/core/modules/system/config/install/system.cron.yml
    
    --- a/core/modules/system/config/install/system.cron.yml
    +++ b/core/modules/system/config/install/system.cron.yml
    
    +++ b/core/modules/system/config/install/system.cron.yml
    +++ b/core/modules/system/config/install/system.cron.yml
    @@ -1,3 +1,4 @@
    
    @@ -1,3 +1,4 @@
     threshold:
       requirements_warning: 172800
       requirements_error: 1209600
    +logging: 0
    

    To be honest I'm not sure we should change the default behaviour as part of this issue. If you would leave the default behaviour to have the logging enabled, this particular patch would be much smaller. You could then have another issue which discusses just the idea of changing the default value to turn it off

  2. +++ b/core/modules/system/src/Form/CronForm.php
    @@ -107,11 +107,31 @@ public function buildForm(array $form, FormStateInterface $form_state) {
    -      $form['cron'] = array(
    +      $form['automated_cron'] = array(
             '#markup' => $this->t('Enable the <em>Automated Cron</em> module to allow cron execution at the end of a server response.'),
           );
         }
     
    +    $form['cron'] = [
    

    Nice Change!

  3. +++ b/core/modules/system/src/Form/CronForm.php
    @@ -107,11 +107,31 @@ public function buildForm(array $form, FormStateInterface $form_state) {
    +      '#default_value' => \Drupal::config('system.cron')->get('logging'),
    
    @@ -119,6 +139,11 @@ public function buildForm(array $form, FormStateInterface $form_state) {
    +    \Drupal::configFactory()->getEditable('system.cron')
    

    Please use ConfigFormBaseTrait to retrieve and set the configuration. That trait documents why that is a good idea :)

Dane Powell’s picture

This version of the patch changes detailed logging to be on by default, and uses ConfigFormBaseTrait. Hopefully I'm using that correctly, it's new to me.

I also added an update hook to set detailed logging to be on by default, but I'm not sure if that's necessary. When you change an existing config schema (in this case by adding the logging option), do existing sites pick up the new value automatically?

Status: Needs review » Needs work

The last submitted patch, 26: drupal-2823543-26.patch, failed testing.

Dane Powell’s picture

Status: Needs work » Needs review
FileSize
11.44 KB
448 bytes

Tested this locally, turns out the update hook is required.

dawehner’s picture

Thank you @Dane Powell!

I guess one last step which would be great is to adapt DbLogTest and add a case which disables the configuration to disable logging and then again count the dblog messages. With that we would actually know that you can turn of the logging for that. I hope this makes sense for you :)

Dane Powell’s picture

Makes sense. Let's see if this passes tests.

Thanks for the feedback and encouragement.

dawehner’s picture

  1. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    @@ -147,6 +147,26 @@ private function verifyCron($row_limit) {
    
    @@ -147,6 +147,26 @@ private function verifyCron($row_limit) {
    +  private function runCron() {
    

    Note for the committer: We are already use private methods, which is totally fine. Tests are not meant to be extended

  2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    @@ -147,6 +147,26 @@ private function verifyCron($row_limit) {
    +    $this->config('system.cron')->set('logging', 1)->save();
    

    Nitpick, if you want to fix it: Note: This call is optional. We clean things up afterwards automatically

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

Sorry meant to set it to RTBC

catch’s picture

Version: 8.2.x-dev » 8.3.x-dev

Making this configurable sounds great, but not sure we need a UI for the config option. Also if we do need a UI for the config option, does it really live with cron settings or errors and logging?

catch’s picture

Status: Reviewed & tested by the community » Needs review
Dane Powell’s picture

I could see arguments either way. But when I noticed the log spam, my first instinct was to check the cron configuration page to see if it was configurable or not. I didn't even think to look under the logging page for this setting, and I certainly would never have expected to look for a hidden configuration option for this.

I expect a significant portion of users will choose to disable the detailed logging, and those folks will look to the same place I did. This seems like a strong argument for having the UI and associating it with the cron page.

dhendriks’s picture

+1 for #35

Dane Powell’s picture

@dawehner thanks, I wasn't sure if individual tests cleaned up after themselves or not.

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

Cool, thank you for addressing the feedback.

catch’s picture

Status: Reviewed & tested by the community » Fixed

#35 is a good explanation. Committed/pushed to 8.3.x, thanks!

  • catch committed f96cbb2 on 8.3.x
    Issue #2823543 by Dane Powell, dawehner, dhendriks: Make cron execution...
Dane Powell’s picture

Thanks to everyone for being so receptive and responsive.

jibran’s picture

+++ b/core/modules/system/system.install
@@ -1746,3 +1746,13 @@ function system_update_8202() {
+function system_update_8203() {

We should have used post update hook here.

dawehner’s picture

@jibran Are you sure about this? Don't we want to have a consistent config system before doing all kind of other stuff?

jibran’s picture

Oh! this is a new setting in config we are introducing so yeah @dawehner is indeed correct we want to have a consistent config system before doing all kind of other stuff so hook_upate_N is used correctly.

Status: Fixed » Closed (fixed)

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

amateescu’s picture

+++ b/core/modules/system/system.install
@@ -1746,3 +1746,13 @@ function system_update_8202() {
+function system_update_8203() {

Since this issue is only for Drupal 8.3.x, this should have been named system_update_8300().

Opened a followup to fix it quickly: #2842480: system_update_8203() is named incorrectly