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.

Sign up for GitHub

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

Jump to bottom

Test failed: Read when socket is closed #3

Closed
htfy96 opened this issue Jan 27, 2017 · 8 comments
Closed

Test failed: Read when socket is closed #3

htfy96 opened this issue Jan 27, 2017 · 8 comments

Comments

@htfy96
Copy link
Owner

htfy96 commented Jan 27, 2017

https://travis-ci.org/htfy96/c10k-server/jobs/195788297

5/5 Test #5: worker_thread_test ...............***Exception: SegFault  3.23 sec

[2017-01-27 07:48:57.243] [Server] [info] A new worker thread created

[2017-01-27 07:48:57.243] [DEBUG] [info] Main thread detached

[2017-01-27 07:49:00.243] [DEBUG] [info] Start to create clientWorker

[2017-01-27 07:49:00.243] [Client] [info] A new worker thread created

[2017-01-27 07:49:00.243] [DEBUG] [info] ClientWorker created

[2017-01-27 07:49:00.244] [DEBUG] [info] New fd added 9: 0/500

[2017-01-27 07:49:00.244] [Server] [info] new fd created = 7

[2017-01-27 07:49:00.244] [Server] [info] new fd created = 11

[2017-01-27 07:49:00.244] [DEBUG] [info] New fd added 12: 1/500

[2017-01-27 07:49:00.245] [Server] [info] new fd created = 13

[2017-01-27 07:49:00.245] [DEBUG] [info] New fd added 14: 2/500

[2017-01-27 07:49:00.245] [Server] [info] new fd created = 15

[2017-01-27 07:49:00.245] [DEBUG] [info] New fd added 7: 3/500

[2017-01-27 07:49:00.246] [Server] [info] new fd created = 9

[2017-01-27 07:49:00.247] [DEBUG] [info] New fd added 11: 4/500

[2017-01-27 07:49:00.247] [Server] [info] new fd created = 12

[2017-01-27 07:49:00.247] [DEBUG] [info] New fd added 13: 5/500

[2017-01-27 07:49:00.248] [Server] [info] new fd created = 14

[2017-01-27 07:49:00.248] [DEBUG] [info] New fd added 7: 6/500

[2017-01-27 07:49:00.249] [DEBUG] [info] New fd added 11: 7/500

[2017-01-27 07:49:00.249] [Server] [info] new fd created = 9

[2017-01-27 07:49:00.250] [DEBUG] [info] New fd added 7: 8/500

[2017-01-27 07:49:00.250] [Server] [info] new fd created = 12

[2017-01-27 07:49:00.251] [Server] [info] new fd created = 13

[2017-01-27 07:49:00.251] [DEBUG] [info] New fd added 9: 9/500

[2017-01-27 07:49:00.253] [Server] [info] new fd created = 11

[2017-01-27 07:49:00.253] [DEBUG] [info] New fd added 7: 10/500

[2017-01-27 07:49:00.254] [Server] [info] new fd created = 12

[2017-01-27 07:49:00.254] [DEBUG] [info] New fd added 9: 11/500

[2017-01-27 07:49:00.255] [Server] [info] new fd created = 13

[2017-01-27 07:49:00.255] [DEBUG] [info] New fd added 7: 12/500

[2017-01-27 07:49:00.256] [Server] [info] new fd created = 11

[2017-01-27 07:49:00.256] [DEBUG] [info] New fd added 9: 13/500

[2017-01-27 07:49:00.257] [Server] [info] new fd created = 12

[2017-01-27 07:49:00.257] [DEBUG] [info] New fd added 7: 14/500

[2017-01-27 07:49:00.258] [Server] [info] new fd created = 13

[2017-01-27 07:49:00.258] [DEBUG] [info] New fd added 9: 15/500

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

worker_thread-test is a Catch v1.6.1 host application.

Run with -? for options

-------------------------------------------------------------------------------

multiple WorkerThread test

-------------------------------------------------------------------------------

/data/test/worker_thread_test.cpp:98

...............................................................................

/data/test/worker_thread_test.cpp:98: FAILED:

