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 2021/08/14 00:59:00 UTC
[GitHub] [pulsar] leizhiyuan edited a comment on issue #11652: deadLetterPolicy is not working with key shared subscription
leizhiyuan edited a comment on issue #11652:
URL: https://github.com/apache/pulsar/issues/11652#issuecomment-898784711
in DeadLetterTopicTest
I add a testcase
```
@Test(groups = "quarantine")
public void testDeadLetterKeyTopic() throws Exception {
final String topic = "persistent://my-property/my-ns/dead-letter-topic";
final int maxRedeliveryCount = 1;
final int sendMessages = 1;
Consumer<byte[]> consumer = pulsarClient.newConsumer(Schema.BYTES)
.topic(topic)
.subscriptionName("my-subscription")
.subscriptionType(SubscriptionType.Key_Shared)
.keySharedPolicy(KeySharedPolicy.autoSplitHashRange())
.ackTimeout(1, TimeUnit.SECONDS)
.deadLetterPolicy(DeadLetterPolicy.builder().maxRedeliverCount(maxRedeliveryCount).build())
.receiverQueueSize(100)
.subscriptionInitialPosition(SubscriptionInitialPosition.Earliest)
.subscribe();
@Cleanup
PulsarClient newPulsarClient = newPulsarClient(lookupUrl.toString(), 0);// Creates new client connection
Consumer<byte[]> deadLetterConsumer = newPulsarClient.newConsumer(Schema.BYTES)
.topic("persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ")
.subscriptionName("my-subscription")
.subscriptionInitialPosition(SubscriptionInitialPosition.Earliest)
.subscribe();
Producer<byte[]> producer = pulsarClient.newProducer(Schema.BYTES)
.topic(topic)
.create();
for (int i = 0; i < sendMessages; i++) {
producer.send(String.format("Hello Pulsar [%d]", i).getBytes());
}
producer.close();
int totalReceived = 0;
do {
Message<byte[]> message = consumer.receive();
log.info("consumer received message : {} {}", message.getMessageId(), new String(message.getData()));
totalReceived++;
} while (totalReceived < sendMessages * (maxRedeliveryCount + 10));
}
```
It seems can not reproduce this issue.
```
08:52:16.839 [pulsar-web-29-4] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:16 +0800] "GET /admin/v2/persistent/my-property/my-ns/dead-letter-topic/partitions?checkAllowAutoCreation=true HTTP/1.1" 200 16 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 164
08:52:16.965 [metadata-store-8-1] INFO org.apache.pulsar.common.naming.NamespaceBundleFactory - Policy updated for namespace my-property/my-ns, refreshing the bundle cache.
08:52:16.968 [metadata-store-8-1] ERROR org.apache.pulsar.metadata.impl.AbstractMetadataStore - Failed to process metadata store notification
java.lang.IllegalArgumentException: Invalid namespace format. expected <tenant>/<namespace> or <tenant>/<cluster>/<namespace> but got: my-property
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:125) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:34) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:46) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:43) ~[classes/:?]
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.get(LocalCache.java:3951) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3974) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4935) ~[guava-30.1-jre.jar:?]
at org.apache.pulsar.common.naming.NamespaceName.get(NamespaceName.java:69) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceBundleFactory.handleMetadataStoreNotification(NamespaceBundleFactory.java:162) ~[classes/:?]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$null$0(AbstractMetadataStore.java:149) ~[classes/:?]
at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:895) ~[?:1.8.0_292]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedNotification$1(AbstractMetadataStore.java:147) ~[classes/:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_292]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.66.Final.jar:4.1.66.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]
Caused by: java.lang.IllegalArgumentException: Invalid namespace format. namespace: my-property
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:122) ~[classes/:?]
... 20 more
08:52:16.977 [metadata-store-8-1] ERROR org.apache.pulsar.metadata.impl.AbstractMetadataStore - Failed to process metadata store notification
java.lang.IllegalArgumentException: Invalid namespace format. expected <tenant>/<namespace> or <tenant>/<cluster>/<namespace> but got: my-property
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:125) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:34) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:46) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:43) ~[classes/:?]
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.get(LocalCache.java:3951) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3974) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4935) ~[guava-30.1-jre.jar:?]
at org.apache.pulsar.common.naming.NamespaceName.get(NamespaceName.java:69) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceBundleFactory.handleMetadataStoreNotification(NamespaceBundleFactory.java:162) ~[classes/:?]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$null$0(AbstractMetadataStore.java:149) ~[classes/:?]
at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:895) ~[?:1.8.0_292]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedNotification$1(AbstractMetadataStore.java:147) ~[classes/:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_292]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.66.Final.jar:4.1.66.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]
Caused by: java.lang.IllegalArgumentException: Invalid namespace format. namespace: my-property
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:122) ~[classes/:?]
... 20 more
08:52:16.978 [metadata-store-8-1] ERROR org.apache.pulsar.metadata.impl.AbstractMetadataStore - Failed to process metadata store notification
java.lang.IllegalArgumentException: Invalid null namespace:
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:97) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:34) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:46) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:43) ~[classes/:?]
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.get(LocalCache.java:3951) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3974) ~[guava-30.1-jre.jar:?]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4935) ~[guava-30.1-jre.jar:?]
at org.apache.pulsar.common.naming.NamespaceName.get(NamespaceName.java:69) ~[classes/:?]
at org.apache.pulsar.common.naming.NamespaceBundleFactory.handleMetadataStoreNotification(NamespaceBundleFactory.java:162) ~[classes/:?]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$null$0(AbstractMetadataStore.java:149) ~[classes/:?]
at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:895) ~[?:1.8.0_292]
at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedNotification$1(AbstractMetadataStore.java:147) ~[classes/:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_292]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_292]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.66.Final.jar:4.1.66.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]
08:52:17.026 [pulsar-4-4] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - 1 brokers being considered for assignment of my-property/my-ns/0x00000000_0xffffffff
08:52:17.032 [pulsar-4-4] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Trying to acquire ownership of my-property/my-ns/0x00000000_0xffffffff
08:52:17.045 [metadata-store-8-1] INFO org.apache.pulsar.metadata.coordination.impl.ResourceLockImpl - Acquired resource lock on /namespace/my-property/my-ns/0x00000000_0xffffffff
08:52:17.045 [metadata-store-8-1] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Successfully acquired ownership of OwnedBundle(bundle=my-property/my-ns/0x00000000_0xffffffff, isActive=1)
08:52:17.062 [metadata-store-8-1] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:16 +0800] "GET /lookup/v2/topic/persistent/my-property/my-ns/dead-letter-topic HTTP/1.1" 200 217 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 179
08:52:17.150 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ConnectionPool - [[id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141]] Connected to server
08:52:17.172 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - New connection from /127.0.0.1:53148
08:52:17.178 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/dead-letter-topic][my-subscription] Subscribing to topic on cnx [id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141], consumerId 0
08:52:17.182 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [0] On [SUBSCRIBE] Pulsar command
08:52:17.191 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] Subscribing on topic persistent://my-property/my-ns/dead-letter-topic / my-subscription
08:52:17.279 [metadata-store-8-1] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger my-property/my-ns/persistent/dead-letter-topic
08:52:17.288 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - Creating '/managed-ledgers/my-property/my-ns/persistent/dead-letter-topic'
08:52:17.289 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.zookeeper.ZooKeeperCache - [MockZookeeper] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeCreated path:/managed-ledgers/my-property/my-ns/persistent/dead-letter-topic
08:52:17.305 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[109, 121, 45, 112, 114, 111, 112, 101, 114, 116, 121, 47, 109, 121, 45, 110, 115, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 100, 101, 97, 100, 45, 108, 101, 116, 116, 101, 114, 45, 116, 111, 112, 105, 99], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
08:52:17.311 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.client.PulsarMockBookKeeper - Creating ledger 3
08:52:17.360 [mock-pulsar-bk-OrderedExecutor-0-0] WARN org.apache.bookkeeper.proto.checksum.CRC32CDigestManager - Sse42Crc32C is not supported, will use a slower CRC32C implementation.
08:52:17.370 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic] Created ledger 3
08:52:17.396 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [my-property/my-ns/persistent/dead-letter-topic] Successfully initialize managed ledger
08:52:17.418 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.AbstractTopic - Disabling publish throttling for persistent://my-property/my-ns/dead-letter-topic
08:52:17.428 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic] There are no replicated subscriptions on the topic
08:52:17.438 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://my-property/my-ns/dead-letter-topic - dedup is disabled
08:52:17.464 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic] Cursor my-subscription recovered to position 3:-1
08:52:17.471 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[109, 121, 45, 112, 114, 111, 112, 101, 114, 116, 121, 47, 109, 121, 45, 110, 115, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 100, 101, 97, 100, 45, 108, 101, 116, 116, 101, 114, 45, 116, 111, 112, 105, 99], pulsar/cursor=[109, 121, 45, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
08:52:17.472 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.client.PulsarMockBookKeeper - Creating ledger 4
08:52:17.492 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - [my-property/my-ns/persistent/dead-letter-topic] [my-subscription] Updating cursor info ledgerId=4 mark-delete=3:-1
08:52:17.494 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic] Updated cursor my-subscription with ledger id 4 md-position=3:-1 rd-position=3:0
08:52:17.495 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic] Opened new cursor: ManagedCursorImpl{ledger=my-property/my-ns/persistent/dead-letter-topic, name=my-subscription, ackPos=3:-1, readPos=3:0}
08:52:17.528 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription] Rewind from 3:0 to 3:0
08:52:17.532 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic] There are no replicated subscriptions on the topic
08:52:17.532 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic][my-subscription] Created new subscription for 0
08:52:17.532 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] Created subscription on topic persistent://my-property/my-ns/dead-letter-topic / my-subscription
08:52:17.533 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [1] On [SUCCESS] Pulsar command
08:52:17.534 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/dead-letter-topic][my-subscription] Subscribed to topic on localhost/127.0.0.1:53141 -- consumer: 0
08:52:17.576 [pulsar-web-29-7] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:17 +0800] "GET /admin/v2/persistent/my-property/my-ns/dead-letter-topic-my-subscription-DLQ/partitions?checkAllowAutoCreation=true HTTP/1.1" 200 16 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 23
08:52:17.610 [pulsar-web-29-8] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:17 +0800] "GET /lookup/v2/topic/persistent/my-property/my-ns/dead-letter-topic-my-subscription-DLQ HTTP/1.1" 200 217 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 15
08:52:17.641 [pulsar-client-io-44-1] INFO org.apache.pulsar.client.impl.ConnectionPool - [[id: 0xf74125a5, L:/127.0.0.1:53150 - R:localhost/127.0.0.1:53141]] Connected to server
08:52:17.655 [pulsar-io-6-3] INFO org.apache.pulsar.broker.service.ServerCnx - New connection from /127.0.0.1:53150
08:52:17.657 [pulsar-client-io-44-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ][my-subscription] Subscribing to topic on cnx [id: 0xf74125a5, L:/127.0.0.1:53150 - R:localhost/127.0.0.1:53141], consumerId 0
08:52:17.661 [pulsar-io-6-3] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [2] On [SUBSCRIBE] Pulsar command
08:52:17.661 [pulsar-io-6-3] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53150] Subscribing on topic persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ / my-subscription
08:52:17.667 [pulsar-io-6-3] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ
08:52:17.669 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - Creating '/managed-ledgers/my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ'
08:52:17.670 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.zookeeper.ZooKeeperCache - [MockZookeeper] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeCreated path:/managed-ledgers/my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ
08:52:17.672 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[109, 121, 45, 112, 114, 111, 112, 101, 114, 116, 121, 47, 109, 121, 45, 110, 115, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 100, 101, 97, 100, 45, 108, 101, 116, 116, 101, 114, 45, 116, 111, 112, 105, 99, 45, 109, 121, 45, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110, 45, 68, 76, 81], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
08:52:17.674 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.client.PulsarMockBookKeeper - Creating ledger 5
08:52:17.674 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Created ledger 5
08:52:17.677 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Successfully initialize managed ledger
08:52:17.678 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.AbstractTopic - Disabling publish throttling for persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ
08:52:17.679 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ] There are no replicated subscriptions on the topic
08:52:17.681 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ - dedup is disabled
08:52:17.683 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Cursor my-subscription recovered to position 5:-1
08:52:17.685 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[109, 121, 45, 112, 114, 111, 112, 101, 114, 116, 121, 47, 109, 121, 45, 110, 115, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 100, 101, 97, 100, 45, 108, 101, 116, 116, 101, 114, 45, 116, 111, 112, 105, 99, 45, 109, 121, 45, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110, 45, 68, 76, 81], pulsar/cursor=[109, 121, 45, 115, 117, 98, 115, 99, 114, 105, 112, 116, 105, 111, 110], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
08:52:17.685 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.client.PulsarMockBookKeeper - Creating ledger 6
08:52:17.687 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] [my-subscription] Updating cursor info ledgerId=6 mark-delete=5:-1
08:52:17.689 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Updated cursor my-subscription with ledger id 6 md-position=5:-1 rd-position=5:0
08:52:17.689 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ] Opened new cursor: ManagedCursorImpl{ledger=my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ, name=my-subscription, ackPos=5:-1, readPos=5:0}
08:52:17.711 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/dead-letter-topic-my-subscription-DLQ-my-subscription] Rewind from 5:0 to 5:0
08:52:17.713 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ] There are no replicated subscriptions on the topic
08:52:17.713 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ][my-subscription] Created new subscription for 0
08:52:17.713 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53150] Created subscription on topic persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ / my-subscription
08:52:17.713 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [3] On [SUCCESS] Pulsar command
08:52:17.715 [pulsar-client-io-44-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ][my-subscription] Subscribed to topic on localhost/127.0.0.1:53141 -- consumer: 0
08:52:17.778 [pulsar-web-29-15] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:17 +0800] "GET /admin/v2/persistent/my-property/my-ns/dead-letter-topic/partitions?checkAllowAutoCreation=true HTTP/1.1" 200 16 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 28
08:52:17.826 [pulsar-web-29-9] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:17 +0800] "GET /lookup/v2/topic/persistent/my-property/my-ns/dead-letter-topic HTTP/1.1" 200 217 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 14
08:52:17.826 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://my-property/my-ns/dead-letter-topic] [null] Creating producer on cnx [id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141]
08:52:17.832 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [4] On [PRODUCER] Pulsar command
08:52:17.837 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148][persistent://my-property/my-ns/dead-letter-topic] Creating producer. producerId=0
08:52:17.850 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] persistent://my-property/my-ns/dead-letter-topic configured with schema false
08:52:17.865 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] Created new producer: Producer{topic=PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic}, client=/127.0.0.1:53148, producerName=test-1-0, producerId=0}
08:52:17.867 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [5] On [PRODUCER_SUCCESS] Pulsar command
08:52:17.871 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://my-property/my-ns/dead-letter-topic] [test-1-0] Created producer on cnx [id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141]
08:52:17.888 [main] WARN com.scurrilous.circe.checksum.Crc32cIntChecksum - Failed to load Circe JNI library. Falling back to Java based CRC32c provider
08:52:17.890 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [6] On [SEND] Pulsar command
08:52:17.897 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [7] On [SEND_RECEIPT] Pulsar command
08:52:17.901 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [8] On [CLOSE_PRODUCER] Pulsar command
08:52:17.903 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic}][test-1-0] Closing producer on cnx /127.0.0.1:53148. producerId=0
08:52:17.905 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic}][test-1-0] Closed producer on cnx /127.0.0.1:53148. producerId=0
08:52:17.905 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [9] On [SUCCESS] Pulsar command
08:52:17.906 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://my-property/my-ns/dead-letter-topic] [test-1-0] Closed Producer
08:52:17.906 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - Send message to topic PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic}, subscription my-subscription
08:52:17.911 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [10] On [MESSAGE] Pulsar command
08:52:17.913 [main] INFO org.apache.pulsar.client.api.DeadLetterTopicTest - consumer received message : 3:0:-1:0 Hello Pulsar [0]
08:52:19.872 [pulsar-timer-40-1] WARN org.apache.pulsar.client.impl.UnAckedMessageTracker - [ConsumerBase{subscription='my-subscription', consumerName='4f67d', topic='persistent://my-property/my-ns/dead-letter-topic'}] 1 messages have timed-out
08:52:19.910 [mock-pulsar-bk-OrderedExecutor-0-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - Send message to topic PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic}, subscription my-subscription
08:52:19.910 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [11] On [MESSAGE] Pulsar command
08:52:19.912 [main] INFO org.apache.pulsar.client.api.DeadLetterTopicTest - consumer received message : 3:0:-1:0 Hello Pulsar [0]
08:52:21.889 [pulsar-timer-40-1] WARN org.apache.pulsar.client.impl.UnAckedMessageTracker - [ConsumerBase{subscription='my-subscription', consumerName='4f67d', topic='persistent://my-property/my-ns/dead-letter-topic'}] 1 messages have timed-out
08:52:21.918 [pulsar-web-29-14] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:21 +0800] "GET /admin/v2/persistent/my-property/my-ns/dead-letter-topic-my-subscription-DLQ/partitions?checkAllowAutoCreation=true HTTP/1.1" 200 16 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 19
08:52:21.929 [pulsar-web-29-16] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [14/Aug/2021:08:52:21 +0800] "GET /lookup/v2/topic/persistent/my-property/my-ns/dead-letter-topic-my-subscription-DLQ HTTP/1.1" 200 217 "-" "Pulsar-Java-v2.9.0-SNAPSHOT" 7
08:52:21.933 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ] [null] Creating producer on cnx [id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141]
08:52:21.934 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [12] On [PRODUCER] Pulsar command
08:52:21.934 [pulsar-io-6-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148][persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ] Creating producer. producerId=1
08:52:21.935 [ForkJoinPool.commonPool-worker-2] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ configured with schema false
08:52:21.939 [ForkJoinPool.commonPool-worker-2] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:53148] Created new producer: Producer{topic=PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ}, client=/127.0.0.1:53148, producerName=test-1-1, producerId=1}
08:52:21.939 [ForkJoinPool.commonPool-worker-2] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [13] On [PRODUCER_SUCCESS] Pulsar command
08:52:21.940 [pulsar-client-io-35-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ] [test-1-1] Created producer on cnx [id: 0xf527e621, L:/127.0.0.1:53148 - R:localhost/127.0.0.1:53141]
08:52:21.945 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [14] On [SEND] Pulsar command
08:52:21.947 [pulsar-io-6-1] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [15] On [SEND_RECEIPT] Pulsar command
08:52:21.950 [broker-topic-workers-OrderedScheduler-1-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - Send message to topic PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ}, subscription my-subscription
08:52:21.951 [pulsar-io-6-3] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - [16] On [MESSAGE] Pulsar command
08:53:09.897 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Writing local data to metadata store because maximum change Infinity% exceeded threshold 10%; time since last report written is 55.167 seconds
08:53:14.569 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Only 1 broker available: no load shedding will be performed
08:54:09.886 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Writing local data to metadata store because maximum change 100.0% exceeded threshold 10%; time since last report written is 59.982 seconds
08:54:14.567 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Only 1 broker available: no load shedding will be performed
08:55:14.565 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Only 1 broker available: no load shedding will be performed
08:56:14.565 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Only 1 broker available: no load shedding will be performed
08:57:14.556 [pulsar-load-manager-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Only 1 broker available: no load shedding will be performed
```
from the log , I can see only receive 2 times, and the message was sent to deadletter
```
08:52:21.950 [broker-topic-workers-OrderedScheduler-1-0] INFO org.apache.pulsar.broker.intercept.CounterBrokerInterceptor - Send message to topic PersistentTopic{topic=persistent://my-property/my-ns/dead-letter-topic-my-subscription-DLQ}, subscription my-subscription
```
--
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