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 · Apr 11, 2024 · feb7100 · feb7100
1 parent de2a41a
commit feb7100
Show file tree

Hide file tree

Showing 3 changed files with 55 additions and 6 deletions.
diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php
@@ -90,6 +90,10 @@ class Connection extends PrimaryReadReplicaConnection {
 	/** @var array<string, int> */
 	protected $tableDirtyWrites = [];
 
+	private ?array $transactionBacktrace = null;
+
+	private bool $logDbErrors = false;
+
 	/**
 	 * Initializes a new instance of the Connection class.
 	 *
@@ -310,7 +314,12 @@ public function executeQuery(string $sql, array $params = [], $types = [], ?Quer
 		$sql = $this->adapter->fixupStatement($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;
+		}
 	}
 
 	/**
@@ -331,7 +340,12 @@ public function executeUpdate(string $sql, array $params = [], array $types = []
 		$sql = $this->adapter->fixupStatement($sql);
 		$this->queriesExecuted++;
 		$this->logQueryToFile($sql);
-		return parent::executeUpdate($sql, $params, $types);
+		try {
+			return parent::executeUpdate($sql, $params, $types);
+		} catch (\Exception $e) {
+			$this->logDatabaseException($e);
+			throw $e;
+		}
 	}
 
 	/**
@@ -357,7 +371,12 @@ public function executeStatement($sql, array $params = [], array $types = []): i
 		$sql = $this->adapter->fixupStatement($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 {
@@ -424,11 +443,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) {
@@ -677,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();
@@ -686,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->warning('Transaction took ' . $timeTook . 's', ['exception' => new \Exception('Transaction took ' . $timeTook . 's')]);
@@ -698,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->warning('Transaction rollback took longer than 1s: ' . $timeTook, ['exception' => new \Exception('Long running transaction rollback')]);
@@ -727,4 +759,12 @@ private function reconnectIfNeeded(): void {
 	private function getConnectionName(): string {
 		return $this->isConnectedToPrimary() ? 'primary' : 'replica';
 	}
+
+	public function logDatabaseException(\Exception $exception): void {
+		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
@@ -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);
+	}
 }
diff --git a/lib/private/DB/QueryBuilder/QueryBuilder.php b/lib/private/DB/QueryBuilder/QueryBuilder.php
@@ -277,7 +277,12 @@ public function execute() {
 			]);
 		}
 
-		$result = $this->queryBuilder->execute();
+		try {
+			$result = $this->queryBuilder->execute();
+		} catch (\Exception $e) {
+			$this->connection->logDatabaseException($e);
+			throw $e;
+		}
 		if (is_int($result)) {
 			return $result;
 		}