Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Flaky-test: C++ ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers #13849

Closed
lhotari opened this issue Jan 20, 2022 · 10 comments · Fixed by #15271
Closed

Flaky-test: C++ ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers #13849

lhotari opened this issue Jan 20, 2022 · 10 comments · Fixed by #15271
Assignees

Comments

@lhotari
Copy link
Member

lhotari commented Jan 20, 2022

ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers fails sporadically.

example failure

2022-01-20 05:08:14.347 INFO  [139723758618368] ProducerTest:208 | Closing
2022-01-20 05:08:14.347 INFO  [139723758618368] ProducerImpl:621 | [persistent://public/default/testProducerIsConnectedPartitioned-1642655293-partition-7, standalone-0-401] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1642655293-partition-7
2022-01-20 05:08:14.347 INFO  [139723758618368] ProducerTest:210 | Close called
2022-01-20 05:08:14.347 INFO  [139724043835136] ProducerImpl:664 | [persistent://public/default/testProducerIsConnectedPartitioned-1642655293-partition-7, standalone-0-401] Closed producer
2022-01-20 05:08:14.347 INFO  [139723758618368] ProducerTest:215 | Closed
/pulsar/pulsar-client-cpp/tests/ProducerTest.cc:236: Failure
Value of: res
  Actual: Ok
Expected: ResultAlreadyClosed
Which is: AlreadyClosed
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers (3431 ms)
[----------] 1 test from ProducerTest (3431 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (3435 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers

full logs at https://gist.github.com/lhotari/f37aefd7919f030399f3a5b7020baa23

@lhotari
Copy link
Member Author

lhotari commented Jan 20, 2022

@BewareMyPower Do you have a chance to check this?

@BewareMyPower
Copy link
Contributor

I'll take a look when I'm free.

BTW, this flaky test might be introduced from #11570, it would be better if @Vanlightly could take a look first.

@BewareMyPower
Copy link
Contributor

I also encountered this flaky test in my PR

2022-01-25 14:11:15.451 INFO  [139754441005824] ProducerTest:167 | Start of run 0
2022-01-25 14:11:15.490 INFO  [139754441005824] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-01-25 14:11:15.490 INFO  [139754441005824] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-01-25 14:11:15.494 INFO  [139754318866176] ClientConnection:368 | [127.0.0.1:32906 -> 127.0.0.1:6650] Connected to broker
2022-01-25 14:11:15.496 INFO  [139754318866176] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-5, ] Getting connection from pool
2022-01-25 14:11:15.533 INFO  [139754318866176] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-5, ] Created producer on broker [127.0.0.1:32906 -> 127.0.0.1:6650]
2022-01-25 14:11:15.552 INFO  [139754175715072] ProducerTest:209 | Closing
2022-01-25 14:11:15.552 INFO  [139754175715072] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-5, standalone-0-374] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-5
2022-01-25 14:11:15.552 INFO  [139754175715072] ProducerTest:211 | Close called
2022-01-25 14:11:15.553 INFO  [139754192496384] ProducerTest:199 | closedAt set to 10
2022-01-25 14:11:15.555 INFO  [139754318866176] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-5, standalone-0-374] Closed producer
2022-01-25 14:11:15.555 INFO  [139754175715072] ProducerTest:216 | Closed
2022-01-25 14:11:15.666 INFO  [139754441005824] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-01-25 14:11:15.666 INFO  [139754441005824] ClientConnection:1548 | [127.0.0.1:32906 -> 127.0.0.1:6650] Connection closed
2022-01-25 14:11:15.666 INFO  [139754441005824] ClientConnection:256 | [127.0.0.1:32906 -> 127.0.0.1:6650] Destroyed connection
2022-01-25 14:11:15.666 INFO  [139754441005824] ProducerTest:242 | End of run 0
2022-01-25 14:11:15.666 INFO  [139754441005824] ProducerTest:167 | Start of run 1
{"reason":"This topic already exists"}2022-01-25 14:11:15.681 INFO  [139754441005824] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-01-25 14:11:15.681 INFO  [139754441005824] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-01-25 14:11:15.694 INFO  [139754209277696] ClientConnection:368 | [127.0.0.1:32922 -> 127.0.0.1:6650] Connected to broker
2022-01-25 14:11:15.698 INFO  [139754209277696] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-6, ] Getting connection from pool
2022-01-25 14:11:15.732 INFO  [139754209277696] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-6, ] Created producer on broker [127.0.0.1:32922 -> 127.0.0.1:6650]
2022-01-25 14:11:16.746 INFO  [139754007951104] ProducerTest:209 | Closing
2022-01-25 14:11:16.746 INFO  [139754007951104] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-6, standalone-0-390] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-6
2022-01-25 14:11:16.746 INFO  [139754007951104] ProducerTest:211 | Close called
2022-01-25 14:11:16.747 INFO  [139754209277696] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1643119875-partition-6, standalone-0-390] Closed producer
2022-01-25 14:11:16.747 INFO  [139754007951104] ProducerTest:216 | Closed
/pulsar/pulsar-client-cpp/tests/ProducerTest.cc:237: Failure
Value of: res
  Actual: Ok
Expected: ResultAlreadyClosed
Which is: AlreadyClosed

I will take a look at this flaky test soon.

