Merge pull request propelorm#1728 from mringler/bugfix/failed_queries…

…_should_be_written_to_log Bugfix: Failed queries should be written to log & Fix PdoConnection::exec()
FXdSP · May 6, 2021 · 3c4c6b5 · 3c4c6b5
2 parents 23ab61d + cb0f1fa
commit 3c4c6b5
Show file tree

Hide file tree

Showing 7 changed files with 246 additions and 37 deletions.
diff --git a/src/Propel/Runtime/Connection/ConnectionInterface.php b/src/Propel/Runtime/Connection/ConnectionInterface.php
@@ -148,7 +148,7 @@ public function transaction(callable $callable);
      * @param string $statement The SQL statement to prepare and execute.
      *                          Data inside the query should be properly escaped.
      *
-     * @return \Propel\Runtime\DataFetcher\DataFetcherInterface The number of rows that were modified or deleted.
+     * @return int The number of rows that were modified or deleted.
      */
     public function exec($statement);
 

diff --git a/src/Propel/Runtime/Connection/ConnectionWrapper.php b/src/Propel/Runtime/Connection/ConnectionWrapper.php
@@ -8,6 +8,7 @@
 
 namespace Propel\Runtime\Connection;
 
+use PDOException;
 use Propel\Runtime\Connection\Exception\RollbackException;
 use Propel\Runtime\Exception\InvalidArgumentException;
 use Propel\Runtime\Propel;
