Skip to content

KAFKA-10017: fix 2 issues in EosBetaUpgradeIntegrationTest #9733

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

Merged
mjsax merged 5 commits into from
Jan 19, 2021
Merged

KAFKA-10017: fix 2 issues in EosBetaUpgradeIntegrationTest #9733

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d3693f4
KAFKA-10017: fix 2 issues in EosBetaUpgradeIntegrationTest
showuon Dec 11, 2020
ee037dd
KAFKA-10017: wait for specific number of rebalancing for new started …
showuon Dec 21, 2020
89eb7ef
KAFKA-10017: address reviewer's comment to use volatile for different…
showuon Dec 23, 2020
f2f0967
KAFKA-10017: fix the exception handler issue
showuon Jan 15, 2021
62cbfb6
trigger the jenkins test again
showuon Jan 15, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
97 changes: 71 additions & 26 deletions ...ams/src/test/java/org/apache/kafka/streams/integration/EosBetaUpgradeIntegrationTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,7 @@
import static org.apache.kafka.test.TestUtils.waitForCondition;
import static org.hamcrest.CoreMatchers.equalTo;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.junit.Assert.fail;
import static org.junit.Assert.assertFalse;

@RunWith(Parameterized.class)
@Category({IntegrationTest.class})
Expand Down Expand Up @@ -123,6 +123,8 @@ public static Collection<Boolean[]> data() {
KeyValue.pair(KafkaStreams.State.PENDING_SHUTDOWN, KafkaStreams.State.NOT_RUNNING)
)
);
private static final KeyValue<KafkaStreams.State, KafkaStreams.State> REBALANCED_RUNNING =
KeyValue.pair(State.REBALANCING, State.RUNNING);

