From 4776494dd021f11b27a1bd915299436301cc856c Mon Sep 17 00:00:00 2001
From: Martijn Harte <mharte@ibuildings.nl>
Date: Thu, 12 Sep 2024 14:01:14 +0200
Subject: [PATCH] Listen to all routes and log the state of the session

Prior to this change session information got lost. We had no way of tracking down what happened to user sessions in the logs.

This change logs whether a session existed and if it's in a valid state. Log information is enriched with a correlation id to be able to distinguish them.
---
 src/EventSubscriber/SessionStateListener.php  |  77 ++++++++
 .../SessionStateListenerTest.php              | 166 ++++++++++++++++++
 2 files changed, 243 insertions(+)
 create mode 100644 src/EventSubscriber/SessionStateListener.php
 create mode 100644 tests/Unit/EventSubscriber/SessionStateListenerTest.php

diff --git a/src/EventSubscriber/SessionStateListener.php b/src/EventSubscriber/SessionStateListener.php
new file mode 100644
index 00000000..61b3aae5
--- /dev/null
+++ b/src/EventSubscriber/SessionStateListener.php
@@ -0,0 +1,77 @@
+<?php
+
+/**
+ * Copyright 2024 SURFnet B.V.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+declare(strict_types = 1);
+
+namespace Surfnet\Tiqr\EventSubscriber;
+
+use Psr\Log\LoggerInterface;
+use Surfnet\Tiqr\Service\SessionCorrelationIdService;
+use Surfnet\Tiqr\WithContextLogger;
+use Symfony\Component\EventDispatcher\EventSubscriberInterface;
+use Symfony\Component\HttpFoundation\Exception\SessionNotFoundException;
+use Symfony\Component\HttpKernel\Event\RequestEvent;
+use Symfony\Component\HttpKernel\KernelEvents;
+
+/**
+ * Listen to all incoming requests and log the session state information.
+ */
+final readonly class SessionStateListener implements EventSubscriberInterface
+{
+    public function __construct(
+        private LoggerInterface             $logger,
+        private SessionCorrelationIdService $sessionCorrelationIdService
+    ) {
+    }
+
+    public function onKernelRequest(RequestEvent $event): void
+    {
+        $logger = WithContextLogger::from($this->logger, [
+            'correlationId' => $this->sessionCorrelationIdService->generateCorrelationId() ?? '',
+            'route' => $event->getRequest()->getRequestUri(),
+        ]);
+
+        $sessionCookieId = $event->getRequest()->cookies->get('PHPSESSID');
+        if ($sessionCookieId === null) {
+            $logger->info('User made a request without a session cookie.');
+            return;
+        }
+
+        $logger->info('User made a request with a session cookie.');
+
+        try {
+            $sessionId = $event->getRequest()->getSession()->getId();
+            $logger->info('User has a session.');
+
+            if ($sessionId !== $sessionCookieId) {
+                $logger->error('The session cookie does not match the session id.');
+                return;
+            }
+        } catch (SessionNotFoundException) {
+            $logger->info('Session not found.');
+            return;
+        }
+
+        $logger->info('User session matches the session cookie.');
+    }
+
+    public static function getSubscribedEvents(): array
+    {
+        return [KernelEvents::REQUEST => ['onKernelRequest', 20]];
+    }
+}
diff --git a/tests/Unit/EventSubscriber/SessionStateListenerTest.php b/tests/Unit/EventSubscriber/SessionStateListenerTest.php
new file mode 100644
index 00000000..580bddbc
--- /dev/null
+++ b/tests/Unit/EventSubscriber/SessionStateListenerTest.php
@@ -0,0 +1,166 @@
+<?php
+/**
+ * Copyright 2024 SURFnet B.V.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+namespace Unit\EventSubscriber;
+
+use Mockery;
+use Psr\Log\LoggerInterface;
+use Psr\Log\LogLevel;
+use Surfnet\Tiqr\EventSubscriber\SessionStateListener;
+use Surfnet\Tiqr\Service\SessionCorrelationIdService;
+use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase;
+use Symfony\Component\EventDispatcher\EventDispatcher;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
+use Symfony\Component\HttpFoundation\Session\Session;
+use Symfony\Component\HttpFoundation\Session\Storage\MockArraySessionStorage;
+use Symfony\Component\HttpKernel\Event\RequestEvent;
+use Symfony\Component\HttpKernel\HttpKernelInterface;
+use Symfony\Component\HttpKernel\KernelEvents;
+
+final class SessionStateListenerTest extends KernelTestCase
+{
+    private const SESSION_ID = 'session-id';
+
+    public function testItLogsWhenUserHasNoSessionCookie(): void
+    {
+        $this->expectNotToPerformAssertions();
+
+        self::bootKernel();
+
+        $request = new Request(server: ['REQUEST_URI' => '/route']);
+
+        $requestStack = new RequestStack();
+        $requestStack->push($request);
+
+        $event = new RequestEvent(self::$kernel, $request, HttpKernelInterface::MAIN_REQUEST);
+
+        $dispatcher = new EventDispatcher();
+
+        $mockLogger = Mockery::mock(LoggerInterface::class);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User made a request without a session cookie.', ['correlationId' => '', 'route' => '/route']);
+
+        $listener = new SessionStateListener($mockLogger, new SessionCorrelationIdService($requestStack));
+
+        $dispatcher->addListener(KernelEvents::REQUEST, [$listener, 'onKernelRequest']);
+        $dispatcher->dispatch($event, KernelEvents::REQUEST);
+    }
+
+    public function testItLogsWhenUserHasNoSession(): void
+    {
+        $this->expectNotToPerformAssertions();
+
+        self::bootKernel();
+
+        $request = new Request(server: ['REQUEST_URI' => '/route'], cookies: ['PHPSESSID' => self::SESSION_ID]);
+
+        $requestStack = new RequestStack();
+        $requestStack->push($request);
+
+        $event = new RequestEvent(self::$kernel, $request, HttpKernelInterface::MAIN_REQUEST);
+
+        $dispatcher = new EventDispatcher();
+
+        $mockLogger = Mockery::mock(LoggerInterface::class);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User made a request with a session cookie.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'Session not found.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+
+        $listener = new SessionStateListener($mockLogger, new SessionCorrelationIdService($requestStack));
+
+        $dispatcher->addListener(KernelEvents::REQUEST, [$listener, 'onKernelRequest']);
+        $dispatcher->dispatch($event, KernelEvents::REQUEST);
+    }
+
+    public function testItLogsAnErrorWhenTheSessionIdDoesNotMatchTheSessionCookie(): void
+    {
+        $this->expectNotToPerformAssertions();
+
+        self::bootKernel();
+
+        $session = new Session(new MockArraySessionStorage());
+        $session->setId('erroneous-session-id');
+
+        $request = new Request(server: ['REQUEST_URI' => '/route'], cookies: ['PHPSESSID' => self::SESSION_ID]);
+        $request->setSession($session);
+
+        $requestStack = new RequestStack();
+        $requestStack->push($request);
+
+        $event = new RequestEvent(self::$kernel, $request, HttpKernelInterface::MAIN_REQUEST);
+
+        $dispatcher = new EventDispatcher();
+
+        $mockLogger = Mockery::mock(LoggerInterface::class);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User made a request with a session cookie.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User has a session.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::ERROR, 'The session cookie does not match the session id.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+
+        $listener = new SessionStateListener($mockLogger, new SessionCorrelationIdService($requestStack));
+
+        $dispatcher->addListener(KernelEvents::REQUEST, [$listener, 'onKernelRequest']);
+        $dispatcher->dispatch($event, KernelEvents::REQUEST);
+    }
+
+    public function testTheUserSessionMatchesTheSessionCookie(): void
+    {
+        $this->expectNotToPerformAssertions();
+
+        self::bootKernel();
+
+        $session = new Session(new MockArraySessionStorage());
+        $session->setId(self::SESSION_ID);
+
+        $request = new Request(server: ['REQUEST_URI' => '/route'], cookies: ['PHPSESSID' => self::SESSION_ID]);
+        $request->setSession($session);
+
+        $requestStack = new RequestStack();
+        $requestStack->push($request);
+
+
+        $event = new RequestEvent(self::$kernel, $request, HttpKernelInterface::MAIN_REQUEST);
+
+        $dispatcher = new EventDispatcher();
+
+        $mockLogger = Mockery::mock(LoggerInterface::class);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User made a request with a session cookie.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User has a session.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+        $mockLogger->shouldReceive('log')
+            ->once()
+            ->with(LogLevel::INFO, 'User session matches the session cookie.', ['correlationId' => 'f6e7cfb6f0861f577c48f171e27542236b1184f7a599dde82aca1640d86da961', 'route' => '/route']);
+
+        $listener = new SessionStateListener($mockLogger, new SessionCorrelationIdService($requestStack));
+
+        $dispatcher->addListener(KernelEvents::REQUEST, [$listener, 'onKernelRequest']);
+        $dispatcher->dispatch($event, KernelEvents::REQUEST);
+    }
+}