`SubscribeProcessedThreeEntriesBecauseWeWaitInTheScope` test sometimes never ends on Mac

mzhurovich commented 9 years ago

Same thing happens in SubscribeToStreamViaHTTP test also. Looks like we have a deadlock in Sherlock.

(lldb) thread backtrace all
  thread #1: tid = 0xfbcd4, 0x00007fff89a5648a libsystem_kernel.dylib`__semwait_signal + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff89a5648a libsystem_kernel.dylib`__semwait_signal + 10
    frame #1: 0x00007fff94614b98 libsystem_pthread.dylib`pthread_join + 445
    frame #2: 0x00007fff95355ba0 libc++.1.dylib`std::__1::thread::join() + 20
    frame #3: 0x0000000103717fd2 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(this=0x00007fd620f00100)::RecordsCollector>::Impl::~Impl() + 114 at sherlock.h:291
    frame #4: 0x0000000103717f55 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(this=0x00007fd620f00100)::RecordsCollector>::Impl::~Impl() + 21 at sherlock.h:283
    frame #5: 0x0000000103717f21 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::~ListenerScope() [inlined] std::__1::default_delete<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::Impl>::operator(this=0x00007fff5c532678, __ptr=0x00007fd620f00100)(sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::Impl*) const + 30 at memory:2431
    frame #6: 0x0000000103717f03 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::~ListenerScope() + 96 at memory:2630
    frame #7: 0x0000000103717ea3 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::~ListenerScope() + 16 at memory:2598
    frame #8: 0x0000000103717e93 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::~ListenerScope() [inlined] std::__1::unique_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::Impl, std::__1::default_delete<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::Impl> >::~unique_ptr(this=0x00007fff5c532678) + 8 at memory:2598
    frame #9: 0x0000000103717e8b test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(this=0x00007fff5c532678)::RecordsCollector>::~ListenerScope() + 27 at sherlock.h:247
    frame #10: 0x000000010370b965 test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(this=0x00007fff5c532678)::RecordsCollector>::~ListenerScope() + 21 at sherlock.h:247
    frame #11: 0x0000000103706f25 test`Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(this=0x00007fd620f00000) + 1157 at test.cc:222
    frame #12: 0x00000001037c3d53 test`void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(object=0x00007fd620f00000, method=0x0000000000000021, location=0x00000001037e8fa5)(), char const*) + 131 at gtest.cc:2078
    frame #13: 0x00000001037209e7 test`void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(object=0x00007fd620f00000, method=0x0000000000000021, location=0x00000001037e8fa5)(), char const*) + 119 at gtest.cc:2114
    frame #14: 0x00000001036dc875 test`testing::Test::Run(this=0x00007fd620f00000) + 197 at gtest.cc:2150
    frame #15: 0x00000001036dddeb test`testing::TestInfo::Run(this=0x00007fd620c13a40) + 219 at gtest.cc:2326
    frame #16: 0x00000001036deab7 test`testing::TestCase::Run(this=0x00007fd620c13570) + 231 at gtest.cc:2444
    frame #17: 0x00000001036ed4b3 test`testing::internal::UnitTestImpl::RunAllTests(this=0x00007fd620c132b0) + 915 at gtest.cc:4315
    frame #18: 0x00000001037bfa03 test`bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(object=0x00007fd620c132b0, method=0x00000001036ed120, location=0x00000001037e9664)(), char const*) + 131 at gtest.cc:2078
    frame #19: 0x00000001037231b7 test`bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(object=0x00007fd620c132b0, method=0x00000001036ed120, location=0x00000001037e9664)(), char const*) + 119 at gtest.cc:2114
    frame #20: 0x00000001036ed0b0 test`testing::UnitTest::Run(this=0x00000001037f7da0) + 416 at gtest.cc:3926
    frame #21: 0x0000000103729b11 test`RUN_ALL_TESTS() + 17 at gtest.h:2288
    frame #22: 0x0000000103704c86 test`main(argc=1, argv=0x00007fd620c147c0) + 102 at gtest-main-with-dflags.h:26
    frame #23: 0x00007fff8b9da5c9 libdyld.dylib`start + 1
    frame #24: 0x00007fff8b9da5c9 libdyld.dylib`start + 1