@BewareMyPower BewareMyPower self-assigned this Jan 25, 2022
@BewareMyPower
Copy link
Contributor

Another failure: https://github.com/apache/pulsar/runs/4996173778?check_suite_focus=true

[ RUN      ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers
2022-01-30 10:31:24.887 INFO  [139625035234048] ProducerTest:167 | Start of run 0
2022-01-30 10:31:24.918 INFO  [139625035234048] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-01-30 10:31:24.918 INFO  [139625035234048] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-01-30 10:31:24.927 INFO  [139624913094400] ClientConnection:368 | [127.0.0.1:48718 -> 127.0.0.1:6650] Connected to broker
2022-01-30 10:31:24.929 INFO  [139624913094400] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538684-partition-0, ] Getting connection from pool
2022-01-30 10:31:24.966 INFO  [139624913094400] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538684-partition-0, ] Created producer on broker [127.0.0.1:48718 -> 127.0.0.1:6650]
2022-01-30 10:31:24.978 INFO  [139624689170176] ProducerTest:209 | Closing
2022-01-30 10:31:24.978 INFO  [139624689170176] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538684-partition-0, standalone-0-372] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1643538684-partition-0
2022-01-30 10:31:24.979 INFO  [139624689170176] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538684-partition-0, standalone-0-372] Closed producer
2022-01-30 10:31:24.979 INFO  [139624689170176] ProducerTest:211 | Close called
2022-01-30 10:31:24.979 INFO  [139624689170176] ProducerTest:216 | Closed
2022-01-30 10:31:24.980 INFO  [139624789825280] ProducerTest:199 | closedAt set to 10
2022-01-30 10:31:25.077 INFO  [139625035234048] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-01-30 10:31:25.077 INFO  [139625035234048] ClientConnection:1548 | [127.0.0.1:48718 -> 127.0.0.1:6650] Connection closed
2022-01-30 10:31:25.078 INFO  [139625035234048] ProducerTest:242 | End of run 0
2022-01-30 10:31:25.078 INFO  [139625035234048] ProducerTest:167 | Start of run 1
2022-01-30 10:31:25.109 INFO  [139625035234048] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-01-30 10:31:25.109 INFO  [139625035234048] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-01-30 10:31:25.110 INFO  [139624689170176] ClientConnection:368 | [127.0.0.1:48724 -> 127.0.0.1:6650] Connected to broker
2022-01-30 10:31:25.113 INFO  [139624689170176] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538685-partition-4, ] Getting connection from pool
2022-01-30 10:31:25.143 INFO  [139624689170176] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538685-partition-4, ] Created producer on broker [127.0.0.1:48724 -> 127.0.0.1:6650]
2022-01-30 10:31:26.143 INFO  [139624672388864] ProducerTest:209 | Closing
2022-01-30 10:31:26.143 INFO  [139624672388864] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538685-partition-4, standalone-0-374] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1643538685-partition-4
2022-01-30 10:31:26.143 INFO  [139624672388864] ProducerTest:211 | Close called
2022-01-30 10:31:26.143 INFO  [139624689170176] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1643538685-partition-4, standalone-0-374] Closed producer
2022-01-30 10:31:26.144 INFO  [139624672388864] ProducerTest:216 | Closed
/pulsar/pulsar-client-cpp/tests/ProducerTest.cc:237: Failure
Value of: res
  Actual: Ok
