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

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

cron.php

@@ -80,7 +80,7 @@ try {
 	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);

lib/base.php

@@ -449,7 +449,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);

lib/private/Server.php

@@ -532,7 +532,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.

lib/private/Session/Internal.php

@@ -35,7 +35,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
@@ -49,7 +53,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', ['']);
@@ -208,11 +213,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());
 		}

lib/private/Session/Memory.php

@@ -42,11 +42,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

lib/private/Session/Session.php

@@ -38,13 +38,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

tests/lib/Session/CryptoSessionDataTest.php

@@ -34,7 +34,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')

tests/lib/Session/MemoryTest.php

@@ -12,10 +12,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);
 

tests/lib/User/SessionTest.php

@@ -115,7 +115,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);
 
@@ -133,7 +133,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');
@@ -152,7 +152,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())
@@ -229,7 +229,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())
@@ -271,7 +271,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']);
@@ -314,7 +314,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']);
@@ -351,7 +351,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']);
@@ -388,7 +388,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);
 
@@ -608,7 +608,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']);
@@ -697,7 +697,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']);
@@ -761,7 +761,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']);
@@ -813,7 +813,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']);
@@ -873,7 +873,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])
@@ -886,7 +886,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());