Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Investigate flakey test: shouldReject #89

Open
cer opened this issue Oct 5, 2022 · 4 comments
Open

Investigate flakey test: shouldReject #89

cer opened this issue Oct 5, 2022 · 4 comments

Comments

@cer
Copy link
Collaborator

cer commented Oct 5, 2022 •
edited
Loading

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
Copy link
Collaborator Author

cer commented Oct 5, 2022

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

cer added a commit that referenced this issue Oct 5, 2022
@cer
Investigate flakey test: shouldReject #89
ab01082
cer added a commit that referenced this issue Oct 5, 2022
@cer
Investigate flakey test: shouldReject #89
96f2ac3
@cer
Copy link
Collaborator Author

cer commented Oct 6, 2022

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 added a commit that referenced this issue Oct 6, 2022
@cer
Investigate flakey test: shouldReject #89
7bf9840
@cer
Copy link
Collaborator Author

cer commented Oct 6, 2022

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
Copy link
Collaborator Author

cer commented Oct 8, 2022

Here is a test run:

  • 19:50:24.941 - order created
  • 19:51:01.604 - command handler invoked

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

cer added a commit that referenced this issue Oct 8, 2022
@cer
Investigate flakey test: shouldReject #89 - increased Eventually time.
ad240b7
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@cer