Don't keep the session open when joining/leaving a room to reduce the…

[nickvergessen]

… chance of dirty reads

Improves the rate of "Session not found 404 redirect" ( #4670 ) from ~50% to ~10% for me.

The problem is the joining and leaving of the room, not actually the signaling code that is later on failing to find the session:

Current case:

join before["8bitgnry"]1667396997.431
join after["8bitgnry","deorokdx"]1667396997.4842

leave before["8bitgnry"]1667396997.4895
leave after[]1667396997.5102

signaling[]1667396997.7326

I also observed working room-changes which did the opposite order:

leave before["8bitgnry"]1667397317.6301
leave after[]1667397317.6513

join before["8bitgnry"]1667397317.6525
join after["8bitgnry","deorokdx"]1667397317.7005 

So it could happen that the session string for the old room was "restored"

[nickvergessen]

Patch to help testing and logging:

Patch

diff --git a/lib/Controller/RoomController.php b/lib/Controller/RoomController.php
index 7f58e475a..93edda8e7 100644
--- a/lib/Controller/RoomController.php
+++ b/lib/Controller/RoomController.php
@@ -1350,6 +1350,7 @@ class RoomController extends AEnvironmentAwareController {
         * @return DataResponse
         */
        public function joinRoom(string $token, string $password = '', bool $force = true): DataResponse {
+               $this->logger->error('join before' . json_encode(array_keys(json_decode(\OC::$server->getSession()->get('spreed-session'), true))) . microtime(true));
                $sessionId = $this->session->getSessionForRoom($token);
                try {
                        $room = $this->manager->getRoomForUserByToken($token, $this->userId, $sessionId);
@@ -1418,6 +1419,7 @@ class RoomController extends AEnvironmentAwareController {
                        $this->sessionService->updateLastPing($session, $this->timeFactory->getTime());
                }
 
+               $this->logger->error('join after' . json_encode(array_keys(json_decode(\OC::$server->getSession()->get('spreed-session'), true))) . microtime(true));
                return new DataResponse($this->formatRoom($room, $participant));
        }
 
@@ -1487,6 +1489,7 @@ class RoomController extends AEnvironmentAwareController {
         * @return DataResponse
         */
        public function leaveRoom(string $token): DataResponse {
+               $this->logger->error('leave before' . json_encode(array_keys(json_decode(\OC::$server->getSession()->get('spreed-session'), true))) . microtime(true));
                $sessionId = $this->session->getSessionForRoom($token);
                $this->session->removeSessionForRoom($token);
 
@@ -1498,6 +1501,7 @@ class RoomController extends AEnvironmentAwareController {
                } catch (ParticipantNotFoundException $e) {
                }
 
+               $this->logger->error('leave after' . json_encode(array_keys(json_decode(\OC::$server->getSession()->get('spreed-session'), true))) . microtime(true));
                return new DataResponse();
        }
 
diff --git a/lib/Controller/SignalingController.php b/lib/Controller/SignalingController.php
index 54cdedca4..faabd298e 100644
--- a/lib/Controller/SignalingController.php
+++ b/lib/Controller/SignalingController.php
@@ -304,6 +304,7 @@ class SignalingController extends OCSController {
         */
        public function pullMessages(string $token): DataResponse {
                if ($this->talkConfig->getSignalingMode() !== Config::SIGNALING_INTERNAL) {
+                       $this->logger->error('1');
                        return new DataResponse('Internal signaling disabled.', Http::STATUS_BAD_REQUEST);
                }
 
@@ -314,6 +315,8 @@ class SignalingController extends OCSController {
                        $sessionId = $this->session->getSessionForRoom($token);
                        if ($sessionId === null) {
                                // User is not active in this room
+                               $this->logger->error('2');
+                               $this->logger->error('signaling' . json_encode(array_keys(json_decode(\OC::$server->getSession()->get('spreed-session'), true))) . microtime(true));
                                return new DataResponse([['type' => 'usersInRoom', 'data' => []]], Http::STATUS_NOT_FOUND);
                        }
 
@@ -325,6 +328,7 @@ class SignalingController extends OCSController {
                                $this->sessionService->updateLastPing($participant->getSession(), $pingTimestamp);
                        }
                } catch (RoomNotFoundException $e) {
+                       $this->logger->error('3');
                        return new DataResponse([['type' => 'usersInRoom', 'data' => []]], Http::STATUS_NOT_FOUND);
                }
 
@@ -356,6 +360,7 @@ class SignalingController extends OCSController {
                        $sessionId = $this->session->getSessionForRoom($token);
                        if ($sessionId === null) {
                                // User is not active in this room
+                               $this->logger->error('4');
                                return new DataResponse([['type' => 'usersInRoom', 'data' => []]], Http::STATUS_NOT_FOUND);
                        }
                }
@@ -380,9 +385,11 @@ class SignalingController extends OCSController {
                                return new DataResponse($data, Http::STATUS_CONFLICT);
                        } catch (ParticipantNotFoundException $e) {
                                // User removed from conversation, bye!
+                               $this->logger->error('5');
                                return new DataResponse($data, Http::STATUS_NOT_FOUND);
                        } catch (RoomNotFoundException $e) {
                                // Complete conversation was killed, bye!
+                               $this->logger->error('6');
                                return new DataResponse($data, Http::STATUS_NOT_FOUND);
                        }
                }

[juliusknorr]

Could you check how this behaves if you reopen the session before reading it again?

[nickvergessen]

this function is "protected" and the usages in this file that "write" it afterwards do it already

[nickvergessen]

But still produces arrays like:

│[error] 2022-11-02T17:56:20.000 spreed           join before["deorokdx"]1667404580.026                                                                                                  │
│[error] 2022-11-02T17:56:20.000 spreed           leave before["deorokdx"]1667404580.0406                                                                                                │
│[error] 2022-11-02T17:56:20.000 spreed           leave after[]1667404580.0694                                                                                                           │
│[error] 2022-11-02T17:56:20.000 spreed           join after["deorokdx","8bitgnry"]1667404580.084    

[nickvergessen]

Let's not merge this but also wait for a review from @danxuliu

[juliusknorr]

Backporting would make sense, right? At least for 25

[nickvergessen]

/backport to stable25