Skip to content

KAFKA-14718: Fix flaky DedicatedMirrorIntegrationTest#13284

Merged
C0urante merged 1 commit into
apache:trunkfrom
divijvaidya:fix-mm-test
Jul 10, 2023
Merged

KAFKA-14718: Fix flaky DedicatedMirrorIntegrationTest#13284
C0urante merged 1 commit into
apache:trunkfrom
divijvaidya:fix-mm-test

Conversation

@divijvaidya

@divijvaidya divijvaidya commented Feb 21, 2023

Copy link
Copy Markdown
Member

Motivation

The test suite DedicatedMirrorIntegrationTest fails in a flaky manner with the following error:

org.opentest4j.AssertionFailedError: Condition not met within timeout 30000. topic A.test-topic-0 was not created on cluster B- ._~:/?#[]@!$&'()*+;="<>%{}|\^`618 in time ==> expected: <true> but was: <false>

Root cause of the failure is available in stdout:

[2023-02-17 18:56:32,308] INFO This node is a follower for A->B- ._~:/?#[]@!$&'()*+;="<>%{}|\^`618. Using existing connector configuration. (org.apache.kafka.connect.mirror.MirrorMaker:234)
[2023-02-17 18:56:42,567] INFO Kafka MirrorMaker stopping (org.apache.kafka.connect.mirror.MirrorMaker:202)
[2023-02-17 18:56:43,371] INFO Kafka MirrorMaker stopped. (org.apache.kafka.connect.mirror.MirrorMaker:213)
[2023-02-17 18:56:43,371] INFO Kafka MirrorMaker stopping (org.apache.kafka.connect.mirror.MirrorMaker:202)
[2023-02-17 18:56:44,376] INFO Kafka MirrorMaker stopped. (org.apache.kafka.connect.mirror.MirrorMaker:213)
[2023-02-17 18:56:44,377] INFO Kafka MirrorMaker stopping (org.apache.kafka.connect.mirror.MirrorMaker:202)
[2023-02-17 18:56:45,782] ERROR Failed to configure MirrorSourceConnector connector for A->B- ._~:/?#[]@!$&'()*+;="<>%{}|\^`618 (org.apache.kafka.connect.mirror.MirrorMaker:236)
org.apache.kafka.connect.errors.ConnectException: Worker is shutting down
	at org.apache.kafka.connect.runtime.distributed.DistributedHerder.halt(DistributedHerder.java:766)
	at org.apache.kafka.connect.runtime.distributed.DistributedHerder.run(DistributedHerder.java:361)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	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)

The test tries to assert topic replication on the second cluster but the mirror maker nodes themselves are unavailable. They are unavailable because the connectors fail to configure. Connectors fail to configure because the worker is already shutting down by the time they are ready to be configured.

Change

This highlights a gap in MirrorMaker startup sequence where it does not wait for connectors to be configured by the herders before declaring itself as "started". This leads to a situation where MirrorMaker claims it has started but the herders are still in the process of configuring the connectors. During this time, mirror maker will not perform any replication.

With this change, we add a dependency on connector configuration for the MirrorMaker to declare itself as started.

Rejected alternative

An alternative approach is to modify the test to wait for connectors to get configured on all 3 MM nodes before starting the actual test i.e. before making a call to create topic. But this alternative is artificially hiding the problems which users of MirrorMaker may also face.

@divijvaidya

Copy link
Copy Markdown
Member Author

@C0urante please take a look when you get a chance. unitTest and integrationTest succeed for me locally.

@C0urante C0urante added tests Test fixes (including flaky tests) mirror-maker-2 labels Feb 23, 2023

@C0urante C0urante left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thanks Divij! I think we're onto something here, but this PR doesn't quite accomplish what it sets out to.

Although we're changing the semantics of the startLatch field here, we don't actually synchronously block on it (i.e., via CountDownLatch::await) anywhere in the code base except in the shutdown hook set up by MirrorMaker, so this doesn't really buy us much right now.

It's also worth noting that, even if we do successfully block on the completion of the callbacks passed to Herder::putConnectorConfig, this only guarantees that connector configs have been written to the config topic. It does not guarantee that the ensuing rebalance (to allocate the new connector) has completed, that task configs have been generated, that the second ensuing rebalance (to allocate tasks) has completed, or that tasks have been successfully started. So, although the approach that's pursued here does have some merit, it doesn't necessarily prevent the test failures we've been seeing from taking place, especially in slow environments like our Jenkins nodes. And even if we did tweak this PR to do that kind of blocking, we'd still have to choose a reasonable amount of time to wait for all of these operations to complete.

