Flaky-test: MessageChunkingTest.testMaxPendingChunkMessages #21046
Description
Search before asking
- I searched in the issues and found nothing similar.
Example failure
https://github.com/apache/pulsar/actions/runs/5934883964/job/16092673164?pr=21043
Exception stacktrace
Error: Tests run: 33, Failures: 1, Errors: 0, Skipped: 19, Time elapsed: 92.431 s <<< FAILURE! - in org.apache.pulsar.client.impl.MessageChunkingTest
Error: org.apache.pulsar.client.impl.MessageChunkingTest.testMaxPendingChunkMessages Time elapsed: 0.253 s <<< FAILURE!
java.lang.AssertionError: expected [null] but found [org.apache.pulsar.client.impl.MessageImpl@1a724188]
at org.testng.Assert.fail(Assert.java:110)
at org.testng.Assert.failNotSame(Assert.java:1573)
at org.testng.Assert.assertNull(Assert.java:1506)
at org.testng.Assert.assertNull(Assert.java:1494)
at org.apache.pulsar.client.impl.MessageChunkingTest.testMaxPendingChunkMessages(MessageChunkingTest.java:356)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
at org.testng.internal.invokers.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:47)
at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:76)
at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
More logs:
2023-08-22T06:00:31,398 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ManagedLedgerImpl@379] - Opening managed ledger my-property/my-ns/persistent/maxPending
2023-08-22T06:00:31,401 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:MetaStoreImpl@113] - Creating '/managed-ledgers/my-property/my-ns/persistent/maxPending'
2023-08-22T06:00:31,405 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PulsarMockBookKeeper@123] - Creating ledger 3
2023-08-22T06:00:31,407 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:ManagedLedgerImpl@532] - [my-property/my-ns/persistent/maxPending] Created ledger 3
2023-08-22T06:00:31,409 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-1-0:ManagedLedgerImpl@379] - Opening managed ledger my-property/my-ns/persistent/__change_events
2023-08-22T06:00:31,413 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-1-0:MetaStoreImpl@113] - Creating '/managed-ledgers/my-property/my-ns/persistent/__change_events'
2023-08-22T06:00:31,414 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ManagedLedgerFactoryImpl$2@386] - [my-property/my-ns/persistent/maxPending] Successfully initialize managed ledger
2023-08-22T06:00:31,416 - INFO - [broker-topic-workers-OrderedExecutor-0-0:BrokerService$2@1683] - Created topic persistent://my-property/my-ns/maxPending - dedup is disabled
2023-08-22T06:00:31,419 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PulsarMockBookKeeper@123] - Creating ledger 4
2023-08-22T06:00:31,419 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PulsarMockBookKeeper@123] - Creating ledger 5
2023-08-22T06:00:31,421 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:ManagedLedgerImpl@532] - [my-property/my-ns/persistent/__change_events] Created ledger 5
2023-08-22T06:00:31,424 - INFO - [metadata-store-2166-1:ManagedCursorImpl@692] - [my-property/my-ns/persistent/maxPending] Cursor my-subscriber-name recovered to position 3:-1
2023-08-22T06:00:31,428 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-1-0:ManagedLedgerFactoryImpl$2@386] - [my-property/my-ns/persistent/__change_events] Successfully initialize managed ledger
2023-08-22T06:00:31,428 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ManagedLedgerImpl$7@1002] - [my-property/my-ns/persistent/maxPending] Opened new cursor: ManagedCursorImpl{ledger=my-property/my-ns/persistent/maxPending, name=my-subscriber-name, ackPos=3:-1, readPos=3:0}
2023-08-22T06:00:31,429 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ManagedCursorImpl@2491] - [my-property/my-ns/persistent/maxPending-my-subscriber-name] Rewind from 3:0 to 3:0
2023-08-22T06:00:31,429 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:PersistentSubscription@1257] - backlog for persistent://my-property/my-ns/maxPending - 0
2023-08-22T06:00:31,429 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ServerCnx@1261] - [/127.0.0.1:36546] Created subscription on topic persistent://my-property/my-ns/maxPending / my-subscriber-name
2023-08-22T06:00:31,430 - INFO - [broker-topic-workers-OrderedExecutor-1-0:ManagedCursorImpl@692] - [my-property/my-ns/persistent/__change_events] Cursor __compaction recovered to position 5:-1
2023-08-22T06:00:31,431 - INFO - [pulsar-client-io-2198-1:ConsumerImpl@925] - [persistent://my-property/my-ns/maxPending][my-subscriber-name] Subscribed to topic on localhost/127.0.0.1:32793 -- consumer: 0
2023-08-22T06:00:31,433 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-1-0:ManagedLedgerImpl$7@1002] - [my-property/my-ns/persistent/__change_events] Opened new cursor: ManagedCursorImpl{ledger=my-property/my-ns/persistent/__change_events, name=__compaction, ackPos=5:-1, readPos=5:0}
2023-08-22T06:00:31,433 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-1-0:BrokerService$2@1683] - Created topic persistent://my-property/my-ns/__change_events - dedup is disabled
2023-08-22T06:00:31,438 - INFO - [pulsar-2171-1:Slf4jRequestLogWriter@62] - 127.0.0.1 - - [22/Aug/2023:06:00:31 +0000] "GET /admin/v2/persistent/my-property/my-ns/maxPending/partitions?checkAllowAutoCreation=true HTTP/1.1" 200 32 "-" "Pulsar-Java-v3.1.0-SNAPSHOT" 6
2023-08-22T06:00:31,439 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PulsarMockBookKeeper@123] - Creating ledger 6
2023-08-22T06:00:31,443 - INFO - [metadata-store-2166-1:PersistentTopic@1042] - [persistent://my-property/my-ns/__change_events][reader-5aad0ea123] Creating non-durable subscription at msg id -1:-1:-1:-1 - {}
2023-08-22T06:00:31,443 - INFO - [metadata-store-2166-1:NonDurableCursorImpl@66] - [my-property/my-ns/persistent/__change_events] Created non-durable cursor read-position=5:0 mark-delete-position=5:-1
2023-08-22T06:00:31,444 - INFO - [metadata-store-2166-1:ManagedLedgerImpl@1131] - [my-property/my-ns/persistent/__change_events] Opened new cursor: NonDurableCursorImpl{ledger=my-property/my-ns/persistent/__change_events, ackPos=5:-1, readPos=5:0}
2023-08-22T06:00:31,444 - INFO - [metadata-store-2166-1:PersistentSubscription@1257] - backlog for persistent://my-property/my-ns/__change_events - 0
2023-08-22T06:00:31,444 - INFO - [metadata-store-2166-1:ServerCnx@1261] - [/127.0.0.1:36554] Created subscription on topic persistent://my-property/my-ns/__change_events / reader-5aad0ea123
2023-08-22T06:00:31,445 - INFO - [pulsar-io-2172-3:ConsumerImpl@925] - [persistent://my-property/my-ns/__change_events][reader-5aad0ea123] Subscribed to topic on localhost/127.0.0.1:32793 -- consumer: 0
2023-08-22T06:00:31,453 - INFO - [pulsar-client-io-2198-1:ProducerImpl@1671] - [persistent://my-property/my-ns/maxPending] [null] Creating producer on cnx [id: 0xd5da1c5a, L:/127.0.0.1:36546 - R:localhost/127.0.0.1:32793]
2023-08-22T06:00:31,453 - INFO - [pulsar-web-2193-5:Slf4jRequestLogWriter@62] - 127.0.0.1 - - [22/Aug/2023:06:00:31 +0000] "GET /lookup/v2/topic/persistent/my-property/my-ns/maxPending HTTP/1.1" 200 217 "-" "Pulsar-Java-v3.1.0-SNAPSHOT" 4
2023-08-22T06:00:31,466 - INFO - [broker-topic-workers-OrderedExecutor-0-0:ServerCnx@1604] - [/127.0.0.1:36546] Created new producer: Producer{topic=PersistentTopic{topic=persistent://my-property/my-ns/maxPending}, client=/127.0.0.1:36546, producerName=test-0-0, producerId=0}
2023-08-22T06:00:31,467 - INFO - [pulsar-client-io-2198-1:ProducerImpl@1729] - [persistent://my-property/my-ns/maxPending] [test-0-0] Created producer on cnx [id: 0xd5da1c5a, L:/127.0.0.1:36546 - R:localhost/127.0.0.1:32793]
2023-08-22T06:00:31,483 - INFO - [pulsar-client-io-2198-1:ConsumerImpl@2700] - Removing chunk message-id 3:0:-1
2023-08-22T06:00:31,488 - INFO - [broker-topic-workers-OrderedExecutor-1-0:ManagedCursorImpl@2491] - [my-property/my-ns/persistent/maxPending-my-subscriber-name] Rewind from 3:3 to 3:0
2023-08-22T06:00:31,493 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PulsarMockBookKeeper@123] - Creating ledger 7
2023-08-22T06:00:31,497 - INFO - [pulsar-client-io-2198-1:ConsumerImpl@2700] - Removing chunk message-id 3:0:-1
2023-08-22T06:00:31,497 - INFO - [pulsar-client-io-2198-1:ConsumerImpl@1453] - Received unexpected chunk messageId 3:3:-1, last-chunk-idnull, chunkId = 1
2023-08-22T06:00:31,498 - INFO - [bookkeeper-ml-scheduler-OrderedScheduler-0-0:ManagedCursorImpl$31@3125] - [my-property/my-ns/persistent/maxPending] Updated cursor my-subscriber-name with ledger id 7 md-position=3:2 rd-position=3:4
2023-08-22T06:00:31,499 - INFO - [pulsar-io-2172-2:ServerCnx@1987] - [PersistentTopic{topic=persistent://my-property/my-ns/maxPending}][test-0-0] Closing producer on cnx /127.0.0.1:36546. producerId=0
2023-08-22T06:00:31,499 - INFO - [pulsar-io-2172-2:ServerCnx@1991] - [PersistentTopic{topic=persistent://my-property/my-ns/maxPending}][test-0-0] Closed producer on cnx /127.0.0.1:36546. producerId=0
2023-08-22T06:00:31,500 - INFO - [pulsar-client-io-2198-1:ProducerImpl@1078] - [persistent://my-property/my-ns/maxPending] [test-0-0] Closed Producer
2023-08-22T06:00:31,500 - INFO - [pulsar-io-2172-2:ServerCnx@2005] - [/127.0.0.1:36546] Closing consumer: consumerId=0
2023-08-22T06:00:31,500 - INFO - [pulsar-io-2172-2:AbstractDispatcherSingleActiveConsumer@211] - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://my-property/my-ns/maxPending, name=my-subscriber-name}, consumerId=0, consumerName=233d1, address=/127.0.0.1:36546}
2023-08-22T06:00:31,500 - INFO - [pulsar-io-2172-2:ServerCnx@2041] - [/127.0.0.1:36546] Closed consumer, consumerId=0
2023-08-22T06:00:31,501 - INFO - [pulsar-client-io-2198-1:ConsumerImpl@1082] - [persistent://my-property/my-ns/maxPending] [my-subscriber-name] Closed consumer
2023-08-22T06:00:31,503 - INFO - [TestNG-method=setup-1-SendThread(127.0.0.1:46313):ClientCnxn$SendThread@1177] - Opening socket connection to server localhost/127.0.0.1:46313.
2023-08-22T06:00:31,503 - INFO - [TestNG-method=setup-1-SendThread(127.0.0.1:46313):ClientCnxn$SendThread@1179] - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2023-08-22T06:00:31,503 - WARN - [TestNG-method=setup-1-SendThread(127.0.0.1:46313):ClientCnxn$SendThread@1300] - Session 0x10000041c7b0004 for server localhost/127.0.0.1:46313, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
at sun.nio.ch.Net.pollConnect(Native Method) ~[?:?]
at sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[?:?]
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:946) ~[?:?]
at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[zookeeper-3.8.1.jar:3.8.1]
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1289) ~[zookeeper-3.8.1.jar:3.8.1]
!!!!!!!!! FAILURE-- [TestClass name=class org.apache.pulsar.client.impl.MessageChunkingTest].testMaxPendingChunkMessages([])-------
java.lang.AssertionError: expected [null] but found [org.apache.pulsar.client.impl.MessageImpl@1a724188]
at org.testng.Assert.fail(Assert.java:110)
at org.testng.Assert.failNotSame(Assert.java:1573)
at org.testng.Assert.assertNull(Assert.java:1506)
at org.testng.Assert.assertNull(Assert.java:1494)
at org.apache.pulsar.client.impl.MessageChunkingTest.testMaxPendingChunkMessages(MessageChunkingTest.java:356)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
at org.testng.internal.invokers.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:47)
at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:76)
at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Are you willing to submit a PR?
- I'm willing to submit a PR!