Enable users to determine which types of log messages get written to dblog/syslog. Right now it's all or nothing.

We discovered an issue with the patch: It calls watchdog_severity_levels() from a hook_watchdog() implementation, but watchdog is one of Drupal's bootstrap hooks which can get invoked very early in the page load, so in some cases that function won't be loaded yet so you can get a fatal error.

The attached patch fixes it by explicitly loading includes/common.inc. Note that this is rerolled based on #4 above, not #6, since #4 is what I was working off of. But I'm also attaching the interdiff showing the changes I made, so someone can apply that to #6 later.

Also setting this to "needs review" so that the testbot will run on it. (I did verify that there were test failures due to the earlier patches and the attached patch fixes the ones I saw, at least.)

If I uncheck some options in 'Allowed message severity ' section, then they don't show up in logs, so it works properly in that way.

However, if I uncheck some options in 'Allowed message types' section, e.g. php (screenshot), then it doesn't prevent php-type messages to show up in logs (screenshot). I also tried to make custom named types of messages in watchdog() ('irek02-patch check '), but after unchecking them they were showing up in the log anyway...

P.S.
To check the patch I included all 8 severity types watchdog() functions in the beginning of the node_view() function in node.module:

watchdog('php', 'Checking the patch: WATCHDOG_DEBUG', $variables = array(), $severity = WATCHDOG_DEBUG, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_INFO', $variables = array(), $severity = WATCHDOG_INFO, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_NOTICE', $variables = array(), $severity = WATCHDOG_NOTICE, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_WARNING', $variables = array(), $severity = WATCHDOG_WARNING, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_ERROR', $variables = array(), $severity = WATCHDOG_ERROR, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_CRITICAL', $variables = array(), $severity = WATCHDOG_CRITICAL, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_ALERT', $variables = array(), $severity = WATCHDOG_ALERT, $link = NULL);
watchdog('php', 'Checking the patch: WATCHDOG_EMERGENCY', $variables = array(), $severity = WATCHDOG_EMERGENCY, $link = NULL);

This piece of code in the patch is responsible for checking if the message type is allowed to go in logs

// If this is not an allowed type we don't log it
if (!in_array($type, $allowed_types)) {
   return FALSE;
}

The reason it doesn't work, because when we uncheck some option in message types, then the value of this type in $allowed_types becomes '0' (e.g. 'php' => '0'). So the proper way to see if any options were unchecked would be something like this:

foreach ($allowed_types as $key => $value ) {  
    if($key == $type && $value == '0')
        return FALSE;
}

After I did this correction the unchecked types of messages stopped showing up in the logs.

Here is the patch with changes I mentioned in my comment #9.

However, sometimes I get warning messages after I save the changes in admin/config/development/logging. I've noticed it before I started modifying the patch:

Bump! This wooden toy needs to become a real boy (AKA get it into core :))

Looks great.

Something simple, also with tests: #1268636: Watchdog should ignore reports below the system reporting level.

Note that this is part of the motivation behind #1594956: Merge watchdog and Symfony logger classes too.

Could not reproduce #10, can anyone else?

Re-rolled patch for 8.x branch

#14: 1408208-14-syslog-dblog-filter-messages.patch queued for re-testing.

Better patch should pass tests

That looks good for me.

Applied patch from #18 and added the following to my node_view() function in node.module (with thanks to irek02 for giving me this code):

$message_types = array('php', 'page not found', 'content');
// Remove quote marks
$severities = array(WATCHDOG_DEBUG, WATCHDOG_INFO, WATCHDOG_NOTICE, WATCHDOG_WARNING, WATCHDOG_ERROR, WATCHDOG_CRITICAL, WATCHDOG_ALERT, WATCHDOG_EMERGENCY);

foreach($message_types as $message_type) {
foreach($severities as $severity) {
watchdog($message_type, 'Checking the patch: '.$severity, $variables = array(), $severity = $severity, $link = NULL);
}
}

Results:

