From 2b38d6ae7e0602d164bb26affa8a877b818e9cb5 Mon Sep 17 00:00:00 2001 From: Christoph Wurst Date: Tue, 25 Jun 2024 15:16:40 +0200 Subject: [PATCH] fix(session): Log when session_* calls are slow Signed-off-by: Christoph Wurst --- cron.php | 2 +- lib/base.php | 5 +++- lib/private/Server.php | 2 +- lib/private/Session/Internal.php | 31 +++++++++++++++++++-- lib/private/Session/Memory.php | 5 ---- lib/private/Session/Session.php | 7 ----- tests/lib/Session/CryptoSessionDataTest.php | 2 +- tests/lib/Session/MemoryTest.php | 4 +-- tests/lib/User/SessionTest.php | 28 +++++++++---------- 9 files changed, 51 insertions(+), 35 deletions(-) diff --git a/cron.php b/cron.php index 0b64bfb957b79..a1cc5250b2052 100644 --- a/cron.php +++ b/cron.php @@ -61,7 +61,7 @@ Server::get(ISession::class)->close(); // initialize a dummy memory session - $session = new \OC\Session\Memory(''); + $session = new \OC\Session\Memory(); $cryptoWrapper = \OC::$server->getSessionCryptoWrapper(); $session = $cryptoWrapper->wrapSession($session); \OC::$server->setSession($session); diff --git a/lib/base.php b/lib/base.php index c84a124628889..bf324e946bc50 100644 --- a/lib/base.php +++ b/lib/base.php @@ -388,7 +388,10 @@ public static function initSession(): void { try { // set the session name to the instance id - which is unique - $session = new \OC\Session\Internal($sessionName); + $session = new \OC\Session\Internal( + $sessionName, + logger('core'), + ); $cryptoWrapper = Server::get(\OC\Session\CryptoWrapper::class); $session = $cryptoWrapper->wrapSession($session); diff --git a/lib/private/Server.php b/lib/private/Server.php index e88f44fc066e8..a0072b43ee20a 100644 --- a/lib/private/Server.php +++ b/lib/private/Server.php @@ -489,7 +489,7 @@ public function __construct($webRoot, \OC\Config $config) { $this->registerService(\OC\User\Session::class, function (Server $c) { $manager = $c->get(IUserManager::class); - $session = new \OC\Session\Memory(''); + $session = new \OC\Session\Memory(); $timeFactory = new TimeFactory(); // Token providers might require a working database. This code // might however be called when Nextcloud is not yet setup. diff --git a/lib/private/Session/Internal.php b/lib/private/Session/Internal.php index b64618245b867..5398dc710af9c 100644 --- a/lib/private/Session/Internal.php +++ b/lib/private/Session/Internal.php @@ -11,7 +11,11 @@ use OC\Authentication\Token\IProvider; use OCP\Authentication\Exceptions\InvalidTokenException; +use OCP\ILogger; use OCP\Session\Exceptions\SessionNotAvailableException; +use Psr\Log\LoggerInterface; +use function call_user_func_array; +use function microtime; /** * Class Internal @@ -25,7 +29,8 @@ class Internal extends Session { * @param string $name * @throws \Exception */ - public function __construct(string $name) { + public function __construct(string $name, + private LoggerInterface $logger) { set_error_handler([$this, 'trapError']); $this->invoke('session_name', [$name]); $this->invoke('session_cache_limiter', ['']); @@ -184,11 +189,31 @@ public function trapError(int $errorNumber, string $errorString) { */ private function invoke(string $functionName, array $parameters = [], bool $silence = false) { try { + $timeBefore = microtime(true); if ($silence) { - return @call_user_func_array($functionName, $parameters); + $result = @call_user_func_array($functionName, $parameters); } else { - return call_user_func_array($functionName, $parameters); + $result = call_user_func_array($functionName, $parameters); } + $timeAfter = microtime(true); + $timeSpent = $timeAfter - $timeBefore; + if ($timeSpent > 0.1) { + $logLevel = match (true) { + $timeSpent > 25 => ILogger::ERROR, + $timeSpent > 10 => ILogger::WARN, + $timeSpent > 0.5 => ILogger::INFO, + default => ILogger::DEBUG, + }; + $this->logger->log( + $logLevel, + "Slow session operation $functionName detected", + [ + 'parameters' => $parameters, + 'timeSpent' => $timeSpent, + ], + ); + } + return $result; } catch (\Error $e) { $this->trapError($e->getCode(), $e->getMessage()); } diff --git a/lib/private/Session/Memory.php b/lib/private/Session/Memory.php index eb10ebe05b4c8..395711836f5ca 100644 --- a/lib/private/Session/Memory.php +++ b/lib/private/Session/Memory.php @@ -20,11 +20,6 @@ class Memory extends Session { protected $data; - public function __construct(string $name) { - //no need to use $name since all data is already scoped to this instance - $this->data = []; - } - /** * @param string $key * @param integer $value diff --git a/lib/private/Session/Session.php b/lib/private/Session/Session.php index 3006eceecba90..b7510b63683d7 100644 --- a/lib/private/Session/Session.php +++ b/lib/private/Session/Session.php @@ -19,13 +19,6 @@ abstract class Session implements \ArrayAccess, ISession { */ protected $sessionClosed = false; - /** - * $name serves as a namespace for the session keys - * - * @param string $name - */ - abstract public function __construct(string $name); - /** * @param mixed $offset * @return bool diff --git a/tests/lib/Session/CryptoSessionDataTest.php b/tests/lib/Session/CryptoSessionDataTest.php index 83768ef49aa6c..6c1536f47698c 100644 --- a/tests/lib/Session/CryptoSessionDataTest.php +++ b/tests/lib/Session/CryptoSessionDataTest.php @@ -20,7 +20,7 @@ class CryptoSessionDataTest extends Session { protected function setUp(): void { parent::setUp(); - $this->wrappedSession = new \OC\Session\Memory($this->getUniqueID()); + $this->wrappedSession = new \OC\Session\Memory(); $this->crypto = $this->createMock(ICrypto::class); $this->crypto->expects($this->any()) ->method('encrypt') diff --git a/tests/lib/Session/MemoryTest.php b/tests/lib/Session/MemoryTest.php index ae4a1b64dc0da..f5d9685039d87 100644 --- a/tests/lib/Session/MemoryTest.php +++ b/tests/lib/Session/MemoryTest.php @@ -11,10 +11,10 @@ class MemoryTest extends Session { protected function setUp(): void { parent::setUp(); - $this->instance = new \OC\Session\Memory($this->getUniqueID()); + $this->instance = new \OC\Session\Memory(); } - + public function testThrowsExceptionOnGetId() { $this->expectException(\OCP\Session\Exceptions\SessionNotAvailableException::class); diff --git a/tests/lib/User/SessionTest.php b/tests/lib/User/SessionTest.php index 236da2a1dcc1b..84af7f552a767 100644 --- a/tests/lib/User/SessionTest.php +++ b/tests/lib/User/SessionTest.php @@ -114,7 +114,7 @@ public function isLoggedInData() { * @dataProvider isLoggedInData */ public function testIsLoggedIn($isLoggedIn) { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $manager = $this->createMock(Manager::class); @@ -132,7 +132,7 @@ public function testIsLoggedIn($isLoggedIn) { } public function testSetUser() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $session->expects($this->once()) ->method('set') ->with('user_id', 'foo'); @@ -151,7 +151,7 @@ public function testSetUser() { } public function testLoginValidPasswordEnabled() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $session->expects($this->once()) ->method('regenerateId'); $this->tokenProvider->expects($this->once()) @@ -228,7 +228,7 @@ public function testLoginValidPasswordEnabled() { public function testLoginValidPasswordDisabled() { $this->expectException(LoginException::class); - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $session->expects($this->never()) ->method('set'); $session->expects($this->once()) @@ -270,7 +270,7 @@ public function testLoginValidPasswordDisabled() { } public function testLoginInvalidPassword() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); //keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -313,7 +313,7 @@ public function testLoginInvalidPassword() { } public function testPasswordlessLoginNoLastCheckUpdate(): void { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); // Keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -350,7 +350,7 @@ public function testPasswordlessLoginNoLastCheckUpdate(): void { } public function testLoginLastCheckUpdate(): void { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); // Keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -387,7 +387,7 @@ public function testLoginLastCheckUpdate(): void { } public function testLoginNonExisting() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $manager = $this->createMock(Manager::class); $userSession = new Session($manager, $session, $this->timeFactory, $this->tokenProvider, $this->config, $this->random, $this->lockdownManager, $this->logger, $this->dispatcher); @@ -607,7 +607,7 @@ public function testTryTokenLoginSessionIdTokenNotFound(): void { } public function testRememberLoginValidToken() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); //keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -696,7 +696,7 @@ public function testRememberLoginValidToken() { } public function testRememberLoginInvalidSessionToken() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); //keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -760,7 +760,7 @@ public function testRememberLoginInvalidSessionToken() { } public function testRememberLoginInvalidToken() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); //keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -812,7 +812,7 @@ public function testRememberLoginInvalidToken() { } public function testRememberLoginInvalidUser() { - $session = $this->getMockBuilder(Memory::class)->setConstructorArgs([''])->getMock(); + $session = $this->createMock(Memory::class); $managerMethods = get_class_methods(Manager::class); //keep following methods intact in order to ensure hooks are working $mockedManagerMethods = array_diff($managerMethods, ['__construct', 'emit', 'listen']); @@ -872,7 +872,7 @@ public function testActiveUserAfterSetSession() { return $users[$uid]; }); - $session = new Memory(''); + $session = new Memory(); $session->set('user_id', 'foo'); $userSession = $this->getMockBuilder(Session::class) ->setConstructorArgs([$manager, $session, $this->timeFactory, $this->tokenProvider, $this->config, $this->random, $this->lockdownManager, $this->logger, $this->dispatcher]) @@ -885,7 +885,7 @@ public function testActiveUserAfterSetSession() { $this->assertEquals($users['foo'], $userSession->getUser()); - $session2 = new Memory(''); + $session2 = new Memory(); $session2->set('user_id', 'bar'); $userSession->setSession($session2); $this->assertEquals($users['bar'], $userSession->getUser());