search

eventuate-tram / eventuate-tram-sagas

Sagas for microservices
Other
1k stars 228 forks source link

Investigate flakey test: shouldReject #89

Open cer opened 2 years ago

cer commented 2 years ago

repeated failures:

https://app.circleci.com/pipelines/github/eventuate-tram/eventuate-tram-sagas/116/workflows/cde3d011-1e42-4b78-867d-407f2ed8a57e/jobs/582

io.eventuate.examples.tram.sagas.ordersandcustomers.spring.reactive.integrationtests.CustomersAndOrdersIntegrationTest

io.eventuate.util.test.async.EventuallyException: Failed after 60 iterations every 500 milliseconds
    at io.eventuate.util.test.async.Eventually.eventuallyReturning(Eventually.java:70)
    at io.eventuate.util.test.async.Eventually.eventually(Eventually.java:37)
    at io.eventuate.util.test.async.Eventually.eventually(Eventually.java:33)
    at io.eventuate.examples.tram.sagas.ordersandcustomers.spring.reactive.integrationtests.CustomersAndOrdersIntegrationTest.assertOrderState(CustomersAndOrdersIntegrationTest.java:83)
    at io.eventuate.examples.tram.sagas.ordersandcustomers.spring.reactive.integrationtests.CustomersAndOrdersIntegrationTest.shouldReject(CustomersAndOrdersIntegrationTest.java:65)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.springframework.test.context.junit4.statements.RunBeforeTestExecutionCallbacks.evaluate(RunBeforeTestExecutionCallbacks.java:74)
    at org.springframework.test.context.junit4.statements.RunAfterTestExecutionCallbacks.evaluate(RunAfterTestExecutionCallbacks.java:84)
    at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:75)
    at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
    at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:251)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:97)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:190)
    at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110)
    at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
    at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
    at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62)
    at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
    at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
    at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:119)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
    at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
    at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:414)
    at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
    at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.junit.ComparisonFailure: expected:<[REJECTED]> but was:<[PENDING]>
    at org.junit.Assert.assertEquals(Assert.java:115)
    at org.junit.Assert.assertEquals(Assert.java:144)
    at io.eventuate.examples.tram.sagas.ordersandcustomers.spring.reactive.integrationtests.CustomersAndOrdersIntegrationTest.lambda$assertOrderState$0(CustomersAndOrdersIntegrationTest.java:86)
    at io.eventuate.util.test.async.Eventually.lambda$eventually$0(Eventually.java:38)
    at io.eventuate.util.test.async.Eventually.eventuallyReturning(Eventually.java:59)
    ... 59 more
cer commented 2 years ago

See https://gist.github.com/cer/0d10de182a7608e710de110697ad5a25

cer commented 2 years ago

The test creates customers:

CustomerID=10
CustomerID=8

but the failing command handler:

 Customer not found: 1665003257045

This looks like currentTimeMillis():

 new java.util.Date(1665003257045L)
$1 ==> Wed Oct 05 13:54:17 PDT 2022
cer commented 2 years ago

TODO - investigate failing builds with additional logging: https://app.circleci.com/pipelines/github/eventuate-tram/eventuate-tram-sagas/120/workflows/ed95176f-143f-4619-99f9-40cc584ab305/jobs/619

cer commented 2 years ago

Here is a test run:

I think it took a long time for Kafka consumer to initialize - waiting to be assigned partition?

2022-10-08 19:50:23.603  INFO 9340 --- [    Test worker] .s.r.i.CustomersAndOrdersIntegrationTest : Started CustomersAndOrdersIntegrationTest in 3.184 seconds (JVM running for 4.169)
2022-10-08 19:50:24.670  INFO 9340 --- [    Test worker] .s.r.i.CustomersAndOrdersIntegrationTest : shouldReject CustomerID=8
...

2022-10-08 19:50:24.941  INFO 9340 --- [tor-tcp-epoll-3] i.e.e.t.s.o.s.r.o.s.CreateOrderSaga      : saga createOrder() with ID=9

....

2022-10-08 19:51:01.604  INFO 9340 --- [tor-tcp-epoll-3] e.e.t.s.o.s.r.c.s.CustomerCommandHandler : reserveCredit OrderId=9, CustomerID=8

2022-10-08 19:51:01.696  INFO 9340 --- [tor-tcp-epoll-3] e.e.t.s.o.s.r.c.s.CustomerCommandHandler : reservedCredit CustomerCreditLimitExceededException OrderId=9, CustomerID=8
2022-10-08 19:51:01.880  INFO 9340 --- [    Test worker] s.r.o.ReactiveSagaInstanceRepositoryJdbc : Saving io.eventuate.examples.tram.sagas.ordersandcustomers.spring.reactive.orders.service.CreateOrderSaga 00000183b926a7f8-0665749bf0590000