From 0f33453610c46ef730192820017f8c1270b3096f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Julius=20H=C3=A4rtl?= Date: Wed, 2 Feb 2022 09:57:50 +0100 Subject: Diagnostics event logging to Nextcloud log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Julius Härtl Add config samples Signed-off-by: Julius Härtl --- config/config.sample.php | 14 +++++ .../DependencyInjection/DIContainer.php | 4 +- lib/private/AppFramework/Http/Dispatcher.php | 11 +++- lib/private/Diagnostics/Event.php | 4 ++ lib/private/Diagnostics/EventLogger.php | 63 ++++++++++++++++++++-- lib/private/Log.php | 2 +- lib/private/Server.php | 7 +-- 7 files changed, 91 insertions(+), 14 deletions(-) diff --git a/config/config.sample.php b/config/config.sample.php index c433fb51d23..32a946ceb51 100644 --- a/config/config.sample.php +++ b/config/config.sample.php @@ -2079,4 +2079,18 @@ $CONFIG = [ * 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/private/AppFramework/DependencyInjection/DIContainer.php b/lib/private/AppFramework/DependencyInjection/DIContainer.php index 293b9e47b25..e06d5226a28 100644 --- a/lib/private/AppFramework/DependencyInjection/DIContainer.php +++ b/lib/private/AppFramework/DependencyInjection/DIContainer.php @@ -46,6 +46,7 @@ use OC\AppFramework\Middleware\SessionMiddleware; 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 @@ class DIContainer extends SimpleContainer implements IAppContainer { $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 0f12dbda629..21d61bc95aa 100644 --- a/lib/private/AppFramework/Http/Dispatcher.php +++ b/lib/private/AppFramework/Http/Dispatcher.php @@ -39,6 +39,7 @@ use OC\DB\ConnectionAdapter; 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 @@ class Dispatcher { 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 @@ class Dispatcher { $this->config = $config; $this->connection = $connection; $this->logger = $logger; + $this->eventLogger = $eventLogger; } @@ -214,7 +221,9 @@ class Dispatcher { $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/Diagnostics/Event.php b/lib/private/Diagnostics/Event.php index 95b737155dc..0c3aa6ae29c 100644 --- a/lib/private/Diagnostics/Event.php +++ b/lib/private/Diagnostics/Event.php @@ -100,4 +100,8 @@ class Event implements IEvent { } 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 4f3343ec625..edaa4bc0d50 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) { if ($this->activated) { $this->events[$id] = new Event($id, $description, microtime(true)); + $this->writeLog($this->events[$id]); } } @@ -53,6 +86,7 @@ class EventLogger implements IEventLogger { if ($this->activated && isset($this->events[$id])) { $timing = $this->events[$id]; $timing->end(microtime(true)); + $this->writeLog($timing); } } @@ -63,6 +97,7 @@ class EventLogger implements IEventLogger { 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 @@ class EventLogger implements IEventLogger { 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 edbfdea7b9d..6ccf467dc8a 100644 --- a/lib/private/Log.php +++ b/lib/private/Log.php @@ -232,7 +232,7 @@ class Log implements ILogger, IDataLogger { } } - private function getLogLevel($context) { + public function getLogLevel($context) { $logCondition = $this->config->getValue('log.condition', []); /** diff --git a/lib/private/Server.php b/lib/private/Server.php index 13bbf972abb..6619302a020 100644 --- a/lib/private/Server.php +++ b/lib/private/Server.php @@ -871,12 +871,7 @@ class Server extends ServerContainer implements IServerContainer { }); $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); -- cgit v1.2.3