[
https://issues.apache.org/jira/browse/FLINK-30703?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17677472#comment-17677472
]
Yufan Sheng edited comment on FLINK-30703 at 1/16/23 4:59 PM:
--------------------------------------------------------------
[~mapohl] It's wired to see the log that the tests on
PulsarOrderedPartitionSplitReaderTest are executed in parallel, am I miss
something? I use a mocked Pulsar instance which only supports one test per
time. The parallel tests executing on same mock Pulsar instance may mess the
cursor which cause the duplication.
{code}
03:06:03,320 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ProducerStatsRecorderImpl [] - Starting
Pulsar producer perf with config:
{"topicName":"persistent://public/default/sXmCOYoouf-partition-0","producerName":null,"sendTimeoutMs":30000,"blockIfQueueFull":false,"maxPendingMessages":0,"maxPendingMessagesAcrossPartitions":0,"messageRoutingMode":"RoundRobinPartition","hashingScheme":"JavaStringHash","cryptoFailureAction":"FAIL","batchingMaxPublishDelayMicros":1000,"batchingPartitionSwitchFrequencyByPublishDelay":10,"batchingMaxMessages":1000,"batchingMaxBytes":131072,"batchingEnabled":false,"chunkingEnabled":false,"compressionType":"NONE","initialSequenceId":null,"autoUpdatePartitions":true,"autoUpdatePartitionsIntervalSeconds":60,"multiSchema":true,"accessMode":"Shared","lazyStartPartitionedProducers":false,"properties":{},"initialSubscriptionName":null}
03:06:03,321 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ProducerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0] [null] Creating producer
on cnx [id: 0xbd68a334, L:/127.0.0.1:40928 - R:localhost/127.0.0.1:42178]
03:06:03,321 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928][persistent://public/default/sXmCOYoouf-partition-0] Creating
producer. producerId=32
03:06:03,321 [ pulsar-io-639-2] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] - Opening
managed ledger public/default/persistent/sXmCOYoouf-partition-0
03:06:03,321 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Creating ledger, metadata:
{component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114],
pulsar/managed-ledger=[112, 117, 98, 108, 105, 99, 47, 100, 101, 102, 97, 117,
108, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 115, 88,
109, 67, 79, 89, 111, 111, 117, 102, 45, 112, 97, 114, 116, 105, 116, 105, 111,
110, 45, 48], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout
: 60 seconds
03:06:03,322 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Created ledger 154
03:06:03,322 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Successfully initialize
managed ledger
03:06:03,323 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0] There are no replicated
subscriptions on the topic
03:06:03,325 [broker-topic-workers-OrderedExecutor-23-0] INFO
org.apache.pulsar.broker.service.AbstractTopic [] - Disabling
publish throttling for persistent://public/default/sXmCOYoouf-partition-0
03:06:03,325 [broker-topic-workers-OrderedExecutor-23-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Cursor pulsar.dedup
recovered to position 154:-1
03:06:03,325 [broker-topic-workers-OrderedExecutor-23-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Creating ledger, metadata:
{component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114],
pulsar/managed-ledger=[112, 117, 98, 108, 105, 99, 47, 100, 101, 102, 97, 117,
108, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 115, 88,
109, 67, 79, 89, 111, 111, 117, 102, 45, 112, 97, 114, 116, 105, 116, 105, 111,
110, 45, 48], pulsar/cursor=[112, 117, 108, 115, 97, 114, 46, 100, 101, 100,
117, 112], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout :
60 seconds
03:06:03,326 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.MetaStoreImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] [pulsar.dedup] Updating
cursor info ledgerId=155 mark-delete=154:-1
03:06:03,326 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Updated cursor pulsar.dedup
with ledger id 155 md-position=154:-1 rd-position=154:0
03:06:03,326 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Opened new cursor:
ManagedCursorImpl{ledger=public/default/persistent/sXmCOYoouf-partition-0,
name=pulsar.dedup, ackPos=154:-1, readPos=154:0}
03:06:03,326 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.pulsar.broker.service.persistent.MessageDeduplication [] -
[persistent://public/default/sXmCOYoouf-partition-0] Replaying 0 entries for
deduplication
03:06:03,327 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.BrokerService [] - Created topic
persistent://public/default/sXmCOYoouf-partition-0 - dedup is enabled
03:06:03,327 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.MessageDeduplication [] -
[persistent://public/default/sXmCOYoouf-partition-0] Enabled deduplication
03:06:03,340 [ pulsar-io-639-3] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928] Created new producer:
Producer{topic=PersistentTopic{topic=persistent://public/default/sXmCOYoouf-partition-0},
client=/127.0.0.1:40928, producerName=mock-pulsar-IvZ7KH-0-76, producerId=32}
03:06:03,340 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ProducerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0] [mock-pulsar-IvZ7KH-0-76]
Created producer on cnx [id: 0xbd68a334, L:/127.0.0.1:40928 -
R:localhost/127.0.0.1:42178]
03:06:03,368 [ main] INFO
org.apache.pulsar.client.impl.ProducerStatsRecorderImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0] [mock-pulsar-IvZ7KH-0-76]
Pending messages: 0 --- Publish throughput: 423.54 msg/s --- 0.03 Mbit/s ---
Latency: med: 1.000 ms - 95pct: 1.000 ms - 99pct: 1.000 ms - 99.9pct: 1.000 ms
- max: 1.000 ms --- BatchSize: med: 1.000 - 95pct: 1.000 - 99pct: 1.000 -
99.9pct: 1.000 - max: 1.000 --- MsgSize: med: 10.000 bytes - 95pct: 10.000
bytes - 99pct: 10.000 bytes - 99.9pct: 10.000 bytes - max: 10.000 bytes --- Ack
received rate: 423.54 ack/s --- Failed messages: 0 --- Pending messages: 0
03:06:03,368 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[PersistentTopic{topic=persistent://public/default/sXmCOYoouf-partition-0}][mock-pulsar-IvZ7KH-0-76]
Closing producer on cnx /127.0.0.1:40928. producerId=32
03:06:03,368 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[PersistentTopic{topic=persistent://public/default/sXmCOYoouf-partition-0}][mock-pulsar-IvZ7KH-0-76]
Closed producer on cnx /127.0.0.1:40928. producerId=32
03:06:03,368 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ProducerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0] [mock-pulsar-IvZ7KH-0-76]
Closed Producer
03:06:03,805 [ pulsar-web-661-36] INFO org.eclipse.jetty.server.RequestLog
[] - 127.0.0.1 - - [11/Jan/2023:03:06:03 +0000] "GET
/admin/v2/persistent/public/default/sXmCOYoouf-partition-0/subscriptions
HTTP/1.1" 200 2 "-" "Pulsar-Java-v2.10.2" 1
03:06:03,812 [ pulsar-web-661-54] INFO
org.apache.pulsar.broker.admin.impl.PersistentTopicsBase [] -
[null][persistent://public/default/sXmCOYoouf-partition-0] Creating
subscription uikegefnOB at message id -1:-1:-1 with properties null
03:06:03,812 [ pulsar-web-661-54] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Cursor uikegefnOB recovered
to position 154:19
03:06:03,813 [ pulsar-web-661-54] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Creating ledger, metadata:
{component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114],
pulsar/managed-ledger=[112, 117, 98, 108, 105, 99, 47, 100, 101, 102, 97, 117,
108, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 115, 88,
109, 67, 79, 89, 111, 111, 117, 102, 45, 112, 97, 114, 116, 105, 116, 105, 111,
110, 45, 48], pulsar/cursor=[117, 105, 107, 101, 103, 101, 102, 110, 79, 66],
application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
03:06:03,819 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.MetaStoreImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] [uikegefnOB] Updating cursor
info ledgerId=178 mark-delete=154:19
03:06:03,819 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Updated cursor uikegefnOB
with ledger id 178 md-position=154:19 rd-position=154:20
03:06:03,819 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Opened new cursor:
ManagedCursorImpl{ledger=public/default/persistent/sXmCOYoouf-partition-0,
name=uikegefnOB, ackPos=154:19, readPos=154:20}
03:06:03,819 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentSubscription [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Successfully
disconnected consumers from subscription, proceeding with cursor reset
03:06:03,824 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Initiate reset position to
154:-1 on cursor uikegefnOB
03:06:03,832 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] reset position to 154:-1
before current read position 154:20 on cursor uikegefnOB
03:06:03,832 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.admin.impl.PersistentTopicsBase [] -
[null][persistent://public/default/sXmCOYoouf-partition-0] Successfully created
subscription uikegefnOB at message id -1:-1:-1
03:06:03,833 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.eclipse.jetty.server.RequestLog [] - 127.0.0.1 - -
[11/Jan/2023:03:06:03 +0000] "PUT
/admin/v2/persistent/public/default/sXmCOYoouf-partition-0/subscription/uikegefnOB?replicated=false
HTTP/1.1" 204 0 "-" "Pulsar-Java-v2.10.2" 22
03:06:03,842 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConsumerStatsRecorderImpl [] - Starting
Pulsar consumer status recorder with config:
{"topicNames":["persistent://public/default/sXmCOYoouf-partition-0"],"topicsPattern":null,"subscriptionName":"uikegefnOB","subscriptionType":"Shared","subscriptionProperties":null,"subscriptionMode":"Durable","receiverQueueSize":1000,"acknowledgementsGroupTimeMicros":100000,"negativeAckRedeliveryDelayMicros":60000000,"maxTotalReceiverQueueSizeAcrossPartitions":50000,"consumerName":null,"ackTimeoutMillis":0,"tickDurationMillis":1000,"priorityLevel":0,"maxPendingChunkedMessage":10,"autoAckOldestChunkedMessageOnQueueFull":false,"expireTimeOfIncompleteChunkedMessageMillis":60000,"cryptoFailureAction":"FAIL","properties":{},"readCompacted":false,"subscriptionInitialPosition":"Latest","patternAutoDiscoveryPeriod":60,"regexSubscriptionMode":"PersistentOnly","deadLetterPolicy":null,"retryEnable":false,"autoUpdatePartitions":true,"autoUpdatePartitionsIntervalSeconds":60,"replicateSubscriptionState":false,"resetIncludeHead":false,"keySharedPolicy":null,"batchIndexAckEnabled":false,"ackReceiptEnabled":false,"poolMessages":false,"startPaused":false,"maxPendingChuckedMessage":10}
03:06:03,843 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConsumerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Subscribing to
topic on cnx [id: 0xbd68a334, L:/127.0.0.1:40928 -
R:localhost/127.0.0.1:42178], consumerId 8
03:06:03,843 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928] Subscribing on topic
persistent://public/default/sXmCOYoouf-partition-0 / uikegefnOB
03:06:03,844 [ pulsar-io-639-2] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0-uikegefnOB] Rewind from
154:-1 to 154:0
03:06:03,844 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0] There are no replicated
subscriptions on the topic
03:06:03,844 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Created new
subscription for 8
03:06:03,844 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928] Created subscription on topic
persistent://public/default/sXmCOYoouf-partition-0 / uikegefnOB
03:06:03,844 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConsumerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Subscribed to
topic on localhost/127.0.0.1:42178 -- consumer: 8
03:06:03,844 [ main] INFO
org.apache.flink.connector.pulsar.source.reader.split.PulsarPartitionSplitReaderBase
[] - Register split
PulsarPartitionSplit{partition=persistent://public/default/sXmCOYoouf-partition-0|0-65535}
consumer for current reader.
03:06:08,332 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.BrokerService [] -
[persistent://public/default/sXmCOYoouf-partition-0] Unloading topic
03:06:08,332 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.Consumer [] - Disconnecting
consumer:
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/sXmCOYoouf-partition-0,
name=uikegefnOB}, consumerId=8, consumerName=10588, address=/127.0.0.1:40928}
03:06:08,332 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
[] - Removed consumer
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/sXmCOYoouf-partition-0,
name=uikegefnOB}, consumerId=8, consumerName=10588, address=/127.0.0.1:40928}
with pending 20 acks
03:06:08,333 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
[] - [persistent://public/default/sXmCOYoouf-partition-0 / uikegefnOB] All
consumers removed. Subscription is disconnected
03:06:08,333 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.persistent.PersistentSubscription [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Successfully
closed subscription
[ManagedCursorImpl{ledger=public/default/persistent/sXmCOYoouf-partition-0,
name=uikegefnOB, ackPos=154:-1, readPos=154:20}]
03:06:08,333 [ pulsar-web-661-1] INFO
org.apache.pulsar.broker.service.persistent.PersistentSubscription [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Successfully
disconnected and closed subscription
03:06:08,333 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConnectionHandler [] -
[persistent://public/default/sXmCOYoouf-partition-0] [uikegefnOB] Closed
connection [id: 0xbd68a334, L:/127.0.0.1:40928 - R:localhost/127.0.0.1:42178]
-- Will try again in 0.1 s
03:06:08,333 [ pulsar-web-661-1] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Closing managed ledger
03:06:08,333 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.MetaStoreImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] [pulsar.dedup] Updating
cursor info ledgerId=-1 mark-delete=154:-1
03:06:08,333 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.MetaStoreImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] [uikegefnOB] Updating cursor
info ledgerId=-1 mark-delete=154:-1
03:06:08,333 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0][pulsar.dedup] Closed cursor
at md-position=154:-1
03:06:08,333 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0][pulsar.dedup] Successfully
closed & deleted ledger 155 in cursor
03:06:08,333 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0][uikegefnOB] Closed cursor at
md-position=154:-1
03:06:08,334 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0] Topic closed
03:06:08,334 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0][uikegefnOB] Successfully
closed & deleted ledger 178 in cursor
03:06:08,434 [ pulsar-timer-675-1] INFO
org.apache.pulsar.client.impl.ConnectionHandler [] -
[persistent://public/default/sXmCOYoouf-partition-0] [uikegefnOB] Reconnecting
after timeout
03:06:08,435 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConsumerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Subscribing to
topic on cnx [id: 0xbd68a334, L:/127.0.0.1:40928 -
R:localhost/127.0.0.1:42178], consumerId 8
03:06:08,435 [ pulsar-io-639-2] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928] Subscribing on topic
persistent://public/default/sXmCOYoouf-partition-0 / uikegefnOB
03:06:08,435 [ pulsar-io-639-2] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] - Opening
managed ledger public/default/persistent/sXmCOYoouf-partition-0
03:06:08,443 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Creating ledger, metadata:
{component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114],
pulsar/managed-ledger=[112, 117, 98, 108, 105, 99, 47, 100, 101, 102, 97, 117,
108, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 115, 88,
109, 67, 79, 89, 111, 111, 117, 102, 45, 112, 97, 114, 116, 105, 116, 105, 111,
110, 45, 48], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout
: 60 seconds
03:06:08,446 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Created ledger 203
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Loading cursor pulsar.dedup
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Recovering from bookkeeper
ledger cursor: pulsar.dedup
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Loading cursor uikegefnOB
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Recovering from bookkeeper
ledger cursor: uikegefnOB
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Cursor pulsar.dedup
recovered to position 154:-1
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Recovery for cursor
pulsar.dedup completed. pos=154:-1 -- todo=1
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Cursor uikegefnOB recovered
to position 154:-1
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Recovery for cursor
uikegefnOB completed. pos=154:-1 -- todo=0
03:06:08,474 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Successfully initialize
managed ledger
03:06:08,475 [bookkeeper-ml-scheduler-OrderedScheduler-26-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0] There are no replicated
subscriptions on the topic
03:06:08,505 [broker-topic-workers-OrderedExecutor-31-0] INFO
org.apache.pulsar.broker.service.AbstractTopic [] - Disabling
publish throttling for persistent://public/default/sXmCOYoouf-partition-0
03:06:08,505 [broker-topic-workers-OrderedExecutor-31-0] INFO
org.apache.pulsar.broker.service.persistent.MessageDeduplication [] -
[persistent://public/default/sXmCOYoouf-partition-0] Replaying 20 entries for
deduplication
03:06:08,507 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.BrokerService [] - Created topic
persistent://public/default/sXmCOYoouf-partition-0 - dedup is enabled
03:06:08,508 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0-uikegefnOB] Rewind from 154:0
to 154:0
03:06:08,508 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0] There are no replicated
subscriptions on the topic
03:06:08,508 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Created new
subscription for 8
03:06:08,508 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.ServerCnx [] -
[/127.0.0.1:40928] Created subscription on topic
persistent://public/default/sXmCOYoouf-partition-0 / uikegefnOB
03:06:08,508 [mock-pulsar-bookkeeper-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.MessageDeduplication [] -
[persistent://public/default/sXmCOYoouf-partition-0] Enabled deduplication
03:06:08,508 [pulsar-client-io-671-1] INFO
org.apache.pulsar.client.impl.ConsumerImpl [] -
[persistent://public/default/sXmCOYoouf-partition-0][uikegefnOB] Subscribed to
topic on localhost/127.0.0.1:42178 -- consumer: 8
03:06:08,650 [pulsar-transaction-executor-613-1] INFO
org.apache.bookkeeper.mledger.impl.NonDurableCursorImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Created non-durable cursor
read-position=154:0 mark-delete-position=154:-1
03:06:08,650 [pulsar-transaction-executor-613-1] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl [] -
[public/default/persistent/sXmCOYoouf-partition-0] Opened new cursor:
NonDurableCursorImpl{ledger=public/default/persistent/sXmCOYoouf-partition-0,
ackPos=154:-1, readPos=154:0}
03:06:08,651 [pulsar-transaction-executor-613-1] INFO
org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer [] -
[persistent://public/default/sXmCOYoouf-partition-0]Transaction buffer snapshot
recover cursor close complete.
{code}
was (Author: syhily):
[~mapohl] It's wired to see the log that the tests on
PulsarOrderedPartitionSplitReaderTest are executed in parallel, am I miss
something?
> PulsarOrderedPartitionSplitReaderTest>PulsarPartitionSplitReaderTestBase.consumeMessageCreatedBeforeHandleSplitsChangesAndResetToEarliestPosition
> fails
> -------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: FLINK-30703
> URL: https://issues.apache.org/jira/browse/FLINK-30703
> Project: Flink
> Issue Type: Bug
> Components: Connectors / Pulsar
> Affects Versions: 1.16.0, 1.15.3, pulsar-3.0.0
> Reporter: Matthias Pohl
> Priority: Major
> Labels: test-stability
>
> A 1.15 build failed due to
> {{PulsarOrderedPartitionSplitReaderTest>PulsarPartitionSplitReaderTestBase.consumeMessageCreatedBeforeHandleSplitsChangesAndResetToEarliestPosition}}:
> {code}
> an 11 03:08:20 [ERROR]
> PulsarOrderedPartitionSplitReaderTest>PulsarPartitionSplitReaderTestBase.consumeMessageCreatedBeforeHandleSplitsChangesAndResetToEarliestPosition:260->PulsarPartitionSplitReaderTestBase.fetchedMessages:169->PulsarPartitionSplitReaderTestBase.fetchedMessages:199
> [We should fetch the expected size]
> Jan 11 03:08:20 Expected size: 20 but was: 25 in:
> Jan 11 03:08:20 [PulsarMessage{id=154:0:0, value=ZHiaOiOhFT, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:1:0, value=uoOmKceWTh, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:2:0, value=oeYYWzisge, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:3:0, value=yhpOOkNLER, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:4:0, value=MIbzxkfFfp, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:0:0, value=ZHiaOiOhFT, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:1:0, value=uoOmKceWTh, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:2:0, value=oeYYWzisge, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:3:0, value=yhpOOkNLER, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:4:0, value=MIbzxkfFfp, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:5:0, value=FaEpggGBTE, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:6:0, value=IlGbzPRuvi, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:7:0, value=aqgIeSbOzo, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:8:0, value=CUScdPriyM, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:9:0, value=zLRsvDxpJG, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:10:0, value=iqsGFVkXDz, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:11:0, value=hFyHYPldqN, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:12:0, value=ZYTlJcwSst, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:13:0, value=mOWkzJQQxE, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:14:0, value=CTfcVXhfUN, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:15:0, value=wAhqCGGwXO, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:16:0, value=LOoTbXaEgG, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:17:0, value=UvfzGIRURy, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:18:0, value=vlYYGbZGAH, eventTime=0},
> Jan 11 03:08:20 PulsarMessage{id=154:19:0, value=wrwPanXvql, eventTime=0}]
> {code}
> https://dev.azure.com/apache-flink/apache-flink/_build/results?buildId=44691&view=logs&j=a5ef94ef-68c2-57fd-3794-dc108ed1c495&t=2c68b137-b01d-55c9-e603-3ff3f320364b&l=27466
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
