From 2e871382d75071bc581a80d7d603012d1e50d198 Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Sun, 28 Nov 2010 01:47:30 +0000 Subject: [PATCH] add debug configuration to debug shutdown-stall bugs / outstanding async operations --- Jamfile | 3 ++ include/libtorrent/debug.hpp | 64 +++++++++++++++++++++++++ src/broadcast_socket.cpp | 16 +++++++ src/connection_queue.cpp | 13 ++++++ src/http_connection.cpp | 77 ++++++++++++++++++++++++++++++ src/lsd.cpp | 13 ++++++ src/natpmp.cpp | 27 +++++++++++ src/peer_connection.cpp | 21 +++++++++ src/session_impl.cpp | 71 ++++++++++++++++++++++++++++ src/torrent.cpp | 13 ++++++ src/tracker_manager.cpp | 9 ++++ src/udp_socket.cpp | 85 ++++++++++++++++++++++++++++++++++ src/udp_tracker_connection.cpp | 6 +++ src/upnp.cpp | 19 ++++++++ 14 files changed, 437 insertions(+) diff --git a/Jamfile b/Jamfile index 7e5da2f4b..ce6b967d2 100755 --- a/Jamfile +++ b/Jamfile @@ -241,6 +241,9 @@ feature asserts : on off production : composite propagated ; feature.compose production : TORRENT_PRODUCTION_ASSERTS=1 ; feature.compose off : TORRENT_NO_ASSERTS=1 ; +feature asio-debugging : off on : composite propagated link-incompatible ; +feature.compose on : TORRENT_ASIO_DEBUGGING ; + feature pool-allocators : on off : composite propagated link-incompatible ; feature.compose off : TORRENT_DISABLE_POOL_ALLOCATOR ; diff --git a/include/libtorrent/debug.hpp b/include/libtorrent/debug.hpp index e45fe6eaa..edc5f5033 100644 --- a/include/libtorrent/debug.hpp +++ b/include/libtorrent/debug.hpp @@ -33,6 +33,70 @@ POSSIBILITY OF SUCH DAMAGE. #ifndef TORRENT_DEBUG_HPP_INCLUDED #define TORRENT_DEBUG_HPP_INCLUDED +#if defined TORRENT_ASIO_DEBUGGING + +#include "libtorrent/assert.hpp" + +#include +#include + +std::string demangle(char const* name); + +namespace libtorrent +{ + struct async_t + { + async_t() : refs(0) {} + std::string stack; + int refs; + }; + + extern std::map _async_ops; + + inline void add_outstanding_async(char const* name) + { + async_t& a = _async_ops[name]; + if (a.stack.empty()) + { + void* stack[50]; + int size = backtrace(stack, 50); + char** symbols = backtrace_symbols(stack, size); + + for (int i = 1; i < size; ++i) + { + char str[200]; + snprintf(str, sizeof(str), "%d: %s\n", i, demangle(symbols[i]).c_str()); + a.stack += str; + } + + free(symbols); + } + ++a.refs; + } + + inline void complete_async(char const* name) + { + async_t& a = _async_ops[name]; + TORRENT_ASSERT(a.refs > 0); + --a.refs; + } + + inline int log_async() + { + int ret = 0; + for (std::map::iterator i = _async_ops.begin() + , end(_async_ops.end()); i != end; ++i) + { + if (i->second.refs <= 0) continue; + ret += i->second.refs; + printf("%s: (%d)\n%s\n", i->first.c_str(), i->second.refs, i->second.stack.c_str()); + } + return ret; + } +} + +#endif + #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING || defined TORRENT_ERROR_LOGGING #include diff --git a/src/broadcast_socket.cpp b/src/broadcast_socket.cpp index c05dd5260..c71075ddd 100644 --- a/src/broadcast_socket.cpp +++ b/src/broadcast_socket.cpp @@ -39,6 +39,10 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/broadcast_socket.hpp" #include "libtorrent/assert.hpp" +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + #ifndef NDEBUG //#include "libtorrent/socket_io.hpp" #endif @@ -259,6 +263,9 @@ namespace libtorrent if (ec) return; m_sockets.push_back(socket_entry(s)); socket_entry& se = m_sockets.back(); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("broadcast_socket::on_receive"); +#endif s->async_receive_from(asio::buffer(se.buffer, sizeof(se.buffer)) , se.remote, boost::bind(&broadcast_socket::on_receive, this, &se, _1, _2)); } @@ -275,6 +282,9 @@ namespace libtorrent if (ec) return; m_unicast_sockets.push_back(socket_entry(s, mask)); socket_entry& se = m_unicast_sockets.back(); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("broadcast_socket::on_receive"); +#endif s->async_receive_from(asio::buffer(se.buffer, sizeof(se.buffer)) , se.remote, boost::bind(&broadcast_socket::on_receive, this, &se, _1, _2)); } @@ -330,9 +340,15 @@ namespace libtorrent void broadcast_socket::on_receive(socket_entry* s, error_code const& ec , std::size_t bytes_transferred) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("broadcast_socket::on_receive"); +#endif if (ec || bytes_transferred == 0 || !m_on_receive) return; m_on_receive(s->remote, s->buffer, bytes_transferred); if (!s->socket) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("broadcast_socket::on_receive"); +#endif s->socket->async_receive_from(asio::buffer(s->buffer, sizeof(s->buffer)) , s->remote, boost::bind(&broadcast_socket::on_receive, this, s, _1, _2)); } diff --git a/src/connection_queue.cpp b/src/connection_queue.cpp index 02b85429b..f970a8e00 100644 --- a/src/connection_queue.cpp +++ b/src/connection_queue.cpp @@ -37,6 +37,10 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/error_code.hpp" #include "libtorrent/error.hpp" +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + namespace libtorrent { @@ -203,6 +207,9 @@ namespace libtorrent ptime expire = time_now_hires() + i->timeout; if (m_num_connecting == 0) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("connection_queue::on_timeout"); +#endif error_code ec; m_timer.expires_at(expire, ec); m_timer.async_wait(boost::bind(&connection_queue::on_timeout, this, _1)); @@ -253,6 +260,9 @@ namespace libtorrent void connection_queue::on_timeout(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("connection_queue::on_timeout"); +#endif mutex_t::scoped_lock l(m_mutex); INVARIANT_CHECK; @@ -302,6 +312,9 @@ namespace libtorrent if (next_expire < max_time()) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("connection_queue::on_timeout"); +#endif error_code ec; m_timer.expires_at(next_expire, ec); m_timer.async_wait(boost::bind(&connection_queue::on_timeout, this, _1)); diff --git a/src/http_connection.cpp b/src/http_connection.cpp index 16c007752..48a70a7da 100644 --- a/src/http_connection.cpp +++ b/src/http_connection.cpp @@ -38,6 +38,10 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/socket.hpp" #include "libtorrent/connection_queue.hpp" +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + #include #include #include @@ -162,6 +166,9 @@ void http_connection::start(std::string const& hostname, std::string const& port m_timeout = timeout; error_code ec; m_timer.expires_from_now(m_timeout, ec); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_timeout"); +#endif m_timer.async_wait(boost::bind(&http_connection::on_timeout , boost::weak_ptr(shared_from_this()), _1)); m_called = false; @@ -184,6 +191,9 @@ void http_connection::start(std::string const& hostname, std::string const& port if (m_sock.is_open() && m_hostname == hostname && m_port == port && m_ssl == ssl && m_bind_addr == bind_addr) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_write"); +#endif async_write(m_sock, asio::buffer(sendbuffer) , boost::bind(&http_connection::on_write, shared_from_this(), _1)); } @@ -257,6 +267,9 @@ void http_connection::start(std::string const& hostname, std::string const& port #if TORRENT_USE_I2P if (is_i2p) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_i2p_resolve"); +#endif i2p_conn->async_name_lookup(hostname.c_str(), boost::bind(&http_connection::on_i2p_resolve , shared_from_this(), _1, _2)); } @@ -273,6 +286,9 @@ void http_connection::start(std::string const& hostname, std::string const& port } else { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_resolve"); +#endif tcp::resolver::query query(hostname, port); m_resolver.async_resolve(query, boost::bind(&http_connection::on_resolve , shared_from_this(), _1, _2)); @@ -306,6 +322,9 @@ void http_connection::on_connect_timeout() void http_connection::on_timeout(boost::weak_ptr p , error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_timeout"); +#endif boost::shared_ptr c = p.lock(); if (!c) return; @@ -315,6 +334,9 @@ void http_connection::on_timeout(boost::weak_ptr p { if (c->m_connection_ticket > -1 && !c->m_endpoints.empty()) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_timeout"); +#endif error_code ec; c->m_sock.close(ec); c->m_timer.expires_at(c->m_last_receive + c->m_timeout, ec); @@ -329,6 +351,9 @@ void http_connection::on_timeout(boost::weak_ptr p } if (!c->m_sock.is_open()) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_timeout"); +#endif error_code ec; c->m_timer.expires_at(c->m_last_receive + c->m_timeout, ec); c->m_timer.async_wait(boost::bind(&http_connection::on_timeout, p, _1)); @@ -351,6 +376,9 @@ void http_connection::close() void http_connection::on_i2p_resolve(error_code const& e , char const* destination) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_i2p_resolve"); +#endif if (e) { callback(e); @@ -369,6 +397,9 @@ void http_connection::on_i2p_resolve(error_code const& e m_sock.get()->set_destination(destination); m_sock.get()->set_command(i2p_stream::cmd_connect); m_sock.get()->set_session_id(m_i2p_conn->session_id()); +#endif +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_connect"); #endif m_sock.async_connect(tcp::endpoint(), boost::bind(&http_connection::on_connect , shared_from_this(), _1)); @@ -378,6 +409,9 @@ void http_connection::on_i2p_resolve(error_code const& e void http_connection::on_resolve(error_code const& e , tcp::resolver::iterator i) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_resolve"); +#endif if (e) { boost::shared_ptr me(shared_from_this()); @@ -447,12 +481,18 @@ void http_connection::connect(int ticket, tcp::endpoint target_address) m_sock.get()->set_dst_name(m_hostname); } } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_connect"); +#endif m_sock.async_connect(target_address, boost::bind(&http_connection::on_connect , shared_from_this(), _1)); } void http_connection::on_connect(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_connect"); +#endif if (m_connection_ticket >= 0) { m_cc.done(m_connection_ticket); @@ -463,6 +503,9 @@ void http_connection::on_connect(error_code const& e) if (!e) { if (m_connect_handler) m_connect_handler(*this); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_write"); +#endif async_write(m_sock, asio::buffer(sendbuffer) , boost::bind(&http_connection::on_write, shared_from_this(), _1)); } @@ -510,6 +553,9 @@ void http_connection::callback(error_code const& e, char const* data, int size) void http_connection::on_write(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_write"); +#endif if (e) { boost::shared_ptr me(shared_from_this()); @@ -528,10 +574,18 @@ void http_connection::on_write(error_code const& e) if (m_download_quota == 0) { if (!m_limiter_timer_active) + { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_assign_bandwidth"); +#endif on_assign_bandwidth(error_code()); + } return; } } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_read"); +#endif m_sock.async_read_some(asio::buffer(&m_recvbuffer[0] + m_read_pos , amount_to_read) , boost::bind(&http_connection::on_read @@ -541,6 +595,9 @@ void http_connection::on_write(error_code const& e) void http_connection::on_read(error_code const& e , std::size_t bytes_transferred) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_read"); +#endif if (m_rate_limit) { m_download_quota -= bytes_transferred; @@ -680,10 +737,18 @@ void http_connection::on_read(error_code const& e if (m_download_quota == 0) { if (!m_limiter_timer_active) + { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_assign_bandwidth"); +#endif on_assign_bandwidth(error_code()); + } return; } } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_read"); +#endif m_sock.async_read_some(asio::buffer(&m_recvbuffer[0] + m_read_pos , amount_to_read) , boost::bind(&http_connection::on_read @@ -692,6 +757,9 @@ void http_connection::on_read(error_code const& e void http_connection::on_assign_bandwidth(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("http_connection::on_assign_bandwidth"); +#endif if ((e == asio::error::operation_aborted && m_limiter_timer_active) || !m_sock.is_open()) @@ -712,6 +780,9 @@ void http_connection::on_assign_bandwidth(error_code const& e) if (!m_sock.is_open()) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_read"); +#endif m_sock.async_read_some(asio::buffer(&m_recvbuffer[0] + m_read_pos , amount_to_read) , boost::bind(&http_connection::on_read @@ -720,6 +791,9 @@ void http_connection::on_assign_bandwidth(error_code const& e) error_code ec; m_limiter_timer_active = true; m_limiter_timer.expires_from_now(milliseconds(250), ec); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_assign_bandwidth"); +#endif m_limiter_timer.async_wait(boost::bind(&http_connection::on_assign_bandwidth , shared_from_this(), _1)); } @@ -733,6 +807,9 @@ void http_connection::rate_limit(int limit) error_code ec; m_limiter_timer_active = true; m_limiter_timer.expires_from_now(milliseconds(250), ec); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("http_connection::on_assign_bandwidth"); +#endif m_limiter_timer.async_wait(boost::bind(&http_connection::on_assign_bandwidth , shared_from_this(), _1)); } diff --git a/src/lsd.cpp b/src/lsd.cpp index a1de7d255..4b3a53ed7 100644 --- a/src/lsd.cpp +++ b/src/lsd.cpp @@ -40,6 +40,10 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/escape_string.hpp" #include "libtorrent/socket_io.hpp" // for print_address +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + #include #include #if BOOST_VERSION < 103500 @@ -110,6 +114,9 @@ void lsd::announce(sha1_hash const& ih, int listen_port) } #endif +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("lsd::resend_announce"); +#endif m_broadcast_timer.expires_from_now(milliseconds(250 * m_retry_count), ec); m_broadcast_timer.async_wait(boost::bind(&lsd::resend_announce, self(), _1 , std::string(msg))); @@ -117,6 +124,9 @@ void lsd::announce(sha1_hash const& ih, int listen_port) void lsd::resend_announce(error_code const& e, std::string msg) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("lsd::resend_announce"); +#endif if (e) return; error_code ec; @@ -126,6 +136,9 @@ void lsd::resend_announce(error_code const& e, std::string msg) if (m_retry_count >= 5) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("lsd::resend_announce"); +#endif m_broadcast_timer.expires_from_now(milliseconds(250 * m_retry_count), ec); m_broadcast_timer.async_wait(boost::bind(&lsd::resend_announce, self(), _1, msg)); } diff --git a/src/natpmp.cpp b/src/natpmp.cpp index 8215f8963..9c1b45b0b 100644 --- a/src/natpmp.cpp +++ b/src/natpmp.cpp @@ -54,6 +54,10 @@ POSSIBILITY OF SUCH DAMAGE. #include #endif +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + using namespace libtorrent; natpmp::natpmp(io_service& ios, address const& listen_interface @@ -111,6 +115,9 @@ void natpmp::rebind(address const& listen_interface) return; } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("natpmp::on_reply"); +#endif m_socket.async_receive_from(asio::buffer(&m_response_buffer, 16) , m_remote, boost::bind(&natpmp::on_reply, self(), _1, _2)); @@ -344,6 +351,9 @@ void natpmp::send_map_request(int i, mutex::scoped_lock& l) } else { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("natpmp::resend_request"); +#endif // linear back-off instead of exponential ++m_retry_count; m_send_timer.expires_from_now(milliseconds(250 * m_retry_count), ec); @@ -353,6 +363,9 @@ void natpmp::send_map_request(int i, mutex::scoped_lock& l) void natpmp::resend_request(int i, error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("natpmp::resend_request"); +#endif if (e) return; mutex::scoped_lock l(m_mutex); if (m_currently_mapping != i) return; @@ -376,6 +389,10 @@ void natpmp::on_reply(error_code const& e { mutex::scoped_lock l(m_mutex); +#if defined TORRENT_ASIO_DEBUGGING + complete_async("natpmp::on_reply"); +#endif + using namespace libtorrent::detail; if (e) { @@ -385,6 +402,9 @@ void natpmp::on_reply(error_code const& e return; } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("natpmp::on_reply"); +#endif m_socket.async_receive_from(asio::buffer(&m_response_buffer, 16) , m_remote, boost::bind(&natpmp::on_reply, self(), _1, _2)); @@ -560,6 +580,10 @@ void natpmp::update_expiration_timer(mutex::scoped_lock& l) #endif error_code ec; if (m_next_refresh >= 0) m_refresh_timer.cancel(ec); + +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("natpmp::mapping_expired"); +#endif m_refresh_timer.expires_from_now(min_expire - now, ec); m_refresh_timer.async_wait(boost::bind(&natpmp::mapping_expired, self(), _1, min_index)); m_next_refresh = min_index; @@ -568,6 +592,9 @@ void natpmp::update_expiration_timer(mutex::scoped_lock& l) void natpmp::mapping_expired(error_code const& e, int i) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("natpmp::mapping_expired"); +#endif if (e) return; mutex::scoped_lock l(m_mutex); char msg[200]; diff --git a/src/peer_connection.cpp b/src/peer_connection.cpp index 3477a3787..34a92268a 100644 --- a/src/peer_connection.cpp +++ b/src/peer_connection.cpp @@ -4436,6 +4436,9 @@ namespace libtorrent peer_log("==> ASYNC_WRITE [ bytes: %d ]", amount_to_send); #endif std::list const& vec = m_send_buffer.build_iovec(amount_to_send); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("peer_connection::on_send_data"); +#endif m_socket->async_write_some( vec, make_write_handler(boost::bind( &peer_connection::on_send_data, self(), _1, _2))); @@ -4503,6 +4506,9 @@ namespace libtorrent if (ec != asio::error::would_block) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("peer_connection::on_receive_data"); +#endif ++m_read_recurse; m_channel_state[download_channel] = peer_info::bw_network; on_receive_data(ec, bytes_transferred); @@ -4592,6 +4598,9 @@ namespace libtorrent peer_log("<== ASYNC_READ [ max: %d bytes ]", max_receive); #endif +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("peer_connection::on_receive_data"); +#endif if (num_bufs == 1) { m_socket->async_read_some( @@ -4776,6 +4785,9 @@ namespace libtorrent TORRENT_ASSERT(m_ses.is_network_thread()); INVARIANT_CHECK; +#if defined TORRENT_ASIO_DEBUGGING + complete_async("peer_connection::on_receive_data"); +#endif // keep ourselves alive in until this function exits in // case we disconnect boost::intrusive_ptr me(self()); @@ -4993,6 +5005,9 @@ namespace libtorrent #endif #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING (*m_logger) << time_now_string() << " ASYNC_CONNECT: " << print_endpoint(m_remote) << "\n"; +#endif +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("peer_connection::on_connection_complete"); #endif m_socket->async_connect(m_remote , boost::bind(&peer_connection::on_connection_complete, self(), _1)); @@ -5008,6 +5023,9 @@ namespace libtorrent void peer_connection::on_connection_complete(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("peer_connection::on_connection_complete"); +#endif ptime completed = time_now(); TORRENT_ASSERT(m_ses.is_network_thread()); @@ -5094,6 +5112,9 @@ namespace libtorrent INVARIANT_CHECK; +#if defined TORRENT_ASIO_DEBUGGING + complete_async("peer_connection::on_send_data"); +#endif // keep ourselves alive in until this function exits in // case we disconnect boost::intrusive_ptr me(self()); diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 4a86d8d39..5f337c815 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -170,6 +170,10 @@ namespace boost { namespace libtorrent { +#if defined TORRENT_ASIO_DEBUGGING + std::map _async_ops; +#endif + namespace detail { @@ -803,9 +807,15 @@ namespace aux { // is called from within the network thread as opposed to the // constructor which is called from the main thread +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_tick"); +#endif error_code ec; m_io_service.post(boost::bind(&session_impl::on_tick, this, ec)); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_lsd_announce"); +#endif int delay = (std::max)(m_settings.local_service_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); m_lsd_announce_timer.expires_from_now(seconds(delay), ec); @@ -814,6 +824,10 @@ namespace aux { TORRENT_ASSERT(!ec); #ifndef TORRENT_DISABLE_DHT + +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_dht_announce"); +#endif delay = (std::max)(m_settings.dht_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); m_dht_announce_timer.expires_from_now(seconds(delay), ec); @@ -1337,6 +1351,9 @@ namespace aux { #ifndef TORRENT_DISABLE_DHT if (m_settings.dht_announce_interval != s.dht_announce_interval) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_dht_announce"); +#endif error_code ec; int delay = (std::max)(s.dht_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); @@ -1348,6 +1365,9 @@ namespace aux { if (m_settings.local_service_announce_interval != s.local_service_announce_interval) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_lsd_announce"); +#endif error_code ec; int delay = (std::max)(s.local_service_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); @@ -1682,6 +1702,9 @@ namespace aux { , *m_socks_listen_socket); TORRENT_ASSERT_VAL(ret, ret); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_socks_accept"); +#endif socks5_stream& s = *m_socks_listen_socket->get(); s.set_command(2); // 2 means BIND (as opposed to CONNECT) m_socks_listen_port = m_listen_interface.port(); @@ -1707,6 +1730,9 @@ namespace aux { , *m_i2p_listen_socket); TORRENT_ASSERT_VAL(ret, ret); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_i2p_accept"); +#endif i2p_stream& s = *m_i2p_listen_socket->get(); s.set_command(i2p_stream::cmd_accept); s.set_session_id(m_i2p_conn.session_id()); @@ -1717,6 +1743,9 @@ namespace aux { void session_impl::on_i2p_accept(boost::shared_ptr const& s , error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_i2p_accept"); +#endif m_i2p_listen_socket.reset(); if (e == asio::error::operation_aborted) return; if (e) @@ -1787,6 +1816,9 @@ namespace aux { { shared_ptr c(new socket_type(m_io_service)); c->instantiate(m_io_service); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_accept_connection"); +#endif listener->async_accept(*c->get() , boost::bind(&session_impl::on_accept_connection, this, c , boost::weak_ptr(listener), _1)); @@ -1795,6 +1827,9 @@ namespace aux { void session_impl::on_accept_connection(shared_ptr const& s , weak_ptr listen_socket, error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_accept_connection"); +#endif TORRENT_ASSERT(is_network_thread()); boost::shared_ptr listener = listen_socket.lock(); if (!listener) return; @@ -1985,6 +2020,9 @@ namespace aux { void session_impl::on_socks_accept(boost::shared_ptr const& s , error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_socks_accept"); +#endif m_socks_listen_socket.reset(); if (e == asio::error::operation_aborted) return; if (e) @@ -2107,6 +2145,9 @@ namespace aux { void session_impl::on_tick(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_tick"); +#endif TORRENT_ASSERT(is_network_thread()); ptime now = time_now_hires(); @@ -2130,6 +2171,9 @@ namespace aux { return; } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_tick"); +#endif error_code ec; m_timer.expires_at(now + milliseconds(m_settings.tick_interval), ec); m_timer.async_wait(bind(&session_impl::on_tick, this, _1)); @@ -2602,11 +2646,17 @@ namespace aux { void session_impl::on_dht_announce(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_dht_announce"); +#endif TORRENT_ASSERT(is_network_thread()); if (e) return; if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_dht_announce"); +#endif // announce to DHT every 15 minutes int delay = (std::max)(m_settings.dht_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); @@ -2628,11 +2678,17 @@ namespace aux { void session_impl::on_lsd_announce(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_lsd_announce"); +#endif TORRENT_ASSERT(is_network_thread()); if (e) return; if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_lsd_announce"); +#endif // announce on local network every 5 minutes int delay = (std::max)(m_settings.local_service_announce_interval / (std::max)(int(m_torrents.size()), 1), 1); @@ -3738,6 +3794,9 @@ namespace aux { void session_impl::add_dht_router(std::pair const& node) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("session_impl::on_dht_router_name_lookup"); +#endif char port[7]; snprintf(port, sizeof(port), "%d", node.second); tcp::resolver::query q(node.first, port); @@ -3748,6 +3807,9 @@ namespace aux { void session_impl::on_dht_router_name_lookup(error_code const& e , tcp::resolver::iterator host) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("session_impl::on_dht_router_name_lookup"); +#endif // TODO: report errors as alerts if (e) return; while (host != tcp::resolver::iterator()) @@ -3797,6 +3859,15 @@ namespace aux { #if defined(TORRENT_VERBOSE_LOGGING) || defined(TORRENT_LOGGING) (*m_logger) << time_now_string() << " waiting for main thread\n"; +#endif +#if defined TORRENT_ASIO_DEBUGGING + int counter = 0; + while (log_async()) + { + sleep(1000); + ++counter; + printf("\n==== Waiting to shut down: %d ==== \n\n", counter); + } #endif m_thread->join(); diff --git a/src/torrent.cpp b/src/torrent.cpp index 4c7dfcc92..9c930e8f1 100644 --- a/src/torrent.cpp +++ b/src/torrent.cpp @@ -1353,6 +1353,9 @@ namespace libtorrent void torrent::on_tracker_announce_disp(boost::weak_ptr p , error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("tracker::on_tracker_announce_disp"); +#endif if (e) return; boost::shared_ptr t = p.lock(); if (!t) return; @@ -1756,6 +1759,9 @@ namespace libtorrent else #endif { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("torrent::on_peer_name_lookup"); +#endif tcp::resolver::query q(i->ip, to_string(i->port).elems); m_ses.m_host_resolver.async_resolve(q, boost::bind(&torrent::on_peer_name_lookup, shared_from_this(), _1, _2, i->pid)); @@ -1863,6 +1869,10 @@ namespace libtorrent INVARIANT_CHECK; +#if defined TORRENT_ASIO_DEBUGGING + complete_async("torrent::on_peer_name_lookup"); +#endif + #if defined TORRENT_LOGGING if (e) *m_ses.m_logger << time_now_string() << " on_peer_name_lookup: " << e.message() << "\n"; @@ -5803,6 +5813,9 @@ namespace libtorrent // always do it // if (m_tracker_timer.expires_at() <= next_announce) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("tracker::on_tracker_announce_disp"); +#endif m_tracker_timer.expires_at(next_announce, ec); m_tracker_timer.async_wait(boost::bind(&torrent::on_tracker_announce_disp, self, _1)); } diff --git a/src/tracker_manager.cpp b/src/tracker_manager.cpp index 668fdcda3..57ec24d21 100644 --- a/src/tracker_manager.cpp +++ b/src/tracker_manager.cpp @@ -85,6 +85,9 @@ namespace libtorrent : (std::min)(m_completion_timeout, timeout); } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("timeout_handler::timeout_callback"); +#endif error_code ec; m_timeout.expires_at(m_read_time + seconds(timeout), ec); m_timeout.async_wait(boost::bind( @@ -106,6 +109,9 @@ namespace libtorrent void timeout_handler::timeout_callback(error_code const& error) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("timeout_handler::timeout_callback"); +#endif if (m_abort) return; ptime now = time_now_hires(); @@ -130,6 +136,9 @@ namespace libtorrent ? m_completion_timeout - total_seconds(m_read_time - m_start_time) : (std::min)(m_completion_timeout - total_seconds(m_read_time - m_start_time), timeout); } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("timeout_handler::timeout_callback"); +#endif error_code ec; m_timeout.expires_at(m_read_time + seconds(timeout), ec); m_timeout.async_wait( diff --git a/src/udp_socket.cpp b/src/udp_socket.cpp index 9f84ba746..ed41f3aae 100644 --- a/src/udp_socket.cpp +++ b/src/udp_socket.cpp @@ -46,6 +46,10 @@ POSSIBILITY OF SUCH DAMAGE. #include #endif +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + using namespace libtorrent; udp_socket::udp_socket(asio::io_service& ios @@ -166,6 +170,9 @@ void udp_socket::send(udp::endpoint const& ep, char const* p, int len, error_cod void udp_socket::on_read(udp::socket* s, error_code const& e, std::size_t bytes_transferred) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_read"); +#endif TORRENT_ASSERT(m_magic == 0x1337); TORRENT_ASSERT(is_single_thread()); @@ -223,6 +230,9 @@ void udp_socket::on_read(udp::socket* s, error_code const& e, std::size_t bytes_ if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif #if TORRENT_USE_IPV6 if (s == &m_ipv4_sock) #endif @@ -267,6 +277,9 @@ void udp_socket::on_read(udp::socket* s, error_code const& e, std::size_t bytes_ if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif s->async_receive_from(asio::buffer(m_v4_buf, sizeof(m_v4_buf)) , m_v4_ep, boost::bind(&udp_socket::on_read, this, s, _1, _2)); } @@ -294,6 +307,9 @@ void udp_socket::on_read(udp::socket* s, error_code const& e, std::size_t bytes_ if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif s->async_receive_from(asio::buffer(m_v6_buf, sizeof(m_v6_buf)) , m_v6_ep, boost::bind(&udp_socket::on_read, this, s, _1, _2)); } @@ -464,6 +480,9 @@ void udp_socket::bind(udp::endpoint const& ep, error_code& ec) if (ec) return; m_ipv4_sock.bind(ep, ec); if (ec) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif m_ipv4_sock.async_receive_from(asio::buffer(m_v4_buf, sizeof(m_v4_buf)) , m_v4_ep, boost::bind(&udp_socket::on_read, this, &m_ipv4_sock, _1, _2)); ++m_outstanding; @@ -475,6 +494,9 @@ void udp_socket::bind(udp::endpoint const& ep, error_code& ec) if (ec) return; m_ipv6_sock.bind(ep, ec); if (ec) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif m_ipv6_sock.async_receive_from(asio::buffer(m_v6_buf, sizeof(m_v6_buf)) , m_v6_ep, boost::bind(&udp_socket::on_read, this, &m_ipv6_sock, _1, _2)); ++m_outstanding; @@ -504,6 +526,9 @@ void udp_socket::bind(int port) m_ipv4_sock.open(udp::v4(), ec); if (!ec) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif m_ipv4_sock.bind(udp::endpoint(address_v4::any(), port), ec); m_ipv4_sock.async_receive_from(asio::buffer(m_v4_buf, sizeof(m_v4_buf)) , m_v4_ep, boost::bind(&udp_socket::on_read, this, &m_ipv4_sock, _1, _2)); @@ -516,6 +541,9 @@ void udp_socket::bind(int port) m_ipv6_sock.open(udp::v6(), ec); if (!ec) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_read"); +#endif m_ipv6_sock.set_option(v6only(true), ec); m_ipv6_sock.bind(udp::endpoint(address_v6::any(), port), ec); m_ipv6_sock.async_receive_from(asio::buffer(m_v6_buf, sizeof(m_v6_buf)) @@ -584,6 +612,9 @@ void udp_socket::on_connect(int ticket) if (m_abort) return; +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_connected"); +#endif m_connection_ticket = ticket; error_code ec; m_socks5_sock.open(m_proxy_addr.address().is_v4()?tcp::v4():tcp::v6(), ec); @@ -593,6 +624,9 @@ void udp_socket::on_connect(int ticket) void udp_socket::on_connected(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_connected"); +#endif CHECK_MAGIC; TORRENT_ASSERT(is_single_thread()); @@ -618,23 +652,35 @@ void udp_socket::on_connected(error_code const& e) write_uint8(2, p); // username/password } TORRENT_ASSERT_VAL(p - m_tmp_buf < sizeof(m_tmp_buf), (p - m_tmp_buf)); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_handshake1"); +#endif asio::async_write(m_socks5_sock, asio::buffer(m_tmp_buf, p - m_tmp_buf) , boost::bind(&udp_socket::handshake1, this, _1)); } void udp_socket::handshake1(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_handshake1"); +#endif CHECK_MAGIC; if (e) return; TORRENT_ASSERT(is_single_thread()); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_handshake2"); +#endif asio::async_read(m_socks5_sock, asio::buffer(m_tmp_buf, 2) , boost::bind(&udp_socket::handshake2, this, _1)); } void udp_socket::handshake2(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_handshake2"); +#endif CHECK_MAGIC; if (e) return; @@ -669,6 +715,9 @@ void udp_socket::handshake2(error_code const& e) write_uint8(m_proxy_settings.password.size(), p); write_string(m_proxy_settings.password, p); TORRENT_ASSERT_VAL(p - m_tmp_buf < sizeof(m_tmp_buf), (p - m_tmp_buf)); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_handshake3"); +#endif asio::async_write(m_socks5_sock, asio::buffer(m_tmp_buf, p - m_tmp_buf) , boost::bind(&udp_socket::handshake3, this, _1)); } @@ -682,17 +731,26 @@ void udp_socket::handshake2(error_code const& e) void udp_socket::handshake3(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_handshake3"); +#endif CHECK_MAGIC; if (e) return; TORRENT_ASSERT(is_single_thread()); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::on_handshake4"); +#endif asio::async_read(m_socks5_sock, asio::buffer(m_tmp_buf, 2) , boost::bind(&udp_socket::handshake4, this, _1)); } void udp_socket::handshake4(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::on_handshake4"); +#endif CHECK_MAGIC; if (e) return; @@ -735,23 +793,35 @@ void udp_socket::socks_forward_udp() #endif detail::write_uint16(port , p); TORRENT_ASSERT_VAL(p - m_tmp_buf < sizeof(m_tmp_buf), (p - m_tmp_buf)); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::connect1"); +#endif asio::async_write(m_socks5_sock, asio::buffer(m_tmp_buf, p - m_tmp_buf) , boost::bind(&udp_socket::connect1, this, _1)); } void udp_socket::connect1(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::connect1"); +#endif CHECK_MAGIC; if (e) return; TORRENT_ASSERT(is_single_thread()); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::connect2"); +#endif asio::async_read(m_socks5_sock, asio::buffer(m_tmp_buf, 10) , boost::bind(&udp_socket::connect2, this, _1)); } void udp_socket::connect2(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::connect2"); +#endif CHECK_MAGIC; if (e) return; @@ -799,12 +869,18 @@ void udp_socket::connect2(error_code const& e) m_queue.pop_front(); } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_socket::hung_up"); +#endif asio::async_read(m_socks5_sock, asio::buffer(m_tmp_buf, 10) , boost::bind(&udp_socket::hung_up, this, _1)); } void udp_socket::hung_up(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_socket::hung_up"); +#endif CHECK_MAGIC; TORRENT_ASSERT(is_single_thread()); @@ -825,6 +901,9 @@ rate_limited_udp_socket::rate_limited_udp_socket(io_service& ios , m_quota(4000) , m_last_tick(time_now()) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("rate_limited_udp_socket::on_tick"); +#endif error_code ec; m_timer.expires_from_now(seconds(1), ec); m_timer.async_wait(boost::bind(&rate_limited_udp_socket::on_tick, this, _1)); @@ -852,10 +931,16 @@ bool rate_limited_udp_socket::send(udp::endpoint const& ep, char const* p, int l void rate_limited_udp_socket::on_tick(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("rate_limited_udp_socket::on_tick"); +#endif if (e) return; if (is_closed()) return; error_code ec; ptime now = time_now_hires(); +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("rate_limited_udp_socket::on_tick"); +#endif m_timer.expires_at(now + seconds(1), ec); m_timer.async_wait(boost::bind(&rate_limited_udp_socket::on_tick, this, _1)); diff --git a/src/udp_tracker_connection.cpp b/src/udp_tracker_connection.cpp index a25f9381f..fafc0f7e7 100644 --- a/src/udp_tracker_connection.cpp +++ b/src/udp_tracker_connection.cpp @@ -110,6 +110,9 @@ namespace libtorrent } else { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("udp_tracker_connection::name_lookup"); +#endif tcp::resolver::query q(hostname, to_string(port).elems); m_ses.m_host_resolver.async_resolve(q , boost::bind( @@ -129,6 +132,9 @@ namespace libtorrent void udp_tracker_connection::name_lookup(error_code const& error , tcp::resolver::iterator i) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("udp_tracker_connection::name_lookup"); +#endif if (m_abort) return; if (error == asio::error::operation_aborted) return; if (error || i == tcp::resolver::iterator()) diff --git a/src/upnp.cpp b/src/upnp.cpp index 65bf1b13e..ab94e330d 100644 --- a/src/upnp.cpp +++ b/src/upnp.cpp @@ -42,6 +42,10 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/enum_net.hpp" #include "libtorrent/escape_string.hpp" +#if defined TORRENT_ASIO_DEBUGGING +#include "libtorrent/debug.hpp" +#endif + #include #include #if BOOST_VERSION < 103500 @@ -144,6 +148,9 @@ void upnp::discover_device_impl(mutex::scoped_lock& l) return; } +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("upnp::resend_request"); +#endif ++m_retry_count; m_broadcast_timer.expires_from_now(seconds(2 * m_retry_count), ec); m_broadcast_timer.async_wait(boost::bind(&upnp::resend_request @@ -244,6 +251,9 @@ bool upnp::get_mapping(int index, int& local_port, int& external_port, int& prot void upnp::resend_request(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("upnp::resend_request"); +#endif if (e) return; boost::intrusive_ptr me(self()); @@ -1188,6 +1198,9 @@ void upnp::on_upnp_map_response(error_code const& e if (next_expire < time_now() || next_expire > m.expires) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("upnp::on_expire"); +#endif error_code ec; m_refresh_timer.expires_at(m.expires, ec); m_refresh_timer.async_wait(boost::bind(&upnp::on_expire, self(), _1)); @@ -1268,6 +1281,9 @@ void upnp::on_upnp_unmap_response(error_code const& e void upnp::on_expire(error_code const& e) { +#if defined TORRENT_ASIO_DEBUGGING + complete_async("upnp::on_expire"); +#endif if (e) return; ptime now = time_now(); @@ -1298,6 +1314,9 @@ void upnp::on_expire(error_code const& e) } if (next_expire != max_time()) { +#if defined TORRENT_ASIO_DEBUGGING + add_outstanding_async("upnp::on_expire"); +#endif error_code ec; m_refresh_timer.expires_at(next_expire, ec); m_refresh_timer.async_wait(boost::bind(&upnp::on_expire, self(), _1));