feat: add additional logging for database errors

including the stack trace of the current database transaction Signed-off-by: Robin Appelman <robin@icewind.nl>
nextcloud · Jul 24, 2024 · c84520e · c84520e
1 parent b839483
commit c84520e
Show file tree

Hide file tree

Showing 3 changed files with 53 additions and 4 deletions.
diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php
@@ -69,6 +69,9 @@ class Connection extends PrimaryReadReplicaConnection {
 	/** @var array<string, int> */
 	protected $tableDirtyWrites = [];
 
+	protected bool $logDbException = false;
+	private ?array $transactionBacktrace = null;
+
 	protected bool $logRequestId;
 	protected string $requestId;
 
@@ -101,6 +104,7 @@ public function __construct(
 		$this->logger = Server::get(LoggerInterface::class);
 
 		$this->logRequestId = $this->systemConfig->getValue('db.log_request_id', false);
+		$this->logDbException = $this->systemConfig->getValue('db.log_exceptions', false);
 		$this->requestId = Server::get(IRequestId::class)->getId();
 
 		/** @var \OCP\Profiler\IProfiler */
@@ -304,7 +308,12 @@ public function executeQuery(string $sql, array $params = [], $types = [], ?Quer
 		$sql = $this->finishQuery($sql);
 		$this->queriesExecuted++;
 		$this->logQueryToFile($sql);
-		return parent::executeQuery($sql, $params, $types, $qcp);
+		try {
+			return parent::executeQuery($sql, $params, $types, $qcp);
+		} catch (\Exception $e) {
+			$this->logDatabaseException($e);
+			throw $e;
+		}
 	}
 
 	/**
@@ -346,7 +355,12 @@ public function executeStatement($sql, array $params = [], array $types = []): i
 		$sql = $this->finishQuery($sql);
 		$this->queriesExecuted++;
 		$this->logQueryToFile($sql);
-		return (int)parent::executeStatement($sql, $params, $types);
+		try {
+			return (int)parent::executeStatement($sql, $params, $types);
+		} catch (\Exception $e) {
+			$this->logDatabaseException($e);
+			throw $e;
+		}
 	}
 
 	protected function logQueryToFile(string $sql): void {
@@ -419,11 +433,21 @@ public function realLastInsertId($seqName = null) {
 	 * @deprecated 15.0.0 - use unique index and "try { $db->insert() } catch (UniqueConstraintViolationException $e) {}" instead, because it is more reliable and does not have the risk for deadlocks - see https://github.com/nextcloud/server/pull/12371
 	 */
 	public function insertIfNotExist($table, $input, ?array $compare = null) {
-		return $this->adapter->insertIfNotExist($table, $input, $compare);
+		try {
+			return $this->adapter->insertIfNotExist($table, $input, $compare);
+		} catch (\Exception $e) {
+			$this->logDatabaseException($e);
+			throw $e;
+		}
 	}
 
 	public function insertIgnoreConflict(string $table, array $values) : int {
-		return $this->adapter->insertIgnoreConflict($table, $values);
+		try {
+			return $this->adapter->insertIgnoreConflict($table, $values);
+		} catch (\Exception $e) {
+			$this->logDatabaseException($e);
+			throw $e;
+		}
 	}
 
 	private function getType($value) {
@@ -682,6 +706,7 @@ private function getMigrator() {
 
 	public function beginTransaction() {
 		if (!$this->inTransaction()) {
+			$this->transactionBacktrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
 			$this->transactionActiveSince = microtime(true);
 		}
 		return parent::beginTransaction();
@@ -691,6 +716,7 @@ public function commit() {
 		$result = parent::commit();
 		if ($this->getTransactionNestingLevel() === 0) {
 			$timeTook = microtime(true) - $this->transactionActiveSince;
+			$this->transactionBacktrace = null;
 			$this->transactionActiveSince = null;
 			if ($timeTook > 1) {
 				$this->logger->debug('Transaction took ' . $timeTook . 's', ['exception' => new \Exception('Transaction took ' . $timeTook . 's')]);
@@ -703,6 +729,7 @@ public function rollBack() {
 		$result = parent::rollBack();
 		if ($this->getTransactionNestingLevel() === 0) {
 			$timeTook = microtime(true) - $this->transactionActiveSince;
+			$this->transactionBacktrace = null;
 			$this->transactionActiveSince = null;
 			if ($timeTook > 1) {
 				$this->logger->debug('Transaction rollback took longer than 1s: ' . $timeTook, ['exception' => new \Exception('Long running transaction rollback')]);
@@ -759,4 +786,20 @@ public function getServerVersion(): string {
 		/** @var ServerInfoAwareConnection $this->_conn */
 		return $this->_conn->getServerVersion();
 	}
+
+	/**
+	 * Log a database exception if enabled
+	 *
+	 * @param \Exception $exception
+	 * @return void
+	 */
+	public function logDatabaseException(\Exception $exception): void {
+		if ($this->logDbException) {
+			if ($exception instanceof Exception\UniqueConstraintViolationException) {
+				$this->logger->info($exception->getMessage(), ['exception' => $exception, 'transaction' => $this->transactionBacktrace]);
+			} else {
+				$this->logger->error($exception->getMessage(), ['exception' => $exception, 'transaction' => $this->transactionBacktrace]);
+			}
+		}
+	}
 }
diff --git a/lib/private/DB/ConnectionAdapter.php b/lib/private/DB/ConnectionAdapter.php
@@ -240,4 +240,8 @@ public function getDatabaseProvider(): string {
 	public function getServerVersion(): string {
 		return $this->inner->getServerVersion();
 	}
+
+	public function logDatabaseException(\Exception $exception) {
+		$this->inner->logDatabaseException($exception);
+	}
 }
diff --git a/lib/private/DB/QueryBuilder/QueryBuilder.php b/lib/private/DB/QueryBuilder/QueryBuilder.php
@@ -253,6 +253,8 @@ public function execute(?IDBConnection $connection = null) {
 			// `IQueryBuilder->execute` never wrapped the exception, but `executeQuery` and `executeStatement` do
 			/** @var \Doctrine\DBAL\Exception $previous */
 			$previous = $e->getPrevious();
+
+			$this->connection->logDatabaseException($previous);
 			throw $previous;
 		}
 	}