turn DHT logging into alerts instead of writing to a file

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

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

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

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

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

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<char> m_send_buf;
 		dos_blocker m_blocker;

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)
 		{

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
 
+*/
+
+

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;
 

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
 

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<node_entry> bucket_t;
 
 struct routing_table_node
@@ -94,7 +90,8 @@ public:
 	typedef std::vector<routing_table_node> 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();

include/libtorrent/kademlia/rpc_manager.hpp

@@ -65,10 +65,7 @@ namespace libtorrent { struct dht_settings; }
 namespace libtorrent { namespace dht
 {
 
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
+struct dht_logger;
-TORRENT_DECLARE_LOG(rpc);
-#endif
-
 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;

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;

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
 

src/kademlia/dht_tracker.cpp

@@ -33,6 +33,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include <set>
 #include <numeric>
 #include <boost/bind.hpp>
+#include <boost/function/function0.hpp>
 #include <boost/ref.hpp>
 
 #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
+		m_log->log(dht_logger::tracker, "starting DHT tracker with node id: %s"
-
+			, to_hex(m_dht.nid().to_string()).c_str());
-//		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();
 #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: "
+			m_log->log(dht_logger::tracker, "<== %s ERROR: %s pos: %d"
-				<< err.message() << " pos: " << pos;
+				, 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: "
+			m_log->log(dht_logger::tracker, "<== %s ERROR: not a dictionary %s"
-				<< print_entry(m_msg, true);
+				, 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;
 		}

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: "
+						logger->log(dht_logger::tracker, "BANNING PEER [ ip: %s time: %f count: %d ]"
-							<< addr << " time: " << total_milliseconds((now - match->limit) + seconds(10)) / 1000.f
+							, print_address(addr).c_str()
-							<< " count: " << match->count << " ]";
+							, 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

src/kademlia/find_data.cpp

@@ -32,6 +32,7 @@ POSSIBILITY OF SUCH DAMAGE.
 
 #include <libtorrent/kademlia/find_data.hpp>
 #include <libtorrent/kademlia/node.hpp>
+#include <libtorrent/kademlia/dht_observer.hpp>
 #include <libtorrent/io.hpp>
 #include <libtorrent/socket.hpp>
 #include <libtorrent/socket_io.hpp>
@@ -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 "
+	get_node().observer()->log(dht_logger::traversal, "[%p] adding write token '%s' under id '%s'"
-		"token '" << to_hex(write_token) << "' under id '" << to_hex(n.to_string()) << "'";
+		, 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<std::pair<node_entry, std::string> > 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: "
+			get_node().observer()->log(dht_logger::traversal, "[%p] not alive: %s"
-				<< o->target_ep();
+				, 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: "
+			get_node().observer()->log(dht_logger::traversal, "[%p] no write token: %s"
-				<< o->target_ep();
+				, 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 << "]     "
+			get_node().observer()->log(dht_logger::traversal, "[%p] %s"
-				<< o->target_ep();
+				, this, print_endpoint(o->target_ep()).c_str());
 #endif
 		--num_results;
 	}

src/kademlia/get_item.cpp

@@ -32,8 +32,10 @@ POSSIBILITY OF SUCH DAMAGE.
 
 #include <libtorrent/config.hpp>
 #include <libtorrent/hasher.hpp>
+#include <libtorrent/bdecode.hpp>
 #include <libtorrent/kademlia/get_item.hpp>
 #include <libtorrent/kademlia/node.hpp>
+#include <libtorrent/kademlia/dht_observer.hpp>
 
 #if TORRENT_USE_ASSERTS
 #include <libtorrent/bencode.hpp>
@@ -197,9 +199,12 @@ void get_item::done()
 void get_item::put(std::vector<std::pair<node_entry, std::string> > const& v)
 {
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-	TORRENT_LOG(node) << "sending put [ v: \"" << m_data.value()
+	// TODO: 3 it would be nice to not have to spend so much time rendering
-		<< "\" seq: " << (m_data.is_mutable() ? m_data.seq() : -1)
+	// the bencoded dict if logging is disabled
-		<< " nodes: " << v.size() << " ]" ;
+	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<std::pair<node_entry, std::string> > 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;
 	}

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_node().observer()->log(dht_logger::traversal, "[%p] PEERS "
-					<< "[" << m_algorithm.get() << "] PEERS"
+					"invoke-count: %d branch-factor: %d addr: %s id: %s distance: %d p: %d"
-					<< " invoke-count: " << m_algorithm->invoke_count()
+					, m_algorithm.get()
-					<< " branch-factor: " << m_algorithm->branch_factor()
+					, m_algorithm->invoke_count()
-					<< " addr: " << m.addr
+					, m_algorithm->branch_factor()
-					<< " id: " << node_id(id.string_ptr())
+					, print_endpoint(m.addr).c_str()
-					<< " distance: " << distance_exp(m_algorithm->target(), node_id(id.string_ptr()))
+					, to_hex(id.string_value()).c_str()
-					<< " p: " << ((end - peers) / 6);
+					, 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_node().observer()->log(dht_logger::traversal, "[%p] PEERS "
-					<< "[" << m_algorithm.get() << "] PEERS"
+					"invoke-count: %d branch-factor: %d addr: %s id: %s distance: %d p: %d"
-					<< " invoke-count: " << m_algorithm->invoke_count()
+					, m_algorithm.get()
-					<< " branch-factor: " << m_algorithm->branch_factor()
+					, m_algorithm->invoke_count()
-					<< " addr: " << m.addr
+					, m_algorithm->branch_factor()
-					<< " id: " << node_id(id.string_ptr())
+					, print_endpoint(m.addr).c_str()
-					<< " distance: " << distance_exp(m_algorithm->target(), node_id(id.string_ptr()))
+					, to_hex(id.string_value()).c_str()
-					<< " p: " << n.list_size();
+					, 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 << "]"
+		get_node().observer()->log(dht_logger::traversal, "[%p] obfuscated get_peers "
-		<< " obfuscated get_peers phase 1 done, spawning get_peers [" << ta.get() << "]";
+			"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()
+		m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] missing response dict"
-			<< "] 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()
+		m_algorithm->get_node().observer()->log(dht_logger::traversal, "[%p] invalid id in response"
-			<< "] invalid id in response";
+			, m_algorithm.get());
 #endif
 		return;
 	}

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
 	}
 
 }}
+*/
 

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<peer_entry>& 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_table(m_id, 8, settings, observer)
-	, m_rpc(m_id, m_table, sock)
+	, 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<udp::endpoint> 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
+		char hex_ih[41];
-			<< " p: " << listen_port
+		to_hex(reinterpret_cast<char const*>(&ih[0]), 20, hex_ih);
-			<< " nodes: " << v.size() << " ]" ;
+		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<void(std::vector<tcp::endpoint> 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<char const*>(&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<bool(item&)> f)
 {
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-	TORRENT_LOG(node) << "starting get for [ hash: " << target << " ]" ;
+	char hex_target[41];
+	to_hex(reinterpret_cast<char const*>(&target[0]), 20, hex_target);
+	m_observer->log(dht_logger::node, "starting get for [ hash: %s ]"
+		, hex_target);
 #endif
 
 	boost::intrusive_ptr<dht::get_item> ta;
@@ -403,8 +405,9 @@ void node::get_item(char const* pk, std::string const& salt
 	, boost::function<bool(item&)> f)
 {
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-	TORRENT_LOG(node) << "starting get for [ key: "
+	char hex_key[65];
-		<< to_hex(std::string(pk, 32)) << " ]" ;
+	to_hex(pk, 32, hex_key);
+	m_observer->log(dht_logger::node, "starting get for [ key: %s ]", hex_key);
 #endif
 
 	boost::intrusive_ptr<dht::get_item> ta;
@@ -429,8 +432,9 @@ struct ping_observer : observer
 		if (!r)
 		{
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-			TORRENT_LOG(traversal) << "[" << m_algorithm.get()
+			m_algorithm->get_node().observer()->log(dht_logger::node
-				<< "] missing response dict";
+				, "[%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
 	}

src/kademlia/refresh.cpp

@@ -33,6 +33,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include <libtorrent/kademlia/refresh.hpp>
 #include <libtorrent/kademlia/rpc_manager.hpp>
 #include <libtorrent/kademlia/node.hpp>
+#include <libtorrent/kademlia/dht_observer.hpp>
 #include <libtorrent/performance_counters.hpp>
 
 #include <libtorrent/io.hpp>
@@ -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 << "]"
+	get_node().observer()->log(dht_logger::traversal, "[%p] bootstrap done, pinging remaining nodes"
-		<< " bootstrap done, pinging remaining nodes";
+		, this);
 #endif
 
 	for (std::vector<observer_ptr>::iterator i = m_results.begin()

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 <typename T, typename K>
 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)
+	, dht_settings const& settings
-	: m_settings(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): "
+				char hex_id[41];
-					<< e.id << " " << e.addr();
+				to_hex(reinterpret_cast<char const*>(&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()
+				char hex_id1[41];
-				<< " existing node: "
+				to_hex(reinterpret_cast<char const*>(&e.id[0]), 20, hex_id1);
-				<< j->id << " " << j->addr();
+				char hex_id2[41];
+				to_hex(reinterpret_cast<char const*>(&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()
+				char hex_id1[41];
-				<< " existing node: "
+				to_hex(reinterpret_cast<char const*>(&e.id[0]), 20, hex_id1);
-				<< j->id << " " << j->addr();
+				char hex_id2[41];
+				to_hex(reinterpret_cast<char const*>(&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
+			char hex_id[41];
-				<< " " << e.addr();
+			to_hex(reinterpret_cast<char const*>(&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"
+		char hex_id[41];
-			" id: " << nid <<
+		to_hex(reinterpret_cast<char const*>(&nid[0]), 20, hex_id);
-			" ip: " << j->ep() <<
+		m_log->log(dht_logger::routing_table, "NODE FAILED id: %s ip: %s fails: %d pinged: %d up-time: %d"
-			" fails: " << j->fail_count() <<
+			, hex_id, print_endpoint(j->ep()).c_str()
-			" pinged: " << j->pinged() <<
+			, int(j->fail_count())
-			" up-time: " << total_seconds(aux::time_now() - j->first_seen);
+			, 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"
+		char hex_id[41];
-			" id: " << nid <<
+		to_hex(reinterpret_cast<char const*>(&nid[0]), 20, hex_id);
-			" ip: " << j->ep() <<
+		m_log->log(dht_logger::routing_table, "NODE FAILED id: %s ip: %s fails: %d pinged: %d up-time: %d"
-			" fails: " << j->fail_count() <<
+			, hex_id, print_endpoint(j->ep()).c_str()
-			" pinged: " << j->pinged() <<
+			, int(j->fail_count())
-			" up-time: " << total_seconds(aux::time_now() - j->first_seen);
+			, 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

src/kademlia/rpc_manager.cpp

@@ -45,6 +45,9 @@ POSSIBILITY OF SUCH DAMAGE.
 #include <libtorrent/kademlia/refresh.hpp>
 #include <libtorrent/kademlia/node.hpp>
 #include <libtorrent/kademlia/observer.hpp>
+#include <libtorrent/kademlia/dht_observer.hpp>
+
+#include <libtorrent/socket_io.hpp> // for print_endpoint
 #include <libtorrent/hasher.hpp>
 #include <libtorrent/session_settings.hpp> // for dht_settings
 #include <libtorrent/time.hpp>
@@ -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: " 
+		m_log->log(dht_logger::rpc_manager, "reply with unknown transaction id size: %d from %s"
-			<< transaction_id.size() << " from " << m.addr;
+			, 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: " 
+	m_log->log(dht_logger::rpc_manager, "[%p] reply with transaction id: %d from %s"
-		<< tid << " from " << m.addr;
+		, 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: " 
+			m_log->log(dht_logger::rpc_manager, "[%p] timing out transaction id: %d from: %s"
-				<< o->transaction_id() << " from " << o->target_ep();
+				, 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: " 
+			m_log->log(dht_logger::rpc_manager, "[%p] short-timing out transaction id: %d from: %s"
-				<< o->transaction_id() << " from " << o->target_ep();
+				, 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 "
+	m_log->log(dht_logger::rpc_manager, "[%p] invoking %s -> %s"
-		<< e["q"].string() << " -> " << target_addr;
+		, 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))

src/kademlia/traversal_algorithm.cpp

@@ -36,6 +36,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include <libtorrent/kademlia/routing_table.hpp>
 #include <libtorrent/kademlia/rpc_manager.hpp>
 #include <libtorrent/kademlia/node.hpp>
+#include <libtorrent/kademlia/dht_observer.hpp> // for dht_logger
 #include <libtorrent/session_status.hpp>
 #include <libtorrent/socket_io.hpp> // for read_*_endpoint
 #include <libtorrent/alert_types.hpp> // 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"
+	char hex_target[41];
-		" target: " << target
+	to_hex(reinterpret_cast<char const*>(&target[0]), 20, hex_target);
-		<< " k: " << m_node.m_table.bucket_size()
+	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 "
+				char hex_id[41];
-				<< "id: " << to_hex(o->id().to_string())
+				to_hex(reinterpret_cast<char const*>(&o->id()[0]), 20, hex_id);
-				<< " addr: " << o->target_addr()
+				get_node().observer()->log(dht_logger::traversal
-				<< " type: " << name()
+					, "[%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())
+			char hex_id[41];
-			<< " addr: " << addr
+			to_hex(reinterpret_cast<char const*>(&id[0]), 20, hex_id);
-			<< " distance: " << distance_exp(m_target, id)
+			get_node().observer()->log(dht_logger::traversal
-			<< " invoke-count: " << m_invoke_count
+				, "[%p] ADD id: %s addr: %s distance: %d invoke-count: %d type: %s"
-			<< " type: " << name()
+				, 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 "
+			char hex_id[41];
-			<< " id: " << to_hex(o->id().to_string())
+			to_hex(reinterpret_cast<char const*>(&o->id()[0]), 20, hex_id);
-			<< " distance: " << distance_exp(m_target, o->id())
+			get_node().observer()->log(dht_logger::traversal
-			<< " addr: " << o->target_ep()
+				, "[%p] 1ST_TIMEOUT id: %s distance: %d addr: %s branch-factor: %d "
-			<< " branch-factor: " << m_branch_factor
+				"invoke-count: %d type: %s"
-			<< " invoke-count: " << m_invoke_count
+				, this, hex_id, distance_exp(m_target, o->id())
-			<< " type: " << name()
+				, 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 "
+			char hex_id[41];
-			<< " id: " << to_hex(o->id().to_string())
+			to_hex(reinterpret_cast<char const*>(&o->id()[0]), 20, hex_id);
-			<< " distance: " << distance_exp(m_target, o->id())
+			get_node().observer()->log(dht_logger::traversal
-			<< " addr: " << o->target_ep()
+				, "[%p] TIMEOUT id: %s distance: %d addr: %s branch-factor: %d "
-			<< " branch-factor: " << m_branch_factor
+				"invoke-count: %d type: %s"
-			<< " invoke-count: " << m_invoke_count
+				, this, hex_id, distance_exp(m_target, o->id())
-			<< " type: " << name()
+				, 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<observer_ptr>::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 << "]  "
+			char hex_id[41];
-				<< results_target
+			to_hex(reinterpret_cast<char const*>(&o->id()[0]), 20, hex_id);
-				<< " id: " << to_hex(o->id().to_string())
+			get_node().observer()->log(dht_logger::traversal
-				<< " distance: " << distance_exp(m_target, o->id())
+				, "[%p] id: %s distance: %d addr: %s"
-				<< " addr: " << o->target_ep()
+				, 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 "
+	get_node().observer()->log(dht_logger::traversal
-		<< "distance: " << closest_target
+		, "[%p] COMPLETED distance: %d type: %s"
-		<< " type: " << name()
+		, 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 "
+		char hex_id[41];
-			<< " nodes-left: " << (m_results.end() - i)
+		to_hex(reinterpret_cast<char const*>(&o->id()[0]), 20, hex_id);
-			<< " top-invoke-count: " << outstanding
+		get_node().observer()->log(dht_logger::traversal
-			<< " invoke-count: " << m_invoke_count
+			, "[%p] INVOKE nodes-left: %d top-invoke-count: %d "
-			<< " branch-factor: " << m_branch_factor
+			"invoke-count: %d branch-factor: %d "
-			<< " distance: " << distance_exp(m_target, o->id())
+			"distance: %d id: %s addr: %s type: %s"
-			<< " id: " << to_hex(o->id().to_string())
+			, this, m_results.end() - i, outstanding, m_invoke_count
-			<< " addr: " << o->target_ep()
+			, m_branch_factor, distance_exp(m_target, o->id()), hex_id
-			<< " type: " << name()
+			, 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. "
+	get_node().observer()->log(dht_logger::traversal
-		<< std::distance(m_node.m_table.router_begin(), m_node.m_table.router_end()) << " routers";
+		, "[%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()
+		m_algorithm->get_node().observer()->log(dht_logger::traversal
-			<< "] missing response dict";
+			, "[%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() << "] "
+	char hex_id[41];
-		"RESPONSE id: " << to_hex(nid.string_value())
+	to_hex(nid.string_ptr(), 20, hex_id);
-		<< " invoke-count: " << m_algorithm->invoke_count()
+	m_algorithm->get_node().observer()->log(dht_logger::traversal
-		<< " addr: " << m.addr
+		, "[%p] RESPONSE id: %s invoke-count: %d addr: %s type: %s"
-		<< " type: " << m_algorithm->name()
+		, 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 "
+	get_node().observer()->log(dht_logger::traversal, "[%p] ABORTED type: %s"
-		<< " type: " << name()
+		, this, name());
-		;
 #endif
 
 	done();

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<dht_get_peers_alert>()) return;
 		m_alerts.emplace_alert<dht_get_peers_alert>(ih);
 	}
 
 	void session_impl::announce(sha1_hash const& ih, address const& addr
-		, int port) TORRENT_OVERRIDE
+		, int port)
 	{
 		if (!m_alerts.should_post<dht_announce_alert>()) return;
 		m_alerts.emplace_alert<dht_announce_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<dht_outgoing_get_peers_alert>()) return;
 		m_alerts.emplace_alert<dht_outgoing_get_peers_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<dht_log_alert>()) 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_log_alert::dht_module_t)m, buf);
+	}
+
 	void session_impl::set_external_address(address const& ip
 		, int source_type, address const& source)
 	{