Allow kernel tests to fail or expect logged errors

📌 Add colinodell/psr-test-logger to core's dev dependencies Fixed 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.

I've revisited this recently, and I think it's becoming more important in light of the drive to have kernel tests that make HTTP requests. I was sure there was a core issue for this, but I can't find it -- only the more general 🌱 [META] Convert some tests into Kernel or Unit tests Active , and this docs page: https://www.drupal.org/docs/automated-testing/phpunit-in-drupal/making-h... →

If you make an HTTP request in a kernel test, you should obviously be checking the response status is a 200, but if it's not, the problem is obscured, as the HTTP kernel catches exceptions to return the 500 response.

Therefore, if you're not expecting a 500 error, you want the test to fail when the error is logged, rather than when you check the status of the HTTP response.

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().

Failing immediately on a log error can be done by registering the test class itself as a logger -- here's some quick and unsubtle code that does it; obviously it needs refining to allow for expected errors:

    $this->container->get('logger.factory')->addLogger($this);

SNIP

  public function log($level, string|\Stringable $message, array $context = []): void {
    $message = strtr($message, $context);

    $level_label = \Drupal\Core\Logger\RfcLogLevel::getLevels()[$level];
    $this->fail("Log $level_label: $message");
  }

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 think I see what you mean - simplified, something like this:

    // Some SUT code that is catching exceptions.
    try {
      // Somewhere inside this block we log an error, and that causes the 
      // test class's log handling to fail the test like this:
      $this->fail();
    }
    catch (\Exception $e) {
      // Our SUT code caught PHPUnit's failure exception (AssertionFailedError extends Exception) and can continue! YAY :(
    }

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. If there's a discrepancy, it can THEN fail the test and say 'log test failures are being caught somewhere'. That would then allow a developer to investigate in the right place.

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.

I had a go at using tearDown() to handle cases where the logger triggering a test failure gets swallowed by a catch() in the SUT. Here's a sandbox I made: https://github.com/joachim-n/test-2903456-test-logging

Do composer install and then `vendor/bin/phpunit`. All tests should fail because of the logged error!

It works, but for the case where the test goes on to fail for another reason, PHPUnit registers two failures.

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()

alexpott → changed the visibility of the branch 2903456-1 to hidden.

alexpott → changed the visibility of the branch 2903456-for-9.4 to hidden.