From 783a9a3c84230b7448922ec131c448074b4c6058 Mon Sep 17 00:00:00 2001 From: Kay Joosten Date: Wed, 5 Aug 2026 11:12:21 +0200 Subject: [PATCH 1/5] Show deprovisioning event and date in the audit log Why is this change needed? Prior to this change, deprovisioning an identity via the lifecycle API left no trace in the audit log. AuditLogProjector explicitly skipped writing an entry for IdentityForgottenEvent, so RA(A)s had no way to see that, or when, an identity had been deprovisioned. How does it address the issue? This change maps IdentityForgottenEvent to a new 'deprovisioned' audit log action and reorders AuditLogProjector::handle() so the deprovisioning entry is persisted before the identity's other audit log entries are anonymized; otherwise the newly created entry would be wiped immediately after. A projector test covers both the new entry and the existing anonymization behavior. Provide links to any relevant tickets, articles or other resources https://github.com/OpenConext/Stepup-RA/issues/423 --- .../Identity/Entity/AuditLogEntry.php | 2 + .../Identity/Projector/AuditLogProjector.php | 5 +- .../Projector/AuditLogProjectorTest.php | 62 +++++++++++++++++++ 3 files changed, 68 insertions(+), 1 deletion(-) diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Entity/AuditLogEntry.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Entity/AuditLogEntry.php index 2edfa0e0..1da3fe7e 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Entity/AuditLogEntry.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Entity/AuditLogEntry.php @@ -38,6 +38,7 @@ use Surfnet\Stepup\Identity\Event\IdentityAccreditedAsRaForInstitutionEvent; use Surfnet\Stepup\Identity\Event\IdentityCreatedEvent; use Surfnet\Stepup\Identity\Event\IdentityEmailChangedEvent; +use Surfnet\Stepup\Identity\Event\IdentityForgottenEvent; use Surfnet\Stepup\Identity\Event\IdentityRenamedEvent; use Surfnet\Stepup\Identity\Event\PhonePossessionProvenAndVerifiedEvent; use Surfnet\Stepup\Identity\Event\PhonePossessionProvenEvent; @@ -87,6 +88,7 @@ class AuditLogEntry implements JsonSerializable GssfPossessionProvenAndVerifiedEvent::class => 'possession_proven', IdentityCreatedEvent::class => 'created', IdentityEmailChangedEvent::class => 'email_changed', + IdentityForgottenEvent::class => 'deprovisioned', IdentityRenamedEvent::class => 'renamed', PhonePossessionProvenEvent::class => 'possession_proven', PhonePossessionProvenAndVerifiedEvent::class => 'possession_proven', diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php index eba995b3..3d94437e 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php @@ -62,7 +62,10 @@ public function handle(DomainMessage $domainMessage): void switch (true) { case $event instanceof IdentityForgottenEvent: - // Don't insert the IdentityForgottenEvent into the audit log, as we'd remove it immediately afterwards. + // Record the deprovisioning itself first, then anonymise the identity's other audit log + // entries. Anonymising first would immediately wipe the actor name off the entry we're + // about to create here. + $this->applyAuditableEvent($event, $domainMessage); $this->applyIdentityForgottenEvent($event); break; // Finally apply the auditable event, most events are auditable this so first handle the unique variants diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php index fb3d8f2a..221f1e92 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php @@ -31,6 +31,7 @@ use PHPUnit\Framework\TestCase; use Surfnet\Stepup\DateTime\DateTime as StepupDateTime; use Surfnet\Stepup\Identity\AuditLog\Metadata; +use Surfnet\Stepup\Identity\Event\IdentityForgottenEvent; use Surfnet\Stepup\Identity\Value\CommonName; use Surfnet\Stepup\Identity\Value\IdentityId; use Surfnet\Stepup\Identity\Value\Institution; @@ -167,6 +168,67 @@ public function it_creates_entries_for_auditable_events(DomainMessage $message, $this->assertEquals($expectedEntry, $actualEntry); } + #[Test] + #[Group('api-projector')] + public function it_creates_a_deprovisioned_entry_and_anonymizes_the_identitys_other_entries(): void + { + $identityId = new IdentityId('abcd'); + $institution = new Institution('efgh'); + + $existingEntry = new AuditLogEntry(); + $existingEntry->id = 'existing-entry'; + $existingEntry->identityId = $identityId; + $existingEntry->identityInstitution = $institution; + $existingEntry->actorCommonName = new CommonName(self::$actorCommonName); + $existingEntry->event = 'SomeEarlierEvent'; + $existingEntry->recordedOn = new StepupDateTime(new CoreDateTime('1970-01-01H00:00:00.000')); + + $entryWhereIdentityIsActor = new AuditLogEntry(); + $entryWhereIdentityIsActor->id = 'actor-entry'; + $entryWhereIdentityIsActor->identityId = new IdentityId('some-other-identity'); + $entryWhereIdentityIsActor->identityInstitution = $institution; + $entryWhereIdentityIsActor->actorId = $identityId; + $entryWhereIdentityIsActor->actorCommonName = new CommonName(self::$actorCommonName); + $entryWhereIdentityIsActor->event = 'SomeEarlierEvent'; + $entryWhereIdentityIsActor->recordedOn = new StepupDateTime(new CoreDateTime('1970-01-01H00:00:00.000')); + + $repository = m::mock(AuditLogRepository::class); + + $newEntry = null; + $repository->shouldReceive('save')->once()->with($this->spy($newEntry)); + /** @var null|AuditLogEntry $newEntry */ + + $repository->shouldReceive('findByIdentityId')->once()->with($identityId)->andReturn([$existingEntry]); + $repository->shouldReceive('findEntriesWhereIdentityIsActorOnly')->once()->with($identityId) + ->andReturn([$entryWhereIdentityIsActor]); + $repository->shouldReceive('saveAll')->once()->with([$existingEntry]); + $repository->shouldReceive('saveAll')->once()->with([$entryWhereIdentityIsActor]); + + $identityRepository = m::mock(IdentityRepository::class); + + $projector = new AuditLogProjector($repository, $identityRepository); + + $message = new DomainMessage( + 'id', + 0, + new MessageMetadata(), + new IdentityForgottenEvent($identityId, $institution), + BroadwayDateTime::fromString('1970-01-01H00:00:00.000'), + ); + + $projector->handle($message); + + // A new "deprovisioned" audit log entry must have been created for the identity. + $this->assertNotNull($newEntry); + $this->assertSame((string)$identityId, $newEntry->identityId); + $this->assertSame($institution, $newEntry->identityInstitution); + $this->assertSame(IdentityForgottenEvent::class, $newEntry->event); + + // Pre-existing entries for the identity must still be anonymized, same as before this change. + $this->assertEquals(CommonName::unknown(), $existingEntry->actorCommonName); + $this->assertEquals(CommonName::unknown(), $entryWhereIdentityIsActor->actorCommonName); + } + private function createAuditLogMetadata( IdentityId $identityId, Institution $institution, From 15a31b25b06d03eaf07065a2ff890885b6f721be Mon Sep 17 00:00:00 2001 From: Kay Joosten Date: Mon, 10 Aug 2026 13:14:08 +0200 Subject: [PATCH 2/5] Include deprovisioned entries in the RA audit log query Why is this change needed? IdentityForgottenEvent was mapped to a new 'deprovisioned' audit log action and persisted, but AuditLogRepository::createSecondFactorSearchQuery() filters entries against an event allowlist that never included it, so the new entry was written but silently filtered out of the RA audit log page. Separately, the comment justifying the projector's insert-before-anonymise ordering had the mechanism backwards, and the projector test mocked findByIdentityId() to omit the just-inserted entry, so it couldn't have caught either issue. How does it address the issue? Adds IdentityForgottenEvent::class to the allowlist so the entry is actually returned to the RA UI. Corrects the ordering comment: inserting before anonymising means the new entry is included in the same anonymisation pass as the identity's other entries (its actor name gets wiped like everything else), not preserved as the old comment claimed. Updates the test to mock findByIdentityId() the way the real repository behaves (returning the freshly flushed entry alongside the pre-existing one), and asserts the new entry's actor name is anonymised too. Provide links to any relevant tickets, articles or other resources https://github.com/OpenConext/Stepup-RA/issues/423 --- .../Identity/Projector/AuditLogProjector.php | 7 ++++--- .../Identity/Repository/AuditLogRepository.php | 2 ++ .../Projector/AuditLogProjectorTest.php | 17 +++++++++++++++-- 3 files changed, 21 insertions(+), 5 deletions(-) diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php index 3d94437e..af16ce5e 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php @@ -62,9 +62,10 @@ public function handle(DomainMessage $domainMessage): void switch (true) { case $event instanceof IdentityForgottenEvent: - // Record the deprovisioning itself first, then anonymise the identity's other audit log - // entries. Anonymising first would immediately wipe the actor name off the entry we're - // about to create here. + // Record the deprovisioning entry first so applyIdentityForgottenEvent's re-query of + // findByIdentityId() picks it up too, anonymising its actor name along with the + // identity's other entries. Anonymising first would query before this entry exists, + // leaving its actor name (typically the deprovisioning system/API actor) untouched. $this->applyAuditableEvent($event, $domainMessage); $this->applyIdentityForgottenEvent($event); break; diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php index 2315844f..22ad8ace 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php @@ -36,6 +36,7 @@ use Surfnet\Stepup\Identity\Event\IdentityAccreditedAsRaaForInstitutionEvent; use Surfnet\Stepup\Identity\Event\IdentityAccreditedAsRaEvent; use Surfnet\Stepup\Identity\Event\IdentityAccreditedAsRaForInstitutionEvent; +use Surfnet\Stepup\Identity\Event\IdentityForgottenEvent; use Surfnet\Stepup\Identity\Event\PhonePossessionProvenAndVerifiedEvent; use Surfnet\Stepup\Identity\Event\PhonePossessionProvenEvent; use Surfnet\Stepup\Identity\Event\PhoneRecoveryTokenPossessionProvenEvent; @@ -104,6 +105,7 @@ public function __construct(ManagerRegistry $registry) RecoveryTokenRevokedEvent::class, PhoneRecoveryTokenPossessionProvenEvent::class, CompliedWithRecoveryCodeRevocationEvent::class, + IdentityForgottenEvent::class, ]; /** diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php index 221f1e92..5b355e13 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php @@ -198,10 +198,19 @@ public function it_creates_a_deprovisioned_entry_and_anonymizes_the_identitys_ot $repository->shouldReceive('save')->once()->with($this->spy($newEntry)); /** @var null|AuditLogEntry $newEntry */ - $repository->shouldReceive('findByIdentityId')->once()->with($identityId)->andReturn([$existingEntry]); + // The new entry is flushed (AuditLogRepository::save() flushes immediately) before this is + // called, so a real findByIdentityId() re-query picks it up alongside the pre-existing entry. + $repository->shouldReceive('findByIdentityId')->once()->with($identityId) + ->andReturnUsing(function () use ($existingEntry, &$newEntry): array { + return [$existingEntry, $newEntry]; + }); $repository->shouldReceive('findEntriesWhereIdentityIsActorOnly')->once()->with($identityId) ->andReturn([$entryWhereIdentityIsActor]); - $repository->shouldReceive('saveAll')->once()->with([$existingEntry]); + $repository->shouldReceive('saveAll')->once()->with( + m::on(function (array $entries) use ($existingEntry, &$newEntry): bool { + return $entries === [$existingEntry, $newEntry]; + }), + ); $repository->shouldReceive('saveAll')->once()->with([$entryWhereIdentityIsActor]); $identityRepository = m::mock(IdentityRepository::class); @@ -227,6 +236,10 @@ public function it_creates_a_deprovisioned_entry_and_anonymizes_the_identitys_ot // Pre-existing entries for the identity must still be anonymized, same as before this change. $this->assertEquals(CommonName::unknown(), $existingEntry->actorCommonName); $this->assertEquals(CommonName::unknown(), $entryWhereIdentityIsActor->actorCommonName); + + // The new "deprovisioned" entry is swept up by the same anonymization pass, since it belongs + // to the identity being forgotten. + $this->assertEquals(CommonName::unknown(), $newEntry->actorCommonName); } private function createAuditLogMetadata( From 3ad99dd6571808caac35438d527672f10349d59a Mon Sep 17 00:00:00 2001 From: Kay Joosten Date: Mon, 7 Sep 2026 14:10:16 +0200 Subject: [PATCH 3/5] Add dedicated command to backfill deprovisioned audit log entries Deprovisioning (IdentityForgottenEvent) was added to the audit log after the fact, so identities forgotten before that change have no 'deprovisioned' entry. The retroactive backfill cannot go through stepup:event:replay + AuditLogProjector: replaying IdentityForgottenEvent also re-runs applyIdentityForgottenEvent(), which anonymises every current audit log entry for the identity - and an identity forgotten, then restored (UpdateIdentityCommand calls Identity::restore()), then active again would have its live audit log scrubbed. stepup:audit-log:backfill-deprovisioned reads IdentityForgottenEvents from the event store and inserts only the missing entries, without any anonymisation: - AuditLogRepository::hasDeprovisionedEntry() keys on identity + event + recordedOn (second precision; a restore has to happen between two forgets so they cannot share a second), and an in-run key guards against re-inserting within a single batch - so the command is idempotent and safe to run more than once. - Entries are persisted in batches of 500 with the entity manager cleared between them, keeping memory flat over a large event set. - A confirmation prompt (bypass with --force or --no-interaction) warns to disable the lifecycle API first: the check and insert are not atomic with AuditLogProjector, so a deprovisioning projected live during the run could otherwise be inserted twice. - --dry-run reports what it would create. --- .../Repository/AuditLogRepository.php | 23 ++ ...illDeprovisionedAuditLogEntriesCommand.php | 228 ++++++++++++++++++ .../Resources/config/console_commands.yml | 6 + ...eprovisionedAuditLogEntriesCommandTest.php | 200 +++++++++++++++ .../ConsoleCommandRegistrationTest.php | 3 + 5 files changed, 460 insertions(+) create mode 100644 src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php create mode 100644 src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/Command/BackfillDeprovisionedAuditLogEntriesCommandTest.php diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php index 22ad8ace..a3568aeb 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Repository/AuditLogRepository.php @@ -21,6 +21,7 @@ use Doctrine\Bundle\DoctrineBundle\Repository\ServiceEntityRepository; use Doctrine\ORM\Query; use Doctrine\Persistence\ManagerRegistry; +use Surfnet\Stepup\DateTime\DateTime; use Surfnet\Stepup\Identity\Event\AppointedAsRaaEvent; use Surfnet\Stepup\Identity\Event\AppointedAsRaaForInstitutionEvent; use Surfnet\Stepup\Identity\Event\AppointedAsRaEvent; @@ -54,6 +55,7 @@ use Surfnet\Stepup\Identity\Event\YubikeyPossessionProvenAndVerifiedEvent; use Surfnet\Stepup\Identity\Event\YubikeySecondFactorBootstrappedEvent; use Surfnet\Stepup\Identity\Value\IdentityId; +use Surfnet\StepupMiddleware\ApiBundle\Doctrine\Type\DateTimeType; use Surfnet\StepupMiddleware\ApiBundle\Exception\RuntimeException; use Surfnet\StepupMiddleware\ApiBundle\Identity\Entity\AuditLogEntry; use Surfnet\StepupMiddleware\ApiBundle\Identity\Query\SecondFactorAuditLogQuery; @@ -166,6 +168,27 @@ public function findByIdentityId(IdentityId $identityId): array ->getResult(); } + /** + * Whether an audit log entry already exists for the given identity, event FQCN and moment. + * + * Used by the deprovisioned-entry backfill to stay idempotent. recordedOn is stored with + * second precision, and an identity cannot be forgotten twice within the same second (a + * restore has to happen in between), so this uniquely identifies a single deprovisioning. + */ + public function hasDeprovisionedEntry(IdentityId $identityId, string $event, DateTime $recordedOn): bool + { + return (int)$this->createQueryBuilder('al') + ->select('COUNT(al.id)') + ->where('al.identityId = :identityId') + ->andWhere('al.event = :event') + ->andWhere('al.recordedOn = :recordedOn') + ->setParameter('identityId', $identityId) + ->setParameter('event', $event) + ->setParameter('recordedOn', $recordedOn, DateTimeType::NAME) + ->getQuery() + ->getSingleScalarResult() > 0; + } + public function save(AuditLogEntry $entry): void { $entityManager = $this->getEntityManager(); diff --git a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php new file mode 100644 index 00000000..d48f4836 --- /dev/null +++ b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php @@ -0,0 +1,228 @@ + Identity::restore()) has to happen between two forgets, so the existence + * check keying on identity + event + second-precision recordedOn uniquely identifies one + * deprovisioning. In-memory the events are still distinguished by playhead, so two same-second + * events in one run are both created. + * + * The whole set of IdentityForgottenEvents is read up front (it is bounded by the number of identities + * ever deprovisioned); the resulting audit log entries are written in batches with the entity manager + * cleared between them. + */ +#[AsCommand( + name: 'stepup:audit-log:backfill-deprovisioned', + description: 'Creates the missing "deprovisioned" audit log entries for identities forgotten before ' + . 'the deprovisioning action was recorded. Idempotent.' +)] +final class BackfillDeprovisionedAuditLogEntriesCommand +{ + private const BATCH_SIZE = 500; + + public function __construct( + private readonly DBALEventHydrator $eventHydrator, + private readonly AuditLogRepository $auditLogRepository, + private readonly ManagerRegistry $managerRegistry, + ) { + } + + public function __invoke( + InputInterface $input, + OutputInterface $output, + #[Option(description: 'Report what would be created without writing anything', name: 'dry-run')] + bool $dryRun = false, + #[Option(description: 'Skip the confirmation prompt', name: 'force')] + bool $force = false, + ): int { + if (!$dryRun && !$force && $input->isInteractive()) { + $question = new ConfirmationQuestion( + 'Run this only with the lifecycle (deprovisioning) API access disabled, to avoid ' + . 'duplicate entries from concurrent live projection. Continue? (y/N) ', + false, + ); + + if (!(new QuestionHelper())->ask($input, $output, $question)) { + $output->writeln('Aborted.'); + + return 1; + } + } + + // Phase 1: every distinct deprovisioning occurrence, keyed by aggregate id + playhead so a + // second IdentityForgottenEvent (after a restore) is never merged with the first. + $occurrences = $this->collectDeprovisioningOccurrences(); + + // Phase 2: keep only the occurrences that have no audit log entry yet. All lookups happen + // before any insert, so two occurrences that fall in the same second are both kept. + $missing = array_values(array_filter( + $occurrences, + fn(array $occurrence): bool => !$this->auditLogRepository->hasDeprovisionedEntry( + $occurrence['identityId'], + IdentityForgottenEvent::class, + $occurrence['recordedOn'], + ), + )); + + foreach ($missing as $occurrence) { + $output->writeln( + sprintf( + '%s deprovisioned entry for identity %s (%s) recorded on %s', + $dryRun ? 'Would create' : 'Creating', + $occurrence['identityId'], + $occurrence['institution'], + $occurrence['recordedOn']->format(DateTime::FORMAT), + ), + OutputInterface::VERBOSITY_VERBOSE, + ); + } + + if (!$dryRun && $missing !== []) { + try { + $this->persistInBatches($missing); + } catch (Throwable $e) { + $output->writeln(sprintf('Backfill failed: %s', $e->getMessage())); + + return 1; + } + } + + $output->writeln( + sprintf( + '%s: %d deprovisioned %s %s, %d already present', + $dryRun ? 'Dry run' : 'Done', + count($missing), + count($missing) === 1 ? 'entry' : 'entries', + $dryRun ? 'would be created' : 'created', + count($occurrences) - count($missing), + ), + ); + + return 0; + } + + /** + * @return array + */ + private function collectDeprovisioningOccurrences(): array + { + $eventStreamType = strtr(IdentityForgottenEvent::class, '\\', '.'); + $events = $this->eventHydrator->fetchByEventTypes([$eventStreamType]); + + $occurrences = []; + + foreach ($events->getIterator() as $domainMessage) { + /** @var DomainMessage $domainMessage */ + $event = $domainMessage->getPayload(); + + if (!$event instanceof IdentityForgottenEvent) { + continue; + } + + $key = $domainMessage->getId() . '|' . $domainMessage->getPlayhead(); + $occurrences[$key] = [ + 'identityId' => $event->identityId, + 'institution' => $event->identityInstitution, + 'recordedOn' => new DateTime(new CoreDateTime($domainMessage->getRecordedOn()->toString())), + ]; + } + + return $occurrences; + } + + /** + * @param array $missing + */ + private function persistInBatches(array $missing): void + { + $entityManager = $this->entityManager(); + + $entityManager->wrapInTransaction(static function () use ($entityManager, $missing): void { + foreach (array_chunk($missing, self::BATCH_SIZE) as $chunk) { + foreach ($chunk as $occurrence) { + $entry = new AuditLogEntry(); + $entry->id = (string)Uuid::uuid4(); + $entry->identityId = (string)$occurrence['identityId']; + $entry->identityInstitution = $occurrence['institution']; + $entry->actorCommonName = CommonName::unknown(); + $entry->event = IdentityForgottenEvent::class; + $entry->recordedOn = $occurrence['recordedOn']; + + $entityManager->persist($entry); + } + + $entityManager->flush(); + $entityManager->clear(); + } + }); + } + + private function entityManager(): EntityManagerInterface + { + $manager = $this->managerRegistry->getManagerForClass(AuditLogEntry::class); + + if (!$manager instanceof EntityManagerInterface) { + throw new RuntimeException('No entity manager configured for AuditLogEntry'); + } + + return $manager; + } +} diff --git a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Resources/config/console_commands.yml b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Resources/config/console_commands.yml index 14b92d16..0f70f1ff 100644 --- a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Resources/config/console_commands.yml +++ b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Resources/config/console_commands.yml @@ -68,3 +68,9 @@ services: arguments: - '@Surfnet\StepupMiddleware\MiddlewareBundle\Service\BootstrapCommandService' - '@Surfnet\StepupMiddleware\MiddlewareBundle\Service\TransactionHelper' + + Surfnet\StepupMiddleware\MiddlewareBundle\Console\Command\BackfillDeprovisionedAuditLogEntriesCommand: + arguments: + - "@middleware.event_replay.dbal_event_hydrator" + - "@surfnet_stepup_middleware_api.repository.audit_log" + - "@doctrine" diff --git a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/Command/BackfillDeprovisionedAuditLogEntriesCommandTest.php b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/Command/BackfillDeprovisionedAuditLogEntriesCommandTest.php new file mode 100644 index 00000000..faf54761 --- /dev/null +++ b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/Command/BackfillDeprovisionedAuditLogEntriesCommandTest.php @@ -0,0 +1,200 @@ +eventHydrator = m::mock(DBALEventHydrator::class); + $this->auditLogRepository = m::mock(AuditLogRepository::class); + $this->entityManager = m::mock(EntityManagerInterface::class); + + $registry = m::mock(ManagerRegistry::class); + $registry->shouldReceive('getManagerForClass')->with(AuditLogEntry::class)->andReturn($this->entityManager); + $this->entityManager->shouldReceive('wrapInTransaction')->andReturnUsing(fn(callable $cb) => $cb()); + + $this->commandTester = new CommandTester( + new BackfillDeprovisionedAuditLogEntriesCommand($this->eventHydrator, $this->auditLogRepository, $registry), + ); + } + + #[Test] + public function it_creates_a_missing_entry_and_skips_one_that_already_exists(): void + { + $forgottenWithoutEntry = new IdentityId('11111111-1111-1111-1111-111111111111'); + $forgottenWithEntry = new IdentityId('22222222-2222-2222-2222-222222222222'); + $institution = new Institution('institution-a.example'); + + $this->eventHydrator->shouldReceive('fetchByEventTypes') + ->once() + ->with(['Surfnet.Stepup.Identity.Event.IdentityForgottenEvent']) + ->andReturn(new DomainEventStream([ + $this->forgottenMessage($forgottenWithoutEntry, $institution, 0, '2020-01-01T10:00:00.000000'), + $this->forgottenMessage($forgottenWithEntry, $institution, 0, '2021-06-15T12:30:00.000000'), + ])); + + $this->auditLogRepository->shouldReceive('hasDeprovisionedEntry') + ->once()->with($forgottenWithoutEntry, IdentityForgottenEvent::class, m::any())->andReturnFalse(); + $this->auditLogRepository->shouldReceive('hasDeprovisionedEntry') + ->once()->with($forgottenWithEntry, IdentityForgottenEvent::class, m::any())->andReturnTrue(); + + $persisted = []; + $this->entityManager->shouldReceive('persist')->once() + ->with(m::on(function (AuditLogEntry $entry) use (&$persisted): bool { + $persisted[] = $entry; + return true; + })); + $this->entityManager->shouldReceive('flush')->once(); + $this->entityManager->shouldReceive('clear')->once(); + + $exitCode = $this->commandTester->execute(['--force' => true]); + + $this->assertSame(0, $exitCode); + $this->assertCount(1, $persisted); + $this->assertSame((string)$forgottenWithoutEntry, $persisted[0]->identityId); + $this->assertSame($institution, $persisted[0]->identityInstitution); + $this->assertSame(IdentityForgottenEvent::class, $persisted[0]->event); + $this->assertStringContainsString('1 deprovisioned entry created, 1 already present', $this->commandTester->getDisplay()); + } + + #[Test] + public function it_keeps_two_forgotten_events_in_the_same_second_as_distinct_entries(): void + { + $identityId = new IdentityId('55555555-5555-5555-5555-555555555555'); + $institution = new Institution('institution-d.example'); + + // Forgotten, restored, forgotten again - two events, same second, different playheads. + $this->eventHydrator->shouldReceive('fetchByEventTypes')->once()->andReturn(new DomainEventStream([ + $this->forgottenMessage($identityId, $institution, 3, '2020-01-01T10:00:00.100000'), + $this->forgottenMessage($identityId, $institution, 7, '2020-01-01T10:00:00.900000'), + ])); + + $this->auditLogRepository->shouldReceive('hasDeprovisionedEntry')->twice()->andReturnFalse(); + + $this->entityManager->shouldReceive('persist')->twice(); + $this->entityManager->shouldReceive('flush')->once(); + $this->entityManager->shouldReceive('clear')->once(); + + $exitCode = $this->commandTester->execute(['--force' => true]); + + $this->assertSame(0, $exitCode); + $this->assertStringContainsString('2 deprovisioned entries created, 0 already present', $this->commandTester->getDisplay()); + } + + #[Test] + public function it_deduplicates_the_same_event_occurrence_seen_twice(): void + { + $identityId = new IdentityId('66666666-6666-6666-6666-666666666666'); + $institution = new Institution('institution-e.example'); + + $message = $this->forgottenMessage($identityId, $institution, 2, '2020-02-02T11:11:11.000000'); + + $this->eventHydrator->shouldReceive('fetchByEventTypes')->once() + ->andReturn(new DomainEventStream([$message, $message])); + + $this->auditLogRepository->shouldReceive('hasDeprovisionedEntry')->once()->andReturnFalse(); + + $this->entityManager->shouldReceive('persist')->once(); + $this->entityManager->shouldReceive('flush')->once(); + $this->entityManager->shouldReceive('clear')->once(); + + $exitCode = $this->commandTester->execute(['--force' => true]); + + $this->assertSame(0, $exitCode); + $this->assertStringContainsString('1 deprovisioned entry created, 0 already present', $this->commandTester->getDisplay()); + } + + #[Test] + public function dry_run_reports_the_same_count_it_would_write(): void + { + $identityId = new IdentityId('55555555-5555-5555-5555-555555555555'); + $institution = new Institution('institution-d.example'); + + $this->eventHydrator->shouldReceive('fetchByEventTypes')->once()->andReturn(new DomainEventStream([ + $this->forgottenMessage($identityId, $institution, 3, '2020-01-01T10:00:00.100000'), + $this->forgottenMessage($identityId, $institution, 7, '2020-01-01T10:00:00.900000'), + ])); + + $this->auditLogRepository->shouldReceive('hasDeprovisionedEntry')->twice()->andReturnFalse(); + $this->entityManager->shouldNotReceive('persist'); + $this->entityManager->shouldNotReceive('flush'); + + $exitCode = $this->commandTester->execute(['--dry-run' => true]); + + $this->assertSame(0, $exitCode); + $this->assertStringContainsString('Dry run: 2 deprovisioned entries would be created', $this->commandTester->getDisplay()); + } + + #[Test] + public function it_aborts_when_the_confirmation_is_declined(): void + { + $this->eventHydrator->shouldNotReceive('fetchByEventTypes'); + + $this->commandTester->setInputs(['no']); + $exitCode = $this->commandTester->execute([]); + + $this->assertSame(1, $exitCode); + $this->assertStringContainsString('Aborted.', $this->commandTester->getDisplay()); + } + + private function forgottenMessage( + IdentityId $identityId, + Institution $institution, + int $playhead, + string $recordedOn, + ): DomainMessage { + return new DomainMessage( + (string)$identityId, + $playhead, + new Metadata([]), + new IdentityForgottenEvent($identityId, $institution), + BroadwayDateTime::fromString($recordedOn), + ); + } +} diff --git a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/ConsoleCommandRegistrationTest.php b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/ConsoleCommandRegistrationTest.php index 78d9d0b2..69f6d7d8 100644 --- a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/ConsoleCommandRegistrationTest.php +++ b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Tests/Console/ConsoleCommandRegistrationTest.php @@ -74,6 +74,9 @@ public static function consoleCommandProvider(): array 'EmailVerifiedSecondFactorRemindersCommand' => [ 'commandName' => 'middleware:cron:email-reminder', ], + 'BackfillDeprovisionedAuditLogEntriesCommand' => [ + 'commandName' => 'stepup:audit-log:backfill-deprovisioned', + ], ]; } From c8346232c438e71c83019bacc27017112f9b57de Mon Sep 17 00:00:00 2001 From: Kay Joosten Date: Tue, 8 Sep 2026 15:19:39 +0200 Subject: [PATCH 4/5] Make deprovisioned audit projection idempotent --- .../Identity/Projector/AuditLogProjector.php | 19 ++++-- .../Projector/AuditLogProjectorTest.php | 64 +++++++++++++++++++ 2 files changed, 79 insertions(+), 4 deletions(-) diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php index af16ce5e..0fea04dd 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Identity/Projector/AuditLogProjector.php @@ -63,9 +63,9 @@ public function handle(DomainMessage $domainMessage): void switch (true) { case $event instanceof IdentityForgottenEvent: // Record the deprovisioning entry first so applyIdentityForgottenEvent's re-query of - // findByIdentityId() picks it up too, anonymising its actor name along with the - // identity's other entries. Anonymising first would query before this entry exists, - // leaving its actor name (typically the deprovisioning system/API actor) untouched. + // findByIdentityId() picks it up too. The actor name is intentionally anonymized, + // consistent with all other entries for a forgotten identity. Anonymizing first + // would query before this entry exists, leaving its actor name untouched. $this->applyAuditableEvent($event, $domainMessage); $this->applyIdentityForgottenEvent($event); break; @@ -83,6 +83,17 @@ public function handle(DomainMessage $domainMessage): void private function applyAuditableEvent(AuditableEvent $event, DomainMessage $domainMessage): void { $auditLogMetadata = $event->getAuditLogMetadata(); + $recordedOn = new DateTime(new CoreDateTime($domainMessage->getRecordedOn()->toString())); + + if ($event instanceof IdentityForgottenEvent + && $this->auditLogRepository->hasDeprovisionedEntry( + $auditLogMetadata->identityId, + $event::class, + $recordedOn, + ) + ) { + return; + } $metadata = $domainMessage->getMetadata()->serialize(); $entry = new AuditLogEntry(); @@ -113,7 +124,7 @@ private function applyAuditableEvent(AuditableEvent $event, DomainMessage $domai $entry->identityId = (string)$auditLogMetadata->identityId; $entry->identityInstitution = $auditLogMetadata->identityInstitution; $entry->event = $event::class; - $entry->recordedOn = new DateTime(new CoreDateTime($domainMessage->getRecordedOn()->toString())); + $entry->recordedOn = $recordedOn; if ($auditLogMetadata->secondFactorId instanceof SecondFactorId) { $entry->secondFactorId = (string)$auditLogMetadata->secondFactorId; diff --git a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php index 5b355e13..135cb149 100644 --- a/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php +++ b/src/Surfnet/StepupMiddleware/ApiBundle/Tests/Identity/Projector/AuditLogProjectorTest.php @@ -195,6 +195,14 @@ public function it_creates_a_deprovisioned_entry_and_anonymizes_the_identitys_ot $repository = m::mock(AuditLogRepository::class); $newEntry = null; + $repository->shouldReceive('hasDeprovisionedEntry') + ->once() + ->with( + $identityId, + IdentityForgottenEvent::class, + m::on(fn(StepupDateTime $actual): bool => $actual == new StepupDateTime(new CoreDateTime('1970-01-01H00:00:00.000'))), + ) + ->andReturnFalse(); $repository->shouldReceive('save')->once()->with($this->spy($newEntry)); /** @var null|AuditLogEntry $newEntry */ @@ -242,6 +250,62 @@ public function it_creates_a_deprovisioned_entry_and_anonymizes_the_identitys_ot $this->assertEquals(CommonName::unknown(), $newEntry->actorCommonName); } + #[Test] + #[Group('api-projector')] + public function it_skips_creating_a_duplicate_deprovisioned_entry_but_still_anonymizes_existing_entries(): void + { + $identityId = new IdentityId('abcd'); + $institution = new Institution('efgh'); + $recordedOn = new StepupDateTime(new CoreDateTime('1970-01-01H00:00:00.000')); + + $existingEntry = new AuditLogEntry(); + $existingEntry->id = 'existing-entry'; + $existingEntry->identityId = $identityId; + $existingEntry->identityInstitution = $institution; + $existingEntry->actorCommonName = new CommonName(self::$actorCommonName); + $existingEntry->event = IdentityForgottenEvent::class; + $existingEntry->recordedOn = $recordedOn; + + $entryWhereIdentityIsActor = new AuditLogEntry(); + $entryWhereIdentityIsActor->id = 'actor-entry'; + $entryWhereIdentityIsActor->identityId = new IdentityId('some-other-identity'); + $entryWhereIdentityIsActor->identityInstitution = $institution; + $entryWhereIdentityIsActor->actorId = $identityId; + $entryWhereIdentityIsActor->actorCommonName = new CommonName(self::$actorCommonName); + $entryWhereIdentityIsActor->event = 'SomeEarlierEvent'; + $entryWhereIdentityIsActor->recordedOn = $recordedOn; + + $repository = m::mock(AuditLogRepository::class); + $repository->shouldReceive('hasDeprovisionedEntry') + ->once() + ->with( + $identityId, + IdentityForgottenEvent::class, + m::on(fn(StepupDateTime $actual): bool => $actual == $recordedOn), + ) + ->andReturnTrue(); + $repository->shouldNotReceive('save'); + $repository->shouldReceive('findByIdentityId')->once()->with($identityId)->andReturn([$existingEntry]); + $repository->shouldReceive('findEntriesWhereIdentityIsActorOnly')->once()->with($identityId) + ->andReturn([$entryWhereIdentityIsActor]); + $repository->shouldReceive('saveAll')->once()->with([$existingEntry]); + $repository->shouldReceive('saveAll')->once()->with([$entryWhereIdentityIsActor]); + + $identityRepository = m::mock(IdentityRepository::class); + + $projector = new AuditLogProjector($repository, $identityRepository); + $projector->handle(new DomainMessage( + 'id', + 0, + new MessageMetadata(), + new IdentityForgottenEvent($identityId, $institution), + BroadwayDateTime::fromString('1970-01-01H00:00:00.000'), + )); + + $this->assertEquals(CommonName::unknown(), $existingEntry->actorCommonName); + $this->assertEquals(CommonName::unknown(), $entryWhereIdentityIsActor->actorCommonName); + } + private function createAuditLogMetadata( IdentityId $identityId, Institution $institution, From 4f34fa159ef8403715a607e0c3848ac131fffbb3 Mon Sep 17 00:00:00 2001 From: Kay Joosten Date: Tue, 8 Sep 2026 15:19:42 +0200 Subject: [PATCH 5/5] Refactor deprovisioned backfill command --- ...illDeprovisionedAuditLogEntriesCommand.php | 169 ++++++++++++------ 1 file changed, 118 insertions(+), 51 deletions(-) diff --git a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php index d48f4836..b4bcb6b5 100644 --- a/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php +++ b/src/Surfnet/StepupMiddleware/MiddlewareBundle/Console/Command/BackfillDeprovisionedAuditLogEntriesCommand.php @@ -68,6 +68,8 @@ * The whole set of IdentityForgottenEvents is read up front (it is bounded by the number of identities * ever deprovisioned); the resulting audit log entries are written in batches with the entity manager * cleared between them. + * + * @SuppressWarnings("PHPMD.CouplingBetweenObjects") */ #[AsCommand( name: 'stepup:audit-log:backfill-deprovisioned', @@ -93,27 +95,83 @@ public function __invoke( #[Option(description: 'Skip the confirmation prompt', name: 'force')] bool $force = false, ): int { - if (!$dryRun && !$force && $input->isInteractive()) { - $question = new ConfirmationQuestion( - 'Run this only with the lifecycle (deprovisioning) API access disabled, to avoid ' - . 'duplicate entries from concurrent live projection. Continue? (y/N) ', - false, - ); + if ($this->shouldAbort($input, $output, $dryRun, $force)) { + return 1; + } - if (!(new QuestionHelper())->ask($input, $output, $question)) { - $output->writeln('Aborted.'); + $occurrences = $this->collectDeprovisioningOccurrences(); + $missing = $this->findMissingOccurrences($occurrences); - return 1; - } - } + $this->reportMissingOccurrences($output, $missing, $dryRun); + return $this->finishBackfill($output, $occurrences, $missing, $dryRun); + } + + /** + * @return array + */ + private function collectDeprovisioningOccurrences(): array + { // Phase 1: every distinct deprovisioning occurrence, keyed by aggregate id + playhead so a // second IdentityForgottenEvent (after a restore) is never merged with the first. - $occurrences = $this->collectDeprovisioningOccurrences(); + $eventStreamType = strtr(IdentityForgottenEvent::class, '\\', '.'); + $events = $this->eventHydrator->fetchByEventTypes([$eventStreamType]); + + $occurrences = []; + + foreach ($events->getIterator() as $domainMessage) { + /** @var DomainMessage $domainMessage */ + $event = $domainMessage->getPayload(); + + if (!$event instanceof IdentityForgottenEvent) { + continue; + } + + $key = $domainMessage->getId() . '|' . $domainMessage->getPlayhead(); + $occurrences[$key] = [ + 'identityId' => $event->identityId, + 'institution' => $event->identityInstitution, + 'recordedOn' => new DateTime(new CoreDateTime($domainMessage->getRecordedOn()->toString())), + ]; + } + + return $occurrences; + } + + private function shouldAbort( + InputInterface $input, + OutputInterface $output, + bool $dryRun, + bool $force, + ): bool { + if ($dryRun || $force || !$input->isInteractive()) { + return false; + } + + $question = new ConfirmationQuestion( + 'Run this only with the lifecycle (deprovisioning) API access disabled, to avoid ' + . 'duplicate entries from concurrent live projection. Continue? (y/N) ', + false, + ); + + if ((new QuestionHelper())->ask($input, $output, $question)) { + return false; + } + + $output->writeln('Aborted.'); + return true; + } + + /** + * @param array $occurrences + * @return list + */ + private function findMissingOccurrences(array $occurrences): array + { // Phase 2: keep only the occurrences that have no audit log entry yet. All lookups happen // before any insert, so two occurrences that fall in the same second are both kept. - $missing = array_values(array_filter( + return array_values(array_filter( $occurrences, fn(array $occurrence): bool => !$this->auditLogRepository->hasDeprovisionedEntry( $occurrence['identityId'], @@ -121,7 +179,13 @@ public function __invoke( $occurrence['recordedOn'], ), )); + } + /** + * @param list $missing + */ + private function reportMissingOccurrences(OutputInterface $output, array $missing, bool $dryRun): void + { foreach ($missing as $occurrence) { $output->writeln( sprintf( @@ -134,58 +198,61 @@ public function __invoke( OutputInterface::VERBOSITY_VERBOSE, ); } + } - if (!$dryRun && $missing !== []) { - try { - $this->persistInBatches($missing); - } catch (Throwable $e) { - $output->writeln(sprintf('Backfill failed: %s', $e->getMessage())); - - return 1; - } + /** + * @param array $occurrences + * @param list $missing + */ + private function finishBackfill( + OutputInterface $output, + array $occurrences, + array $missing, + bool $dryRun, + ): int { + if (!$this->persistMissingOccurrences($output, $missing, $dryRun)) { + return 1; } - $output->writeln( - sprintf( - '%s: %d deprovisioned %s %s, %d already present', - $dryRun ? 'Dry run' : 'Done', - count($missing), - count($missing) === 1 ? 'entry' : 'entries', - $dryRun ? 'would be created' : 'created', - count($occurrences) - count($missing), - ), - ); + $output->writeln($this->summary($occurrences, $missing, $dryRun)); return 0; } /** - * @return array + * @param list $missing */ - private function collectDeprovisioningOccurrences(): array + private function persistMissingOccurrences(OutputInterface $output, array $missing, bool $dryRun): bool { - $eventStreamType = strtr(IdentityForgottenEvent::class, '\\', '.'); - $events = $this->eventHydrator->fetchByEventTypes([$eventStreamType]); - - $occurrences = []; + if ($dryRun || $missing === []) { + return true; + } - foreach ($events->getIterator() as $domainMessage) { - /** @var DomainMessage $domainMessage */ - $event = $domainMessage->getPayload(); + try { + $this->persistInBatches($missing); + } catch (Throwable $e) { + $output->writeln(sprintf('Backfill failed: %s', $e->getMessage())); - if (!$event instanceof IdentityForgottenEvent) { - continue; - } - - $key = $domainMessage->getId() . '|' . $domainMessage->getPlayhead(); - $occurrences[$key] = [ - 'identityId' => $event->identityId, - 'institution' => $event->identityInstitution, - 'recordedOn' => new DateTime(new CoreDateTime($domainMessage->getRecordedOn()->toString())), - ]; + return false; } - return $occurrences; + return true; + } + + /** + * @param array $occurrences + * @param list $missing + */ + private function summary(array $occurrences, array $missing, bool $dryRun): string + { + return sprintf( + '%s: %d deprovisioned %s %s, %d already present', + $dryRun ? 'Dry run' : 'Done', + count($missing), + count($missing) === 1 ? 'entry' : 'entries', + $dryRun ? 'would be created' : 'created', + count($occurrences) - count($missing), + ); } /**