From d7313cce1965c3407a20773c3b79740be20b8983 Mon Sep 17 00:00:00 2001 From: catch <catch@35733.no-reply.drupal.org> Date: Thu, 16 Mar 2023 16:08:23 +0000 Subject: [PATCH] Issue #3313355 by mondrake, mfb, Anchal_gupta, daffie, larowlan, alexpott: Allow the database query log to be dispatched as log events --- core/core.services.yml | 3 + core/lib/Drupal/Core/Database/Connection.php | 158 +++++++++++++ core/lib/Drupal/Core/Database/Database.php | 10 + .../Core/Database/Event/DatabaseEvent.php | 24 ++ .../Event/StatementExecutionEndEvent.php | 54 +++++ .../Event/StatementExecutionStartEvent.php | 41 ++++ .../StatementExecutionSubscriber.php | 38 +++ .../Database/Exception/EventException.php | 11 + core/lib/Drupal/Core/Database/Log.php | 59 +++-- .../Core/Database/StatementPrefetch.php | 29 ++- .../Drupal/Core/Database/StatementWrapper.php | 29 ++- core/lib/Drupal/Core/Utility/Error.php | 4 +- .../database_test/database_test.services.yml | 5 + .../DatabaseEventSubscriber.php | 61 +++++ .../Core/Database/DatabaseEventTest.php | 82 +++++++ .../KernelTests/Core/Database/LoggingTest.php | 5 + .../Tests/Core/Database/ConnectionTest.php | 221 ++++++++++++++++++ .../Core/Database/DatabaseEventsTest.php | 79 +++++++ .../Drupal/Tests/Core/Database/LogTest.php | 11 +- 19 files changed, 895 insertions(+), 29 deletions(-) create mode 100644 core/lib/Drupal/Core/Database/Event/DatabaseEvent.php create mode 100644 core/lib/Drupal/Core/Database/Event/StatementExecutionEndEvent.php create mode 100644 core/lib/Drupal/Core/Database/Event/StatementExecutionStartEvent.php create mode 100644 core/lib/Drupal/Core/Database/EventSubscriber/StatementExecutionSubscriber.php create mode 100644 core/lib/Drupal/Core/Database/Exception/EventException.php create mode 100644 core/modules/system/tests/modules/database_test/database_test.services.yml create mode 100644 core/modules/system/tests/modules/database_test/src/EventSubscriber/DatabaseEventSubscriber.php create mode 100644 core/tests/Drupal/KernelTests/Core/Database/DatabaseEventTest.php create mode 100644 core/tests/Drupal/Tests/Core/Database/DatabaseEventsTest.php diff --git a/core/core.services.yml b/core/core.services.yml index 3beafcd932cf..aa09c6a4d482 100644 --- a/core/core.services.yml +++ b/core/core.services.yml @@ -415,6 +415,9 @@ services: tags: - { name: event_subscriber } Drupal\Core\Database\ReplicaKillSwitch: '@database.replica_kill_switch' + Drupal\Core\Database\EventSubscriber\StatementExecutionSubscriber: + tags: + - { name: event_subscriber } datetime.time: class: Drupal\Component\Datetime\Time arguments: ['@request_stack'] diff --git a/core/lib/Drupal/Core/Database/Connection.php b/core/lib/Drupal/Core/Database/Connection.php index b6f7968dcf86..75966d7fcbc8 100644 --- a/core/lib/Drupal/Core/Database/Connection.php +++ b/core/lib/Drupal/Core/Database/Connection.php @@ -3,6 +3,8 @@ namespace Drupal\Core\Database; use Drupal\Component\Assertion\Inspector; +use Drupal\Core\Database\Event\DatabaseEvent; +use Drupal\Core\Database\Exception\EventException; use Drupal\Core\Database\Query\Condition; use Drupal\Core\Database\Query\Delete; use Drupal\Core\Database\Query\Insert; @@ -216,6 +218,14 @@ abstract class Connection { */ protected $identifierQuotes; + /** + * Tracks the database API events to be dispatched. + * + * For performance reasons, database API events are not yielded by default. + * Call ::enableEvents() to enable them. + */ + private array $enabledEvents = []; + /** * Constructs a Connection object. * @@ -1867,4 +1877,152 @@ public function hasJson(): bool { } } + /** + * Returns the status of a database API event toggle. + * + * @param string $eventName + * The name of the event to check. + * + * @return bool + * TRUE if the event is going to be fired by the database API, FALSE + * otherwise. + */ + public function isEventEnabled(string $eventName): bool { + return $this->enabledEvents[$eventName] ?? FALSE; + } + + /** + * Enables database API events dispatching. + * + * @param string[] $eventNames + * A list of database events to be enabled. + * + * @return static + */ + public function enableEvents(array $eventNames): static { + foreach ($eventNames as $eventName) { + assert(class_exists($eventName), "Event class {$eventName} does not exist"); + $this->enabledEvents[$eventName] = TRUE; + } + return $this; + } + + /** + * Disables database API events dispatching. + * + * @param string[] $eventNames + * A list of database events to be disabled. + * + * @return static + */ + public function disableEvents(array $eventNames): static { + foreach ($eventNames as $eventName) { + assert(class_exists($eventName), "Event class {$eventName} does not exist"); + $this->enabledEvents[$eventName] = FALSE; + } + return $this; + } + + /** + * Dispatches a database API event via the container dispatcher. + * + * @param \Drupal\Core\Database\Event\DatabaseEvent $event + * The database event. + * @param string|null $eventName + * (Optional) the name of the event to dispatch. + * + * @return \Drupal\Core\Database\Event\DatabaseEvent + * The database event. + * + * @throws \Drupal\Core\Database\Exception\EventException + * If the container is not initialized. + */ + public function dispatchEvent(DatabaseEvent $event, ?string $eventName = NULL): DatabaseEvent { + if (\Drupal::hasService('event_dispatcher')) { + return \Drupal::service('event_dispatcher')->dispatch($event, $eventName); + } + throw new EventException('The event dispatcher service is not available. Database API events can only be fired if the container is initialized'); + } + + /** + * Determine the last non-database method that called the database API. + * + * Traversing the call stack from the very first call made during the + * request, we define "the routine that called this query" as the last entry + * in the call stack that is not any method called from the namespace of the + * database driver, is not inside the Drupal\Core\Database namespace and does + * have a file (which excludes call_user_func_array(), anonymous functions + * and similar). That makes the climbing logic very simple, and handles the + * variable stack depth caused by the query builders. + * + * See the @link http://php.net/debug_backtrace debug_backtrace() @endlink + * function. + * + * @return array + * This method returns a stack trace entry similar to that generated by + * debug_backtrace(). However, it flattens the trace entry and the trace + * entry before it so that we get the function and args of the function that + * called into the database system, not the function and args of the + * database call itself. + */ + public function findCallerFromDebugBacktrace(): array { + $stack = $this->removeDatabaseEntriesFromDebugBacktrace($this->getDebugBacktrace(), $this->getConnectionOptions()['namespace']); + // Return the first function call whose stack entry has a 'file' key, that + // is, it is not a callback or a closure. + for ($i = 0; $i < count($stack); $i++) { + if (!empty($stack[$i]['file'])) { + return [ + 'file' => $stack[$i]['file'], + 'line' => $stack[$i]['line'], + 'function' => $stack[$i + 1]['function'], + 'class' => $stack[$i + 1]['class'] ?? NULL, + 'type' => $stack[$i + 1]['type'] ?? NULL, + 'args' => $stack[$i + 1]['args'] ?? [], + ]; + } + } + + return []; + } + + /** + * Removes database related calls from a backtrace array. + * + * @param array $backtrace + * A standard PHP backtrace. Passed by reference. + * @param string $driver_namespace + * The PHP namespace of the database driver. + * + * @return array + * The cleaned backtrace array. + */ + public static function removeDatabaseEntriesFromDebugBacktrace(array $backtrace, string $driver_namespace): array { + // Starting from the very first entry processed during the request, find + // the first function call that can be identified as a call to a + // method/function in the database layer. + for ($n = count($backtrace) - 1; $n >= 0; $n--) { + // If the call was made from a function, 'class' will be empty. We give + // it a default empty string value in that case. + $class = $backtrace[$n]['class'] ?? ''; + if (str_starts_with($class, __NAMESPACE__) || str_starts_with($class, $driver_namespace)) { + break; + } + } + + return array_values(array_slice($backtrace, $n)); + } + + /** + * Gets the debug backtrace. + * + * Wraps the debug_backtrace function to allow mocking results in PHPUnit + * tests. + * + * @return array[] + * The debug backtrace. + */ + protected function getDebugBacktrace(): array { + return debug_backtrace(); + } + } diff --git a/core/lib/Drupal/Core/Database/Database.php b/core/lib/Drupal/Core/Database/Database.php index 425a271cfaec..ac37df511d15 100644 --- a/core/lib/Drupal/Core/Database/Database.php +++ b/core/lib/Drupal/Core/Database/Database.php @@ -3,6 +3,8 @@ namespace Drupal\Core\Database; use Composer\Autoload\ClassLoader; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; use Drupal\Core\Extension\ExtensionDiscovery; /** @@ -122,6 +124,10 @@ final public static function startLog($logging_key, $key = 'default') { // logging object associated with it. if (!empty(self::$connections[$key])) { foreach (self::$connections[$key] as $connection) { + $connection->enableEvents([ + StatementExecutionStartEvent::class, + StatementExecutionEndEvent::class, + ]); $connection->setLogger(self::$logs[$key]); } } @@ -450,6 +456,10 @@ final protected static function openConnection($key, $target) { // If we have any active logging objects for this connection key, we need // to associate them with the connection we just opened. if (!empty(self::$logs[$key])) { + $new_connection->enableEvents([ + StatementExecutionStartEvent::class, + StatementExecutionEndEvent::class, + ]); $new_connection->setLogger(self::$logs[$key]); } diff --git a/core/lib/Drupal/Core/Database/Event/DatabaseEvent.php b/core/lib/Drupal/Core/Database/Event/DatabaseEvent.php new file mode 100644 index 000000000000..1f759011584e --- /dev/null +++ b/core/lib/Drupal/Core/Database/Event/DatabaseEvent.php @@ -0,0 +1,24 @@ +<?php + +namespace Drupal\Core\Database\Event; + +use Drupal\Component\EventDispatcher\Event; + +/** + * Represents a database event. + */ +abstract class DatabaseEvent extends Event { + + /** + * The time of the event. + */ + public readonly float $time; + + /** + * Constructs a DatabaseEvent object. + */ + public function __construct() { + $this->time = microtime(TRUE); + } + +} diff --git a/core/lib/Drupal/Core/Database/Event/StatementExecutionEndEvent.php b/core/lib/Drupal/Core/Database/Event/StatementExecutionEndEvent.php new file mode 100644 index 000000000000..30718843d6c5 --- /dev/null +++ b/core/lib/Drupal/Core/Database/Event/StatementExecutionEndEvent.php @@ -0,0 +1,54 @@ +<?php + +namespace Drupal\Core\Database\Event; + +/** + * Represents the end of a statement execution as an event. + */ +class StatementExecutionEndEvent extends DatabaseEvent { + + /** + * Constructs a StatementExecutionEndEvent object. + * + * See 'Customizing database settings' in settings.php for an explanation of + * the $key and $target connection values. + * + * @param int $statementObjectId + * The id of the StatementInterface object as returned by spl_object_id(). + * @param string $key + * The database connection key. + * @param string $target + * The database connection target. + * @param string $queryString + * The SQL statement string being executed, with placeholders. + * @param array $args + * The placeholders' replacement values. + * @param array $caller + * A normalized debug backtrace entry representing the last non-db method + * called. + * @param float $startTime + * The time of the statement execution start. + */ + public function __construct( + public readonly int $statementObjectId, + public readonly string $key, + public readonly string $target, + public readonly string $queryString, + public readonly array $args, + public readonly array $caller, + public readonly float $startTime, + ) { + parent::__construct(); + } + + /** + * Gets the query execution elapsed time. + * + * @return float + * The elapsed time. + */ + public function getElapsedTime(): float { + return $this->time - $this->startTime; + } + +} diff --git a/core/lib/Drupal/Core/Database/Event/StatementExecutionStartEvent.php b/core/lib/Drupal/Core/Database/Event/StatementExecutionStartEvent.php new file mode 100644 index 000000000000..010f810966a1 --- /dev/null +++ b/core/lib/Drupal/Core/Database/Event/StatementExecutionStartEvent.php @@ -0,0 +1,41 @@ +<?php + +namespace Drupal\Core\Database\Event; + +/** + * Represents the start of a statement execution as an event. + */ +class StatementExecutionStartEvent extends DatabaseEvent { + + /** + * Constructs a StatementExecutionStartEvent object. + * + * See 'Customizing database settings' in settings.php for an explanation of + * the $key and $target connection values. + * + * @param int $statementObjectId + * The id of the StatementInterface object as returned by spl_object_id(). + * @param string $key + * The database connection key. + * @param string $target + * The database connection target. + * @param string $queryString + * The SQL statement string being executed, with placeholders. + * @param array $args + * The placeholders' replacement values. + * @param array $caller + * A normalized debug backtrace entry representing the last non-db method + * called. + */ + public function __construct( + public readonly int $statementObjectId, + public readonly string $key, + public readonly string $target, + public readonly string $queryString, + public readonly array $args, + public readonly array $caller, + ) { + parent::__construct(); + } + +} diff --git a/core/lib/Drupal/Core/Database/EventSubscriber/StatementExecutionSubscriber.php b/core/lib/Drupal/Core/Database/EventSubscriber/StatementExecutionSubscriber.php new file mode 100644 index 000000000000..f8fa73d96eee --- /dev/null +++ b/core/lib/Drupal/Core/Database/EventSubscriber/StatementExecutionSubscriber.php @@ -0,0 +1,38 @@ +<?php + +namespace Drupal\Core\Database\EventSubscriber; + +use Drupal\Core\Database\Database; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Symfony\Component\EventDispatcher\EventSubscriberInterface; + +/** + * Response subscriber to statement executions. + */ +class StatementExecutionSubscriber implements EventSubscriberInterface { + + /** + * {@inheritdoc} + */ + public static function getSubscribedEvents(): array { + return [ + StatementExecutionEndEvent::class => 'onStatementExecutionEnd', + ]; + } + + /** + * Subscribes to a statement execution finished event. + * + * Logs the statement query if logging is active. + * + * @param \Drupal\Core\Database\Event\StatementExecutionEndEvent $event + * The database event. + */ + public function onStatementExecutionEnd(StatementExecutionEndEvent $event): void { + $logger = Database::getConnection($event->target, $event->key)->getLogger(); + if ($logger) { + $logger->logFromEvent($event); + } + } + +} diff --git a/core/lib/Drupal/Core/Database/Exception/EventException.php b/core/lib/Drupal/Core/Database/Exception/EventException.php new file mode 100644 index 000000000000..66c97d34763f --- /dev/null +++ b/core/lib/Drupal/Core/Database/Exception/EventException.php @@ -0,0 +1,11 @@ +<?php + +namespace Drupal\Core\Database\Exception; + +use Drupal\Core\Database\DatabaseException; + +/** + * Exception thrown by the database event API. + */ +class EventException extends \RuntimeException implements DatabaseException { +} diff --git a/core/lib/Drupal/Core/Database/Log.php b/core/lib/Drupal/Core/Database/Log.php index 6a1de6a0c3ad..876be39f8b98 100644 --- a/core/lib/Drupal/Core/Database/Log.php +++ b/core/lib/Drupal/Core/Database/Log.php @@ -2,6 +2,8 @@ namespace Drupal\Core\Database; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; + /** * Database query logger. * @@ -100,6 +102,25 @@ public function end($logging_key) { unset($this->queryLog[$logging_key]); } + /** + * Log a query to all active logging keys, from a statement execution event. + * + * @param \Drupal\Core\Database\Event\StatementExecutionEndEvent $event + * The statement execution event. + */ + public function logFromEvent(StatementExecutionEndEvent $event): void { + foreach (array_keys($this->queryLog) as $key) { + $this->queryLog[$key][] = [ + 'query' => $event->queryString, + 'args' => $event->args, + 'target' => $event->target, + 'caller' => $event->caller, + 'time' => $event->getElapsedTime(), + 'start' => $event->startTime, + ]; + } + } + /** * Log a query to all active logging keys. * @@ -113,8 +134,14 @@ public function end($logging_key) { * @param float $start * The time the query started as a float (in seconds since the Unix epoch * with microsecond precision). + * + * @deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use + * ::logFromEvent(). + * + * @see https://www.drupal.org/node/3328053 */ public function log(StatementInterface $statement, $args, $time, float $start = NULL) { + @trigger_error(__METHOD__ . '() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use ::logFromEvent(). See https://www.drupal.org/node/3328053', E_USER_DEPRECATED); foreach (array_keys($this->queryLog) as $key) { $this->queryLog[$key][] = [ 'query' => $statement->getQueryString(), @@ -147,8 +174,14 @@ public function log(StatementInterface $statement, $args, $time, float $start = * entry before it so that we get the function and args of the function that * called into the database system, not the function and args of the * database call itself. + * + * @deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use + * Connection::findCallerFromDebugBacktrace(). + * + * @see https://www.drupal.org/node/3328053 */ public function findCaller() { + @trigger_error(__METHOD__ . '() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::findCallerFromDebugBacktrace(). See https://www.drupal.org/node/3328053', E_USER_DEPRECATED); $driver_namespace = Database::getConnectionInfo($this->connectionKey)['default']['namespace']; $stack = static::removeDatabaseEntries($this->getDebugBacktrace(), $driver_namespace); @@ -178,21 +211,15 @@ public function findCaller() { * * @return array * The cleaned backtrace array. + * + * @deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use + * Connection::removeDatabaseEntriesFromDebugBacktrace(). + * + * @see https://www.drupal.org/node/3328053 */ public static function removeDatabaseEntries(array $backtrace, string $driver_namespace): array { - // Starting from the very first entry processed during the request, find - // the first function call that can be identified as a call to a - // method/function in the database layer. - for ($n = count($backtrace) - 1; $n >= 0; $n--) { - // If the call was made from a function, 'class' will be empty. We give - // it a default empty string value in that case. - $class = $backtrace[$n]['class'] ?? ''; - if (str_starts_with($class, __NAMESPACE__) || str_starts_with($class, $driver_namespace)) { - break; - } - } - - return array_values(array_slice($backtrace, $n)); + @trigger_error(__METHOD__ . '() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::removeDatabaseEntriesFromDebugBacktrace(). See https://www.drupal.org/node/3328053', E_USER_DEPRECATED); + return Connection::removeDatabaseEntriesFromDebugBacktrace($backtrace, $driver_namespace); } /** @@ -203,8 +230,14 @@ public static function removeDatabaseEntries(array $backtrace, string $driver_na * * @return array[] * The debug backtrace. + * + * @deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. There is + * no replacement. + * + * @see https://www.drupal.org/node/3328053 */ protected function getDebugBacktrace() { + @trigger_error(__METHOD__ . '() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. There is no replacement. See https://www.drupal.org/node/3328053', E_USER_DEPRECATED); return debug_backtrace(); } diff --git a/core/lib/Drupal/Core/Database/StatementPrefetch.php b/core/lib/Drupal/Core/Database/StatementPrefetch.php index 7edbf7b26ba1..74946cdb1e78 100644 --- a/core/lib/Drupal/Core/Database/StatementPrefetch.php +++ b/core/lib/Drupal/Core/Database/StatementPrefetch.php @@ -2,6 +2,9 @@ namespace Drupal\Core\Database; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; + /** * An implementation of StatementInterface that prefetches all data. * @@ -172,9 +175,16 @@ public function execute($args = [], $options = []) { } } - $logger = $this->connection->getLogger(); - if (!empty($logger)) { - $query_start = microtime(TRUE); + if ($this->connection->isEventEnabled(StatementExecutionStartEvent::class)) { + $startEvent = new StatementExecutionStartEvent( + spl_object_id($this), + $this->connection->getKey(), + $this->connection->getTarget(), + $this->getQueryString(), + $args ?? [], + $this->connection->findCallerFromDebugBacktrace() + ); + $this->connection->dispatchEvent($startEvent); } // Prepare the query. @@ -207,9 +217,16 @@ public function execute($args = [], $options = []) { $this->columnNames = []; } - if (!empty($logger)) { - $query_end = microtime(TRUE); - $logger->log($this, $args, $query_end - $query_start, $query_start); + if (isset($startEvent) && $this->connection->isEventEnabled(StatementExecutionEndEvent::class)) { + $this->connection->dispatchEvent(new StatementExecutionEndEvent( + $startEvent->statementObjectId, + $startEvent->key, + $startEvent->target, + $startEvent->queryString, + $startEvent->args, + $startEvent->caller, + $startEvent->time + )); } // Initialize the first row in $this->currentRow. diff --git a/core/lib/Drupal/Core/Database/StatementWrapper.php b/core/lib/Drupal/Core/Database/StatementWrapper.php index 4381fd1af62a..8b70f3d6d38a 100644 --- a/core/lib/Drupal/Core/Database/StatementWrapper.php +++ b/core/lib/Drupal/Core/Database/StatementWrapper.php @@ -2,6 +2,9 @@ namespace Drupal\Core\Database; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; + // cSpell:ignore maxlen driverdata INOUT /** @@ -87,16 +90,30 @@ public function execute($args = [], $options = []) { } } - $logger = $this->connection->getLogger(); - if (!empty($logger)) { - $query_start = microtime(TRUE); + if ($this->connection->isEventEnabled(StatementExecutionStartEvent::class)) { + $startEvent = new StatementExecutionStartEvent( + spl_object_id($this), + $this->connection->getKey(), + $this->connection->getTarget(), + $this->getQueryString(), + $args ?? [], + $this->connection->findCallerFromDebugBacktrace() + ); + $this->connection->dispatchEvent($startEvent); } $return = $this->clientStatement->execute($args); - if (!empty($logger)) { - $query_end = microtime(TRUE); - $logger->log($this, $args, $query_end - $query_start, $query_start); + if (isset($startEvent) && $this->connection->isEventEnabled(StatementExecutionEndEvent::class)) { + $this->connection->dispatchEvent(new StatementExecutionEndEvent( + $startEvent->statementObjectId, + $startEvent->key, + $startEvent->target, + $startEvent->queryString, + $startEvent->args, + $startEvent->caller, + $startEvent->time + )); } return $return; diff --git a/core/lib/Drupal/Core/Utility/Error.php b/core/lib/Drupal/Core/Utility/Error.php index 1f55be5a2952..d5bb777f06f0 100644 --- a/core/lib/Drupal/Core/Utility/Error.php +++ b/core/lib/Drupal/Core/Utility/Error.php @@ -4,9 +4,9 @@ use Drupal\Component\Render\FormattableMarkup; use Drupal\Component\Utility\Xss; +use Drupal\Core\Database\Connection; use Drupal\Core\Database\Database; use Drupal\Core\Database\DatabaseExceptionWrapper; -use Drupal\Core\Database\Log; /** * Drupal error utility class. @@ -52,7 +52,7 @@ public static function decodeException($exception) { // skipping internal functions of the database layer. if ($exception instanceof \PDOException || $exception instanceof DatabaseExceptionWrapper) { $driver_namespace = Database::getConnectionInfo()['default']['namespace']; - $backtrace = Log::removeDatabaseEntries($backtrace, $driver_namespace); + $backtrace = Connection::removeDatabaseEntriesFromDebugBacktrace($backtrace, $driver_namespace); if (isset($exception->query_string, $exception->args)) { $message .= ": " . $exception->query_string . "; " . print_r($exception->args, TRUE); } diff --git a/core/modules/system/tests/modules/database_test/database_test.services.yml b/core/modules/system/tests/modules/database_test/database_test.services.yml new file mode 100644 index 000000000000..0bac13c303af --- /dev/null +++ b/core/modules/system/tests/modules/database_test/database_test.services.yml @@ -0,0 +1,5 @@ +services: + # A test subscriber for the database API events. + Drupal\database_test\EventSubscriber\DatabaseEventSubscriber: + tags: + - { name: event_subscriber } diff --git a/core/modules/system/tests/modules/database_test/src/EventSubscriber/DatabaseEventSubscriber.php b/core/modules/system/tests/modules/database_test/src/EventSubscriber/DatabaseEventSubscriber.php new file mode 100644 index 000000000000..e35d333fd234 --- /dev/null +++ b/core/modules/system/tests/modules/database_test/src/EventSubscriber/DatabaseEventSubscriber.php @@ -0,0 +1,61 @@ +<?php + +namespace Drupal\database_test\EventSubscriber; + +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; +use Symfony\Component\EventDispatcher\EventSubscriberInterface; + +/** + * Responds to database API events. + */ +class DatabaseEventSubscriber implements EventSubscriberInterface { + + /** + * A counter of started statement executions. + */ + public int $countStatementStarts = 0; + + /** + * A counter of finished statement executions. + */ + public int $countStatementEnds = 0; + + /** + * A map of statements being executed. + */ + public array $statementIdsInExecution = []; + + /** + * {@inheritdoc} + */ + public static function getSubscribedEvents(): array { + return [ + StatementExecutionStartEvent::class => 'onStatementExecutionStart', + StatementExecutionEndEvent::class => 'onStatementExecutionEnd', + ]; + } + + /** + * Subscribes to a statement execution started event. + * + * @param \Drupal\Core\Database\Event\StatementExecutionStartEvent $event + * The database event. + */ + public function onStatementExecutionStart(StatementExecutionStartEvent $event): void { + $this->statementIdsInExecution[$event->statementObjectId] = TRUE; + $this->countStatementStarts++; + } + + /** + * Subscribes to a statement execution finished event. + * + * @param \Drupal\Core\Database\Event\StatementExecutionEndEvent $event + * The database event. + */ + public function onStatementExecutionEnd(StatementExecutionEndEvent $event): void { + unset($this->statementIdsInExecution[$event->statementObjectId]); + $this->countStatementEnds++; + } + +} diff --git a/core/tests/Drupal/KernelTests/Core/Database/DatabaseEventTest.php b/core/tests/Drupal/KernelTests/Core/Database/DatabaseEventTest.php new file mode 100644 index 000000000000..895b61b88074 --- /dev/null +++ b/core/tests/Drupal/KernelTests/Core/Database/DatabaseEventTest.php @@ -0,0 +1,82 @@ +<?php + +namespace Drupal\KernelTests\Core\Database; + +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; +use Drupal\database_test\EventSubscriber\DatabaseEventSubscriber; + +/** + * Tests the database API events. + * + * @group Database + */ +class DatabaseEventTest extends DatabaseTestBase { + + /** + * Tests statement execution events. + */ + public function testStatementExecutionEvents(): void { + $subscriber = $this->container->get(DatabaseEventSubscriber::class); + + // At first, no events have occurred, and events are not enabled. + $this->assertSame(0, $subscriber->countStatementStarts); + $this->assertSame(0, $subscriber->countStatementEnds); + $this->assertEmpty($subscriber->statementIdsInExecution); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + + // Execute a query, still no events captured. + $this->connection->query('SELECT * FROM {test}'); + $this->assertSame(0, $subscriber->countStatementStarts); + $this->assertSame(0, $subscriber->countStatementEnds); + $this->assertEmpty($subscriber->statementIdsInExecution); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + + // Enable the statement execution start event and execute a query, start + // event captured but no end one. + $this->connection->enableEvents([StatementExecutionStartEvent::class]); + $this->connection->query('SELECT * FROM {test}'); + $this->assertSame(1, $subscriber->countStatementStarts); + $this->assertSame(0, $subscriber->countStatementEnds); + $this->assertCount(1, $subscriber->statementIdsInExecution); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + // Reset the statements in execution map to cleanup for following tests. + $subscriber->statementIdsInExecution = []; + + // Enable the statement execution end event and execute a query, both + // events captured. + $this->connection->enableEvents([StatementExecutionEndEvent::class]); + $this->connection->query('SELECT * FROM {test}'); + $this->assertSame(2, $subscriber->countStatementStarts); + $this->assertSame(1, $subscriber->countStatementEnds); + $this->assertEmpty($subscriber->statementIdsInExecution); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + + // Disable both events, no more events captured. + $this->connection->disableEvents([ + StatementExecutionStartEvent::class, + StatementExecutionEndEvent::class, + ]); + $this->connection->query('SELECT * FROM {test}'); + $this->assertSame(2, $subscriber->countStatementStarts); + $this->assertSame(1, $subscriber->countStatementEnds); + $this->assertEmpty($subscriber->statementIdsInExecution); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + + // Enable the statement execution end only, no events captured since the + // start event is required before the end one can be fired. + $this->connection->enableEvents([StatementExecutionEndEvent::class]); + $this->connection->query('SELECT * FROM {test}'); + $this->assertSame(2, $subscriber->countStatementStarts); + $this->assertSame(1, $subscriber->countStatementEnds); + $this->assertEmpty($subscriber->statementIdsInExecution); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + } + +} diff --git a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php index 7858169af184..27e2ac2aadd6 100644 --- a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php @@ -154,8 +154,13 @@ public function testGetLoggingWrongKey() { * @covers ::findCaller * * @dataProvider providerContribDriverLog + * + * @group legacy */ public function testContribDriverLog($driver_namespace, $stack, array $expected_entry) { + $this->expectDeprecation('Drupal\Core\Database\Log::findCaller() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::findCallerFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); + $this->expectDeprecation('Drupal\Core\Database\Log::removeDatabaseEntries() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::removeDatabaseEntriesFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); + $mock_builder = $this->getMockBuilder(Log::class); $log = $mock_builder ->onlyMethods(['getDebugBacktrace']) diff --git a/core/tests/Drupal/Tests/Core/Database/ConnectionTest.php b/core/tests/Drupal/Tests/Core/Database/ConnectionTest.php index e46a01d8e7a2..f0d0bc766066 100644 --- a/core/tests/Drupal/Tests/Core/Database/ConnectionTest.php +++ b/core/tests/Drupal/Tests/Core/Database/ConnectionTest.php @@ -3,6 +3,7 @@ namespace Drupal\Tests\Core\Database; use Composer\Autoload\ClassLoader; +use Drupal\Core\Database\Database; use Drupal\Tests\Core\Database\Stub\StubConnection; use Drupal\Tests\Core\Database\Stub\StubPDO; use Drupal\Tests\UnitTestCase; @@ -645,4 +646,224 @@ public function provideQueriesToTrim() { ]; } + /** + * Tests that the proper caller is retrieved from the backtrace. + * + * @covers ::findCallerFromDebugBacktrace + * @covers ::removeDatabaseEntriesFromDebugBacktrace + * @covers ::getDebugBacktrace + */ + public function testFindCallerFromDebugBacktrace() { + Database::addConnectionInfo('default', 'default', [ + 'driver' => 'test', + 'namespace' => 'Drupal\Tests\Core\Database\Stub', + ]); + $connection = new StubConnection($this->createMock(StubPDO::class), []); + $result = $connection->findCallerFromDebugBacktrace(); + $this->assertSame([ + 'file' => __FILE__, + 'line' => 662, + 'function' => 'testFindCallerFromDebugBacktrace', + 'class' => 'Drupal\Tests\Core\Database\ConnectionTest', + 'type' => '->', + 'args' => [], + ], $result); + } + + /** + * Tests that a log called by a custom database driver returns proper caller. + * + * @param string $driver_namespace + * The driver namespace to be tested. + * @param array $stack + * A test debug_backtrace stack. + * @param array $expected_entry + * The expected stack entry. + * + * @covers ::findCallerFromDebugBacktrace + * @covers ::removeDatabaseEntriesFromDebugBacktrace + * + * @dataProvider providerMockedBacktrace + * + * @group legacy + */ + public function testFindCallerFromDebugBacktraceWithMockedBacktrace(string $driver_namespace, array $stack, array $expected_entry): void { + $mock_builder = $this->getMockBuilder(StubConnection::class); + $connection = $mock_builder + ->onlyMethods(['getDebugBacktrace', 'getConnectionOptions']) + ->setConstructorArgs([$this->createMock(StubPDO::class), []]) + ->getMock(); + $connection->expects($this->once()) + ->method('getConnectionOptions') + ->willReturn([ + 'driver' => 'test', + 'namespace' => $driver_namespace, + ]); + $connection->expects($this->once()) + ->method('getDebugBacktrace') + ->willReturn($stack); + + $result = $connection->findCallerFromDebugBacktrace(); + $this->assertEquals($expected_entry, $result); + } + + /** + * Provides data for testFindCallerFromDebugBacktraceWithMockedBacktrace. + * + * @return array[] + * A associative array of simple arrays, each having the following elements: + * - the contrib driver PHP namespace + * - a test debug_backtrace stack + * - the stack entry expected to be returned. + * + * @see ::testFindCallerFromDebugBacktraceWithMockedBacktrace() + */ + public function providerMockedBacktrace(): array { + $stack = [ + [ + 'file' => '/var/www/core/lib/Drupal/Core/Database/Log.php', + 'line' => 125, + 'function' => 'findCaller', + 'class' => 'Drupal\\Core\\Database\\Log', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/libraries/drudbal/lib/Statement.php', + 'line' => 264, + 'function' => 'log', + 'class' => 'Drupal\\Core\\Database\\Log', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/libraries/drudbal/lib/Connection.php', + 'line' => 213, + 'function' => 'execute', + 'class' => 'Drupal\\Driver\\Database\\dbal\\Statement', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 23, + 'function' => 'query', + 'class' => 'Drupal\\Driver\\Database\\dbal\\Connection', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 1154, + 'function' => 'testEnableLogging', + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 842, + 'function' => 'runTest', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestResult.php', + 'line' => 693, + 'function' => 'runBare', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 796, + 'function' => 'run', + 'class' => 'PHPUnit\\Framework\\TestResult', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => 'Standard input code', + 'line' => 57, + 'function' => 'run', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => 'Standard input code', + 'line' => 111, + 'function' => '__phpunit_run_isolated_test', + 'args' => [ + 0 => 'test', + ], + ], + ]; + + return [ + // Test that if the driver namespace is in the stack trace, the first + // non-database entry is returned. + 'contrib driver namespace' => [ + 'Drupal\\Driver\\Database\\dbal', + $stack, + [ + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'function' => 'testEnableLogging', + 'file' => '/var/www/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 23, + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + ], + // Extreme case, should not happen at normal runtime - if the driver + // namespace is not in the stack trace, the first entry to a method + // in core database namespace is returned. + 'missing driver namespace' => [ + 'Drupal\\Driver\\Database\\fake', + $stack, + [ + 'class' => 'Drupal\\Driver\\Database\\dbal\\Statement', + 'function' => 'execute', + 'file' => '/var/www/libraries/drudbal/lib/Statement.php', + 'line' => 264, + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + ], + ]; + } + } diff --git a/core/tests/Drupal/Tests/Core/Database/DatabaseEventsTest.php b/core/tests/Drupal/Tests/Core/Database/DatabaseEventsTest.php new file mode 100644 index 000000000000..81215fe8b26b --- /dev/null +++ b/core/tests/Drupal/Tests/Core/Database/DatabaseEventsTest.php @@ -0,0 +1,79 @@ +<?php + +namespace Drupal\Tests\Core\Database; + +use Drupal\Core\Database\Connection; +use Drupal\Core\Database\Event\DatabaseEvent; +use Drupal\Core\Database\Event\StatementExecutionEndEvent; +use Drupal\Core\Database\Event\StatementExecutionStartEvent; +use Drupal\Core\Database\Exception\EventException; +use Drupal\Tests\Core\Database\Stub\StubConnection; +use Drupal\Tests\Core\Database\Stub\StubPDO; +use Drupal\Tests\UnitTestCase; + +/** + * @coversDefaultClass \Drupal\Core\Database\Connection + * + * @group Database + */ +class DatabaseEventsTest extends UnitTestCase { + + /** + * A database connection. + */ + protected Connection $connection; + + /** + * {@inheritdoc} + */ + protected function setUp(): void { + $this->connection = new StubConnection($this->createMock(StubPDO::class), []); + } + + /** + * @covers ::isEventEnabled + * @covers ::enableEvent + * @covers ::disableEvent + */ + public function testEventEnablingAndDisabling(): void { + $this->connection->enableEvents([ + StatementExecutionStartEvent::class, + StatementExecutionEndEvent::class, + ]); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + $this->connection->disableEvents([ + StatementExecutionEndEvent::class, + ]); + $this->assertTrue($this->connection->isEventEnabled(StatementExecutionStartEvent::class)); + $this->assertFalse($this->connection->isEventEnabled(StatementExecutionEndEvent::class)); + } + + /** + * @covers ::enableEvent + */ + public function testEnableInvalidEvent(): void { + $this->expectException(\AssertionError::class); + $this->expectExceptionMessage('Event class foo does not exist'); + $this->connection->enableEvents(['foo']); + } + + /** + * @covers ::disableEvent + */ + public function testDisableInvalidEvent(): void { + $this->expectException(\AssertionError::class); + $this->expectExceptionMessage('Event class bar does not exist'); + $this->connection->disableEvents(['bar']); + } + + /** + * @covers ::dispatchEvent + */ + public function testEventDispatchingWhenNoContainerAvailable(): void { + $this->expectException(EventException::class); + $this->expectExceptionMessage('The event dispatcher service is not available. Database API events can only be fired if the container is initialized'); + $this->connection->dispatchEvent($this->createMock(DatabaseEvent::class)); + } + +} diff --git a/core/tests/Drupal/Tests/Core/Database/LogTest.php b/core/tests/Drupal/Tests/Core/Database/LogTest.php index 7184be4dc2ca..7d5e5fec71a6 100644 --- a/core/tests/Drupal/Tests/Core/Database/LogTest.php +++ b/core/tests/Drupal/Tests/Core/Database/LogTest.php @@ -12,6 +12,7 @@ * Tests the Log class. * * @group Database + * @group legacy * @runTestsInSeparateProcesses * @preserveGlobalState disabled * @coversDefaultClass \Drupal\Core\Database\Log @@ -29,11 +30,14 @@ public function testContribDriverLog() { 'namespace' => 'Drupal\Tests\Core\Database\Stub', ]); + $this->expectDeprecation('Drupal\Core\Database\Log::findCaller() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::findCallerFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); + $this->expectDeprecation('Drupal\Core\Database\Log::getDebugBacktrace() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. There is no replacement. See https://www.drupal.org/node/3328053'); + $this->expectDeprecation('Drupal\Core\Database\Log::removeDatabaseEntries() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::removeDatabaseEntriesFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); $pdo = $this->prophesize(StubPDO::class)->reveal(); $result = (new StubConnection($pdo, []))->testLogCaller(); $this->assertSame([ 'file' => __FILE__, - 'line' => 33, + 'line' => 37, 'function' => 'testContribDriverLog', 'class' => 'Drupal\Tests\Core\Database\LogTest', 'type' => '->', @@ -41,10 +45,13 @@ public function testContribDriverLog() { ], $result); // Test calling the database log from outside of database code. + $this->expectDeprecation('Drupal\Core\Database\Log::findCaller() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::findCallerFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); + $this->expectDeprecation('Drupal\Core\Database\Log::getDebugBacktrace() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. There is no replacement. See https://www.drupal.org/node/3328053'); + $this->expectDeprecation('Drupal\Core\Database\Log::removeDatabaseEntries() is deprecated in drupal:10.1.0 and is removed from drupal:11.0.0. Use Connection::removeDatabaseEntriesFromDebugBacktrace(). See https://www.drupal.org/node/3328053'); $result = (new Log())->findCaller(); $this->assertSame([ 'file' => __FILE__, - 'line' => 44, + 'line' => 51, 'function' => 'testContribDriverLog', 'class' => 'Drupal\Tests\Core\Database\LogTest', 'type' => '->', -- GitLab