@@ -408,15 +409,13 @@ public function prepare(string $statement, array $driverOptions = [])
      */
     public function exec($statement)
     {
-        $return = $this->connection->exec($statement);
-
         if ($this->useDebug) {
-            $this->log($statement);
-            $this->setLastExecutedQuery($statement);
-            $this->incrementQueryCount();
+            $callback = [$this->connection, 'exec'];
+
+            return $this->callUserFunctionWithLogging($callback, [$statement], $statement);
         }
 
-        return $return;
+        return $this->connection->exec($statement);
     }
 
     /**
@@ -437,12 +436,43 @@ public function query($statement)
         $args = func_get_args();
         $sql = array_shift($args);
         $statementWrapper = $this->createStatementWrapper($sql);
-        $return = call_user_func_array([$statementWrapper, 'query'], $args);
+        $callback = [$statementWrapper, 'query'];
 
-        if ($this->useDebug) {
-            $this->log($sql);
-            $this->setLastExecutedQuery($sql);
-            $this->incrementQueryCount();
+        return call_user_func_array($callback, $args);
+    }
+
+    /**
+     * Run a query callback and log the SQL statement.
+     *
+     * This method ensures, that the statement is logged, even if an error occures, and that the
+     * query is logged after it was run. The latter is necessary for profiling to work.
+     *
+     * @param callable $callback
+     * @param array|null $args
+     * @param string $sqlForLog Logged SQL query
+     *
+     * @throws \PDOException
+     *
+     * @return mixed
+     */
+    public function callUserFunctionWithLogging(callable $callback, ?array $args, string $sqlForLog)
+    {
+        $pdoException = null;
+        $return = null;
+
+        try {
+            $return = call_user_func_array($callback, $args ?? []);
+        } catch (PDOException $e) {
+            $pdoException = $e;
+        }
+
+        // For profiling to work, $this->log() needs to be run after the query was executed
+        $this->log($sqlForLog);
+        $this->setLastExecutedQuery($sqlForLog);
+        $this->incrementQueryCount();
+
+        if ($pdoException !== null) {
+            throw $pdoException;
         }
 
         return $return;
@@ -665,7 +695,7 @@ public function log($msg)
         do {
             $callingMethod = $backtrace[$i]['function'];
             $i++;
-        } while ($callingMethod === 'log' && $i < $stackSize);
+        } while (in_array($callingMethod, ['log', 'callUserFunctionWithLogging'], true) && $i < $stackSize);
 
         if (!$msg || !$this->isLogEnabledForMethod($callingMethod)) {
             return;

diff --git a/src/Propel/Runtime/Connection/PdoConnection.php b/src/Propel/Runtime/Connection/PdoConnection.php
@@ -137,13 +137,11 @@ public function query($statement)
     /**
      * @inheritDoc
      *
-     * @return \Propel\Runtime\DataFetcher\DataFetcherInterface
+     * @return int
      */
     public function exec($statement)
     {
-        $stmt = $this->pdo->exec($statement);
-
-        return $this->getDataFetcher($stmt);
+        return $this->pdo->exec($statement);
     }
 
     /**

diff --git a/src/Propel/Runtime/Connection/StatementWrapper.php b/src/Propel/Runtime/Connection/StatementWrapper.php
@@ -89,8 +89,12 @@ public function prepare($options)
      */
     public function query()
     {
-        /** @var \PDOStatement $statement */
-        $statement = $this->connection->getWrappedConnection()->query($this->sql);
+        if ($this->connection->useDebug) {
+            $callback = [$this->connection->getWrappedConnection(), 'query'];
+            $statement = $this->connection->callUserFunctionWithLogging($callback, [$this->sql], $this->sql);
+        } else {
+            $statement = $this->connection->getWrappedConnection()->query($this->sql);
+        }
         $this->statement = $statement;
 
         return $this->connection->getWrappedConnection()->getDataFetcher($this);
@@ -201,15 +205,14 @@ public function columnCount()
      */
     public function execute($inputParameters = null)
     {
-        $return = $this->statement->execute($inputParameters);
         if ($this->connection->useDebug) {
             $sql = $this->getExecutedQueryString($inputParameters);
-            $this->connection->log($sql);
-            $this->connection->setLastExecutedQuery($sql);
-            $this->connection->incrementQueryCount();
+            $args = ($inputParameters !== null) ? [$inputParameters] : [];
+
+            return $this->connection->callUserFunctionWithLogging([$this->statement, 'execute'], $args, $sql);
         }
 
-        return $return;
+        return $this->statement->execute($inputParameters);
     }
 
     /**

diff --git a/tests/Propel/Tests/Runtime/Connection/ConnectionWrapperTest.php b/tests/Propel/Tests/Runtime/Connection/ConnectionWrapperTest.php
@@ -0,0 +1,107 @@
+<?php
+
+/**
+ * MIT License. This file is part of the Propel package.
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Propel\Tests\Runtime\Connection;
+
+use Exception;
+use Propel\Runtime\Connection\ConnectionWrapper;
+use Propel\Tests\Helpers\Bookstore\BookstoreTestBase;
+
+/**
+ * @group database
+ */
+class ConnectionWrapperTest extends BookstoreTestBase
+{
+    /**
+     * Make sure logging is done after execution, otherwise Profiler will give wrong data.
+     *
+     * @return void
+     */
+    public function testQueriesAreLoggedAfterExecution()
+    {
+        $wrapper = new class ($this->con) extends ConnectionWrapper{
+            public $orderStack = [];
+
+            public function pushToOrderStack(string $op)
+            {
+                $this->orderStack[] = $op;
+            }
+
+            public function log($msg)
+            {
+                $this->pushToOrderStack('log');
+            }
+        };
+        $wrapper->callUserFunctionWithLogging([$wrapper, 'pushToOrderStack'], ['execute'], '');
+        $this->assertEquals(['execute', 'log'], $wrapper->orderStack, 'Execute should run before logging');
+    }
+
+    /**
+     * @return void
+     */
+    public function testQueryIsUnaffectedByDebugMode()
+    {
+        $con = new ConnectionWrapper($this->con->getWrappedConnection());
+
+        $query = 'SELECT * FROM book';
+
+        $con->useDebug(false);
+        $resultWithoutDebug = null;
+        try {
+            $resultWithoutDebug = $con->query($query)->fetch();
+        } catch (Exception $e) {
+            $this->fail('Could not execute query with debug mode DISABLED: ' . $e->getMessage());
+        }
+
+        $con->useDebug(true);
+        $resultWithDebug = null;
+        try {
+            $resultWithDebug = $con->query($query)->fetch();
+        } catch (Exception $e) {
+            $this->fail('Could not execute query with debug mode ENABLED: ' . $e->getMessage());
+        }
+
+        $this->assertEquals($resultWithoutDebug, $resultWithDebug);
+    }
+
+    /**
+     * @return void
+     */
+    public function testExecuteRunsInDebugMode()
+    {
+        $this->assertExecSimpleInsertWithGivenDebugModeWorks('ENABLED', true);
+    }
+
+    /**
+     * @return void
+     */
+    public function testExecuteRunsWithoutDebugMode()
+    {
+        $this->assertExecSimpleInsertWithGivenDebugModeWorks('DISABLED', false);
+    }
+
+    /**
+     * @return void
+     */
+    public function assertExecSimpleInsertWithGivenDebugModeWorks(string $description, bool $debugMode): void
+    {
+        $con = new ConnectionWrapper($this->con->getWrappedConnection());
+
+        $query = "INSERT INTO publisher(name) VALUES('Le Publisher')";
+
+        $con->useDebug($debugMode);
+        $affectedRows = -1;
+        try {
+            $affectedRows = $con->exec($query);
+        } catch (Exception $e) {
+            $this->fail("Could not execute query with debug mode $description: " . $e->getMessage());
+        }
+
+        $this->assertEquals(1, $affectedRows, "ConnectionWrapper::exec() should have inserted one rows with $description debug mode");
+    }
+}
diff --git a/tests/Propel/Tests/Runtime/Connection/PropelPDOTest.php b/tests/Propel/Tests/Runtime/Connection/PropelPDOTest.php
@@ -14,6 +14,7 @@
 use PDO;
 use PDOException;
 use Propel\Runtime\ActiveQuery\Criteria;
+use Propel\Runtime\Connection\ConnectionWrapper;
 use Propel\Runtime\Connection\Exception\RollbackException;
 use Propel\Runtime\Connection\PropelPDO;
 use Propel\Tests\Bookstore\Author;
@@ -483,16 +484,8 @@ public function testDebugQueryCount()
      */
     public function testDebugLog()
     {
-        $con = $this->con;
-
-        // save data to return to normal state after test
-        $logger = $con->getLogger();
-        $logMethods = $con->getLogMethods();
+        [$con, $handler] = LastMessageHandler::buildHandledConnection($this->con);
 
-        $testLog = new Logger('debug');
-        $handler = new LastMessageHandler();
-        $testLog->pushHandler($handler);
-        $con->setLogger($testLog);
         $con->setLogMethods([
             'exec',
             'query',
@@ -501,7 +494,6 @@ public function testDebugLog()
             'commit',
             'rollBack',
         ]);
-        $con->useDebug(true);
 
         $con->beginTransaction();
         // test transaction log
@@ -544,10 +536,22 @@ public function testDebugLog()
         $this->assertEquals($latestExecutedQuery, $handler->latestMessage, 'PropelPDO logs exec queries in debug mode');
 
         $con->commit();
+    }
 
-        // return to normal state after test
-        $con->setLogger($logger);
-        $con->setLogMethods($logMethods);
+    /**
+     * @return void
+     */
+    public function testLogFailedQueries()
+    {
+        [$con, $handler] = LastMessageHandler::buildHandledConnection($this->con);
+
+        $incorrectQuery = 'Oh, this is no query';
+        try {
+            $con->exec($incorrectQuery);
+            $this->fail("Cannot run test when query does not fail. Query: [$incorrectQuery]");
+        } catch (PDOException $e) {
+        }
+        $this->assertEquals($incorrectQuery, $handler->latestMessage, 'PropelPDO should log failed queries.');
     }
 }
 
@@ -561,4 +565,16 @@ public function handle(array $record)
 
         return false === $this->bubble;
     }