@ClassRule
public static final EmbeddedKafkaCluster CLUSTER = new EmbeddedKafkaCluster(
Expand All @@ -135,8 +137,13 @@ public static Collection<Boolean[]> data() {
private final static String CONSUMER_GROUP_ID = "readCommitted";
private final static String MULTI_PARTITION_INPUT_TOPIC = "multiPartitionInputTopic";
private final static String MULTI_PARTITION_OUTPUT_TOPIC = "multiPartitionOutputTopic";
private final static String APP_DIR_1 = "appDir1";
private final static String APP_DIR_2 = "appDir2";
private final static String UNEXPECTED_EXCEPTION_MSG = "Fail the test since we got an unexpected exception or" +
"there are too many exceptions thrown, please check standard error log for more info.";

@mjsax mjsax Dec 22, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: missing space between or (line above) and there

private final String storeName = "store";


private final StableAssignmentListener assignmentListener = new StableAssignmentListener();

private final AtomicBoolean errorInjectedClient1 = new AtomicBoolean(false);
Expand All @@ -147,9 +154,16 @@ public static Collection<Boolean[]> data() {
private final AtomicInteger commitCounterClient2 = new AtomicInteger(-1);
private final AtomicInteger commitRequested = new AtomicInteger(0);

private Throwable uncaughtException;

private int testNumber = 0;
private boolean hasUnexpectedError = false;

@mjsax mjsax Dec 22, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This variable should be declare volatile because the callback is executed on a different thread.

@showuon showuon Dec 23, 2020

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice catch! Fixed.

private Map<String, Integer> exceptionCounts = new HashMap<String, Integer>() {
{
put(APP_DIR_1, 0);
put(APP_DIR_2, 0);
}
};
private int prevNumAssignments = 0;
private int expectedNumAssignments = 0;

@Before
public void createTopics() throws Exception {
Expand Down Expand Up @@ -235,7 +249,7 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {

try {
// phase 1: start both clients
streams1Alpha = getKafkaStreams("appDir1", StreamsConfig.EXACTLY_ONCE);
streams1Alpha = getKafkaStreams(APP_DIR_1, StreamsConfig.EXACTLY_ONCE);
streams1Alpha.setStateListener(
(newState, oldState) -> stateTransitions1.add(KeyValue.pair(oldState, newState))
);
Expand All @@ -246,18 +260,19 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);
waitForRunning(stateTransitions1);

streams2Alpha = getKafkaStreams("appDir2", StreamsConfig.EXACTLY_ONCE);
streams2Alpha = getKafkaStreams(APP_DIR_2, StreamsConfig.EXACTLY_ONCE);
streams2Alpha.setStateListener(
(newState, oldState) -> stateTransitions2.add(KeyValue.pair(oldState, newState))
);
stateTransitions1.clear();

assignmentListener.prepareForRebalance();
prevNumAssignments = assignmentListener.prepareForRebalance();
streams2Alpha.cleanUp();
streams2Alpha.start();
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);

@mjsax mjsax Dec 16, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To avoid the issue you point out, we actually use this line. As a matter of fact, there is no guarantee if there would be even more than two rebalances. \cc @ableegoldman might be able to provide more input?

@showuon showuon Dec 16, 2020 •
edited
Loading

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mjsax
The stacktrace is like this. The line number is not mapped to master branch correctly, but you can know what it is from the method name. It failed when it's trying to get all state data and checking if the current stream is in RUNNING state, but it's under rebalancing. And this exception won't do any retry.

Stacktrace

org.apache.kafka.streams.errors.InvalidStateStoreException: Cannot get state store store because the stream thread is PARTITIONS_ASSIGNED, not RUNNING
	at org.apache.kafka.streams.state.internals.StreamThreadStateStoreProvider.stores(StreamThreadStateStoreProvider.java:81)
	at org.apache.kafka.streams.state.internals.WrappingStoreProvider.stores(WrappingStoreProvider.java:50)
	at org.apache.kafka.streams.state.internals.CompositeReadOnlyKeyValueStore.all(CompositeReadOnlyKeyValueStore.java:119)
	at org.apache.kafka.streams.integration.EosBetaUpgradeIntegrationTest.keysFromInstance(EosBetaUpgradeIntegrationTest.java:1112)
	at org.apache.kafka.streams.integration.EosBetaUpgradeIntegrationTest.shouldUpgradeFromEosAlphaToEosBeta(EosBetaUpgradeIntegrationTest.java:494)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

And, yes, we make sure it completed the rebalance then checking the running state, but as I mentioned, there will be 2 rebalance happened(1 for Adding new member, 1 for leader re-joining group during Stable), and we only wait 1 rebalance completes, so there might be another rebalancing later. The 2 stream state transition log is like this:

stateTransitions1:
[KeyValue(CREATED, REBALANCING), KeyValue(REBALANCING, RUNNING), KeyValue(RUNNING, REBALANCING), KeyValue(REBALANCING, RUNNING)]  

stateTransitions2: 
[KeyValue(RUNNING, REBALANCING), KeyValue(REBALANCING, RUNNING), KeyValue(RUNNING, REBALANCING), KeyValue(REBALANCING, RUNNING)]

So, as you can see, we might enter next step when we are in step 2 (KeyValue(REBALANCING, RUNNING)), and there will be another rebalancing soon. That's why I'll wait explicitly for this transition pair [KeyValue(RUNNING, REBALANCING), KeyValue(REBALANCING, RUNNING)]

@mjsax mjsax Dec 16, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The line number is not mapped to master branch correctly, but you can know what it is from the method name.

Well, this seem to imply the the run was on an older version that did not contain the retry yet -- note. adding the retry it was part of the latest PR for this test that we merged: https://github.com/apache/kafka/pull/9688/files#diff-86a5136ae170df067137442b5eae05fa5fd9d1e02aca85bac8a251b7d2557b0eR1089

Thus, I would assume the the whole test failure you observes was before the last fix.

there will be 2 rebalance happened

Correct, but we actually "cut off" the unstable rebalances (there might actually be more then 2...) via assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);

To me, it seems that you observe the test failure before the PR got merged -- otherwise the line numbers for keysFromInstance would match.

@showuon showuon Dec 16, 2020

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You're right! I didn't notice there is already new added retry in master. I'll revert my change for it. Thank you!

expectedNumAssignments = assignmentListener.numTotalAssignments() - prevNumAssignments;
waitForNumRebalancingToRunning(stateTransitions2, expectedNumAssignments);
waitForRunning(stateTransitions1);

@mjsax mjsax Dec 23, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you reasoning is right, do we need to use waitForNumRebalancingToRunning here, too? If there are multiple rebalances, both clients would participate?

Also, you PR does not update all stages when we wait for state changes. Why? Would we not need to apply to logic each time?

@showuon showuon Dec 24, 2020 •
edited
Loading

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for your questions. Answer them below:

Also, you PR does not update all stages when we wait for state changes. Why? Would we not need to apply to logic each time?

--> Yes, I should do that. What I did now is just focusing on the case: 1 new started stream + 1 already running stream, which will have more failures here. But you're right, I should put the change in all stages.

If you reasoning is right, do we need to use waitForNumRebalancingToRunning here, too? If there are multiple rebalances, both clients would participate?

--> Good question! I have explained in the previous comment (#9733 (comment)) though, I can explain again since I know you didn't understand exactly why I did this change before.

I only waitForNumRebalancingToRunning for the new started stream only, not for the "already running stream" because I found sometimes if the stream runs fast enough, the "already running stream" might not have the expected number of [REBALANCING -> RUNNING] state transition. The reason is this line:

[appDir2-StreamThread-1] State transition from PARTITIONS_ASSIGNED to PARTITIONS_ASSIGNED

Basically, The already running stream thread should have the state change: [RUNNING to PARTITIONS_REVOKED], [PARTITIONS_REVOKED to PARTITIONS_ASSIGNED](unstable), [PARTITIONS_ASSIGNED to RUNNING], [RUNNING to PARTITIONS_ASSIGNED](stable), [PARTITIONS_ASSIGNED to RUNNING]. Because it needs one more PARTITIONS_REVOKED step, it might be under 2 PARTITIONS_ASSIGNED at the same time (no RUNNING in the middle). And that's why the stream client doesn't change to RUNNING as we expected.

Does that make sense?

waitForRunning(stateTransitions2);

// in all phases, we write comments that assume that p-0/p-1 are assigned to the first client
// and p-2/p-3 are assigned to the second client (in reality the assignment might be different though)
Expand Down Expand Up @@ -389,6 +404,7 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
stateTransitions1.clear();
streams1Alpha.close();
waitForStateTransition(stateTransitions1, CLOSE_CRASHED);
assertFalse(UNEXPECTED_EXCEPTION_MSG, hasUnexpectedError);
}

// phase 5: (restart first client)
Expand All @@ -411,12 +427,13 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
commitRequested.set(0);
stateTransitions1.clear();
stateTransitions2.clear();
streams1Beta = getKafkaStreams("appDir1", StreamsConfig.EXACTLY_ONCE_BETA);
streams1Beta = getKafkaStreams(APP_DIR_1, StreamsConfig.EXACTLY_ONCE_BETA);
streams1Beta.setStateListener((newState, oldState) -> stateTransitions1.add(KeyValue.pair(oldState, newState)));
assignmentListener.prepareForRebalance();
prevNumAssignments = assignmentListener.prepareForRebalance();
streams1Beta.start();
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);
waitForRunning(stateTransitions1);
expectedNumAssignments = assignmentListener.numTotalAssignments() - prevNumAssignments;
waitForNumRebalancingToRunning(stateTransitions1, expectedNumAssignments);
waitForRunning(stateTransitions2);

final Set<Long> newlyCommittedKeys;
Expand Down Expand Up @@ -527,6 +544,7 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
stateTransitions2.clear();
streams2Alpha.close();
waitForStateTransition(stateTransitions2, CLOSE_CRASHED);
assertFalse(UNEXPECTED_EXCEPTION_MSG, hasUnexpectedError);

final List<KeyValue<Long, Long>> expectedCommittedResultAfterFailure =
computeExpectedResult(uncommittedInputDataAfterFirstUpgrade, committedState);
Expand Down Expand Up @@ -555,15 +573,16 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
commitCounterClient2.set(-1);
stateTransitions1.clear();
stateTransitions2.clear();
streams2AlphaTwo = getKafkaStreams("appDir2", StreamsConfig.EXACTLY_ONCE);
streams2AlphaTwo = getKafkaStreams(APP_DIR_2, StreamsConfig.EXACTLY_ONCE);
streams2AlphaTwo.setStateListener(
(newState, oldState) -> stateTransitions2.add(KeyValue.pair(oldState, newState))
);
assignmentListener.prepareForRebalance();
prevNumAssignments = assignmentListener.prepareForRebalance();
streams2AlphaTwo.start();
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);
expectedNumAssignments = assignmentListener.numTotalAssignments() - prevNumAssignments;
waitForNumRebalancingToRunning(stateTransitions2, expectedNumAssignments);
waitForRunning(stateTransitions1);
waitForRunning(stateTransitions2);

// 7b. write third batch of input data
final Set<Long> keysFirstClientBeta = keysFromInstance(streams1Beta);
Expand Down Expand Up @@ -617,6 +636,7 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
stateTransitions1.clear();
streams1Beta.close();
waitForStateTransition(stateTransitions1, CLOSE_CRASHED);
assertFalse(UNEXPECTED_EXCEPTION_MSG, hasUnexpectedError);

final List<KeyValue<Long, Long>> expectedCommittedResultAfterFailure =
computeExpectedResult(uncommittedInputDataBetweenUpgrade, committedState);
Expand All @@ -626,12 +646,13 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
// 7c. restart the first client in eos-beta mode and wait until rebalance stabilizes
stateTransitions1.clear();
stateTransitions2.clear();
streams1BetaTwo = getKafkaStreams("appDir1", StreamsConfig.EXACTLY_ONCE_BETA);
streams1BetaTwo = getKafkaStreams(APP_DIR_1, StreamsConfig.EXACTLY_ONCE_BETA);
streams1BetaTwo.setStateListener((newState, oldState) -> stateTransitions1.add(KeyValue.pair(oldState, newState)));
assignmentListener.prepareForRebalance();
prevNumAssignments = assignmentListener.prepareForRebalance();
streams1BetaTwo.start();
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);
waitForRunning(stateTransitions1);
expectedNumAssignments = assignmentListener.numTotalAssignments() - prevNumAssignments;
waitForNumRebalancingToRunning(stateTransitions1, expectedNumAssignments);
waitForRunning(stateTransitions2);
}

