test(logging): guard identity enrichment + auth logging, cover request-id subscriber

turegjorup · claude · turegjorup · commit 1243de6c2be6 · 2026-06-03T22:15:07.000+02:00
Apply the "logging must never break the request it annotates" principle
consistently:

- RequestContextProcessor: widen the try/catch from getActiveTenant() to the
  whole identity block, so screen_id (getScreen()-&gt;getId() on an unhydrated
  ScreenUser throws an uninitialized-typed-property Error) and user_id are
  guarded too. Fields set before a throw are kept.
- AuthLoggingSubscriber: run each handler's logging through a guard() so a
  failure (context building or write) drops the line instead of aborting
  authentication, making the class's "only logs, never alters auth" contract
  real.

Tests:
- New RequestIdSubscriberTest: adopt/mint/empty-header/no-overwrite/sub-request.
- AuthLoggingSubscriberTest: add onLoginSuccess and onJwtFailure (all four
  match arms: invalid/expired/not_found/unknown).

Co-Authored-By: Claude Opus 4.8 &lt;noreply@anthropic.com&gt;
diff --git a/src/Logger/EventSubscriber/AuthLoggingSubscriber.php b/src/Logger/EventSubscriber/AuthLoggingSubscriber.php
@@ -46,35 +46,35 @@ public static function getSubscribedEvents(): array
 
     public function onLoginSuccess(LoginSuccessEvent $event): void
     {
-        $this->logger->info('Authentication succeeded', [
+        $this->guard(fn () => $this->logger->info('Authentication succeeded', [
             'event' => 'auth.login_success',
             'user_identifier' => $event->getUser()->getUserIdentifier(),
             'firewall' => $event->getFirewallName(),
             'authenticator' => $event->getAuthenticator()::class,
-        ]);
+        ]));
     }
 
     public function onLoginFailure(LoginFailureEvent $event): void
     {
-        $this->logger->warning('Authentication failed', [
+        $this->guard(fn () => $this->logger->warning('Authentication failed', [
             'event' => 'auth.login_failure',
             'firewall' => $event->getFirewallName(),
             'authenticator' => $event->getAuthenticator()::class,
             'exception' => $event->getException(),
-        ]);
+        ]));
     }
 
     public function onLogout(LogoutEvent $event): void
     {
-        $this->logger->info('User logged out', [
+        $this->guard(fn () => $this->logger->info('User logged out', [
             'event' => 'auth.logout',
             'user_identifier' => $event->getToken()?->getUserIdentifier(),
-        ]);
+        ]));
     }
 
     public function onJwtFailure(JWTFailureEventInterface $event): void
     {
-        $this->logger->warning('JWT authentication failed', [
+        $this->guard(fn () => $this->logger->warning('JWT authentication failed', [
             'event' => 'auth.jwt_failure',
             'reason' => match (true) {
                 $event instanceof JWTInvalidEvent => 'invalid',
@@ -83,6 +83,23 @@ public function onJwtFailure(JWTFailureEventInterface $event): void
                 default => 'unknown',
             },
             'exception' => $event->getException(),
-        ]);
+        ]));
+    }
+
+    /**
+     * Runs a logging closure, swallowing any failure.
+     *
+     * This subscriber observes authentication events; logging must never break
+     * them. Both the context building (identity accessors that can throw) and the
+     * write itself run inside the guard, so a logging failure drops the line
+     * rather than aborting login/logout.
+     */
+    private function guard(callable $log): void
+    {
+        try {
+            $log();
+        } catch (\Throwable) {
+            // Intentionally silent — see method doc.
+        }
     }
 }
