From e44c8e90020eae6886c0a77ededfed9cef5df4b7 Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Thu, 28 May 2015 20:36:22 +0000 Subject: [PATCH] optimize logging of DHT packets by deferring copying and printing, to only do it if the alert category is enabled --- include/libtorrent/alert_types.hpp | 38 ++++++++++++++++++- include/libtorrent/aux_/session_impl.hpp | 4 +- include/libtorrent/kademlia/dht_observer.hpp | 8 ++-- include/libtorrent/stack_allocator.hpp | 10 ++++- src/alert.cpp | 38 +++++++++++++++++++ src/kademlia/dht_tracker.cpp | 32 ++++++---------- src/session_impl.cpp | 40 +++----------------- test/test_dht.cpp | 4 +- test/test_dos_blocker.cpp | 23 +++++------ 9 files changed, 119 insertions(+), 78 deletions(-) diff --git a/include/libtorrent/alert_types.hpp b/include/libtorrent/alert_types.hpp index fb8f8a691..4c86614e0 100644 --- a/include/libtorrent/alert_types.hpp +++ b/include/libtorrent/alert_types.hpp @@ -2319,12 +2319,48 @@ namespace libtorrent int m_msg_idx; }; + // This alert is posted every time a DHT message is sent or received. It is + // only posted if the ``alert::dht_log_notification`` alert category is + // enabled. It contains a verbatim copy of the message. + struct TORRENT_EXPORT dht_pkt_alert : alert + { + enum direction_t + { incoming, outgoing }; + + dht_pkt_alert(aux::stack_allocator& alloc, char const* buf, int size + , dht_pkt_alert::direction_t d, udp::endpoint ep); + + static const int static_category = alert::dht_log_notification; + TORRENT_DEFINE_ALERT(dht_pkt_alert, 86) + + virtual std::string message() const; + + // returns a pointer to the packet buffer and size of the packet, + // respectively. This buffer is only valid for as long as the alert itself + // is valid, which is owned by libtorrent and reclaimed whenever + // pop_alerts() is called on the session. + char const* pkt_buf() const; + int pkt_size() const; + + // whether this is an incoming or outgoing packet. + direction_t dir; + + // the DHT node we received this packet from, or sent this packet to + // (depending on ``dir``). + udp::endpoint node; + + private: + aux::stack_allocator& m_alloc; + int m_msg_idx; + int m_size; + }; + #undef TORRENT_DEFINE_ALERT_IMPL #undef TORRENT_DEFINE_ALERT #undef TORRENT_DEFINE_ALERT_PRIO #undef TORRENT_CLONE - enum { num_alert_types = 86 }; + enum { num_alert_types = 87 }; } diff --git a/include/libtorrent/aux_/session_impl.hpp b/include/libtorrent/aux_/session_impl.hpp index 9310b3a9d..7c2f22411 100644 --- a/include/libtorrent/aux_/session_impl.hpp +++ b/include/libtorrent/aux_/session_impl.hpp @@ -566,8 +566,8 @@ namespace libtorrent , sha1_hash const& sent_target, udp::endpoint const& ep) TORRENT_OVERRIDE; 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); + virtual void log_packet(message_direction_t dir, char const* pkt, int len + , udp::endpoint node) 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 684aff2ea..b09bcd2cd 100644 --- a/include/libtorrent/kademlia/dht_observer.hpp +++ b/include/libtorrent/kademlia/dht_observer.hpp @@ -53,14 +53,12 @@ namespace libtorrent { namespace dht enum message_direction_t { incoming_message, - outgoing_message, - incoming_message_error, - outgoing_message_error + outgoing_message }; 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; + virtual void log_packet(message_direction_t dir, char const* pkt, int len + , udp::endpoint node) = 0; protected: ~dht_logger() {} diff --git a/include/libtorrent/stack_allocator.hpp b/include/libtorrent/stack_allocator.hpp index 7b147f3fc..23d8335f8 100644 --- a/include/libtorrent/stack_allocator.hpp +++ b/include/libtorrent/stack_allocator.hpp @@ -41,7 +41,7 @@ namespace libtorrent { namespace aux struct stack_allocator { stack_allocator() {} - + int copy_string(std::string const& str) { int ret = int(m_storage.size()); @@ -59,6 +59,14 @@ namespace libtorrent { namespace aux return ret; } + int copy_buffer(char const* buf, int size) + { + int ret = int(m_storage.size()); + m_storage.resize(ret + size); + memcpy(&m_storage[ret], buf, size); + return ret; + } + int allocate(int bytes) { int ret = int(m_storage.size()); diff --git a/src/alert.cpp b/src/alert.cpp index 80806f430..c749b0ff5 100644 --- a/src/alert.cpp +++ b/src/alert.cpp @@ -1739,5 +1739,43 @@ namespace libtorrent { return ret; } + dht_pkt_alert::dht_pkt_alert(aux::stack_allocator& alloc + , char const* buf, int size, dht_pkt_alert::direction_t d, udp::endpoint ep) + : dir(d) + , node(ep) + , m_alloc(alloc) + , m_msg_idx(alloc.copy_buffer(buf, size)) + , m_size(size) + {} + + char const* dht_pkt_alert::pkt_buf() const + { + return m_alloc.ptr(m_msg_idx); + } + + int dht_pkt_alert::pkt_size() const + { + return m_size; + } + + std::string dht_pkt_alert::message() const + { + bdecode_node print; + error_code ec; + + // ignore errors here. This is best-effort. It may be a broken encoding + // but at least we'll print the valid parts + bdecode(pkt_buf(), pkt_buf() + pkt_size(), print, ec, NULL, 100, 100); + + std::string msg = print_entry(print, true); + + char const* prefix[2] = { "<==", "==>"}; + char buf[1024]; + snprintf(buf, sizeof(buf), "%s [%s] %s", prefix[dir] + , print_endpoint(node).c_str(), msg.c_str()); + + return buf; + } + } // namespace libtorrent diff --git a/src/kademlia/dht_tracker.cpp b/src/kademlia/dht_tracker.cpp index 09e636827..f1ca93e95 100644 --- a/src/kademlia/dht_tracker.cpp +++ b/src/kademlia/dht_tracker.cpp @@ -394,7 +394,7 @@ namespace libtorrent { namespace dht using libtorrent::entry; using libtorrent::bdecode; - + TORRENT_ASSERT(size > 0); int pos; @@ -403,10 +403,7 @@ namespace libtorrent { namespace dht if (ret != 0) { #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)); + m_log->log_packet(dht_logger::incoming_message, buf, size, ep); #endif return false; } @@ -414,9 +411,7 @@ namespace libtorrent { namespace dht if (m_msg.type() != bdecode_node::dict_t) { #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()); + m_log->log_packet(dht_logger::incoming_message, buf, size, ep); #endif // it's not a good idea to send invalid messages // especially not in response to an invalid message @@ -427,8 +422,8 @@ namespace libtorrent { namespace dht } #ifndef TORRENT_DISABLE_LOGGING - m_log->log_message(dht_logger::incoming_message, buf - , size, "%s", print_endpoint(ep).c_str()); + m_log->log_packet(dht_logger::incoming_message, buf + , size, ep); #endif libtorrent::dht::msg m(m_msg, ep); @@ -448,7 +443,7 @@ namespace libtorrent { namespace dht } } // anonymous namespace - + entry dht_tracker::state() const { entry ret(entry::dictionary_t); @@ -523,9 +518,8 @@ namespace libtorrent { namespace dht { m_counters.inc_stats_counter(counters::dht_messages_out_dropped); #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()); + m_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), addr); #endif return false; } @@ -536,9 +530,8 @@ namespace libtorrent { namespace dht , addr.address().is_v6() ? 48 : 28); m_counters.inc_stats_counter(counters::dht_messages_out); #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()); + m_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), addr); #endif return true; } @@ -547,9 +540,8 @@ namespace libtorrent { namespace dht m_counters.inc_stats_counter(counters::dht_messages_out_dropped); #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()); + m_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0] + , m_send_buf.size(), addr); #endif return false; } diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 1f042f45c..1b2dbcb5d 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -6493,43 +6493,15 @@ 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, ...) + void session_impl::log_packet(message_direction_t dir, char const* pkt, int len + , udp::endpoint node) { - if (!m_alerts.should_post()) return; + 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]); + dht_pkt_alert::direction_t d = dir == dht_logger::incoming_message + ? dht_pkt_alert::incoming : dht_pkt_alert::outgoing; - va_list v; - va_start(v, fmt); - offset += vsnprintf(&buf[offset], sizeof(buf) - offset, fmt, v); - va_end(v); - - if (offset < sizeof(buf) - 1) - { - buf[offset++] = ' '; - - bdecode_node print; - error_code ec; - - // ignore errors here. This is best-effort. It may be a broken encoding - // but at least we'll print the valid parts - bdecode(pkt, pkt + len, print, ec, NULL, 100, 100); - - // TODO: 3 there should be a separate dht_log_alert for messages that - // contains the raw packet separately. This printing should be moved - // down to the ::message() function of that alert - 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); + m_alerts.emplace_alert(pkt, len, d, node); } void session_impl::set_external_address(address const& ip diff --git a/test/test_dht.cpp b/test/test_dht.cpp index fbd99ffb4..ff128166f 100644 --- a/test/test_dht.cpp +++ b/test/test_dht.cpp @@ -434,8 +434,8 @@ struct obs : dht::dht_observer , 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::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 {} + virtual void log_packet(message_direction_t dir, char const* pkt, int len + , udp::endpoint node) TORRENT_OVERRIDE {} }; // TODO: test obfuscated_get_peers diff --git a/test/test_dos_blocker.cpp b/test/test_dos_blocker.cpp index 80beb8638..9d19f3e3b 100644 --- a/test/test_dos_blocker.cpp +++ b/test/test_dos_blocker.cpp @@ -37,43 +37,40 @@ POSSIBILITY OF SUCH DAMAGE. #include "libtorrent/kademlia/dos_blocker.hpp" #include "libtorrent/kademlia/dht_observer.hpp" #include "libtorrent/error_code.hpp" +#include "libtorrent/socket_io.hpp" // for print_endpoint + +using namespace libtorrent; struct log_t : libtorrent::dht::dht_logger { virtual void log(dht_logger::module_t m, char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(3, 4) { - va_list v; + 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) + virtual void log_packet(message_direction_t dir, char const* pkt, int len + , udp::endpoint node) TORRENT_OVERRIDE { - 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()); + + char const* prefix[2] = { "<==", "==>"}; + printf("%s [%s] %s", prefix[dir], print_endpoint(node).c_str() + , msg.c_str()); } }; int test_main() { #ifndef TORRENT_DISABLE_DHT - using namespace libtorrent; using namespace libtorrent::dht; log_t l;