You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by "Technoboy- (via GitHub)" <gi...@apache.org> on 2023/08/22 08:16:30 UTC
[GitHub] [pulsar] Technoboy- opened a new issue, #21046: Flaky-test: MessageChunkingTest.testMaxPendingChunkMessages
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: commits-unsubscribe@pulsar.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] mattisonchao commented on issue #21046: Flaky-test: MessageChunkingTest.testMaxPendingChunkMessages
Posted by "mattisonchao (via GitHub)" <gi...@apache.org>.
mattisonchao commented on issue #21046:
URL: https://github.com/apache/pulsar/issues/21046#issuecomment-1689432002
@RobertIndie, I saw you were working on the chunk message part. Would you mind taking a look at it by any chance?
--
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
[GitHub] [pulsar] github-actions[bot] commented on issue #21046: Flaky-test: MessageChunkingTest.testMaxPendingChunkMessages
Posted by "github-actions[bot] (via GitHub)" <gi...@apache.org>.
github-actions[bot] commented on issue #21046:
URL: https://github.com/apache/pulsar/issues/21046#issuecomment-1732175444
The issue had no activity for 30 days, mark with Stale label.
--
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