+
+    public static function buildHandledConnection(ConnectionWrapper $con): array
+    {
+        $con = new ConnectionWrapper($con->getWrappedConnection());
+        $logger = new Logger('debug');
+        $handler = new LastMessageHandler();
+        $logger->pushHandler($handler);
+        $con->setLogger($logger);
+        $con->useDebug(true);
+
+        return [$con, $handler];
+    }
 }
diff --git a/tests/Propel/Tests/Runtime/Connection/StatementWrapperTest.php b/tests/Propel/Tests/Runtime/Connection/StatementWrapperTest.php
@@ -0,0 +1,55 @@
+<?php
+
+/**
+ * MIT License. This file is part of the Propel package.
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Propel\Tests\Runtime\Connection;
+
+use Propel\Runtime\Connection\ConnectionWrapper;
+use Propel\Tests\Helpers\Bookstore\BookstoreTestBase;
+use Exception;
+
+/**
+ * @group database
+ */
+class StatementWrapperTest extends BookstoreTestBase
+{
+    /**
+     * @return void
+     */
+    public function testExecuteRunsInDebugMode()
+    {
+        $exitCode = $this->executeSimpleQueryWithGivenDebugMode('ENABLED', true);
+        $this->assertTrue($exitCode);
+    }
+
+    /**
+     * @return void
+     */
+    public function testExecuteRunsWithoutDebugMode()
+    {
+        $exitCode = $this->executeSimpleQueryWithGivenDebugMode('DISABLED', false);
+        $this->assertTrue($exitCode);
+    }
+
+    /**
+     *
+     * @return void
+     */
+    private function executeSimpleQueryWithGivenDebugMode(string $description, bool $debugMode): bool
+    {
+        $query = 'SELECT * FROM book';
+        $wrapper = new ConnectionWrapper($this->con->getWrappedConnection());
+        $wrapper->useDebug($debugMode);
+
+        $stmt = $wrapper->prepare($query);
+        try{
+            return $stmt->execute();
+        } catch (Exception $e) {
+            $this->fail("Could not run query with debug mode $description: " . $e->getMessage());
+        }
+    }
+}