Expected: ResultAlreadyClosed
Which is: AlreadyClosed
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers (1257 ms)
[----------] 1 test from ProducerTest (1257 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (1257 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers

@RobertIndie
Copy link
Member

Another failure: https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:646

[ RUN      ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers
2022-02-13 13:42:55.629 INFO  [139735466076928] ProducerTest:167 | Start of run 0
2022-02-13 13:42:55.656 INFO  [139735466076928] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-02-13 13:42:55.656 INFO  [139735466076928] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-02-13 13:42:55.662 INFO  [139735343937280] ClientConnection:368 | [127.0.0.1:57358 -> 127.0.0.1:6650] Connected to broker
2022-02-13 13:42:55.668 INFO  [139735343937280] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16447[597](https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:597)75-partition-0, ] Getting connection from pool
2022-02-13 13:42:55.706 INFO  [139735343937280] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, ] Created producer on broker [127.0.0.1:57358 -> 127.0.0.1:6650]
2022-02-13 13:42:55.724 INFO  [139735200687872] ProducerTest:209 | Closing
2022-02-13 13:42:55.724 INFO  [139735200687872] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, standalone-0-382] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0
2022-02-13 13:42:55.724 INFO  [139735200687872] ProducerTest:211 | Close called
2022-02-13 13:42:55.725 INFO  [139735217469184] ProducerTest:199 | closedAt set to 10
2022-02-13 13:42:55.728 INFO  [139735343937280] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, standalone-0-382] Closed producer
2022-02-13 13:42:55.728 INFO  [139735200687872] ProducerTest:216 | Closed
2022-02-13 13:42:55.827 INFO  [13973546[607](https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:607)6928] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-02-13 13:42:55.827 INFO  [139735466076928] ClientConnection:1548 | [127.0.0.1:57358 -> 127.0.0.1:6650] Connection closed
2022-02-13 13:42:55.827 INFO  [139735466076928] ProducerTest:242 | End of run 0
2022-02-13 13:42:55.827 INFO  [139735466076928] ProducerTest:167 | Start of run 1
{"reason":"This topic already exists"}2022-02-13 13:42:55.841 INFO  [139735466076928] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-02-13 13:42:55.841 INFO  [139735466076928] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-02-13 13:42:55.846 INFO  [139735200687872] ClientConnection:368 | [127.0.0.1:57364 -> 127.0.0.1:6650] Connected to broker
2022-02-13 13:42:55.848 INFO  [139735200687872] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1[644](https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:644)759775-partition-0, ] Getting connection from pool
2022-02-13 13:42:55.850 INFO  [139735200687872] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, ] Created producer on broker [127.0.0.1:57364 -> 127.0.0.1:6[650](https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:650)]
2022-02-13 13:42:55.860 INFO  [139735183906560] ProducerTest:209 | Closing
2022-02-13 13:42:55.861 INFO  [139735183906560] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, standalone-0-384] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0
2022-02-13 13:42:55.861 INFO  [139735183906560] ProducerTest:211 | Close called
2022-02-13 13:42:55.861 INFO  [139735217469184] ProducerTest:199 | closedAt set to 10
2022-02-13 13:42:55.864 INFO  [139735200687872] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-0, standalone-0-384] Closed producer
2022-02-13 13:42:55.864 INFO  [139735183906560] ProducerTest:216 | Closed
2022-02-13 13:42:55.961 INFO  [139735466076928] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-02-13 13:42:55.961 INFO  [139735466076928] ClientConnection:1548 | [127.0.0.1:57364 -> 127.0.0.1:6650] Connection closed
2022-02-13 13:42:55.962 INFO  [139735466076928] ProducerTest:242 | End of run 1
2022-02-13 13:42:55.962 INFO  [139735466076928] ProducerTest:167 | Start of run 2
{"reason":"This topic already exists"}2022-02-13 13:42:55.974 INFO  [139735466076928] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-02-13 13:42:55.974 INFO  [139735466076928] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-02-13 13:42:55.974 INFO  [139735183906560] ClientConnection:368 | [127.0.0.1:57368 -> 127.0.0.1:6650] Connected to broker
2022-02-13 13:42:55.976 INFO  [139735183906560] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-8, ] Getting connection from pool
2022-02-13 13:42:56.001 INFO  [139735183906560] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-8, ] Created producer on broker [127.0.0.1:57368 -> 127.0.0.1:6650]
2022-02-13 13:42:56.011 INFO  [139734881924864] ProducerTest:209 | Closing
2022-02-13 13:42:56.011 INFO  [139734881924864] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-8, standalone-0-385] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-8
2022-02-13 13:42:56.011 INFO  [139734881924864] ProducerTest:211 | Close called
2022-02-13 13:42:56.012 INFO  [139735183906560] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759775-partition-8, standalone-0-385] Closed producer
2022-02-13 13:42:56.012 INFO  [139734881924864] ProducerTest:216 | Closed
2022-02-13 13:42:56.012 INFO  [139735217469184] ProducerTest:199 | closedAt set to 10
2022-02-13 13:42:56.123 INFO  [139735466076928] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-02-13 13:42:56.123 INFO  [139735466076928] ClientConnection:1548 | [127.0.0.1:57368 -> 127.0.0.1:6650] Connection closed
2022-02-13 13:42:56.123 INFO  [139735466076928] ProducerTest:242 | End of run 2
2022-02-13 13:42:56.123 INFO  [139735466076928] ProducerTest:167 | Start of run 3
2022-02-13 13:42:56.168 INFO  [139735466076928] ClientConnection:182 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-02-13 13:42:56.168 INFO  [139735466076928] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-02-13 13:42:56.184 INFO  [139734881924864] ClientConnection:368 | [127.0.0.1:57382 -> 127.0.0.1:6650] Connected to broker
2022-02-13 13:42:56.188 INFO  [139734881924864] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759776-partition-3, ] Getting connection from pool
2022-02-13 13:42:56.227 INFO  [139734881924864] ProducerImpl:189 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759776-partition-3, ] Created producer on broker [127.0.0.1:57382 -> 127.0.0.1:6650]
2022-02-13 13:42:57.235 INFO  [1397348[651](https://github.com/apache/pulsar/runs/5173936162?check_suite_focus=true#step:11:651)43552] ProducerTest:209 | Closing
2022-02-13 13:42:57.235 INFO  [139734865143552] ProducerImpl:686 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759776-partition-3, standalone-0-401] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-1644759776-partition-3
2022-02-13 13:42:57.235 INFO  [139734865143552] ProducerTest:211 | Close called
2022-02-13 13:42:57.236 INFO  [139734881924864] ProducerImpl:729 | [persistent://public/default/testProducerIsConnectedPartitioned-1644759776-partition-3, standalone-0-401] Closed producer
2022-02-13 13:42:57.236 INFO  [139734865143552] ProducerTest:216 | Closed
/pulsar/pulsar-client-cpp/tests/ProducerTest.cc:237: Failure
Value of: res
  Actual: Ok
Expected: ResultAlreadyClosed
Which is: AlreadyClosed
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers (1607 ms)
[----------] 1 test from ProducerTest (1607 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (1607 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers

@github-actions
Copy link

The issue had no activity for 30 days, mark with Stale label.

@BewareMyPower
Copy link
Contributor

Finally I have time for this issue now. 😂 Hope I could figure out the reason soon.

@BewareMyPower
Copy link
Contributor

I debugged it with lldb and sometimes I found an EXC_BAD_ACCESS.

Process 67307 stopped
* thread #58, stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
    frame #0: 0x00000001043a6fcc libpulsar.2.10.0-SNAPSHOT.dylib`boost::asio::detail::io_object_impl<boost::asio::detail::deadline_timer_service<boost::asio::time_traits<boost::posix_time::ptime> >, boost::asio::any_io_executor>::get_service(this=0x0000000000000000) at io_object_impl.hpp:116:13
   113 	  // Get the service associated with the I/O object.
   114 	  service_type& get_service()
   115 	  {
-> 116 	    return *service_;
   117 	  }
   118 	
   119 	  // Get the service associated with the I/O object.
Target 0: (main) stopped.

The command is

(lldb) r --gtest_filter='*Concurrent*LazyProducers' --gtest_repeat=5

The frame is

* thread #58, stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
  * frame #0: 0x00000001043a6fcc libpulsar.2.10.0-SNAPSHOT.dylib`boost::asio::detail::io_object_impl<boost::asio::detail::deadline_timer_service<boost::asio::time_traits<boost::posix_time::ptime> >, boost::asio::any_io_executor>::get_service(this=0x0000000000000000) at io_object_impl.hpp:116:13
    frame #1: 0x00000001043a23da libpulsar.2.10.0-SNAPSHOT.dylib`boost::asio::basic_deadline_timer<boost::posix_time::ptime, boost::asio::time_traits<boost::posix_time::ptime>, boost::asio::any_io_executor>::expires_from_now(this=0x0000000000000000, expiry_time=0x0000700011a632f8) at basic_deadline_timer.hpp:547:27
    frame #2: 0x000000010474b866 libpulsar.2.10.0-SNAPSHOT.dylib`pulsar::ProducerImpl::sendAsyncWithStatsUpdate(this=0x0000000103101418, msg=0x0000700011a63ed0, callback=0x0000700011a639c0)> const&) at ProducerImpl.cc:477:26
    frame #3: 0x000000010474abf9 libpulsar.2.10.0-SNAPSHOT.dylib`pulsar::ProducerImpl::sendAsync(this=0x0000000103101418, msg=0x0000700011a63ed0, callback=pulsar::SendCallback @ 0x0000700011a63c20)>) at ProducerImpl.cc:392:5
    frame #4: 0x00000001046e6823 libpulsar.2.10.0-SNAPSHOT.dylib`pulsar::PartitionedProducerImpl::sendAsync(this=0x0000000101f33598, msg=0x0000700011a63ed0, callback=pulsar::SendCallback @ 0x0000700011a63cc0)>) at PartitionedProducerImpl.cc:209:15
    frame #5: 0x0000000104734d6a libpulsar.2.10.0-SNAPSHOT.dylib`pulsar::Producer::sendAsync(this=0x00007ff7bfefef78, msg=0x0000700011a63ed0, callback=pulsar::SendCallback @ 0x0000700011a63ef0)>) at Producer.cc:68:12
    frame #6: 0x00000001002adcd8 main`ProducerTest_testSendAsyncCloseAsyncConcurrentlyWithLazyProducers_Test::TestBody(this=0x00006000017008c8)::$_0::operator()() const at ProducerTest.cc:202:26

@BewareMyPower
Copy link
Contributor

Another error.

2022-03-25 13:24:26.779 INFO  [0x1011f4600] ProducerTest:167 | Start of run 0
2022-03-25 13:24:26.814 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:26.814 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:26.815 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55382 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:26.817 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858660-partition-0, ] Getting connection from pool
2022-03-25 13:24:26.848 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858660-partition-0, ] Created producer on broker [127.0.0.1:55382 -> 127.0.0.1:6650] 
2022-03-25 13:24:26.860 INFO  [0x70001090f000] ProducerTest:209 | Closing
2022-03-25 13:24:26.860 INFO  [0x70001090f000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858660-partition-0, standalone-0-781] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858660-partition-0
2022-03-25 13:24:26.860 INFO  [0x70001090f000] ProducerTest:211 | Close called
2022-03-25 13:24:26.861 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858660-partition-0, standalone-0-781] Closed producer
2022-03-25 13:24:26.861 INFO  [0x70001090f000] ProducerTest:216 | Closed
2022-03-25 13:24:26.861 INFO  [0x70001088c000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:26.977 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:26.977 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55382 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:26.977 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55382 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:26.977 INFO  [0x1011f4600] ProducerTest:242 | End of run 0
2022-03-25 13:24:26.977 INFO  [0x1011f4600] ProducerTest:167 | Start of run 1
2022-03-25 13:24:27.008 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.009 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.010 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55384 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.011 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858661-partition-4, ] Getting connection from pool
2022-03-25 13:24:27.042 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858661-partition-4, ] Created producer on broker [127.0.0.1:55384 -> 127.0.0.1:6650] 
2022-03-25 13:24:27.054 INFO  [0x700010992000] ProducerTest:209 | Closing
2022-03-25 13:24:27.055 INFO  [0x700010992000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858661-partition-4, standalone-0-782] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858661-partition-4
2022-03-25 13:24:27.055 INFO  [0x700010992000] ProducerTest:211 | Close called
2022-03-25 13:24:27.056 INFO  [0x70001090f000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:27.057 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858661-partition-4, standalone-0-782] Closed producer
2022-03-25 13:24:27.057 INFO  [0x700010992000] ProducerTest:216 | Closed
2022-03-25 13:24:27.172 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:27.172 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55384 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:27.172 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55384 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:27.172 INFO  [0x1011f4600] ProducerTest:242 | End of run 1
2022-03-25 13:24:27.172 INFO  [0x1011f4600] ProducerTest:167 | Start of run 2
2022-03-25 13:24:27.204 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.204 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.205 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55386 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.208 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858672-partition-3, ] Getting connection from pool
2022-03-25 13:24:27.237 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858672-partition-3, ] Created producer on broker [127.0.0.1:55386 -> 127.0.0.1:6650] 
2022-03-25 13:24:27.249 INFO  [0x700010a15000] ProducerTest:209 | Closing
2022-03-25 13:24:27.250 INFO  [0x700010a15000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858672-partition-3, standalone-0-783] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858672-partition-3
2022-03-25 13:24:27.250 INFO  [0x700010a15000] ProducerTest:211 | Close called
2022-03-25 13:24:27.251 INFO  [0x700010992000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:27.251 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858672-partition-3, standalone-0-783] Closed producer
2022-03-25 13:24:27.251 INFO  [0x700010a15000] ProducerTest:216 | Closed
2022-03-25 13:24:27.367 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:27.367 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55386 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:27.367 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55386 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:27.367 INFO  [0x1011f4600] ProducerTest:242 | End of run 2
2022-03-25 13:24:27.368 INFO  [0x1011f4600] ProducerTest:167 | Start of run 3
2022-03-25 13:24:27.398 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.398 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.399 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55388 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.401 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858673-partition-7, ] Getting connection from pool
2022-03-25 13:24:27.432 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858673-partition-7, ] Created producer on broker [127.0.0.1:55388 -> 127.0.0.1:6650] 
2022-03-25 13:24:27.444 INFO  [0x700010a98000] ProducerTest:209 | Closing
2022-03-25 13:24:27.444 INFO  [0x700010a98000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858673-partition-7, standalone-0-784] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858673-partition-7
2022-03-25 13:24:27.444 INFO  [0x700010a98000] ProducerTest:211 | Close called
2022-03-25 13:24:27.445 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858673-partition-7, standalone-0-784] Closed producer
2022-03-25 13:24:27.445 INFO  [0x700010a98000] ProducerTest:216 | Closed
2022-03-25 13:24:27.445 INFO  [0x700010a15000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:27.560 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:27.560 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55388 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:27.560 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55388 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:27.560 INFO  [0x1011f4600] ProducerTest:242 | End of run 3
2022-03-25 13:24:27.560 INFO  [0x1011f4600] ProducerTest:167 | Start of run 4
2022-03-25 13:24:27.593 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.594 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.595 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55393 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.597 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858674-partition-9, ] Getting connection from pool
2022-03-25 13:24:27.628 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858674-partition-9, ] Created producer on broker [127.0.0.1:55393 -> 127.0.0.1:6650] 
2022-03-25 13:24:27.640 INFO  [0x700010b1b000] ProducerTest:209 | Closing
2022-03-25 13:24:27.641 INFO  [0x700010b1b000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858674-partition-9, standalone-0-785] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858674-partition-9
2022-03-25 13:24:27.641 INFO  [0x700010b1b000] ProducerTest:211 | Close called
2022-03-25 13:24:27.642 INFO  [0x700010a98000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:27.643 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858674-partition-9, standalone-0-785] Closed producer
2022-03-25 13:24:27.643 INFO  [0x700010b1b000] ProducerTest:216 | Closed
2022-03-25 13:24:27.757 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:27.757 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55393 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:27.757 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55393 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:27.757 INFO  [0x1011f4600] ProducerTest:242 | End of run 4
2022-03-25 13:24:27.757 INFO  [0x1011f4600] ProducerTest:167 | Start of run 5
2022-03-25 13:24:27.789 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.789 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.790 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55395 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.793 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858675-partition-0, ] Getting connection from pool
2022-03-25 13:24:27.822 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858675-partition-0, ] Created producer on broker [127.0.0.1:55395 -> 127.0.0.1:6650] 
2022-03-25 13:24:27.835 INFO  [0x700010b9e000] ProducerTest:209 | Closing
2022-03-25 13:24:27.835 INFO  [0x700010b9e000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858675-partition-0, standalone-0-786] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858675-partition-0
2022-03-25 13:24:27.835 INFO  [0x700010b9e000] ProducerTest:211 | Close called
2022-03-25 13:24:27.836 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858675-partition-0, standalone-0-786] Closed producer
2022-03-25 13:24:27.836 INFO  [0x700010b9e000] ProducerTest:216 | Closed
2022-03-25 13:24:27.836 INFO  [0x700010b1b000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:27.952 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:27.952 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55395 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:27.953 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55395 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:27.953 INFO  [0x1011f4600] ProducerTest:242 | End of run 5
2022-03-25 13:24:27.953 INFO  [0x1011f4600] ProducerTest:167 | Start of run 6
2022-03-25 13:24:27.982 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:27.982 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:27.983 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55397 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:27.985 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858676-partition-3, ] Getting connection from pool
2022-03-25 13:24:28.017 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858676-partition-3, ] Created producer on broker [127.0.0.1:55397 -> 127.0.0.1:6650] 
2022-03-25 13:24:28.029 INFO  [0x700010c21000] ProducerTest:209 | Closing
2022-03-25 13:24:28.029 INFO  [0x700010c21000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858676-partition-3, standalone-0-787] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858676-partition-3
2022-03-25 13:24:28.029 INFO  [0x700010c21000] ProducerTest:211 | Close called
2022-03-25 13:24:28.030 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858676-partition-3, standalone-0-787] Closed producer
2022-03-25 13:24:28.030 INFO  [0x700010b9e000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:28.030 INFO  [0x700010c21000] ProducerTest:216 | Closed
2022-03-25 13:24:28.146 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:28.147 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55397 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:28.147 INFO  [0x1011f4600] ProducerTest:242 | End of run 6
2022-03-25 13:24:28.147 INFO  [0x1011f4600] ProducerTest:167 | Start of run 7
2022-03-25 13:24:28.179 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:28.179 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:28.181 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55399 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:28.183 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858687-partition-3, ] Getting connection from pool
2022-03-25 13:24:28.213 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858687-partition-3, ] Created producer on broker [127.0.0.1:55399 -> 127.0.0.1:6650] 
2022-03-25 13:24:28.225 INFO  [0x700010ca4000] ProducerTest:209 | Closing
2022-03-25 13:24:28.225 INFO  [0x700010ca4000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858687-partition-3, standalone-0-788] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858687-partition-3
2022-03-25 13:24:28.225 INFO  [0x700010ca4000] ProducerTest:211 | Close called
2022-03-25 13:24:28.226 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858687-partition-3, standalone-0-788] Closed producer
2022-03-25 13:24:28.226 INFO  [0x700010ca4000] ProducerTest:216 | Closed
2022-03-25 13:24:28.226 INFO  [0x700010c21000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:28.341 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:28.341 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55399 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:28.341 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55399 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:28.341 INFO  [0x1011f4600] ProducerTest:242 | End of run 7
2022-03-25 13:24:28.341 INFO  [0x1011f4600] ProducerTest:167 | Start of run 8
2022-03-25 13:24:28.372 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:28.372 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:28.373 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55401 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:28.375 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858688-partition-6, ] Getting connection from pool
2022-03-25 13:24:28.407 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858688-partition-6, ] Created producer on broker [127.0.0.1:55401 -> 127.0.0.1:6650] 
2022-03-25 13:24:28.419 INFO  [0x700010d27000] ProducerTest:209 | Closing
2022-03-25 13:24:28.420 INFO  [0x700010d27000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858688-partition-6, standalone-0-789] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858688-partition-6
2022-03-25 13:24:28.420 INFO  [0x700010d27000] ProducerTest:211 | Close called
2022-03-25 13:24:28.420 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858688-partition-6, standalone-0-789] Closed producer
2022-03-25 13:24:28.420 INFO  [0x700010ca4000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:28.421 INFO  [0x700010d27000] ProducerTest:216 | Closed
2022-03-25 13:24:28.536 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:28.536 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55401 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:28.536 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55401 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:28.536 INFO  [0x1011f4600] ProducerTest:242 | End of run 8
2022-03-25 13:24:28.537 INFO  [0x1011f4600] ProducerTest:167 | Start of run 9
2022-03-25 13:24:28.569 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:28.569 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:28.570 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55403 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:28.572 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858689-partition-2, ] Getting connection from pool
2022-03-25 13:24:28.603 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858689-partition-2, ] Created producer on broker [127.0.0.1:55403 -> 127.0.0.1:6650] 
2022-03-25 13:24:28.615 INFO  [0x700010daa000] ProducerTest:209 | Closing
2022-03-25 13:24:28.615 INFO  [0x700010daa000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858689-partition-2, standalone-0-790] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-16481858689-partition-2
2022-03-25 13:24:28.615 INFO  [0x700010daa000] ProducerTest:211 | Close called
2022-03-25 13:24:28.616 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-16481858689-partition-2, standalone-0-790] Closed producer
2022-03-25 13:24:28.616 INFO  [0x700010d27000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:28.616 INFO  [0x700010daa000] ProducerTest:216 | Closed
2022-03-25 13:24:28.730 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:28.731 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55403 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:28.731 INFO  [0x1011f4600] ProducerTest:242 | End of run 9
2022-03-25 13:24:28.731 INFO  [0x70000fcc7000] ClientConnection:263 | [127.0.0.1:55403 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:28.731 INFO  [0x1011f4600] ProducerTest:167 | Start of run 10
2022-03-25 13:24:28.764 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:28.764 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:28.765 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55408 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:28.768 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586810-partition-6, ] Getting connection from pool
2022-03-25 13:24:28.797 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586810-partition-6, ] Created producer on broker [127.0.0.1:55408 -> 127.0.0.1:6650] 
2022-03-25 13:24:28.809 INFO  [0x700010e2d000] ProducerTest:209 | Closing
2022-03-25 13:24:28.809 INFO  [0x700010e2d000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586810-partition-6, standalone-0-791] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586810-partition-6
2022-03-25 13:24:28.809 INFO  [0x700010e2d000] ProducerTest:211 | Close called
2022-03-25 13:24:28.810 INFO  [0x700010daa000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:28.811 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586810-partition-6, standalone-0-791] Closed producer
2022-03-25 13:24:28.811 INFO  [0x700010e2d000] ProducerTest:216 | Closed
2022-03-25 13:24:28.926 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:28.927 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55408 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:28.927 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55408 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:28.927 INFO  [0x1011f4600] ProducerTest:242 | End of run 10
2022-03-25 13:24:28.927 INFO  [0x1011f4600] ProducerTest:167 | Start of run 11
2022-03-25 13:24:28.959 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:28.959 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:28.960 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55410 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:28.962 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586811-partition-7, ] Getting connection from pool
2022-03-25 13:24:28.992 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586811-partition-7, ] Created producer on broker [127.0.0.1:55410 -> 127.0.0.1:6650] 
2022-03-25 13:24:29.005 INFO  [0x700010eb0000] ProducerTest:209 | Closing
2022-03-25 13:24:29.005 INFO  [0x700010eb0000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586811-partition-7, standalone-0-792] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586811-partition-7
2022-03-25 13:24:29.005 INFO  [0x700010eb0000] ProducerTest:211 | Close called
2022-03-25 13:24:29.006 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586811-partition-7, standalone-0-792] Closed producer
2022-03-25 13:24:29.006 INFO  [0x700010eb0000] ProducerTest:216 | Closed
2022-03-25 13:24:29.006 INFO  [0x700010e2d000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:29.122 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:29.122 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55410 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:29.122 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55410 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:29.122 INFO  [0x1011f4600] ProducerTest:242 | End of run 11
2022-03-25 13:24:29.122 INFO  [0x1011f4600] ProducerTest:167 | Start of run 12
2022-03-25 13:24:29.154 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:29.154 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:29.155 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55412 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:29.158 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586912-partition-4, ] Getting connection from pool
2022-03-25 13:24:29.187 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586912-partition-4, ] Created producer on broker [127.0.0.1:55412 -> 127.0.0.1:6650] 
2022-03-25 13:24:29.199 INFO  [0x700010f33000] ProducerTest:209 | Closing
2022-03-25 13:24:29.199 INFO  [0x700010f33000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586912-partition-4, standalone-0-793] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586912-partition-4
2022-03-25 13:24:29.199 INFO  [0x700010f33000] ProducerTest:211 | Close called
2022-03-25 13:24:29.200 INFO  [0x700010eb0000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:29.201 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586912-partition-4, standalone-0-793] Closed producer
2022-03-25 13:24:29.201 INFO  [0x700010f33000] ProducerTest:216 | Closed
2022-03-25 13:24:29.315 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:29.316 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55412 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:29.316 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55412 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:29.316 INFO  [0x1011f4600] ProducerTest:242 | End of run 12
2022-03-25 13:24:29.316 INFO  [0x1011f4600] ProducerTest:167 | Start of run 13
2022-03-25 13:24:29.348 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:29.348 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:29.349 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55414 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:29.351 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586913-partition-5, ] Getting connection from pool
2022-03-25 13:24:29.382 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586913-partition-5, ] Created producer on broker [127.0.0.1:55414 -> 127.0.0.1:6650] 
2022-03-25 13:24:29.394 INFO  [0x700010fb6000] ProducerTest:209 | Closing
2022-03-25 13:24:29.394 INFO  [0x700010fb6000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586913-partition-5, standalone-0-794] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586913-partition-5
2022-03-25 13:24:29.394 INFO  [0x700010fb6000] ProducerTest:211 | Close called
2022-03-25 13:24:29.395 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586913-partition-5, standalone-0-794] Closed producer
2022-03-25 13:24:29.395 INFO  [0x700010f33000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:29.395 INFO  [0x700010fb6000] ProducerTest:216 | Closed
2022-03-25 13:24:29.511 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:29.511 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55414 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:29.511 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55414 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:29.511 INFO  [0x1011f4600] ProducerTest:242 | End of run 13
2022-03-25 13:24:29.512 INFO  [0x1011f4600] ProducerTest:167 | Start of run 14
2022-03-25 13:24:29.544 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:29.544 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:29.545 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55416 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:29.548 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586914-partition-0, ] Getting connection from pool
2022-03-25 13:24:29.578 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586914-partition-0, ] Created producer on broker [127.0.0.1:55416 -> 127.0.0.1:6650] 
2022-03-25 13:24:29.590 INFO  [0x700011039000] ProducerTest:209 | Closing
2022-03-25 13:24:29.590 INFO  [0x700011039000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586914-partition-0, standalone-0-795] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586914-partition-0
2022-03-25 13:24:29.591 INFO  [0x700011039000] ProducerTest:211 | Close called
2022-03-25 13:24:29.591 INFO  [0x700010fb6000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:29.592 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586914-partition-0, standalone-0-795] Closed producer
2022-03-25 13:24:29.592 INFO  [0x700011039000] ProducerTest:216 | Closed
2022-03-25 13:24:29.707 INFO  [0x1011f4600] ClientImpl:496 | Closing Pulsar client with 1 producers and 0 consumers
2022-03-25 13:24:29.707 INFO  [0x1011f4600] ClientConnection:1559 | [127.0.0.1:55416 -> 127.0.0.1:6650] Connection closed
2022-03-25 13:24:29.707 INFO  [0x1011f4600] ClientConnection:263 | [127.0.0.1:55416 -> 127.0.0.1:6650] Destroyed connection
2022-03-25 13:24:29.708 INFO  [0x1011f4600] ProducerTest:242 | End of run 14
2022-03-25 13:24:29.708 INFO  [0x1011f4600] ProducerTest:167 | Start of run 15
2022-03-25 13:24:29.739 INFO  [0x1011f4600] ClientConnection:189 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-03-25 13:24:29.739 INFO  [0x1011f4600] ConnectionPool:96 | Created connection for pulsar://localhost:6650
2022-03-25 13:24:29.740 INFO  [0x70000fcc7000] ClientConnection:375 | [127.0.0.1:55418 -> 127.0.0.1:6650] Connected to broker
2022-03-25 13:24:29.742 INFO  [0x70000fcc7000] HandlerBase:64 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586915-partition-0, ] Getting connection from pool
2022-03-25 13:24:29.772 INFO  [0x70000fcc7000] ProducerImpl:188 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586915-partition-0, ] Created producer on broker [127.0.0.1:55418 -> 127.0.0.1:6650] 
2022-03-25 13:24:29.783 INFO  [0x7000110bc000] ProducerTest:209 | Closing
2022-03-25 13:24:29.783 INFO  [0x7000110bc000] ProducerImpl:682 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586915-partition-0, standalone-0-796] Closing producer for topic persistent://public/default/testProducerIsConnectedPartitioned-164818586915-partition-0
2022-03-25 13:24:29.783 INFO  [0x7000110bc000] ProducerTest:211 | Close called
2022-03-25 13:24:29.784 INFO  [0x700011039000] ProducerTest:199 | closedAt set to 10
2022-03-25 13:24:29.785 INFO  [0x70000fcc7000] ProducerImpl:725 | [persistent://public/default/testProducerIsConnectedPartitioned-164818586915-partition-0, standalone-0-796] Closed producer
2022-03-25 13:24:29.786 INFO  [0x7000110bc000] ProducerTest:216 | Closed
pulsar-client-cpp/tests/ProducerTest.cc:229: Failure
Expected equality of these values:
  true
  promises[i].isComplete()
    Which is: false
[  FAILED  ] ProducerTest.testSendAsyncCloseAsyncConcurrentlyWithLazyProducers (3121 ms)

@BewareMyPower
Copy link
Contributor

I found this test is just wrong. See

if (i >= closedAt) {
ASSERT_EQ(ResultAlreadyClosed, res);
}

If we changed the code to

            if (i >= closedAt) {
                ASSERT_EQ(ResultAlreadyClosed, res);
            } else {
                ASSERT_EQ(ResultOk, res);
            }

The test will fail because the send results are all ResultAlreadyClosed, not only for i >= closedAt.

BewareMyPower added a commit to BewareMyPower/pulsar that referenced this issue Apr 22, 2022
Fixes apache#13849
Fixes apache#14848

### Motivation

apache#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
apache#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1
BewareMyPower added a commit that referenced this issue Apr 22, 2022
Fixes #13849
Fixes #14848

### Motivation

#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1
codelipenghui pushed a commit that referenced this issue Apr 28, 2022
Fixes #13849
Fixes #14848

### Motivation

#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1

(cherry picked from commit eeea9ca)
nicoloboschi pushed a commit to datastax/pulsar that referenced this issue May 9, 2022
Fixes apache#13849
Fixes apache#14848

### Motivation

apache#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
apache#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1

(cherry picked from commit eeea9ca)
(cherry picked from commit 83b6833)
BewareMyPower added a commit that referenced this issue May 24, 2022
Fixes #13849
Fixes #14848

### Motivation

#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1

(cherry picked from commit eeea9ca)
BewareMyPower added a commit that referenced this issue Jul 27, 2022
Fixes #13849
Fixes #14848

### Motivation

#11570 adds a `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers` for
the case that some `sendAsync` calls that are invoked after `closeAsync`
is called in another thread must complete with `ResultAlreadyClosed`.
It's flaky because the synchronization between two threads is not
strict. This test uses `sendStartLatch` for the order of `sendAsync` and
`closeAsync`:

```
sendAsync 0,1,...,9 -> sendStartLatch is done -> closeAsync
```

However, it cannot guarantee the rest `sendAsync` calls happen after
`closeAsync` is called. If so, all `sendAsync` calls will complete with
`ResultOk`.

On the other hand, this test is meaningless because it requires strict
synchronization between two threads so there is no need to run
`sendAsync` and `closeAsync` in two threads.

The verification of this test is also wrong, see
#13849 (comment).
When `closeAsync` is called, the previous `sendAsync` calls might not
complete, so all `sendAsync` will complete with `ResultAlreadyClosed`,
not only those called after `closeAsync`.

In addition, this PR also tries to fix the flaky `testReferenceCount`,
which assumes too strictly.

### Modifications

- Remove `testSendAsyncCloseAsyncConcurrentlyWithLazyProducers`
- Only check the reference count is greater than 0 instead of equal to 1

(cherry picked from commit eeea9ca)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants