Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[stable22] Diagnostics event logging to log #31405

Closed
wants to merge 5 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions apps/dav/lib/Server.php
Original file line number Diff line number Diff line change
Expand Up @@ -330,7 +330,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 {
Expand Down
7 changes: 7 additions & 0 deletions lib/base.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -789,6 +795,7 @@ public static function init() {
}
}
$eventLogger->end('boot');
$eventLogger->log('init', 'OC::init', $loaderStart, microtime(true));
}

/**
Expand Down
8 changes: 8 additions & 0 deletions lib/private/AppFramework/Bootstrap/Coordinator.php
Original file line number Diff line number Diff line change
Expand Up @@ -57,6 +57,9 @@ class Coordinator {
/** @var IEventDispatcher */
private $eventDispatcher;

/** @var IEventLogger */
private $eventLogger;

/** @var LoggerInterface */
private $logger;

Expand All @@ -75,6 +78,7 @@ public function __construct(IServerContainer $container,
$this->registry = $registry;
$this->dashboardManager = $dashboardManager;
$this->eventDispatcher = $eventListener;
$this->eventLogger = $eventLogger;
$this->logger = $logger;
}

Expand Down Expand Up @@ -123,7 +127,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(), [
Expand Down Expand Up @@ -169,6 +175,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);
Expand All @@ -186,6 +193,7 @@ public function bootApp(string $appId): void {
'exception' => $e,
]);
}
$this->eventLogger->end('bootstrap:boot_app_' . $appId);
}

public function isBootable(string $appId) {
Expand Down
4 changes: 3 additions & 1 deletion lib/private/AppFramework/DependencyInjection/DIContainer.php
Original file line number Diff line number Diff line change
Expand Up @@ -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 OCA\WorkflowEngine\Manager;
Expand Down Expand Up @@ -183,7 +184,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)
);
});

Expand Down
11 changes: 10 additions & 1 deletion lib/private/AppFramework/Http/Dispatcher.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
Expand All @@ -79,21 +83,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;
}


Expand Down Expand Up @@ -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)) {
Expand Down
12 changes: 11 additions & 1 deletion lib/private/DB/Connection.php
Original file line number Diff line number Diff line change
Expand Up @@ -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());
Expand Down
4 changes: 4 additions & 0 deletions lib/private/Diagnostics/Event.php
Original file line number Diff line number Diff line change
Expand Up @@ -100,4 +100,8 @@ public function getDuration() {
}
return $this->end - $this->start;
}

public function __toString() {
return $this->getId() . ' ' . $this->getDescription() . ' ' . $this->getDuration();
}
}
65 changes: 59 additions & 6 deletions lib/private/Diagnostics/EventLogger.php
Original file line number Diff line number Diff line change
Expand Up @@ -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]);
}
}

Expand All @@ -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);
}
}

Expand All @@ -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]);
}
}

Expand All @@ -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']);
}
}
}
2 changes: 1 addition & 1 deletion lib/private/Log.php
Original file line number Diff line number Diff line change
Expand Up @@ -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', []);

/**
Expand Down
12 changes: 9 additions & 3 deletions lib/private/RedisFactory.php
Original file line number Diff line number Diff line change
Expand Up @@ -26,23 +26,27 @@
*/
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';

/** @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() {
Expand Down Expand Up @@ -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`
Expand All @@ -133,6 +138,7 @@ private function create() {
if (isset($config['dbindex'])) {
$this->instance->select($config['dbindex']);
}
$this->eventLogger->end('connect:redis');
}
}

Expand Down
9 changes: 2 additions & 7 deletions lib/private/Server.php
Original file line number Diff line number Diff line change
Expand Up @@ -713,7 +713,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) {
Expand Down Expand Up @@ -866,12 +866,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);
Expand Down
Loading