On Fri, Jun 4, 2010 at 6:46 PM, Jorge Moraleda <moraleda@rii.ricoh.com> wrote:
When testing boost.asio (example/http/server2) for race conditions using valgrind drd, some errors are reported right after the first connection to the server is made. I am using Valgrind-3.6.0.SVN and gcc version 4.4.4 (Debian 4.4.4-4). This is an up to date Debian sid 64 bit system.
To reproduce:
g++ -l boost_thread -l boost_system /opt/boost/boost/doc/html/boost_asio/example/http/server2/*cpp
valgrind --tool=drd ./a.out 127.0.0.1 31174 8 /tmp
While it is running type "http://localhost:31174/main.cpp" in your browser (where main.cpp is a file in /tmp). Then several race conditions occur. These are the valgrind error messages:
==7737== drd, a thread error detector ==7737== Copyright (C) 2006-2010, and GNU GPL'd, by Bart Van Assche. ==7737== Using Valgrind-3.6.0.SVN and LibVEX; rerun with -h for copyright info ==7737== Command: ./a.out 127.0.0.1 31174 8 /tmp ==7737== ==7737== Thread 4: ==7737== Conflicting load by thread 4 at 0x061875f0 size 8 ==7737== at 0x40DB72: boost::asio::detail::op_queue<boost::asio::detail::reactor_op>::front() (in /tmp/a.out) ==7737== by 0x417974: boost::asio::detail::epoll_reactor::run(bool, boost::asio::detail::op_queue<boost::asio::detail::task_io_service_operation<boost::asio::detail::epoll_reactor>
&) (in /tmp/a.out) ==7737== by 0x41C809: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::do_one(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&, boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::idle_thread_info*) (in /tmp/a.out) ==7737== by 0x41A026: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::run(boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x417D26: boost::asio::io_service::run() (in /tmp/a.out) ==7737== by 0x430358: unsigned long boost::_mfi::mf0<unsigned long, boost::asio::io_service>::call<boost::shared_ptr<boost::asio::io_service> (boost::shared_ptr<boost::asio::io_service>&, void const*) const (in /tmp/a.out) ==7737== by 0x42FF74: unsigned long boost::_mfi::mf0<unsigned long, boost::asio::io_service>::operator()<boost::shared_ptr<boost::asio::io_service> (boost::shared_ptr<boost::asio::io_service>&) const (in /tmp/a.out) ==7737== by 0x42FE1E: unsigned long boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service>
::operator()<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list0>(boost::_bi::type<unsigned long>, boost::_mfi::mf0<unsigned long, boost::asio::io_service>&, boost::_bi::list0&, long) (in /tmp/a.out) ==7737== by 0x42FD66: boost::_bi::bind_t<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service>
::operator()() (in /tmp/a.out) ==7737== by 0x42EE79: boost::detail::thread_data<boost::_bi::bind_t<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service>
::run() (in /tmp/a.out) ==7737== by 0x4E41F5F: thread_proxy (in /usr/local/lib/libboost_thread.so.1.43.0) ==7737== by 0x4C2EA60: vgDrd_thread_wrapper (drd_pthread_intercepts.c:272) ==7737== Address 0x61875f0 is at offset 80 from 0x61875a0. Allocation context: ==7737== at 0x4C26FD1: operator new(unsigned long) (vg_replace_malloc.c:261) ==7737== by 0x43BDC8: __gnu_cxx::new_allocator<std::_List_node<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> > ::allocate(unsigned long, void const*) (in /tmp/a.out) ==7737== by 0x43B72D: std::_List_base<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state>, std::allocator<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> > ::_M_get_node() (in /tmp/a.out) ==7737== by 0x43AD64: std::list<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state>, std::allocator<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> > ::_M_create_node(std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> const&) (in /tmp/a.out) ==7737== by 0x43A0FC: std::list<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state>, std::allocator<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> > ::insert(std::_List_iterator<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> >, std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> const&) (in /tmp/a.out) ==7737== by 0x439A77: boost::asio::detail::hash_map<int, boost::asio::detail::epoll_reactor::descriptor_state>::values_insert(std::_List_iterator<std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> >, std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> const&) (in /tmp/a.out) ==7737== by 0x438B60: boost::asio::detail::hash_map<int, boost::asio::detail::epoll_reactor::descriptor_state>::insert(std::pair<int, boost::asio::detail::epoll_reactor::descriptor_state> const&) (in /tmp/a.out) ==7737== by 0x43811B: boost::asio::detail::epoll_reactor::register_descriptor(int, boost::asio::detail::epoll_reactor::descriptor_state*&) (in /tmp/a.out) ==7737== by 0x43DE25: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D954: boost::asio::stream_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D689: boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> ::assign(boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D274: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::accept_op_base<boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> > ::do_perform(boost::asio::detail::reactor_op*) (in /tmp/a.out) ==7737== Other segment start (thread 3) ==7737== at 0x4C2F283: pthread_mutex_lock (drd_pthread_intercepts.c:578) ==7737== by 0x40AC2B: boost::asio::detail::posix_mutex::lock() (in /tmp/a.out) ==7737== by 0x40D4CF: boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>::scoped_lock(boost::asio::detail::posix_mutex&) (in /tmp/a.out) ==7737== by 0x4380D4: boost::asio::detail::epoll_reactor::register_descriptor(int, boost::asio::detail::epoll_reactor::descriptor_state*&) (in /tmp/a.out) ==7737== by 0x43DE25: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D954: boost::asio::stream_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D689: boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> ::assign(boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D274: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::accept_op_base<boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> > ::do_perform(boost::asio::detail::reactor_op*) (in /tmp/a.out) ==7737== by 0x40AF7A: boost::asio::detail::reactor_op::perform() (in /tmp/a.out) ==7737== by 0x41798B: boost::asio::detail::epoll_reactor::run(bool, boost::asio::detail::op_queue<boost::asio::detail::task_io_service_operation<boost::asio::detail::epoll_reactor> &) (in /tmp/a.out) ==7737== by 0x41C809: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::do_one(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&, boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::idle_thread_info*) (in /tmp/a.out) ==7737== by 0x41A026: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::run(boost::system::error_code&) (in /tmp/a.out) ==7737== Other segment end (thread 3) ==7737== at 0x4C2FE7F: pthread_mutex_unlock (drd_pthread_intercepts.c:631) ==7737== by 0x40AC45: boost::asio::detail::posix_mutex::unlock() (in /tmp/a.out) ==7737== by 0x40D500: boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>::~scoped_lock() (in /tmp/a.out) ==7737== by 0x438273: boost::asio::detail::epoll_reactor::register_descriptor(int, boost::asio::detail::epoll_reactor::descriptor_state*&) (in /tmp/a.out) ==7737== by 0x43DE25: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D954: boost::asio::stream_socket_service<boost::asio::ip::tcp>::assign(boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::implementation_type&, boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D689: boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> ::assign(boost::asio::ip::tcp const&, int const&, boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x43D274: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::accept_op_base<boost::asio::basic_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> > ::do_perform(boost::asio::detail::reactor_op*) (in /tmp/a.out) ==7737== by 0x40AF7A: boost::asio::detail::reactor_op::perform() (in /tmp/a.out) ==7737== by 0x41798B: boost::asio::detail::epoll_reactor::run(bool, boost::asio::detail::op_queue<boost::asio::detail::task_io_service_operation<boost::asio::detail::epoll_reactor> &) (in /tmp/a.out) ==7737== by 0x41C809: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::do_one(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&, boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::idle_thread_info*) (in /tmp/a.out) ==7737== by 0x41A026: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::run(boost::system::error_code&) (in /tmp/a.out) ==7737== ==7737== Thread 3: ==7737== Probably a race condition: condition variable 0x8583c40 has been signaled but the associated mutex 0x61820f8 is not locked by the signalling thread. ==7737== at 0x4C283F9: pthread_cond_signal@* (drd_pthread_intercepts.c:736) ==7737== by 0x4119FE: void boost::asio::detail::posix_event::signal_and_unlock<boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex> (boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&) (in /tmp/a.out) ==7737== by 0x4108F2: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::wake_one_idle_thread_and_unlock(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&) (in /tmp/a.out) ==7737== by 0x40F1C2: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::wake_one_thread_and_unlock(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&) (in /tmp/a.out) ==7737== by 0x40DA56: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::init_task() (in /tmp/a.out) ==7737== by 0x40B941: boost::asio::detail::epoll_reactor::init_task() (in /tmp/a.out) ==7737== by 0x4148D8: boost::asio::detail::reactive_socket_service<boost::asio::ip::tcp>::reactive_socket_service(boost::asio::io_service&) (in /tmp/a.out) ==7737== by 0x414035: boost::asio::stream_socket_service<boost::asio::ip::tcp>::stream_socket_service(boost::asio::io_service&) (in /tmp/a.out) ==7737== by 0x413893: boost::asio::io_service::service* boost::asio::detail::service_registry::create<boost::asio::stream_socket_service<boost::asio::ip::tcp> (boost::asio::io_service&) (in /tmp/a.out) ==7737== by 0x40ADB8: boost::asio::detail::service_registry::do_use_service(boost::asio::io_service::service::key const&, boost::asio::io_service::service* (*)(boost::asio::io_service&)) (in /tmp/a.out) ==7737== by 0x412B7E: boost::asio::stream_socket_service<boost::asio::ip::tcp>& boost::asio::detail::service_registry::use_service<boost::asio::stream_socket_service<boost::asio::ip::tcp> () (in /tmp/a.out) ==7737== by 0x411B3A: boost::asio::stream_socket_service<boost::asio::ip::tcp>& boost::asio::use_service<boost::asio::stream_socket_service<boost::asio::ip::tcp> (boost::asio::io_service&) (in /tmp/a.out) ==7737== cond 0x8583c40 was first observed at: ==7737== at 0x4C27C59: pthread_cond_init@* (drd_pthread_intercepts.c:652) ==7737== by 0x417573: boost::asio::detail::posix_event::posix_event() (in /tmp/a.out) ==7737== by 0x419F07: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::idle_thread_info::idle_thread_info() (in /tmp/a.out) ==7737== by 0x419FBC: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::run(boost::system::error_code&) (in /tmp/a.out) ==7737== by 0x417D26: boost::asio::io_service::run() (in /tmp/a.out) ==7737== by 0x430358: unsigned long boost::_mfi::mf0<unsigned long, boost::asio::io_service>::call<boost::shared_ptr<boost::asio::io_service> (boost::shared_ptr<boost::asio::io_service>&, void const*) const (in /tmp/a.out) ==7737== by 0x42FF74: unsigned long boost::_mfi::mf0<unsigned long, boost::asio::io_service>::operator()<boost::shared_ptr<boost::asio::io_service> (boost::shared_ptr<boost::asio::io_service>&) const (in /tmp/a.out) ==7737== by 0x42FE1E: unsigned long boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service> ::operator()<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list0>(boost::_bi::type<unsigned long>, boost::_mfi::mf0<unsigned long, boost::asio::io_service>&, boost::_bi::list0&, long) (in /tmp/a.out) ==7737== by 0x42FD66: boost::_bi::bind_t<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service> ::operator()() (in /tmp/a.out) ==7737== by 0x42EE79: boost::detail::thread_data<boost::_bi::bind_t<unsigned long, boost::_mfi::mf0<unsigned long, boost::asio::io_service>, boost::_bi::list1<boost::_bi::value<boost::shared_ptr<boost::asio::io_service> ::run() (in /tmp/a.out) ==7737== by 0x4E41F5F: thread_proxy (in /usr/local/lib/libboost_thread.so.1.43.0) ==7737== by 0x4C2EA60: vgDrd_thread_wrapper (drd_pthread_intercepts.c:272) ==7737== mutex 0x61820f8 was first observed at: ==7737== at 0x4C2EC6B: pthread_mutex_init (drd_pthread_intercepts.c:537) ==7737== by 0x40AB63: boost::asio::detail::posix_mutex::posix_mutex() (in /tmp/a.out) ==7737== by 0x410B72: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>::task_io_service(boost::asio::io_service&) (in /tmp/a.out) ==7737== by 0x40F679: boost::asio::io_service::service* boost::asio::detail::service_registry::create<boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor> (boost::asio::io_service&) (in /tmp/a.out) ==7737== by 0x40ADB8: boost::asio::detail::service_registry::do_use_service(boost::asio::io_service::service::key const&, boost::asio::io_service::service* (*)(boost::asio::io_service&)) (in /tmp/a.out) ==7737== by 0x40DDDE: boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor>& boost::asio::detail::service_registry::use_service<boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor> () (in /tmp/a.out) ==7737== by 0x417C48: boost::asio::io_service::io_service() (in /tmp/a.out) ==7737== by 0x416921: http::server2::io_service_pool::io_service_pool(unsigned long) (in /tmp/a.out) ==7737== by 0x437816: http::server2::server::server(std::string const&, std::string const&, std::string const&, unsigned long) (in /tmp/a.out) ==7737== by 0x43064D: main (in /tmp/a.out) ==7737== ^C==7737== ==7737== For counts of detected and suppressed errors, rerun with: -v ==7737== ERROR SUMMARY: 3 errors from 2 contexts (suppressed: 225 from 194)
I asked the same question in the valgrind list and I append the reply I got. They seem to suggest that there indeed may be some problems in asio. Will someone who is familiar with boost.asio design comment? I am getting the same warnings in my own program, that I modeled after the example. Response from valgrind list ---------------------------------------- This looks like a race on descriptor_state::op_queue_, so I had a look at the following source code: http://www.boost.org/doc/libs/1_43_0/boost/asio/detail/epoll_reactor.hpp. My comments on this source code are as follows: * The comments at the bottom of class epoll_reactor say that any access of registered_descriptors_ should be protected by registered_descriptors_mutex_. However, the method shutdown_service() modifies the container registered_descriptors_ but doesn't lock registered_descriptors_mutex_. * The method epoll_reactor::register_descriptor() modifies its second argument (descriptor_data) such that it points to the newly created descriptor_state object. All data members of the struct descriptor_state are public, but all accesses must be guarded by a lock on descriptor_state::mutex_. So all callers of register_descriptor() must be checked in order to verify whether or not there are any thread-unsafe accesses of descriptor_state::op_queue_ or descriptor_state::shutdown_. Personally I never recommended such a class design. * While all accesses of the members of struct descriptor_state should be protected by locking descriptor_state::mutex_, no lock is held on this last mutex by register_descriptor() when it sets descriptor_data::shutdown_ nor by shutdown_service() while it modifies descriptor_state::op_queue_ and descriptor_state::shutdown_. The former is easy to fix: move the "descriptor_data->shutdown_ = false" statement to somewhere before the epoll_ctl() system call. Does one of the above scenarios explain the race report you have observed ?