From 99de70604af1f4ced920a40e8759e00b4dbc2545 Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Sat, 16 May 2015 19:29:49 +0000 Subject: [PATCH] remove dht-verbose logging build configuration. tie it to the main logging configuration (which now is on by default) and make it less costly when dht logging alerts are disabled --- Jamfile | 8 +-- include/libtorrent/aux_/session_impl.hpp | 4 +- include/libtorrent/kademlia/dht_observer.hpp | 14 ++++- include/libtorrent/kademlia/node.hpp | 2 +- include/libtorrent/kademlia/node_entry.hpp | 2 +- include/libtorrent/kademlia/observer.hpp | 4 +- include/libtorrent/kademlia/routing_table.hpp | 2 +- src/kademlia/dht_tracker.cpp | 62 +++++++++---------- src/kademlia/dos_blocker.cpp | 4 +- src/kademlia/find_data.cpp | 14 ++--- src/kademlia/get_item.cpp | 6 +- src/kademlia/get_peers.cpp | 12 ++-- src/kademlia/node.cpp | 26 ++++---- src/kademlia/node_entry.cpp | 6 +- src/kademlia/refresh.cpp | 2 +- src/kademlia/routing_table.cpp | 14 ++--- src/kademlia/rpc_manager.cpp | 18 +++--- src/kademlia/traversal_algorithm.cpp | 28 ++++----- src/session_impl.cpp | 30 ++++++++- test/test_dht.cpp | 4 +- test/test_dos_blocker.cpp | 24 ++++++- 21 files changed, 172 insertions(+), 114 deletions(-) diff --git a/Jamfile b/Jamfile index 6d8e58f54..2b9c199f0 100755 --- a/Jamfile +++ b/Jamfile @@ -454,9 +454,8 @@ feature.compose on : TORRENT_SIMULATE_SLOW_READ ; feature logging : on off : composite propagated link-incompatible ; feature.compose off : TORRENT_DISABLE_LOGGING ; -feature dht : on off logging : composite propagated link-incompatible ; +feature dht : on off : composite propagated link-incompatible ; feature.compose off : TORRENT_DISABLE_DHT ; -feature.compose logging : TORRENT_DHT_VERBOSE_LOGGING ; feature encryption : on off : composite propagated link-incompatible ; feature.compose off : TORRENT_DISABLE_ENCRYPTION ; @@ -509,7 +508,7 @@ variant test_release ; variant test_debug : debug : openssl on on - logging debug on + debug on full shared on on source multi ; @@ -772,10 +771,7 @@ lib torrent shared:BOOST_SYSTEM_SOURCE on:src/kademlia/$(KADEMLIA_SOURCES).cpp - logging:src/kademlia/$(KADEMLIA_SOURCES).cpp - on:ed25519/src/$(ED25519_SOURCES).cpp - logging:ed25519/src/$(ED25519_SOURCES).cpp @building @warnings diff --git a/include/libtorrent/aux_/session_impl.hpp b/include/libtorrent/aux_/session_impl.hpp index 1501e8821..f82332d00 100644 --- a/include/libtorrent/aux_/session_impl.hpp +++ b/include/libtorrent/aux_/session_impl.hpp @@ -568,8 +568,10 @@ 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, ...) + virtual void log(libtorrent::dht::dht_logger::module_t m, char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(3,4); + virtual void log_message(message_direction_t dir, char const* pkt, int len + , char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(5, 6); 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 50260cbdc..684aff2ea 100644 --- a/include/libtorrent/kademlia/dht_observer.hpp +++ b/include/libtorrent/kademlia/dht_observer.hpp @@ -41,7 +41,7 @@ namespace libtorrent { namespace dht { struct dht_logger { - enum dht_module_t + enum module_t { tracker, node, @@ -50,7 +50,17 @@ namespace libtorrent { namespace dht traversal }; - virtual void log(dht_module_t m, char const* fmt, ...) TORRENT_FORMAT(3,4) = 0; + enum message_direction_t + { + incoming_message, + outgoing_message, + incoming_message_error, + outgoing_message_error + }; + + virtual void log(module_t m, char const* fmt, ...) TORRENT_FORMAT(3,4) = 0; + virtual void log_message(message_direction_t dir, char const* pkt, int len + , char const* fmt, ...) TORRENT_FORMAT(5, 6) = 0; protected: ~dht_logger() {} diff --git a/include/libtorrent/kademlia/node.hpp b/include/libtorrent/kademlia/node.hpp index 748f80a44..856059dec 100644 --- a/include/libtorrent/kademlia/node.hpp +++ b/include/libtorrent/kademlia/node.hpp @@ -232,7 +232,7 @@ public: int data_size() const { return int(m_map.size()); } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING void print_state(std::ostream& os) const { m_table.print_state(os); } #endif diff --git a/include/libtorrent/kademlia/node_entry.hpp b/include/libtorrent/kademlia/node_entry.hpp index 39368544e..3d8500e78 100644 --- a/include/libtorrent/kademlia/node_entry.hpp +++ b/include/libtorrent/kademlia/node_entry.hpp @@ -60,7 +60,7 @@ struct TORRENT_EXTRA_EXPORT node_entry address addr() const { return address_v4(a); } int port() const { return p; } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING time_point first_seen; #endif diff --git a/include/libtorrent/kademlia/observer.hpp b/include/libtorrent/kademlia/observer.hpp index dca765871..a426f88ba 100644 --- a/include/libtorrent/kademlia/observer.hpp +++ b/include/libtorrent/kademlia/observer.hpp @@ -129,8 +129,8 @@ struct observer : boost::noncopyable flag_done = 128 }; -#ifndef TORRENT_DHT_VERBOSE_LOGGING - // TODO: 2 make this private and unconditional +#ifdef TORRENT_DISABLE_LOGGING + // TODO: 3 make this private and unconditional protected: #endif diff --git a/include/libtorrent/kademlia/routing_table.hpp b/include/libtorrent/kademlia/routing_table.hpp index 3800bb76b..8d00952af 100644 --- a/include/libtorrent/kademlia/routing_table.hpp +++ b/include/libtorrent/kademlia/routing_table.hpp @@ -175,7 +175,7 @@ public: void replacement_cache(bucket_t& nodes) const; -#if defined TORRENT_DHT_VERBOSE_LOGGING || defined TORRENT_DEBUG +#if defined TORRENT_DEBUG // used for debug and monitoring purposes. This will print out // the state of the routing table to the given stream void print_state(std::ostream& os) const; diff --git a/src/kademlia/dht_tracker.cpp b/src/kademlia/dht_tracker.cpp index 6b63d7f5f..09b6e32ff 100644 --- a/src/kademlia/dht_tracker.cpp +++ b/src/kademlia/dht_tracker.cpp @@ -79,7 +79,7 @@ namespace libtorrent { namespace dht { void incoming_error(entry& e, char const* msg); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING std::string parse_dht_client(bdecode_node const& e) { bdecode_node ver = e.dict_find_string("v"); @@ -161,7 +161,7 @@ namespace libtorrent { namespace dht , m_abort(false) , m_host_resolver(sock.get_io_service()) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_log->log(dht_logger::tracker, "starting DHT tracker with node id: %s" , to_hex(m_dht.nid().to_string()).c_str()); #endif @@ -260,12 +260,12 @@ namespace libtorrent { namespace dht { m_last_new_key = now; m_dht.new_write_key(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_log->log(dht_logger::tracker, "*** new write key***"); #endif } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#if defined TORRENT_DEBUG && TORRENT_USE_IOSTREAM std::ofstream st("dht_routing_table_state.txt", std::ios_base::trunc); m_dht.print_state(st); #endif @@ -410,18 +410,21 @@ namespace libtorrent { namespace dht int ret = bdecode(buf, buf + size, m_msg, err, &pos, 10, 500); if (ret != 0) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - m_log->log(dht_logger::tracker, "<== %s ERROR: %s pos: %d" - , print_endpoint(ep).c_str(), err.message().c_str(), int(pos)); +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::incoming_message_error, buf + , size, "%s ERROR: %s pos: %d" + , print_endpoint(ep).c_str(), err.message().c_str() + , int(pos)); #endif return false; } if (m_msg.type() != bdecode_node::dict_t) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING - m_log->log(dht_logger::tracker, "<== %s ERROR: not a dictionary %s" - , print_endpoint(ep).c_str(), print_entry(m_msg, true).c_str()); +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::incoming_message_error, buf + , size, "%s ERROR: not a dictionary" + , print_endpoint(ep).c_str()); #endif // it's not a good idea to send invalid messages // especially not in response to an invalid message @@ -431,6 +434,11 @@ namespace libtorrent { namespace dht return false; } +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::incoming_message, buf + , size, "%s", print_endpoint(ep).c_str()); +#endif + libtorrent::dht::msg m(m_msg, ep); m_dht.incoming(m); return true; @@ -517,25 +525,15 @@ namespace libtorrent { namespace dht bencode(std::back_inserter(m_send_buf), e); error_code ec; -#ifdef TORRENT_DHT_VERBOSE_LOGGING - // 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); - 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)) { if (ec) { m_counters.inc_stats_counter(counters::dht_messages_out_dropped); -#ifdef TORRENT_DHT_VERBOSE_LOGGING - m_log->log(dht_logger::tracker, "==> %s DROPPED (%s) %s" - , print_endpoint(addr).c_str(), ec.message().c_str() - , outgoing_message.c_str()); +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), "%s DROPPED (%s)" + , print_endpoint(addr).c_str(), ec.message().c_str()); #endif return false; } @@ -545,10 +543,10 @@ namespace libtorrent { namespace dht m_counters.inc_stats_counter(counters::sent_ip_overhead_bytes , addr.address().is_v6() ? 48 : 28); m_counters.inc_stats_counter(counters::dht_messages_out); -#ifdef TORRENT_DHT_VERBOSE_LOGGING - m_log->log(dht_logger::tracker, "==> %s %s" - , print_endpoint(addr).c_str() - , outgoing_message.c_str()); +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), "%s" + , print_endpoint(addr).c_str()); #endif return true; } @@ -556,10 +554,10 @@ namespace libtorrent { namespace dht { m_counters.inc_stats_counter(counters::dht_messages_out_dropped); -#ifdef TORRENT_DHT_VERBOSE_LOGGING - m_log->log(dht_logger::tracker, "==> %s DROPPED %s" - , print_endpoint(addr).c_str() - , outgoing_message.c_str()); +#ifndef TORRENT_DISABLE_LOGGING + m_log->log_message(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), "%s" + , print_endpoint(addr).c_str()); #endif return false; } diff --git a/src/kademlia/dos_blocker.cpp b/src/kademlia/dos_blocker.cpp index 90006c77e..707a0de2e 100644 --- a/src/kademlia/dos_blocker.cpp +++ b/src/kademlia/dos_blocker.cpp @@ -32,7 +32,7 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/kademlia/dos_blocker.hpp" -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING #include "libtorrent/socket_io.hpp" // for print_address #include "libtorrent/kademlia/dht_observer.hpp" // for dht_logger #endif @@ -76,7 +76,7 @@ namespace libtorrent { namespace dht { if (match->count == m_message_rate_limit * 10) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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 diff --git a/src/kademlia/find_data.cpp b/src/kademlia/find_data.cpp index 82176d429..def9184b2 100644 --- a/src/kademlia/find_data.cpp +++ b/src/kademlia/find_data.cpp @@ -52,7 +52,7 @@ void find_data_observer::reply(msg const& m) bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" , m_algorithm.get()); #endif @@ -62,7 +62,7 @@ void find_data_observer::reply(msg const& m) bdecode_node id = r.dict_find_string("id"); if (!id || id.string_length() != 20) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" , m_algorithm.get()); #endif @@ -111,7 +111,7 @@ void find_data::start() void find_data::got_write_token(node_id const& n, std::string const& write_token) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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 @@ -136,7 +136,7 @@ void find_data::done() m_done = true; -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] %s DONE" , this, name()); #endif @@ -149,7 +149,7 @@ void find_data::done() observer_ptr const& o = *i; if ((o->flags & observer::flag_alive) == 0) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] not alive: %s" , this, print_endpoint(o->target_ep()).c_str()); #endif @@ -158,14 +158,14 @@ void find_data::done() std::map::iterator j = m_write_tokens.find(o->id()); if (j == m_write_tokens.end()) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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 +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] %s" , this, print_endpoint(o->target_ep()).c_str()); #endif diff --git a/src/kademlia/get_item.cpp b/src/kademlia/get_item.cpp index 1a51765b1..5c09d2625 100644 --- a/src/kademlia/get_item.cpp +++ b/src/kademlia/get_item.cpp @@ -198,7 +198,7 @@ void get_item::done() // as the v argument void get_item::put(std::vector > const& v) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING // 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 ]" @@ -215,7 +215,7 @@ void get_item::put(std::vector > const& v) for (std::vector >::const_iterator i = v.begin() , end(v.end()); i != end; ++i) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] put-distance: %d" , this, 160 - distance_exp(m_target, i->first.id)); #endif @@ -257,7 +257,7 @@ void get_item_observer::reply(msg const& m) bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" , m_algorithm.get()); #endif diff --git a/src/kademlia/get_peers.cpp b/src/kademlia/get_peers.cpp index 79cde5431..4c856b872 100644 --- a/src/kademlia/get_peers.cpp +++ b/src/kademlia/get_peers.cpp @@ -50,7 +50,7 @@ void get_peers_observer::reply(msg const& m) bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" , m_algorithm.get()); #endif @@ -68,7 +68,7 @@ void get_peers_observer::reply(msg const& m) char const* peers = n.list_at(0).string_ptr(); char const* end = peers + n.list_at(0).string_length(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING bdecode_node id = r.dict_find_string("id"); if (id && id.string_length() == 20) { @@ -90,7 +90,7 @@ void get_peers_observer::reply(msg const& m) { // assume it's uTorrent/libtorrent format read_endpoint_list(n, peer_list); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING bdecode_node id = r.dict_find_string("id"); if (id && id.string_length() == 20) { @@ -276,7 +276,7 @@ void obfuscated_get_peers::done() m_data_callback.clear(); m_nodes_callback.clear(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] obfuscated get_peers " "phase 1 done, spawning get_peers [ %p ]" , this, ta.get()); @@ -307,7 +307,7 @@ void obfuscated_get_peers_observer::reply(msg const& m) bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict" , m_algorithm.get()); #endif @@ -317,7 +317,7 @@ void obfuscated_get_peers_observer::reply(msg const& m) bdecode_node id = r.dict_find_string("id"); if (!id || id.string_length() != 20) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" , m_algorithm.get()); #endif diff --git a/src/kademlia/node.cpp b/src/kademlia/node.cpp index e2f9a8c99..03969dbe5 100644 --- a/src/kademlia/node.cpp +++ b/src/kademlia/node.cpp @@ -124,7 +124,7 @@ bool node::verify_token(std::string const& token, char const* info_hash { if (token.length() != 4) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_observer->log(dht_logger::node, "token of incorrect length: %d" , token.length()); #endif @@ -180,14 +180,14 @@ void node::bootstrap(std::vector const& nodes boost::intrusive_ptr r(new dht::bootstrap(*this, target, f)); m_last_self_refresh = aux::time_now(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING int count = 0; #endif for (std::vector::const_iterator i = nodes.begin() , end(nodes.end()); i != end; ++i) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING ++count; #endif r->add_entry(node_id(0), *i, observer::flag_initial); @@ -196,7 +196,7 @@ void node::bootstrap(std::vector const& nodes // make us start as far away from our node ID as possible r->trim_seed_nodes(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_observer->log(dht_logger::node, "bootstrapping with %d nodes", count); #endif r->start(); @@ -282,7 +282,7 @@ void node::incoming(msg const& m) } case 'e': { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING bdecode_node err = m.message.dict_find_list("e"); if (err && err.list_size() >= 2) { @@ -302,7 +302,7 @@ namespace void announce_fun(std::vector > const& v , node& node, int listen_port, sha1_hash const& ih, int flags) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_ih[41]; to_hex(reinterpret_cast(&ih[0]), 20, hex_ih); node.observer()->log(dht_logger::node, "sending announce_peer [ ih: %s " @@ -317,7 +317,7 @@ namespace for (std::vector >::const_iterator i = v.begin() , end(v.end()); i != end; ++i) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING node.observer()->log(dht_logger::node, "announce-distance: %d" , (160 - distance_exp(ih, i->first.id))); #endif @@ -345,7 +345,7 @@ namespace void node::add_router_node(udp::endpoint router) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_observer->log(dht_logger::node, "adding router node: %s" , print_endpoint(router).c_str()); #endif @@ -362,7 +362,7 @@ void node::add_node(udp::endpoint node) void node::announce(sha1_hash const& info_hash, int listen_port, int flags , boost::function const&)> f) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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 ]" @@ -391,7 +391,7 @@ void node::announce(sha1_hash const& info_hash, int listen_port, int flags void node::get_item(sha1_hash const& target , boost::function f) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_target[41]; to_hex(reinterpret_cast(&target[0]), 20, hex_target); m_observer->log(dht_logger::node, "starting get for [ hash: %s ]" @@ -406,7 +406,7 @@ void node::get_item(sha1_hash const& target void node::get_item(char const* pk, std::string const& salt , boost::function f) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_key[65]; to_hex(pk, 32, hex_key); m_observer->log(dht_logger::node, "starting get for [ key: %s ]", hex_key); @@ -433,7 +433,7 @@ struct ping_observer : observer bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::node , "[%p] missing response dict" , m_algorithm.get()); @@ -899,7 +899,7 @@ void node::incoming_request(msg const& m, entry& e) if (msg_keys[1] && msg_keys[1].int_value() != 0) noseed = true; if (msg_keys[2] && msg_keys[2].int_value() != 0) scrape = true; lookup_peers(info_hash, reply, noseed, scrape); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING if (reply.find_key("values")) { m_observer->log(dht_logger::node, "values: %d" diff --git a/src/kademlia/node_entry.cpp b/src/kademlia/node_entry.cpp index 71a5a952d..32a7d7902 100644 --- a/src/kademlia/node_entry.cpp +++ b/src/kademlia/node_entry.cpp @@ -46,7 +46,7 @@ namespace libtorrent { namespace dht , rtt(roundtriptime & 0xffff) , timeout_count(pinged ? 0 : 0xff) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING first_seen = aux::time_now(); #endif } @@ -59,7 +59,7 @@ namespace libtorrent { namespace dht , rtt(0xffff) , timeout_count(0xff) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING first_seen = aux::time_now(); #endif } @@ -71,7 +71,7 @@ namespace libtorrent { namespace dht , rtt(0xffff) , timeout_count(0xff) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING first_seen = aux::time_now(); #endif } diff --git a/src/kademlia/refresh.cpp b/src/kademlia/refresh.cpp index 898a0c158..44aaef047 100644 --- a/src/kademlia/refresh.cpp +++ b/src/kademlia/refresh.cpp @@ -87,7 +87,7 @@ void bootstrap::trim_seed_nodes() void bootstrap::done() { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] bootstrap done, pinging remaining nodes" , this); #endif diff --git a/src/kademlia/routing_table.cpp b/src/kademlia/routing_table.cpp index 172322b9c..f4278cc5d 100644 --- a/src/kademlia/routing_table.cpp +++ b/src/kademlia/routing_table.cpp @@ -197,7 +197,7 @@ int routing_table::depth() const return m_depth; } -#if (defined TORRENT_DHT_VERBOSE_LOGGING || defined TORRENT_DEBUG) && TORRENT_USE_IOSTREAM +#if defined TORRENT_DEBUG && TORRENT_USE_IOSTREAM void routing_table::print_state(std::ostream& os) const { @@ -585,7 +585,7 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) // routing table if (m_settings.restrict_routing_ips) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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" @@ -668,7 +668,7 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) // we already have a node in this bucket with an IP very // 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 +#ifndef TORRENT_DISABLE_LOGGING char hex_id1[41]; to_hex(reinterpret_cast(&e.id[0]), 20, hex_id1); char hex_id2[41]; @@ -684,7 +684,7 @@ routing_table::add_node_status_t routing_table::add_node_impl(node_entry e) if (j != rb.end()) { // same thing but for the replacement bucket -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_id1[41]; to_hex(reinterpret_cast(&e.id[0]), 20, hex_id1); char hex_id2[41]; @@ -864,7 +864,7 @@ 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()); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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" @@ -1037,7 +1037,7 @@ void routing_table::node_failed(node_id const& nid, udp::endpoint const& ep) j->timed_out(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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" @@ -1058,7 +1058,7 @@ void routing_table::node_failed(node_id const& nid, udp::endpoint const& ep) { j->timed_out(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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" diff --git a/src/kademlia/rpc_manager.cpp b/src/kademlia/rpc_manager.cpp index 36b913c52..7fa361a8c 100644 --- a/src/kademlia/rpc_manager.cpp +++ b/src/kademlia/rpc_manager.cpp @@ -57,7 +57,7 @@ POSSIBILITY OF SUCH DAMAGE. #include #include // for aux::time_now -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING #include #endif @@ -222,7 +222,7 @@ void rpc_manager::check_invariant() const void rpc_manager::unreachable(udp::endpoint const& ep) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_log->log(dht_logger::rpc_manager, "PORT_UNREACHABLE [ ip: %s ]" , print_endpoint(ep).c_str()); #endif @@ -235,7 +235,7 @@ void rpc_manager::unreachable(udp::endpoint const& ep) if (o->target_ep() != ep) { ++i; continue; } observer_ptr ptr = i->second; i = m_transactions.erase(i); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_log->log(dht_logger::rpc_manager, "found transaction [ tid: %d ]" , int(ptr->transaction_id())); #endif @@ -276,7 +276,7 @@ bool rpc_manager::incoming(msg const& m, node_id* id if (!o) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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 @@ -293,7 +293,7 @@ bool rpc_manager::incoming(msg const& m, node_id* id time_point now = clock_type::now(); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING std::ofstream reply_stats("round_trip_ms.log", std::ios::app); reply_stats << m.addr << "\t" << total_milliseconds(now - o->sent()) << std::endl; @@ -334,7 +334,7 @@ bool rpc_manager::incoming(msg const& m, node_id* id return false; } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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()); @@ -374,7 +374,7 @@ time_duration rpc_manager::tick() time_duration diff = now - o->sent(); if (diff >= seconds(timeout)) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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()); @@ -388,7 +388,7 @@ time_duration rpc_manager::tick() // already called it once if (diff >= seconds(short_timeout) && !o->has_short_timeout()) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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()); @@ -435,7 +435,7 @@ bool rpc_manager::invoke(entry& e, udp::endpoint target_addr o->set_target(target_addr); o->set_transaction_id(tid); -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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()); diff --git a/src/kademlia/traversal_algorithm.cpp b/src/kademlia/traversal_algorithm.cpp index def5ed652..737144d68 100644 --- a/src/kademlia/traversal_algorithm.cpp +++ b/src/kademlia/traversal_algorithm.cpp @@ -89,7 +89,7 @@ traversal_algorithm::traversal_algorithm( , m_responses(0) , m_timeouts(0) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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" @@ -117,7 +117,7 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig void* ptr = m_node.m_rpc.allocate_observer(); if (ptr == 0) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] failed to allocate memory or observer. aborting!" , this); #endif @@ -167,7 +167,7 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig // we already have a node in this search with an IP very // 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 +#ifndef TORRENT_DISABLE_LOGGING char hex_id[41]; to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); get_node().observer()->log(dht_logger::traversal @@ -182,7 +182,7 @@ 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 +#ifndef TORRENT_DISABLE_LOGGING char hex_id[41]; to_hex(reinterpret_cast(&id[0]), 20, hex_id); get_node().observer()->log(dht_logger::traversal @@ -238,7 +238,7 @@ char const* traversal_algorithm::name() const void traversal_algorithm::traverse(node_id const& id, udp::endpoint addr) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING if (id.is_all_zeros()) { get_node().observer()->log(dht_logger::traversal @@ -304,7 +304,7 @@ void traversal_algorithm::failed(observer_ptr o, int flags) if ((o->flags & observer::flag_short_timeout) == 0) ++m_branch_factor; o->flags |= observer::flag_short_timeout; -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_id[41]; to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); get_node().observer()->log(dht_logger::traversal @@ -323,7 +323,7 @@ void traversal_algorithm::failed(observer_ptr o, int flags) if (o->flags & observer::flag_short_timeout) --m_branch_factor; -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_id[41]; to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); get_node().observer()->log(dht_logger::traversal @@ -350,7 +350,7 @@ void traversal_algorithm::failed(observer_ptr o, int flags) void traversal_algorithm::done() { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING int results_target = m_node.m_table.bucket_size(); int closest_target = 160; @@ -433,7 +433,7 @@ bool traversal_algorithm::add_requests() continue; } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING char hex_id[41]; to_hex(reinterpret_cast(&o->id()[0]), 20, hex_id); get_node().observer()->log(dht_logger::traversal @@ -468,7 +468,7 @@ bool traversal_algorithm::add_requests() void traversal_algorithm::add_router_entries() { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING 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()))); @@ -523,7 +523,7 @@ void traversal_observer::reply(msg const& m) bdecode_node r = m.message.dict_find_dict("r"); if (!r) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal , "[%p] missing response dict" , m_algorithm.get()); @@ -531,7 +531,7 @@ void traversal_observer::reply(msg const& m) return; } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING bdecode_node nid = r.dict_find_string("id"); char hex_id[41]; to_hex(nid.string_ptr(), 20, hex_id); @@ -559,7 +559,7 @@ void traversal_observer::reply(msg const& m) bdecode_node id = r.dict_find_string("id"); if (!id || id.string_length() != 20) { -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response" , m_algorithm.get(), m_algorithm->name()); #endif @@ -581,7 +581,7 @@ void traversal_algorithm::abort() o.flags |= observer::flag_done; } -#ifdef TORRENT_DHT_VERBOSE_LOGGING +#ifndef TORRENT_DISABLE_LOGGING get_node().observer()->log(dht_logger::traversal, "[%p] ABORTED type: %s" , this, name()); #endif diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 50f16ce05..801f69741 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -6473,7 +6473,7 @@ retry: } TORRENT_FORMAT(3,4) - void session_impl::log(libtorrent::dht::dht_logger::dht_module_t m, char const* fmt, ...) + void session_impl::log(libtorrent::dht::dht_logger::module_t m, char const* fmt, ...) { if (!m_alerts.should_post()) return; @@ -6485,6 +6485,34 @@ retry: m_alerts.emplace_alert((dht_log_alert::dht_module_t)m, buf); } + TORRENT_FORMAT(5, 6) + void session_impl::log_message(message_direction_t dir, char const* pkt, int len + , char const* fmt, ...) + { + if (!m_alerts.should_post()) return; + + char buf[1024]; + int offset = 0; + char const* prefix[] = + { "<== ", "<== ERROR ", "==> ", "==> ERROR " }; + offset += snprintf(&buf[offset], sizeof(buf) - offset, prefix[dir]); + + va_list v; + va_start(v, fmt); + offset += vsnprintf(&buf[offset], sizeof(buf) - offset, fmt, v); + va_end(v); + + bdecode_node print; + error_code ec; + int ret = bdecode(buf, buf + len, print, ec, NULL, 100, 100); + + std::string msg = print_entry(print, true); + + strncpy(&buf[offset], msg.c_str(), sizeof(buf) - offset); + + m_alerts.emplace_alert(dht_log_alert::tracker, buf); + } + void session_impl::set_external_address(address const& ip , int source_type, address const& source) { diff --git a/test/test_dht.cpp b/test/test_dht.cpp index 97136dace..fbd99ffb4 100644 --- a/test/test_dht.cpp +++ b/test/test_dht.cpp @@ -433,7 +433,9 @@ struct obs : dht::dht_observer virtual void outgoing_get_peers(sha1_hash const& target , sha1_hash const& sent_target, udp::endpoint const& ep) TORRENT_OVERRIDE {} virtual void announce(sha1_hash const& ih, address const& addr, int port) TORRENT_OVERRIDE {} - virtual void log(dht_logger::dht_module_t l, char const* fmt, ...) TORRENT_OVERRIDE {} + virtual void log(dht_logger::module_t l, char const* fmt, ...) TORRENT_OVERRIDE {} + virtual void log_message(message_direction_t dir, char const* pkt, int len + , char const* fmt, ...) TORRENT_OVERRIDE {} }; // TODO: test obfuscated_get_peers diff --git a/test/test_dos_blocker.cpp b/test/test_dos_blocker.cpp index a215011bc..80beb8638 100644 --- a/test/test_dos_blocker.cpp +++ b/test/test_dos_blocker.cpp @@ -36,16 +36,38 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/time.hpp" #include "libtorrent/kademlia/dos_blocker.hpp" #include "libtorrent/kademlia/dht_observer.hpp" +#include "libtorrent/error_code.hpp" struct log_t : libtorrent::dht::dht_logger { - virtual void log(dht_logger::dht_module_t m, char const* fmt, ...) + virtual void log(dht_logger::module_t m, char const* fmt, ...) + TORRENT_OVERRIDE TORRENT_FORMAT(3, 4) { va_list v; va_start(v, fmt); vfprintf(stderr, fmt, v); va_end(v); } + + virtual void log_message(message_direction_t dir, char const* pkt, int len + , char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(5, 6) + { + char const* prefix[] = + { "<== ", "<== ERROR ", "==> ", "==> ERROR " }; + printf(prefix[dir]); + + va_list v; + va_start(v, fmt); + vprintf(fmt, v); + va_end(v); + + libtorrent::bdecode_node print; + libtorrent::error_code ec; + int ret = bdecode(pkt, pkt + len, print, ec, NULL, 100, 100); + + std::string msg = print_entry(print, true); + printf("%s", msg.c_str()); + } }; int test_main()