How to properly log custom exceptions?

Question

I'm trying to improve the code quality of my custom module by adding custom exceptions. Before, I was lazy and throwing \Exception everywhere, but I recently refactored all my code to use custom exceptions.

In mymodule/src/Exception, I created MyModuleException:

class MyModuleException extends \Exception {
}

And then several additional exceptions such as MyModuleLogicException and MyModuleOutOfBoundsException, which extend MyModuleException.

Then I made an EventSubscriber to log the exceptions:

<?php

namespace Drupal\mymodule\EventSubscriber;

use Drupal\Core\Http\Exception\CacheableAccessDeniedHttpException;
use Drupal\Core\Logger\LoggerChannelFactoryInterface;
use Symfony\Component\EventDispatcher\EventSubscriberInterface;
use Symfony\Component\HttpFoundation\Response;
use Symfony\Component\HttpKernel\Event\ExceptionEvent;
use Symfony\Component\HttpKernel\KernelEvents;
use Webmozart\Assert\InvalidArgumentException;

/**
 * Event subscriber MyModuleExceptionSubscriber.
 */
class MyModuleExceptionSubscriber implements EventSubscriberInterface {
    
  /**
   * Implement with a priority higher than 50.
   *
   * Must run before Drupal\Core\EventSubscriber\ExceptionLoggingSubscriber.
   */
  const PRIORITY_HIGHER_THAN_50 = 60;

  /**
   * Logger factory.
   *
   * @var \Drupal\Core\Logger\LoggerChannelFactoryInterface
   */
  protected LoggerChannelFactoryInterface $logger;

  /**
   * MyModuleExceptionSubscriber constructor.
   *
   * @param \Drupal\Core\Logger\LoggerChannelFactoryInterface $logger
   *   The logger factory interface.
   */
  public function __construct(LoggerChannelFactoryInterface $logger) {
    $this->logger = $logger;
  }

  /**
   * Log my custom exceptions.
   *
   * @param \Symfony\Component\HttpKernel\Event\ExceptionEvent $event
   *   The event to process.
   */
  public function onException(ExceptionEvent $event): void {
    $exception = $event
      ->getThrowable();

    if ($exception instanceof MyModuleException) {
      $this->logger->get('mymodule_exception')->error($this->getErrorMessage($exception));
      $response = new Response("Something bad happened!", 500);
      $event->setResponse($response);
    }
  }

  /**
   * {@inheritDoc}
   */
  public static function getSubscribedEvents(): array {
    $events = [];
    $events[KernelEvents::EXCEPTION][] = [
      'onException',
      self::PRIORITY_HIGHER_THAN_50,
    ];
    return $events;
  }

  /**
   * Generate a useful error message to log an exception.
   *
   * @param \Exception $exception
   *   The exception to generate an error message for.
   *
   * @return string
   *   The generated error message.
   */
  private function getErrorMessage(\Exception $exception): string {
    $exception_class = get_class($exception);
    return "Class: $exception_class <br>Message: " .
      $exception->getMessage() .
      "<br>File: " .
      $exception->getFile() .
      "<br>Line number: " .
      $exception->getLine() .
      "<br>Stack trace:<br>" .
      $exception->getTraceAsString();
  }
    
}

Then I ran some behat tests and triggered all the different types of exceptions.

What I found was that in most cases, the custom exceptions were logged correctly by my exception event subscriber.

However, for exceptions thrown from code running in a hook_node_presave() or hook_node_insert(), the logs show the exception as a standard php exception, so they are not getting picked up by my event subscriber:

Drupal\Core\Entity\EntityStorageException: My custom exception message Drupal\Core\Entity\Sql\SqlContentEntityStorage->save() (line 811 of /app/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorage.php).

I think the problem is that the event subscriber is only seeing uncaught exceptions, and so my custom exceptions are getting caught in Drupal's entity saving logic and then getting rethrown as a generic PHP exception.

I implemented the exception event subscriber because I thought that would be a lot less code (put the logging logic in one place and handle all exceptions as they come in), since all my exceptions are fatal and don't need to be caught.

But, because of this, Drupal is catching the exceptions for me and replacing my custom exception messages with generic Drupal ones.

So the question is: what's the best practice to ensure that I get a custom log message whenever one of my exceptions is thrown? I could write a try/catch block for every exception and then put the logging logic in the catch block, but that seems like a lot of extra code. Is there a more elegant way to handle this?

Answer 1

If a try/catch block is implemented correctly and preserves the original exception like in the mentioned example of the entity save operation:

SqlContentEntityStorage::save()

  public function save(EntityInterface $entity) {
    $transaction = $this->database->startTransaction();
    try {
      ...
    }
    catch (\Exception $e) {
      $transaction->rollBack();
      ...
      throw new EntityStorageException($e->getMessage(), $e->getCode(), $e);
    }
  }

the originally thrown exception is stored as third parameter in the newly thrown exception.

Then your EventSubscriber can get the original exception by running getPrevious() recursively (in case the exception you've raised is nested in multiple try/catch blocks):

public function onException(ExceptionEvent $event) {
  $exception = $event->getThrowable();
  $original_exception = $exception;
  while ($original_exception->getPrevious()) {
    $original_exception = $original_exception->getPrevious();
  }
  if ($original_exception instanceof MyModuleException) {
    // your code logging the exception
  }
}