Merge pull request #31124 from nextcloud/enh/diagnostics-logging

Diagnostics event logging to log

Author: juliusknorr

apps/dav/lib/Server.php

@@ -35,6 +35,7 @@
 namespace OCA\DAV;
 
 use OCA\DAV\Connector\Sabre\RequestIdHeaderPlugin;
+use OCP\Diagnostics\IEventLogger;
 use Psr\Log\LoggerInterface;
 use OCA\DAV\AppInfo\PluginManager;
 use OCA\DAV\CalDAV\BirthdayService;
@@ -337,7 +338,11 @@ function () {
 	}
 
 	public function exec() {
+		/** @var IEventLogger $eventLogger */
+		$eventLogger = \OC::$server->get(IEventLogger::class);
+		$eventLogger->start('dav_server_exec', '');
 		$this->server->exec();
+		$eventLogger->end('dav_server_exec');
 	}
 
 	private function requestIsForSubtree(array $subTrees): bool {

config/config.sample.php

@@ -2079,4 +2079,18 @@
  * 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/base.php

@@ -61,6 +61,7 @@
  * along with this program. If not, see <http://www.gnu.org/licenses/>
  *
  */
+
 use OCP\EventDispatcher\IEventDispatcher;
 use OCP\Group\Events\UserRemovedEvent;
 use OCP\ILogger;
@@ -595,8 +596,13 @@ public static function init() {
 		// setup the basic server
 		self::$server = new \OC\Server(\OC::$WEBROOT, self::$config);
 		self::$server->boot();
+
 		$eventLogger = \OC::$server->getEventLogger();
 		$eventLogger->log('autoloader', 'Autoloader', $loaderStart, $loaderEnd);
+		$eventLogger->start('request', 'Full request after autoloading');
+		register_shutdown_function(function () use ($eventLogger) {
+			$eventLogger->end('request');
+		});
 		$eventLogger->start('boot', 'Initialize');
 
 		// Override php.ini and log everything if we're troubleshooting
@@ -794,6 +800,7 @@ public static function init() {
 			}
 		}
 		$eventLogger->end('boot');
+		$eventLogger->log('init', 'OC::init', $loaderStart, microtime(true));
 	}
 
 	/**

lib/private/AppFramework/Bootstrap/Coordinator.php

@@ -30,6 +30,7 @@
 
 namespace OC\AppFramework\Bootstrap;
 
+use OCP\Diagnostics\IEventLogger;
 use function class_exists;
 use function class_implements;
 use function in_array;
@@ -58,6 +59,9 @@ class Coordinator {
 	/** @var IEventDispatcher */
 	private $eventDispatcher;
 
+	/** @var IEventLogger */
+	private $eventLogger;
+
 	/** @var LoggerInterface */
 	private $logger;
 
@@ -72,12 +76,14 @@ public function __construct(
 		Registry $registry,
 		IManager $dashboardManager,
 		IEventDispatcher $eventListener,
+		IEventLogger $eventLogger,
 		LoggerInterface $logger
 	) {
 		$this->serverContainer = $container;
 		$this->registry = $registry;
 		$this->dashboardManager = $dashboardManager;
 		$this->eventDispatcher = $eventListener;
+		$this->eventLogger = $eventLogger;
 		$this->logger = $logger;
 	}
 
@@ -126,7 +132,9 @@ private function registerApps(array $appIds): void {
 						continue;
 					}
 
+					$this->eventLogger->start('bootstrap:register_app_' . $appId, '');
 					$application->register($this->registrationContext->for($appId));
+					$this->eventLogger->end('bootstrap:register_app_' . $appId);
 				}
 			} catch (Throwable $e) {
 				$this->logger->emergency('Error during app service registration: ' . $e->getMessage(), [
@@ -172,6 +180,7 @@ public function bootApp(string $appId): void {
 		 * the instance was already created for register, but any other
 		 * (legacy) code will now do their magic via the constructor.
 		 */
+		$this->eventLogger->start('bootstrap:boot_app_' . $appId, '');
 		try {
 			/** @var App $application */
 			$application = $this->serverContainer->query($applicationClassName);
@@ -189,6 +198,7 @@ public function bootApp(string $appId): void {
 				'exception' => $e,
 			]);
 		}
+		$this->eventLogger->end('bootstrap:boot_app_' . $appId);
 	}
 
 	public function isBootable(string $appId) {

lib/private/AppFramework/DependencyInjection/DIContainer.php

@@ -46,6 +46,7 @@
 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 @@ public function __construct($appName, $urlParams = [], ServerContainer $server =
 				$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 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,21 +83,24 @@ class Dispatcher {
 	 * @param IConfig $config
 	 * @param ConnectionAdapter $connection
 	 * @param LoggerInterface $logger
+	 * @param IEventLogger $eventLogger
 	 */
 	public function __construct(Http $protocol,
 								MiddlewareDispatcher $middlewareDispatcher,
 								ControllerMethodReflector $reflector,
 								IRequest $request,
 								IConfig $config,
 								ConnectionAdapter $connection,
-								LoggerInterface $logger) {
+								LoggerInterface $logger,
+								IEventLogger $eventLogger) {
 		$this->protocol = $protocol;
 		$this->middlewareDispatcher = $middlewareDispatcher;
 		$this->reflector = $reflector;
 		$this->request = $request;
 		$this->config = $config;
 		$this->connection = $connection;
 		$this->logger = $logger;
+		$this->eventLogger = $eventLogger;
 	}
 
 
@@ -214,7 +221,9 @@ private function executeController(Controller $controller, string $methodName):
 			$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/DB/Connection.php

@@ -81,7 +81,17 @@ class Connection extends \Doctrine\DBAL\Connection {
 	 */
 	public function connect() {
 		try {
-			return parent::connect();
+			if ($this->_conn) {
+				return parent::connect();
+			}
+
+			// Only trigger the event logger for the initial connect call
+			$eventLogger = \OC::$server->getEventLogger();
+			$eventLogger->start('connect:db', 'db connection opened');
+			$status = parent::connect();
+			$eventLogger->end('connect:db');
+
+			return $status;
 		} catch (Exception $e) {
 			// throw a new exception to prevent leaking info from the stacktrace
 			throw new Exception('Failed to connect to the database: ' . $e->getMessage(), $e->getCode());

lib/private/Diagnostics/Event.php

@@ -100,4 +100,8 @@ public function getDuration() {
 		}
 		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) {
+	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 @@ public function end($id) {
 		if ($this->activated && isset($this->events[$id])) {
 			$timing = $this->events[$id];
 			$timing->end(microtime(true));
+			$this->writeLog($timing);
 		}
 	}
 
@@ -63,6 +97,7 @@ public function log($id, $description, $start, $end) {
 		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 @@ public function log($id, $description, $start, $end) {
 	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 @@ public function log(int $level, string $message, array $context = []) {
 		}
 	}
 
-	private function getLogLevel($context) {
+	public function getLogLevel($context) {
 		$logCondition = $this->config->getValue('log.condition', []);
 
 		/**