Diagnostics event logging to Nextcloud log

Signed-off-by: Julius Härtl <jus@bitgrid.net>

Add config samples

Signed-off-by: Julius Härtl <jus@bitgrid.net>

config/config.sample.php

@@ -2079,4 +2079,18 @@ $CONFIG = [
  * Also, it might log sensitive data into a plain text file.
  */
 'ldap_log_file' => '',
+
+/**
+ * Enable diagnostics event logging
+ *
+ * If enabled the timings of common execution steps will be logged to the
+ * Nextcloud log at debug level. log.condition is useful to enable this on
+ * production systems to only log under some conditions
+ */
+'diagnostics.logging' => true,
+
+/**
+ * Limit diagnostics event logging to events longer than the configured threshold in ms
+ */
+'diagnostics.logging.threshold' => 0,
 ];

lib/private/AppFramework/DependencyInjection/DIContainer.php

@@ -46,6 +46,7 @@ use OC\AppFramework\Middleware\SessionMiddleware;
 use OC\AppFramework\ScopedPsrLogger;
 use OC\AppFramework\Utility\SimpleContainer;
 use OC\Core\Middleware\TwoFactorMiddleware;
+use OC\Diagnostics\EventLogger;
 use OC\Log\PsrLoggerAdapter;
 use OC\ServerContainer;
 use OC\Settings\AuthorizedGroupMapper;
@@ -184,7 +185,8 @@ class DIContainer extends SimpleContainer implements IAppContainer {
 				$c->get(IRequest::class),
 				$c->get(IConfig::class),
 				$c->get(IDBConnection::class),
-				$c->get(LoggerInterface::class)
+				$c->get(LoggerInterface::class),
+				$c->get(EventLogger::class)
 			);
 		});
 

lib/private/AppFramework/Http/Dispatcher.php

@@ -39,6 +39,7 @@ use OC\DB\ConnectionAdapter;
 use OCP\AppFramework\Controller;
 use OCP\AppFramework\Http\DataResponse;
 use OCP\AppFramework\Http\Response;
+use OCP\Diagnostics\IEventLogger;
 use OCP\IConfig;
 use OCP\IRequest;
 use Psr\Log\LoggerInterface;
