From 02e0d672bd4880847bab4579444bc4165d5f01f5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn=20Fromme?= Date: Fri, 18 Sep 2026 11:16:57 +0200 Subject: [PATCH] feat: comprehensive audit log --- config/packages/monolog.yaml | 25 +- config/services.yaml | 7 + .../Admin/Resource/CreateController.php | 11 +- .../Admin/Resource/DeleteController.php | 15 +- .../Admin/Resource/EditController.php | 12 +- .../Admin/ResourceGroup/CreateController.php | 11 +- .../Admin/ResourceGroup/DeleteController.php | 10 +- .../Admin/ResourceGroup/EditController.php | 11 +- src/Controller/Booking/ReleaseController.php | 17 +- src/Controller/Series/EndController.php | 13 +- src/EventListener/AuditSessionListener.php | 55 ++++ src/Logger/AuditActorProcessor.php | 61 ++++ src/Security/EpAuthenticator.php | 23 ++ src/Service/AuditLogger.php | 269 ++++++++++++++++++ src/Service/BookingManager.php | 33 ++- tests/Controller/Security/LogoutAuditTest.php | 67 +++++ .../AuditSessionListenerTest.php | 50 ++++ tests/Logger/AuditActorProcessorTest.php | 52 ++++ tests/Security/EpAuthenticatorTest.php | 93 ++++++ tests/Service/AuditLoggerTest.php | 179 ++++++++++++ 20 files changed, 932 insertions(+), 82 deletions(-) create mode 100644 src/EventListener/AuditSessionListener.php create mode 100644 src/Logger/AuditActorProcessor.php create mode 100644 src/Service/AuditLogger.php create mode 100644 tests/Controller/Security/LogoutAuditTest.php create mode 100644 tests/EventListener/AuditSessionListenerTest.php create mode 100644 tests/Logger/AuditActorProcessorTest.php create mode 100644 tests/Service/AuditLoggerTest.php diff --git a/config/packages/monolog.yaml b/config/packages/monolog.yaml index 8a42097..7df0de2 100644 --- a/config/packages/monolog.yaml +++ b/config/packages/monolog.yaml @@ -1,6 +1,21 @@ monolog: channels: # To see all channels, run bin/console debug:autowiring logger - deprecation # Deprecations are logged in the dedicated "deprecation" channel when it exists + - audit # Who did what to a booking or a resource -- see App\Service\AuditLogger + + handlers: + # The audit trail is kept in every environment, on its own file and for 30 days. It is + # deliberately not routed through the handlers below: those are fingers_crossed in prod, + # which means records are dropped unless an error happens to flush the buffer -- fine for + # debug noise, useless for a trail that has to be complete. Hence the plain handler, and + # hence "!audit" on the others so the same record is not duplicated into them. + audit: + type: rotating_file + path: "%kernel.logs_dir%/audit.%kernel.environment%.log" + max_files: 30 + level: info + channels: [audit] + formatter: monolog.formatter.json when@dev: monolog: @@ -9,11 +24,11 @@ when@dev: type: stream path: "%kernel.logs_dir%/%kernel.environment%.log" level: debug - channels: ["!event"] + channels: ["!event", "!audit"] console: type: console process_psr_3_messages: false - channels: ["!event", "!doctrine", "!console"] + channels: ["!event", "!doctrine", "!console", "!audit"] when@test: monolog: @@ -23,7 +38,7 @@ when@test: action_level: error handler: nested excluded_http_codes: [404, 405] - channels: ["!event"] + channels: ["!event", "!audit"] nested: type: stream path: "%kernel.logs_dir%/%kernel.environment%.log" @@ -37,7 +52,7 @@ when@prod: action_level: error handler: nested excluded_http_codes: [404, 405] - channels: ["!deprecation"] + channels: ["!deprecation", "!audit"] buffer_size: 50 # How many messages should be saved? Prevent memory leaks nested: type: stream @@ -47,7 +62,7 @@ when@prod: console: type: console process_psr_3_messages: false - channels: ["!event", "!doctrine"] + channels: ["!event", "!doctrine", "!audit"] deprecation: type: stream channels: [deprecation] diff --git a/config/services.yaml b/config/services.yaml index f3f35f8..f7d5f5a 100644 --- a/config/services.yaml +++ b/config/services.yaml @@ -19,6 +19,13 @@ services: App\: resource: '../src/' + # The audit trail writes to its own channel, never to the default one: the rotating + # audit.*.log is the record of who moved what, and mixing framework noise into it (or the + # trail into the framework log) would defeat both. + App\Service\AuditLogger: + arguments: + $logger: '@monolog.logger.audit' + # The myep OAuth2 client. Endpoint URLs are configuration rather than constants (same as # myep-team), so dev, staging and production differ by .env alone. Empty credentials are a # valid state: the login page then says the client is not registered yet instead of bouncing diff --git a/src/Controller/Admin/Resource/CreateController.php b/src/Controller/Admin/Resource/CreateController.php index f183b88..cc5c42e 100644 --- a/src/Controller/Admin/Resource/CreateController.php +++ b/src/Controller/Admin/Resource/CreateController.php @@ -9,8 +9,8 @@ use App\Enum\ResourceType; use App\Form\Admin\ResourceFormType; use App\Htmx\HxRedirectResponse; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -22,7 +22,7 @@ final class CreateController extends AbstractController { public function __construct( private readonly EntityManagerInterface $em, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -43,12 +43,7 @@ final class CreateController extends AbstractController $this->em->persist($resource); $this->em->flush(); - $this->logger->info('Admin created a resource.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'resource_id' => $resource->getId(), - 'type' => $type->value, - 'label' => $resource->getLabel(), - ]); + $this->audit->resourceCreated($resource); $this->addFlash('success', \sprintf('%s angelegt.', $resource->getLabel())); return new HxRedirectResponse($this->generateUrl('app_admin_resource')); diff --git a/src/Controller/Admin/Resource/DeleteController.php b/src/Controller/Admin/Resource/DeleteController.php index 6588e0d..6e01747 100644 --- a/src/Controller/Admin/Resource/DeleteController.php +++ b/src/Controller/Admin/Resource/DeleteController.php @@ -12,8 +12,8 @@ use App\Htmx\HxRedirectResponse; use App\Repository\BookingRepository; use App\Security\Role; use Doctrine\DBAL\LockMode; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -38,7 +38,7 @@ final class DeleteController extends AbstractController public function __construct( private readonly EntityManagerInterface $em, private readonly BookingRepository $bookings, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -61,8 +61,10 @@ final class DeleteController extends AbstractController $this->denyUnlessCsrfValid($request, $tokenId); - $id = $resource->getId(); + // Snapshotted before the delete: afterwards the entity no longer knows its own id. + $id = (int) $resource->getId(); $label = $resource->getLabel(); + $type = $resource->getType(); $deleted = $this->em->wrapInTransaction(function () use ($resource): int { $this->em->lock($resource, LockMode::PESSIMISTIC_WRITE); @@ -87,12 +89,7 @@ final class DeleteController extends AbstractController return (int) $deleted; }); - $this->logger->info('Admin deleted a resource.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'resource_id' => $id, - 'label' => $label, - 'bookings_deleted' => $deleted, - ]); + $this->audit->resourceDeleted($id, $label, $type, $deleted); $this->addFlash('success', $deleted > 0 ? \sprintf('%s und %d Buchungen gelöscht.', $label, $deleted) diff --git a/src/Controller/Admin/Resource/EditController.php b/src/Controller/Admin/Resource/EditController.php index b81e425..0076008 100644 --- a/src/Controller/Admin/Resource/EditController.php +++ b/src/Controller/Admin/Resource/EditController.php @@ -9,8 +9,8 @@ use App\Form\Admin\ResourceFormType; use App\Htmx\HxRedirectResponse; use App\Repository\BookingRepository; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -31,7 +31,7 @@ final class EditController extends AbstractController public function __construct( private readonly EntityManagerInterface $em, private readonly BookingRepository $bookings, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -49,13 +49,7 @@ final class EditController extends AbstractController if ($form->isSubmitted() && $form->isValid()) { $this->em->flush(); - $this->logger->info('Admin edited a resource.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'resource_id' => $resource->getId(), - 'label' => $resource->getLabel(), - 'group' => $resource->getGroup()?->getLabel(), - 'active' => $resource->isActive(), - ]); + $this->audit->resourceUpdated($resource, $wasActive); $remaining = $wasActive && !$resource->isActive() ? $this->bookings->countFromDate($resource, new \DateTimeImmutable('today')) diff --git a/src/Controller/Admin/ResourceGroup/CreateController.php b/src/Controller/Admin/ResourceGroup/CreateController.php index c15893b..9ff2bca 100644 --- a/src/Controller/Admin/ResourceGroup/CreateController.php +++ b/src/Controller/Admin/ResourceGroup/CreateController.php @@ -10,8 +10,8 @@ use App\Form\Admin\ResourceGroupFormType; use App\Htmx\HxRedirectResponse; use App\Repository\ResourceGroupRepository; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -24,7 +24,7 @@ final class CreateController extends AbstractController public function __construct( private readonly EntityManagerInterface $em, private readonly ResourceGroupRepository $groups, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -45,12 +45,7 @@ final class CreateController extends AbstractController $this->em->persist($group); $this->em->flush(); - $this->logger->info('Admin created a resource group.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'group_id' => $group->getId(), - 'type' => $type->value, - 'label' => $group->getLabel(), - ]); + $this->audit->resourceGroupCreated($group); $this->addFlash('success', \sprintf('%s angelegt.', $group->getLabel())); return new HxRedirectResponse($this->generateUrl('app_admin_resource')); diff --git a/src/Controller/Admin/ResourceGroup/DeleteController.php b/src/Controller/Admin/ResourceGroup/DeleteController.php index 5d15f0a..5576924 100644 --- a/src/Controller/Admin/ResourceGroup/DeleteController.php +++ b/src/Controller/Admin/ResourceGroup/DeleteController.php @@ -9,8 +9,8 @@ use App\Entity\ResourceGroup; use App\Htmx\HxRedirectResponse; use App\Repository\ResourceRepository; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -31,7 +31,7 @@ final class DeleteController extends AbstractController public function __construct( private readonly EntityManagerInterface $em, private readonly ResourceRepository $resources, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -51,11 +51,7 @@ final class DeleteController extends AbstractController $this->denyUnlessCsrfValid($request, 'delete-resource-group-'.$group->getId()); - $this->logger->info('Admin deleted a resource group.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'group_id' => $group->getId(), - 'label' => $group->getLabel(), - ]); + $this->audit->resourceGroupDeleted((int) $group->getId(), $group->getLabel(), $group->getType()); $label = $group->getLabel(); $this->em->remove($group); diff --git a/src/Controller/Admin/ResourceGroup/EditController.php b/src/Controller/Admin/ResourceGroup/EditController.php index 4b5d709..3ddd5ad 100644 --- a/src/Controller/Admin/ResourceGroup/EditController.php +++ b/src/Controller/Admin/ResourceGroup/EditController.php @@ -8,8 +8,8 @@ use App\Entity\ResourceGroup; use App\Form\Admin\ResourceGroupFormType; use App\Htmx\HxRedirectResponse; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -21,7 +21,7 @@ final class EditController extends AbstractController { public function __construct( private readonly EntityManagerInterface $em, - private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -36,12 +36,7 @@ final class EditController extends AbstractController if ($form->isSubmitted() && $form->isValid()) { $this->em->flush(); - $this->logger->info('Admin edited a resource group.', [ - 'admin' => $this->getUser()?->getUserIdentifier(), - 'group_id' => $group->getId(), - 'label' => $group->getLabel(), - 'position' => $group->getPosition(), - ]); + $this->audit->resourceGroupUpdated($group); $this->addFlash('success', \sprintf('%s gespeichert.', $group->getLabel())); return new HxRedirectResponse($this->generateUrl('app_admin_resource')); diff --git a/src/Controller/Booking/ReleaseController.php b/src/Controller/Booking/ReleaseController.php index 4b88eb8..0ae9cfd 100644 --- a/src/Controller/Booking/ReleaseController.php +++ b/src/Controller/Booking/ReleaseController.php @@ -12,7 +12,6 @@ use App\Htmx\HxTrait; use App\Security\Role; use App\Service\BoardContextFactory; use App\Service\BookingManager; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -28,7 +27,6 @@ final class ReleaseController extends AbstractController public function __construct( private readonly BoardContextFactory $boardContext, private readonly BookingManager $manager, - private readonly LoggerInterface $logger, ) { } @@ -57,18 +55,9 @@ final class ReleaseController extends AbstractController $holder = $booking->getUser(); $onBehalf = !$booking->belongsTo($this->currentUser()); - if ($onBehalf) { - // The row is about to be deleted, so without this line nothing records that an - // administrator freed somebody else's desk. - $this->logger->info('Admin released a booking on behalf of another user.', [ - 'admin' => $this->currentUser()->getEmail(), - 'holder' => $holder->getEmail(), - 'resource' => $label, - 'date' => $date->format('Y-m-d'), - 'time' => (string) $booking->getTimeRange(), - ]); - } - + // The release itself is audited from BookingManager, which is also where the row still + // exists to be described. An administrator freeing somebody else's desk needs nothing + // extra here: the record carries the holder, and the actor comes from the token. $this->manager->release($booking); $this->addFlash('success', $onBehalf diff --git a/src/Controller/Series/EndController.php b/src/Controller/Series/EndController.php index 21e131a..d7f98cb 100644 --- a/src/Controller/Series/EndController.php +++ b/src/Controller/Series/EndController.php @@ -10,7 +10,6 @@ use App\Entity\BookingSeries; use App\Htmx\HxTrait; use App\Security\Role; use App\Service\BookingManager; -use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; use Symfony\Component\HttpFoundation\Response; @@ -24,7 +23,6 @@ final class EndController extends AbstractController public function __construct( private readonly BookingManager $manager, - private readonly LoggerInterface $logger, ) { } @@ -45,17 +43,10 @@ final class EndController extends AbstractController $this->denyUnlessCsrfValid($request, 'end-series-'.$series->getId()); + // Only the flash still cares who the series belongs to; the audit record is written + // from BookingManager and names holder and actor by itself. $onBehalf = $series->getUser()->getId() !== $this->currentUser()->getId(); - if ($onBehalf) { - $this->logger->info('Admin ended a series on behalf of another user.', [ - 'admin' => $this->currentUser()->getEmail(), - 'holder' => $series->getUser()->getEmail(), - 'resource' => $series->getResource()->getLabel(), - 'series' => $series->getId(), - ]); - } - $removed = $this->manager->endSeries($series, new \DateTimeImmutable('today')); $this->addFlash('success', $onBehalf diff --git a/src/EventListener/AuditSessionListener.php b/src/EventListener/AuditSessionListener.php new file mode 100644 index 0000000..b26bcfa --- /dev/null +++ b/src/EventListener/AuditSessionListener.php @@ -0,0 +1,55 @@ +getUser(); + + if ($user instanceof User) { + $this->audit->signedIn($user); + } + } + + /** + * The token is still in place while this event is dispatched -- LogoutListener clears it + * afterwards -- but the account is read off the event rather than off the token store all + * the same, so the record stays complete if that order ever changes. + */ + #[AsEventListener(event: LogoutEvent::class)] + public function onLogout(LogoutEvent $event): void + { + $user = $event->getToken()?->getUser(); + + if ($user instanceof User) { + $this->audit->signedOut($user); + } + } +} diff --git a/src/Logger/AuditActorProcessor.php b/src/Logger/AuditActorProcessor.php new file mode 100644 index 0000000..1ecb7ed --- /dev/null +++ b/src/Logger/AuditActorProcessor.php @@ -0,0 +1,61 @@ +extra['actor'] = $this->actor(); + + return $record; + } + + private function actor(): string + { + $user = $this->security->getUser(); + + if ($user instanceof User) { + return $user->getEmail(); + } + + // The user is asked for first and the SAPI only afterwards, so that a console command + // running with a token -- a future import, say -- is still attributed to whoever it runs + // as, rather than swallowed by a blanket "cli means system" check. + if (null !== $user) { + return $user->getUserIdentifier(); + } + + return 'cli' === \PHP_SAPI ? self::SYSTEM : self::ANONYMOUS; + } +} diff --git a/src/Security/EpAuthenticator.php b/src/Security/EpAuthenticator.php index f498516..55b74d3 100644 --- a/src/Security/EpAuthenticator.php +++ b/src/Security/EpAuthenticator.php @@ -9,6 +9,7 @@ use App\Repository\UserRepository; use App\Security\OAuth2\AuthorizationRequestException; use App\Security\OAuth2\EpClient; use App\Security\OAuth2\UserinfoUnavailableException; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; use League\OAuth2\Client\Provider\Exception\IdentityProviderException; use Psr\Log\LoggerInterface; @@ -42,6 +43,7 @@ class EpAuthenticator extends AbstractAuthenticator private readonly EntityManagerInterface $em, private readonly UrlGeneratorInterface $urlGenerator, private readonly LoggerInterface $logger, + private readonly AuditLogger $audit, ) { } @@ -56,6 +58,10 @@ class EpAuthenticator extends AbstractAuthenticator $accessToken = $this->client->fetchAccessToken($request); } catch (AuthorizationRequestException|IdentityProviderException $e) { $this->logger->error('Login via myep failed: no access token', ['exception' => $e]); + // Audited here rather than from a failure event: this is the only point that still + // knows why the sign-in did not happen. Downstream there is only the German message + // the login page shows. + $this->audit->signInRefused('no_access_token'); throw new CustomUserMessageAuthenticationException('Anmeldung über myep fehlgeschlagen.'); } @@ -64,6 +70,7 @@ class EpAuthenticator extends AbstractAuthenticator $userinfo = $this->client->fetchUserinfo($accessToken); } catch (UserinfoUnavailableException $e) { $this->logger->error('Login via myep failed: userinfo unreadable', ['exception' => $e]); + $this->audit->signInRefused('userinfo_unreadable'); throw new CustomUserMessageAuthenticationException('Anmeldung über myep fehlgeschlagen.'); } @@ -74,6 +81,7 @@ class EpAuthenticator extends AbstractAuthenticator $email = $userinfo['email'] ?? null; if (!\is_string($email) || '' === $email) { $this->logger->error('Login via myep failed: userinfo carried no email claim'); + $this->audit->signInRefused('no_email_claim'); throw new CustomUserMessageAuthenticationException('Anmeldung über myep fehlgeschlagen.'); } @@ -81,6 +89,7 @@ class EpAuthenticator extends AbstractAuthenticator $roles = Role::eligibleOnly($this->claimedRoles($userinfo)); if ([] === $roles) { $this->logger->info('Login via myep refused: no eligible role', ['email' => $email]); + $this->audit->signInRefused('no_eligible_role', $email); throw new CustomUserMessageAuthenticationException( 'Für E&P Platz ist eine Mitarbeiter- oder Administrator-Rolle erforderlich.', @@ -154,6 +163,7 @@ class EpAuthenticator extends AbstractAuthenticator private function createOrUpdate(string $email, string $name, array $roles): User { $user = $this->users->findOneBy(['email' => $email]); + $isNew = null === $user; if (null === $user) { $user = new User($email, $name); @@ -162,11 +172,24 @@ class EpAuthenticator extends AbstractAuthenticator $user->setName($name); } + // Filtered the same way the claim was, so the comparison below is between two sets of + // the same shape -- getRoles() would add ROLE_USER to one side and not the other. + $previousRoles = Role::eligibleOnly($user->getRoles()); + // myep leads: a role it no longer reports is withdrawn here, not kept because it was // granted once. $user->setRoles($roles); $this->em->flush(); + // After the flush, so nothing is recorded that a failing write would have undone. Both + // records show "anonymous" as their actor, correctly: they happen while the person is + // being authenticated and before any token exists, which is why they name the account. + if ($isNew) { + $this->audit->accountProvisioned($user); + } elseif ($previousRoles !== $roles) { + $this->audit->rolesChanged($user, $previousRoles, $roles); + } + return $user; } } diff --git a/src/Service/AuditLogger.php b/src/Service/AuditLogger.php new file mode 100644 index 0000000..02df964 --- /dev/null +++ b/src/Service/AuditLogger.php @@ -0,0 +1,269 @@ +info()` + * calls hold on to. Naming the events here also makes the list of what is audited readable in + * one place, so a new write that nobody logged is a visible gap rather than an invisible one. + * + * Messages are English, like every other developer-facing string in this project: an audit log + * is read by whoever is investigating, not by the person who was booking a desk. + * + * The acting user is NOT passed in. AuditActorProcessor takes it from the security token and + * puts it in `extra.actor`, so no call site can log the wrong one. What the context carries is + * the subject -- `holder` for a booking -- and a record whose holder is not its actor is an + * administrator having acted for somebody else. + * + * Level is info throughout: an audit record is a fact, not a problem. Something that *is* a + * problem belongs in the framework log, which is what the default channel is for -- a refused + * sign-in is audited here *and* logged with its exception there, because the two readers want + * different things from it. + */ +final readonly class AuditLogger +{ + public function __construct(private LoggerInterface $logger) + { + } + + public function bookingCreated(Booking $booking): void + { + $this->logger->info('Booking created.', $this->booking($booking)); + } + + /** + * One record for the series, not one per occurrence: the occurrences are the same act, and + * a year of weekly bookings would otherwise bury everything else in the file. The individual + * days stay recoverable -- the series id is on every booking record that follows. + */ + public function seriesCreated(SeriesResult $result): void + { + $series = $result->series; + + $this->logger->info('Booking series created.', [ + 'series_id' => $series->getId(), + 'holder' => $series->getUser()->getEmail(), + 'resource' => $series->getResource()->getLabel(), + 'resource_id' => $series->getResource()->getId(), + 'rule' => $series->getRule()->value, + 'start_date' => $series->getStartDate()->format('Y-m-d'), + 'end_date' => $series->getEndDate()->format('Y-m-d'), + 'time' => self::clock($series->getTimeRange()), + 'bookings_created' => $result->createdCount(), + // The days the series could not have, so a later "why is Tuesday missing" has an + // answer without reconstructing what was booked at the time. + 'skipped_dates' => array_keys($result->skipped), + ]); + } + + public function bookingRescheduled(Booking $booking, TimeRange $previous): void + { + $this->logger->info('Booking rescheduled.', $this->booking($booking) + [ + 'previous_time' => self::clock($previous), + ]); + } + + /** + * Called before the row goes, since afterwards there is nothing left to describe it. + */ + public function bookingReleased(Booking $booking): void + { + $this->logger->info('Booking released.', $this->booking($booking)); + } + + /** + * The id is passed rather than read off the series, because ending one can delete it and + * Doctrine nulls the identifier of a deleted entity (UnitOfWork::executeDeletions) -- asking + * the series for its own id afterwards yields null exactly on the records that matter most. + */ + public function seriesEnded(BookingSeries $series, ?int $seriesId, \DateTimeImmutable $from, int $removed): void + { + $this->logger->info('Booking series ended.', [ + 'series_id' => $seriesId, + 'holder' => $series->getUser()->getEmail(), + 'resource' => $series->getResource()->getLabel(), + 'resource_id' => $series->getResource()->getId(), + 'ended_from' => $from->format('Y-m-d'), + 'bookings_removed' => $removed, + ]); + } + + public function signedIn(User $user): void + { + $this->logger->info('User signed in.', [ + 'account' => $user->getEmail(), + 'roles' => $user->getRoles(), + ]); + } + + /** + * The account is named separately from the actor because a refused sign-in has no token + * behind it -- the actor of these records is always "anonymous", and on the paths that fail + * before the userinfo response is read there is not even an email to name. + * + * @param string $reason a short English tag, not a message: these are counted and filtered, + * and the user-facing German explanation says nothing to whoever reads + * the trail. The exception detail stays in the framework log. + */ + public function signInRefused(string $reason, ?string $email = null): void + { + $this->logger->info('Sign-in refused.', [ + 'account' => $email, + 'reason' => $reason, + ]); + } + + public function signedOut(User $user): void + { + $this->logger->info('User signed out.', [ + 'account' => $user->getEmail(), + ]); + } + + /** + * First sign-in: myep authenticates the person, and this is the moment ephub gains a row for + * them. Audited because it is the only place an account comes into existence -- nobody + * creates one by hand. + */ + public function accountProvisioned(User $user): void + { + $this->logger->info('User account provisioned.', [ + 'account' => $user->getEmail(), + 'roles' => $user->getRoles(), + ]); + } + + /** + * Roles follow myep on every sign-in, so a person can gain or lose administrative access + * without anybody here doing anything. That is worth a record of its own: it is the one + * change to an account that alters what its holder may do. + * + * @param list $previous + * @param list $current + */ + public function rolesChanged(User $user, array $previous, array $current): void + { + $this->logger->info('User roles changed.', [ + 'account' => $user->getEmail(), + 'previous_roles' => $previous, + 'roles' => $current, + ]); + } + + public function resourceCreated(Resource $resource): void + { + $this->logger->info('Resource created.', $this->resource($resource)); + } + + public function resourceUpdated(Resource $resource, bool $wasActive): void + { + $this->logger->info('Resource updated.', $this->resource($resource) + [ + // Retiring and reactivating are ordinary edits to the form and to the database, but + // not to the people whose bookings they affect, so the transition is spelled out + // rather than left to be diffed out of two consecutive records. + 'was_active' => $wasActive, + ]); + } + + /** + * Takes a snapshot rather than the entity: by the time a deletion is worth recording, the + * entity no longer has an id to read. + */ + public function resourceDeleted(int $id, string $label, ResourceType $type, int $bookingsDeleted): void + { + $this->logger->info('Resource deleted.', [ + 'resource' => $label, + 'resource_id' => $id, + 'type' => $type->value, + 'bookings_deleted' => $bookingsDeleted, + ]); + } + + public function resourceGroupCreated(ResourceGroup $group): void + { + $this->logger->info('Resource group created.', $this->group($group)); + } + + public function resourceGroupUpdated(ResourceGroup $group): void + { + $this->logger->info('Resource group updated.', $this->group($group)); + } + + public function resourceGroupDeleted(int $id, string $label, ResourceType $type): void + { + $this->logger->info('Resource group deleted.', [ + 'group' => $label, + 'group_id' => $id, + 'type' => $type->value, + ]); + } + + /** + * @return array + */ + private function booking(Booking $booking): array + { + return [ + 'booking_id' => $booking->getId(), + 'holder' => $booking->getUser()->getEmail(), + 'resource' => $booking->getResource()->getLabel(), + 'resource_id' => $booking->getResource()->getId(), + 'date' => $booking->getDate()->format('Y-m-d'), + 'time' => self::clock($booking->getTimeRange()), + 'series_id' => $booking->getSeries()?->getId(), + ]; + } + + /** + * Clock times rather than (string) $time: TimeRange's own string form is the German one the + * UI shows ("ganztägig"), and an audit record is read by whoever is investigating. This also + * keeps every record's time in one shape, which "all day" would not be. + */ + private static function clock(TimeRange $time): string + { + return $time->start().'-'.$time->end(); + } + + /** + * @return array + */ + private function resource(Resource $resource): array + { + return [ + 'resource' => $resource->getLabel(), + 'resource_id' => $resource->getId(), + 'type' => $resource->getType()->value, + 'group' => $resource->getGroup()?->getLabel(), + 'active' => $resource->isActive(), + ]; + } + + /** + * @return array + */ + private function group(ResourceGroup $group): array + { + return [ + 'group' => $group->getLabel(), + 'group_id' => $group->getId(), + 'type' => $group->getType()->value, + 'position' => $group->getPosition(), + ]; + } +} diff --git a/src/Service/BookingManager.php b/src/Service/BookingManager.php index afd2951..a844165 100644 --- a/src/Service/BookingManager.php +++ b/src/Service/BookingManager.php @@ -43,6 +43,7 @@ final readonly class BookingManager public function __construct( private EntityManagerInterface $em, private BookingRepository $bookings, + private AuditLogger $audit, ) { } @@ -54,7 +55,7 @@ final readonly class BookingManager // All day is the default, as it was before ranges existed. $time ??= TimeRange::wholeDay(); - return $this->em->wrapInTransaction(function () use ($user, $resource, $date, $time): Booking { + $booking = $this->em->wrapInTransaction(function () use ($user, $resource, $date, $time): Booking { $this->em->lock($resource, LockMode::PESSIMISTIC_WRITE); $this->assertFree($resource, $date, $time); @@ -65,6 +66,13 @@ final readonly class BookingManager return $booking; }); + + // Audited outside the transaction, here and below: a record of a write that was rolled + // back afterwards would be worse than no record, and a refused booking throws before + // ever reaching this line. + $this->audit->bookingCreated($booking); + + return $booking; } /** @@ -76,7 +84,7 @@ final readonly class BookingManager */ public function bookSeries(BookingSeries $series): SeriesResult { - return $this->em->wrapInTransaction(function () use ($series): SeriesResult { + $result = $this->em->wrapInTransaction(function () use ($series): SeriesResult { $resource = $series->getResource(); $user = $series->getUser(); $time = $series->getTimeRange(); @@ -108,6 +116,10 @@ final readonly class BookingManager return new SeriesResult($series, $created, $skipped); }); + + $this->audit->seriesCreated($result); + + return $result; } /** @@ -115,6 +127,8 @@ final readonly class BookingManager */ public function reschedule(Booking $booking, TimeRange $time): void { + $previous = $booking->getTimeRange(); + $this->em->wrapInTransaction(function () use ($booking, $time): void { $resource = $booking->getResource(); $this->em->lock($resource, LockMode::PESSIMISTIC_WRITE); @@ -124,10 +138,15 @@ final readonly class BookingManager $booking->changeTime($time); $this->em->flush(); }); + + $this->audit->bookingRescheduled($booking, $previous); } public function release(Booking $booking): void { + // Before the flush, while the booking still knows its own id. + $this->audit->bookingReleased($booking); + $this->em->remove($booking); $this->em->flush(); } @@ -140,7 +159,11 @@ final readonly class BookingManager */ public function endSeries(BookingSeries $series, \DateTimeImmutable $from): int { - return $this->em->wrapInTransaction(function () use ($series, $from): int { + // Read before the transaction: ending a series can delete it, and a deleted entity no + // longer knows its own id. + $seriesId = $series->getId(); + + $removed = $this->em->wrapInTransaction(function () use ($series, $from): int { $from = $from->setTime(0, 0); $removed = 0; @@ -159,6 +182,10 @@ final readonly class BookingManager return $removed; }); + + $this->audit->seriesEnded($series, $seriesId, $from, $removed); + + return $removed; } /** diff --git a/tests/Controller/Security/LogoutAuditTest.php b/tests/Controller/Security/LogoutAuditTest.php new file mode 100644 index 0000000..a95ce96 --- /dev/null +++ b/tests/Controller/Security/LogoutAuditTest.php @@ -0,0 +1,67 @@ +client = self::createClient(server: ['HTTPS' => true]); + $this->client->disableReboot(); + $this->em = self::getContainer()->get(EntityManagerInterface::class); + $this->em->getConnection()->beginTransaction(); + + $this->auditRecords = new TestHandler(); + $audit = self::getContainer()->get('monolog.logger.audit'); + \assert($audit instanceof Logger); + $audit->pushHandler($this->auditRecords); + } + + protected function tearDown(): void + { + $this->em->getConnection()->rollBack(); + parent::tearDown(); + } + + public function testSigningOutIsAudited(): void + { + $user = new User('anna@ep-reisen.de', 'Anna'); + $user->setRoles(['ROLE_EMPLOYEE']); + $this->em->persist($user); + $this->em->flush(); + + $this->client->loginUser($user); + $this->client->request('GET', '/logout'); + + self::assertResponseRedirects(); + + $records = array_values(array_filter( + $this->auditRecords->getRecords(), + static fn ($record): bool => 'User signed out.' === $record->message, + )); + + self::assertCount(1, $records); + self::assertSame('anna@ep-reisen.de', $records[0]->context['account']); + self::assertSame('anna@ep-reisen.de', $records[0]->extra['actor']); + } +} diff --git a/tests/EventListener/AuditSessionListenerTest.php b/tests/EventListener/AuditSessionListenerTest.php new file mode 100644 index 0000000..1f42169 --- /dev/null +++ b/tests/EventListener/AuditSessionListenerTest.php @@ -0,0 +1,50 @@ +onLogout(new LogoutEvent(new Request(), new UsernamePasswordToken($user, 'main', $user->getRoles()))); + + $record = $handler->getRecords()[0]; + + self::assertSame('User signed out.', $record->message); + self::assertSame('anna@ep-reisen.de', $record->context['account']); + } + + /** + * /logout is public, so it can be reached without a session at all -- that is not an event + * worth a record, and it must not be an error either. + */ + public function testSigningOutWithoutATokenRecordsNothing(): void + { + $handler = new TestHandler(); + $listener = new AuditSessionListener(new AuditLogger(new Logger('audit', [$handler]))); + + $listener->onLogout(new LogoutEvent(new Request(), null)); + + self::assertSame([], $handler->getRecords()); + } +} diff --git a/tests/Logger/AuditActorProcessorTest.php b/tests/Logger/AuditActorProcessorTest.php new file mode 100644 index 0000000..61dbae1 --- /dev/null +++ b/tests/Logger/AuditActorProcessorTest.php @@ -0,0 +1,52 @@ +process(new User('admin@ep-reisen.de', 'Admin')); + + self::assertSame('admin@ep-reisen.de', $record->extra['actor']); + } + + /** + * PHPUnit runs under the CLI SAPI, which is the same context a console command or the + * message worker writes from -- so this is the system branch, not the anonymous one. + */ + public function testAWriteWithNoUserBehindItIsAttributedToTheSystem(): void + { + $record = $this->process(null); + + self::assertSame(AuditActorProcessor::SYSTEM, $record->extra['actor']); + } + + private function process(?User $user): LogRecord + { + $security = $this->createStub(Security::class); + $security->method('getUser')->willReturn($user); + + $processor = new AuditActorProcessor($security); + + return $processor(new LogRecord( + new \DateTimeImmutable(), + 'audit', + Level::Info, + 'Booking created.', + )); + } +} diff --git a/tests/Security/EpAuthenticatorTest.php b/tests/Security/EpAuthenticatorTest.php index a9c2211..dc544c7 100644 --- a/tests/Security/EpAuthenticatorTest.php +++ b/tests/Security/EpAuthenticatorTest.php @@ -11,8 +11,12 @@ use App\Security\OAuth2\AuthorizationRequestException; use App\Security\OAuth2\EpClient; use App\Security\OAuth2\UserinfoUnavailableException; use App\Security\Role; +use App\Service\AuditLogger; use Doctrine\ORM\EntityManagerInterface; use League\OAuth2\Client\Token\AccessToken; +use Monolog\Handler\TestHandler; +use Monolog\Logger; +use Monolog\LogRecord; use Psr\Log\NullLogger; use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase; use Symfony\Component\HttpFoundation\Request; @@ -29,12 +33,14 @@ use Symfony\Component\Security\Http\Authenticator\Passport\Badge\UserBadge; class EpAuthenticatorTest extends KernelTestCase { private EntityManagerInterface $em; + private TestHandler $auditRecords; protected function setUp(): void { self::bootKernel(); $this->em = self::getContainer()->get(EntityManagerInterface::class); $this->em->getConnection()->beginTransaction(); + $this->auditRecords = new TestHandler(); } protected function tearDown(): void @@ -189,6 +195,79 @@ class EpAuthenticatorTest extends KernelTestCase ->authenticate(new Request()); } + public function testAFirstSignInIsAudited(): void + { + $this->authenticate(['email' => 'anna@ep-reisen.de', 'roles' => ['ROLE_EMPLOYEE']]); + + $record = $this->audited('User account provisioned.'); + + self::assertSame('anna@ep-reisen.de', $record->context['account']); + self::assertContains(Role::EMPLOYEE, $record->context['roles']); + } + + /** + * Roles follow myep on every sign-in, so somebody can lose administrative access without + * anybody here doing anything -- which is exactly the kind of change the trail is for. + */ + public function testAWithdrawnRoleIsAudited(): void + { + $existing = new User('chef@ep-reisen.de', 'Chef'); + $existing->setRoles([Role::EMPLOYEE, Role::ADMIN]); + $this->em->persist($existing); + $this->em->flush(); + + $this->authenticate(['email' => 'chef@ep-reisen.de', 'roles' => ['ROLE_EMPLOYEE']]); + + $record = $this->audited('User roles changed.'); + + self::assertSame([Role::EMPLOYEE, Role::ADMIN], $record->context['previous_roles']); + self::assertSame([Role::EMPLOYEE], $record->context['roles']); + } + + public function testASignInThatChangesNothingIsNotAuditedAsARoleChange(): void + { + $existing = new User('anna@ep-reisen.de', 'Anna'); + $existing->setRoles([Role::EMPLOYEE]); + $this->em->persist($existing); + $this->em->flush(); + + $this->authenticate(['email' => 'anna@ep-reisen.de', 'roles' => ['ROLE_EMPLOYEE']]); + + self::assertFalse($this->auditRecords->hasInfoThatContains('User roles changed.')); + self::assertFalse($this->auditRecords->hasInfoThatContains('User account provisioned.')); + } + + /** + * The reason is the point: by the time the failure reaches the login page it is one German + * sentence, whatever went wrong. + */ + public function testARefusedSignInIsAuditedWithWhyItWasRefused(): void + { + try { + $this->authenticate(['email' => 'kunde@example.org', 'roles' => ['ROLE_CUSTOMER']]); + } catch (CustomUserMessageAuthenticationException) { + } + + $record = $this->audited('Sign-in refused.'); + + self::assertSame('no_eligible_role', $record->context['reason']); + self::assertSame('kunde@example.org', $record->context['account']); + } + + public function testAFailureBeforeTheUserIsKnownIsAuditedWithoutAnAccount(): void + { + try { + $this->authenticator(throwOnToken: new AuthorizationRequestException('state mismatch')) + ->authenticate(new Request()); + } catch (CustomUserMessageAuthenticationException) { + } + + $record = $this->audited('Sign-in refused.'); + + self::assertSame('no_access_token', $record->context['reason']); + self::assertNull($record->context['account']); + } + public function testItOnlyFiresOnTheCallbackRoute(): void { $authenticator = $this->authenticator(); @@ -246,6 +325,20 @@ class EpAuthenticatorTest extends KernelTestCase $this->em, self::getContainer()->get(UrlGeneratorInterface::class), new NullLogger(), + new AuditLogger(new Logger('audit', [$this->auditRecords])), ); } + + /** The one audit record carrying this message. */ + private function audited(string $message): LogRecord + { + $records = array_values(array_filter( + $this->auditRecords->getRecords(), + static fn (LogRecord $record): bool => $message === $record->message, + )); + + self::assertCount(1, $records, \sprintf('Expected exactly one "%s" audit record.', $message)); + + return $records[0]; + } } diff --git a/tests/Service/AuditLoggerTest.php b/tests/Service/AuditLoggerTest.php new file mode 100644 index 0000000..969ca79 --- /dev/null +++ b/tests/Service/AuditLoggerTest.php @@ -0,0 +1,179 @@ +handler = new TestHandler(); + $this->audit = new AuditLogger(new Logger('audit', [$this->handler])); + } + + public function testACreatedBookingIsRecordedWithItsHolderAndResource(): void + { + $this->audit->bookingCreated($this->booking()); + + $record = $this->record(); + + self::assertSame('Booking created.', $record->message); + self::assertSame('holder@ep-reisen.de', $record->context['holder']); + self::assertSame('D1', $record->context['resource']); + self::assertSame('2026-09-18', $record->context['date']); + self::assertSame('09:00-13:00', $record->context['time']); + } + + public function testARescheduledBookingKeepsTheSpanItCameFrom(): void + { + $booking = $this->booking(); + $previous = $booking->getTimeRange(); + $booking->changeTime(TimeRange::fromMinutes(600, 900)); + + $this->audit->bookingRescheduled($booking, $previous); + + $record = $this->record(); + + self::assertSame('Booking rescheduled.', $record->message); + self::assertSame('09:00-13:00', $record->context['previous_time']); + self::assertSame('10:00-15:00', $record->context['time']); + } + + /** + * A series is one record, not one per occurrence -- otherwise a year of weekly bookings + * buries every other event in the file. + */ + public function testASeriesIsRecordedOnceWithTheDaysItCouldNotHave(): void + { + $series = new BookingSeries( + $this->user(), + $this->resource(), + RecurrenceRule::WEEKLY, + new \DateTimeImmutable('2026-09-18'), + new \DateTimeImmutable('2026-10-02'), + TimeRange::fromMinutes(540, 780), + ); + + $this->audit->seriesCreated(new SeriesResult($series, [$this->booking()], ['2026-09-25' => 'taken'])); + + $records = $this->handler->getRecords(); + + self::assertCount(1, $records); + self::assertSame('Booking series created.', $records[0]->message); + self::assertSame(1, $records[0]->context['bookings_created']); + self::assertSame(['2026-09-25'], $records[0]->context['skipped_dates']); + } + + /** + * Ending a series can delete it, and Doctrine nulls the id of a deleted entity -- so the id + * is passed in, and the record must use the one it was given. + */ + public function testAnEndedSeriesIsRecordedWithTheIdItHadBeforeItWasDeleted(): void + { + $series = new BookingSeries( + $this->user(), + $this->resource(), + RecurrenceRule::WEEKLY, + new \DateTimeImmutable('2026-09-18'), + new \DateTimeImmutable('2026-10-02'), + TimeRange::fromMinutes(540, 780), + ); + + $this->audit->seriesEnded($series, 42, new \DateTimeImmutable('2026-09-25'), 2); + + $record = $this->record(); + + self::assertSame(42, $record->context['series_id']); + self::assertSame('2026-09-25', $record->context['ended_from']); + self::assertSame(2, $record->context['bookings_removed']); + } + + public function testRetiringAResourceIsRecordedAsTheTransitionItIs(): void + { + $resource = $this->resource(); + $resource->setGroup(new ResourceGroup(ResourceType::DESK, 'Room 1')); + $resource->setActive(false); + + $this->audit->resourceUpdated($resource, true); + + $record = $this->record(); + + self::assertSame('Resource updated.', $record->message); + self::assertTrue($record->context['was_active']); + self::assertFalse($record->context['active']); + self::assertSame('Room 1', $record->context['group']); + } + + public function testADeletedResourceIsRecordedWithHowManyBookingsWentWithIt(): void + { + $this->audit->resourceDeleted(7, 'D1', ResourceType::DESK, 3); + + $record = $this->record(); + + self::assertSame('Resource deleted.', $record->message); + self::assertSame(7, $record->context['resource_id']); + self::assertSame(3, $record->context['bookings_deleted']); + } + + public function testASignInAndASignOutAreBothRecordedAgainstTheAccount(): void + { + $this->audit->signedIn($this->user()); + $this->audit->signedOut($this->user()); + + $records = $this->handler->getRecords(); + + self::assertSame('User signed in.', $records[0]->message); + self::assertSame('holder@ep-reisen.de', $records[0]->context['account']); + self::assertSame('User signed out.', $records[1]->message); + self::assertSame('holder@ep-reisen.de', $records[1]->context['account']); + } + + private function record(): LogRecord + { + return $this->handler->getRecords()[0]; + } + + private function booking(): Booking + { + return new Booking( + $this->user(), + $this->resource(), + new \DateTimeImmutable('2026-09-18'), + TimeRange::fromMinutes(540, 780), + ); + } + + private function user(): User + { + return new User('holder@ep-reisen.de', 'Holder'); + } + + private function resource(): Resource + { + return new Resource(ResourceType::DESK, 'D1'); + } +}