search

spring-projects / spring-modulith

Modular applications with Spring Boot
https://spring.io/projects/spring-modulith
Apache License 2.0
788 stars 132 forks source link

Clarify ordering guarantees out externalized events #415

Open gunnarmorling opened 9 months ago

gunnarmorling commented 9 months ago

Hi, I am trying to understand the ordering guarantees of externalized events, in particular whether it is guaranteed that two events originating from two concurrent requests are sent to Kafka (or whatever message broker is used) in the exact same order as the database transactions are committed? This is vital for ensuring a consistent state across the database and the Kafka event consumers. Are the transaction listeners used for sending the message somehow synchronized? Thanks for any clarifications!

matiwinnetou commented 6 months ago

From what I see there is out of order processing at least for internal events, I have a proof right here:

2024-03-19T10:06:45.064+01:00  INFO 77510 --- [sk-executor-817] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:977c6018241ca4d2b25a9ec1b241be6d0197b350014e1e946a4e1133508bd989, status:STARTED, seq:1
2024-03-19T10:06:45.065+01:00  INFO 77510 --- [sk-executor-819] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:834be5d70408401f20208ccae23a240755de4b42f9ea58e827d8928b5caed2ee, status:STARTED, seq:3
2024-03-19T10:06:45.067+01:00  INFO 77510 --- [sk-executor-820] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:1fb6d54ceaeda9186fdcce17e751e711a65ae81e3a262e4f484376bf56a55776, status:STARTED, seq:4
2024-03-19T10:06:45.073+01:00  INFO 77510 --- [sk-executor-821] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:14ed2744fb5cfbf77894deea7aa00cbc3cf3b2149ea6e27e0b3dc21faec08af2, status:STARTED, seq:5
2024-03-19T10:06:45.093+01:00  INFO 77510 --- [sk-executor-822] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:7a4ffc82b2ae6828fccd898e32a84c818162f729d44c6fb0c8c2f423308cce35, status:STARTED, seq:6
2024-03-19T10:06:45.118+01:00  INFO 77510 --- [sk-executor-823] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:1b2e6aaf665e943da10a228611edc31584b2a4688ebf80015f0b7488b5c76c12, status:STARTED, seq:7
2024-03-19T10:06:45.140+01:00  INFO 77510 --- [sk-executor-824] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:a074a83167c55c549abcc741dd4ff579e36e98b3e22536f903b4965305192744, status:STARTED, seq:8
2024-03-19T10:06:45.178+01:00  INFO 77510 --- [sk-executor-825] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:ab60eeccac1178616efd9b54b2add8aa480636d49e85daacc0160bbfe14d85aa, status:STARTED, seq:9
2024-03-19T10:06:45.201+01:00  INFO 77510 --- [sk-executor-826] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:a68cbcbb71f82792ebf643a0ecf4327ad43e7af3971b6d7e55d247a771424f84, status:STARTED, seq:10
2024-03-19T10:06:45.216+01:00  INFO 77510 --- [sk-executor-829] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:e58520c546986a4723ef99c9eefbb30cb390e6e3caf8b81a06978f4bc4316abd, status:STARTED, seq:13
2024-03-19T10:06:45.221+01:00  INFO 77510 --- [sk-executor-830] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:806a7606a1d08fe65014866bb044688d74981428626f9a268f71ba523a5f0b98, status:STARTED, seq:14
2024-03-19T10:06:45.225+01:00  INFO 77510 --- [sk-executor-833] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:bc54d1576290c3f19432bce3519c9d2f854814f8f8b6970cb1593eaae5ee3bf4, status:STARTED, seq:17
2024-03-19T10:06:45.226+01:00  INFO 77510 --- [sk-executor-834] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:2c0938908c20ab1994bee0b713fce20bf2bea7bfff3d5475eb7ead6388ce92ef, status:STARTED, seq:18
2024-03-19T10:06:45.230+01:00  INFO 77510 --- [sk-executor-835] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:cde62775ea7b4987b56b9312054dad18c2a5cf5b6ef6270331b58b98cd5bb379, status:STARTED, seq:19
2024-03-19T10:06:45.286+01:00  INFO 77510 --- [sk-executor-839] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:9f2641d10be2d00107fbb0975f6f29ee5e261455ecd305f9f215d09fa59e32db, status:STARTED, seq:23
2024-03-19T10:06:45.396+01:00  INFO 77510 --- [sk-executor-838] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:455d0d8e99c701267354c1da6ad832238ad411b8bf0e45260b97c0b35496be42, status:STARTED, seq:22
2024-03-19T10:06:45.397+01:00  INFO 77510 --- [sk-executor-836] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:36a4de70240fe6cf1fd946f8f17722017bd05821e7ba2382cf7300627e600164, status:STARTED, seq:20
2024-03-19T10:06:45.413+01:00  INFO 77510 --- [sk-executor-827] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:20f0c63138874ad0e11749c2f945cc41bf931e095a990b6957057c1dae9ab633, status:STARTED, seq:11
2024-03-19T10:06:45.413+01:00  INFO 77510 --- [sk-executor-828] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:f95869f010c8a9c680304fbd19b034bcad9917e4155b71a38ae4a9cb3a4c3e34, status:STARTED, seq:12
2024-03-19T10:06:45.434+01:00  INFO 77510 --- [sk-executor-832] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:42a9288b6d195bd78a80106a58b9cb76f31c1ef35c25d163a5fec2f4414f0966, status:STARTED, seq:16
2024-03-19T10:06:45.441+01:00  INFO 77510 --- [sk-executor-837] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:51a3789cec4690ff31c2f9746ec6c8d21f6c13fca1aceedef3f701ab63aa9d9a, status:STARTED, seq:21
2024-03-19T10:06:45.450+01:00  INFO 77510 --- [sk-executor-840] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:454ba9c73ded8bc85daf15fc9da3cdb7c85ecf6a1eedb2c6a0517c7dc137b8ee, status:FINISHED, seq:24
2024-03-19T10:06:45.456+01:00  INFO 77510 --- [sk-executor-818] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:8cd93f65836ad6a33358b7dda0a6c3b59196679e9507320ea7cd53674a456fb3, status:STARTED, seq:2
2024-03-19T10:06:45.502+01:00  INFO 77510 --- [sk-executor-831] o.c.l.a.a.s.i.AccountingCoreEventHandler : Received handleERPIngestionEvent event...., event, batch_id:196a01af9ab8576ce7750e560c181e9067a2b52835926fbefa55b038a0da1390, chunk_id:1e11aa2a415692f700c9d0642dd2d87506d093e3d47718d375771bcaf9cc6a61, status:STARTED, seq:15

so as you can see "FINISHED" arrives sometimes before it is really finished. It makes sense as this is @ApplicationModuleListener with Async annotation.