otmanel31 opened a new issue #6599: TimeoutException on some client connected
URL: https://github.com/apache/pulsar/issues/6599
 
 
   **TimeoutException on some client connected**
   Since few moments, i face some issues on my standalone pulsar install. It 
ran without any issue until last week.
   
   I need to restart pulsar in order to have a clean pulsar broker but timeout 
exception come back few hours later and some clients are disconnected.
   All clients that are trying to connect are directly disconnected.
   
   For me, it's due to something that happen with topics policies may be.
   
   Any hints about this issue ? is it due to zookeepper ? or something due to 
disk memory ? 
   
   Thanks by advance.
   
   **Piece of Generated exception**
   
   >15:36:37.371 [ForkJoinPool.commonPool-worker-14] INFO  
org.apache.pulsar.broker.service.AbstractTopic - Disabling publish throttling 
for 
persistent://mytenant/agent_namespace/data_up-38e04c4a-f49b-487d-a87e-5cc51f3d7dc4
   15:36:37.368 [pulsar-ordered-OrderedExecutor-5-0] WARN  
org.apache.pulsar.broker.service.BrokerService - Got exception when reading 
persistence policy for 
persistent://my_tenant/agent_namespace/data_up-c8aa8f88-8db6-4fbc-b1cd-c5cf6237a5af:
 null
   java.util.concurrent.TimeoutException: null
           at 
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.get(ZooKeeperDataCache.java:97) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$getManagedLedgerConfig$32(BrokerService.java:922)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.mledger.util.SafeRun$2.safeRun(SafeRun.java:49) 
[org.apache.pulsar-managed-ledger-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) 
[org.apache.bookkeeper-bookkeeper-common-4.10.0.jar:4.10.0]
           at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) 
[?:1.8.0_232]
           at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 
[?:1.8.0_232]
           at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
           at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]
   15:36:37.368 [pulsar-ordered-OrderedExecutor-6-0] WARN  
org.apache.pulsar.broker.service.BrokerService - Got exception when reading 
persistence policy for 
persistent://mytenant/agent_namespace/action_down-11844a57-10ab-415a-9d1a-4c3017a588b3:
 null
   java.util.concurrent.TimeoutException: null
           at 
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.get(ZooKeeperDataCache.java:97) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$getManagedLedgerConfig$32(BrokerService.java:922)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.mledger.util.SafeRun$2.safeRun(SafeRun.java:49) 
[org.apache.pulsar-managed-ledger-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) 
[org.apache.bookkeeper-bookkeeper-common-4.10.0.jar:4.10.0]
           at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) 
[?:1.8.0_232]
           at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 
[?:1.8.0_232]
           at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
           at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]
   15:36:37.379 [pulsar-ordered-OrderedExecutor-6-0] WARN  
org.apache.pulsar.broker.service.persistent.PersistentTopic - 
[persistent://mytenant/agent_namespace/action_down-11844a57-10ab-415a-9d1a-4c3017a588b3]
 Failed to update persistence-policies java.util.concurrent.TimeoutException
   15:36:37.379 [pulsar-ordered-OrderedExecutor-5-0] WARN  
org.apache.pulsar.broker.service.persistent.PersistentTopic - 
[persistent://mytenant/agent_namespace/data_up-c8aa8f88-8db6-4fbc-b1cd-c5cf6237a5af]
 Failed to update persistence-policies java.util.concurrent.TimeoutException
   15:36:38.903 [pulsar-web-57-9] INFO  org.eclipse.jetty.server.RequestLog - 
xx.xxx.xxx.xxx - - [24/Mar/2020:15:36:38 +0000] "GET /metrics HTTP/1.1" 302 0 
"-" "Prometheus/2.16.0" 1
   15:36:38.906 [pulsar-web-57-14] INFO  org.eclipse.jetty.server.RequestLog - 
xx.xxx.xxx.xxx - - [24/Mar/2020:15:36:08 +0000] "GET /metrics/ HTTP/1.1" 500 
331 "http://xx.xxx.xxxx.xxxx:8082/metrics"; "Prometheus/2.16.0" 30002
   15:36:53.904 [pulsar-web-57-18] INFO  org.eclipse.jetty.server.RequestLog - 
xx.xxx.xxx.xxx - - [24/Mar/2020:15:36:53 +0000] "GET /metrics HTTP/1.1" 302 0 
"-" "Prometheus/2.16.0" 1
   15:36:53.906 [pulsar-web-57-19] INFO  org.eclipse.jetty.server.RequestLog - 
xx.xxx.xxx.xxx - - [24/Mar/2020:15:36:23 +0000] "GET /metrics/ HTTP/1.1" 500 
331 "http://xx.xxx.xxx.xxx:8082/metrics"; "Prometheus/2.16.0" 30002
   15:37:07.366 [prometheus-stats-69-1] ERROR 
org.apache.pulsar.broker.service.BacklogQuotaManager - Failed to read policies 
data, will apply the default backlog quota: namespace=mytenant/agent_namespace
   java.util.concurrent.TimeoutException: null
           at 
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.get(ZooKeeperDataCache.java:97) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BacklogQuotaManager.getBacklogQuota(BacklogQuotaManager.java:64)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.persistent.PersistentTopic.getBacklogQuota(PersistentTopic.java:1746)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.NamespaceStatsAggregator.getTopicStats(NamespaceStatsAggregator.java:96)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.NamespaceStatsAggregator.lambda$null$0(NamespaceStatsAggregator.java:64)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:385)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:159)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.NamespaceStatsAggregator.lambda$null$1(NamespaceStatsAggregator.java:63)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:385)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:159)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.NamespaceStatsAggregator.lambda$generate$2(NamespaceStatsAggregator.java:62)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:385)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:159)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.NamespaceStatsAggregator.generate(NamespaceStatsAggregator.java:59)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.PrometheusMetricsGenerator.generate(PrometheusMetricsGenerator.java:73)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.stats.prometheus.PrometheusMetricsServlet.lambda$doGet$0(PrometheusMetricsServlet.java:70)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.mledger.util.SafeRun$1.safeRun(SafeRun.java:32) 
[org.apache.pulsar-managed-ledger-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) 
[org.apache.bookkeeper-bookkeeper-common-4.10.0.jar:4.10.0]
           at 
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) 
[?:1.8.0_232]
           at java.util.concurrent.FutureTask.run(FutureTask.java:266) 