due to unexpected exception with message:

  Read when socket is closed

===============================================================================

test casesworker_thread-test is a Catch v1.6.1 host application.

Run with -? for options

: 1 | 1 failed

assertions: 2 | 2 failed

80% tests passed, 1 tests failed out of 5

Total Test time (real) =   5.59 sec

The following tests FAILED:

	  5 - worker_thread_test (SEGFAULT)
@htfy96
Copy link
Owner Author

htfy96 commented Jan 27, 2017

https://travis-ci.org/htfy96/c10k-server/jobs/195895315

@htfy96
Copy link
Owner Author

htfy96 commented Jan 27, 2017

The two bugs are probably caused by data race in eventloop::handle_event: Event e { data->fd } and eventloop:modify_event which changes data->fd in another thread. Current workaround is to force handle_event to acquire map_mutex before reading data->fd

7ce2d49

@htfy96
Copy link
Owner Author

htfy96 commented Jan 27, 2017

Still broken in https://travis-ci.org/htfy96/c10k-server/jobs/195955076 7ce2d49.

1x SEGV
2x unhandled exception read when socket is closed

No DR was reported

@htfy96
Copy link
Owner Author

htfy96 commented Jan 29, 2017

With logbt we acquired backtrace of SEGV:
https://travis-ci.org/htfy96/c10k-server/jobs/196185054

worker_thread-test: ../nptl/pthread_mutex_lock.c:81: __pthread_mutex_lock: Assertion `mutex->__data.__owner == 0' failed.

Core was generated by `/data/build/worker_thread-test'.

Program terminated with signal SIGABRT, Aborted.

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
58	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.

[Current thread is 1 (Thread 0x7ff0ced02700 (LWP 48))]

Thread 4 (Thread 0x7ff0cfd04700 (LWP 46)):
#0  0x00007ff0d0105ced in write () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007ff0d0088927 in _IO_new_file_write (f=0x7ff0d03d0600 <_IO_2_1_stdout_>, data=0x891af0, n=707) at fileops.c:1271
#2  0x00007ff0d008a492 in new_do_write (to_do=707, data=0x891af0 "\n\n", '~' <repeats 158 times>, "\n\nworker_thread-test is a Catch v1.6.1 h"..., fp=0x7ff0d03d0600 <_IO_2_1_stdout_>) at fileops.c:526
#3  _IO_new_do_write (fp=0x7ff0d03d0600 <_IO_2_1_stdout_>, data=0x891af0 "\n\n", '~' <repeats 158 times>, "\n\nworker_thread-test is a Catch v1.6.1 h"..., to_do=707) at fileops.c:502
#4  0x00007ff0d0087ec8 in _IO_new_file_sync (fp=0x7ff0d03d0600 <_IO_2_1_stdout_>) at fileops.c:882
#5  0x00007ff0d007ca1c in __GI__IO_fflush (fp=0x7ff0d03d0600 <_IO_2_1_stdout_>) at iofflush.c:40
#6  0x00007ff0d06fd98e in std::ostream::flush() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x0000000000467d14 in Catch::ConsoleReporter::printTestCaseAndSectionHeader() ()
#8  0x0000000000467efc in Catch::ConsoleReporter::lazyPrint() ()
#9  0x00000000004683dc in Catch::ConsoleReporter::assertionEnded(Catch::AssertionStats const&) ()
#10 0x000000000045f881 in Catch::RunContext::assertionEnded(Catch::AssertionResult const&) ()
#11 0x0000000000448f6d in Catch::ResultBuilder::handleResult(Catch::AssertionResult const&) ()
#12 0x000000000044a292 in Catch::ResultBuilder::captureExpression() ()
#13 0x000000000046b9c1 in Catch::RunContext::handleFatalErrorCondition(std::string const&) ()
#14 0x00000000004579e5 in Catch::fatal(std::string const&, int) ()
#15 0x0000000000457a8c in Catch::FatalConditionHandler::handleSignal(int) ()
#16 <signal handler called>
#17 0x00007ff0c8000078 in ?? ()
#18 0x000000000047dc35 in c10k::EventLoop::loop() ()
#19 0x0000000000445201 in std::thread::_Impl<std::_Bind_simple<std::reference_wrapper<c10k::detail::WorkerThread<ServerHandler> > ()> >::_M_run() ()
#20 0x00007ff0d06a78f0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#21 0x00007ff0d097b6ca in start_thread (arg=0x7ff0cfd04700) at pthread_create.c:333
#22 0x00007ff0d01160af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105

