KAFKA-9974: Fix flaky test by removing unneeded asserts by showuon · Pull Request #8646 · apache/kafka

showuon · 2020-05-11T08:53:22Z

java.lang.AssertionError: Expected: is <0L> but: was <43L> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6) at org.apache.kafka.streams.integration.OptimizedKTableIntegrationTest.shouldApplyUpdatesToStandbyStore(OptimizedKTableIntegrationTest.java:138)

The tests failed at assertThat(listener.startOffset, is(equalTo(0L)));. It looks like that it did a restore before the assert. But we should expect the restore sometimes happen to resume the failed tasks by itself. It should not cause the test failure under this situation.

On the other hands, I checked the original tests in below PR link:
https://github.com/apache/kafka/pull/7238/files#diff-7b659da73450d5bf7a1731b5606e4c83R205
The original tests added the assertThat(listener.startOffset, is(equalTo(0L))); is because in the end of the test, we'll also test the startOffset value. But in the newer version of the test, we don't really care about the startOffset or totalNumRestored value. All we want to test in this test is:
Assert that the current value in store reflects all messages being processed

So, removing the assert can avoid flaky test failure, and also be able to test what the test case want to test.

Committer Checklist (excluded from commit message)

Verify design and implementation
Verify test coverage and CI build status
Verify documentation (including upgrade notes)

showuon · 2020-05-11T08:55:07Z

Hi @mjsax , could you please check this PR to fix a flaky test when available? Thanks.

mjsax · 2020-05-12T22:51:43Z

-        // Assert that no restore has occurred, ensures that when we check later that the restore
-        // notification actually came from after the rebalance.
-        assertThat(listener.startOffset, is(equalTo(0L)));
-        assertThat(listener.totalNumRestored, is(equalTo(0L)));


I am not sure if this is the right fix. Note that "restoring" and "standby task update" are two different things, and a standby task should. never use the "restore" code path what this assertion verifies.

What could explain a restore is the migration of the active task from one instance to the other. However, this should actually not happen either. Could you reproduce the issue locally? We recently worked on rebalancing so maybe the issue is with regard to that.

Sorry @mjsax , I tried to trace the code to find out why that would happen, but I still can't figure it out. Do you have any suggestion for it? If not, I think we can at least have more clear message output when this assert failure happen again. I'm not sure if the info is enough if the error happened again. And not sure if you have any thoughts about it?

It'll look like this when assert failure.

Thanks.

I am not 100% sure about the root cause of the issue... If you have a good suggestion for a better error message, that would be great. I have not idea how we could improve it atm.

I think one possible explanation is that when we start the two instances, the rebalances took not just once but twice (once for the first instance, and another time for the second). In between the task may already be processed a bit on the first instance, and then after the second rebalance it was migrated and hence was restored a bit causing the listener to be triggered.

I'd agree with @showuon here that we do not need to strictly forbids restoration not happening when starting the first two instances, just making sure after closing one instance we can restore the other up to the first batch is enough (which is already validated). So I'm fine with removing this listener all together.

BTW there's another report that line 159 can also fail:

java.lang.AssertionError: Expected: is <true> but: was <false> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6) at org.apache.kafka.streams.integration.OptimizedKTableIntegrationTest.shouldApplyUpdatesToStandbyStore(OptimizedKTableIntegrationTest.java:159)

Which is a bit mystery to me, since I cannot really think of a way how that could happen.

ANyways, for now removing that listener all together seems good to me.

guozhangwang

@showuon I did some analysis on the test case itself, left some comments.

guozhangwang · 2020-06-10T19:29:05Z

-        // Assert that no restore has occurred, ensures that when we check later that the restore
-        // notification actually came from after the rebalance.
-        assertThat(listener.startOffset, is(equalTo(0L)));
-        assertThat(listener.totalNumRestored, is(equalTo(0L)));


I think one possible explanation is that when we start the two instances, the rebalances took not just once but twice (once for the first instance, and another time for the second). In between the task may already be processed a bit on the first instance, and then after the second rebalance it was migrated and hence was restored a bit causing the listener to be triggered.

I'd agree with @showuon here that we do not need to strictly forbids restoration not happening when starting the first two instances, just making sure after closing one instance we can restore the other up to the first batch is enough (which is already validated). So I'm fine with removing this listener all together.

guozhangwang · 2020-06-10T19:30:09Z

-        // Assert that no restore has occurred, ensures that when we check later that the restore
-        // notification actually came from after the rebalance.
-        assertThat(listener.startOffset, is(equalTo(0L)));
-        assertThat(listener.totalNumRestored, is(equalTo(0L)));


BTW there's another report that line 159 can also fail:

java.lang.AssertionError: Expected: is <true> but: was <false> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6) at org.apache.kafka.streams.integration.OptimizedKTableIntegrationTest.shouldApplyUpdatesToStandbyStore(OptimizedKTableIntegrationTest.java:159)

Which is a bit mystery to me, since I cannot really think of a way how that could happen.

