fix(session): Log when session_* calls are slow

Signed-off-by: Christoph Wurst <christoph@winzerhof-wurst.at>

diff --git a/cron.php b/cron.php
index 0b64bfb957b79110a570042726a74a731e1a73e3..a1cc5250b20528756de9ba51b5d8fc86631745de 100644 (file)
--- a/cron.php
+++ b/cron.php
@@ -61,7 +61,7 @@ Options:
        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 c84a124628889909be12d7e97d845e953e294c0a..bf324e946bc509b705ba35457b18c8b85e2ed647 100644 (file)
--- a/lib/base.php
+++ b/lib/base.php
@@ -388,7 +388,10 @@ class OC {
 
                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 e88f44fc066e80078c95b7aa2d2a18f6b52dd2c9..a0072b43ee20ae10abaac6de225a0065ed7bac5e 100644 (file)
--- a/lib/private/Server.php
+++ b/lib/private/Server.php
@@ -489,7 +489,7 @@ class Server extends ServerContainer implements IServerContainer {
 
                $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 b64618245b86707bcb8eaaea7c74e43238a391db..5398dc710af9c39d8fde2060489c0dbec05066ef 100644 (file)
--- a/lib/private/Session/Internal.php
+++ b/lib/private/Session/Internal.php
@@ -11,7 +11,11 @@ namespace OC\Session;
 
 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 @@ class Internal extends Session {
         */
        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 eb10ebe05b4c87a71ccee8f62f30b8556627c4db..395711836f5ca35924449c78fb9b9bbc85ed371a 100644 (file)
--- a/lib/private/Session/Memory.php
+++ b/lib/private/Session/Memory.php
@@ -20,11 +20,6 @@ use OCP\Session\Exceptions\SessionNotAvailableException;
 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 3006eceecba9064ab988bf349426cbdcaf5d84f2..b7510b63683d708f4408e63de921e14418b63791 100644 (file)
--- 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 83768ef49aa6cb602108779617a57879721777da..6c1536f47698c2e808fdf18f4465d0157ec1fda3 100644 (file)
--- 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 ae4a1b64dc0dafdf2958a8abb2cab44e0be51867..f5d9685039d8719ec1a01cdd7128a4369ff1e88a 100644 (file)
--- a/tests/lib/Session/MemoryTest.php
+++ b/tests/lib/Session/MemoryTest.php
@@ -11,10 +11,10 @@ namespace Test\Session;
 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 236da2a1dcc1be6b5cb6d61b249b8676e7de03dd..84af7f552a76752daeee42b3a11ab131124acfec 100644 (file)
--- a/tests/lib/User/SessionTest.php
+++ b/tests/lib/User/SessionTest.php
@@ -114,7 +114,7 @@ class SessionTest extends \Test\TestCase {
         * @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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
        }
 
        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 @@ class SessionTest extends \Test\TestCase {
                                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 @@ class SessionTest extends \Test\TestCase {
 
                $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());