feat(dav): report inefficient DAV plugins in logs

Signed-off-by: Salvatore Martire <4652631+salmart-dev@users.noreply.github.com>

apps/dav/composer/composer/autoload_classmap.php

@@ -216,6 +216,7 @@ return array(
     'OCA\\DAV\\Connector\\Sabre\\Node' => $baseDir . '/../lib/Connector/Sabre/Node.php',
     'OCA\\DAV\\Connector\\Sabre\\ObjectTree' => $baseDir . '/../lib/Connector/Sabre/ObjectTree.php',
     'OCA\\DAV\\Connector\\Sabre\\Principal' => $baseDir . '/../lib/Connector/Sabre/Principal.php',
+    'OCA\\DAV\\Connector\\Sabre\\PropFindMonitorPlugin' => $baseDir . '/../lib/Connector/Sabre/PropFindMonitorPlugin.php',
     'OCA\\DAV\\Connector\\Sabre\\PropfindCompressionPlugin' => $baseDir . '/../lib/Connector/Sabre/PropfindCompressionPlugin.php',
     'OCA\\DAV\\Connector\\Sabre\\PublicAuth' => $baseDir . '/../lib/Connector/Sabre/PublicAuth.php',
     'OCA\\DAV\\Connector\\Sabre\\QuotaPlugin' => $baseDir . '/../lib/Connector/Sabre/QuotaPlugin.php',

apps/dav/composer/composer/autoload_static.php

@@ -231,6 +231,7 @@ class ComposerStaticInitDAV
         'OCA\\DAV\\Connector\\Sabre\\Node' => __DIR__ . '/..' . '/../lib/Connector/Sabre/Node.php',
         'OCA\\DAV\\Connector\\Sabre\\ObjectTree' => __DIR__ . '/..' . '/../lib/Connector/Sabre/ObjectTree.php',
         'OCA\\DAV\\Connector\\Sabre\\Principal' => __DIR__ . '/..' . '/../lib/Connector/Sabre/Principal.php',
+        'OCA\\DAV\\Connector\\Sabre\\PropFindMonitorPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PropFindMonitorPlugin.php',
         'OCA\\DAV\\Connector\\Sabre\\PropfindCompressionPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PropfindCompressionPlugin.php',
         'OCA\\DAV\\Connector\\Sabre\\PublicAuth' => __DIR__ . '/..' . '/../lib/Connector/Sabre/PublicAuth.php',
         'OCA\\DAV\\Connector\\Sabre\\QuotaPlugin' => __DIR__ . '/..' . '/../lib/Connector/Sabre/QuotaPlugin.php',

apps/dav/lib/Connector/Sabre/PropFindMonitorPlugin.php

@@ -0,0 +1,78 @@
+<?php
+
+declare(strict_types = 1);
+
+/**
+ * SPDX-FileCopyrightText: 2025 Nextcloud GmbH and Nextcloud contributors
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+namespace OCA\DAV\Connector\Sabre;
+
+use Sabre\DAV\Server as SabreServer;
+use Sabre\DAV\ServerPlugin;
+use Sabre\HTTP\RequestInterface;
+use Sabre\HTTP\ResponseInterface;
+
+/**
+ * This plugin runs after requests and logs an error if a plugin is detected
+ * to be doing too many SQL requests.
+ */
+class PropFindMonitorPlugin extends ServerPlugin {
+
+	/**
+	 * A Plugin can scan up to this amount of nodes without an error being
+	 * reported.
+	 */
+	public const THRESHOLD_NODES = 50;
+
+	/**
+	 * A plugin can use up to this amount of queries per node.
+	 */
+	public const THRESHOLD_QUERY_FACTOR = 1;
+
+	private SabreServer $server;
+
+	public function initialize(SabreServer $server): void {
+		$this->server = $server;
+		$this->server->on('afterResponse', [$this, 'afterResponse']);
+	}
+
+	public function afterResponse(
+		RequestInterface $request,
+		ResponseInterface $response): void {
+		if (!$this->server instanceof Server) {
+			return;
+		}
+
+		$pluginQueries = $this->server->getPluginQueries();
+		if (empty($pluginQueries)) {
+			return;
+		}
+		$maxDepth = max(0, ...array_keys($pluginQueries));
+		// entries at the top are usually not interesting
+		unset($pluginQueries[$maxDepth]);
+
+		$logger = $this->server->getLogger();
+		foreach ($pluginQueries as $depth => $propFinds) {
+			foreach ($propFinds as $pluginName => $propFind) {
+				[
+					'queries' => $queries,
+					'nodes' => $nodes
+				] = $propFind;
+				if ($queries === 0 || $nodes > $queries || $nodes < self::THRESHOLD_NODES
+					|| $queries < $nodes * self::THRESHOLD_QUERY_FACTOR) {
+					continue;
+				}
+				$logger->error(
+					'{name} scanned {scans} nodes with {count} queries in depth {depth}/{maxDepth}. This is bad for performance, please report to the plugin developer!', [
+						'name' => $pluginName,
+						'scans' => $nodes,
+						'count' => $queries,
+						'depth' => $depth,
+						'maxDepth' => $maxDepth,
+					]
+				);
+			}
+		}
+	}
+}

apps/dav/lib/Connector/Sabre/Server.php

@@ -7,7 +7,11 @@
  */
 namespace OCA\DAV\Connector\Sabre;
 
+use OC\DB\Connection;
+use Override;
 use Sabre\DAV\Exception;
+use Sabre\DAV\INode;
+use Sabre\DAV\PropFind;
 use Sabre\DAV\Version;
 use TypeError;
 
@@ -21,6 +25,14 @@ use TypeError;
 class Server extends \Sabre\DAV\Server {
 	/** @var CachingTree $tree */
 
+	/**
+	 * Tracks queries done by plugins.
+	 * @var array<int, array<string, array{nodes:int, queries:int}>>
+	 */
+	private array $pluginQueries = [];
+
+	public bool $debugEnabled = false;
+
 	/**
 	 * @see \Sabre\DAV\Server
 	 */
@@ -30,6 +42,97 @@ class Server extends \Sabre\DAV\Server {
 		$this->enablePropfindDepthInfinity = true;
 	}
 
+	#[Override]
+	public function once(
+		string $eventName,
+		callable $callBack,
+		int $priority = 100,
+	): void {
+		$this->debugEnabled ? $this->monitorPropfindQueries(
+			parent::once(...),
+			...func_get_args(),
+		) : parent::once(...func_get_args());
+	}
+
+	#[Override]
+	public function on(
+		string $eventName,
+		callable $callBack,
+		int $priority = 100,
+	): void {
+		$this->debugEnabled ? $this->monitorPropfindQueries(
+			parent::on(...),
+			...func_get_args(),
+		) : parent::on(...func_get_args());
+	}
+
+	/**
+	 * Wraps the handler $callBack into a query-monitoring function and calls
+	 * $parentFn to register it.
+	 */
+	private function monitorPropfindQueries(
+		callable $parentFn,
+		string $eventName,
+		callable $callBack,
+		int $priority = 100,
+	): void {
+		if ($eventName !== 'propFind') {
+			$parentFn($eventName, $callBack, $priority);
+			return;
+		}
+
+		$pluginName = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 3)[2]['class'] ?? 'unknown';
+		$callback = $this->getMonitoredCallback($callBack, $pluginName);
+
+		$parentFn($eventName, $callback, $priority);
+	}
+
+	/**
+	 * Returns a callable that wraps $callBack with code that monitors and
+	 * records queries per plugin.
+	 */
+	private function getMonitoredCallback(
+		callable $callBack,
+		string $pluginName,
+	): callable {
+		return function (PropFind $propFind, INode $node) use (
+			$callBack,
+			$pluginName,
+		) {
+			$connection = \OCP\Server::get(Connection::class);
+			$queriesBefore = $connection->getStats()['executed'];
+			$result = $callBack($propFind, $node);
+			$queriesAfter = $connection->getStats()['executed'];
+			$this->trackPluginQueries(
+				$pluginName,
+				$queriesAfter - $queriesBefore,
+				$propFind->getDepth()
+			);
+
+			return $result;
+		};
+	}
+
+	/**
+	 * Tracks the queries executed by a specific plugin.
+	 */
+	private function trackPluginQueries(
+		string $pluginName,
+		int $queriesExecuted,
+		int $depth,
+	): void {
+		// report only nodes which cause queries to the DB
+		if ($queriesExecuted === 0) {
+			return;
+		}
+
+		$this->pluginQueries[$depth][$pluginName]['nodes']
+			= ($this->pluginQueries[$depth][$pluginName]['nodes'] ?? 0) + 1;
+
+		$this->pluginQueries[$depth][$pluginName]['queries']
+			= ($this->pluginQueries[$depth][$pluginName]['queries'] ?? 0) + $queriesExecuted;
+	}
+
 	/**
 	 *
 	 * @return void
@@ -115,4 +218,13 @@ class Server extends \Sabre\DAV\Server {
 			$this->sapi->sendResponse($this->httpResponse);
 		}
 	}
+
+	/**
+	 * Returns queries executed by registered plugins.
+	 *
+	 * @return array<int, array<string, array{nodes:int, queries:int}>>
+	 */
+	public function getPluginQueries(): array {
+		return $this->pluginQueries;
+	}
 }

