Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #11032

lhotari · 2021-06-23T05:42:57Z

ZKSessionTest is flaky. The testReacquireLeadershipAfterSessionLost test method fails sporadically.

Error:  Tests run: 6, Failures: 1, Errors: 0, Skipped: 4, Time elapsed: 31.46 s <<< FAILURE! - in org.apache.pulsar.metadata.ZKSessionTest
Error:  testReacquireLeadershipAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 15.396 s  <<< FAILURE!
org.awaitility.core.ConditionTimeoutException: Assertion condition defined as a lambda expression in org.apache.pulsar.metadata.ZKSessionTest that uses org.apache.pulsar.metadata.api.coordination.LeaderElection expected [Leading] but found [NoLeader] within 10 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:165)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:119)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:31)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:895)
	at org.awaitility.core.ConditionFactory.untilAsserted(ConditionFactory.java:679)
	at org.apache.pulsar.metadata.ZKSessionTest.testReacquireLeadershipAfterSessionLost(ZKSessionTest.java:174)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.AssertionError: expected [Leading] but found [NoLeader]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
	at org.testng.Assert.assertEquals(Assert.java:122)
	at org.testng.Assert.assertEquals(Assert.java:617)
	at org.apache.pulsar.metadata.ZKSessionTest.lambda$testReacquireLeadershipAfterSessionLost$1(ZKSessionTest.java:175)
	at org.awaitility.core.AssertionCondition.lambda$new$0(AssertionCondition.java:53)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:222)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:209)
	... 4 more

The text was updated successfully, but these errors were encountered:

lhotari · 2021-06-23T05:46:39Z

Another exception in the same test

Error:  Tests run: 6, Failures: 1, Errors: 0, Skipped: 4, Time elapsed: 17.285 s <<< FAILURE! - in org.apache.pulsar.metadata.ZKSessionTest
Error:  testReacquireLeadershipAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 3.037 s  <<< FAILURE!
java.lang.AssertionError: expected [null] but found [NoLeader]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotSame(Assert.java:1033)
	at org.testng.Assert.assertNull(Assert.java:965)
	at org.testng.Assert.assertNull(Assert.java:953)
	at org.apache.pulsar.metadata.ZKSessionTest.testReacquireLeadershipAfterSessionLost(ZKSessionTest.java:179)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)

lhotari · 2021-06-23T21:24:51Z

another failure in testReacquireLocksAfterSessionLost method

Error:  Tests run: 6, Failures: 1, Errors: 0, Skipped: 3, Time elapsed: 75.825 s <<< FAILURE! - in org.apache.pulsar.metadata.ZKSessionTest
Error:  testReacquireLocksAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 24.543 s  <<< FAILURE!
java.util.concurrent.CompletionException: org.apache.pulsar.metadata.api.MetadataStoreException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /key-1455163628288
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
	at java.base/java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:777)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$storeDelete$21(ZKMetadataStore.java:277)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.apache.pulsar.metadata.api.MetadataStoreException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /key-1455163628288
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.getException(ZKMetadataStore.java:314)
	... 5 more
Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /key-1455163628288
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:134)
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.getException(ZKMetadataStore.java:304)
	... 5 more

mattisonchao · 2021-06-24T03:21:17Z

I want to fix it. :)

Fixes #11032 #11143 Master Issue: #11032 #11143 Motivation In some cases, testing errors occurred due to Zookeeper's notification delay. Modifications Waiting async notice until timeout.

lhotari · 2021-08-24T11:21:04Z

This test remains flaky. Reopening this issue

Here's a recent failure:

Error:  testReacquireLocksAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 17.782 s  <<< FAILURE!
org.awaitility.core.ConditionTimeoutException: Assertion condition defined as a lambda expression in org.apache.pulsar.metadata.ZKSessionTest that uses org.apache.pulsar.metadata.api.coordination.ResourceLock expected [false] but found [true] within 10 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:165)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:119)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:31)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:895)
	at org.awaitility.core.ConditionFactory.untilAsserted(ConditionFactory.java:679)
	at org.apache.pulsar.metadata.ZKSessionTest.testReacquireLocksAfterSessionLost(ZKSessionTest.java:130)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.AssertionError: expected [false] but found [true]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertFalse(Assert.java:67)
	at org.testng.Assert.assertFalse(Assert.java:77)
	at org.apache.pulsar.metadata.ZKSessionTest.lambda$testReacquireLocksAfterSessionLost$0(ZKSessionTest.java:131)
	at org.awaitility.core.AssertionCondition.lambda$new$0(AssertionCondition.java:53)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:222)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:209)
	... 4 more

this happened in https://github.com/apache/pulsar/pull/11758/checks?check_run_id=3408040594#step:8:4706

lhotari · 2021-08-24T11:26:00Z

There's also expected [SessionReestablished] but found [Reconnected] type of assertion failures

Error:  Tests run: 6, Failures: 1, Errors: 0, Skipped: 3, Time elapsed: 43.614 s <<< FAILURE! - in org.apache.pulsar.metadata.ZKSessionTest
Error:  testReacquireLocksAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 8.149 s  <<< FAILURE!
java.lang.AssertionError: expected [SessionReestablished] but found [Reconnected]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
	at org.testng.Assert.assertEquals(Assert.java:122)
	at org.testng.Assert.assertEquals(Assert.java:617)
	at org.apache.pulsar.metadata.ZKSessionTest.testReacquireLocksAfterSessionLost(ZKSessionTest.java:128)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)

in https://github.com/apache/pulsar/pull/11758/checks?check_run_id=3408040594#step:8:3079

lhotari · 2021-08-24T12:26:59Z

also

Error:  Tests run: 6, Failures: 1, Errors: 0, Skipped: 3, Time elapsed: 30.201 s <<< FAILURE! - in org.apache.pulsar.metadata.ZKSessionTest
Error:  testReacquireLocksAfterSessionLost(org.apache.pulsar.metadata.ZKSessionTest)  Time elapsed: 12.986 s  <<< FAILURE!
org.awaitility.core.ConditionTimeoutException: Assertion condition defined as a lambda expression in org.apache.pulsar.metadata.ZKSessionTest that uses org.apache.pulsar.metadata.api.coordination.ResourceLock expected [false] but found [true] within 10 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:165)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:119)
	at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:31)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:895)
	at org.awaitility.core.ConditionFactory.untilAsserted(ConditionFactory.java:679)
	at org.apache.pulsar.metadata.ZKSessionTest.testReacquireLocksAfterSessionLost(ZKSessionTest.java:130)
	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.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
	at org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.AssertionError: expected [false] but found [true]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertFalse(Assert.java:67)
	at org.testng.Assert.assertFalse(Assert.java:77)
	at org.apache.pulsar.metadata.ZKSessionTest.lambda$testReacquireLocksAfterSessionLost$0(ZKSessionTest.java:131)
	at org.awaitility.core.AssertionCondition.lambda$new$0(AssertionCondition.java:53)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:222)
	at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:209)
	... 4 more

…ate between retries - mitigates flaky tests in LockManagerTest apache#11690 and ZkSessionTest apache#11032

lhotari · 2021-08-25T06:17:42Z

there's a mitigation for this flaky test in #11771 by using a solution which cleans up state between test retries.

…ate between retries (#11771) * [Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup state between retries - mitigates flaky tests in LockManagerTest #11690 and ZkSessionTest #11032 * [Tests] Add notes about the correct usage of TestRetrySupport

…ate between retries (apache#11771) * [Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup state between retries - mitigates flaky tests in LockManagerTest apache#11690 and ZkSessionTest apache#11032 * [Tests] Add notes about the correct usage of TestRetrySupport (cherry picked from commit 7de9992)

lhotari · 2021-09-02T04:49:47Z

fixed by #11886

…ate between retries (#11771) * [Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup state between retries - mitigates flaky tests in LockManagerTest #11690 and ZkSessionTest #11032 * [Tests] Add notes about the correct usage of TestRetrySupport (cherry picked from commit 7de9992)

…#11062) Fixes apache#11032 apache#11143 Master Issue: apache#11032 apache#11143 Motivation In some cases, testing errors occurred due to Zookeeper's notification delay. Modifications Waiting async notice until timeout.

…ate between retries (apache#11771) * [Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup state between retries - mitigates flaky tests in LockManagerTest apache#11690 and ZkSessionTest apache#11032 * [Tests] Add notes about the correct usage of TestRetrySupport

lhotari · 2023-03-09T07:34:16Z

related to #19754 . @mattisonchao please remove ZKSessionTest from quarantine and fix this. Thanks

lhotari mentioned this issue Jun 23, 2021

Make Metadata ZKSessionTest less Flaky #10955

Merged

sijie mentioned this issue Jun 23, 2021

ISSUE-11032: Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost streamnative/pulsar-archived#2683

Closed

This was referenced Jun 24, 2021

[ Issue 11032 ] Fixed flaky test ZKSessionTest.. #11032 #11061

Closed

[ Issue 11032 ] Fixed flaky test ZKSessionTest.. #11032 #11062

Merged

sijie closed this as completed in #11062 Jul 14, 2021

lhotari reopened this Aug 24, 2021

sijie mentioned this issue Aug 24, 2021

ISSUE-11032: Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost streamnative/pulsar-archived#2950

Closed

lhotari added a commit to lhotari/pulsar that referenced this issue Aug 25, 2021

[Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup st…

56535f8

…ate between retries - mitigates flaky tests in LockManagerTest apache#11690 and ZkSessionTest apache#11032

lhotari mentioned this issue Aug 25, 2021

[Tests] Use TestRetrySupport for BaseMetadataStoreTests to cleanup state between retries #11771

Merged

lhotari mentioned this issue Sep 2, 2021

Flaky-test: [org.apache.pulsar.metadata.ZKSessionTest].[testReacquireLeadershipAfterSessionLost] #11143

Closed

lhotari closed this as completed Sep 2, 2021

dave2wave mentioned this issue Dec 2, 2022

Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #18641

Closed

2 tasks

lhotari reopened this Mar 9, 2023

lhotari assigned mattisonchao Mar 9, 2023

sijie mentioned this issue Mar 9, 2023

ISSUE-11032: Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost streamnative/pulsar-archived#5606

Open

mattisonchao mentioned this issue Mar 9, 2023

[improve][meta] Fix busy-loop causes watcher can't acquire lock. #19769

Merged

5 tasks

mattisonchao closed this as completed in #19769 Mar 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #11032

Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #11032

lhotari commented Jun 23, 2021

lhotari commented Jun 23, 2021

lhotari commented Jun 23, 2021 •

edited

Loading

mattisonchao commented Jun 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 25, 2021

lhotari commented Sep 2, 2021

lhotari commented Mar 9, 2023

Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #11032

Flaky-test: ZKSessionTest.testReacquireLeadershipAfterSessionLost #11032

Comments

lhotari commented Jun 23, 2021

lhotari commented Jun 23, 2021

lhotari commented Jun 23, 2021 • edited Loading

mattisonchao commented Jun 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 24, 2021

lhotari commented Aug 25, 2021

lhotari commented Sep 2, 2021

lhotari commented Mar 9, 2023

lhotari commented Jun 23, 2021 •

edited

Loading