From 64f35b125540dcfd9f8a89f47a008cd7c73d712c Mon Sep 17 00:00:00 2001
From: Christoph Wurst <christoph@winzerhof-wurst.at>
Date: Tue, 25 Jun 2024 15:16:40 +0200
Subject: [PATCH] fix(session): Log when session_* calls are slow

Signed-off-by: Christoph Wurst <christoph@winzerhof-wurst.at>
---
 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  |  8 +-------
 6 files changed, 35 insertions(+), 18 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 91ca87426e156..2ebc1b3c6bcd5 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 bcdf482f02d0e..60e6dd2507c17 100644
--- a/lib/private/Server.php
+++ b/lib/private/Server.php
@@ -487,7 +487,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 4384b0ab5c0c4..46b459109f663 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]);
 		try {
@@ -183,11 +188,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..fec71e65b3b28 100644
--- a/lib/private/Session/Session.php
+++ b/lib/private/Session/Session.php
@@ -9,6 +9,7 @@
 namespace OC\Session;
 
 use OCP\ISession;
+use Psr\Log\LoggerInterface;
 
 /**
  * @template-implements \ArrayAccess<string,mixed>
@@ -19,13 +20,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