From e0624eace0f967f003ca838213896860583975b0 Mon Sep 17 00:00:00 2001 From: matthieu Date: Wed, 22 Apr 2026 19:34:22 +0200 Subject: [PATCH] fix(audit-log) : reset pendingLogs sur onFlush + valide filtres + documente contrat rollback MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Trois corrections issues du code review multi-agent sur la PR audit-log : - AuditListener : reset defensif de pendingLogs en debut de onFlush. Si un flush precedent a leve une exception avant postFlush (qui n'est jamais appele sur un flush rate), le state listener gardait des changements jamais committes, ecrits a tort par le prochain postFlush reussi — audit_log pouvait donc contenir des lignes decrivant des evenements qui n'ont pas eu lieu en DB. Test de regression via Reflection pour injecter un log orphelin et verifier qu'il n'arrive pas dans audit_log. - AuditLogProvider : validation explicite des filtres performed_at[after] et performed_at[before] (strtotime) + whitelist stricte sur `action` (create|update|delete). Avant, un input malforme remontait jusqu'a Postgres et faisait un 500 (SQLSTATE[22007]). Desormais 400 explicite, pas de log pollue. - doc/audit-log.md : ajoute une section "Contrat" qui explicite ce que audit_log garantit (journal des intentions appliquees par l'ORM) et ne garantit PAS (reflet exact du commit outermost — une ligne audit peut persister si une transaction outermost rollback apres un flush inner reussi, parce que l'audit ecrit sur une connexion DBAL dediee). Co-Authored-By: Claude Opus 4.7 (1M context) --- doc/audit-log.md | 13 +++++ .../State/Provider/AuditLogProvider.php | 35 ++++++++++-- .../Infrastructure/Doctrine/AuditListener.php | 8 +++ tests/Module/Core/Api/AuditLogApiTest.php | 21 +++++++ .../Doctrine/AuditListenerTest.php | 56 +++++++++++++++++++ 5 files changed, 127 insertions(+), 6 deletions(-) diff --git a/doc/audit-log.md b/doc/audit-log.md index 7838048..4dad029 100644 --- a/doc/audit-log.md +++ b/doc/audit-log.md @@ -89,6 +89,19 @@ Table non geree par Doctrine ORM (pas d'entite). Ecriture via DBAL uniquement po - **`performed_by` denormalise** : string, pas FK — le nom persiste meme si l'utilisateur est supprime - **Migration** : dans `migrations/` (namespace racine `DoctrineMigrations`) a cause du bug de tri alphabetique FQCN de Doctrine Migrations 3.x entre namespaces +### Contrat : ce que `audit_log` garantit (et ne garantit pas) + +`audit_log` enregistre les **tentatives de modification** capturees par le `postFlush` Doctrine, ecrites via une connexion DBAL dediee (`audit_connection`). Ce choix est intentionnel : les lignes d'audit survivent au rollback eventuel de la transaction metier principale, ce qui permet de tracer les tentatives meme en cas d'echec applicatif. + +**Conséquence à connaître** : si un controller enveloppe plusieurs operations dans une transaction explicite sur la connexion `default` et que cette transaction outermost rollback apres un flush intermediaire reussi, la ligne audit correspondante **persiste** sur la connexion `audit` alors que la modification metier a ete annulee. L'audit log peut donc contenir des lignes decrivant un etat qui n'existe pas en base metier. + +En pratique : +- Ce cas est rare dans un CRM interne (les rollbacks explicites outermost sont marginaux par rapport aux flushes atomiques). +- La ligne audit garde son `request_id` qui permet une correlation post-mortem avec les logs applicatifs pour distinguer une tentative avortee d'un commit reussi. +- Le comportement est volontaire — pas un bug. Pour un besoin de garantie « audit = reflet exact du commit outermost », il faudrait basculer l'audit sur la meme connexion que le metier (voir `AuditLogWriter`), au prix de perdre la resilience au rollback partiel. + +L'audit est donc un **journal des intentions appliquees par l'ORM**, pas une source de verite transactionnelle sur l'etat final de la DB. + --- ## Composants backend diff --git a/src/Module/Core/Infrastructure/ApiPlatform/State/Provider/AuditLogProvider.php b/src/Module/Core/Infrastructure/ApiPlatform/State/Provider/AuditLogProvider.php index e5fd16c..cc69e85 100644 --- a/src/Module/Core/Infrastructure/ApiPlatform/State/Provider/AuditLogProvider.php +++ b/src/Module/Core/Infrastructure/ApiPlatform/State/Provider/AuditLogProvider.php @@ -15,6 +15,7 @@ use Doctrine\DBAL\ArrayParameterType; use Doctrine\DBAL\Connection; use Doctrine\DBAL\Query\QueryBuilder; use Symfony\Component\DependencyInjection\Attribute\Autowire; +use Symfony\Component\HttpKernel\Exception\BadRequestHttpException; /** * Provider API Platform pour la resource AuditLog. @@ -128,20 +129,42 @@ final readonly class AuditLogProvider implements ProviderInterface } } - foreach (['entity_id', 'action', 'performed_by'] as $key) { + foreach (['entity_id', 'performed_by'] as $key) { if (isset($raw[$key]) && is_string($raw[$key]) && '' !== $raw[$key]) { $filters[$key] = $raw[$key]; } } + // `action` : whitelist stricte. Un input hors-liste provoquait avant + // un simple match vide (resultat 0 ligne) mais permettait d'incrementer + // le log applicatif a chaque variation ; on rejette en 400 explicite. + if (isset($raw['action']) && is_string($raw['action']) && '' !== $raw['action']) { + if (!in_array($raw['action'], ['create', 'update', 'delete'], true)) { + throw new BadRequestHttpException( + 'Filtre "action" invalide : valeurs autorisees create|update|delete.', + ); + } + $filters['action'] = $raw['action']; + } + // Filtres de plage `performed_at[after]` / `performed_at[before]`. + // Sans validation, un input malforme remonte jusqu'a Postgres qui + // leve `SQLSTATE[22007]: invalid input syntax for type timestamp` → + // 500 Internal Server Error, log Monolog pollue, mauvaise UX API. + // On valide en amont et on rejette en 400 explicite. if (isset($raw['performed_at']) && is_array($raw['performed_at'])) { $range = $raw['performed_at']; - if (isset($range['after']) && is_string($range['after']) && '' !== $range['after']) { - $filters['performed_at_after'] = $range['after']; - } - if (isset($range['before']) && is_string($range['before']) && '' !== $range['before']) { - $filters['performed_at_before'] = $range['before']; + foreach (['after', 'before'] as $bound) { + if (!isset($range[$bound]) || !is_string($range[$bound]) || '' === $range[$bound]) { + continue; + } + if (false === strtotime($range[$bound])) { + throw new BadRequestHttpException(sprintf( + 'Filtre "performed_at[%s]" invalide : date ISO 8601 attendue (ex: 2026-04-22T00:00:00Z).', + $bound, + )); + } + $filters['performed_at_'.$bound] = $range[$bound]; } } diff --git a/src/Module/Core/Infrastructure/Doctrine/AuditListener.php b/src/Module/Core/Infrastructure/Doctrine/AuditListener.php index 98b302f..c478cda 100644 --- a/src/Module/Core/Infrastructure/Doctrine/AuditListener.php +++ b/src/Module/Core/Infrastructure/Doctrine/AuditListener.php @@ -102,6 +102,14 @@ final class AuditListener $em = $args->getObjectManager(); $uow = $em->getUnitOfWork(); + // Reset defensif en debut de cycle : si un flush precedent a leve une + // exception, Doctrine n'appelle PAS postFlush et pendingLogs reste + // rempli avec des changements jamais committes. Sans ce reset, un + // flush ulterieur reussi ecrirait les fausses entrees dans audit_log. + // Le swap-and-clear dans postFlush couvre deja les flushes re-entrants, + // ce reset ne le fragilise donc pas. + $this->pendingLogs = []; + foreach ($uow->getScheduledEntityInsertions() as $entity) { $this->capturePendingLog($entity, $em, $uow, 'create'); } diff --git a/tests/Module/Core/Api/AuditLogApiTest.php b/tests/Module/Core/Api/AuditLogApiTest.php index a0e82f7..869da99 100644 --- a/tests/Module/Core/Api/AuditLogApiTest.php +++ b/tests/Module/Core/Api/AuditLogApiTest.php @@ -188,6 +188,27 @@ final class AuditLogApiTest extends AbstractApiTestCase self::assertSame($row['id'], $data['id']); } + /** + * Validation des filtres : un input malforme doit retourner un 400 + * explicite, pas un 500 (Postgres qui rejette le cast timestamp) ni + * un match silencieux sur une valeur inattendue. + */ + public function testInvalidPerformedAtFilterReturns400(): void + { + $client = $this->authenticatedClient('admin', 'admin'); + $response = $client->request('GET', '/api/audit-logs?performed_at[after]=pas-une-date'); + + self::assertSame(400, $response->getStatusCode()); + } + + public function testInvalidActionFilterReturns400(): void + { + $client = $this->authenticatedClient('admin', 'admin'); + $response = $client->request('GET', '/api/audit-logs?action=dropTable'); + + self::assertSame(400, $response->getStatusCode()); + } + public function testPostIsNotAllowed(): void { $client = $this->authenticatedClient('admin', 'admin'); diff --git a/tests/Module/Core/Infrastructure/Doctrine/AuditListenerTest.php b/tests/Module/Core/Infrastructure/Doctrine/AuditListenerTest.php index 8f16cce..d705710 100644 --- a/tests/Module/Core/Infrastructure/Doctrine/AuditListenerTest.php +++ b/tests/Module/Core/Infrastructure/Doctrine/AuditListenerTest.php @@ -7,8 +7,11 @@ namespace App\Tests\Module\Core\Infrastructure\Doctrine; use App\Module\Core\Domain\Entity\Permission; use App\Module\Core\Domain\Entity\Role; use App\Module\Core\Domain\Entity\User; +use App\Module\Core\Infrastructure\Doctrine\AuditListener; use Doctrine\DBAL\Connection; use Doctrine\ORM\EntityManagerInterface; +use ReflectionProperty; +use stdClass; use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase; use Symfony\Component\PasswordHasher\Hasher\UserPasswordHasherInterface; @@ -328,6 +331,59 @@ final class AuditListenerTest extends KernelTestCase ); } + /** + * Regression : quand un flush precedent a leve une exception avant + * d'atteindre postFlush, `$pendingLogs` reste rempli avec des changements + * jamais committes. Le flush suivant doit les ecraser, pas les fusionner — + * sinon audit_log contient des lignes pour des evenements qui n'ont pas + * eu lieu en base. + * + * Reproduction : on injecte manuellement une entree orpheline dans le + * listener (comme si un flush precedent l'avait capturee puis avait plante), + * on declenche un flush valide, et on verifie que l'orpheline n'apparait + * jamais dans audit_log. + */ + public function testOnFlushResetsStalePendingLogsFromFailedPreviousFlush(): void + { + /** @var AuditListener $listener */ + $listener = self::getContainer()->get(AuditListener::class); + + // Injecte une entree orpheline : comme si onFlush avait capture ce + // changement, puis que le flush avait plante avant postFlush. + $reflection = new ReflectionProperty($listener, 'pendingLogs'); + $reflection->setValue($listener, [[ + 'entity' => new stdClass(), + 'metadata' => null, + 'entityType' => 'test.StaleEntity', + 'action' => 'create', + 'changes' => ['fake' => ['old' => null, 'new' => 'stale']], + 'capturedId' => 'stale-id-'.$this->testRunTag, + ]]); + + // Flush valide qui DOIT re-initialiser pendingLogs avant de capturer + // ses propres changements. + $user = $this->makeUser(); + $this->em->persist($user); + $this->em->flush(); + $this->createdUserIds[] = $user->getId(); + + $staleRows = $this->auditConnection->fetchAllAssociative( + 'SELECT * FROM audit_log WHERE entity_type = :t', + ['t' => 'test.StaleEntity'], + ); + + self::assertCount( + 0, + $staleRows, + 'Une entree orpheline d\'un flush precedent ne doit pas fuiter dans audit_log.', + ); + + // Sanity : le vrai flush a quand meme bien ecrit sa propre ligne. + $userRows = $this->fetchAuditRows($user->getId()); + self::assertCount(1, $userRows); + self::assertSame('create', $userRows[0]['action']); + } + /** * @return list */