Thread 3 (Thread 0x7ff0d0da9740 (LWP 45)):
#0  __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
#1  0x00007ff0d007d992 in __GI__IO_fwrite (buf=0x7ff0d03d1760 <_IO_stdfile_1_lock>, size=1, count=26, fp=0x7ff0d012407c <__lll_lock_wait_private+28>) at iofwrite.c:37
#2  0x00007ff0d06fe9f6 in std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x000000000046794b in Catch::ConsoleReporter::printOpenHeader(std::string const&) ()
#4  0x0000000000467ae5 in Catch::ConsoleReporter::printTestCaseAndSectionHeader() ()
#5  0x0000000000467efc in Catch::ConsoleReporter::lazyPrint() ()
#6  0x00000000004683dc in Catch::ConsoleReporter::assertionEnded(Catch::AssertionStats const&) ()
#7  0x000000000045f881 in Catch::RunContext::assertionEnded(Catch::AssertionResult const&) ()
#8  0x0000000000448f6d in Catch::ResultBuilder::handleResult(Catch::AssertionResult const&) ()
#9  0x000000000044a292 in Catch::ResultBuilder::captureExpression() ()
#10 0x000000000044e158 in Catch::ResultBuilder::useActiveException(Catch::ResultDisposition::Flags) ()
#11 0x0000000000452e02 in Catch::runTests(Catch::Ptr<Catch::Config> const&) ()
#12 0x000000000043099a in main ()

Thread 2 (Thread 0x7ff0cf503700 (LWP 47)):
#0  0x00007ff0d09848fd in accept () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000000432954 in std::thread::_Impl<std::_Bind_simple<____C_A_T_C_H____T_E_S_T____0()::{lambda()#1} ()> >::_M_run() ()
#2  0x00007ff0d06a78f0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007ff0d097b6ca in start_thread (arg=0x7ff0cf503700) at pthread_create.c:333
#4  0x00007ff0d01160af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105

Thread 1 (Thread 0x7ff0ced02700 (LWP 48)):
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
#1  0x00007ff0d00453ea in __GI_abort () at abort.c:89
#2  0x00007ff0d003bbb7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x7ff0d09873c2 "mutex->__data.__owner == 0", file=file@entry=0x7ff0d09873a5 "../nptl/pthread_mutex_lock.c", line=line@entry=81, function=function@entry=0x7ff0d0987530 <__PRETTY_FUNCTION__.8476> "__pthread_mutex_lock") at assert.c:92
#3  0x00007ff0d003bc62 in __GI___assert_fail (assertion=assertion@entry=0x7ff0d09873c2 "mutex->__data.__owner == 0", file=file@entry=0x7ff0d09873a5 "../nptl/pthread_mutex_lock.c", line=line@entry=81, function=function@entry=0x7ff0d0987530 <__PRETTY_FUNCTION__.8476> "__pthread_mutex_lock") at assert.c:101
#4  0x00007ff0d097e068 in __GI___pthread_mutex_lock (mutex=<optimized out>) at ../nptl/pthread_mutex_lock.c:81
#5  0x000000000047dc62 in c10k::EventLoop::loop() ()
#6  0x0000000000445171 in std::thread::_Impl<std::_Bind_simple<std::reference_wrapper<c10k::detail::WorkerThread<ClientHandler> > ()> >::_M_run() ()

#7  0x00007ff0d06a78f0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

#8  0x00007ff0d097b6ca in start_thread (arg=0x7ff0ced02700) at pthread_create.c:333
#9  0x00007ff0d01160af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105

@htfy96
Copy link
Owner Author

htfy96 commented Jan 29, 2017

