[GitHub] [pulsar] tomscut commented on issue #12333: Flaky-test: org.apache.pulsar.broker.admin.TopicPoliciesTest.testDisableSubscribeRate

[GitBox <gi...@apache.org>]

tomscut commented on issue #12333:
URL: https://github.com/apache/pulsar/issues/12333#issuecomment-941895520


   @eolivelli @nicoloboschi @lordcheng10 
   I found that the internal execution time was greater than the default 10s.
   When updating the code from 
   ```
   Awaitility.await().untilAsserted(()-> {
               Optional<SubscribeRateLimiter> limiter1 = (Optional<SubscribeRateLimiter>) field.get(topic);
               assertTrue(limiter1.isPresent());
           });
   ```
   to 
   ```
   Awaitility.waitAtMost(PulsarResources.DEFAULT_OPERATION_TIMEOUT_SEC + 1, TimeUnit.SECONDS).untilAsserted(()-> {
               Optional<SubscribeRateLimiter> limiter1 = (Optional<SubscribeRateLimiter>) field.get(topic);
               assertTrue(limiter1.isPresent());
           });
   ```
   we can see following log
   ```
   2021-10-13T11:53:24,107+0800 [metadata-store-10-1] WARN  org.apache.pulsar.broker.service.persistent.DispatchRateLimiter - Failed to get message-rate for persistent://my-tenant/my-namespace/test-set-backlog-quota-partition-1 
   org.apache.pulsar.metadata.api.MetadataStoreException: Failed to get data from /admin/policies/my-tenant/my-namespace
   	at org.apache.pulsar.broker.resources.BaseResources.get(BaseResources.java:91) ~[classes/:?]
   	at org.apache.pulsar.broker.resources.NamespaceResources.getPolicies(NamespaceResources.java:105) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.DispatchRateLimiter.getPolicies(DispatchRateLimiter.java:324) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.getPoliciesSubscribeRate(SubscribeRateLimiter.java:237) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.getPoliciesSubscribeRate(SubscribeRateLimiter.java:215) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.<init>(SubscribeRateLimiter.java:60) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.PersistentTopic.initializeRateLimiterIfNeeded(PersistentTopic.java:379) ~[classes/:?]
   	at org.apache.pulsar.broker.service.persistent.PersistentTopic.onPoliciesUpdate(PersistentTopic.java:2409) ~[classes/:?]
   	at org.apache.pulsar.broker.service.BrokerService.lambda$null$80(BrokerService.java:1798) ~[classes/:?]
   	at java.util.Optional.ifPresent(Optional.java:159) ~[?:1.8.0_221]
   	at org.apache.pulsar.broker.service.BrokerService.lambda$null$81(BrokerService.java:1798) ~[classes/:?]
   	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:669) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:1997) ~[?:1.8.0_221]
   	at org.apache.pulsar.broker.service.BrokerService.lambda$null$82(BrokerService.java:1793) ~[classes/:?]
   	at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:387) ~[classes/:?]
   	at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:159) ~[classes/:?]
   	at org.apache.pulsar.broker.service.BrokerService.lambda$handlePoliciesUpdates$83(BrokerService.java:1789) ~[classes/:?]
   	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962) ~[?:1.8.0_221]
   	at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$null$7(ZKMetadataStore.java:139) ~[classes/:?]
   	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_221]
   	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_221]
   	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.68.Final.jar:4.1.68.Final]
   	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
   Caused by: java.util.concurrent.TimeoutException
   	at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771) ~[?:1.8.0_221]
   	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915) ~[?:1.8.0_221]
   	at org.apache.pulsar.broker.resources.BaseResources.get(BaseResources.java:86) ~[classes/:?]
   	... 26 more
   ```.
   
   The code that causes the timeout is here ```getAsync(path).get(operationTimeoutSec, TimeUnit.SECONDS)```
   ```
       protected Optional<T> get(String path) throws MetadataStoreException {
           try {
               return getAsync(path).get(operationTimeoutSec, TimeUnit.SECONDS);
           } catch (ExecutionException e) {
               throw (e.getCause() instanceof MetadataStoreException) ? (MetadataStoreException) e.getCause()
                       : new MetadataStoreException(e.getCause());
           } catch (Exception e) {
               throw new MetadataStoreException("Failed to get data from " + path, e);
           }
       }
   ```
   


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org