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

@@ -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 };
 }
 
 

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
+			virtual void log_packet(message_direction_t dir, char const* pkt, int len
-				, char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(5, 6);
+				, udp::endpoint node) TORRENT_OVERRIDE;
 
 			void set_external_address(address const& ip
 				, int source_type, address const& source);

include/libtorrent/kademlia/dht_observer.hpp

@@ -53,14 +53,12 @@ namespace libtorrent { namespace dht
 		enum message_direction_t
 		{
 			incoming_message,
-			outgoing_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
+		virtual void log_packet(message_direction_t dir, char const* pkt, int len
-			, char const* fmt, ...) TORRENT_FORMAT(5, 6) = 0;
+			, udp::endpoint node) = 0;
 
 	protected:
 		~dht_logger() {}

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());

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
 

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
+			m_log->log_packet(dht_logger::incoming_message, buf, size, ep);
-				, size, "%s ERROR: %s pos: %d"
-				, print_endpoint(ep).c_str(), err.message().c_str()
-				, int(pos));
 #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
+			m_log->log_packet(dht_logger::incoming_message, buf, size, ep);
-				, 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
@@ -427,8 +422,8 @@ namespace libtorrent { namespace dht
 		}
 
 #ifndef TORRENT_DISABLE_LOGGING
-		m_log->log_message(dht_logger::incoming_message, buf
+		m_log->log_packet(dht_logger::incoming_message, buf
-			, size, "%s", print_endpoint(ep).c_str());
+			, 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_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0]
-					, m_send_buf.size(), "%s DROPPED (%s)"
+					, m_send_buf.size(), addr);
-					, print_endpoint(addr).c_str(), ec.message().c_str());
 #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_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0]
-				, m_send_buf.size(), "%s"
+				, m_send_buf.size(), addr);
-				, print_endpoint(addr).c_str());
 #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_log->log_packet(dht_logger::outgoing_message, &m_send_buf[0]
-				, m_send_buf.size(), "%s"
+				, m_send_buf.size(), addr);
-				, print_endpoint(addr).c_str());
 #endif
 			return false;
 		}

src/session_impl.cpp

@@ -6493,43 +6493,15 @@ retry:
 		m_alerts.emplace_alert<dht_log_alert>((dht_log_alert::dht_module_t)m, buf);
 	}
 
-	TORRENT_FORMAT(5, 6)
+	void session_impl::log_packet(message_direction_t dir, char const* pkt, int len
-	void session_impl::log_message(message_direction_t dir, char const* pkt, int len
+		, udp::endpoint node)
-		, char const* fmt, ...)
 	{
-		if (!m_alerts.should_post<dht_log_alert>()) return;
+		if (!m_alerts.should_post<dht_pkt_alert>()) return;
 
-		char buf[1024];
+		dht_pkt_alert::direction_t d = dir == dht_logger::incoming_message
-		int offset = 0;
+			? dht_pkt_alert::incoming : dht_pkt_alert::outgoing;
-		char const* prefix[] =
-		{ "<== ", "==> ", "<== ERROR ", "==> ERROR " };
-		offset += snprintf(&buf[offset], sizeof(buf) - offset, prefix[dir]);
 
-		va_list v;
+		m_alerts.emplace_alert<dht_pkt_alert>(pkt, len, d, node);
-		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>(dht_log_alert::tracker, buf);
 	}
 
 	void session_impl::set_external_address(address const& ip

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
+	virtual void log_packet(message_direction_t dir, char const* pkt, int len
-		, char const* fmt, ...) TORRENT_OVERRIDE {}
+		, udp::endpoint node) TORRENT_OVERRIDE {}
 };
 
 // TODO: test obfuscated_get_peers

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
+	virtual void log_packet(message_direction_t dir, char const* pkt, int len
-		, char const* fmt, ...) TORRENT_OVERRIDE TORRENT_FORMAT(5, 6)
+		, 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;