Do you think it might be worth it to just bump the timeouts of these tests? We might go from 30 seconds to, say, 2 minutes. This would make things worse for local development if the changes that someone is testing actually cause the tests to fail, but at this point it seems like the cost of CI flakiness might outweigh that; would be interested in your thoughts.

@divijvaidya

Copy link
Copy Markdown
Member Author

Thank you for the detailed explanation @C0urante!

so this doesn't really buy us much right now.

Oops, my bad! I did not notice that.

this only guarantees that connector configs have been written to the config topic.

That is true. We need a more comprehensive check. I was basing this change on the fact that we use similar verification in other tests (see waitUntilMirrorMakerIsRunning() in MirrorConnectorsIntegrationBaseTest). It's more of a "better than nothing" approach here.

And even if we did tweak this PR to do that kind of blocking, we'd still have to choose a reasonable amount of time to wait for all of these operations to complete.

I think that fixing the test by extending the timeout might hide the problems that users may be facing in production as well. Ideally the MirrorMaker#start() should be returning a Future which could be tracked to check the completion of start. In absence of such a mechanism, today, a user might call MirrorMaker#start() and assume that it has started correctly while in the background, connector start up might have failed (just as it did in this test scenario). Hence, I believe, we need a better mechanism to check for successful startup of MirrorMaker. Thoughts?

Do you think it might be worth it to just bump the timeouts of these tests?

We could do that AND as a partial safety check block topic creation in this test until connectors have at least been configured (see rejected alternative). Let's reach to a conclusion on the above point first and then we can proceed with this option if that's what we agree to.

@C0urante

C0urante commented Feb 28, 2023

Copy link
Copy Markdown
Contributor

I think that fixing the test by extending the timeout might hide the problems that users may be facing in production as well.

I don't think that bumping the timeouts in these tests is likely to hide issues that may surface in production; rather, I'm only worried that they'll make local testing and development more cumbersome.

It's also worth noting that no matter how precise we make the wait-for-startup logic, we'll still probably end up effectively bumping timeouts in this PR (if we add a 30-second wait for MM2 startup, then that turns the existing 30-second timeout for initial topic replication into 60 seconds).

Hence, I believe, we need a better mechanism to check for successful startup of MirrorMaker. Thoughts?

Agreed 👍 IMO MM2 observability in general can be improved. Right now you're basically limited to JMX, other custom metrics reporters, and logs. There's no public API for viewing cluster-wide health info (the closest thing is reading directly from the status topic, but that's not public API and we shouldn't count on users doing that or recommend it).

If there's an issue starting one of the connectors, instead of failing startup of the MM2 node, we log a message and move on. I can't imagine this is very easy for users to work with, though maybe I'm underestimating the utility of JMX and logs here.

In absence of such a mechanism, today, a user might call MirrorMaker#start() and assume that it has started correctly while in the background, connector start up might have failed (just as it did in this test scenario).

This is less concerning because the MirrorMaker class isn't part of public API; users are not expected to directly interact with any instances of this class and we do not support any use cases like that right now.

I'm wondering if, instead of a Future-based approach, we might add an internal API to the MirrorMaker class to expose the status of the connectors running on it?

A brief sketch:

public class MirrorMaker {
    public ConnectorStateInfo connectorStatus(String source, String target, String connector) {
        SourceAndTarget sourceAndTarget = new SourceAndTarget(source, target);
        checkHerder(sourceAndTarget);
        return herders.get(new SourceAndTarget(source, target)).connectorStatus(connector);
    }
}

We could then leverage this API in the DedicatedMirrorIntegrationTest suite to implement an equivalent of the waitUntilMirrorMakerIsRunning method from the MirrorConnectorsIntegrationBaseTest suite.

@divijvaidya

Copy link
Copy Markdown
Member Author

This is less concerning because the MirrorMaker class isn't part of public API;

It's not technically part of public API but it has a main() method which is executed by the customers. As you pointed out, today, they have to rely on logs/metrics to figure out whether MM started correctly or not.

I agree to the creation of connectorStatus() and usage in tests as you suggested, but additionally we should block the completion of main() until all connectors are online. The part about blocking could be taken up in a different PR and we can discuss the merits/demerits of doing that over there.

Meanwhile, I will add connectorStatus() and relevant changes to this PR.

@divijvaidya divijvaidya changed the title KAFKA-14718: Make MirrorMaker startup synchronously depend on connector start KAFKA-14718: Fix flaky test DedicatedMirrorIntegrationTest Mar 1, 2023
@divijvaidya divijvaidya changed the title KAFKA-14718: Fix flaky test DedicatedMirrorIntegrationTest KAFKA-14718: Fix flaky DedicatedMirrorIntegrationTest Mar 1, 2023
@divijvaidya

Copy link
Copy Markdown
Member Author

