Early Bird Registration for DrupalCon Portland 2024 is open! Register by 23:59 PST on 31 March 2024, to get $100 off your ticket.
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?
Comment | File | Size | Author |
---|---|---|---|
#37 | interdiff-drupal-2823543-30-36.txt | 547 bytes | Dane Powell |
#37 | drupal-2823543-36.patch | 13.78 KB | Dane Powell |
Comments
Comment #2
cilefen CreditAttribution: cilefen as a volunteer commentedComment #3
Dane Powell CreditAttribution: Dane Powell at Acquia commentedI 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.
Comment #4
Dane Powell CreditAttribution: Dane Powell at Acquia commentedThis 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).
Comment #6
Dane Powell CreditAttribution: Dane Powell commentedUnsurprisingly, 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.
Comment #7
dawehnerGiven 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
.Comment #8
dawehnerDon't be that negative about the world :)
Comment #9
Dane Powell CreditAttribution: Dane Powell at Acquia commentedThanks 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 :)
Comment #10
Dane Powell CreditAttribution: Dane Powell at Acquia commentedComment #11
dhendriks CreditAttribution: dhendriks commentedThere is a typo in the class name in the patch from #9, 'NullLOgger' should be 'NullLogger'.
Comment #13
dawehnerAttitude often changes your and others behaviour, that's kinda simple :)
Comment #14
Dane Powell CreditAttribution: Dane Powell at Acquia commented@dhendriks thanks for catching that.
I cleaned up the UI and fixed tests, let's see if they pass this time...
Comment #16
Dane Powell CreditAttribution: Dane Powell at Acquia commentedYowser... testbot gets very angry if you specify the wrong config schema...
Comment #17
dhendriks CreditAttribution: dhendriks commentedThere 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...
Comment #19
Dane Powell CreditAttribution: Dane Powell at Acquia commentedThanks. 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.
Comment #20
Dane Powell CreditAttribution: Dane Powell at Acquia commentedActually the spacing of the array elements is different too. Grr.
Comment #24
Dane Powell CreditAttribution: Dane Powell at Acquia commentedComment #25
dawehnerTo 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
Nice Change!
Please use
ConfigFormBaseTrait
to retrieve and set the configuration. That trait documents why that is a good idea :)Comment #26
Dane Powell CreditAttribution: Dane Powell at Acquia commentedThis 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?
Comment #28
Dane Powell CreditAttribution: Dane Powell at Acquia commentedTested this locally, turns out the update hook is required.
Comment #29
dawehnerThank 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 :)Comment #30
Dane Powell CreditAttribution: Dane Powell at Acquia commentedMakes sense. Let's see if this passes tests.
Thanks for the feedback and encouragement.
Comment #31
dawehnerNote for the committer: We are already use private methods, which is totally fine. Tests are not meant to be extended
Nitpick, if you want to fix it: Note: This call is optional. We clean things up afterwards automatically
Comment #32
dawehnerSorry meant to set it to RTBC
Comment #33
catchMaking 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?
Comment #34
catchComment #35
Dane Powell CreditAttribution: Dane Powell at Acquia commentedI 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.
Comment #36
dhendriks CreditAttribution: dhendriks commented+1 for #35
Comment #37
Dane Powell CreditAttribution: Dane Powell at Acquia commented@dawehner thanks, I wasn't sure if individual tests cleaned up after themselves or not.
Comment #38
dawehnerCool, thank you for addressing the feedback.
Comment #39
catch#35 is a good explanation. Committed/pushed to 8.3.x, thanks!
Comment #41
Dane Powell CreditAttribution: Dane Powell at Acquia commentedThanks to everyone for being so receptive and responsive.
Comment #42
jibranWe should have used post update hook here.
Comment #43
dawehner@jibran Are you sure about this? Don't we want to have a consistent config system before doing all kind of other stuff?
Comment #44
jibranOh! this is a new setting in config we are introducing so yeah @dawehner is indeed correct
so hook_upate_N is used correctly.Comment #46
amateescu CreditAttribution: amateescu for Pfizer, Inc. commentedSince 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