@@ -69,6 +70,9 @@ class Dispatcher {
 	/** @var LoggerInterface */
 	private $logger;
 
+	/** @var IEventLogger */
+	private $eventLogger;
+
 	/**
 	 * @param Http $protocol the http protocol with contains all status headers
 	 * @param MiddlewareDispatcher $middlewareDispatcher the dispatcher which
@@ -79,6 +83,7 @@ class Dispatcher {
 	 * @param IConfig $config
 	 * @param ConnectionAdapter $connection
 	 * @param LoggerInterface $logger
+	 * @param IEventLogger $eventLogger
 	 */
 	public function __construct(Http $protocol,
 								MiddlewareDispatcher $middlewareDispatcher,
@@ -86,7 +91,8 @@ class Dispatcher {
 								IRequest $request,
 								IConfig $config,
 								ConnectionAdapter $connection,
-								LoggerInterface $logger) {
+								LoggerInterface $logger,
+								IEventLogger $eventLogger) {
 		$this->protocol = $protocol;
 		$this->middlewareDispatcher = $middlewareDispatcher;
 		$this->reflector = $reflector;
@@ -94,6 +100,7 @@ class Dispatcher {
 		$this->config = $config;
 		$this->connection = $connection;
 		$this->logger = $logger;
+		$this->eventLogger = $eventLogger;
 	}
 
 
@@ -214,7 +221,9 @@ class Dispatcher {
 			$arguments[] = $value;
 		}
 
+		$this->eventLogger->start('controller:' . get_class($controller) . '::' . $methodName, 'App framework controller execution');
 		$response = \call_user_func_array([$controller, $methodName], $arguments);
+		$this->eventLogger->end('controller:' . get_class($controller) . '::' . $methodName);
 
 		// format response
 		if ($response instanceof DataResponse || !($response instanceof Response)) {

lib/private/Diagnostics/Event.php

@@ -100,4 +100,8 @@ class Event implements IEvent {
 		}
 		return $this->end - $this->start;
 	}
+
+	public function __toString() {
+		return $this->getId() . ' ' . $this->getDescription() . ' ' . $this->getDuration();
+	}
 }

lib/private/Diagnostics/EventLogger.php

@@ -24,25 +24,58 @@
  */
 namespace OC\Diagnostics;
 
+use OC\Log;
+use OC\SystemConfig;
+use OCP\Diagnostics\IEvent;
 use OCP\Diagnostics\IEventLogger;
+use Psr\Log\LoggerInterface;
 
 class EventLogger implements IEventLogger {
-	/**
-	 * @var \OC\Diagnostics\Event[]
-	 */
+
+	/** @var Event[] */
 	private $events = [];
-	
+
+	/** @var SystemConfig */
+	private $config;
+
+	/** @var LoggerInterface */
+	private $logger;
+
+	/** @var Log */
+	private $internalLogger;
+
 	/**
 	 * @var bool - Module needs to be activated by some app
 	 */
 	private $activated = false;
 
+	public function __construct(SystemConfig $config, LoggerInterface $logger, Log $internalLogger) {
+		$this->config = $config;
+		$this->logger = $logger;
+		$this->internalLogger = $internalLogger;
+
+		if ($this->isLoggingActivated()) {
+			$this->activate();
+		}
+	}
+
+	public function isLoggingActivated(): bool {
+		if ($this->config->getValue('debug', false)) {
+			return true;
+		}
+
+		$isDebugLevel = $this->internalLogger->getLogLevel([]) === Log::DEBUG;
+		$systemValue = (bool)$this->config->getValue('diagnostics.logging', false);
+		return $systemValue && $isDebugLevel;
+	}
+
 	/**
 	 * @inheritdoc
 	 */
 	public function start($id, $description) {
 		if ($this->activated) {
 			$this->events[$id] = new Event($id, $description, microtime(true));
+			$this->writeLog($this->events[$id]);
 		}
 	}
 
@@ -53,6 +86,7 @@ class EventLogger implements IEventLogger {
 		if ($this->activated && isset($this->events[$id])) {
 			$timing = $this->events[$id];
 			$timing->end(microtime(true));
+			$this->writeLog($timing);
 		}
 	}
 
@@ -63,6 +97,7 @@ class EventLogger implements IEventLogger {
 		if ($this->activated) {
 			$this->events[$id] = new Event($id, $description, $start);
 			$this->events[$id]->end($end);
+			$this->writeLog($this->events[$id]);
 		}
 	}
 
@@ -72,11 +107,29 @@ class EventLogger implements IEventLogger {
 	public function getEvents() {
 		return $this->events;
 	}
-	
+
 	/**
 	 * @inheritdoc
 	 */
 	public function activate() {
 		$this->activated = true;
 	}
+
+	private function writeLog(IEvent $event) {
+		if ($this->activated) {
+			if ($event->getEnd() === null) {
+				return;
+			}
+			$duration = $event->getDuration();
+			$timeInMs = round($duration * 1000, 4);
+
+			$loggingMinimum = (int)$this->config->getValue('diagnostics.logging.threshold', 0);
+			if ($loggingMinimum > 0 && $timeInMs < $loggingMinimum) {
+				return;
+			}
+
+			$message = microtime() . ' - ' . $event->getId() . ': ' . $timeInMs . ' (' . $event->getDescription() . ')';
+			$this->logger->debug($message, ['app' => 'diagnostics']);
+		}
+	}
 }

lib/private/Log.php

@@ -232,7 +232,7 @@ class Log implements ILogger, IDataLogger {
 		}
 	}
 
-	private function getLogLevel($context) {
+	public function getLogLevel($context) {
 		$logCondition = $this->config->getValue('log.condition', []);
 
 		/**

lib/private/Server.php

@@ -871,12 +871,7 @@ class Server extends ServerContainer implements IServerContainer {
 		});
 		$this->registerDeprecatedAlias('HttpClientService', IClientService::class);
 		$this->registerService(IEventLogger::class, function (ContainerInterface $c) {
-			$eventLogger = new EventLogger();
-			if ($c->get(SystemConfig::class)->getValue('debug', false)) {
-				// In debug mode, module is being activated by default
-				$eventLogger->activate();
-			}
-			return $eventLogger;
+			return new EventLogger($c->get(SystemConfig::class), $c->get(LoggerInterface::class), $c->get(Log::class));
 		});
 		/** @deprecated 19.0.0 */
 		$this->registerDeprecatedAlias('EventLogger', IEventLogger::class);