* thread #2: tid = 0xfbcdb, 0x00007fff89a56136 libsystem_kernel.dylib`__psynch_cvwait + 10
  * frame #0: 0x00007fff89a56136 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff94611e0c libsystem_pthread.dylib`_pthread_cond_wait + 693
    frame #2: 0x00007fff95316c95 libc++.1.dylib`std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&) + 47
    frame #3: 0x0000000103781a45 test`void std::__1::condition_variable::wait<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl::Wait(std::__1::function<bool (std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> > const&)>) const::'lambda'()>(this=0x00007fd620f00278, __lk=0x0000000103a0aa38, __pred=bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl::(anonymous class) at 0x0000000103a0a990)>) const::'lambda'()) + 69 at __mutex_base:340
    frame #4: 0x000000010377b80b test`bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl::Wait(this=0x00007fd620f00220, predicate=function<bool (const std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> > &)> at 0x0000000103a0abb0)>) const + 331 at waitable_atomic.h:192
    frame #5: 0x0000000103710a2f test`sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody(terminate=shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<RecordsCollector>::ReallyAtomicFlag> at 0x0000000103a0adc0, data=0x00007fd620f00220, listener=OptionallyOwned<RecordsCollector> at 0x0000000103a0ada8)::RecordsCollector>::Impl::StaticListenerThread(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>) + 143 at sherlock.h:317
    frame #6: 0x00000001037117d0 test`void* std::__1::__thread_proxy<std::__1::tuple<void (*)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> > >(void*) [inlined] decltype(__f=0x00007fd620f002b0, __args=0x00007fd620f002b8, __args=0x00007fd620f002c8, __args=0x00007fd620f002d0)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>)>(fp)(std::__1::forward<std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> >(fp0))) std::__1::__invoke<void (*)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> >(void (*&&)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>&&, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>&&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>&&) + 232 at __functional_base:413
    frame #7: 0x00000001037116e8 test`void* std::__1::__thread_proxy<std::__1::tuple<void (*)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> > >(void*) [inlined] void std::__1::__thread_execute<void (*)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>, 1ul, 2ul, 3ul>(__t=0x00007fd620f002b0, (null)=__tuple_indices<1, 2, 3> at 0x0000000103a0ad80)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> >&, std::__1::__tuple_indices<1ul, 2ul, 3ul>) + 136 at thread:332
    frame #8: 0x0000000103711660 test`void* std::__1::__thread_proxy<std::__1::tuple<void (*)(std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl&, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>), std::__1::shared_ptr<sherlock::StreamInstanceImpl<RecordWithTimestamp>::ListenerScope<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector>::ReallyAtomicFlag>, std::__1::reference_wrapper<bricks::WaitableAtomicImpl<std::__1::vector<RecordWithTimestamp, std::__1::allocator<RecordWithTimestamp> >, false>::BasicImpl>, sherlock::OptionallyOwned<Sherlock_SubscribeToStreamViaHTTP_Test::TestBody()::RecordsCollector> > >(__vp=0x00007fd620f002b0) + 368 at thread:342
    frame #9: 0x00007fff94611268 libsystem_pthread.dylib`_pthread_body + 131
    frame #10: 0x00007fff946111e5 libsystem_pthread.dylib`_pthread_start + 176
    frame #11: 0x00007fff9460f41d libsystem_pthread.dylib`thread_start + 13

dkorolev commented 9 years ago

On me, thanks @mzhurovich.

Consistently reproducible:

./.noshit/test  --gtest_repeat=987654321 --gtest_filter=Sherlock.SubscribeProcessedThreeEntriesBecauseWeWaitInTheScope

dkorolev commented 9 years ago

Looked into it.

It appears to be a consequence of a bad design, namely:

The listener currently has two semantics: a non-detachable one, the lifetime of which is bounded by the top-level scoped object, and a detachable one, that gets passed a unique_ptr<> to the actual listener object, and passes the ownership of this listener object to a dedicated thread.
These two implementations are now joined in one class.
These two implementations should have different semantics as to which thread owns the termination flag, since either the caller or the listener thread can outlive the other.
Thus, this flag is now boxed into a shared_ptr<>
+ multi-threading concurrency issues I am not proficient in.
...
= PROFIT : The issue we are observing.

I think the right solution is to decouple detachable and non-detachable implementations altogether. No time from my end as of right now, hope to get back to it shotlt.

dkorolev commented 9 years ago

By the way, this is fixed!

KnowSheet / Sherlock

`SubscribeProcessedThreeEntriesBecauseWeWaitInTheScope` test sometimes never ends on Mac #14