Expand Down Expand Up @@ -738,6 +759,7 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
stateTransitions2.clear();
streams2AlphaTwo.close();
waitForStateTransition(stateTransitions2, CLOSE_CRASHED);
assertFalse(UNEXPECTED_EXCEPTION_MSG, hasUnexpectedError);
}

// phase 10: (restart second client)
Expand All @@ -759,15 +781,16 @@ public void shouldUpgradeFromEosAlphaToEosBeta() throws Exception {
commitRequested.set(0);
stateTransitions1.clear();
stateTransitions2.clear();
streams2Beta = getKafkaStreams("appDir1", StreamsConfig.EXACTLY_ONCE_BETA);
streams2Beta = getKafkaStreams(APP_DIR_1, StreamsConfig.EXACTLY_ONCE_BETA);
streams2Beta.setStateListener(
(newState, oldState) -> stateTransitions2.add(KeyValue.pair(oldState, newState))
);
assignmentListener.prepareForRebalance();
prevNumAssignments = assignmentListener.prepareForRebalance();
streams2Beta.start();
assignmentListener.waitForNextStableAssignment(MAX_WAIT_TIME_MS);
expectedNumAssignments = assignmentListener.numTotalAssignments() - prevNumAssignments;
waitForNumRebalancingToRunning(stateTransitions2, expectedNumAssignments);
waitForRunning(stateTransitions1);
waitForRunning(stateTransitions2);

newlyCommittedKeys.clear();
if (!injectError) {
Expand Down Expand Up @@ -869,7 +892,7 @@ public void init(final ProcessorContext context) {
this.context = context;
state = (KeyValueStore<Long, Long>) context.getStateStore(storeName);
final String clientId = context.appConfigs().get(StreamsConfig.CLIENT_ID_CONFIG).toString();
if ("appDir1".equals(clientId)) {
if (APP_DIR_1.equals(clientId)) {
crash = errorInjectedClient1;
sharedCommit = commitCounterClient1;
} else {
Expand Down Expand Up @@ -938,11 +961,22 @@ public void close() {}

final KafkaStreams streams = new KafkaStreams(builder.build(), config, new TestKafkaClientSupplier());
streams.setUncaughtExceptionHandler((t, e) -> {
if (uncaughtException != null) {
if (!injectError) {
// we don't expect any exception thrown in stop case
e.printStackTrace(System.err);
fail("Should only get one uncaught exception from Streams.");
hasUnexpectedError = true;
} else {
int exceptionCount = (int) exceptionCounts.get(appDir);
// should only have our injected exception or commit exception, and 2 exceptions for each stream
if (++exceptionCount > 2 || !(e instanceof RuntimeException) ||
!(e.getMessage().contains("test exception"))) {
// The exception won't cause the test fail since we actually "expected" exception thrown and failed the stream.
// So, log to stderr for debugging when the exception is not what we expected, and fail in the main thread
e.printStackTrace(System.err);
hasUnexpectedError = true;
}
exceptionCounts.put(appDir, exceptionCount);
}
uncaughtException = e;
});

return streams;
Expand All @@ -956,14 +990,25 @@ private void waitForRunning(final List<KeyValue<KafkaStreams.State, KafkaStreams
);
}

// Wait for the numRebalancing of <REBALANCING -> RUNNING> state transition because when new stream joined,
// we'll do multiple rebalancing. So, if we only wait for Running, it might enter rebalancing soon
private void waitForNumRebalancingToRunning(final List<KeyValue<KafkaStreams.State, KafkaStreams.State>> observed,
final int numRebalancing) throws Exception {
waitForCondition(() -> !observed.isEmpty() &&
observed.stream().filter(kv -> kv.equals(REBALANCED_RUNNING)).count() == numRebalancing,
MAX_WAIT_TIME_MS,
() -> "Client did not run " + numRebalancing + " of Rebalancing to Running on time. Observers transitions: " + observed
);
}

private void waitForStateTransition(final List<KeyValue<KafkaStreams.State, KafkaStreams.State>> observed,
final List<KeyValue<KafkaStreams.State, KafkaStreams.State>> expected)
throws Exception {

waitForCondition(
() -> observed.equals(expected),
MAX_WAIT_TIME_MS,
() -> "Client did not startup on time. Observers transitions: " + observed
() -> "Client did not have the expected state transition on time. Observers transitions: " + observed
);
}

Expand Down Expand Up @@ -1143,7 +1188,7 @@ private class ErrorInjector extends KafkaProducer<byte[], byte[]> {
public ErrorInjector(final Map<String, Object> configs) {
super(configs, new ByteArraySerializer(), new ByteArraySerializer());
final String clientId = configs.get(ProducerConfig.CLIENT_ID_CONFIG).toString();
if (clientId.contains("appDir1")) {
if (clientId.contains(APP_DIR_1)) {
crash = commitErrorInjectedClient1;
} else {
crash = commitErrorInjectedClient2;
Expand All @@ -1156,7 +1201,7 @@ public void commitTransaction() {
if (!crash.compareAndSet(true, false)) {
super.commitTransaction();
} else {
throw new RuntimeException("Injected producer commit exception.");
throw new RuntimeException("Injected producer commit test exception.");
}
}
}
Expand Down
14 changes: 13 additions & 1 deletion streams/src/test/java/org/apache/kafka/streams/integration/utils/IntegrationTestUtils.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1270,15 +1270,24 @@ public static <S> S getStore(final long waitTime,

public static class StableAssignmentListener implements AssignmentListener {
final AtomicInteger numStableAssignments = new AtomicInteger(0);
final AtomicInteger totalAssignments = new AtomicInteger(0);
int nextExpectedNumStableAssignments;

@Override
public void onAssignmentComplete(final boolean stable) {
totalAssignments.incrementAndGet();
if (stable) {
numStableAssignments.incrementAndGet();
}
}

/**
* get the total number of assignments (unstable + stable)
*/
public int numTotalAssignments() {
return totalAssignments.get();
}

public int numStableAssignments() {
return numStableAssignments.get();
}
Expand All @@ -1287,9 +1296,12 @@ public int numStableAssignments() {
* Saves the current number of stable rebalances so that we can tell when the next stable assignment has been
* reached. This should be called once for every invocation of {@link #waitForNextStableAssignment(long)},
* before the rebalance-triggering event.
*
* @return the total number of assignments so far
*/
public void prepareForRebalance() {
public int prepareForRebalance() {
nextExpectedNumStableAssignments = numStableAssignments.get() + 1;
return totalAssignments.get();
}

/**
Expand Down