pulsar-client-cpp
pulsar-client-cpp copied to clipboard
Flaky test: ClientTest.testCloseClient
FAILED TESTS (5/418):
743 ms: ./pulsar-tests ClientTest.testReferenceCount (try #1)
11653 ms: ./pulsar-tests ClientTest.testCloseClient (try #1)
9692 ms: ./pulsar-tests ClientTest.testCloseClient (try #2)
8242 ms: ./pulsar-tests ClientTest.testCloseClient (try #3)
8126 ms: ./pulsar-tests ClientTest.testCloseClient (try #4)
// ...
2022-12-29T01:22:46.5133298Z 2022-12-29 01:22:46.253 INFO [140291349905088] ConnectionPool:97 | Created connection for pulsar://localhost:6650
2022-12-29T01:22:46.5133649Z 2022-12-29 01:22:46.253 INFO [140291346781760] ClientConnection:387 | [[::1]:60292 -> [::1]:6650] Connected to broker
2022-12-29T01:22:46.5133967Z 2022-12-29 01:22:46.253 INFO [140291349905088] ClientImpl:516 | Closing Pulsar client with 0 producers and 0 consumers
2022-12-29T01:22:46.5134331Z 2022-12-29 01:22:46.254 INFO [140291330000448] ClientConnection:1602 | [[::1]:60292 -> [::1]:6650] Connection disconnected
2022-12-29T01:22:46.5134974Z 2022-12-29 01:22:46.254 ERROR [140291346781760] ClientImpl:183 | Error Checking/Getting Partition Metadata while creating producer on persistent://public/default/client-test-close-client-1672276958 -- NotConnected
2022-12-29T01:22:46.5135316Z 2022-12-29 01:22:46.254 INFO [140291330000448] ClientConnection:268 | [[::1]:60292 -> [::1]:6650] Destroyed connection
2022-12-29T01:22:46.5135700Z 2022-12-29 01:22:46.255 INFO [140291349905088] ClientConnection:190 | [<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
2022-12-29T01:22:46.5136036Z 2022-12-29 01:22:46.255 INFO [140291349905088] ConnectionPool:97 | Created connection for pulsar://localhost:6650
2022-12-29T01:22:46.5136486Z 2022-12-29 01:22:46.255 INFO [140291330000448] ClientConnection:387 | [[::1]:60300 -> [::1]:6650] Connected to broker
2022-12-29T01:22:46.5136808Z 2022-12-29 01:22:46.255 INFO [140291349905088] ClientImpl:516 | Closing Pulsar client with 0 producers and 0 consumers
2022-12-29T01:22:46.5137078Z [208/418] ClientTest.testCloseClient returned with exit code -11 (8126 ms)
It can be easily reproduced in local env by:
./tests/pulsar-tests --gtest_filter='ClientTest.testCloseClient' --gtest_repeat=20
This test is still very flaky on macOS.
I tested tag v3.2.0.
* thread #4, stop reason = EXC_BAD_ACCESS (code=1, address=0x98)
frame #0: 0x0000000100070d44 pulsar-tests`boost::asio::detail::kqueue_reactor::deregister_descriptor(this=0x0000000103804820, descriptor=8, descriptor_data=0x0000600002608070, closing=true) at kqueue_reactor.ipp:336:25
333
334 mutex::scoped_lock descriptor_lock(descriptor_data->mutex_);
335
-> 336 if (!descriptor_data->shutdown_)
337 {
338 if (closing)
339 {
Target 0: (pulsar-tests) stopped.
(lldb) bt
* thread #4, stop reason = EXC_BAD_ACCESS (code=1, address=0x98)
* frame #0: 0x0000000100070d44 pulsar-tests`boost::asio::detail::kqueue_reactor::deregister_descriptor(this=0x0000000103804820, descriptor=8, descriptor_data=0x0000600002608070, closing=true) at kqueue_reactor.ipp:336:25
frame #1: 0x00000001043126a0 libpulsar.dylib`boost::asio::detail::reactive_socket_service_base::close(this=0x0000600002114078, impl=0x0000600002608068, ec=0x000000016ff9dca0) at reactive_socket_service_base.ipp:110:14
frame #2: 0x00000001042ca264 libpulsar.dylib`boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::any_io_executor>::close(this=0x0000600002608060, ec=0x000000016ff9dca0) at basic_socket.hpp:547:25
frame #3: 0x00000001042d73c0 libpulsar.dylib`pulsar::ClientConnection::closeSocket(this=0x0000000106809400) at ClientConnection.cc:1334:18
frame #4: 0x00000001042c49ec libpulsar.dylib`pulsar::ClientConnection::close(this=0x0000000106809400, result=ResultDisconnected) at ClientConnection.cc:1163:5
frame #5: 0x00000001043eb718 libpulsar.dylib`pulsar::ConnectionPool::close(this=0x0000000103804308) at ConnectionPool.cc:56:22
frame #6: 0x0000000104362320 libpulsar.dylib`pulsar::ClientImpl::shutdown(this=0x00000001038041a8) at ClientImpl.cc:703:16
frame #7: 0x00000001043d5c5c libpulsar.dylib`pulsar::ClientImpl::handleClose(this=0x0000600001708408)>)::$_4::operator()() const at ClientImpl.cc:668:13
frame #8: 0x00000001043d5c00 libpulsar.dylib`decltype(__f=0x0000600001708408)>)::$_4>()()) std::__1::__invoke[abi:v15006]<pulsar::ClientImpl::handleClose(pulsar::Result, std::__1::shared_ptr<int>, std::__1::function<void (pulsar::Result)>)::$_4>(pulsar::ClientImpl::handleClose(pulsar::Result, std::__1::shared_ptr<int>, std::__1::function<void (pulsar::Result)>)::$_4&&) at invoke.h:394:23
frame #9: 0x00000001043d5b9c libpulsar.dylib`void std::__1::__thread_execute[abi:v15006]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, pulsar::ClientImpl::handleClose(pulsar::Result, std::__1::shared_ptr<int>, std::__1::function<void (pulsar::Result)>)::$_4>(__t=size=2, (null)=__tuple_indices<> @ 0x000000016ff9ef7f)>)::$_4>&, std::__1::__tuple_indices<>) at thread:290:5
frame #10: 0x00000001043d553c libpulsar.dylib`void* std::__1::__thread_proxy[abi:v15006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, pulsar::ClientImpl::handleClose(pulsar::Result, std::__1::shared_ptr<int>, std::__1::function<void (pulsar::Result)>)::$_4> >(__vp=0x0000600001708400) at thread:301:5
frame #11: 0x0000000188213fa8 libsystem_pthread.dylib`_pthread_start + 148