Here is the most detailed backtrace until now from travis CI:

Thread 3 (Thread 0x7f49e28c2700 (LWP 45)):
#0  0x00007f49e324d323 in std::locale::locale() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#1  0x00007f49e324a9c8 in std::ios_base::_M_init() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#2  0x00007f49e32a1c51 in std::basic_ios<char, std::char_traits<char> >::init(std::basic_streambuf<char, std::char_traits<char> >*) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007f49e32c3d26 in std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >::basic_ostringstream(std::_Ios_Openmode) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x0000559c47a0744e in Catch::ConsoleReporter::SummaryColumn::addRow (this=0x7f49e28bd900, count=2) at /data/vendor/Catch/include/reporters/catch_reporter_console.hpp:329
#5  0x0000559c47a079ed in Catch::ConsoleReporter::printTotals (this=0x559c48c54fa0, totals=...) at /data/vendor/Catch/include/reporters/catch_reporter_console.hpp:364
#6  0x0000559c47a05ea3 in Catch::ConsoleReporter::testRunEnded (this=0x559c48c54fa0, _testRunStats=...) at /data/vendor/Catch/include/reporters/catch_reporter_console.hpp:97
#7  0x0000559c479fa5e4 in Catch::RunContext::handleFatalErrorCondition (this=0x7ffe07827440, message="SIGSEGV - Segmentation violation signal") at /data/vendor/Catch/include/internal/catch_run_context.hpp:255
#8  0x0000559c479f8312 in Catch::fatal (message="SIGSEGV - Segmentation violation signal", exitCode=-11) at /data/vendor/Catch/include/internal/catch_fatal_condition.hpp:19
#9  0x0000559c479f83d7 in Catch::FatalConditionHandler::handleSignal (sig=11) at /data/vendor/Catch/include/internal/catch_fatal_condition.hpp:59
#10 <signal handler called>
#11 0x00007f49dc0008b0 in ?? ()
#12 0x0000559c47a5c052 in std::_Mem_fn_base<void (c10k::Connection::*)(c10k::Event const&), true>::_M_call<std::shared_ptr<c10k::Connection>&, c10k::Event const&> (this=0x7f49dc0069b0, __ptr=std::shared_ptr (empty) 0x0) at /usr/include/c++/5/functional:634
#13 0x0000559c47a5be0d in std::_Mem_fn_base<void (c10k::Connection::*)(c10k::Event const&), true>::operator()<std::shared_ptr<c10k::Connection>&, c10k::Event const&, void> (this=0x7f49dc0069b0, __object=std::shared_ptr (empty) 0x0) at /usr/include/c++/5/functional:610 // why do we have an empty shared_ptr here?
#14 0x0000559c47a5b8ab in std::_Bind<std::_Mem_fn<void (c10k::Connection::*)(c10k::Event const&)> (std::shared_ptr<c10k::Connection>, std::_Placeholder<1>)>::__call<void, c10k::Event const&, 0ul, 1ul>(std::tuple<c10k::Event const&>&&, std::_Index_tuple<0ul, 1ul>) (this=0x7f49dc0069b0, __args=<unknown type in /data/build/worker_thread-test, CU 0x17316a, DIE 0x1b7cca>) at /usr/include/c++/5/functional:1074
#15 0x0000559c47a5aa28 in std::_Bind<std::_Mem_fn<void (c10k::Connection::*)(c10k::Event const&)> (std::shared_ptr<c10k::Connection>, std::_Placeholder<1>)>::operator()<c10k::Event const&, void>(c10k::Event const&) (this=0x7f49dc0069b0) at /usr/include/c++/5/functional:1133
#16 0x0000559c47a5903c in std::_Function_handler<void (c10k::Event const&), std::_Bind<std::_Mem_fn<void (c10k::Connection::*)(c10k::Event const&)> (std::shared_ptr<c10k::Connection>, std::_Placeholder<1>)> >::_M_invoke(std::_Any_data const&, c10k::Event const&) (__functor=..., __args#0=...) at /usr/include/c++/5/functional:1871
#17 0x0000559c47a4ff28 in std::function<void (c10k::Event const&)>::operator()(c10k::Event const&) const (this=0x7f49d4000f28, __args#0=...) at /usr/include/c++/5/functional:2267
#18 0x0000559c47a4d745 in c10k::EventLoop::<lambda(const epoll_event&)>::operator()(const epoll_event &) const (__closure=0x7f49e28bec60, ev=...) at /data/src/c10k/event_loop.cpp:64
#19 0x0000559c47a4e004 in std::for_each<epoll_event*, c10k::EventLoop::handle_events(epoll_event*, epoll_event*)::<lambda(const epoll_event&)> >(epoll_event *, epoll_event *, c10k::EventLoop::<lambda(const epoll_event&)>) (__first=0x7f49e28bed6c, __last=0x7f49e28bed54, __f=...) at /usr/include/c++/5/bits/stl_algo.h:3767
#20 0x0000559c47a4d79e in c10k::EventLoop::handle_events (this=0x7ffe078264c0, st=0x7f49e28bed60, ed=0x7f49e28bed54) at /data/src/c10k/event_loop.cpp:65
#21 0x0000559c47a4d5da in c10k::EventLoop::loop (this=0x7ffe078264c0) at /data/src/c10k/event_loop.cpp:49
#22 0x0000559c479de0ce in c10k::detail::WorkerThread<ServerHandler>::operator() (this=0x7ffe078264c0) at /data/src/c10k/worker_thread.hpp:42
#23 0x0000559c479ddf59 in std::__invoke<c10k::detail::WorkerThread<ServerHandler>>(c10k::detail::WorkerThread<ServerHandler>&) (__f=...) at /usr/include/c++/5/functional:201
#24 0x0000559c479ddd73 in std::reference_wrapper<c10k::detail::WorkerThread<ServerHandler> >::operator()<>() const (this=0x559c48c59528) at /usr/include/c++/5/functional:428
#25 0x0000559c479ddb30 in std::_Bind_simple<std::reference_wrapper<c10k::detail::WorkerThread<ServerHandler> > ()>::_M_invoke<>(std::_Index_tuple<>) (this=0x559c48c59528) at /usr/include/c++/5/functional:1531
#26 0x0000559c479dd30a in std::_Bind_simple<std::reference_wrapper<c10k::detail::WorkerThread<ServerHandler> > ()>::operator()() (this=0x559c48c59528) at /usr/include/c++/5/functional:1520
#27 0x0000559c479dc92f in std::thread::_Impl<std::_Bind_simple<std::reference_wrapper<c10k::detail::WorkerThread<ServerHandler> > ()> >::_M_run() (this=0x559c48c59510) at /usr/include/c++/5/thread:115

