You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by GitBox <gi...@apache.org> on 2019/06/10 12:45:31 UTC
[GitHub] [pulsar] codelipenghui opened a new issue #4503: Consumer stop
consume messages in Exclusive subscription
codelipenghui opened a new issue #4503: Consumer stop consume messages in Exclusive subscription
URL: https://github.com/apache/pulsar/issues/4503
**Describe the bug**
Subscription has backlog but consumer can't consume messages.
Here is topic internal stats:
```
{
"entriesAddedCounter" : 441007,
"numberOfEntries" : 441006,
"totalSize" : 192462854,
"currentLedgerEntries" : 41006,
"currentLedgerSize" : 17684520,
"lastLedgerCreatedTimestamp" : "2019-06-09T21:27:41.34+08:00",
"waitingCursorsCount" : 0,
"pendingAddEntriesCount" : 0,
"lastConfirmedEntry" : "35422:41005",
"state" : "LedgerOpened",
"ledgers" : [ {
"ledgerId" : 35080,
"entries" : 50000,
"size" : 21842638,
"offloaded" : false
}, {
"ledgerId" : 35138,
"entries" : 50000,
"size" : 21962861,
"offloaded" : false
}, {
"ledgerId" : 35180,
"entries" : 50000,
"size" : 21873789,
"offloaded" : false
}, {
"ledgerId" : 35217,
"entries" : 50000,
"size" : 21909420,
"offloaded" : false
}, {
"ledgerId" : 35248,
"entries" : 50000,
"size" : 21858432,
"offloaded" : false
}, {
"ledgerId" : 35288,
"entries" : 50000,
"size" : 21754235,
"offloaded" : false
}, {
"ledgerId" : 35336,
"entries" : 50000,
"size" : 21736912,
"offloaded" : false
}, {
"ledgerId" : 35374,
"entries" : 50000,
"size" : 21840047,
"offloaded" : false
}, {
"ledgerId" : 35422,
"entries" : 0,
"size" : 0,
"offloaded" : false
} ],
"cursors" : {
"test-sub" : {
"markDeletePosition" : "35422:36450",
"readPosition" : "35422:36451",
"waitingReadOp" : false,
"pendingReadOps" : 1,
"messagesConsumedCounter" : 436452,
"cursorLedger" : 35405,
"cursorLedgerLastEntry" : 10782,
"individuallyDeletedMessages" : "[]",
"lastLedgerSwitchTimestamp" : "2019-06-09T20:43:41.812+08:00",
"state" : "Open",
"numberOfEntriesSinceFirstNotAckedMessage" : 1,
"totalNonContiguousDeletedMessagesRange" : 0,
"properties" : { }
}
}
}
```
and topic stats:
```
{
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"averageMsgSize" : 0.0,
"storageSize" : 1974139,
"publishers" : [ {
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"averageMsgSize" : 0.0,
"producerId" : 9,
"metadata" : { },
"producerName" : "65-2103",
"connectedSince" : "2019-06-08T20:43:38.072+08:00",
"clientVersion" : "2.3.1",
"address" : "/10.1.1.130:58110"
}, {
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"averageMsgSize" : 0.0,
"producerId" : 16,
"metadata" : { },
"producerName" : "65-2105",
"connectedSince" : "2019-06-08T20:43:39.287+08:00",
"clientVersion" : "2.3.1",
"address" : "/10.1.2.239:34895"
}, {
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"averageMsgSize" : 0.0,
"producerId" : 17,
"metadata" : { },
"producerName" : "65-2106",
"connectedSince" : "2019-06-08T20:43:40.458+08:00",
"clientVersion" : "2.3.1",
"address" : "/10.1.1.63:3963"
}, {
"msgRateIn" : 0.0,
"msgThroughputIn" : 0.0,
"averageMsgSize" : 0.0,
"producerId" : 27,
"metadata" : { },
"producerName" : "65-2104",
"connectedSince" : "2019-06-08T20:43:38.111+08:00",
"clientVersion" : "2.3.1",
"address" : "/10.1.2.165:43102"
} ],
"subscriptions" : {
"test-sub" : {
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"msgRateRedeliver" : 0.0,
"msgBacklog" : 4555,
"blockedSubscriptionOnUnackedMsgs" : false,
"unackedMessages" : 0,
"type" : "Exclusive",
"activeConsumerName" : "61d6d",
"msgRateExpired" : 0.0,
"consumers" : [ {
"msgRateOut" : 0.0,
"msgThroughputOut" : 0.0,
"msgRateRedeliver" : 0.0,
"consumerName" : "61d6d",
"availablePermits" : 1000,
"unackedMessages" : 0,
"blockedConsumerOnUnackedMsgs" : false,
"metadata" : { },
"connectedSince" : "2019-06-10T01:12:51.666+08:00",
"clientVersion" : "2.3.1",
"address" : "/10.1.1.226:48925"
} ]
}
},
"replication" : { },
"deduplicationStatus" : "Disabled"
}
```
When i peek messages by pulsar admin, i got timeout error. check the broker's log, found some exceptions logs:
```
20:06:39.464 [bookkeeper-ml-scheduler-OrderedScheduler-1-0] WARN org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/113]-35422 read entry timeout for 36451-36451 after 120 sec
20:06:39.464 [bookkeeper-ml-scheduler-OrderedScheduler-1-0] WARN org.apache.bookkeeper.mledger.impl.OpReadEntry - [public/default/persistent/113][test-sub] read failed from ledger at position:35422:36451 : Bookie operation timeout
20:06:39.464 [broker-topic-workers-OrderedScheduler-5-0] ERROR org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer - [persistent://public/default/113 / test-sub-Consumer{subscription=PersistentSubscription{topic=persistent://public/default/113, name=test-sub}, consumerId=69167, consumerName=61d6d, address=/10.1.1.226:48925}] Error reading entries at 35422:36451 : Bookie operation timeout - Retrying to read in 59.0 seconds
20:06:50.674 [pulsar-web-28-15] INFO org.eclipse.jetty.server.RequestLog - 10.1.2.2 - - [10/Jun/2019:20:06:50 +0800] "GET /metrics HTTP/1.1" 302 0 "-" "Prometheus/2.7.2" 0
20:06:50.679 [prometheus-stats-37-1] INFO org.eclipse.jetty.server.RequestLog - 10.1.2.2 - - [10/Jun/2019:20:06:50 +0800] "GET /metrics/ HTTP/1.1" 200 156435 "http://10.1.2.88:7790/metrics" "Prometheus/2.7.2" 5
20:06:58.380 [bookkeeper-ml-scheduler-OrderedScheduler-6-0] WARN org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/113]-35422 read entry timeout for 35422:36451 after 120 sec
20:06:58.380 [pulsar-web-28-18] ERROR org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [null] Failed to get message at position 1 from persistent://public/default/113 test-sub
java.util.concurrent.ExecutionException: org.apache.bookkeeper.mledger.ManagedLedgerException: Bookie operation timeout
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_121]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_121]
at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalPeekNthMessage(PersistentTopicsBase.java:1045) ~[org.apache.pulsar-pulsar-broker-2.3.2.jar:2.3.2]
at org.apache.pulsar.broker.admin.v2.PersistentTopics.peekNthMessage(PersistentTopics.java:417) ~[org.apache.pulsar-pulsar-broker-2.3.2.jar:2.3.2]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_121]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_121]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_121]
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:76) ~[org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:148) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:191) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:200) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:103) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:493) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:415) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:104) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:277) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:272) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:268) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:316) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:298) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:268) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:289) [org.glassfish.jersey.core-jersey-common-2.27.jar:?]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:256) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:703) [org.glassfish.jersey.core-jersey-server-2.27.jar:?]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:416) [org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) [org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) [org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) [org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) [org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) [org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655) [org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:53) [org.apache.pulsar-pulsar-broker-2.3.2.jar:2.3.2]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) [org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533) [org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1340) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) [org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1242) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:174) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.Server.handle(Server.java:503) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [org.eclipse.jetty-jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [org.eclipse.jetty-jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [org.eclipse.jetty-jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
Caused by: org.apache.bookkeeper.mledger.ManagedLedgerException: Bookie operation timeout
20:07:38.465 [broker-topic-workers-OrderedScheduler-5-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught
java.lang.ArrayIndexOutOfBoundsException: null
```
**Pulsar version**
broker: 2.3.2
client: 2.3.1
----------------------------------------------------------------
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:
users@infra.apache.org
With regards,
Apache Git Services