move some DHT verbose stats logging over to performance counters

include/libtorrent/kademlia/dht_tracker.hpp

@@ -157,20 +157,6 @@ namespace libtorrent { namespace dht
 
 		// used to resolve hostnames for nodes
 		udp::resolver m_host_resolver;
-
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-		int m_replies_sent[5];
-		int m_queries_received[5];
-		int m_replies_bytes_sent[5];
-		int m_queries_bytes_received[5];
-		int m_counter;
-
-		int m_total_message_input;
-		int m_total_in_bytes;
-		int m_total_out_bytes;
-		
-		int m_queries_out_bytes;
-#endif
 	};
 }}
 

include/libtorrent/performance_counters.hpp

@@ -228,6 +228,11 @@ namespace libtorrent
 			dht_put_in,
 			dht_put_out,
 
+			dht_invalid_announce,
+			dht_invalid_get_peers,
+			dht_invalid_put,
+			dht_invalid_get,
+
 			// uTP counters.
 			utp_packet_loss,
 			utp_timeout,

src/kademlia/dht_tracker.cpp

@@ -30,10 +30,6 @@ POSSIBILITY OF SUCH DAMAGE.
 
 */
 
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-#include <fstream>
-#endif
-
 #include <set>
 #include <numeric>
 #include <boost/bind.hpp>
@@ -73,22 +69,8 @@ namespace
 
 namespace libtorrent { namespace dht
 {
-
 	void incoming_error(entry& e, char const* msg);
 
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-	int g_az_message_input = 0;
-	int g_ut_message_input = 0;
-	int g_lt_message_input = 0;
-	int g_mp_message_input = 0;
-	int g_gr_message_input = 0;
-	int g_mo_message_input = 0;
-	int g_unknown_message_input = 0;
-
-	int g_announces = 0;
-	int g_failed_announces = 0;
-#endif
-		
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
 	std::string parse_dht_client(lazy_entry const& e)
 	{
@@ -97,42 +79,34 @@ namespace libtorrent { namespace dht
 		std::string const& client = ver->string_value();
 		if (client.size() < 2)
 		{
-			++g_unknown_message_input;
 			return client;
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "Az"))
 		{
-			++g_az_message_input;
 			return "Azureus";
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "UT"))
 		{
-			++g_ut_message_input;
 			return "uTorrent";
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "LT"))
 		{
-			++g_lt_message_input;
 			return "libtorrent";
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "MP"))
 		{
-			++g_mp_message_input;
 			return "MooPolice";
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "GR"))
 		{
-			++g_gr_message_input;
 			return "GetRight";
 		}
 		else if (std::equal(client.begin(), client.begin() + 2, "MO"))
 		{
-			++g_mo_message_input;
 			return "Mono Torrent";
 		}
 		else
 		{
-			++g_unknown_message_input;
 			return client;
 		}
 	}
