Add event logging to app loading

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

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 @@ class OC {
 		// 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
@@ -792,6 +798,7 @@ class OC {
 			}
 		}
 		$eventLogger->end('boot');
+		$eventLogger->log('init', 'OC::init', $loaderStart, microtime(true));
 	}
 
 	/**

lib/private/AppFramework/Bootstrap/Coordinator.php

@@ -30,6 +30,7 @@ declare(strict_types=1);
 
 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 @@ class Coordinator {
 		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 @@ class Coordinator {
 						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 @@ class Coordinator {
 		 * 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 @@ class Coordinator {
 				'exception' => $e,
 			]);
 		}
+		$this->eventLogger->end('bootstrap:boot_app_' . $appId);
 	}
 
 	public function isBootable(string $appId) {

lib/private/Diagnostics/EventLogger.php

@@ -72,7 +72,7 @@ class EventLogger implements IEventLogger {
 	/**
 	 * @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]);

lib/private/legacy/OC_App.php

@@ -173,6 +173,7 @@ class OC_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,
@@ -181,7 +182,6 @@ class OC_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) {
@@ -201,8 +201,9 @@ class OC_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\IBootstrap;
 use OCP\AppFramework\Bootstrap\IRegistrationContext;
 use OCP\AppFramework\QueryException;
 use OCP\Dashboard\IManager;
+use OCP\Diagnostics\IEventLogger;
 use OCP\EventDispatcher\IEventDispatcher;
 use OCP\IServerContainer;
 use PHPUnit\Framework\MockObject\MockObject;
@@ -57,6 +58,9 @@ class CoordinatorTest extends TestCase {
 	/** @var IEventDispatcher|MockObject */
 	private $eventDispatcher;
 
+	/** @var IEventLogger|MockObject */
+	private $eventLogger;
+
 	/** @var LoggerInterface|MockObject */
 	private $logger;
 
@@ -71,6 +75,7 @@ class CoordinatorTest extends TestCase {
 		$this->crashReporterRegistry = $this->createMock(Registry::class);
 		$this->dashboardManager = $this->createMock(IManager::class);
 		$this->eventDispatcher = $this->createMock(IEventDispatcher::class);
+		$this->eventLogger = $this->createMock(IEventLogger::class);
 		$this->logger = $this->createMock(LoggerInterface::class);
 
 		$this->coordinator = new Coordinator(
@@ -78,6 +83,7 @@ class CoordinatorTest extends TestCase {
 			$this->crashReporterRegistry,
 			$this->dashboardManager,
 			$this->eventDispatcher,
+			$this->eventLogger,
 			$this->logger
 		);
 	}