@C0urante ready for your review. I have increased the timeout to 2 min. and also added the wait for mirror maker to get ready. In a separate JIRA we should talk about how we can make the startup synchronous. I have created one such JIRA at https://issues.apache.org/jira/browse/KAFKA-14773

@divijvaidya

Copy link
Copy Markdown
Member Author

The test failures seems unrelated (and ./gradlew unitTest pass for me locally), hence, rebasing against trunk with a hope that the gradle issues go away.

@C0urante C0urante left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thanks @divijvaidya, this is closer to what I had in mind.

I'd like to clarify again that the semantics of MirrorMaker::start do not matter; instead, the user-facing behavior of the MM2 startup script is what matters here. The invocation of that script encapsulates the entire lifetime of MM2, including the creation of connectors and waiting for the process to shut down. It is not necessary to make that method synchronous since there are no problems with the user-facing behavior right now, at least in that regard. And sure, we may choose to improve MM2 observability in general, but IMO that has very little to do with the start method as more than a minor implementation detail.

With regards to this suggestion:

we should block the completion of main() until all connectors are online.

This already happens, unless the process is prematurely terminated. Feel free to test this scenario out yourself by running MM2 in dedicated mode and taking a thread dump at any point in the lifetime of the program.

Comment thread connect/mirror/src/main/java/org/apache/kafka/connect/mirror/MirrorMaker.java Outdated
Comment thread connect/mirror/src/main/java/org/apache/kafka/connect/mirror/MirrorMaker.java Outdated
Comment thread connect/mirror/src/main/java/org/apache/kafka/connect/mirror/MirrorMaker.java Outdated
@divijvaidya

Copy link
Copy Markdown
Member Author

Hey @C0urante
I haven't forgotten about this PR :) I am stuck right now and would solicit your help here.
I have made the changes that you suggested but the below condition is never satisfied.

// verify that at least one task exists
&& !connectorStatus.tasks().isEmpty()

I am not very much familiar with MM code and connect framework. If you have a suggestion to fix it, I would be happy to do so, otherwise, I will probably need some time to dig into this further.

@C0urante

C0urante commented Jun 2, 2023

Copy link
Copy Markdown
Contributor

@divijvaidya No worries about the delay--looks like we're both guilty on that front 😅

I took at look at this and the issue is that the MirrorCheckpointConnector and MirrorSourceConnector instances are generating empty lists of task configs, which makes since since the former never generates tasks during these tests and the latter only generates tasks once a to-be-mirrored topic on the upstream cluster is created, which currently takes place only after our startup check has finished.