[?:1.8.0_232]
           at 
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
 [?:1.8.0_232]
           at 
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
 [?:1.8.0_232]
           at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) 
[?:1.8.0_232]
           at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 
[?:1.8.0_232]
           at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
           at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]
   15:37:07.368 [pulsar-ordered-OrderedExecutor-0-0] WARN  
org.apache.pulsar.broker.service.BrokerService - Got exception when reading 
persistence policy for 
persistent://mytenant/agent_namespace/data_up-8498c9ea-0d9f-446a-9efe-9990d3c26293:
 null
   java.util.concurrent.TimeoutException: null
           at 
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.get(ZooKeeperDataCache.java:97) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$getManagedLedgerConfig$32(BrokerService.java:922)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.mledger.util.SafeRun$2.safeRun(SafeRun.java:49) 
[org.apache.pulsar-managed-ledger-2.5.0.jar:2.5.0]
           at 
org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) 
[org.apache.bookkeeper-bookkeeper-common-4.10.0.jar:4.10.0]
           at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) 
[?:1.8.0_232]
           at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 
[?:1.8.0_232]
           at 
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
           at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]
   15:37:07.368 [pulsar-ordered-OrderedExecutor-0-0] WARN  
org.apache.pulsar.broker.service.persistent.PersistentTopic - 
[persistent://mytenant/agent_namespace/data_up-8498c9ea-0d9f-446a-9efe-9990d3c26293]
 Failed to update persistence-policies java.util.concurrent.TimeoutException
   15:37:07.368 [ForkJoinPool.commonPool-worker-9] ERROR 
org.apache.pulsar.broker.service.persistent.PersistentTopic - 
[persistent://mytenant/agent_namespace/data_down-c6a8df26-acce-45bd-8704-974f73b237f3]
 Policies update failed 
org.apache.pulsar.broker.service.BrokerServiceException$ServerMetadataException:
 java.util.concurrent.TimeoutException, scheduled retry in 60 seconds
   java.util.concurrent.CompletionException: 
org.apache.pulsar.broker.service.BrokerServiceException$ServerMetadataException:
 java.util.concurrent.TimeoutException
           at 
java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:661) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:683)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2010) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.broker.service.persistent.PersistentTopic.checkReplicationAndRetryOnFailure(PersistentTopic.java:976)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.persistent.PersistentTopic.onPoliciesUpdate(PersistentTopic.java:1722)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$null$48(BrokerService.java:1309)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at java.util.Optional.ifPresent(Optional.java:159) ~[?:1.8.0_232]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$null$49(BrokerService.java:1309)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:670) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:683)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2010) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.broker.service.BrokerService.lambda$onUpdate$50(BrokerService.java:1304)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:385)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:159)
 ~[org.apache.pulsar-pulsar-common-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.onUpdate(BrokerService.java:1300)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.BrokerService.onUpdate(BrokerService.java:151) 
~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.lambda$4(ZooKeeperDataCache.java:138)
 ~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:670) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:646)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperCache.lambda$18(ZooKeeperCache.java:374) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:670) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:646)
 ~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperCache.lambda$14(ZooKeeperCache.java:355) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
 [?:1.8.0_232]
           at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) 
[?:1.8.0_232]
           at 
java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056) 
[?:1.8.0_232]
           at 
java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692) 
[?:1.8.0_232]
           at 
java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157) 
[?:1.8.0_232]
   Caused by: 
org.apache.pulsar.broker.service.BrokerServiceException$ServerMetadataException:
 java.util.concurrent.TimeoutException
           at 
org.apache.pulsar.broker.service.persistent.PersistentTopic.checkReplication(PersistentTopic.java:1030)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           ... 29 more
   Caused by: java.util.concurrent.TimeoutException
           at 
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784) 
~[?:1.8.0_232]
           at 
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) 
~[?:1.8.0_232]
           at 
org.apache.pulsar.zookeeper.ZooKeeperDataCache.get(ZooKeeperDataCache.java:97) 
~[org.apache.pulsar-pulsar-zookeeper-utils-2.5.0.jar:2.5.0]
           at 
org.apache.pulsar.broker.service.persistent.PersistentTopic.checkReplication(PersistentTopic.java:1026)
 ~[org.apache.pulsar-pulsar-broker-2.5.0.jar:2.5.0]
           ... 29 more
   
    - ServerOS: centos7
    - client: linux or windows
   
   
   

----------------------------------------------------------------
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.
 
For queries about this service, please contact Infrastructure at:
[email protected]


With regards,
Apache Git Services

Reply via email to