ANyways, for now removing that listener all together seems good to me.

showuon · 2020-06-15T09:58:37Z

Thanks for the suggestion, @guozhangwang , I've removed the listeners in this commit e82aa88. I agree we can fix it in this way first, and keep monitoring it. Thanks.

guozhangwang · 2020-06-15T16:47:27Z

test this

showuon · 2020-06-16T05:41:27Z

JDK 8 and Scala 2.12
failed kafka.admin.ReassignPartitionsUnitTest.testModifyBrokerThrottles
--> traced in KAFKA-10155, PR: #8853

JDK 14 and Scala 2.13
failed org.apache.kafka.streams.integration.HighAvailabilityTaskAssignorIntegrationTest.shouldScaleOutWithWarmupTasksAndPersistentStores
--> passed locally
kafka.admin.ReassignPartitionsUnitTest.testModifyBrokerThrottles
--> traced in KAFKA-10155, PR: #8853

JDK 11 and Scala 2.13
org.apache.kafka.connect.mirror.MirrorConnectorsIntegrationTest.testReplication
--> passed locally
kafka.api.PlaintextConsumerTest.testLowMaxFetchSizeForRequestAndPartition
kafka.api.PlaintextConsumerTest.testLowMaxFetchSizeForRequestAndPartition
--> traced in KAFKA-8460 KAFKA-8264
kafka.admin.ReassignPartitionsUnitTest.testModifyBrokerThrottles
kafka.admin.ReassignPartitionsUnitTest.testModifyBrokerThrottles
--> traced in KAFKA-10155, PR: #8853

guozhangwang · 2020-06-16T05:55:47Z

test this

guozhangwang · 2020-06-16T05:56:01Z

test this

The tests failed at assertThat(listener.startOffset, is(equalTo(0L)));. It looks like that it did a restore before the assert. But we should expect the restore sometimes happen to resume the failed tasks by itself. It should not cause the test failure under this situation. On the other hands, the original tests added the assertThat(listener.startOffset, is(equalTo(0L))); is because in the end of the test, we'll also test the startOffset value. But in the newer version of the test, we don't really care about the startOffset or totalNumRestored value. All we want to test in this test is: Assert that the current value in store reflects all messages being processed So, removing the assert can avoid flaky test failure, and also be able to test what the test case want to test. Reviewers: Matthias J. Sax <matthias@confluent.io>, Guozhang Wang <wangguoz@gmail.com>

guozhangwang · 2020-06-16T17:23:48Z

Cherry-picked to 2.6.

* 'trunk' of github.com:apache/kafka: KAFKA-10150: task state transitions/management and committing cleanup (apache#8856) KAFKA-10169: Error message when transit to Aborting / AbortableError / FatalError (apache#8880) KAFKA-9974: Fix flaky test by removing unneeded asserts (apache#8646) MINOR: Documentation for KIP-585 (apache#8839)

KAFKA-9974: fix flaky test by removing unneeded asserts

95ed0d7

mjsax added streams tests Test fixes (including flaky tests) labels May 12, 2020

mjsax reviewed May 12, 2020

View reviewed changes

showuon added 2 commits May 21, 2020 16:11

Merge branch 'trunk' of https://github.com/apache/kafka into KAFKA-9974

28c7b7d

add more info when failed

8f26e43

guozhangwang reviewed Jun 10, 2020

View reviewed changes

Merge branch 'trunk' of https://github.com/apache/kafka into KAFKA-9974

fd53b0c

KAFKA-9974: remove the listener

e82aa88

showuon force-pushed the KAFKA-9974 branch from 9d44f2c to e82aa88 Compare June 15, 2020 14:20

guozhangwang merged commit e5bb535 into apache:trunk Jun 16, 2020

Uh oh!

Conversation

showuon commented May 11, 2020

Committer Checklist (excluded from commit message)

Uh oh!

showuon commented May 11, 2020

Uh oh!

mjsax May 12, 2020

Choose a reason for hiding this comment

Uh oh!

showuon May 21, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mjsax May 23, 2020

Choose a reason for hiding this comment

Uh oh!

guozhangwang Jun 10, 2020

Choose a reason for hiding this comment

Uh oh!

guozhangwang Jun 10, 2020

Choose a reason for hiding this comment

Uh oh!

guozhangwang left a comment

Choose a reason for hiding this comment

Uh oh!

guozhangwang Jun 10, 2020

Choose a reason for hiding this comment

Uh oh!

guozhangwang Jun 10, 2020

Choose a reason for hiding this comment

Uh oh!

showuon commented Jun 15, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

guozhangwang commented Jun 15, 2020

Uh oh!

showuon commented Jun 16, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

guozhangwang commented Jun 16, 2020

Uh oh!

guozhangwang commented Jun 16, 2020

Uh oh!

guozhangwang commented Jun 16, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

showuon May 21, 2020 •

edited

Loading

showuon commented Jun 15, 2020 •

edited

Loading

showuon commented Jun 16, 2020 •

edited

Loading