Flaky-test: BrokerRegistryMetadataStoreIntegrationTest.cleanup

[lhotari]

Search before asking

• I searched in the issues and found nothing similar.

Example failure

https://github.com/apache/pulsar/actions/runs/11231028428/job/31223989424?pr=23410#step:11:1773

Logs: https://gist.github.com/lhotari/f8271c5229f85862c5a471e56a2c56c9

Exception stacktrace

  Error:  Tests run: 3, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 69.073 s <<< FAILURE! - in org.apache.pulsar.broker.loadbalance.extensions.BrokerRegistryMetadataStoreIntegrationTest
  Error:  org.apache.pulsar.broker.loadbalance.extensions.BrokerRegistryMetadataStoreIntegrationTest.cleanup  Time elapsed: 62.361 s  <<< FAILURE!
  java.lang.RuntimeException: Broker took 61822ms to close
  	at org.apache.pulsar.broker.loadbalance.extensions.BrokerRegistryIntegrationTest.cleanup(BrokerRegistryIntegrationTest.java:73)
  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
  	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
  	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
  	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethodConsideringTimeout(MethodInvocationHelper.java:69)
  	at org.testng.internal.invokers.ConfigInvoker.invokeConfigurationMethod(ConfigInvoker.java:361)
  	at org.testng.internal.invokers.ConfigInvoker.invokeConfigurations(ConfigInvoker.java:296)
  	at org.testng.internal.invokers.TestMethodWorker.invokeAfterClassMethods(TestMethodWorker.java:222)
  	at org.testng.internal.invokers.TestMethodWorker.run(TestMethodWorker.java:131)
  	at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
  	at org.testng.TestRunner.privateRun(TestRunner.java:829)
  	at org.testng.TestRunner.run(TestRunner.java:602)
  	at org.testng.SuiteRunner.runTest(SuiteRunner.java:437)
  	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:431)
  	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:391)
  	at org.testng.SuiteRunner.run(SuiteRunner.java:330)
  	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
  	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:95)
  	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1256)
  	at org.testng.TestNG.runSuitesLocally(TestNG.java:1176)
  	at org.testng.TestNG.runSuites(TestNG.java:1099)
  	at org.testng.TestNG.run(TestNG.java:1067)
  	at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:155)
  	at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeSingleClass(TestNGDirectoryTestSuite.java:102)
  	at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeLazy(TestNGDirectoryTestSuite.java:117)
  	at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:86)
  	at org.apache.maven.surefire.testng.TestNGProvider.invoke(TestNGProvider.java:137)
  	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
  	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
  	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
  	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)

Are you willing to submit a PR?

• I'm willing to submit a PR!

[lhotari]

This flaky test was introduced in #23371. @heesung-sn please take a look. /cc @BewareMyPower

[BewareMyPower]

I believe there was a regression introduced recently.

When I upgraded the latest master in the downstream project, I found the broker close time became too long.

21:19:33.487 [main:io.streamnative.pulsar.handlers.kop.KsnCluster@182] INFO  io.streamnative.pulsar.handlers.kop.KsnCluster - Stopping broker 0...
21:19:40.842 [main:io.streamnative.pulsar.handlers.kop.KsnCluster@184] INFO  io.streamnative.pulsar.handlers.kop.KsnCluster - Stopped broker 0
21:19:40.842 [main:io.streamnative.pulsar.handlers.kop.KsnCluster@182] INFO  io.streamnative.pulsar.handlers.kop.KsnCluster - Stopping broker 1...
21:19:48.185 [main:io.streamnative.pulsar.handlers.kop.KsnCluster@184] INFO  io.streamnative.pulsar.handlers.kop.KsnCluster - Stopped broker 1

There are two brokers that each of them takes 7+ seconds to complete the close.

[BewareMyPower]

2024-10-10T18:14:59,125 - INFO  - [pulsar-load-manager-22-1:ServiceUnitStateChannelImpl] - XYZ start health check for localhost:65430
2024-10-10T18:15:29,187 - INFO  - [AsyncHttpClient-63-2:ServiceUnitStateChannelImpl] - XYZ failed health check localhost:65430

            log.info("XYZ start health check for {}", brokerId);
            admin.brokers().healthcheckAsync(TopicVersion.V2, Optional.of(brokerId))
                    .whenComplete((__, e) -> {
                        if (e == null) {
                            log.info("XYZ Completed health-check broker :{}", brokerId, e);
                            future.complete(null);
                            return;
                        }
                        log.info("XYZ failed health check {}", brokerId, e);

I added some logs and found the healthcheckAsync call could take 30 seconds to complete, which also blocks the server.stop() in WebServer#close.