From c95206ad381afb5985d4ed93d99a1b98121abcec Mon Sep 17 00:00:00 2001
From: Robin Appelman <robin@icewind.nl>
Date: Thu, 11 Apr 2024 17:08:34 +0200
Subject: [PATCH] feat: add additional logging for database errors

including the stack trace of the current database transaction

Signed-off-by: Robin Appelman <robin@icewind.nl>
---
 lib/private/DB/Connection.php        | 51 +++++++++++++++++++++++++---
 lib/private/DB/ConnectionAdapter.php |  4 +++
 2 files changed, 51 insertions(+), 4 deletions(-)

diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php
index 6337eee947584..6e2db8e47bcd3 100644
--- a/lib/private/DB/Connection.php
+++ b/lib/private/DB/Connection.php
@@ -92,6 +92,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;
 
@@ -124,6 +127,7 @@ public function __construct(
 		$this->logger = \OC::$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 */
@@ -325,7 +329,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;
+		}
 	}
 
 	/**
@@ -370,7 +379,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 {
@@ -437,11 +451,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) {
@@ -700,6 +724,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();
@@ -709,6 +734,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')]);
@@ -721,6 +747,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')]);
@@ -750,4 +777,20 @@ private function reconnectIfNeeded(): void {
 	private function getConnectionName(): string {
 		return $this->isConnectedToPrimary() ? 'primary' : 'replica';
 	}
+
+	/**
+	 * 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
index 411ce3a7e55df..890161ef76f0f 100644
--- a/lib/private/DB/ConnectionAdapter.php
+++ b/lib/private/DB/ConnectionAdapter.php
@@ -261,4 +261,8 @@ public function getDatabaseProvider(): string {
 			throw new \Exception('Database ' . $platform::class . ' not supported');
 		}
 	}
+
+	public function logDatabaseException(\Exception $exception) {
+		$this->inner->logDatabaseException($exception);
+	}
 }