Technoboy- opened a new issue, #21046: URL: https://github.com/apache/pulsar/issues/21046
### Search before asking - [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar. ### Example failure https://github.com/apache/pulsar/actions/runs/5934883964/job/16092673164?pr=21043 ### Exception stacktrace <!-- copy-paste the stack trace in the code block below --> ``` 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! -- 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: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