#28 0x00007f49e32658f0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

#29 0x00007f49e35396ca in start_thread (arg=0x7f49e28c2700) at pthread_create.c:333
#30 0x00007f49e2cd40af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105

@htfy96
Copy link
Owner Author

htfy96 commented Jan 30, 2017 

#1  0x0000562d556e639c in std::_Mem_fn<void (c10k::Connection::*)(c10k::Event const&)>::_M_call<std::shared_ptr<c10k::Connection>&, c10k::Event const&> (this=0x7fbb70003b30, __ptr=std::shared_ptr (count 1744830584, weak 32698) 0x7fbb68002770) at /usr/include/c++/4.9/functional:526

Since shared_cnt block is placed at the end of Handler, I guess there exists overflow in this program :(

@htfy96
Copy link
Owner Author

htfy96 commented Jan 30, 2017 

#9  0x000055ab953e3c3e in c10k::EventLoop::handle_events (this=0x7ffdde173f30, st=0x7f953002fd60, ed=0x7f953002fd54) at /data/src/c10k/event_loop.cpp:65

WTF

@htfy96
Copy link
Owner Author

htfy96 commented Feb 4, 2017

Finally fixed in d0a931e 458d177 7ce2d49 8d3abb5 75928e8 29daa07

@htfy96 htfy96 closed this as completed Feb 4, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@htfy96