[stable21] Diagnostics event logging to log

apps/dav/lib/Server.php

@@ -329,7 +329,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 {

lib/base.php

@@ -586,8 +586,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
@@ -783,6 +788,7 @@ public static function init() {
 			}
 		}
 		$eventLogger->end('boot');
+		$eventLogger->log('init', 'OC::init', $loaderStart, microtime(true));
 	}
 
 	/**

lib/private/AppFramework/Bootstrap/Coordinator.php

@@ -75,6 +75,7 @@ public function __construct(IServerContainer $container,
 		$this->registry = $registry;
 		$this->dashboardManager = $dashboardManager;
 		$this->eventDispatcher = $eventListener;
+		$this->eventLogger = $eventLogger;
 		$this->logger = $logger;
 	}
 
@@ -123,6 +124,7 @@ private function registerApps(array $appIds): void {
 						continue;
 					}
 					$application->register($this->registrationContext->for($appId));
+					$this->eventLogger->end('bootstrap:register_app_' . $appId);
 				}
 			} catch (Throwable $e) {
 				$this->logger->logException($e, [
@@ -169,6 +171,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);
@@ -187,6 +190,7 @@ public function bootApp(string $appId): void {
 				'level' => ILogger::FATAL,
 			]);
 		}
+		$this->eventLogger->end('bootstrap:boot_app_' . $appId);
 	}
 
 	public function isBootable(string $appId) {

lib/private/AppFramework/DependencyInjection/DIContainer.php

@@ -47,6 +47,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 OCA\WorkflowEngine\Manager;
@@ -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

@@ -40,6 +40,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;
@@ -70,6 +71,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
@@ -80,21 +84,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;
 	}
 
 
@@ -215,7 +222,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

@@ -79,7 +79,17 @@ class Connection extends ReconnectWrapper {
 	 */
 	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

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

lib/private/Diagnostics/EventLogger.php

@@ -25,25 +25,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]);
 		}
 	}
 
@@ -54,6 +87,7 @@ public function end($id) {
 		if ($this->activated && isset($this->events[$id])) {
 			$timing = $this->events[$id];
 			$timing->end(microtime(true));
+			$this->writeLog($timing);
 		}
 	}
 
@@ -64,6 +98,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]);
 		}
 	}
 
@@ -73,11 +108,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

@@ -233,7 +233,7 @@ public function log(int $level, string $message, array $context = []) {
 		}
 	}
 
-	private function getLogLevel($context) {
+	public function getLogLevel($context) {
 		$logCondition = $this->config->getValue('log.condition', []);
 
 		/**

lib/private/RedisFactory.php

@@ -27,20 +27,24 @@
 
 namespace OC;
 
+use OCP\Diagnostics\IEventLogger;
+
 class RedisFactory {
 	/** @var  \Redis */
 	private $instance;
 
-	/** @var  SystemConfig */
-	private $config;
+	private SystemConfig $config;
+
+	private IEventLogger $eventLogger;
 
 	/**
 	 * RedisFactory constructor.
 	 *
 	 * @param SystemConfig $config
 	 */
-	public function __construct(SystemConfig $config) {
+	public function __construct(SystemConfig $config, IEventLogger $eventLogger) {
 		$this->config = $config;
+		$this->eventLogger = $eventLogger;
 	}
 
 	private function create() {
@@ -97,6 +101,7 @@ private function create() {
 			if (isset($config['dbindex'])) {
 				$this->instance->select($config['dbindex']);
 			}
+			$this->eventLogger->end('connect:redis');
 		}
 	}
 

lib/private/Server.php

@@ -708,7 +708,7 @@ public function __construct($webRoot, \OC\Config $config) {
 
 		$this->registerService('RedisFactory', function (Server $c) {
 			$systemConfig = $c->get(SystemConfig::class);
-			return new RedisFactory($systemConfig);
+			return new RedisFactory($systemConfig, $c->getEventLogger());
 		});
 
 		$this->registerService(\OCP\Activity\IManager::class, function (Server $c) {
@@ -843,12 +843,7 @@ public function __construct($webRoot, \OC\Config $config) {
 		$this->registerAlias(IClientService::class, ClientService::class);
 		$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);

lib/private/legacy/OC_App.php

@@ -172,6 +172,7 @@ public static function loadApp(string $app) {
 
 		$hasAppPhpFile = is_file($appPath . '/appinfo/app.php');
 
+		\OC::$server->getEventLogger()->start('bootstrap:load_app_' . $app, 'Load app: ' . $app);
 		if ($isBootable && $hasAppPhpFile) {
 			\OC::$server->getLogger()->error('/appinfo/app.php is not loaded when \OCP\AppFramework\Bootstrap\IBootstrap on the application class is used. Migrate everything from app.php to the Application class.', [
 				'app' => $app,
@@ -180,7 +181,6 @@ public static function loadApp(string $app) {
 			\OC::$server->getLogger()->debug('/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.', [
 				'app' => $app,
 			]);
-			\OC::$server->getEventLogger()->start('load_app_' . $app, 'Load app: ' . $app);
 			try {
 				self::requireAppFile($app);
 			} catch (Throwable $ex) {
@@ -200,8 +200,9 @@ public static function loadApp(string $app) {
 					]);
 				}
 			}
-			\OC::$server->getEventLogger()->end('load_app_' . $app);
 		}
+		\OC::$server->getEventLogger()->end('bootstrap:load_app_' . $app);
+
 		$coordinator->bootApp($app);
 
 		$info = self::getAppInfo($app);

tests/lib/AppFramework/Bootstrap/CoordinatorTest.php

@@ -34,6 +34,7 @@
 use OCP\AppFramework\Bootstrap\IRegistrationContext;
 use OCP\AppFramework\QueryException;
 use OCP\Dashboard\IManager;
+use OCP\Diagnostics\IEventLogger;
 use OCP\EventDispatcher\IEventDispatcher;
 use OCP\ILogger;
 use OCP\IServerContainer;
@@ -78,6 +79,7 @@ protected function setUp(): void {
 			$this->crashReporterRegistry,
 			$this->dashboardManager,
 			$this->eventDispatcher,
+			$this->eventLogger,
 			$this->logger
 		);
 	}