diff --git a/apps/dav/lib/Server.php b/apps/dav/lib/Server.php index ba5bcf935e1b5..1488eb0a30d0f 100644 --- a/apps/dav/lib/Server.php +++ b/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 { diff --git a/lib/base.php b/lib/base.php index c42f427ca40b7..f4bb11b6ffb87 100644 --- a/lib/base.php +++ b/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)); } /** diff --git a/lib/private/AppFramework/Bootstrap/Coordinator.php b/lib/private/AppFramework/Bootstrap/Coordinator.php index 80ef24b520432..6190351ea0a41 100644 --- a/lib/private/AppFramework/Bootstrap/Coordinator.php +++ b/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) { diff --git a/lib/private/AppFramework/DependencyInjection/DIContainer.php b/lib/private/AppFramework/DependencyInjection/DIContainer.php index 3ef816f503e41..5403b4ab9f6be 100644 --- a/lib/private/AppFramework/DependencyInjection/DIContainer.php +++ b/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) ); }); diff --git a/lib/private/AppFramework/Http/Dispatcher.php b/lib/private/AppFramework/Http/Dispatcher.php index 9ec69558e889d..7cbe9b6df9e38 100644 --- a/lib/private/AppFramework/Http/Dispatcher.php +++ b/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,6 +84,7 @@ class Dispatcher { * @param IConfig $config * @param ConnectionAdapter $connection * @param LoggerInterface $logger + * @param IEventLogger $eventLogger */ public function __construct(Http $protocol, MiddlewareDispatcher $middlewareDispatcher, @@ -87,7 +92,8 @@ public function __construct(Http $protocol, IRequest $request, IConfig $config, ConnectionAdapter $connection, - LoggerInterface $logger) { + LoggerInterface $logger, + IEventLogger $eventLogger) { $this->protocol = $protocol; $this->middlewareDispatcher = $middlewareDispatcher; $this->reflector = $reflector; @@ -95,6 +101,7 @@ public function __construct(Http $protocol, $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)) { diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php index 92f89dab5d2d9..be57254d97840 100644 --- a/lib/private/DB/Connection.php +++ b/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()); diff --git a/lib/private/Diagnostics/Event.php b/lib/private/Diagnostics/Event.php index 97da22b12a3cc..897e9e7dba3fd 100644 --- a/lib/private/Diagnostics/Event.php +++ b/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(); + } } diff --git a/lib/private/Diagnostics/EventLogger.php b/lib/private/Diagnostics/EventLogger.php index 115a8ebba923a..a13fc02888d46 100644 --- a/lib/private/Diagnostics/EventLogger.php +++ b/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']); + } + } } diff --git a/lib/private/Log.php b/lib/private/Log.php index 3c3f22293d9cf..ee2489c139634 100644 --- a/lib/private/Log.php +++ b/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', []); /** diff --git a/lib/private/RedisFactory.php b/lib/private/RedisFactory.php index 52e69a1877839..71747ef1988da 100644 --- a/lib/private/RedisFactory.php +++ b/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'); } } diff --git a/lib/private/Server.php b/lib/private/Server.php index 0708d508c4227..d939e1954a571 100644 --- a/lib/private/Server.php +++ b/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); diff --git a/lib/private/legacy/OC_App.php b/lib/private/legacy/OC_App.php index d76a34b03a4f6..a9255ed8a99e3 100644 --- a/lib/private/legacy/OC_App.php +++ b/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); diff --git a/tests/lib/AppFramework/Bootstrap/CoordinatorTest.php b/tests/lib/AppFramework/Bootstrap/CoordinatorTest.php index 1fca34423d51d..aed4b9f782658 100644 --- a/tests/lib/AppFramework/Bootstrap/CoordinatorTest.php +++ b/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 ); } diff --git a/tests/lib/AppFramework/Http/DispatcherTest.php b/tests/lib/AppFramework/Http/DispatcherTest.php index 966e49effcb87..e47e1ae0bebad 100644 --- a/tests/lib/AppFramework/Http/DispatcherTest.php +++ b/tests/lib/AppFramework/Http/DispatcherTest.php @@ -32,6 +32,7 @@ use OCP\AppFramework\Http\DataResponse; use OCP\AppFramework\Http\JSONResponse; use OCP\AppFramework\Http\Response; +use OCP\Diagnostics\IEventLogger; use OCP\IConfig; use OCP\IRequest; use PHPUnit\Framework\MockObject\MockObject; @@ -99,6 +100,10 @@ class DispatcherTest extends \Test\TestCase { private $config; /** @var LoggerInterface|MockObject */ private $logger; + /** + * @var IEventLogger|MockObject + */ + private $eventLogger; protected function setUp(): void { parent::setUp(); @@ -106,6 +111,7 @@ protected function setUp(): void { $this->config = $this->createMock(IConfig::class); $this->logger = $this->createMock(LoggerInterface::class); + $this->eventLogger = $this->createMock(IEventLogger::class); $app = $this->getMockBuilder( 'OC\AppFramework\DependencyInjection\DIContainer') ->disableOriginalConstructor() @@ -143,7 +149,8 @@ protected function setUp(): void { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $this->response = $this->createMock(Response::class); @@ -321,7 +328,8 @@ public function testControllerParametersInjected() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); @@ -355,7 +363,8 @@ public function testControllerParametersInjectedDefaultOverwritten() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); @@ -392,7 +401,8 @@ public function testResponseTransformedByUrlFormat() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); @@ -428,7 +438,8 @@ public function testResponseTransformsDataResponse() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); @@ -465,7 +476,8 @@ public function testResponseTransformedByAcceptHeader() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); @@ -504,7 +516,8 @@ public function testResponsePrimarilyTransformedByParameterFormat() { $this->request, $this->config, \OC::$server->getDatabaseConnection(), - $this->logger + $this->logger, + $this->eventLogger ); $controller = new TestController('app', $this->request); diff --git a/tests/lib/Diagnostics/EventLoggerTest.php b/tests/lib/Diagnostics/EventLoggerTest.php index c26ca2ce20204..4e24c24f225c5 100644 --- a/tests/lib/Diagnostics/EventLoggerTest.php +++ b/tests/lib/Diagnostics/EventLoggerTest.php @@ -21,18 +21,25 @@ namespace Test\Diagnostics; +use Psr\Log\LoggerInterface; use OC\Diagnostics\EventLogger; +use OC\Log; +use OC\SystemConfig; use Test\TestCase; class EventLoggerTest extends TestCase { /** @var \OC\Diagnostics\EventLogger */ private $logger; - + protected function setUp(): void { parent::setUp(); - $this->logger = new EventLogger(); + $this->logger = new EventLogger( + $this->createMock(SystemConfig::class), + $this->createMock(LoggerInterface::class), + $this->createMock(Log::class) + ); } public function testQueryLogger() {