Allow kernel tests to fail or expect logged errors

Just lost an hour (again) to this

This works well.

Probably a bit extreme to cause a watchdog_exception to fail a test. But maybe not.

Ha some of those are legitimate issues with tests :)

Probably a bit extreme to cause a watchdog_exception to fail a test. But maybe not.

Well, I'd say that you would have to be able to differentiate between an expected and an unexpected watchdog_exception, like you can do with php exceptions. I think an unexpected watchdog_exception should fail a test. And having to provide explicit silencing/asserting/handling of expected watchdog_exceptions doesn't sound like a bad thing, right?

Well, I'd say that you would have to be able to differentiate between an expected and an unexpected watchdog_exception, like you can do with php exceptions

Right, so making it a class property allows you to tune that up and down.

I think many of the fails in the test run above are valid issues in tests.

Many of them would just need to have their threshold tuned down, because we're expecting exceptions.

I'm all for that! I've had this in some of my tests already, but I do think it makes sense for pretty much all of them. So, as long as this can be controlled or turned off (maybe we should have a special $this->logLevelThreshold === NULL check for that, or a second, boolean property?) easily, this would be great to have!

I assume this would break a lot of contrib modules' test suites when committed like this – but I don't think that's really a problem, is it? We don't have any BC guarantees for test bases, as far as I know. (My modules have their tests broken regularly, so I assume not.)

Finally: Wouldn't this also make equally much sense for functional tests? (Or even more there, as going through the UI will a) hide even more exceptions, and b) give even less helpful fail messages ("Expected status code 200, but was 500.").)

But, in any case: Great approach, thanks for the patch!

+1

I would also like to have something like this for functional tests (actually especially functional tests). I guess though that it would be a little harder to implement as in that case a cron run would happen in a separate PHP process (if I'm right) and as a result then also the exception that is thrown during a cron run. I assume that the logger service set in the test in the way it is done in #4 won't have effect on operations performed by the 'browser' (for example via drupalGet()). Maybe for that reason support for functional tests should happen in a follow-up.

+1 for the general idea. These try/catch statements hide actual problems.

fail: [Other] Line 0 of sites/default/files/simpletest/phpunit-132.xml:
PHPunit Test failed to complete; Error: PHPUnit 6.5.8 by Sebastian Bergmann and contributors.

Testing Drupal\Tests\block\Kernel\Migrate\d7\MigrateBlockTest
F                                                                   1 / 1 (100%)

Time: 3.73 seconds, Memory: 4.00MB

There was 1 failure:

1) Drupal\Tests\block\Kernel\Migrate\d7\MigrateBlockTest::testBlockMigration
Missing filter plugin: filter_null. (/var/www/html/vendor/phpunit/phpunit/src/Framework/Assert.php:2719)
Failed asserting that false is true.

/var/www/html/core/tests/Drupal/KernelTests/AssertLegacyTrait.php:23
/var/www/html/core/modules/migrate/tests/src/Kernel/MigrateTestBase.php:195
/var/www/html/core/modules/migrate/src/MigrateExecutable.php:437
/var/www/html/core/modules/migrate/src/MigrateExecutable.php:247
/var/www/html/core/modules/migrate/tests/src/Kernel/MigrateTestBase.php:169
/var/www/html/core/modules/migrate/tests/src/Kernel/MigrateTestBase.php:183
/var/www/html/core/modules/migrate/tests/src/Kernel/MigrateTestBase.php:184
/var/www/html/core/modules/block/tests/src/Kernel/Migrate/d7/MigrateBlockTest.php:50

Given the potential disruption for contrib tests I'd suggest to just add this to the next minor release.

1.

So, as long as this can be controlled or turned off (maybe we should have a special $this->logLevelThreshold === NULL check for that, or a second, boolean property?) easily, this would be great to have!

As I understand it, in the patch as it stands these will all work to suppress errors:

protected $logLevelThreshold = RfcLogLevel::EMERGENCY;
protected $logLevelThreshold = FALSE;
protected $logLevelThreshold = NULL;

because even an RfcLogLevel::EMERGENCY (===0) is not less than the above.

2. I do wonder if it would be better DX though for protected $logLevelThreshold = RfcLogLevel::ERROR; to mean "fail on logs of level ERROR and above", rather than "fail on logs of levels above ERROR".

3. The name may be worth bikeshedding. I'd expect logLevelThreshold to be about the logging of something, not failing on response to logs. Maybe $failFromLogLevel.

4. We've got a boatload of core test failures across many test classes. Maybe the best solution is to
a) commit this with the test failure threshold set to NOT cause any failures by default, so it's opt-in at first
b) file follow-ups for the test failures
c) file a follow-up to turn it on by default when the fails have been addressed. This could be for D9 because of the contrib disruption.

Might be good to ask for a release manager opinion on this last.

