diff --git a/examples/client_test.cpp b/examples/client_test.cpp index faf74945a..a0f5ad929 100644 --- a/examples/client_test.cpp +++ b/examples/client_test.cpp @@ -1324,6 +1324,7 @@ int main(int argc, char* argv[]) + alert::session_log_notification + alert::torrent_log_notification + alert::peer_log_notification + + alert::dht_log_notification )); ses.set_load_function(&load_torrent); diff --git a/include/libtorrent/alert.hpp b/include/libtorrent/alert.hpp index 811787410..d0374ede5 100644 --- a/include/libtorrent/alert.hpp +++ b/include/libtorrent/alert.hpp @@ -189,6 +189,9 @@ namespace libtorrent { // enables the incoming_request_alert. incoming_request_notification = 0x10000, + // enables dht_log_alert, debug logging for the DHT + dht_log_notification = 0x20000, + // The full bitmask, representing all available categories. // // since the enum is signed, make sure this isn't diff --git a/include/libtorrent/alert_types.hpp b/include/libtorrent/alert_types.hpp index 369278c48..30892ab6f 100644 --- a/include/libtorrent/alert_types.hpp +++ b/include/libtorrent/alert_types.hpp @@ -2315,12 +2315,42 @@ namespace libtorrent peer_request req; }; + struct TORRENT_EXPORT dht_log_alert : alert + { + enum dht_module_t + { + tracker, + node, + routing_table, + rpc_manager, + traversal + }; + + dht_log_alert(aux::stack_allocator& alloc + , dht_module_t m, char const* msg); + + static const int static_category = alert::dht_log_notification; + TORRENT_DEFINE_ALERT(dht_log_alert, 85) + + virtual std::string message() const; + + // the log message + char const* log_message() const; + + // the module, or part, of the DHT that produced this log message. + dht_module_t module; + + private: + aux::stack_allocator& m_alloc; + int m_msg_idx; + }; + #undef TORRENT_DEFINE_ALERT_IMPL #undef TORRENT_DEFINE_ALERT #undef TORRENT_DEFINE_ALERT_PRIO #undef TORRENT_CLONE - enum { num_alert_types = 85 }; + enum { num_alert_types = 86 }; } diff --git a/include/libtorrent/aux_/session_impl.hpp b/include/libtorrent/aux_/session_impl.hpp index d1e4b72a8..cdf1aead7 100644 --- a/include/libtorrent/aux_/session_impl.hpp +++ b/include/libtorrent/aux_/session_impl.hpp @@ -575,6 +575,7 @@ namespace libtorrent virtual void announce(sha1_hash const& ih, address const& addr, int port) TORRENT_OVERRIDE; virtual void outgoing_get_peers(sha1_hash const& target , sha1_hash const& sent_target, udp::endpoint const& ep) TORRENT_OVERRIDE; + virtual void log(libtorrent::dht::dht_logger::dht_module_t m, char const* fmt, ...) TORRENT_OVERRIDE; void set_external_address(address const& ip , int source_type, address const& source); diff --git a/include/libtorrent/kademlia/dht_observer.hpp b/include/libtorrent/kademlia/dht_observer.hpp index 953859a5c..876f00403 100644 --- a/include/libtorrent/kademlia/dht_observer.hpp +++ b/include/libtorrent/kademlia/dht_observer.hpp @@ -38,7 +38,29 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { namespace dht { - struct dht_observer + struct dht_logger + { + enum dht_module_t + { + tracker, + node, + routing_table, + rpc_manager, + traversal + }; + + // TODO: 3 instead of these format attributes, make a macro for it + virtual void log(dht_module_t m, char const* fmt, ...) +#if defined __GNUC__ || defined __clang__ + __attribute__((format(printf, 3, 4))) +#endif + = 0; + + protected: + ~dht_logger() {} + }; + + struct dht_observer : dht_logger { virtual void set_external_address(address const& addr , address const& source) = 0; @@ -47,6 +69,7 @@ namespace libtorrent { namespace dht virtual void outgoing_get_peers(sha1_hash const& target , sha1_hash const& sent_target, udp::endpoint const& ep) = 0; virtual void announce(sha1_hash const& ih, address const& addr, int port) = 0; + protected: ~dht_observer() {} }; diff --git a/include/libtorrent/kademlia/dht_tracker.hpp b/include/libtorrent/kademlia/dht_tracker.hpp index a195825ee..42d82f062 100644 --- a/include/libtorrent/kademlia/dht_tracker.hpp +++ b/include/libtorrent/kademlia/dht_tracker.hpp @@ -64,11 +64,6 @@ namespace libtorrent namespace libtorrent { namespace dht { - -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_DECLARE_LOG(dht_tracker); -#endif - struct dht_tracker; struct dht_tracker @@ -146,6 +141,7 @@ namespace libtorrent { namespace dht counters& m_counters; node m_dht; rate_limited_udp_socket& m_sock; + dht_logger* m_log; std::vector m_send_buf; dos_blocker m_blocker; diff --git a/include/libtorrent/kademlia/dos_blocker.hpp b/include/libtorrent/kademlia/dos_blocker.hpp index 811cb5200..a65244c52 100644 --- a/include/libtorrent/kademlia/dos_blocker.hpp +++ b/include/libtorrent/kademlia/dos_blocker.hpp @@ -41,6 +41,8 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { namespace dht { + struct dht_logger; + // this is a class that maintains a list of abusive DHT nodes, // blocking their access to our DHT node. struct TORRENT_EXTRA_EXPORT dos_blocker @@ -50,7 +52,7 @@ namespace libtorrent { namespace dht // called every time we receive an incoming packet. Returns // true if we should let the packet through, and false if // it's blocked - bool incoming(address addr, time_point now); + bool incoming(address addr, time_point now, dht_logger* logger); void set_rate_limit(int l) { diff --git a/include/libtorrent/kademlia/logging.hpp b/include/libtorrent/kademlia/logging.hpp index 45206add6..1c1e602a4 100644 --- a/include/libtorrent/kademlia/logging.hpp +++ b/include/libtorrent/kademlia/logging.hpp @@ -30,6 +30,7 @@ POSSIBILITY OF SUCH DAMAGE. */ +/* #ifndef TORRENT_LOGGING_HPP #define TORRENT_LOGGING_HPP @@ -138,3 +139,6 @@ public: #endif +*/ + + diff --git a/include/libtorrent/kademlia/node.hpp b/include/libtorrent/kademlia/node.hpp index 80a80d8ab..e10295f8c 100644 --- a/include/libtorrent/kademlia/node.hpp +++ b/include/libtorrent/kademlia/node.hpp @@ -67,10 +67,6 @@ namespace libtorrent { namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DECLARE_LOG(node); -#endif - struct traversal_algorithm; struct dht_observer; diff --git a/include/libtorrent/kademlia/observer.hpp b/include/libtorrent/kademlia/observer.hpp index ef711fd3b..dca765871 100644 --- a/include/libtorrent/kademlia/observer.hpp +++ b/include/libtorrent/kademlia/observer.hpp @@ -130,6 +130,7 @@ struct observer : boost::noncopyable }; #ifndef TORRENT_DHT_VERBOSE_LOGGING + // TODO: 2 make this private and unconditional protected: #endif diff --git a/include/libtorrent/kademlia/routing_table.hpp b/include/libtorrent/kademlia/routing_table.hpp index d09c0e9eb..1b7d29436 100644 --- a/include/libtorrent/kademlia/routing_table.hpp +++ b/include/libtorrent/kademlia/routing_table.hpp @@ -64,12 +64,8 @@ namespace libtorrent namespace libtorrent { namespace dht { +struct dht_logger; -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DECLARE_LOG(table); -#endif - - typedef std::vector bucket_t; struct routing_table_node @@ -94,7 +90,8 @@ public: typedef std::vector table_t; routing_table(node_id const& id, int bucket_size - , dht_settings const& settings); + , dht_settings const& settings + , dht_logger* log); #ifndef TORRENT_NO_DEPRECATE void status(session_status& s) const; @@ -193,6 +190,8 @@ public: private: + dht_logger* m_log; + table_t::iterator find_bucket(node_id const& id); void split_bucket(); diff --git a/include/libtorrent/kademlia/rpc_manager.hpp b/include/libtorrent/kademlia/rpc_manager.hpp index 895b19976..d74d2bd21 100644 --- a/include/libtorrent/kademlia/rpc_manager.hpp +++ b/include/libtorrent/kademlia/rpc_manager.hpp @@ -65,10 +65,7 @@ namespace libtorrent { struct dht_settings; } namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DECLARE_LOG(rpc); -#endif - +struct dht_logger; struct udp_socket_interface; struct null_observer : public observer @@ -85,7 +82,9 @@ class TORRENT_EXTRA_EXPORT rpc_manager public: rpc_manager(node_id const& our_id - , routing_table& table, udp_socket_interface* sock); + , routing_table& table + , udp_socket_interface* sock + , dht_logger* log); ~rpc_manager(); void unreachable(udp::endpoint const& ep); @@ -126,6 +125,7 @@ private: transactions_t m_transactions; udp_socket_interface* m_sock; + dht_logger* m_log; routing_table& m_table; time_point m_timer; node_id m_our_id; diff --git a/include/libtorrent/kademlia/traversal_algorithm.hpp b/include/libtorrent/kademlia/traversal_algorithm.hpp index 751a84827..78e64d545 100644 --- a/include/libtorrent/kademlia/traversal_algorithm.hpp +++ b/include/libtorrent/kademlia/traversal_algorithm.hpp @@ -50,9 +50,6 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { struct dht_lookup; } namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DECLARE_LOG(traversal); -#endif class rpc_manager; class node; diff --git a/src/alert.cpp b/src/alert.cpp index 52a4c56d6..284c5266c 100644 --- a/src/alert.cpp +++ b/src/alert.cpp @@ -1710,5 +1710,34 @@ namespace libtorrent { return msg; } + dht_log_alert::dht_log_alert(aux::stack_allocator& alloc + , dht_log_alert::dht_module_t m, const char* msg) + : module(m) + , m_alloc(alloc) + , m_msg_idx(alloc.copy_string(msg)) + {} + + char const* dht_log_alert::log_message() const + { + return m_alloc.ptr(m_msg_idx); + } + + std::string dht_log_alert::message() const + { + const static char const* dht_modules[] = + { + "tracker", + "node", + "routing_table", + "rpc_manager", + "traversal" + }; + + char ret[900]; + snprintf(ret, sizeof(ret), "%s: %s", dht_modules[module] + , log_message()); + return ret; + } + } // namespace libtorrent diff --git a/src/kademlia/dht_tracker.cpp b/src/kademlia/dht_tracker.cpp index 998f1520a..93d53a19c 100644 --- a/src/kademlia/dht_tracker.cpp +++ b/src/kademlia/dht_tracker.cpp @@ -33,6 +33,7 @@ POSSIBILITY OF SUCH DAMAGE. #include #include #include +#include #include #include "libtorrent/kademlia/node.hpp" @@ -40,6 +41,7 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/kademlia/traversal_algorithm.hpp" #include "libtorrent/kademlia/dht_tracker.hpp" #include "libtorrent/kademlia/msg.hpp" +#include "libtorrent/kademlia/dht_observer.hpp" #include "libtorrent/socket.hpp" #include "libtorrent/socket_io.hpp" @@ -111,10 +113,6 @@ namespace libtorrent { namespace dht } #endif -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_DEFINE_LOG(dht_tracker) -#endif - namespace { node_id extract_node_id(bdecode_node e) @@ -146,6 +144,7 @@ namespace libtorrent { namespace dht : m_counters(cnt) , m_dht(this, settings, extract_node_id(state), observer, cnt) , m_sock(sock) + , m_log(observer) , m_last_new_key(clock_type::now() - minutes(int(key_refresh))) , m_timer(sock.get_io_service()) , m_connection_timer(sock.get_io_service()) @@ -156,14 +155,8 @@ namespace libtorrent { namespace dht , m_host_resolver(sock.get_io_service()) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - // turns on and off individual components' logging - -// rpc_log().enable(false); -// node_log().enable(false); -// traversal_log().enable(false); -// dht_tracker_log.enable(false); - - TORRENT_LOG(dht_tracker) << "starting DHT tracker with node id: " << m_dht.nid(); + m_log->log(dht_logger::tracker, "starting DHT tracker with node id: %s" + , to_hex(m_dht.nid().to_string()).c_str()); #endif } @@ -261,7 +254,7 @@ namespace libtorrent { namespace dht m_last_new_key = now; m_dht.new_write_key(); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << " *** new write key"; + m_log->log(dht_logger::tracker, "*** new write key***"); #endif } @@ -397,7 +390,7 @@ namespace libtorrent { namespace dht return true; } - if (!m_blocker.incoming(ep.address(), clock_type::now())) + if (!m_blocker.incoming(ep.address(), clock_type::now(), m_log)) return true; using libtorrent::entry; @@ -411,8 +404,8 @@ namespace libtorrent { namespace dht if (ret != 0) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << "<== " << ep << " ERROR: " - << err.message() << " pos: " << pos; + m_log->log(dht_logger::tracker, "<== %s ERROR: %s pos: %d" + , print_endpoint(ep).c_str(), err.message().c_str(), int(pos)); #endif return false; } @@ -420,8 +413,8 @@ namespace libtorrent { namespace dht if (m_msg.type() != bdecode_node::dict_t) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << "<== " << ep << " ERROR: not a dictionary: " - << print_entry(m_msg, true); + m_log->log(dht_logger::tracker, "<== %s ERROR: not a dictionary %s" + , print_endpoint(ep).c_str(), print_entry(m_msg, true).c_str()); #endif // it's not a good idea to send invalid messages // especially not in response to an invalid message @@ -518,11 +511,13 @@ namespace libtorrent { namespace dht error_code ec; #ifdef TORRENT_DHT_VERBOSE_LOGGING - std::stringstream log_line; + // TODO: 3 it would be nice to not have to decode this if logging + // is not enabled. Maybe there could be a separate log function for + // incoming and outgoing packets. bdecode_node print; int ret = bdecode(&m_send_buf[0], &m_send_buf[0] + m_send_buf.size(), print, ec); TORRENT_ASSERT(ret == 0); - log_line << print_entry(print, true); + std::string outgoing_message = print_entry(print, true); #endif if (m_sock.send(addr, &m_send_buf[0], (int)m_send_buf.size(), ec, send_flags)) @@ -531,7 +526,9 @@ namespace libtorrent { namespace dht { m_counters.inc_stats_counter(counters::dht_messages_out_dropped); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << "==> " << addr << " DROPPED (" << ec.message() << ") " << log_line.str(); + m_log->log(dht_logger::tracker, "==> %s DROPPED (%s) %s" + , print_endpoint(addr).c_str(), ec.message().c_str() + , outgoing_message.c_str()); #endif return false; } @@ -542,7 +539,9 @@ namespace libtorrent { namespace dht , addr.address().is_v6() ? 48 : 28); m_counters.inc_stats_counter(counters::dht_messages_out); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << "==> " << addr << " " << log_line.str(); + m_log->log(dht_logger::tracker, "==> %s %s" + , print_endpoint(addr).c_str() + , outgoing_message.c_str()); #endif return true; } @@ -551,7 +550,9 @@ namespace libtorrent { namespace dht m_counters.inc_stats_counter(counters::dht_messages_out_dropped); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << "==> " << addr << " DROPPED " << log_line.str(); + m_log->log(dht_logger::tracker, "==> %s DROPPED %s" + , print_endpoint(addr).c_str() + , outgoing_message.c_str()); #endif return false; } diff --git a/src/kademlia/dos_blocker.cpp b/src/kademlia/dos_blocker.cpp index 2e275af3a..90006c77e 100644 --- a/src/kademlia/dos_blocker.cpp +++ b/src/kademlia/dos_blocker.cpp @@ -33,16 +33,12 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/kademlia/dos_blocker.hpp" #ifdef TORRENT_DHT_VERBOSE_LOGGING -#include "libtorrent/kademlia/logging.hpp" +#include "libtorrent/socket_io.hpp" // for print_address +#include "libtorrent/kademlia/dht_observer.hpp" // for dht_logger #endif namespace libtorrent { namespace dht { - -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_DECLARE_LOG(dht_tracker); -#endif - dos_blocker::dos_blocker() : m_message_rate_limit(5) , m_block_timeout(5 * 60) @@ -54,7 +50,7 @@ namespace libtorrent { namespace dht } } - bool dos_blocker::incoming(address addr, time_point now) + bool dos_blocker::incoming(address addr, time_point now, dht_logger* logger) { node_ban_entry* match = 0; node_ban_entry* min = m_ban_nodes; @@ -81,9 +77,10 @@ namespace libtorrent { namespace dht if (match->count == m_message_rate_limit * 10) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(dht_tracker) << " BANNING PEER [ ip: " - << addr << " time: " << total_milliseconds((now - match->limit) + seconds(10)) / 1000.f - << " count: " << match->count << " ]"; + logger->log(dht_logger::tracker, "BANNING PEER [ ip: %s time: %f count: %d ]" + , print_address(addr).c_str() + , total_milliseconds((now - match->limit) + seconds(10)) / 1000.f + , int(match->count)); #endif // we've received too many messages in less than 10 seconds // from this node. Ignore it until it's silent for 5 minutes diff --git a/src/kademlia/find_data.cpp b/src/kademlia/find_data.cpp index 9e728e998..82176d429 100644 --- a/src/kademlia/find_data.cpp +++ b/src/kademlia/find_data.cpp @@ -32,6 +32,7 @@ POSSIBILITY OF SUCH DAMAGE. #include #include +#include #include #include #include @@ -40,10 +41,6 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_DECLARE_LOG(traversal); -#endif - using detail::read_endpoint_list; using detail::read_v4_endpoint; #if TORRENT_USE_IPV6 @@ -56,7 +53,8 @@ void find_data_observer::reply(msg const& m) if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" + , m_algorithm.get()); #endif return; } @@ -65,7 +63,8 @@ void find_data_observer::reply(msg const& m) if (!id || id.string_length() != 20) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] invalid id in response"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" + , m_algorithm.get()); #endif return; } @@ -113,8 +112,8 @@ void find_data::start() void find_data::got_write_token(node_id const& n, std::string const& write_token) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] adding write " - "token '" << to_hex(write_token) << "' under id '" << to_hex(n.to_string()) << "'"; + get_node().observer()->log(dht_logger::traversal, "[%p] adding write token '%s' under id '%s'" + , this, to_hex(write_token).c_str(), to_hex(n.to_string()).c_str()); #endif m_write_tokens[n] = write_token; } @@ -138,7 +137,8 @@ void find_data::done() m_done = true; #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] " << name() << " DONE"; + get_node().observer()->log(dht_logger::traversal, "[%p] %s DONE" + , this, name()); #endif std::vector > results; @@ -150,8 +150,8 @@ void find_data::done() if ((o->flags & observer::flag_alive) == 0) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] not alive: " - << o->target_ep(); + get_node().observer()->log(dht_logger::traversal, "[%p] not alive: %s" + , this, print_endpoint(o->target_ep()).c_str()); #endif continue; } @@ -159,15 +159,15 @@ void find_data::done() if (j == m_write_tokens.end()) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] no write token: " - << o->target_ep(); + get_node().observer()->log(dht_logger::traversal, "[%p] no write token: %s" + , this, print_endpoint(o->target_ep()).c_str()); #endif continue; } results.push_back(std::make_pair(node_entry(o->id(), o->target_ep()), j->second)); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] " - << o->target_ep(); + get_node().observer()->log(dht_logger::traversal, "[%p] %s" + , this, print_endpoint(o->target_ep()).c_str()); #endif --num_results; } diff --git a/src/kademlia/get_item.cpp b/src/kademlia/get_item.cpp index 80527e330..1a51765b1 100644 --- a/src/kademlia/get_item.cpp +++ b/src/kademlia/get_item.cpp @@ -32,8 +32,10 @@ POSSIBILITY OF SUCH DAMAGE. #include #include +#include #include #include +#include #if TORRENT_USE_ASSERTS #include @@ -197,9 +199,12 @@ void get_item::done() void get_item::put(std::vector > const& v) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "sending put [ v: \"" << m_data.value() - << "\" seq: " << (m_data.is_mutable() ? m_data.seq() : -1) - << " nodes: " << v.size() << " ]" ; + // TODO: 3 it would be nice to not have to spend so much time rendering + // the bencoded dict if logging is disabled + get_node().observer()->log(dht_logger::traversal, "[%p] sending put [ v: \"%s\" seq: %" PRId64 " nodes: %d ]" + , this, m_data.value().to_string().c_str() + , (m_data.is_mutable() ? m_data.seq() : -1) + , int(v.size())); #endif // create a dummy traversal_algorithm @@ -211,7 +216,8 @@ void get_item::put(std::vector > const& v) , end(v.end()); i != end; ++i) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << " put-distance: " << (160 - distance_exp(m_target, i->first.id)); + get_node().observer()->log(dht_logger::traversal, "[%p] put-distance: %d" + , this, 160 - distance_exp(m_target, i->first.id)); #endif void* ptr = m_node.m_rpc.allocate_observer(); @@ -252,7 +258,8 @@ void get_item_observer::reply(msg const& m) if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" + , m_algorithm.get()); #endif return; } diff --git a/src/kademlia/get_peers.cpp b/src/kademlia/get_peers.cpp index 551ea591d..79cde5431 100644 --- a/src/kademlia/get_peers.cpp +++ b/src/kademlia/get_peers.cpp @@ -51,7 +51,8 @@ void get_peers_observer::reply(msg const& m) if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" + , m_algorithm.get()); #endif return; } @@ -71,14 +72,15 @@ void get_peers_observer::reply(msg const& m) bdecode_node id = r.dict_find_string("id"); if (id && id.string_length() == 20) { - TORRENT_LOG(traversal) - << "[" << m_algorithm.get() << "] PEERS" - << " invoke-count: " << m_algorithm->invoke_count() - << " branch-factor: " << m_algorithm->branch_factor() - << " addr: " << m.addr - << " id: " << node_id(id.string_ptr()) - << " distance: " << distance_exp(m_algorithm->target(), node_id(id.string_ptr())) - << " p: " << ((end - peers) / 6); + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] PEERS " + "invoke-count: %d branch-factor: %d addr: %s id: %s distance: %d p: %d" + , m_algorithm.get() + , m_algorithm->invoke_count() + , m_algorithm->branch_factor() + , print_endpoint(m.addr).c_str() + , to_hex(id.string_value()).c_str() + , distance_exp(m_algorithm->target(), node_id(id.string_ptr())) + , (end - peers) / 6); } #endif while (end - peers >= 6) @@ -92,14 +94,15 @@ void get_peers_observer::reply(msg const& m) bdecode_node id = r.dict_find_string("id"); if (id && id.string_length() == 20) { - TORRENT_LOG(traversal) - << "[" << m_algorithm.get() << "] PEERS" - << " invoke-count: " << m_algorithm->invoke_count() - << " branch-factor: " << m_algorithm->branch_factor() - << " addr: " << m.addr - << " id: " << node_id(id.string_ptr()) - << " distance: " << distance_exp(m_algorithm->target(), node_id(id.string_ptr())) - << " p: " << n.list_size(); + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] PEERS " + "invoke-count: %d branch-factor: %d addr: %s id: %s distance: %d p: %d" + , m_algorithm.get() + , m_algorithm->invoke_count() + , m_algorithm->branch_factor() + , print_endpoint(m.addr).c_str() + , to_hex(id.string_value()).c_str() + , distance_exp(m_algorithm->target(), node_id(id.string_ptr())) + , n.list_size()); } #endif } @@ -274,8 +277,9 @@ void obfuscated_get_peers::done() m_nodes_callback.clear(); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << " [" << this << "]" - << " obfuscated get_peers phase 1 done, spawning get_peers [" << ta.get() << "]"; + get_node().observer()->log(dht_logger::traversal, "[%p] obfuscated get_peers " + "phase 1 done, spawning get_peers [ %p ]" + , this, ta.get()); #endif int num_added = 0; @@ -304,8 +308,8 @@ void obfuscated_get_peers_observer::reply(msg const& m) if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() - << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" + , m_algorithm.get()); #endif return; } @@ -314,8 +318,8 @@ void obfuscated_get_peers_observer::reply(msg const& m) if (!id || id.string_length() != 20) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() - << "] invalid id in response"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" + , m_algorithm.get()); #endif return; } diff --git a/src/kademlia/logging.cpp b/src/kademlia/logging.cpp index 8f47b9ddd..40b2daac7 100644 --- a/src/kademlia/logging.cpp +++ b/src/kademlia/logging.cpp @@ -32,7 +32,7 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/kademlia/logging.hpp" #include "libtorrent/time.hpp" - +/* namespace libtorrent { namespace dht { // TODO: 3 replace this logging with alerts @@ -58,4 +58,5 @@ namespace libtorrent { namespace dht } }} +*/ diff --git a/src/kademlia/node.cpp b/src/kademlia/node.cpp index 91400cb8c..e89d0972f 100644 --- a/src/kademlia/node.cpp +++ b/src/kademlia/node.cpp @@ -69,10 +69,6 @@ using detail::write_endpoint; // TODO: 2 make this configurable in dht_settings enum { announce_interval = 30 }; -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DEFINE_LOG(node) -#endif - namespace { // remove peers that have timed out @@ -83,12 +79,7 @@ void purge_peers(std::set& peers) { // the peer has timed out if (i->added + minutes(int(announce_interval * 1.5f)) < aux::time_now()) - { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "peer timed out at: " << i->addr; -#endif peers.erase(i++); - } else ++i; } @@ -114,8 +105,8 @@ node::node(udp_socket_interface* sock , struct counters& cnt) : m_settings(settings) , m_id(calculate_node_id(nid, observer)) - , m_table(m_id, 8, settings) - , m_rpc(m_id, m_table, sock) + , m_table(m_id, 8, settings, observer) + , m_rpc(m_id, m_table, sock, observer) , m_observer(observer) , m_last_tracker_tick(aux::time_now()) , m_last_self_refresh(min_time()) @@ -132,7 +123,8 @@ bool node::verify_token(std::string const& token, char const* info_hash if (token.length() != 4) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "token of incorrect length: " << token.length(); + m_observer->log(dht_logger::node, "token of incorrect length: %d" + , token.length()); #endif return false; } @@ -203,7 +195,7 @@ void node::bootstrap(std::vector const& nodes r->trim_seed_nodes(); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "bootstrapping with " << count << " nodes"; + m_observer->log(dht_logger::node, "bootstrapping with %d nodes", count); #endif r->start(); } @@ -292,7 +284,8 @@ void node::incoming(msg const& m) bdecode_node err = m.message.dict_find_list("e"); if (err && err.list_size() >= 2) { - TORRENT_LOG(node) << "INCOMING ERROR: " << err.list_string_value_at(1); + m_observer->log(dht_logger::node, "INCOMING ERROR: %s" + , err.list_string_value_at(1).c_str()); } #endif node_id id; @@ -308,9 +301,10 @@ namespace , node& node, int listen_port, sha1_hash const& ih, int flags) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "sending announce_peer [ ih: " << ih - << " p: " << listen_port - << " nodes: " << v.size() << " ]" ; + char hex_ih[41]; + to_hex(reinterpret_cast(&ih[0]), 20, hex_ih); + node.observer()->log(dht_logger::node, "sending announce_peer [ ih: %s " + " p: %d nodes: %d ]", hex_ih, listen_port, int(v.size())); #endif // create a dummy traversal_algorithm @@ -322,7 +316,8 @@ namespace , end(v.end()); i != end; ++i) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << " announce-distance: " << (160 - distance_exp(ih, i->first.id)); + node.observer()->log(dht_logger::node, "announce-distance: %d" + , (160 - distance_exp(ih, i->first.id))); #endif void* ptr = node.m_rpc.allocate_observer(); @@ -349,7 +344,8 @@ namespace void node::add_router_node(udp::endpoint router) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "adding router node: " << router; + m_observer->log(dht_logger::node, "adding router node: %s" + , print_endpoint(router).c_str()); #endif m_table.add_router_node(router); } @@ -365,7 +361,10 @@ void node::announce(sha1_hash const& info_hash, int listen_port, int flags , boost::function const&)> f) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "announcing [ ih: " << info_hash << " p: " << listen_port << " ]" ; + char hex_ih[41]; + to_hex(reinterpret_cast(&info_hash[0]), 20, hex_ih); + m_observer->log(dht_logger::node, "announcing [ ih: %s p: %d ]" + , hex_ih, listen_port); #endif // search for nodes with ids close to id or with peers // for info-hash id. then send announce_peer to them. @@ -391,7 +390,10 @@ void node::get_item(sha1_hash const& target , boost::function f) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "starting get for [ hash: " << target << " ]" ; + char hex_target[41]; + to_hex(reinterpret_cast(&target[0]), 20, hex_target); + m_observer->log(dht_logger::node, "starting get for [ hash: %s ]" + , hex_target); #endif boost::intrusive_ptr ta; @@ -403,8 +405,9 @@ void node::get_item(char const* pk, std::string const& salt , boost::function f) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(node) << "starting get for [ key: " - << to_hex(std::string(pk, 32)) << " ]" ; + char hex_key[65]; + to_hex(pk, 32, hex_key); + m_observer->log(dht_logger::node, "starting get for [ key: %s ]", hex_key); #endif boost::intrusive_ptr ta; @@ -429,8 +432,9 @@ struct ping_observer : observer if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() - << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::node + , "[%p] missing response dict" + , m_algorithm.get()); #endif return; } @@ -896,7 +900,8 @@ void node::incoming_request(msg const& m, entry& e) #ifdef TORRENT_DHT_VERBOSE_LOGGING if (reply.find_key("values")) { - TORRENT_LOG(node) << " values: " << reply["values"].list().size(); + m_observer->log(dht_logger::node, "values: %d" + , int(reply["values"].list().size())); } #endif } diff --git a/src/kademlia/refresh.cpp b/src/kademlia/refresh.cpp index 41192e318..898a0c158 100644 --- a/src/kademlia/refresh.cpp +++ b/src/kademlia/refresh.cpp @@ -33,6 +33,7 @@ POSSIBILITY OF SUCH DAMAGE. #include #include #include +#include #include #include @@ -40,10 +41,6 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_DECLARE_LOG(traversal); -#endif - observer_ptr bootstrap::new_observer(void* ptr , udp::endpoint const& ep, node_id const& id) { @@ -91,8 +88,8 @@ void bootstrap::trim_seed_nodes() void bootstrap::done() { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "]" - << " bootstrap done, pinging remaining nodes"; + get_node().observer()->log(dht_logger::traversal, "[%p] bootstrap done, pinging remaining nodes" + , this); #endif for (std::vector::iterator i = m_results.begin() diff --git a/src/kademlia/routing_table.cpp b/src/kademlia/routing_table.cpp index 001fe98ed..03a2d591b 100644 --- a/src/kademlia/routing_table.cpp +++ b/src/kademlia/routing_table.cpp @@ -42,15 +42,13 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/broadcast_socket.hpp" // for cidr_distance #include "libtorrent/session_status.hpp" #include "libtorrent/kademlia/node_id.hpp" +#include "libtorrent/kademlia/dht_observer.hpp" #include "libtorrent/time.hpp" #include "libtorrent/alert_types.hpp" // for dht_routing_bucket +#include "libtorrent/socket_io.hpp" // for print_endpoint #include "libtorrent/invariant_check.hpp" -#if (defined TORRENT_DHT_VERBOSE_LOGGING || defined TORRENT_DEBUG) && TORRENT_USE_IOSTREAM -#include "libtorrent/socket_io.hpp" // for print_endpoint -#endif - using boost::uint8_t; #if BOOST_VERSION <= 104700 @@ -65,10 +63,6 @@ size_t hash_value(libtorrent::address_v4::bytes_type ip) namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DEFINE_LOG(table) -#endif - template void erase_one(T& container, K const& key) { @@ -78,8 +72,10 @@ void erase_one(T& container, K const& key) } routing_table::routing_table(node_id const& id, int bucket_size - , dht_settings const& settings) - : m_settings(settings) + , dht_settings const& settings + , dht_logger* log) + : m_log(log) + , m_settings(settings) , m_id(id) , m_depth(0) , m_last_self_refresh(min_time()) @@ -584,8 +580,10 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) if (m_settings.restrict_routing_ips) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << "ignoring node (duplicate IP): " - << e.id << " " << e.addr(); + char hex_id[41]; + to_hex(reinterpret_cast(&e.id[0]), 20, hex_id); + m_log->log(dht_logger::routing_table, "ignoring node (duplicate IP): %s %s" + , hex_id, print_address(e.addr()).c_str()); #endif return failed_to_add; } @@ -632,7 +630,6 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) TORRENT_ASSERT(j->id == e.id && j->ep() == e.ep()); j->timeout_count = 0; j->update_rtt(e.rtt); -// TORRENT_LOG(table) << "updating node: " << i->id << " " << i->addr(); return node_added; } @@ -666,9 +663,13 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) // close to this one. We know that it's not the same, because // it claims a different node-ID. Ignore this to avoid attacks #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << "ignoring node: " << e.id << " " << e.addr() - << " existing node: " - << j->id << " " << j->addr(); + char hex_id1[41]; + to_hex(reinterpret_cast(&e.id[0]), 20, hex_id1); + char hex_id2[41]; + to_hex(reinterpret_cast(&j->id[0]), 20, hex_id2); + m_log->log(dht_logger::routing_table, "ignoring node: %s %s existing node: %s %s" + , hex_id1, print_address(e.addr()).c_str() + , hex_id2, print_address(j->addr()).c_str()); #endif return failed_to_add; } @@ -678,9 +679,13 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) { // same thing but for the replacement bucket #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << "ignoring (replacement) node: " << e.id << " " << e.addr() - << " existing node: " - << j->id << " " << j->addr(); + char hex_id1[41]; + to_hex(reinterpret_cast(&e.id[0]), 20, hex_id1); + char hex_id2[41]; + to_hex(reinterpret_cast(&j->id[0]), 20, hex_id2); + m_log->log(dht_logger::routing_table, "ignoring (replacement) node: %s %s existing node: %s %s" + , hex_id1, print_address(e.addr()).c_str() + , hex_id2, print_address(j->addr()).c_str()); #endif return failed_to_add; } @@ -692,7 +697,6 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) if (b.empty()) b.reserve(bucket_size_limit); b.push_back(e); m_ips.insert(e.addr().to_v4().to_bytes()); -// TORRENT_LOG(table) << "inserting node: " << e.id << " " << e.addr(); return node_added; } @@ -726,7 +730,6 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) erase_one(m_ips, j->addr().to_v4().to_bytes()); *j = e; m_ips.insert(e.addr().to_v4().to_bytes()); -// TORRENT_LOG(table) << "replacing unpinged node: " << e.id << " " << e.addr(); return node_added; } @@ -748,7 +751,6 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) erase_one(m_ips, j->addr().to_v4().to_bytes()); *j = e; m_ips.insert(e.addr().to_v4().to_bytes()); -// TORRENT_LOG(table) << "replacing stale node: " << e.id << " " << e.addr(); return node_added; } @@ -857,8 +859,10 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) *j = e; m_ips.insert(e.addr().to_v4().to_bytes()); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << "replacing node with higher RTT: " << e.id - << " " << e.addr(); + char hex_id[41]; + to_hex(reinterpret_cast(&e.id[0]), sha1_hash::size, hex_id); + m_log->log(dht_logger::routing_table, "replaving node with higher RTT: %s %s" + , hex_id, print_address(e.addr()).c_str()); #endif return node_added; } @@ -902,7 +906,6 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) if (rb.empty()) rb.reserve(m_bucket_size); rb.push_back(e); m_ips.insert(e.addr().to_v4().to_bytes()); -// TORRENT_LOG(table) << "inserting node in replacement cache: " << e.id << " " << e.addr(); return node_added; } @@ -1029,12 +1032,13 @@ void routing_table::node_failed(node_id const& nid, udp::endpoint const& ep) j->timed_out(); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << " NODE FAILED" - " id: " << nid << - " ip: " << j->ep() << - " fails: " << j->fail_count() << - " pinged: " << j->pinged() << - " up-time: " << total_seconds(aux::time_now() - j->first_seen); + char hex_id[41]; + to_hex(reinterpret_cast(&nid[0]), 20, hex_id); + m_log->log(dht_logger::routing_table, "NODE FAILED id: %s ip: %s fails: %d pinged: %d up-time: %d" + , hex_id, print_endpoint(j->ep()).c_str() + , int(j->fail_count()) + , int(j->pinged()) + , int(total_seconds(aux::time_now() - j->first_seen))); #endif return; } @@ -1049,12 +1053,13 @@ void routing_table::node_failed(node_id const& nid, udp::endpoint const& ep) j->timed_out(); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(table) << " NODE FAILED" - " id: " << nid << - " ip: " << j->ep() << - " fails: " << j->fail_count() << - " pinged: " << j->pinged() << - " up-time: " << total_seconds(aux::time_now() - j->first_seen); + char hex_id[41]; + to_hex(reinterpret_cast(&nid[0]), 20, hex_id); + m_log->log(dht_logger::routing_table, "NODE FAILED id: %s ip: %s fails: %d pinged: %d up-time: %d" + , hex_id, print_endpoint(j->ep()).c_str() + , int(j->fail_count()) + , int(j->pinged()) + , int(total_seconds(aux::time_now() - j->first_seen))); #endif // if this node has failed too many times, or if this node diff --git a/src/kademlia/rpc_manager.cpp b/src/kademlia/rpc_manager.cpp index 38e8b17d4..8f961177e 100644 --- a/src/kademlia/rpc_manager.cpp +++ b/src/kademlia/rpc_manager.cpp @@ -45,6 +45,9 @@ POSSIBILITY OF SUCH DAMAGE. #include #include #include +#include + +#include // for print_endpoint #include #include // for dht_settings #include @@ -59,10 +62,6 @@ namespace libtorrent { namespace dht namespace io = libtorrent::detail; -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DEFINE_LOG(rpc) -#endif - void intrusive_ptr_add_ref(observer const* o) { TORRENT_ASSERT(o != 0); @@ -84,12 +83,7 @@ void intrusive_ptr_release(observer const* o) void observer::set_target(udp::endpoint const& ep) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - // use high resolution timers for logging m_sent = clock_type::now(); -#else - m_sent = aux::time_now(); -#endif m_port = ep.port(); #if TORRENT_USE_IPV6 @@ -165,46 +159,22 @@ enum { observer_size = max3< }; rpc_manager::rpc_manager(node_id const& our_id - , routing_table& table, udp_socket_interface* sock) + , routing_table& table, udp_socket_interface* sock + , dht_logger* log) : m_pool_allocator(observer_size, 10) , m_sock(sock) + , m_log(log) , m_table(table) , m_timer(aux::time_now()) , m_our_id(our_id) , m_allocated_observers(0) , m_destructing(false) -{ -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "Constructing"; - -#define PRINT_OFFSETOF(x, y) TORRENT_LOG(rpc) << " +" << offsetof(x, y) << ": " #y - - TORRENT_LOG(rpc) << " observer: " << sizeof(observer); - PRINT_OFFSETOF(dht::observer, m_sent); - PRINT_OFFSETOF(dht::observer, m_refs); - PRINT_OFFSETOF(dht::observer, m_algorithm); - PRINT_OFFSETOF(dht::observer, m_id); - PRINT_OFFSETOF(dht::observer, m_addr); - PRINT_OFFSETOF(dht::observer, m_port); - PRINT_OFFSETOF(dht::observer, m_transaction_id); - PRINT_OFFSETOF(dht::observer, flags); - - TORRENT_LOG(rpc) << " announce_observer: " << sizeof(announce_observer); - TORRENT_LOG(rpc) << " null_observer: " << sizeof(null_observer); - TORRENT_LOG(rpc) << " find_data_observer: " << sizeof(find_data_observer); - -#undef PRINT_OFFSETOF -#endif - -} +{} rpc_manager::~rpc_manager() { TORRENT_ASSERT(!m_destructing); m_destructing = true; -#ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "Destructing"; -#endif for (transactions_t::iterator i = m_transactions.begin() , end(m_transactions.end()); i != end; ++i) @@ -249,7 +219,8 @@ void rpc_manager::check_invariant() const void rpc_manager::unreachable(udp::endpoint const& ep) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << " PORT_UNREACHABLE [ ip: " << ep << " ]"; + m_log->log(dht_logger::rpc_manager, "PORT_UNREACHABLE [ ip: %s ]" + , print_endpoint(ep).c_str()); #endif for (transactions_t::iterator i = m_transactions.begin(); @@ -261,7 +232,8 @@ void rpc_manager::unreachable(udp::endpoint const& ep) observer_ptr ptr = i->second; i = m_transactions.erase(i); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << " found transaction [ tid: " << ptr->transaction_id() << " ]"; + m_log->log(dht_logger::rpc_manager, "found transaction [ tid: %d ]" + , int(ptr->transaction_id())); #endif ptr->timeout(); break; @@ -301,8 +273,8 @@ bool rpc_manager::incoming(msg const& m, node_id* id if (!o) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "Reply with unknown transaction id size: " - << transaction_id.size() << " from " << m.addr; + m_log->log(dht_logger::rpc_manager, "reply with unknown transaction id size: %d from %s" + , transaction_id.size(), print_endpoint(m.addr).c_str()); #endif // this isn't necessarily because the other end is doing // something wrong. This can also happen when we restart @@ -359,8 +331,9 @@ bool rpc_manager::incoming(msg const& m, node_id* id } #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "[" << o->m_algorithm.get() << "] Reply with transaction id: " - << tid << " from " << m.addr; + m_log->log(dht_logger::rpc_manager, "[%p] reply with transaction id: %d from %s" + , o->m_algorithm.get(), transaction_id.size() + , print_endpoint(m.addr).c_str()); #endif o->reply(m); *id = nid; @@ -398,8 +371,9 @@ time_duration rpc_manager::tick() if (diff >= seconds(timeout)) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "[" << o->m_algorithm.get() << "] Timing out transaction id: " - << o->transaction_id() << " from " << o->target_ep(); + m_log->log(dht_logger::rpc_manager, "[%p] timing out transaction id: %d from: %s" + , o->m_algorithm.get(), o->transaction_id() + , print_endpoint(o->target_ep()).c_str()); #endif m_transactions.erase(i++); timeouts.push_back(o); @@ -411,8 +385,9 @@ time_duration rpc_manager::tick() if (diff >= seconds(short_timeout) && !o->has_short_timeout()) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "[" << o->m_algorithm.get() << "] Short-Timing out transaction id: " - << o->transaction_id() << " from " << o->target_ep(); + m_log->log(dht_logger::rpc_manager, "[%p] short-timing out transaction id: %d from: %s" + , o->m_algorithm.get(), o->transaction_id() + , print_endpoint(o->target_ep()).c_str()); #endif ++i; @@ -457,8 +432,9 @@ bool rpc_manager::invoke(entry& e, udp::endpoint target_addr o->set_transaction_id(tid); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(rpc) << "[" << o->m_algorithm.get() << "] invoking " - << e["q"].string() << " -> " << target_addr; + m_log->log(dht_logger::rpc_manager, "[%p] invoking %s -> %s" + , o->m_algorithm.get(), e["q"].string().c_str() + , print_endpoint(target_addr).c_str()); #endif if (m_sock->send_packet(e, target_addr, 1)) diff --git a/src/kademlia/traversal_algorithm.cpp b/src/kademlia/traversal_algorithm.cpp index adf68d226..def5ed652 100644 --- a/src/kademlia/traversal_algorithm.cpp +++ b/src/kademlia/traversal_algorithm.cpp @@ -36,6 +36,7 @@ POSSIBILITY OF SUCH DAMAGE. #include #include #include +#include // for dht_logger #include #include // for read_*_endpoint #include // for dht_lookup @@ -44,10 +45,6 @@ POSSIBILITY OF SUCH DAMAGE. namespace libtorrent { namespace dht { -#ifdef TORRENT_DHT_VERBOSE_LOGGING -TORRENT_DEFINE_LOG(traversal) -#endif - using detail::read_v4_endpoint; #if TORRENT_USE_IPV6 using detail::read_v6_endpoint; @@ -93,10 +90,10 @@ traversal_algorithm::traversal_algorithm( , m_timeouts(0) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] NEW" - " target: " << target - << " k: " << m_node.m_table.bucket_size() - ; + char hex_target[41]; + to_hex(reinterpret_cast(&target[0]), 20, hex_target); + get_node().observer()->log(dht_logger::traversal, "[%p] NEW target: %s k: %d" + , this, hex_target, int(m_node.m_table.bucket_size())); #endif } @@ -121,7 +118,8 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig if (ptr == 0) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] failed to allocate memory for observer. aborting!"; + get_node().observer()->log(dht_logger::traversal, "[%p] failed to allocate memory or observer. aborting!" + , this); #endif done(); return; @@ -170,11 +168,11 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig // close to this one. We know that it's not the same, because // it claims a different node-ID. Ignore this to avoid attacks #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] IGNORING result " - << "id: " << to_hex(o->id().to_string()) - << " addr: " << o->target_addr() - << " type: " << name() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] IGNORING result id: %s addr: %s type: %s" + , this, hex_id, print_address(o->target_addr()).c_str(), name()); #endif return; } @@ -185,12 +183,12 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig TORRENT_ASSERT((o->flags & observer::flag_no_id) || std::find_if(m_results.begin(), m_results.end() , boost::bind(&observer::id, _1) == id) == m_results.end()); #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] ADD id: " << to_hex(id.to_string()) - << " addr: " << addr - << " distance: " << distance_exp(m_target, id) - << " invoke-count: " << m_invoke_count - << " type: " << name() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&id[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] ADD id: %s addr: %s distance: %d invoke-count: %d type: %s" + , this, hex_id, print_endpoint(addr).c_str() + , distance_exp(m_target, id), m_invoke_count, name()); #endif i = m_results.insert(i, o); @@ -243,7 +241,9 @@ void traversal_algorithm::traverse(node_id const& id, udp::endpoint addr) #ifdef TORRENT_DHT_VERBOSE_LOGGING if (id.is_all_zeros()) { - TORRENT_LOG(traversal) << " [" << this << "] WARNING node returned a list which included a node with id 0"; + get_node().observer()->log(dht_logger::traversal + , "[%p] WARNING node returned a list which included a node with id 0" + , this); } #endif @@ -305,14 +305,14 @@ void traversal_algorithm::failed(observer_ptr o, int flags) ++m_branch_factor; o->flags |= observer::flag_short_timeout; #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] 1ST_TIMEOUT " - << " id: " << to_hex(o->id().to_string()) - << " distance: " << distance_exp(m_target, o->id()) - << " addr: " << o->target_ep() - << " branch-factor: " << m_branch_factor - << " invoke-count: " << m_invoke_count - << " type: " << name() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] 1ST_TIMEOUT id: %s distance: %d addr: %s branch-factor: %d " + "invoke-count: %d type: %s" + , this, hex_id, distance_exp(m_target, o->id()) + , print_address(o->target_addr()).c_str(), m_branch_factor + , m_invoke_count, name()); #endif } else @@ -324,14 +324,14 @@ void traversal_algorithm::failed(observer_ptr o, int flags) --m_branch_factor; #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] TIMEOUT " - << " id: " << to_hex(o->id().to_string()) - << " distance: " << distance_exp(m_target, o->id()) - << " addr: " << o->target_ep() - << " branch-factor: " << m_branch_factor - << " invoke-count: " << m_invoke_count - << " type: " << name() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] TIMEOUT id: %s distance: %d addr: %s branch-factor: %d " + "invoke-count: %d type: %s" + , this, hex_id, distance_exp(m_target, o->id()) + , print_address(o->target_addr()).c_str(), m_branch_factor + , m_invoke_count, name()); #endif ++m_timeouts; @@ -354,6 +354,8 @@ void traversal_algorithm::done() int results_target = m_node.m_table.bucket_size(); int closest_target = 160; + // TODO: 3 it would be nice to not have to perform this loop if + // logging is disabled for (std::vector::iterator i = m_results.begin() , end(m_results.end()); i != end && results_target > 0; ++i) { @@ -361,23 +363,22 @@ void traversal_algorithm::done() if (o->flags & observer::flag_alive) { TORRENT_ASSERT(o->flags & observer::flag_queried); - TORRENT_LOG(traversal) << "[" << this << "] " - << results_target - << " id: " << to_hex(o->id().to_string()) - << " distance: " << distance_exp(m_target, o->id()) - << " addr: " << o->target_ep() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] id: %s distance: %d addr: %s" + , this, hex_id, closest_target + , print_endpoint(o->target_ep()).c_str()); + --results_target; int dist = distance_exp(m_target, o->id()); if (dist < closest_target) closest_target = dist; } } - TORRENT_LOG(traversal) << "[" << this << "] COMPLETED " - << "distance: " << closest_target - << " type: " << name() - ; - + get_node().observer()->log(dht_logger::traversal + , "[%p] COMPLETED distance: %d type: %s" + , this, closest_target, name()); #endif // delete all our references to the observer objects so // they will in turn release the traversal algorithm @@ -433,16 +434,15 @@ bool traversal_algorithm::add_requests() } #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] INVOKE " - << " nodes-left: " << (m_results.end() - i) - << " top-invoke-count: " << outstanding - << " invoke-count: " << m_invoke_count - << " branch-factor: " << m_branch_factor - << " distance: " << distance_exp(m_target, o->id()) - << " id: " << to_hex(o->id().to_string()) - << " addr: " << o->target_ep() - << " type: " << name() - ; + char hex_id[41]; + to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); + get_node().observer()->log(dht_logger::traversal + , "[%p] INVOKE nodes-left: %d top-invoke-count: %d " + "invoke-count: %d branch-factor: %d " + "distance: %d id: %s addr: %s type: %s" + , this, m_results.end() - i, outstanding, m_invoke_count + , m_branch_factor, distance_exp(m_target, o->id()), hex_id + , print_address(o->target_addr()).c_str(), name()); #endif o->flags |= observer::flag_queried; @@ -469,8 +469,9 @@ bool traversal_algorithm::add_requests() void traversal_algorithm::add_router_entries() { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] using router nodes to initiate traversal algorithm. " - << std::distance(m_node.m_table.router_begin(), m_node.m_table.router_end()) << " routers"; + get_node().observer()->log(dht_logger::traversal + , "[%p] using router nodes to initiate traversal algorithm %d routers" + , this, int(std::distance(m_node.m_table.router_begin(), m_node.m_table.router_end()))); #endif for (routing_table::router_iterator i = m_node.m_table.router_begin() , end(m_node.m_table.router_end()); i != end; ++i) @@ -523,20 +524,21 @@ void traversal_observer::reply(msg const& m) if (!r) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() - << "] missing response dict"; + m_algorithm->get_node().observer()->log(dht_logger::traversal + , "[%p] missing response dict" + , m_algorithm.get()); #endif return; } #ifdef TORRENT_DHT_VERBOSE_LOGGING bdecode_node nid = r.dict_find_string("id"); - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] " - "RESPONSE id: " << to_hex(nid.string_value()) - << " invoke-count: " << m_algorithm->invoke_count() - << " addr: " << m.addr - << " type: " << m_algorithm->name() - ; + char hex_id[41]; + to_hex(nid.string_ptr(), 20, hex_id); + m_algorithm->get_node().observer()->log(dht_logger::traversal + , "[%p] RESPONSE id: %s invoke-count: %d addr: %s type: %s" + , m_algorithm.get(), hex_id, m_algorithm->invoke_count() + , print_endpoint(target_ep()).c_str(), m_algorithm->name()); #endif // look for nodes bdecode_node n = r.dict_find_string("nodes"); @@ -558,7 +560,8 @@ void traversal_observer::reply(msg const& m) if (!id || id.string_length() != 20) { #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] invalid id in response"; + m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" + , m_algorithm.get(), m_algorithm->name()); #endif return; } @@ -579,9 +582,8 @@ void traversal_algorithm::abort() } #ifdef TORRENT_DHT_VERBOSE_LOGGING - TORRENT_LOG(traversal) << "[" << this << "] ABORTED " - << " type: " << name() - ; + get_node().observer()->log(dht_logger::traversal, "[%p] ABORTED type: %s" + , this, name()); #endif done(); diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 11671e1c4..7135ada28 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -6431,43 +6431,55 @@ retry: m_upnp.reset(); } - external_ip const& session_impl::external_address() const TORRENT_OVERRIDE + external_ip const& session_impl::external_address() const { return m_external_ip; } // this is the DHT observer version. DHT is the implied source void session_impl::set_external_address(address const& ip - , address const& source) TORRENT_OVERRIDE + , address const& source) { set_external_address(ip, source_dht, source); } - address session_impl::external_address() TORRENT_OVERRIDE + address session_impl::external_address() { return m_external_ip.external_address(address_v4()); } - void session_impl::get_peers(sha1_hash const& ih) TORRENT_OVERRIDE + void session_impl::get_peers(sha1_hash const& ih) { if (!m_alerts.should_post()) return; m_alerts.emplace_alert(ih); } void session_impl::announce(sha1_hash const& ih, address const& addr - , int port) TORRENT_OVERRIDE + , int port) { if (!m_alerts.should_post()) return; m_alerts.emplace_alert(addr, port, ih); } void session_impl::outgoing_get_peers(sha1_hash const& target - , sha1_hash const& sent_target, udp::endpoint const& ep) TORRENT_OVERRIDE + , sha1_hash const& sent_target, udp::endpoint const& ep) { if (!m_alerts.should_post()) return; m_alerts.emplace_alert(target, sent_target, ep); } + void session_impl::log(libtorrent::dht::dht_logger::dht_module_t m, char const* fmt, ...) + { + if (!m_alerts.should_post()) return; + + va_list v; + va_start(v, fmt); + char buf[1024]; + vsnprintf(buf, sizeof(buf), fmt, v); + va_end(v); + m_alerts.emplace_alert((dht_log_alert::dht_module_t)m, buf); + } + void session_impl::set_external_address(address const& ip , int source_type, address const& source) {