Correct me if I'm wrong: the idea here is to add granularity to test failure messages so that we can differentiate between MM2 startup issues (caused by lagginess or connector/task failures) and issues with the actual replication logic performed by MM2. If that's the case, do you think it might make sense to do the following?

  • Alter the "await startup" logic to fail immediately if it detects any failed connectors or tasks
  • Alter the "await startup" logic to operate on a per-connector-type basis, and selectively await the startup of different connector types at different points in the test (e.g., we could await the startup of the heartbeat connector in any place where we currently call waitForMirrorMakersToStart, but only await the startup of the source connector and its tasks once we've created a to-be-replicated topic on the upstream cluster)

@divijvaidya

Copy link
Copy Markdown
Member Author

@C0urante thank you for the suggestions. The new code should be close to what you suggested. The test passes locally for me now. Please feel free to review when you get a chance.

@divijvaidya
divijvaidya requested a review from C0urante June 7, 2023 13:13
@divijvaidya

Copy link
Copy Markdown
Member Author
[Build / JDK 17 and Scala 2.13 / org.apache.kafka.common.security.oauthbearer.internals.secured.RefreshingHttpsJwksTest.testSecondaryRefreshAfterElapsedDelay()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.common.security.oauthbearer.internals.secured/RefreshingHttpsJwksTest/Build___JDK_17_and_Scala_2_13___testSecondaryRefreshAfterElapsedDelay__/)
[Build / JDK 17 and Scala 2.13 / kafka.zk.ZkMigrationIntegrationTest.[1] Type=ZK, Name=testNewAndChangedTopicsInDualWrite, MetadataVersion=3.4-IV0, Security=PLAINTEXT](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/kafka.zk/ZkMigrationIntegrationTest/Build___JDK_17_and_Scala_2_13____1__Type_ZK__Name_testNewAndChangedTopicsInDualWrite__MetadataVersion_3_4_IV0__Security_PLAINTEXT/)
[Build / JDK 17 and Scala 2.13 / org.apache.kafka.trogdor.coordinator.CoordinatorTest.testTaskRequestWithOldStartMsGetsUpdated()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.trogdor.coordinator/CoordinatorTest/Build___JDK_17_and_Scala_2_13___testTaskRequestWithOldStartMsGetsUpdated__/)
[Build / JDK 11 and Scala 2.13 / org.apache.kafka.connect.mirror.integration.MirrorConnectorsIntegrationSSLTest.testSyncTopicConfigs()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.connect.mirror.integration/MirrorConnectorsIntegrationSSLTest/Build___JDK_11_and_Scala_2_13___testSyncTopicConfigs__/)
[Build / JDK 8 and Scala 2.12 / org.apache.kafka.connect.mirror.integration.MirrorConnectorsIntegrationBaseTest.testSyncTopicConfigs()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.connect.mirror.integration/MirrorConnectorsIntegrationBaseTest/Build___JDK_8_and_Scala_2_12___testSyncTopicConfigs__/)
[Build / JDK 17 and Scala 2.13 / org.apache.kafka.controller.QuorumControllerTest.testBalancePartitionLeaders()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.controller/QuorumControllerTest/Build___JDK_17_and_Scala_2_13___testBalancePartitionLeaders__/)
[Build / JDK 11 and Scala 2.13 / org.apache.kafka.controller.QuorumControllerTest.testBalancePartitionLeaders()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.controller/QuorumControllerTest/Build___JDK_11_and_Scala_2_13___testBalancePartitionLeaders__/)
[Build / JDK 8 and Scala 2.12 / org.apache.kafka.controller.QuorumControllerTest.testBalancePartitionLeaders()](https://ci-builds.apache.org/job/Kafka/job/kafka-pr/job/PR-13284/9/testReport/junit/org.apache.kafka.controller/QuorumControllerTest/Build___JDK_8_and_Scala_2_12___testBalancePartitionLeaders___2/)

Test failures are unrelated. @C0urante pinging for review when you get a chance.

viktorsomogyi pushed a commit that referenced this pull request Jun 16, 2023
…e connector tasks (#13819)

Discovered while researching KAFKA-14718

Currently, we perform a check during zombie fencing that causes the round of zombie fencing to fail when a rebalance is pending (i.e., when we've detected from a background poll of the config topic that a new connector has been created, that an existing connector has been deleted, or that a new set of connector tasks has been generated).

It's possible but not especially likely that this check causes issues when running vanilla Kafka Connect. Even when it does, it's easy enough to restart failed tasks via the REST API.

However, when running MirrorMaker 2 in dedicated mode, this check is more likely to cause issues as we write three connector configs to the config topic in rapid succession on startup. And in that mode, there is no API to restart failed tasks aside from restarting the worker that they are hosted on.

In either case, this check can lead to test flakiness in integration tests for MirrorMaker 2 both in dedicated mode and when deployed onto a vanilla Kafka Connect cluster.

This check is not actually necessary, and we can safely remove it. Copied from Jira:

>If the worker that we forward the zombie fencing request to is a zombie leader (i.e., a worker that believes it is the leader but in reality is not), it will fail to finish the round of zombie fencing because it won't be able to write to the config topic with a transactional producer.

>If the connector has just been deleted, we'll still fail the request since we force a read-to-end of the config topic and refresh our snapshot of its contents before checking to see if the connector exists.

>And regardless, the worker that owns the task will still do a read-to-end of the config topic and verify that (1) no new task configs have been generated for the connector and (2) the worker is still assigned the connector, before allowing the task to process any data.

In addition, while waiting on a fix for KAFKA-14718 that adds more granularity for diagnosing failures in the DedicatedMirrorIntegrationTest suite (#13284), some of the timeouts in that test are bumped to work better on our CI infrastructure.

Reviewers: Mickael Maison <mickael.maison@gmail.com>, Yash Mayya <yash.mayya@gmail.com>, Viktor Somogyi-Vass <viktorsomogyi@gmail.com>

@C0urante C0urante left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thanks Divij! One last round of thoughts and then this should be good to go.

@divijvaidya

Copy link
Copy Markdown
Member Author

I had to rebase with trunk to resolve merge conflicts. Changes in latest revision.

1\ Moved awaitMirrorMakerStart into the test cases.
2\ Only check for one mirror maker node to start instead of all of them.
3\ Only check for connector tasks in one MM node instead of all of the nodes.
4\ Use NoRetryException to fail fast in case of a task/connector failure. (Thank you for introducing me to this nice test utility!)
5\ Task/Connector failure is already logged at ERROR level.

This test passes locally. @C0urante ready for review.

@C0urante C0urante left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thanks Divij, LGTM!

@C0urante
C0urante merged commit d9a3e60 into apache:trunk Jul 10, 2023
@divijvaidya

Copy link
Copy Markdown
Member Author

Thank you for your patience on this one @C0urante. Appreciate it!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

mirror-maker-2 tests Test fixes (including flaky tests)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants