RemoteInfinispanSessionDataStoreTest.testSavePeriodDirtySession is flaky

[lorban]

Jetty version(s)
12.1.x

Jetty Environment
EE9

Description
org.eclipse.jetty.ee9.session.infinispan.remote.RemoteInfinispanSessionDataStoreTest.testSavePeriodDirtySession() fails with:

org.infinispan.client.hotrod.exceptions.HotRodClientException:Request for messageId=55 returned server error (status=0x85): org.infinispan.commons.CacheConfigurationException: ISPN000436: Cache 'RemoteInfinispanSessionDataStoreTest319340114473317' has been requested, but no matching cache configuration exists
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096)
	at org.infinispan.client.hotrod.impl.Util.await(Util.java:52)
	at org.infinispan.client.hotrod.impl.RemoteCacheManagerAdminImpl.getOrCreateCache(RemoteCacheManagerAdminImpl.java:90)
	at org.eclipse.jetty.session.test.tools.RemoteInfinispanTestSupport.<init>(RemoteInfinispanTestSupport.java:133)
	at org.eclipse.jetty.ee9.session.infinispan.remote.RemoteInfinispanSessionDataStoreTest.<init>(RemoteInfinispanSessionDataStoreTest.java:60)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486)
	at java.base/java.util.Optional.orElseGet(Optional.java:364)
	at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:507)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.tryRemoveAndExec(ForkJoinPool.java:1534)
	at java.base/java.util.concurrent.ForkJoinPool.helpJoin(ForkJoinPool.java:2269)
	at java.base/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:495)
	at java.base/java.util.concurrent.ForkJoinTask.join(ForkJoinTask.java:662)
	at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:507)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1491)
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:2073)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2035)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)

See:

• https://jenkins.webtide.net/job/jetty.project/job/jetty-12.1.x/190/testReport/junit/org.eclipse.jetty.ee9.session.infinispan.remote/RemoteInfinispanSessionDataStoreTest/Parallel_Stage___Build___Test___JDK22___testSavePeriodDirtySession/
• https://jenkins.webtide.net/job/jetty.project/job/jetty-12.1.x/197/testReport/junit/org.eclipse.jetty.ee9.session.infinispan.remote/RemoteInfinispanSessionDataStoreTest/Parallel_Stage___Build___Test___JDK23___testSavePeriodDirtySession_2/

[janbartel]

@olamy why are there so many RemoteInfinispanSessionDataStoreTests with different contexts on this log trace? Shouldn't there be only a single test active in this docker instance?

215529 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,011 INFO  [o.i.LIFECYCLE] [Context=RemoteInfinispanSessionDataStoreTest319340012368609][Scope=69e413f63cf2-17930]ISPN100002: Starting rebalance with members [69e413f63cf2-17930, 6a2ed80012af-18503, 4488a2a7b8ae-42568], phase READ_OLD_WRITE_ALL, topology id 6&amp#27;[m
215531 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,013 INFO  [o.i.LIFECYCLE] [Context=RemoteInfinispanSessionDataStoreTest319340012368609][Scope=69e413f63cf2-17930]ISPN100010: Finished rebalance with members [69e413f63cf2-17930, 6a2ed80012af-18503, 4488a2a7b8ae-42568], topology id 6&amp#27;[m
215543 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,025 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340012368609]ISPN100009: Advancing to rebalance phase READ_ALL_WRITE_ALL, topology id 7&amp#27;[m
215546 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,028 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340012368609]ISPN100009: Advancing to rebalance phase READ_NEW_WRITE_ALL, topology id 8&amp#27;[m
215548 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,031 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340012368609]ISPN100010: Finished rebalance with members [69e413f63cf2-17930, 6a2ed80012af-18503, 4488a2a7b8ae-42568], topology id 9&amp#27;[m
215568 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,050 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340114473317]ISPN100002: Starting rebalance with members [4488a2a7b8ae-42568, 6a2ed80012af-18503], phase READ_OLD_WRITE_ALL, topology id 2&amp#27;[m
215586 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,069 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340114473317]ISPN100009: Advancing to rebalance phase READ_ALL_WRITE_ALL, topology id 3&amp#27;[m
215591 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,074 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340114473317]ISPN100009: Advancing to rebalance phase READ_NEW_WRITE_ALL, topology id 4&amp#27;[m
215594 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,077 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340114473317]ISPN100010: Finished rebalance with members [4488a2a7b8ae-42568, 6a2ed80012af-18503], topology id 5&amp#27;[m
215633 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,114 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340176631229]ISPN100002: Starting rebalance with members [6a2ed80012af-18503, 4488a2a7b8ae-42568], phase READ_OLD_WRITE_ALL, topology id 2&amp#27;[m
215634 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,115 ERROR [o.i.s.h.BaseRequestProcessor] ISPN005003: Exception reported org.infinispan.commons.CacheConfigurationException: ISPN000436: Cache 'RemoteInfinispanSessionDataStoreTest319340114473317' has been requested, but no matching cache configuration exists
WARN: ISPN004005: Error received from the server: org.infinispan.commons.CacheConfigurationException: ISPN000436: Cache 'RemoteInfinispanSessionDataStoreTest319340114473317' has been requested, but no matching cache configuration exists
215641 [HotRod-client-async-pool-1-3] WARN org.infinispan.HOTROD - ISPN004005: Error received from the server: org.infinispan.commons.CacheConfigurationException: ISPN000436: Cache 'RemoteInfinispanSessionDataStoreTest319340114473317' has been requested, but no matching cache configuration exists
215643 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,125 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340183084404]ISPN100002: Starting rebalance with members [6a2ed80012af-18503, 69e413f63cf2-17930], phase READ_OLD_WRITE_ALL, topology id 2&amp#27;[m
215644 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,127 INFO  [o.i.LIFECYCLE] [Context=RemoteInfinispanSessionDataStoreTest319340183084404][Scope=69e413f63cf2-17930]ISPN100002: Starting rebalance with members [6a2ed80012af-18503, 69e413f63cf2-17930], phase READ_OLD_WRITE_ALL, topology id 2&amp#27;[m
215646 [docker-java-stream-2117145189] INFO org.eclipse.jetty.server.session.remote.infinispanLogs - STDOUT: 2024-09-20 15:52:07,128 INFO  [o.i.CLUSTER] [Context=RemoteInfinispanSessionDataStoreTest319340176631229]ISPN100009: Advancing to rebalance phase READ_ALL_WRITE_ALL, topology id 3&amp#27;[m

I'm attaching the full log file for your convenience.
log.txt

[olamy]

@janbartel how do you get those logs?
Running locally doesn't generate those logs with using

mvn clean install  -pl :jetty-ee9-test-sessions-infinispan -Dmaven.build.cache.enabled=false

[janbartel]

@olamy no magic, it's on the Jenkins output from the failures that @lorban linked above.

[olamy]

@olamy why are there so many RemoteInfinispanSessionDataStoreTests with different contexts on this log trace? Shouldn't there be only a single test active in this docker instance?

no Infinispan instance is started only once and reused for all tests in parallel.
So multiple tests (max 2 in parallel) can use same Infinispan at the same time, that's why every single test uses a cache name such as this getClass().getSimpleName() + System.nanoTime() to avoid any collision.

Maybe we could simply use UUID.randomUUID().toString() as cache name. but that's probably not the problem.

My concern is more about Infinispan API, as we are using _manager.administration().getOrCreateCache, which is supposed to (if I'm correctly understanding English) always return something (a new cache if not exist), but this one does not in fact.
I will dig into the infinispan code.

[janbartel]

See #12338