We're discussing something similar in DrupalTestTraits, and we have tests for the functionality that could provide inspiration here.

https://gitlab.com/weitzman/drupal-test-traits/-/merge_requests/94

Here I have rerolled patch #4 on D-9.1.x.

Still needs work for tests.

We just committed a version of this on https://gitlab.com/weitzman/drupal-test-traits/-/merge_requests/94 that I think is slightly improved. It takes onboard @lendude's point in #7 about explicit expectation of exceptions, and also has test coverage.

It can be basically copied-pasted back into a patch here. Any thoughts about this @joachim?

1. +++ b/core/tests/Drupal/KernelTests/KernelTestBase.php
   @@ -216,6 +221,16 @@ abstract class KernelTestBase extends TestCase implements ServiceProviderInterfa
   +   * Log level threshold.
   +   *
   +   * Log messages below this will trigger a failing test. Defaults to 'Warning',
   +   * meaning emergency, alert, critical and error will cause the test to fail.
   +   *
   +   * @var int
   +   */
   +  protected $logLevelThreshold = RfcLogLevel::WARNING;
   

   I think it's more intuitive if message of this level OR below trigger exceptions. What do you reckon?

2. +++ b/core/tests/Drupal/KernelTests/KernelTestBase.php
   @@ -239,6 +254,7 @@ protected function setUp() {
   +    $this->container->get('logger.factory')->addLogger($this);
   

   This is not opt in. So it will break half of contrib overnight. From a release management perspective, it'd seem necessary to make this opt-in at first, then have another issue to enable it by default, which would be blocked by all the child issue to cleanup the fails this will expose.

break contrib *tests*, which is not the same thing as breaking contrib. What's the policy on BC for tests?

I've come across #2629286: Use getDisplayName() for user names consistently 188-193 where @alexpott is reluctant to break contrib tests en masse

Looks like this is an issue for the PHPUnit component queue, at this stage

the logged error stops the SUT

Uggh. You're totally right. The current approach is good - better than simply ignoring logged errors silently - but not great.

I'm wondering whether we should change the handling in log() to keep a record of seen errors instead of throwing the exception immediately, and then examine the log in tearDown().

As you suspected, tearDown() is not the right place for this.

What we need to do is:
1. We need our own expectLog() methods that parallel PhpUnit's expectException() etc.
2. When a log is thrown, we immediately thrown an expection if is more severe than the acceptable level AND it is not expected.
3. When a log is thrown, we record it for checking at the end.
4. We override runTest() and append our own log handling, so that when a test ends we can check that we got all the logs we expected to get.

opt-in per test *method*, not test class.

That's why the DTT implemetation has methods to vary acceptable severity level on the fly during a test.

Hmm. That seems like a good idea. Using phpunit mocks it would look something like this:

trait MockLoggerTrait {

  protected $failOnLogsLevel = RfcLogLevel::ERROR;

  protected function createMockLogger($failOnLogsLevel = NULL) {
   $logger = $this->createMock(LoggerInterface::class);

    if (is_null($failOnLogsLevel)) {
      $failOnLogsLevel = $this->failOnLogsLevel;
    }

    $levels = array_keys(RfcLogLevel::getLevels());
    sort($levels);

    foreach ($levels as $level) {
      if ($level >= $failOnLogsLevel) {
        $logger->expects($this->never())
           ->method('log')
           ->with($level);
      }
    }
    
     return $logger;
  }

  protected function addMockLogger() {
    if (is_null($this->mockLogger)) {
      $this->mockLogger = $this->createMockLogger();
    }
    $this->container->get('logger.factory')->addLogger($this->mockLogger);
  }

}

class KernelTestBase extends whatever {

  use MockLoggerTrait;

  protected function setUp() {
    $this->addMockLogger();
    ...
  }

}

class MyTest extends KernelTestBase {

  // WORKS: Make this test fail if any warning is logged.
  protected $failOnLogsLevel = RfcLogLevel::WARNING;  

  protected function myTest() {
   // WORKS: make this test fail if a particular notice is not logged.
    $this->mockLogger->expects($this->once())
      ->method('log')
      ->with(RfcLogLevel::NOTICE, 'my_module');
    ...
    // DOES NOT WORK: allow a single error to happen after a particular point in the test
    $this->mockLogger->expects($this->once())
      ->method('log')
      ->with(RfcLogLevel::ERROR, 'my_module');
   ...
  }

}

We hit the problem that once a phpunit mock has been told that by default something should never happen, we cannot override that in a more specific place.

I've never used prophecy but I think it might be more flexible about this. It's docs say:

Every argument token type has a different score level, which wildcard then uses to calculate the final arguments match score and use the method prophecy promise that has the highest score.... The simple rule of thumb - more precise token always wins.

So it might be possible to make a more specific error message be allowed despite having disallowed errors in general. Anyone familiar enough with prophecy to suggest the correct syntax?

I've done a fair bit with Prophecy, so I'll try to have a play with this later.

Great. I'm happy to keep reviewing and staying with it all the way to RTBC.

I'm vaguely thinking that for Kernel tests, we might end up providing some helper methods to make it easier for developers to set up the logging expectations.

That would be good.

For Functional tests I'm not sure yet. I've definitely thought about the problem of mocking a service in a Functional test, but I don't remember if I came up with a plan for doing that.

I've been trying to wrap my head around https://gitlab.com/weitzman/drupal-test-traits/-/merge_requests/96

What's it's taught me is that since #2664150: Expand BrowserTestBase with error handling support we attempt to transport exceptions from the SUT into PhpUnit, by using Guzzle middleware https://github.com/drupal/drupal/blob/9.0.x/core/lib/Drupal/Core/Test/HttpClientMiddleware/TestHttpClientMiddleware.php that intercepts X-Drupal-Assertion headers added by the SUT.

Searching the codebase for those headers leads me to core/includes/errors.inc which includes

function _drupal_error_handler_real($error_level, $message, $filename, $line, $context) {
  if ($error_level & error_reporting()) {
    ...
    _drupal_log_error(...)
    ...
}

function _drupal_log_error($error, $fatal = FALSE) {
 ...
  // When running inside the testing framework, we relay the errors
  // to the tested site by the way of HTTP headers.
  if (DRUPAL_TEST_IN_CHILD_SITE && !headers_sent() && (!defined('SIMPLETEST_COLLECT_ERRORS') || SIMPLETEST_COLLECT_ERRORS)) {
    _drupal_error_header($error['@message'], $error['%type'], $error['%function'], $error['%file'], $error['%line']);
  }

This appears to get invoked every time anything, even a notice is logged.

So it seems we should have access to all SUT logs in browser test base. What will be different about this is that we won't be able to fail immediately when something is logged, we might have to wait for PhpUnit to process the complete response from the SUT.

We might therefore need 2 traits, one for Kernel tests and a slightly different one for browser tests. Traits are good, they will help us reuse this in Drupal Test Traits which doesn't directly extend BrowserTestBase, and the logic will likely grow to be non trivial by the time we're done with the helper methods.

This seems closely related to #652394: Aggressive watchdog message assertion, unsure if it's an exact duplicate or they just complement each other.

Good spot. I closed #652394: Aggressive watchdog message assertion as a duplicate of this. While it is older, it is so outdated that it's better to work here.

Going back to #30/#32, I think we can do this with a custom logger for tests, a trait (so it is opt-in per class) and assertPostConditions() which conveniently runs after the test but before tearDown().

Proof of concept attached with two test cases, expecting a message and expecting no message. We can add other expectations around log levels, matching messages with regex, etc.

If we want to explicitly say "expect no log messages" we could add a separate method for that instead of expecting it by default.

I also think the functional test version will be quite different so wonder if it's worth spinning off a new issue for that?

(Sorry, cross-posted with @longwave, didn't mean to hide file and not responding to him)

I had a moment of doubtabout the mock logger approach. Before we go too far down it we need to make sure that it will allow us to adjust expectations party way through as test as nimbly as we might want to.

For example:
public function myTest() {

$this->expectNoLogs(Error);
// Some code here. Warnings OK, errors not.

$this->expectNoLogs(Warning);
//Some code here. Warnings now not OK.

$this->expectNoLogs(Error);
//Some code here. Warnings now OK.

//$this->expectLog(Error, my_module)
// Should still be failing on warnings, but this specific error is allowed.

}

The hardest thing is to de-escalate negative expectations, the transition from disallowing warnings to no longer disallowing warnings.

I think we're OK, as long as our mock logger callback can have a reference to a property of the test class that tracks the currently allowed log level.

@longwave thanks for introducing me to both assertPostConditions() and expectNotToPerformAssertions(), nice.

I'm a bit uncomfortable with overriding assertPostConditions() in a trait, that could have consequences that people using the trait don't expect. e.g. if they also define assertPostConditions() in the test class. But we could have an assertLogExpectationsMet() in the trait, and then call that from assertPostConditions() in the base class(es) when we add the trait to the base classes.

I think we can move forward with defining the trait and the API we're trying to add here, even before resolving this question of how exactly we trigger failure.

How's this for our API:

function expectLog($severity = 'UNSPECIFIED', $channel = 'UNSPECIFIED', $message = 'UNSPECIFIED') {
  $this->expectLogs($severity, $channel, $message, 1);
}

function expectLogs($severity = 'UNSPECIFIED', $channel = 'UNSPECIFIED', $message = 'UNSPECIFIED', $count = NULL) {
  $this->expectedLogs[$severity][$channel][$message] = $count;
}

function expectNoLogs($severity = 'UNSPECIFIED', $channel = 'UNSPECIFIED', $message = 'UNSPECIFIED') {
  $this->unwantedLogs[$channel][$message] = $severity;
}

// Call when a log is received.
function handleLog($severity, $channel, $message) {
  if (isset($this->expectedLogs[$severity][$channel][$message])) {
     if (!is_null($this->expectedLogs[$severity][$channel][$message])) {
        $this->expectedLogs[$severity][$channel][$message] = $this->expectedLogs[$severity][$channel][$message] - 1;
     }
     if ($this->expectedLogs[$severity][$channel][$message] === 0) {
        unset($this->expectedLogs[$severity][$channel][$message]);
     }
  }
  else {
    $this->assertNoUnwantedLogsMatching($severity, $channel, $message);
  }
}

function assertNoUnwantedLogsMatching($severity, $channel, $message) {
  $unwantedMessages = $this->unwantedLogs[$channel];
  foreach($unwantedMessages as $unwantedMessage => $unwantedSeverity) {
    if ($unwantedMessage == $message && $unwantedSeverity >= $severity) {
      $this->fail("Log message received: $severity $channel $message");
    }
  }
}

// Call at end of test.
function assertLogExpectationsMet() {
  $this->assertEmpty($this->expectedLogs);
}

I got @drumm to enable issue forks for this issue, so we have that to play with.

The issue summary appears to be up-to-date, removed the "Needs issue summary update" tag.

I can't see where to make a new fork for this issue to work on it though :/

Use the existing fork and create a new branch and MR.

Sorry, I collided with you on this.

I have improved the docs. More importantly, I have added the trait to KernelTestBase.

The implementation as it stands is completely opt-in and should not break any core or contrib tests (unless they have a method name collision with the trait).

In follow-up issues we can:
- throw a deprecation error in KernelTestBase if tests generate logged errors without explicitly expecting them
- add expectations to any core tests that generate logged errors
- one day remove the deprecation error and simply add expectNoLog(RfcLogLebel::ERROR) ins KernelTestBase::setUp() so that that tests extending from KernelTestBase will fail if they generate logged errors that they have not more specifically expected.

why do we need a trait for this

A lot (most) of this trait is probably still relevant to functional tests. And it could be used in ExistingSite tests, which don't extend KernelTestBase. Probably most importantly, doesn't it make things easier to understand if the log is organised into a trait rahter than making the base class even longer?

I think threshold expectations should be checked at the end, rather than fail the test as soon as a single bad log is received. I know this is following the pattern of expectException(), but with exceptions you have no choice but to stop when one is thrown. With logs, we can keep going. This is better DX, because it means a developer can fix ALL the bad log problems before running the tests again.

If we fail immediately if a unexpected error is logged, then the stacktrace pinpoints the cause. I think this probably outweights the sensible reasons for deferring you give.

What are the pros and cons of using the test class as the logger vs. using a separate logger class

If it's good to fail immediately if a unexpected error is logged, this requires the logger to be able to have access to the allowed and expected logs defined in the test.

I suppose we could pass these off to the logger from the test, instead of storing them on the test.

I do kind of like the idea of having as much as possible outside the test class, shall we give this a try?

Should we be concerned about running out of memory by storing all the log messages in a class property?

I can't see how, assuming things are properly cleaned pu between tests. But anyway, we're not storing the log messages, the current implementation only stores the rules about the expected/allowed/disallowed logs, not the actual logs received.

I've realised that expectNoLogMoreSevereThan() is the wrong name to use.

This is because the current implementation is designed so that ::expectNoLogMoreSevereThan(RfcLogLevel::WARNING) will fail on warnings and errors, not just errors.

We could change the implementation but I think it's more natural and direct to pass as parameter the severity one does not want to have logged, rather than passing the level immediately below it.

::expectNoLogOfSeverityGreaterThanOrEqualTo() seems just silly. We could have ::expectNoLogOfSeverity() but I don't see how that is really better than ::expectNoLog().

I suggest we revert back to ::expectNoLog().

I've realised that expectNoLogMoreSevereThan() is the wrong name to use.

I think expectNoLog is misleading.

I've implemented expectNoLogsAsSevereAs() which I think might satisfy your concern but is tolerably concise.

I've had to completely rework the implementation to check for generated but disallowed logs at the end of the test, not immediately when they're thrown. This is the approach we previously rejected in #61 / 63. The reason I've done it is that I've realised that it's not OK for the test to throw ExpectationFailedExceptions when acting as a logger and processing logs during test execution. This is because log handling is part of the System-Under-Test, and we can't predict how the SUT will handle these exceptions our test logger is generating. It may well catch and suppress them, so they never bubble up into the original test execution context.

This does leave us with the problem I raised in #63, that we would not have the stacktrace available to indicate which code in the test triggered the log. However, there are workarounds for this. We could capture the stacktrace when the logs are generated, and store it with the record of logs generated during the test. I haven't implemented this yet, but it will be easy to do if people are happy with the rest of the approach here.

The fail is random, this is now complete and green.

The fail is random

@alexpott asked for a reroll onto 10.0, but that's beyond my gitfu.

This looks super useful. Nice one. I've added a load of comments to the MR. All quite minor things to fix. I think we should add a CR to inform developers about this and the fact they can use this in Kernel tests.

CR done: https://www.drupal.org/node/3280722

The MR 2903456-for-9.4 should be good as is.

The MR 2903456-1 needs someone to reroll it onto 10.x

Added primitive type hints. The changes since #72 are basically docs, typehints and coding stamdards, so this is RTBC once the bot is happy.

MR!14 for 10.0 is unhappy has become unhappy and is claiming it's not mergeable, but nothing has changed to make that happen. Maybe it needs a reroll.

The test fail is random.

Hmmm. I think this matters

Approach A

#89 revisits the debate from #30 / 32 about whether our logger should throw exceptions so test execution can be halted immediately. We decided not to do this, because the SUT can catch exceptions and so throwing them in the logger is not a reliable way to cause a test to fail.

However we could combine this approach with approach of inspecting the logs in assertPostConditions(). We could store a record of the log, throw an exception if it was unexpected, and then inspect the logs in assertPostconditions() and trigger failure if appropriate in case the thrown exception was caught and didn't stop the test earlier.

One concern I have here is sequencing. If a test generates 2 logs errors, and the exception from the first is caught but that from the second is not, then test execution would stop with the second log and assertPostConditions() would be skipped and the first log (more likely to be the root cause) would be unreported. We might be able to make this sort of OK with better reporting, but it's not trivial.

The other concern I have is that SUT code that catches the exception thrown by our logger could itself then try to log that exception. Which would lead to extra logs being reported in a slightly messy way. More generally, this approach is more invasive of the SUT and hence liable to odd side-effects like this.

This approach would also not help with cron either, because that is an example of a SUT that catches exceptions.

Balance against all of that, in the 95% use case this would give more timely and useful reporting of the root cause of a test failing.

Approach B

If we could find a way to report the disallowed logs whenever a test ended early due to assertion failure, that would seem like a robust solution.

We could do this:

protected function runTest() {
  try {
    parent::runTest();
  }
  catch (AssertFailedException($e)) {
    // Add some output here, maybe by adding to the exception message.
    throw $e;
  }
}

or maybe even better just this:

    /**
     * Returns the status message of this test.
     *
     * @return string
     */
    public function getStatusMessage()
    {
      if ($this->hasFailed()) {
        $logs = $this->getAssertableLogger()->getDisallowedLogs();
        if ($logs) {
        }
        return $this->statusMessage . print_r($this->getAssertableLogger()->getDisallowedLogs(), TRUE));
      }
        return $this->statusMessage;
    }

Approach C

If we don't want to do any of this, we could add a method like this to LoggingTrait:

  /**
   * Assert that no logs were received that should not have been.
   */
  protected function assertNoDisallowedLogs(): void {
    if ($this->getAssertableLogger()) {
      $this->assertEmpty($this->getAssertableLogger()->getDisallowedLogs(), "Logs were generated during the test that were explicitly expected not to be generated. " . print_r($this->getAssertableLogger()->getDisallowedLogs(), TRUE));
    }
  }

This would allow test code to do more frequent checking for bad logs to assist debugging.

Going to look at approach B next.

Yeah, I quite like the version of #90 B that overrides getStatusMessage.

FWIW a cruder version of this kind of functionality was implemented in Drupal Test Traits:
https://gitlab.com/weitzman/drupal-test-traits/-/merge_requests/110/diffs

I've just discovered Psr\Log\Test\TestLogger, in the psr/log package.

Yes! See #3321905: Add colinodell/psr-test-logger to core's dev dependencies. Previously this was very crude, but it's now matured to do exactly the kind of thing we want here, so yay!

Let's postpone on #3321905: Add colinodell/psr-test-logger to core's dev dependencies.

See #3321905-9: Add colinodell/psr-test-logger to core's dev dependencies for news there.

#3321905: Add colinodell/psr-test-logger to core's dev dependencies got committed, so we're unblocked.

For anyone looking for a workaround while waiting for this to be fixed, here's the setup I'm using based on the BufferingLogger and tying it to my logger channel.

mymodule/tests/Kernel/MyModuleTestBase.php

namespace Drupal\Tests\mymodule\Kernel;

use Drupal\Core\DependencyInjection\ContainerBuilder;
use Drupal\Core\Logger\RfcLogLevel;
use Drupal\KernelTests\Core\Entity\EntityKernelTestBase;
use Symfony\Component\ErrorHandler\BufferingLogger;

/**
 * Base class for setting up MyModule tests.
 *
 * @group mymodule
 */
abstract class MyModuleTestBase extends EntityKernelTestBase {

  /**
   * The entity type manager service.
   *
   * @var \Psr\Log\LoggerInterface
   */
  protected $logger;

  /**
   * {@inheritdoc}
   */
  public function register(ContainerBuilder $container) {
    parent::register($container);
    $container
      ->register('logger.channel.mymodule', BufferingLogger::class)
      ->addTag('logger');
  }

  /**
   * {@inheritdoc}
   */
  protected function setUp(): void {
    parent::setUp();

    $this->logger = $this->container->get('logger.channel.mymodule');

    // Clean any existing logs.
    $this->logger->cleanLogs();
  }
  
  /**
   * Verify that no logs were written worse than a certain level.
   *
   * @param string $minLogLevel
   *   The RfcLogLevel name that is the minimum allowed. One of:
   *   EMERGENCY, ALERT, CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG
   * @param string $message
   *   An optional message to print.
   *
   * @return array
   *   The logs in our logger for further examination.
   */
  protected function assertNoLogsWorseThan(string $minLogLevel, string $message = NULL): array {
    $logs = $this->logger->cleanLogs();
    $rfcLogLevels = new \ReflectionClass(RfcLogLevel::class);
    $minLogLevelText = strtoupper(trim($minLogLevel));
    $this->assertContains($minLogLevelText, array_keys($rfcLogLevels->getConstants()), "\$this->assertLogsNoWorseThan(\$minLogLevel): \$minLogLevel=$minLogLevel is not one of ".implode(", ", array_keys($rfcLogLevels->getConstants())));
    $minLogLevelInt = $rfcLogLevels->getConstant($minLogLevelText);
    foreach ($logs as [$level, $message, $context]) {
      $level = trim($level);
      $logLevelText = strtoupper($level);
      $logLevelInt = $rfcLogLevels->getConstant($logLevelText);
      $this->assertGreaterThanOrEqual($minLogLevelInt, $logLevelInt, "Log worse than $minLogLevel recorded: [$level] ".$this->getLogMessage($level, $message, $context));
    }
    return $logs;
  }

  /**
   * Assert that a log matching the level and regular expression exists.
   *
   * @param string $level
   *   The RfcLogLevel name that is the minimum allowed. One of:
   *   EMERGENCY, ALERT, CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG
   * @param string $regex
   *   A regular expression to log.
   * @param array $logs
   *   An optional array of logs to examine for multiple checks. If not passed
   *   logs will be cleared from the logger.
   * @param string $message
   *   An optional message to print.
   *
   * @return array
   *   The logs in our logger for further examination.
   */
  protected function assertLogsMatchingRegex(string $level, string $regex, $logs = NULL, string $message = NULL): array {
    if (!is_array($logs)) {
      $logs = $this->logger->cleanLogs();
    }
    $found = FALSE;
    $messages = [];
    foreach ($logs as [$logLevel, $logMessage, $logContext]) {
      $messages[] = $logLevel . "\t" . $logMessage;
      if (strtolower($logLevel) == strtolower($level) && preg_match($regex, strval($logMessage))) {
        $found = TRUE;
        break;
      }
    }
    if ($message) {
      $this->assertTrue($found, $message);
    }
    else {
      $this->assertTrue($found, "Expected a message of level $level matching $regex but didn't find one in:\n\t" . implode("\n\t", $messages));
    }
    return $logs;
  }
  /**
   * Answer message string from a BufferingLogger entry.
   *
   * Copied from BufferingLogger::__destruct().
   *
   * @param string $level
   *   The log level string.
   * @param string $message
   *   The message with placeholders.
   * @param array $context
   *   An array of placeholders to place in the message.
   *
   * @return string
   *  The formatted output.
   */
  public function getLogMessage($level, $message, $context) {
    if (str_contains($message, '{')) {
      foreach ($context as $key => $val) {
        if (null === $val || \is_scalar($val) || (\is_object($val) && \is_callable([$val, '__toString']))) {
          $message = str_replace("{{$key}}", $val, $message);
        } elseif ($val instanceof \DateTimeInterface) {
          $message = str_replace("{{$key}}", $val->format(\DateTimeInterface::RFC3339), $message);
        } elseif (\is_object($val)) {
          $message = str_replace("{{$key}}", '[object '.get_debug_type($val).']', $message);
        } else {
          $message = str_replace("{{$key}}", '['.\gettype($val).']', $message);
        }
      }
    }
    return $message;
  }
}

Then in my kernel tests I can execute some code and then something like:

    $this->assertNoLogsWorseThan('debug');

Which will result in an error like:

Log worse than debug recorded: [info] person: Created jdoe@middlebury.edu 00000001. User 1
Failed asserting that 6 is equal to 7 or is greater than 7.

If I need to examine logs more closely to look for an expected warning message, I can use something like:

    // Ensure that a warning about our conflict was logged.
    $logs = $this->assertNoLogsWorseThan('warning');
    $this->assertLogsMatchingRegex('warning', '/^Error syncing person\. ID: 00000009/', $logs);

Which will result in an error message like the following:

Expected a message of level warning matching /^Error syncing person\. PIDM: 00000009/ but didn't find one in:
        info    person: Created jdoe@middlebury.edu 00000001. User 1
        warning Error syncing person. PIDM: 00000002 Error: Found an existing account matching name or mail=jdoe@middlebury.edu [1] that was created during the past year. Skipping auto-rename of old account.
        info    person: Created rjones@middlebury.edu 00000003. User 2
        info    person: Created ldoe@middlebury.edu 00000004. User 3
        info    person: Synced all people. 4 total, 3 changed, 1 failed.

This isn't completely generalized and has the ugly need to pass logs to do multiple checks, but the DX isn't terrible in my actual tests.

Regarding the open question of when and how to fail tests for log errors, I am starting to think if we need *both* flavours -- fail immediately on log, AND fail if log errors are found in tearDown().

I agree that failing on both is an acceptable solution to the concern about immediate failing raised in #67.

But I remain nervous about immediate failing because it runs the risk of changing the code flow in the SUT. If the log throws an exception, and the exception is caught in the SUT, the code will flow down pathways it may not otherwise have done. So the test could fail with a different exception error from the SUT or an assertion failure that would not have been shown if we had not thrown an exception on the log. This would be unexpected behavior for developers and could be confusing for people trying to debug test failures.

I hadn't imagined our logger would call this->fail() instead of just throwing some exception, but you make a good case why even that wouldn't help. So yes, we're on the same page.

I wonder whether our logger can keep track of the fact that it failed the test on a log error, and then check for that in tearDown.

That sounds like what I called "failing on both".

Maybe if the log exception was caught and we didn't catch it until the end of the test we could completely suppress phpunits normal error/assertion failure messaging and replace it with our unexpected log message, so that the developer was never exposed to the potentially misleading messages.

tearDown() isn't quite the right place maybe. See #90, especially #90.B that suggests to tinker with getStatusMessage() to append logs to it.

I was just trying to write a functional test that asserts that a log message emitted by my SUT is correct and ran smack into this issue. I gave the patch a try and have not had much success. I might be in the minority here, but I found the description and instructions on the trait to be unclear:

/**
 * Sets test expectations for generated log messages.
 *
 * A test class using this trait should:
 * - ensure that AssertableLogger::log() is called when logs are generated,
 * - provide a getAssertableLogger() method that returns that logger, and
 * - call LoggingTrait::assertLogExpectationsMet(), typically in its
 * assertPostConditions() method.
 *
 * In order to assert that a test does or does not generate logs, the test
 * must call LoggingTrait::expectLog() or
 * LoggingTrait::expectNoLogsAsSevereAs(); it may also call
 * LoggingTrait::allowLogsAsSevereAs().
 */

Here's what is unclear:

• "ensure that AssertableLogger::log() is called when logs are generated" -- wouldn't the SUT be the one logging errors, not the test? Or is this a method I am supposed to call before or after the code I am testing? I do not understand what this means.
• "provide a getAssertableLogger() method that returns that logger" -- by that logger, what logger are we talking about?
• "In order to assert that a test does or does not generate logs, the test must call LoggingTrait::expectLog() or LoggingTrait::expectNoLogsAsSevereAs(); it may also call LoggingTrait::allowLogsAsSevereAs()." -- when must these be called? Before the code being tested? After it?

@GuyPaddock see the proposed changes to KernelTestBase, and the usage in KernelTestBaseTest.
Answers:
1. Yes, the SUT logs. But you have to add this new logger to the SUT somehow to make the logs from the SUT available outside it in the test.
2. The assertable one added in the SUT
3. As per the phpunit methods with similar names, like expectException()

We can convert \Drupal\KernelTests\Core\Extension\ModuleInstallerTest, \Drupal\Tests\system\Kernel\SecurityAdvisories\SecurityAdvisoriesFetcherTest and \Drupal\KernelTests\Core\Config\ConfigImporterMissingContentTest are converted to use this.

At the moment this trait has an architectural flaw - the logging expectations do not survive a container rebuild which they need to.

#116 is resolved and tested.

Next time I will use search better.
I tried to do pretty similar thing but with different approach at #3496184: Replace usage of dblog module at tests with alternative.
And I am very happy about approach used at this issue. Having this at Kernel test by default will improve DX a lot, because now there are tons of different ways doing this.

I would suggest not to replace tokens at message, but keep original message and provide tokens value. Because at FormattableMarkup::placeholderFormat token values can be escaped and wrapped with <em class="placeholder"></em>.
And we are not checking message display but provided values.
And it much easy to search message source.

You can check example at MR 10863, but here is some code for short example.

     $expected_message = [
      'message' => "View display '@id': Comment field formatter '@name' was disabled because it is using the comment view display '@display' (@mode) that was just disabled.",
      'context' => [
        '@id' => $host_display_id,
        '@name' => $field_name,
        '@display' => EntityViewMode::load("comment.$mode")->label(),
        '@mode' => $mode,
      ],
    ];
    $this->assertTrue($logger->hasRecord($expected_message, RfcLogLevel::WARNING));

The MR is 1280+ commits behind head, needs a rebase.

I think #120 is interesting, possibly simpler than some of the alternatives suggested in #90, because it makes use of phpunit's exception reporting.

However, it seems like it would do a bad job at handling multiple logged errors, because we could only rethrow one.

So while capturing the backtrace in the logger is necessary, I'm not sure rethrowing is what's needed.

#123 makes sense to me. In which case, yes, #120 seems good.

We need to identify the right point to trigger the rethrowing, before the test begins to output information about assertion failures, as these may be subsequent to the original exception and so confusing.

I find that even as someone who's spent hours working on solutions for this problem in the past, when I read the suggested DX, my mind is completely blank as to what the difference is, until I read the comments. That seems like a bad sign! Are you convinced this is necessary?

One thing I like to see in a test log system is the concept of marking log messages as "read".
I do this whenever I implement my own custom test logging helper for a custom or contrib project.

This is especially useful in a test that goes through multiple subsequent operations or steps, which is common in Drupal tests.
It helps to not get confused with messages from previous operations.
It also helps to not get confused with log messages from Drupal install.

Like this:

1. Create a node type "page".
2. Mark all non-error messages as read.
3. Visit node/add/page.
4. Assert unread log message "no access", and mark as read.
5. Login as admin.
6. Assert unread log message "logged in", and mark as read.
7. Visit node/add/page, again.
8. (assert no further unread log messages)
9. Fill form and submit.
10. Assert unread log message "node was created", and mark as read.
11. Edit the node. Submit.
12. Assert unread log message "node was updated", and mark as read.
13. In tearDown(), assert that no further unread log messages with failure exist, OR that not any unread log messages exist.

The "assert next unread and mark as read" can be implemented as an atomic operation.
Whenever this is called, we can also assert that no failure log messages exist (warning, error etc).
I wrote a PoC of this in #3274834: Allow functional tests to fail or expect logged errors, using dblog as backend. Still WIP.
The "mark as read" does not need any additional storage, because the test itself is the only thing that needs to know about it.

One thing I like to see in a test log system is the concept of marking log messages as "read".
I do this whenever I implement my own custom test logging helper for a custom or contrib project.

Changing my mind from previous post:

• We should call ->expectLogMessage() before it occurs, rather than calling "->assertLogMessageExists()" after it occurs.
• We queue up expectations for log messages, and then "consume" them when we find matching messages in the log.
• A queued log expectation has a match condition and then an assert condition.
  If the expectation match condition does not match, it is kept in the queue.
  If the match condition matches but the assert condition does not, it produces a failure.
• Conditions for match and assert can be callbacks, to allow for dynamic conditions for match and assert, e.g. if some parts of the log message are not hard-predictable or it would make the test too rigid.
• We store an expected count with each expectation.
  On a match, we count down.
  On zero, we remove the expectation.
  Negative numbers allow for infinite matches.
  We can use -1 for "at least one match", and lower negative numbers for "any number or zero matches".
• We match the logs to expectations automatically at strategic moments, e.g. in functional tests we can do it after we receive a page response. In those places we fail on unexpected log messages, but not on unmatched expectations.
• At the end of a test we fail for unmatched expectations.

If the match condition matches but the assert condition does not, it produces a failure.

Do you mean that we store this for a subsequent check, or the end of the test, or that we fail immediately?

We fail at the moment when we compare actual logged messages to the queued expectations.
This would mean:

• In a kernel test, most of the time we can do it immediately when ->log() is called.
  For a failure, we can just Assert::fail() or a regular Assert::assertSame() etc, the original ->log() call will naturally be in the stack trace.
• In a functional test, we have to store the log somewhere persistent at first.
  Like dblog/watchdog, but it could be a separate solution without a module. And it should store a backtrace every time, and additional metadata similar to dblog.
  Then in the test, we can load the stored messages at strategic moments, and compare them against expectations.
  E.g. it could trigger automatically after a server request, and at the end of a test.
  On failure, we need to add metadata to the failure message:
  - This log happened in a web request to (url).
  - The original stack trace was this: (trace)
  - Show metadata stored with the log record.

The expectations queue only needs to exist in the test process. It does not need to be persisted. Therefore it is safe for it to contain callbacks.

EDIT: I realize we need some kind of buffer even in kernel tests, because, as you say, exceptions (and test failures) may be caught.