diff --git a/apps/dav/lib/Server.php b/apps/dav/lib/Server.php index 055c37f8472f5..adbe1796d2c2f 100644 --- a/apps/dav/lib/Server.php +++ b/apps/dav/lib/Server.php @@ -336,7 +336,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/config/config.sample.php b/config/config.sample.php index b099b08f78c43..c760c7ebaceed 100644 --- a/config/config.sample.php +++ b/config/config.sample.php @@ -2068,4 +2068,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, ]; diff --git a/lib/base.php b/lib/base.php index 78dba4f835e86..08f18fd37b744 100644 --- a/lib/base.php +++ b/lib/base.php @@ -61,6 +61,7 @@ * along with this program. If not, see * */ + use OCP\EventDispatcher\IEventDispatcher; use OCP\Group\Events\UserRemovedEvent; use OCP\ILogger; @@ -592,8 +593,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 @@ -789,6 +795,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 6e05b7fdc8802..b6378830732c5 100644 --- a/lib/private/AppFramework/Bootstrap/Coordinator.php +++ b/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) { diff --git a/lib/private/AppFramework/DependencyInjection/DIContainer.php b/lib/private/AppFramework/DependencyInjection/DIContainer.php index 293b9e47b2580..e06d5226a28f0 100644 --- a/lib/private/AppFramework/DependencyInjection/DIContainer.php +++ b/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) ); }); diff --git a/lib/private/AppFramework/Http/Dispatcher.php b/lib/private/AppFramework/Http/Dispatcher.php index 0f12dbda629ce..21d61bc95aaf1 100644 --- a/lib/private/AppFramework/Http/Dispatcher.php +++ b/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,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 @@ 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; @@ -94,6 +100,7 @@ public function __construct(Http $protocol, $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)) { diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php index 9efacb0f9ae34..237323a0ddf58 100644 --- a/lib/private/DB/Connection.php +++ b/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()); diff --git a/lib/private/Diagnostics/Event.php b/lib/private/Diagnostics/Event.php index 95b737155dc37..0c3aa6ae29ce4 100644 --- a/lib/private/Diagnostics/Event.php +++ b/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(); + } } diff --git a/lib/private/Diagnostics/EventLogger.php b/lib/private/Diagnostics/EventLogger.php index 4f3343ec625ae..02867b3b4b741 100644 --- a/lib/private/Diagnostics/EventLogger.php +++ b/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']); + } + } } diff --git a/lib/private/Log.php b/lib/private/Log.php index edbfdea7b9dec..6ccf467dc8aaf 100644 --- a/lib/private/Log.php +++ b/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', []); /** diff --git a/lib/private/RedisFactory.php b/lib/private/RedisFactory.php index 3062be28a780d..89af26132f352 100644 --- a/lib/private/RedisFactory.php +++ b/lib/private/RedisFactory.php @@ -26,6 +26,8 @@ */ namespace OC; +use OCP\Diagnostics\IEventLogger; + class RedisFactory { public const REDIS_MINIMAL_VERSION = '3.1.3'; public const REDIS_EXTRA_PARAMETERS_MINIMAL_VERSION = '5.3.0'; @@ -33,16 +35,18 @@ class RedisFactory { /** @var \Redis|\RedisCluster */ 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() { @@ -113,6 +117,7 @@ private function create() { $port = null; } + $this->eventLogger->start('connect:redis', 'Connect to redis and send AUTH, SELECT'); // Support for older phpredis versions not supporting connectionParameters if ($connectionParameters !== null) { // Non-clustered redis requires connection parameters to be wrapped inside `stream` @@ -133,6 +138,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 d1e038d971ee0..e86a37319426c 100644 --- a/lib/private/Server.php +++ b/lib/private/Server.php @@ -718,7 +718,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) { @@ -871,12 +871,7 @@ public function __construct($webRoot, \OC\Config $config) { }); $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 1ce3662000ea3..ca01e91216b75 100644 --- a/lib/private/legacy/OC_App.php +++ b/lib/private/legacy/OC_App.php @@ -173,6 +173,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, @@ -181,7 +182,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) { @@ -201,8 +201,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 d6ceefa42684d..5a151806adf78 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\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 @@ protected function setUp(): void { $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 @@ 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() {