diff --git a/src/Logger/Processor/RequestContextProcessor.php b/src/Logger/Processor/RequestContextProcessor.php
@@ -48,22 +48,27 @@ public function __invoke(LogRecord $record): LogRecord
 
         $user = $this->security->getUser();
         if (null !== $user) {
-            // Screen tokens authenticate as ScreenUser; everything else is a
-            // back-office User. Populate screen_id XOR user_id accordingly.
-            if ($user instanceof ScreenUser) {
-                $record->extra['screen_id'] = (string) $user->getScreen()->getId();
-            } else {
-                $record->extra['user_id'] = $user->getUserIdentifier();
-            }
+            // Enrichment must never break the request it is annotating. Every
+            // identity accessor below can throw — getActiveTenant() when no tenant
+            // is resolved yet, getScreen() on a not-yet-hydrated screen token,
+            // getUserIdentifier() on a custom user — so the whole block is guarded.
+            // Fields written before a throw are kept (the record is mutated in
+            // place); the failing one and any after it are simply left unset.
+            try {
+                // Screen tokens authenticate as ScreenUser; everything else is a
+                // back-office User. Populate screen_id XOR user_id accordingly.
+                if ($user instanceof ScreenUser) {
+                    $record->extra['screen_id'] = (string) $user->getScreen()->getId();
+                } else {
+                    $record->extra['user_id'] = $user->getUserIdentifier();
+                }
 
-            if ($user instanceof TenantScopedUserInterface) {
-                // getActiveTenant() can throw when no tenant is resolved yet;
-                // enrichment must never break the request it is annotating.
-                try {
+                if ($user instanceof TenantScopedUserInterface) {
                     $record->extra['tenant_id'] = $user->getActiveTenant()->getTenantKey();
-                } catch (\Throwable) {
-                    // No active tenant on this request — leave tenant_id unset.
                 }
+            } catch (\Throwable) {
+                // An identity accessor failed (no active tenant, unhydrated screen,
+                // lazy-load error, …). Keep whatever was set; never break logging.
             }
         }
 
diff --git a/tests/Logger/EventSubscriber/AuthLoggingSubscriberTest.php b/tests/Logger/EventSubscriber/AuthLoggingSubscriberTest.php
@@ -5,19 +5,92 @@
 namespace App\Tests\Logger\EventSubscriber;
 
 use App\Logger\EventSubscriber\AuthLoggingSubscriber;
+use Lexik\Bundle\JWTAuthenticationBundle\Event\JWTExpiredEvent;
+use Lexik\Bundle\JWTAuthenticationBundle\Event\JWTFailureEventInterface;
+use Lexik\Bundle\JWTAuthenticationBundle\Event\JWTInvalidEvent;
+use Lexik\Bundle\JWTAuthenticationBundle\Event\JWTNotFoundEvent;
 use Monolog\Handler\TestHandler;
 use Monolog\Level;
 use Monolog\Logger;
 use PHPUnit\Framework\TestCase;
 use Symfony\Component\HttpFoundation\Request;
 use Symfony\Component\Security\Core\Authentication\Token\TokenInterface;
+use Symfony\Component\Security\Core\Exception\AuthenticationException;
 use Symfony\Component\Security\Core\Exception\BadCredentialsException;
+use Symfony\Component\Security\Core\User\UserInterface;
 use Symfony\Component\Security\Http\Authenticator\AuthenticatorInterface;
+use Symfony\Component\Security\Http\Authenticator\Passport\Badge\UserBadge;
+use Symfony\Component\Security\Http\Authenticator\Passport\SelfValidatingPassport;
 use Symfony\Component\Security\Http\Event\LoginFailureEvent;
+use Symfony\Component\Security\Http\Event\LoginSuccessEvent;
 use Symfony\Component\Security\Http\Event\LogoutEvent;
 
 class AuthLoggingSubscriberTest extends TestCase
 {
+    public function testLoginSuccessEmitsInfoWithIdentifierFirewallAndAuthenticator(): void
+    {
+        $handler = new TestHandler();
+        $subscriber = new AuthLoggingSubscriber(new Logger('auth', [$handler]));
+
+        $user = $this->createMock(UserInterface::class);
+        $user->method('getUserIdentifier')->willReturn('editor@example.com');
+        $authenticator = $this->createMock(AuthenticatorInterface::class);
+
+        $event = new LoginSuccessEvent(
+            $authenticator,
+            new SelfValidatingPassport(new UserBadge('editor@example.com', fn () => $user)),
+            $this->createMock(TokenInterface::class),
+            Request::create('/v2/authentication/token', Request::METHOD_POST),
+            null,
+            'main',
+        );
+
+        $subscriber->onLoginSuccess($event);
+
+        $this->assertTrue($handler->hasInfoRecords());
+        $record = $handler->getRecords()[0];
+        $this->assertSame('auth.login_success', $record->context['event']);
+        $this->assertSame('editor@example.com', $record->context['user_identifier']);
+        $this->assertSame('main', $record->context['firewall']);
+        $this->assertSame($authenticator::class, $record->context['authenticator']);
+    }
+
+    /**
+     * The `reason` string is what operators key dashboards on, and the three
+     * concrete Lexik events all share JWTFailureEventInterface — an easy arm to
+     * mis-wire — so pin each mapping, including the `unknown` default.
+     */
+    public function testJwtFailureMapsEachEventTypeToReason(): void
+    {
+        $exception = new AuthenticationException('nope');
+        $cases = [
+            'invalid' => new JWTInvalidEvent($exception, null),
+            'expired' => new JWTExpiredEvent($exception, null),
+            'not_found' => new JWTNotFoundEvent($exception, null),
+            'unknown' => $this->unknownFailureEvent($exception),
+        ];
+
+        foreach ($cases as $expectedReason => $event) {
+            $handler = new TestHandler();
+            $subscriber = new AuthLoggingSubscriber(new Logger('auth', [$handler]));
+
+            $subscriber->onJwtFailure($event);
+
+            $this->assertTrue($handler->hasWarningRecords(), "reason=$expectedReason");
+            $record = $handler->getRecords()[0];
+            $this->assertSame('auth.jwt_failure', $record->context['event']);
+            $this->assertSame($expectedReason, $record->context['reason']);
+        }
+    }
+
+    private function unknownFailureEvent(AuthenticationException $exception): JWTFailureEventInterface
+    {
+        $event = $this->createMock(JWTFailureEventInterface::class);
+        $event->method('getException')->willReturn($exception);
+
+        return $event;
+    }
+
     public function testLoginFailureEmitsAuthWarningWithoutCredentials(): void
     {
         $handler = new TestHandler();
diff --git a/tests/Logger/EventSubscriber/RequestIdSubscriberTest.php b/tests/Logger/EventSubscriber/RequestIdSubscriberTest.php
@@ -0,0 +1,97 @@
+<?php
+
+declare(strict_types=1);
+
+namespace App\Tests\Logger\EventSubscriber;
+
+use App\Logger\EventSubscriber\RequestIdSubscriber;
+use PHPUnit\Framework\TestCase;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\Response;
+use Symfony\Component\HttpKernel\Event\RequestEvent;
+use Symfony\Component\HttpKernel\Event\ResponseEvent;
+use Symfony\Component\HttpKernel\HttpKernelInterface;
+
+class RequestIdSubscriberTest extends TestCase
+{
+    private const HEADER = 'X-Request-Id';
+    private const ATTR = '_request_id';
+
+    public function testInboundHeaderIsAdoptedAndEchoedOnResponse(): void
+    {
+        $subscriber = new RequestIdSubscriber();
+        $request = Request::create('/');
+        $request->headers->set(self::HEADER, 'upstream-id-123');
+
+        $subscriber->onRequest($this->requestEvent($request));
+        $this->assertSame('upstream-id-123', $request->attributes->get(self::ATTR));
+
+        $response = new Response();
+        $subscriber->onResponse($this->responseEvent($request, $response));
+        $this->assertSame('upstream-id-123', $response->headers->get(self::HEADER));
+    }
+
+    public function testIdIsMintedWhenNoInboundHeaderAndEchoedOnResponse(): void
+    {
+        $subscriber = new RequestIdSubscriber();
+        $request = Request::create('/');
+
+        $subscriber->onRequest($this->requestEvent($request));
+        $minted = $request->attributes->get(self::ATTR);
+        $this->assertIsString($minted);
+        $this->assertNotSame('', $minted);
+
+        $response = new Response();
+        $subscriber->onResponse($this->responseEvent($request, $response));
+        $this->assertSame($minted, $response->headers->get(self::HEADER));
+    }
+
+    public function testEmptyInboundHeaderMintsAFreshId(): void
+    {
+        $subscriber = new RequestIdSubscriber();
+        $request = Request::create('/');
+        $request->headers->set(self::HEADER, '');
+
+        $subscriber->onRequest($this->requestEvent($request));
+
+        // `?:` treats the empty header as absent and mints a non-empty id.
+        $this->assertNotSame('', $request->attributes->get(self::ATTR));
+    }
+
+    public function testResponseHeaderIsNotOverwrittenWhenAlreadySet(): void
+    {
+        $subscriber = new RequestIdSubscriber();
+        $request = Request::create('/');
+        $request->attributes->set(self::ATTR, 'our-id');
+
+        $response = new Response();
+        $response->headers->set(self::HEADER, 'downstream-id');
+        $subscriber->onResponse($this->responseEvent($request, $response));
+
+        $this->assertSame('downstream-id', $response->headers->get(self::HEADER));
+    }
+
+    public function testSubRequestIsIgnored(): void
+    {
+        $subscriber = new RequestIdSubscriber();
+        $request = Request::create('/');
+
+        $subscriber->onRequest($this->requestEvent($request, HttpKernelInterface::SUB_REQUEST));
+        $this->assertNull($request->attributes->get(self::ATTR));
+
+        $request->attributes->set(self::ATTR, 'main-id');
+        $response = new Response();
+        $subscriber->onResponse($this->responseEvent($request, $response, HttpKernelInterface::SUB_REQUEST));
+        $this->assertFalse($response->headers->has(self::HEADER));
+    }
+
+    private function requestEvent(Request $request, int $type = HttpKernelInterface::MAIN_REQUEST): RequestEvent
+    {
+        return new RequestEvent($this->createMock(HttpKernelInterface::class), $request, $type);
+    }
+
+    private function responseEvent(Request $request, Response $response, int $type = HttpKernelInterface::MAIN_REQUEST): ResponseEvent
+    {
+        return new ResponseEvent($this->createMock(HttpKernelInterface::class), $request, $type, $response);
+    }
+}