@@ -177,18 +151,6 @@ namespace libtorrent { namespace dht
 		, m_host_resolver(sock.get_io_service())
 	{
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-		m_counter = 0;
-		std::fill_n(m_replies_bytes_sent, 5, 0);
-		std::fill_n(m_queries_bytes_received, 5, 0);
-		std::fill_n(m_replies_sent, 5, 0);
-		std::fill_n(m_queries_received, 5, 0);
-		g_announces = 0;
-		g_failed_announces = 0;
-		m_total_message_input = 0;
-		m_total_in_bytes = 0;
-		m_total_out_bytes = 0;
-		m_queries_out_bytes = 0;
-		
 		// turns on and off individual components' logging
 
 //		rpc_log().enable(false);
@@ -297,92 +259,6 @@ namespace libtorrent { namespace dht
 			TORRENT_LOG(dht_tracker) << " *** new write key";
 #endif
 		}
-		
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-		// TODO: 3 move all this out of libtorrent. It can be done in libtorrent-webui
-		// just like session_stats
-		static bool first = true;
-
-		std::ofstream st("dht_routing_table_state.txt", std::ios_base::trunc);
-		m_dht.print_state(st);
-		
-		// count torrents
-		int torrents = m_dht.num_torrents();
-		
-		// count peers
-		int peers = m_dht.num_peers();
-
-		std::ofstream pc("dht_stats.log", first ? std::ios_base::trunc : std::ios_base::app);
-		if (first)
-		{
-			first = false;
-			pc << "\n\n *****   starting log at " << time_now_string() << "   *****\n\n"
-				<< "minute:active nodes:passive nodes:confirmed nodes"
-				":ping replies sent:ping queries recvd"
-				":ping replies bytes sent:ping queries bytes recvd"
-				":find_node replies sent:find_node queries recv"
-				":find_node replies bytes sent:find_node queries bytes recv"
-				":get_peers replies sent:get_peers queries recvd"
-				":get_peers replies bytes sent:get_peers queries bytes recv"
-				":announce_peer replies sent:announce_peer queries recvd"
-				":announce_peer replies bytes sent:announce_peer queries bytes recv"
-				":error replies sent:error queries recvd"
-				":error replies bytes sent:error queries bytes recv"
-				":num torrents:num peers:announces per min"
-				":failed announces per min:total msgs per min"
-				":az msgs per min:ut msgs per min:lt msgs per min:mp msgs per min"
-				":gr msgs per min:mo msgs per min:bytes in per sec:bytes out per sec"
-				":queries out bytes per sec\n\n";
-		}
-
-		int active;
-		int passive;
-		int confirmed;
-		boost::tie(active, passive, confirmed) = m_dht.size();
-		pc << (m_counter * tick_period)
-			<< "\t" << active
-			<< "\t" << passive
-			<< "\t" << confirmed;
-		for (int i = 0; i < 5; ++i)
-			pc << "\t" << (m_replies_sent[i] / float(tick_period))
-				<< "\t" << (m_queries_received[i] / float(tick_period))
-				<< "\t" << (m_replies_bytes_sent[i] / float(tick_period*60))
-				<< "\t" << (m_queries_bytes_received[i] / float(tick_period*60));
-		
-		pc << "\t" << torrents
-			<< "\t" << peers
-			<< "\t" << g_announces / float(tick_period)
-			<< "\t" << g_failed_announces / float(tick_period)
-			<< "\t" << (m_total_message_input / float(tick_period))
-			<< "\t" << (g_az_message_input / float(tick_period))
-			<< "\t" << (g_ut_message_input / float(tick_period))
-			<< "\t" << (g_lt_message_input / float(tick_period))
-			<< "\t" << (g_mp_message_input / float(tick_period))
-			<< "\t" << (g_gr_message_input / float(tick_period))
-			<< "\t" << (g_mo_message_input / float(tick_period))
-			<< "\t" << (m_total_in_bytes / float(tick_period*60))
-			<< "\t" << (m_total_out_bytes / float(tick_period*60))
-			<< "\t" << (m_queries_out_bytes / float(tick_period*60))
-			<< std::endl;
-		++m_counter;
-		std::fill_n(m_replies_bytes_sent, 5, 0);
-		std::fill_n(m_queries_bytes_received, 5, 0);
-		std::fill_n(m_replies_sent, 5, 0);
-		std::fill_n(m_queries_received, 5, 0);
-		g_announces = 0;
-		g_failed_announces = 0;
-		m_total_message_input = 0;
-		g_az_message_input = 0;
-		g_ut_message_input = 0;
-		g_lt_message_input = 0;
-		g_mp_message_input = 0;
-		g_gr_message_input = 0;
-		g_mo_message_input = 0;
-		g_unknown_message_input = 0;
-		m_total_in_bytes = 0;
-		m_total_out_bytes = 0;
-		m_queries_out_bytes = 0;
-#endif
 	}
 
 	void dht_tracker::announce(sha1_hash const& ih, int listen_port, int flags
@@ -510,11 +386,6 @@ namespace libtorrent { namespace dht
 		if (!m_blocker.incoming(ep.address(), time_now()))
 			return true;
 
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-		++m_total_message_input;
-		m_total_in_bytes += size;
-#endif
-
 		using libtorrent::entry;
 		using libtorrent::bdecode;
 			
@@ -549,26 +420,6 @@ namespace libtorrent { namespace dht
 			return false;
 		}
 
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-		parse_dht_client(e);
-		TORRENT_LOG(dht_tracker) << "<== " << ep << " " << print_entry(e, true);
-
-		if (e.dict_find_string_value("y") == "q")
-		{
-			std::string cmd = e.dict_find_string_value("q");
-			int cmd_idx = -1;
-			if (cmd == "ping") cmd_idx = 0;
-			else if (cmd == "find_node") cmd_idx = 1;
-			else if (cmd == "get_peers") cmd_idx = 2;
-			else if (cmd == "announce_peeer") cmd_idx = 3;
-			if (cmd_idx >= 0)
-			{
-				++m_queries_received[cmd_idx];
-				m_queries_bytes_received[cmd_idx] += size;
-			}
-		}
-#endif
-
 		m_dht.incoming(m);
 		return true;
 	}
@@ -675,8 +526,6 @@ namespace libtorrent { namespace dht
 				, addr.address().is_v6() ? 48 : 28);
 			m_counters.inc_stats_counter(counters::dht_messages_out);
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
-			m_total_out_bytes += m_send_buf.size();
-		
 			if (e["y"].string() == "r")
 			{
 /*

src/kademlia/node.cpp

@@ -69,10 +69,6 @@ enum { announce_interval = 30 };
 
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
 TORRENT_DEFINE_LOG(node)
-
-extern int g_failed_announces;
-extern int g_announces;
-
 #endif
 
 // remove peers that have timed out
@@ -338,7 +334,7 @@ namespace
 			a["token"] = i->second;
 			a["seed"] = (flags & node_impl::flag_seed) ? 1 : 0;
 			if (flags & node_impl::flag_implied_port) a["implied_port"] = 1;
-			node.stats_counters().inc_stats_counter(counters::dht_announce_peer_in);
+			node.stats_counters().inc_stats_counter(counters::dht_announce_peer_out);
 			node.m_rpc.invoke(e, i->first.ep(), o);
 		}
 	}
@@ -864,8 +860,10 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		};
 
 		lazy_entry const* msg_keys[3];
-		if (!verify_message(arg_ent, msg_desc, msg_keys, 3, error_string, sizeof(error_string)))
+		if (!verify_message(arg_ent, msg_desc, msg_keys, 3, error_string
+			, sizeof(error_string)))
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_get_peers);
 			incoming_error(e, error_string);
 			return;
 		}
@@ -927,9 +925,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		lazy_entry const* msg_keys[6];
 		if (!verify_message(arg_ent, msg_desc, msg_keys, 6, error_string, sizeof(error_string)))
 		{
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-			++g_failed_announces;
-#endif
+			m_counters.inc_stats_counter(counters::dht_invalid_announce);
 			incoming_error(e, error_string);
 			return;
 		}
@@ -943,9 +939,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 
 		if (port < 0 || port >= 65536)
 		{
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-			++g_failed_announces;
-#endif
+			m_counters.inc_stats_counter(counters::dht_invalid_announce);
 			incoming_error(e, "invalid port");
 			return;
 		}
@@ -960,9 +954,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 
 		if (!verify_token(msg_keys[2]->string_value(), msg_keys[0]->string_ptr(), m.addr))
 		{
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-			++g_failed_announces;
-#endif
+			m_counters.inc_stats_counter(counters::dht_invalid_announce);
 			incoming_error(e, "invalid token");
 			return;
 		}
@@ -1021,9 +1013,6 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		std::set<peer_entry>::iterator i = v->peers.find(peer);
 		if (i != v->peers.end()) v->peers.erase(i++);
 		v->peers.insert(i, peer);
-#ifdef TORRENT_DHT_VERBOSE_LOGGING
-		++g_announces;
-#endif
 	}
 	else if (strcmp(query, "put") == 0)
 	{
@@ -1044,6 +1033,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		lazy_entry const* msg_keys[7];
 		if (!verify_message(arg_ent, msg_desc, msg_keys, 7, error_string, sizeof(error_string)))
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_put);
 			incoming_error(e, error_string);
 			return;
 		}
@@ -1065,6 +1055,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		std::pair<char const*, int> buf = msg_keys[1]->data_section();
 		if (buf.second > 1000 || buf.second <= 0)
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_put);
 			incoming_error(e, "message too big", 205);
 			return;
 		}
@@ -1075,6 +1066,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 				msg_keys[6]->string_ptr(), msg_keys[6]->string_length());
 		if (salt.second > 64)
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_put);
 			incoming_error(e, "salt too big", 207);
 			return;
 		}
@@ -1095,6 +1087,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 		// specific target hashes. it must match the one we got a "get" for
 		if (!verify_token(msg_keys[0]->string_value(), (char const*)&target[0], m.addr))
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_put);
 			incoming_error(e, "invalid token");
 			return;
 		}
@@ -1147,6 +1140,7 @@ void node_impl::incoming_request(msg const& m, entry& e)
 			if (!verify_mutable_item(buf, salt
 				, msg_keys[2]->int_value(), pk, sig))
 			{
+				m_counters.inc_stats_counter(counters::dht_invalid_put);
 				incoming_error(e, "invalid signature", 206);
 				return;
 			}
@@ -1205,12 +1199,14 @@ void node_impl::incoming_request(msg const& m, entry& e)
 				// writers are accessing the same slot
 				if (msg_keys[5] && item->seq != msg_keys[5]->int_value())
 				{
+					m_counters.inc_stats_counter(counters::dht_invalid_put);
 					incoming_error(e, "CAS mismatch", 301);
 					return;
 				}
 
 				if (item->seq > boost::uint64_t(msg_keys[2]->int_value()))
 				{
+					m_counters.inc_stats_counter(counters::dht_invalid_put);
 					incoming_error(e, "old sequence number", 302);
 					return;
 				}
@@ -1257,8 +1253,10 @@ void node_impl::incoming_request(msg const& m, entry& e)
 
 		// attempt to parse the message
 		lazy_entry const* msg_keys[2];
-		if (!verify_message(arg_ent, msg_desc, msg_keys, 2, error_string, sizeof(error_string)))
+		if (!verify_message(arg_ent, msg_desc, msg_keys, 2, error_string
+			, sizeof(error_string)))
 		{
+			m_counters.inc_stats_counter(counters::dht_invalid_get);
 			incoming_error(e, error_string);
 			return;
 		}

src/session_stats.cpp

@@ -439,6 +439,12 @@ namespace libtorrent
 		METRIC(dht, dht_put_in)
 		METRIC(dht, dht_put_out)
 
+		// the number of failed incoming DHT requests by kind of request
+		METRIC(dht, dht_invalid_announce)
+		METRIC(dht, dht_invalid_get_peers)
+		METRIC(dht, dht_invalid_put)
+		METRIC(dht, dht_invalid_get)
+
 		// uTP counters. Each counter represents the number of time each event
 		// has occurred.
 		METRIC(utp, utp_packet_loss)