[CPP test] Flaky-test: [KeySharedConsumerTest].[testMultiTopics]

[codelipenghui]

https://github.com/apache/pulsar/runs/4944727743?check_suite_focus=true

[BewareMyPower]

2022-01-25 23:40:14.535 INFO  [140702461217536] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-01-25 23:40:14.535 INFO  [140702461217536] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-01-25 23:40:14.537 INFO  [140702339077888] ClientConnection:368 | [127.0.0.1:56772 -> 127.0.0.1:6650] Connected to broker
2022-01-25 23:40:14.540 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, ] Getting connection from pool
2022-01-25 23:40:14.576 INFO  [140702339077888] ProducerImpl:189 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, ] Created producer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.580 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, ] Getting connection from pool
2022-01-25 23:40:14.616 INFO  [140702339077888] ProducerImpl:189 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, ] Created producer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.620 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, ] Getting connection from pool
2022-01-25 23:40:14.656 INFO  [140702339077888] ProducerImpl:189 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, ] Created producer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.665 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 0] Getting connection from pool
2022-01-25 23:40:14.666 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 1] Getting connection from pool
2022-01-25 23:40:14.666 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 2] Getting connection from pool
2022-01-25 23:40:14.685 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 1] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.685 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 0] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.686 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 2] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.686 INFO  [140702339077888] MultiTopicsConsumerImpl:95 | Successfully Subscribed to Topics
2022-01-25 23:40:14.690 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 3] Getting connection from pool
2022-01-25 23:40:14.691 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 4] Getting connection from pool
2022-01-25 23:40:14.691 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 5] Getting connection from pool
2022-01-25 23:40:14.692 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 3] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.693 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 4] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.693 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 5] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.694 INFO  [140702339077888] MultiTopicsConsumerImpl:95 | Successfully Subscribed to Topics
2022-01-25 23:40:14.700 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 6] Getting connection from pool
2022-01-25 23:40:14.701 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 7] Getting connection from pool
2022-01-25 23:40:14.701 INFO  [140702339077888] HandlerBase:64 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 8] Getting connection from pool
2022-01-25 23:40:14.702 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 6] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.702 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 7] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.702 INFO  [140702339077888] ConsumerImpl:224 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 8] Created consumer on broker [127.0.0.1:56772 -> 127.0.0.1:6650]
2022-01-25 23:40:14.703 INFO  [140702339077888] MultiTopicsConsumerImpl:95 | Successfully Subscribed to Topics
2022-01-25 23:40:24.075 INFO  [140702461217536] KeySharedConsumerTest:124 | messagesPerConsumer: {0 => 1136, 1 => 799, 2 => 1014}
/pulsar/pulsar-client-cpp/tests/KeySharedConsumerTest.cc:129: Failure
Value of: expectedNumTotalMessages
  Actual: 3000
Expected: numTotalMessages
Which is: 2949
2022-01-25 23:40:24.075 INFO  [140702461217536] ClientImpl:496 | Closing Pulsar client with 3 producers and 3 consumers
2022-01-25 23:40:24.075 INFO  [140702461217536] ProducerImpl:686 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, standalone-0-317] Closing producer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540140
2022-01-25 23:40:24.075 INFO  [140702461217536] ProducerImpl:686 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, standalone-0-318] Closing producer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540141
2022-01-25 23:40:24.075 INFO  [140702461217536] ProducerImpl:686 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, standalone-0-319] Closing producer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540142
2022-01-25 23:40:24.075 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 0] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540140
2022-01-25 23:40:24.075 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 1] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540141
2022-01-25 23:40:24.075 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 2] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540142
2022-01-25 23:40:24.075 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 3] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540140
2022-01-25 23:40:24.075 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 4] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540141
2022-01-25 23:40:24.076 INFO  [140702339077888] ProducerImpl:729 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, standalone-0-317] Closed producer
2022-01-25 23:40:24.076 INFO  [140702339077888] ProducerImpl:729 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, standalone-0-318] Closed producer
2022-01-25 23:40:24.078 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 5] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540142
2022-01-25 23:40:24.078 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 6] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540140
2022-01-25 23:40:24.078 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 7] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540141
2022-01-25 23:40:24.079 INFO  [140702461217536] ConsumerImpl:999 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 8] Closing consumer for topic persistent://public/default/KeySharedConsumerTest-multi-topics16431540142
2022-01-25 23:40:24.079 INFO  [140702339077888] ProducerImpl:729 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, standalone-0-319] Closed producer
2022-01-25 23:40:24.079 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 0] Closed consumer 0
2022-01-25 23:40:24.079 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 1] Closed consumer 1
2022-01-25 23:40:24.081 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 2] Closed consumer 2
2022-01-25 23:40:24.081 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 3] Closed consumer 3
2022-01-25 23:40:24.081 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 4] Closed consumer 4
2022-01-25 23:40:24.081 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 5] Closed consumer 5
2022-01-25 23:40:24.081 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, SubscriptionName, 6] Closed consumer 6
2022-01-25 23:40:24.082 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, SubscriptionName, 7] Closed consumer 7
2022-01-25 23:40:24.082 INFO  [140702339077888] ConsumerImpl:1055 | [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, SubscriptionName, 8] Closed consumer 8
2022-01-25 23:40:24.082 INFO  [140702339077888] ClientConnection:1548 | [127.0.0.1:56772 -> 127.0.0.1:6650] Connection closed
2022-01-25 23:40:24.085 INFO  [140702461217536] ProducerImpl:655 | Producer - [persistent://public/default/KeySharedConsumerTest-multi-topics16431540140, standalone-0-317] , [batching  = off]
2022-01-25 23:40:24.085 INFO  [140702461217536] ProducerImpl:655 | Producer - [persistent://public/default/KeySharedConsumerTest-multi-topics16431540141, standalone-0-318] , [batching  = off]
2022-01-25 23:40:24.085 INFO  [140702461217536] ProducerImpl:655 | Producer - [persistent://public/default/KeySharedConsumerTest-multi-topics16431540142, standalone-0-319] , [batching  = off]
2022-01-25 23:40:24.085 INFO  [140702461217536] ClientConnection:256 | [127.0.0.1:56772 -> 127.0.0.1:6650] Destroyed connection
[  FAILED  ] KeySharedConsumerTest.testMultiTopics (9551 ms)

[BewareMyPower]

It looks like the test was affected by the default value of subscriptionKeySharedUseConsistentHashing. I can reproduce it in my local env.

However, I change the standalone's config to

subscriptionKeySharedUseConsistentHashing=false

The test never failed again.

[lhotari]

I filed an issue #13965 . this looks like a real bug and not just a flaky test. @BewareMyPower is this correct?