1. Deselecting "emergency" in either database logging or syslog section - or both sections concurrently - changes do not seem to take effect, although the "configuration options have been saved" message appears. Page refreshes with both checkboxes for "emergency" message severity levels checked instead of unchecked as they should be. Also, 'Recent log messages' include messages for severity level 0 (Emergency).
2. Deselecting "emergency" in both sections concurrently yields error: "Warning: array_combine() [function.array-combine]: Both parameters should have at least 1 element in dblog_form_system_logging_settings_alter() (line 212 of /Users/jordangraham/Sites/drupal/core/modules/dblog/dblog.module)." (see attached screen shot - same errors as Comment #10)
3. Deselecting "alert", "notice" or "info" in both sections concurrently yields same error, but boxes stay unchecked and the corresponding messages do not appear in the log
4. Deselecting "warning" in both sections concurrently yields the same error, boxes stay unchecked and most "warning" messages do not appear in the log, except for the same array_combine() error as above, which shows up as a warning (processed before the warning messages are turned off?) see screenshot
5. Deselecting the allowed message types works as intended; corresponding messages do not appear in the log
6. Once all three message types are deselected, reselecting php message type results in array_combine errors per attached screen shot; reselecting the page not found or content message types from a state where all three have been deselected does not create these errors. Reselecting one or the other php message type checkboxes - but not both at the same time - does not result in the array_combine errors.

Thanks! Some small documentation and style fixes.

1. +++ b/core/modules/dblog/dblog.moduleundefined
   @@ -140,10 +140,48 @@ function _dblog_get_message_types() {
   +  // Ensure the type is trimmed to fit in the db column
   ...
   +  // Load up the known types as well as the allowed types
   ...
   +  // If this is a new type, we allow it and we add it to the lists
   ...
   +  // If curent $type in $allowed_types array has '0' value, we don't log it
   
   +++ b/core/modules/syslog/syslog.moduleundefined
   @@ -102,6 +141,39 @@ function syslog_watchdog(array $log_entry) {
   +  // Load up the known types as well as the allowed types
   ...
   +  // If this is a new type, we allow it and we add it to the lists
   ...
   +  // If curent $type in $allowed_types array has '0' value, we don't log it
   

   These comments should end in a period.

2. +++ b/core/modules/syslog/syslog.moduleundefined
   @@ -61,12 +65,47 @@ function syslog_form_system_logging_settings_alter(&$form, &$form_state) {
   +    // If dblog is not enabled, provide a few standard core types. New types will get enabled by default
   +    // and added to the variable syslog_known_types. Users can disable new types of warnings on the config
   +    // page after they've been discovered and recorded in the variable syslog_known_types.
   

   This comment should be wrapped at 80 characters.

3. +++ b/core/modules/syslog/syslog.moduleundefined
   @@ -102,6 +141,39 @@ function syslog_watchdog(array $log_entry) {
   +    if($key == $type && $value == '0')
   +        return FALSE;
   

   Need a space between 'if' and '(', the if statement should use braces, and the return should only be indented 2 spaces within the if statement.

4. +++ b/core/modules/dblog/dblog.moduleundefined
   @@ -140,10 +140,48 @@ function _dblog_get_message_types() {
   +  // If curent $type in $allowed_types array has '0' value, we don't log it
   
   +++ b/core/modules/syslog/syslog.moduleundefined
   @@ -102,6 +141,39 @@ function syslog_watchdog(array $log_entry) {
   +  // If curent $type in $allowed_types array has '0' value, we don't log it
   

   There are two comments with the "curent" typo.

5. +++ b/core/modules/syslog/syslog.moduleundefined
   @@ -61,12 +65,47 @@ function syslog_form_system_logging_settings_alter(&$form, &$form_state) {
   +  // Get $all_types to provide as a default values for types of messages to log.
   +  if (module_exists('dblog')) {
   +    // If dblog is enabled, get a list of types from the watchdog table.
   +    $all_types = array_combine(_dblog_get_message_types(), _dblog_get_message_types());
   

   "Get $all_types to provide as default values for types of messages to log." - or remove the first comment, I think the "If dblog is enabled…" comment explains this better.

Forgot to mention, there are a few lines with trailing whitespace as well :)

The patch from #18 fails on 8.x rev 6273774d30615b882068ffe20736137b45d1f2a6, since the dblog_install hook doesn't even exists in the install file.

Im working on getting it to work on HEAD and fixing the issues mentioned above.

This a bit more advanced, since a lot of variable_get, variable_set is handled, and needed to be converted to the new configuration system.

Rerolled the patch from #18.

Now supporting CMI.

I don't want to bikeshed or anything, but is there any chance we could get in the ability to alter or discard watchdog messages in other modules? I'm basically looking for the ability to have a custom module hook in and make watchdog() not write a given message (regardless of the severity level).

For example, for one site, I may be interested in failed login attempts, but I don't care about login and logout notices. Or, I might be interested in PHP notices from one module, but not for others, so I could alter the watchdog entry and somehow tell watchdog to not log a message if it's from module 'xyz'.

Technically, nothing would obviously prevent us from adding such an alter hook.

However, watchdog() calls can be very numerous and we want their resolution to be as fast as possible, so I do not think it is a good idea to add it. Better filter and route calls directly from the configuration, which is the direction taken by the Monolog patch #1289536: Switch Watchdog to a PSR-3 logging framework, on which I'll be working again soon.

Updated issue summary.

Might I suggest adding an alter hook before the log entry is processed. This would not only be generally useful, but in handling cases where the log entry array is emptied, we can prevent processing of watchdog messages as needed.

28: bootstrap_watchdog-log-entry-alter_1408208_28.patch queued for re-testing.

Fixed patch - created in relation to Drupal root.

The patch above won't apply to a standard Drupal site as most don't have a docroot folder (as Acquia does).

Try cd /docroot and then run git diff --relative inside docroot.

Thank. you. ElijahLynn.

This one should work now.

This is getting tested against D8 not D7. It will need to be re-rolled for Drupal 8.

I agree with @breathingrock that using drupal_alter() is a nice approach and deserves to be in D7 and D8. Thanks for that patch.

drupal_alter() is nice, but as I said on #27, it also has a cost, and this hook can be fired quite often, so we probably want to minimize its cost: simply cutting out messages by reference to a logging level, as proposed on #1268636: Watchdog should ignore reports below the system reporting level, is less expensive.

As you know, drupal_alter() has benefits to offset that cost. It's been added to more than a few functions that can be fired quite often. Like url(), menu_get_item(), etc. IMHO it's worth the cost for (a) the added flexibility, and (b) the small patch that could actually make it into D7.

I haven't actually tested the performance impact it would have on watchdog(). But watchdog() already invokes hook_watchdog(), so I'm guessing the change would be from kinda slow to kinda slower, not from fast to slow.

Since we are now firmly in D8 territory and no longer in D7, maybe a cleaner approach would be to use the native features we have in D8 ?

In the logger case, we have the notion of overriding a service, which means code which would run less often. In D7, using drupal_alter means a log event with the patch is handled like:

1. watchdog($message, $context, ...)
2. drupal_alter('watchdog', $log_entry)
3. vastly simplified: foreach (module_implements('watchdog') as $module) { module_invoke('watchdog_alter', $log_entry); }
4. alteringmodule_watchdog_alter($log_entry)
5. and only then dispatch the modified event (modified the same way) to each registered watchdog implementation)

By contrast, in D8, assume a service override:

1. define a logger.channel_filtered service implementing this modification, and tagged as a service collector for "logger"
   services
2. override the service definition for logger channels (possibly specifically per channel, which cannot be done with drupal_alter) redefining parent to logger.channel_filtered instead of logger.channel_base
3. on cache flush only, core will replace the parent for logger.channel.* by your filtering logic, and your collector will receive the list of loggers
4. at runtime, logger events will be passed to your filter, which can then apply its logic and invoke the loggers. Big plus: it can now handle the filtering specifically for each logger, maybe stripping more data for remote logging and keeping more for a heavy duty destination like a local logger

Since feature requests are only accepted for Drupal 8.5.x+ and there is no patch for D8 here, I'm changing the status to active. The plan proposed by @fgm in #46 seems a reasonable plan to start.

Hi. I've faced the same need and found this thread. Pretty informative and provides some good ideas. But, @fgm, seems like your idea with re-assigning parent for logger channels will not work as LoggerChannelFactory::get() creates only instance of LoggerChannel class ($instance = new LoggerChannel($channel);).

So, in order to get this work, you need to re-define the whole chain: logger factory -> logger channel. I suggest even easier approach: don't change parents for all the channels but change the class of logger.channel_base instead.

I didn't find the better approach than just patch system module and implement logger channel there. It could be done directly in LoggerChannel but I found it weird that class from Drupal\Core (lib) must know something about module's config.

Please, take a look at this patch. With this applied you can setup filtering mapping for each channel and even loggers. For example:

my_channel:
  warning:
    - Drupal\dblog\Logger\DbLog
  debug:
    - Drupal\dblog\Logger\SysLog

In this example, DbLog will log records which have level warning and higher. Syslog will log every record. All these rules are applied only to my_channel channel.

Correct one (previous didn't create new files from the patch)

@Loparev Thanks for working on this! I have a few comments on the current code, and some additional requests at the end.

1. +++ b/core/modules/system/src/Form/LoggingForm.php
   @@ -44,15 +47,71 @@ public function buildForm(array $form, FormStateInterface $form_state) {
   +    $filtering_mapping_placeholder = <<<EOF
   

   In my opinion, I think is better to expose this as a config setting in settings.php. I don't remember a place (besides configuration management UI) where you can specify settings directly as YAML.

2. +++ b/core/modules/system/src/Logger/LoggerChannel.php
   @@ -0,0 +1,108 @@
   +    foreach ($this->sortLoggers() as $logger) {
   

   This could be refactored to exit the function sooner, instead of having so many nested foreach and ifs.

3. +++ b/core/modules/system/src/SystemServiceProvider.php
   @@ -0,0 +1,24 @@
   +    $container->getDefinition('logger.factory')
   

   Here you could check if the settings are defined to alter the logger.

Finally, there is one way to test the syslog functionality. Take a look to #2874069: Make syslog testable to know how initial tests were implemented.

Regarding config/settings, IMO logging configuration is very much a per-environment thing, so it is more something that belongs in settings than in config ; "config settings in settings.php" is a bit ambiguous about that.

Regarding testing, #2874069: Make syslog testable is a start, but a good next step would be to have some SyslogInterface for this wrapping implementation, one level up from LoggerInterface, allowing a simpler spy mechanism than the existing kerneltest which needs to touch the filesystem, probably going one level down to an actual in-memory unit test. This could be done as part of the test for this patch, and possibly taken from there back to the syslog tests.

Hi, @dagmar

In my opinion, I think is better to expose this as a config setting in settings.php.

Oh, ok. Even better to have $filtering_mapping defined as php array.

This could be refactored to exit the function sooner, instead of having so many nested foreach and ifs.

Yes, this looks terrible for now. I've started writing unit tests and found out that there are some issue with current implementation. Will work on this.

Here you could check if the settings are defined to alter the logger.

Got it, thanks.

Finally, there is one way to test the syslog functionality. Take a look to #2874069: Make syslog testable to know how initial tests were implemented.

Yes, I've looked at syslog tests and took them as a base for my tests.

Hi, @fgm

Regarding testing, #2874069: Make syslog testable is a start, but a good next step would be to have some SyslogInterface for this wrapping implementation, one level up from LoggerInterface, allowing a simpler spy mechanism than the existing kerneltest which needs to touch the filesystem, probably going one level down to an actual in-memory unit test. This could be done as part of the test for this patch, and possibly taken from there back to the syslog tests.

Will think about this, thank you. Probably I will implement tests in syslog-like style and then refactor them as you said.

Thank you, guys, for the feedback. I'll continue to work on this.

Refactored:

• Filtering mapping is not a config but setting in settings.php instead
• Added tests

Since we don't use config object here maybe it would be better to patch existing LoggerChannel instead of defining the new one and overriding the service definition? I mean LoggerChannel doesn't depend on core's module config.

Seems like it would be better to have this changes directly in core's LoggerChannel.

1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -79,6 +80,11 @@ class LoggerChannel implements LoggerChannelInterface {
      /**
   

   Missing the documentation of the property.

2. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -79,6 +80,11 @@ class LoggerChannel implements LoggerChannelInterface {
   +   * @var array
   

   Better to change to `string[]`.

3. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -79,6 +80,11 @@ class LoggerChannel implements LoggerChannelInterface {
   +  protected $log_filter = [];
   

   Should be `$logFilters` I believe.

4. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -133,7 +148,22 @@ public function log($level, $message, array $context = []) {
   +        if ($setting_channel == $this->channel &&
   

   Put the condition per line.

5. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -133,7 +148,22 @@ public function log($level, $message, array $context = []) {
   +          $suppressed = TRUE;
   

   Shouldn't we have `break` or even `return` here?

Thanks, @BR0kEN

Done.

I think this tests are a good candidate to use of @dataProvider. Instead of repeat the assertions you could simplify a lot the amount of code provided.

I avoided using data provider intentionally because I think it's not so good. What if you used data provider with a lot of input sets and the test fails? The only info you will be given is just "Test failed on data set N" (or something close to this). It's really bad because you don't really know what that data set means and what it tests. But if you have separate tests then you will see "thatLongTestNameMethodWhichTestsSomething failed". This error message gives some additional context about the error. And moreover, test will remain that big even if you will use data providers just because you will need to describe your inputs and outputs in one big array.

99% I might be wrong with all of this, just wanted to hear from you about this. If using data providers is a common practice then for sure I will rewrite tests.

I see what do you mean @Loparev. What about this:

Move this code:

    $this->assertEquals(2, count(array_filter($log_records, function($v) {
      return strpos($v, LoggingTest::EMERGENCY_MESSAGE);
    })));

Into a protected method, and then call it in one line. As part of the assertion:

$this->assertLogCount(2, LoggingTest::EMERGENCY_MESSAGE, $log_records);
$this->assertLogCount(9, LoggingTest::CHANNEL_NAME_1, $log_records);

I think it will reduce around 600 lines of code by replacing those 4 lines (including the space) into one line of code.

Indeed. Done.

Thanks!

+++ b/sites/default/default.settings.php
@@ -747,6 +747,26 @@
+ * Drupal core logging system can be configured in a way to filter
+ * out log messages by severity level on logger and channel level.
+ *
+ * For example:
+ * @code
+ * $settings['log_filters'] = [
+ *   'content' => [
+ *     'info' => [
+ *       'Drupal\dblog\Logger\DbLog',
+ *     ],
+ *   ]
+ * ];
+ * @endcode

Reading this documentation is not 100% clear to me how this could work. I think this needs to include some extra examples of:

1. How users can know which available options are ('content', 'php', etc)?
2. What 'info' means, are other options available?
3. Why there is a Logger after all, does this means an excluded log will be logged for all the missing options?

Maybe a useful set of @see links to other documentation pages can enrich the explanations provided here.

Also. Is log_filters the right name? If we compare them with views filters for example or array_filter, they are used in the opposite way in the sense what you filter is what you get from results. Maybe logs_exclude or logs_suppress is a better name for this setting.

Finally. There are 50+ coding standard messages that are reported here: https://www.drupal.org/pift-ci-job/1009521

Hi @dagmar

I improved the description and fixed linter reported issues. As for the log_filters, I would like to suggest logs_suppression. What do you think?

1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -86,6 +94,15 @@ class LoggerChannel implements LoggerChannelInterface {
   +    foreach (Settings::get('logs_suppression', []) as $channel => $severity_levels) {
   

   I'm not sure if this makes sense from a performance point of view. You are forcing to iterate through all the settings in the log function.

   If you just save the settings as they are defined in settings.php You can skip a few cycles by just checking if there are some keys defined.

2. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -133,7 +150,25 @@ public function log($level, $message, array $context = []) {
   +          $level > $this->levelTranslation[$setting_level] &&
   

   I'm not really sure that we want to ignore all the logs higher than this. I rather prefer to specify each log by separate. Or maybe introduce an 'all' options to exclude them all.

3. +++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
   @@ -0,0 +1,813 @@
   +  public static $modules = ['system', 'syslog', 'syslog_test', 'logging_test'];
   
   +++ b/sites/default/default.settings.php
   @@ -747,6 +747,62 @@
   + * Logging configuration.
   

   system is enabled by default.

4. +++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
   @@ -0,0 +1,813 @@
   +   * @param $count
   

   Missing descriptions here.

5. +++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
   @@ -0,0 +1,813 @@
   +    $this->assertLogCount(16, LoggingTest::CHANNEL_NAME_1, $log_records);
   

   You could replace CHANNEL_NAME_1 and CHANNEL_NAME_2 by CHANNEL_A and CHANNEL_B.
   To make them shorter.

6. +++ b/sites/default/default.settings.php
   @@ -747,6 +747,62 @@
   + * Drupal core logging system can be configured in a way to suppress
   

   This is not just for core.

7. +++ b/sites/default/default.settings.php
   @@ -747,6 +747,62 @@
   + * then this log record will be suppressed and will not be logged into the
   + * database as rule allows only records with severity level equals to or
   + * higher than 'info'. The rule is applicable only to that log records which
   + * are being logged to 'my_channel' channel from the \Drupal\dblog\Logger\DbLog
   + * logger.
   

   I've been thinking about the use of suppress, removed, filter here. I think the word we are looking for is 'ignore'. Since we are not deleting logs, just not persist them.

8. +++ b/sites/default/default.settings.php
   @@ -747,6 +747,62 @@
   + *   'my_channel' => [
   

   Maybe here we could use the 'page not found' since this one of the the most used cases.

9. +++ b/sites/default/default.settings.php
   @@ -747,6 +747,62 @@
   + * second rule will not be applied as there is another one defined earlier
   + * for the same channel and logger.
   

   I think this could be deleted if the > operator is changed to == in the LoggerChannel class.

10. +++ b/sites/default/default.settings.php
    @@ -747,6 +747,62 @@
    + * severity level name. Core channels are defined in a core.services.yml
    

    I'm afraid this is incomplete. Most of the channels are dynamic and they are defined when you call \Drupal::logger().

    I list of the ones called by core are:

    • 'access denied'
    • 'config_sync'
    • 'cron'
    • 'entity_reference'
    • 'example'
    • 'field'
    • 'file system'
    • 'file'
    • 'filter'
    • 'image'
    • 'locale'
    • 'migrate_drupal_ui'
    • 'migrate'
    • 'php'
    • 'responsive_image'
    • 'security'
    • 'system'
    • 'theme'
    • 'tracker'
    • 'user'
    • 'views'

    We may want to show small list of the most relevant.

Mm..ok, agree, let's change > logic to = logic. By "all options" you mean something like this: "channel->level->*", "channel->*->loggers", "*->level->loggers", "channel->*->*", "*->*->loggers", "*->level->*" and "*->*->*" (probably just "*")? Just want to make sure we discussed all the things before implementing.

Yes @Loparev. I don't see a use case for * -> * -> * you could just disable the logging module in that case. Maybe we should analyze if the nested option is the best alternative here.

I'm thinking that maybe a plain set of configurations is more flexible and allow the use of `*` in a natural way. For example

$settings['ignore_logs'] = [
  [
    'channel' => 'page not found',
    'level' => '*'
    'logger' => 'Drupal\dblog\Logger\DbLog'
  ],
  [ 
    'channel' => 'php'
    'level' => 'info'
    'logger' => '*'
  ]
];

Agree. Will work on this.

But @dagmar, if we choose

$settings['ignore_logs'] = [
  [
    'channel' => 'page not found',
    'level' => '*'
    'logger' => 'Drupal\dblog\Logger\DbLog'
  ],
  [ 
    'channel' => 'php'
    'level' => 'info'
    'logger' => '*'
  ]
];

we need to admit we would need to iterate through all the settings in each log() call.

You could create a new structure based on the settings defined in the settings.php. So you analyze the settings once, and create an optimized version to determinate if a log should be ignored or not.

I've rewritten the patch in order to meet all the requirements/suggestions/review issues (I believe :))

• Switched ">" logic to "=" logic
• Rewritten integration tests
• Added unit tests (data provider is used because seems like this approach is accepted throughout the unit tests)
• Renamed setting name to suggested ignore_logs
• Added new method: LoggerChannel::isIgnoredLog() which returns TRUE in case we need to ignore current log record

Fixed typo.

Hi @dagmar,

What do you think about the latest patch?

@Loparev I will review it during this week.

Thanks!

Referenced the older issue, which someone found in may.

1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -86,6 +94,44 @@ class LoggerChannel implements LoggerChannelInterface {
   +      $level = $ignore_log["level"] == "*" ? $ignore_log["level"] : $this->levelTranslation[$ignore_log["level"]];
   

   Use single quotes instead of double.

2. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -86,6 +94,44 @@ class LoggerChannel implements LoggerChannelInterface {
   +    $full_match = in_array("{$channel}:{$level}:{$logger}", $this->ignoreLogs);
   

   I'm not really sure if this is the fastest way to check this. Makes sense from a readability point of view, but I wonder if there is another way to organize things to make this less cpu consuming.

   I'm not saying this is slow. But clearly it adds some extra checks before each log and with hundred of logs written by minute it could affect performance.

I'm not a algorithms expert. Maybe another person can take a look and give another point of view.

You're right. I think using isset() instead of in_array() will help not to impact performance dramatically. Additionally, not evaluating conditions in advance will help as well.

There are some error related to coding standards:

line 41	Expected 1 blank line before function; 2 found
44	TRUE, FALSE and NULL must be uppercase; expected "TRUE" but found "true"
101	Line indented incorrectly; expected 4 spaces, found 5
245	A comma should follow the last multiline array item. Found: ]
290	A comma should follow the last multiline array item. Found: ]
335	A comma should follow the last multiline array item. Found: ]
380	A comma should follow the last multiline array item. Found: ]
425	A comma should follow the last multiline array item. Found: ]
470	A comma should follow the last multiline array item. Found: ]
515	A comma should follow the last multiline array item. Found: ]

1. +++ b/sites/default/default.settings.php
   @@ -730,6 +730,69 @@
   + * Drupal logging system can be configured in a way to ignore
   

   This can be organized to fit in a 80 line.

2. +++ b/sites/default/default.settings.php
   @@ -730,6 +730,69 @@
   + *     'level' => \Psr\Log\LogLevel::DEBUG,
   ...
   + * List of available severity levels:
   

   This is not consistent with the use of level above.
   Maybe \Psr\Log\LogLevel::DEBUG, instead?

Rerolled addressing the points in #89 plus a few more in other files touched by the patch.

Note that, standards-wise, there is still an issue with the fact that LoggerChannelTest.php contains 2 classes instead of just one. Not sure what is the core practice regarding this: it should respect coding standards, but test class files with multiple classes in them are still very frequent (22 classes in ProxyBuilderTest, for example), so I assumed we would keep things that way.

Hi, @dagmar and @fgm.

Thanks for the feedback and fixing sniffer issues. What are the next steps regarding this patch? Are there some other stages to be done before getting this into the codebase?

1. +++ b/sites/default/default.settings.php
   @@ -729,6 +729,68 @@
   + * List of available severity levels:
   + *  - 'debug'
   + *  - 'info'
   + *  - 'notice'
   + *  - 'warning'
   + *  - 'error'
   + *  - 'critical'
   + *  - 'alert'
   + *  - 'emergency'
   

   This is still not addressed. I think we should use the LogLevel::EMERGENCY, LogLevel::ERROR, etc instead.

2. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -79,13 +80,51 @@ class LoggerChannel implements LoggerChannelInterface {
   +    return
   +      isset($this->ignoreLogs["{$channel}:{$level}:{$logger}"]) ||
   +      isset($this->ignoreLogs["{$channel}:{$level}:*"]) ||
   

   I think we could add a check to verify there something defined in $this->ignoreLogs.

   Like !empty($this->ignoreLogs)

   Because right now it will fail (but check) all the conditions if the array is empty.

I'll handle this today.

Regarding 1. : the code uses the numeric RfcLogLevel::* constants, so we can not really use the strings or the LogLevel::*. Also testLogRecursionProtection() should probably use the RfcLogLevel::* constants instead of hardcoding 0 to 7, I guess.

Regarding 2. : since this is new code for 8.7 which won't be backported to 8.6, AIUI we can require PHP7 syntax, probably taking advantage of the ?? null-coalescing syntax instead of using isset() or empty().

I was doing a performance review of the code and noticed this. When you hit a not found page the, this is the how LoggerChannels methods are executed:

1. __construct
2. setRequestStack
3. setCurrentUser
4. setLoggers
5. log
6. sortLoggers
7. isIgnoredLog
8. __construct
9. setRequestStack
10. setCurrentUser
11. setLoggers
12. __construct
13. setRequestStack
14. setCurrentUser
15. setLoggers

In another test, for example adding a notExistentFunction() to the user login form I get this call stack.

1. __construct
2. setRequestStack
3. setCurrentUser
4. setLoggers
5. __construct
6. setRequestStack
7. setCurrentUser
8. setLoggers
9. log
10. sortLoggers
11. isIgnoredLog

(You can try this by yourself adding a var_dump at the beginning of each method of the class.)

Since the constructor is called 2 or 3 times in each execution, it could be interesting to move the code that reads the settings from the constructor outside. For example directly into isIgnoredLog. That the first time checks if the settings are initialized, and if they are not, load them from there.

This is still not addressed. I think we should use the LogLevel::EMERGENCY, LogLevel::ERROR, etc instead.

Done.

I think we could add a check to verify there something defined in $this->ignoreLogs.

Done.

the code uses the numeric RfcLogLevel::* constants, so we can not really use the strings or the LogLevel::*

Internally code uses numeric RfcLogLevel constants but in settings user defines rules with LogLevel string constants. Not sure why can't we use string constants here.

Also testLogRecursionProtection() should probably use the RfcLogLevel::* constants instead of hardcoding 0 to 7, I guess.

Done.

since this is new code for 8.7 which won't be backported to 8.6, AIUI we can require PHP7 syntax, probably taking advantage of the ?? null-coalescing syntax instead of using isset() or empty().

Done.

Since the constructor is called 2 or 3 times in each execution, it could be interesting to move the code that reads the settings from the constructor outside. For example directly into isIgnoredLog. That the first time checks if the settings are initialized, and if they are not, load them from there.

Done.

Sorry, uploaded the wrong patch. Here is the correct one.

This is looking really good to me. I did a full review again and just found a few changes that can improve the patch.

+++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
@@ -0,0 +1,305 @@
+    $this->setSettings([]);

This line should be removed to be consistent with the settings defined before this patch.

+++ b/sites/default/default.settings.php
@@ -730,6 +730,68 @@
+ * will be ignored. Wildcard symbol can be used in with any parameter in
+ * any sequence.

The wildcard symbol can be used with any parameter in any sequence.

I did a final review of the patch. And since I have no extra comments to add, the code looks good, with good test coverage, and all my concerns has been addressed, I'm marking this as RTBC.

@Loparev great work! You should probably expect an extra requests of changes by other eyes that may see things that I don't see.

Just a minor, minor thing (that i'm not totally sure anyway).

1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
   @@ -79,7 +80,14 @@ class LoggerChannel implements LoggerChannelInterface {
   +   * @var string[]|NULL
   

   @var array[string]bool|NULL

I didn't find any occurrences of array[string]bool in the core and I'm not sure if it's a correct way to say array containing string keys and bool values.

Thank you for the review!

1. +++ b/core/modules/system/tests/modules/logging_test/logging_test.services.yml
   @@ -0,0 +1,7 @@
   +services:
   

   we don't actually need this, or the logger - see https://www.previousnext.com.au/blog/making-your-drupal-8-kernel-tests-f... - we can just make the test class the logger class.

2. +++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
   @@ -0,0 +1,303 @@
   +  protected function setSettings(array $settings) {
   +    new Settings([
   +      'ignore_logs' => $settings,
   +    ]);
   

   Any reasons not to use \Drupal\KernelTests\KernelTestBase::setSetting ?

3. +++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
   @@ -0,0 +1,303 @@
   +  public function testLoggingEmptyIgnoreConfig() {
   ...
   +  public function testLoggingFullMatch() {
   ...
   +  public function testLoggingAllLoggersMatch() {
   

   It feels like these methods all follow the same pattern, setSettings, fire logs, assert counts.

   I think you could refactor them to use a data provider and remove the duplication

4. +++ b/core/tests/Drupal/Tests/Core/Logger/LoggerChannelTest.php
   @@ -53,7 +85,31 @@ public function testLog(callable $expected, Request $request = NULL, AccountInte
   +      $this->assertEquals($this->invokeMethod($channel, 'isIgnoredLog', $case['params']), $case['result']);
   

   another option would be to subclass LoggerChannel for testing sake (put the class in this file) and flip the method to public in the subclass, then test that instead

5. +++ b/core/tests/Drupal/Tests/Core/Logger/LoggerChannelTest.php
   @@ -145,18 +201,370 @@ function ($context) {
   +    $cases[] = [
   ...
   +    $cases[] = [
   

   chance you could key this array?

   case #3 is harder to debug in a fail than

   case 'some description'

Hi @larowlan

I'll look at this on weekend.

Thanks.

1. Got it. Done.
2. Didn't notice this method. Done.
3. Done.
4. Done.
5. Oh, it was my point why I don't use data providers. I didn't even realize we can set meaningful keys for cases array) Now I see all the power of data providers :D Done.

+++ b/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
@@ -0,0 +1,316 @@
+  public static $modules = ['syslog', 'syslog_test'];
+  protected $logFileName;

syslog and syslog_test module are no longer required as far I can see.

There are a few coding standards warnings reported too:

/var/lib/drupalci/workspace/jenkins-drupal_patches-68713/source/core/modules/system/tests/src/Kernel/Logging/LoggingTest.php
line 190	A comma should follow the last multiline array item. Found: 16
210	A comma should follow the last multiline array item. Found: 16
230	A comma should follow the last multiline array item. Found: 16
250	A comma should follow the last multiline array item. Found: 16
270	A comma should follow the last multiline array item. Found: 15
290	A comma should follow the last multiline array item. Found: 14
310	A comma should follow the last multiline array item. Found: 8

Also, it could be nice to add a Kernel test to dblog module to test that no logs are created when the settings are set to ignore page not found, like the example of default.settings.php

syslog and syslog_test module are no longer required as far I can see.

No, they are required as we test cases with two loggers presented. Take a look at assertions of full_match, for example. We ignore messages for LoggingTest logger for debug level and for channel a channel and that's why there is 'debug_messages_count' => 3, assertion (2 messages for channel_b and one for channel_a).

There are a few coding standards warnings reported too:

Done. Also, it's weird that test bot doesn't fail the build if there are some coding standard issues. Developer sees the green build, how he/she could know if there are some issues?) I didn't even have a thought to open the build console if it's green.

I don't really understand why do we need this additional test. Seems like we've covered all the cases in Drupal\Tests\system\Kernel\Logging\LoggingTest test.

Let's merge this if there are no objections?

Hi, I know you were working on the Drupal 8.6.0, it is great to see the new release!

I just want to draw a few attention to this ticket. I suggest marking this as RTBC in order to gather more reviews/attention here.

I took another look to the patch and it is looking really good.

However after reading again the issue summary and thinking this feature being used by all sort of drupal (big and small) sites I wonder if we should provide a way to decide wether Severity Level filter should be more customizable. (Greater than certain level >= or just equal to the defined setting ==)

The oldest request I found related to this issue is: #77875: Allow administrator to set logging level for Watchdog. The idea of Severity greater or lower than certain values was proposed there too. I was the one that proposed in #72 that this should be changed to == but now thinking this more carefully I'm not sure if we should support both options. Or if we opt in for one of them, at least think better what is the best option here.

Having == gives enough flexibility to select what to ignore and what not. But using >= allow users to reduce the amount of settings to write in case you want to ignore a group of different severity levels for some particular channel or logger.

I understand this adds complexity to the patch and also requires some extra considerations of how to define if the severity check should be greater, equal or lower than the specified. Also brings some collision situations (where you define < Error and > Warning in two different options.

So please, share your thoughts on this.

Regarding the current code:

+++ b/core/tests/Drupal/Tests/Core/Logger/LoggerChannelTest.php
@@ -53,7 +63,31 @@ public function testLog(callable $expected, Request $request = NULL, AccountInte
+   * @throws \ReflectionException

This is no longer the case. Since you are changing the visibility scope in LoggerChannelTestable.

Another thing I notice is that there is no use of the Splat operator in core yet. There is a relevant issue here: #2551661: replace call_user_func_array() with splat (variadics) which is quite old and the reasons that blocked the process are no longer valid today.

As for == vs >=. Both have pros and cons. Logic == is straightforward but too verbose. On the other hand >= logic is flexible enough (you can ignore a bunch of logs with only one rule defined) but it's too flexible :) (there might be collisions in logic but, to be honest, it's not the issue as we could implement "first/last matching rule wins" logic). So, both options are good enough. It's just the question of taste. Personally, I would prefer == logic as it's simple, straightforward and doesn't require handling collisions and extra considerations for severity levels.

This is no longer the case. Since you are changing the visibility scope in LoggerChannelTestable.

Oh, thank you. Fixed.

Another thing I notice is that there is no use of the Splat operator in core yet. There is a relevant issue here: #2551661: Speed up Drupal with splat (variadics) which is quite old and the reasons that blocked the process are no longer valid today.

According to this post since Drupal 8.7.x it's required to use PHP 7 and, thereby, splat operator in the core is no longer the issue. So it should be safe to use it in this patch since it against 8.7.x.

When I stumbled into this issue I thought the same @fgm brought up in #27: why don't we use the existing tools to achieve this, without having to introduce new settings or APIs? Like Monolog's FilterHandler, we can decorate any LoggerInterface with our own custom or third-party LoggerInterface decorators that filter log messages by severity, or by whatever other condition you want. The added benefit is that this approach allows the use of existing third-party PSR-3 solutions, and it's very similar to how other logging frameworks handle this, making this easier to grasp for a lot of people.

I just did a roundup of the patterns we currently have in core to access logger channels, and it's annoyingly diverse:

• in most cases, the channel is declared like { parent: logger.channel_base, arguments: ["channel_name"] }, which is AFAICS the recommended pattern. However...
• exception.logger and plugin.manager.mail both directly take @logger.factory and do what they want with it outside general view
• logger.channel_base, logger.channel.contact and logger.channel.file are created with something like { factory: "logger.factory:get", arguments: ["channel_name"] }

So tackling filtering early on, on the "emitter" side, is not obvious: the filtering will be easier on the "logger" side, because these are gathered by the @logger.factory using the { tags: { name: "service_collector", tag: "logger" } } pattern, meaning all loggers gathered at this point can be handled at once by adding an implementation of CompilerPassInterface that will run before the TaggedHandlersPass and update all services tagger with logger to wrap them with a filtering decorator before they are collected by the TaggedHandlersPass.

Just want to follow up on this. What should be the next steps?

@loparev, maybe evaluating the "compilerpass" option I mentioned ?

this feature would be amazing... kinda nuts that it doesn't already exist!

Patch #113 does not apply successfully on 10.1.x-dev. Need new patch for it.

The Needs Review Queue Bot tested this issue. It either no longer applies to Drupal core, or fails the Drupal core commit checks. Therefore, this issue status is now "Needs work".

Apart from a re-roll or rebase, this issue may need more work to address feedback in the issue or MR comments. To progress an issue, incorporate this feedback as part of the process of updating the issue. This helps other contributors to know what is outstanding.

Consult the Drupal Contributor Guide to find step-by-step guides for working with issues.

Thanks for all the work on this. I was about to add an issue to squelch 403/404s from the watchdog log, and thought there might be something more general floating around!

I've taken the patch from #113, made an MR from it, rebased against latest, and nudged the tests back to green again.

all loggers gathered at this point can be handled at once by adding an implementation of CompilerPassInterface that will run before the TaggedHandlersPass and update all services tagger with logger to wrap them with a filtering decorator before they are collected by the TaggedHandlersPass.

I started looking at this, and while I kinda hate to push this back further when what's there is eminently usable, I was thinking it might make sense to add a more general purpose collected_service_decorator tag to simplify adding decorators to any group of collected services. Don't want to add complexity, was just thinking we'd be pretty much writing it anyway, so it might make sense to do it in a general purpose way.

If that makes sense, I'm not sure if it should be a new issue where it can be worked on in isolation, or part of this issue where it can be used when it's introduced.

Thanks!

This is not really system.module, changing component to base system. I think we should move the kernel test to core/tests/Drupal/KernelTests/Core as well.