apps/dav/lib/Connector/Sabre/ServerFactory.php

@@ -68,6 +68,7 @@ class ServerFactory {
 		Plugin $authPlugin,
 		callable $viewCallBack,
 	): Server {
+		$debugEnabled = $this->config->getSystemValue('debug', false);
 		// Fire up server
 		if ($isPublicShare) {
 			$rootCollection = new SimpleCollection('root');
@@ -89,6 +90,10 @@ class ServerFactory {
 		));
 		$server->addPlugin(new AnonymousOptionsPlugin());
 		$server->addPlugin($authPlugin);
+		if ($debugEnabled) {
+			$server->debugEnabled = $debugEnabled;
+			$server->addPlugin(new PropFindMonitorPlugin());
+		}
 		// FIXME: The following line is a workaround for legacy components relying on being able to send a GET to /
 		$server->addPlugin(new DummyGetResponsePlugin());
 		$server->addPlugin(new ExceptionLoggerPlugin('webdav', $this->logger));
@@ -117,7 +122,8 @@ class ServerFactory {
 		}
 
 		// wait with registering these until auth is handled and the filesystem is setup
-		$server->on('beforeMethod:*', function () use ($server, $tree, $viewCallBack, $isPublicShare, $rootCollection): void {
+		$server->on('beforeMethod:*', function () use ($server, $tree,
+			$viewCallBack, $isPublicShare, $rootCollection, $debugEnabled): void {
 			// ensure the skeleton is copied
 			$userFolder = \OC::$server->getUserFolder();
 
@@ -181,7 +187,7 @@ class ServerFactory {
 					\OCP\Server::get(IFilenameValidator::class),
 					\OCP\Server::get(IAccountManager::class),
 					false,
-					!$this->config->getSystemValue('debug', false)
+					!$debugEnabled
 				)
 			);
 			$server->addPlugin(new QuotaPlugin($view));

apps/dav/lib/Server.php

@@ -45,6 +45,7 @@ use OCA\DAV\Connector\Sabre\FilesReportPlugin;
 use OCA\DAV\Connector\Sabre\LockPlugin;
 use OCA\DAV\Connector\Sabre\MaintenancePlugin;
 use OCA\DAV\Connector\Sabre\PropfindCompressionPlugin;
+use OCA\DAV\Connector\Sabre\PropFindMonitorPlugin;
 use OCA\DAV\Connector\Sabre\QuotaPlugin;
 use OCA\DAV\Connector\Sabre\RequestIdHeaderPlugin;
 use OCA\DAV\Connector\Sabre\SharesPlugin;
@@ -108,6 +109,7 @@ class Server {
 		private IRequest $request,
 		private string $baseUri,
 	) {
+		$debugEnabled = \OCP\Server::get(IConfig::class)->getSystemValue('debug', false);
 		$this->profiler = \OCP\Server::get(IProfiler::class);
 		if ($this->profiler->isEnabled()) {
 			/** @var IEventLogger $eventLogger */
@@ -120,6 +122,7 @@ class Server {
 
 		$root = new RootCollection();
 		$this->server = new \OCA\DAV\Connector\Sabre\Server(new CachingTree($root));
+		$this->server->setLogger($logger);
 
 		// Add maintenance plugin
 		$this->server->addPlugin(new MaintenancePlugin(\OCP\Server::get(IConfig::class), \OC::$server->getL10N('dav')));
@@ -167,7 +170,9 @@ class Server {
 		$authPlugin->addBackend($authBackend);
 
 		// debugging
-		if (\OCP\Server::get(IConfig::class)->getSystemValue('debug', false)) {
+		if ($debugEnabled) {
+			$this->server->debugEnabled = true;
+			$this->server->addPlugin(new PropFindMonitorPlugin());
 			$this->server->addPlugin(new \Sabre\DAV\Browser\Plugin());
 		} else {
 			$this->server->addPlugin(new DummyGetResponsePlugin());

apps/dav/tests/unit/Connector/Sabre/PropFindMonitorPluginTest.php

@@ -0,0 +1,123 @@
+<?php
+
+/**
+ * SPDX-FileCopyrightText: 2025 Nextcloud GmbH and Nextcloud contributors
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+namespace unit\Connector\Sabre;
+
+use OCA\DAV\Connector\Sabre\PropFindMonitorPlugin;
+use OCA\DAV\Connector\Sabre\Server;
+use PHPUnit\Framework\MockObject\MockObject;
+use Psr\Log\LoggerInterface;
+use Sabre\HTTP\Request;
+use Sabre\HTTP\Response;
+use Test\TestCase;
+
+class PropFindMonitorPluginTest extends TestCase {
+
+	private PropFindMonitorPlugin $plugin;
+	private Server&MockObject $server;
+	private LoggerInterface&MockObject $logger;
+	private Request&MockObject $request;
+	private Response&MockObject $response;
+
+	public static function dataTest(): array {
+		$minQueriesTrigger = PropFindMonitorPlugin::THRESHOLD_QUERY_FACTOR
+			* PropFindMonitorPlugin::THRESHOLD_NODES;
+		return [
+			'No queries logged' => [[], 0],
+			'Plugins with queries in less than threshold nodes should not be logged' => [
+				[
+					[
+						'PluginName' => ['queries' => 100, 'nodes'
+							=> PropFindMonitorPlugin::THRESHOLD_NODES - 1]
+					],
+					[],
+				],
+				0
+			],
+			'Plugins with query-to-node ratio less than threshold should not be logged' => [
+				[
+					[
+						'PluginName' => [
+							'queries' => $minQueriesTrigger - 1,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES ],
+					],
+					[],
+				],
+				0
+			],
+			'Plugins with more nodes scanned than queries executed should not be logged' => [
+				[
+					[
+						'PluginName' => [
+							'queries' => $minQueriesTrigger,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES * 2],
+					],
+					[],
+				],
+				0
+			],
+			'Plugins with queries only in highest depth level should not be logged' => [
+				[
+					[
+						'PluginName' => [
+							'queries' => $minQueriesTrigger,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES - 1
+						]
+					],
+					[
+						'PluginName' => [
+							'queries' => $minQueriesTrigger * 2,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES
+						]
+					]
+				],
+				0
+			],
+			'Plugins with too many queries should be logged' => [
+				[
+					[
+						'FirstPlugin' => [
+							'queries' => $minQueriesTrigger,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES,
+						],
+						'SecondPlugin' => [
+							'queries' => $minQueriesTrigger,
+							'nodes' => PropFindMonitorPlugin::THRESHOLD_NODES,
+						]
+					],
+					[]
+				],
+				2
+			]
+		];
+	}
+
+	/**
+	 * @dataProvider dataTest
+	 */
+	public function test(array $queries, $expectedLogCalls): void {
+		$this->plugin->initialize($this->server);
+		$this->server->expects($this->once())->method('getPluginQueries')
+			->willReturn($queries);
+
+		$this->server->expects(empty($queries) ? $this->never() : $this->once())
+			->method('getLogger')
+			->willReturn($this->logger);
+
+		$this->logger->expects($this->exactly($expectedLogCalls))->method('error');
+		$this->plugin->afterResponse($this->request, $this->response);
+	}
+
+	protected function setUp(): void {
+		parent::setUp();
+
+		$this->plugin = new PropFindMonitorPlugin();
+		$this->server = $this->createMock(Server::class);
+		$this->logger = $this->createMock(LoggerInterface::class);
+		$this->request = $this->createMock(Request::class);
+		$this->response = $this->createMock(Response::class);
+	}
+}