improve DHT logging a bit

src/kademlia/traversal_algorithm.cpp

@@ -170,8 +170,8 @@ void traversal_algorithm::add_entry(node_id const& id, udp::endpoint addr, unsig
 				// it claims a different node-ID. Ignore this to avoid attacks
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
 			TORRENT_LOG(traversal) << "[" << this << "] IGNORING result "
-				<< "id: " << o->id()
+				<< "id: " << to_hex(o->id().to_string())
-				<< " address: " << o->target_addr()
+				<< " addr: " << o->target_addr()
 				<< " type: " << name()
 				;
 #endif
@@ -184,8 +184,8 @@ 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: " << id
+		TORRENT_LOG(traversal) << "[" << this << "] ADD id: " << to_hex(id.to_string())
-			<< " address: " << addr
+			<< " addr: " << addr
 			<< " distance: " << distance_exp(m_target, id)
 			<< " invoke-count: " << m_invoke_count
 			<< " type: " << name()
@@ -298,7 +298,7 @@ void traversal_algorithm::failed(observer_ptr o, int flags)
 		o->flags |= observer::flag_short_timeout;
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
 		TORRENT_LOG(traversal) << "[" << this << "] 1ST_TIMEOUT "
-			<< " id: " << o->id()
+			<< " id: " << to_hex(o->id().to_string())
 			<< " distance: " << distance_exp(m_target, o->id())
 			<< " addr: " << o->target_ep()
 			<< " branch-factor: " << m_branch_factor
@@ -317,7 +317,7 @@ void traversal_algorithm::failed(observer_ptr o, int flags)
 
 #ifdef TORRENT_DHT_VERBOSE_LOGGING
 		TORRENT_LOG(traversal) << "[" << this << "] TIMEOUT "
-			<< " id: " << o->id()
+			<< " id: " << to_hex(o->id().to_string())
 			<< " distance: " << distance_exp(m_target, o->id())
 			<< " addr: " << o->target_ep()
 			<< " branch-factor: " << m_branch_factor
@@ -358,9 +358,9 @@ void traversal_algorithm::done()
 			TORRENT_ASSERT(o->flags & observer::flag_queried);
 			TORRENT_LOG(traversal) << "[" << this << "]  "
 				<< results_target
-				<< " id: " << o->id()
+				<< " id: " << to_hex(o->id().to_string())
 				<< " distance: " << distance_exp(m_target, o->id())
-				<< " address: " << o->target_ep()
+				<< " addr: " << o->target_ep()
 				;
 			--results_target;
 			int dist = distance_exp(m_target, o->id());
@@ -433,7 +433,9 @@ bool traversal_algorithm::add_requests()
 			<< " top-invoke-count: " << outstanding
 			<< " invoke-count: " << m_invoke_count
 			<< " branch-factor: " << m_branch_factor
-			<< " distance: " << distance_exp(m_target, (*i)->id())
+			<< " distance: " << distance_exp(m_target, o->id())
+			<< " id: " << to_hex(o->id().to_string())
+			<< " addr: " << o->target_ep()
 			<< " type: " << name()
 			;
 #endif
@@ -524,6 +526,15 @@ void traversal_observer::reply(msg const& m)
 		return;
 	}
 
+#ifdef TORRENT_DHT_VERBOSE_LOGGING
+	lazy_entry const* nid = r->dict_find_string("id");
+	TORRENT_LOG(traversal) << "[" << m_algorithm.get() << "] "
+		"RESPONSE id: " << to_hex(nid->string_value())
+		<< " invoke-count: " << m_algorithm->invoke_count()
+		<< " addr: " << m.addr
+		<< " type: " << m_algorithm->name()
+		;
+#endif
 	// look for nodes
 	lazy_entry const* n = r->dict_find_string("nodes");
 	if (n)

tools/parse_dht_log.py

@@ -21,6 +21,9 @@ counter = 0;
 #  d: distance (from target)
 #  o: outstanding searches
 #  e: event (NEW, COMPLETED, ADD, INVOKE, TIMEOUT)
+#  i: node-id
+#  a: IP address and port
+#  s: source node-id (only for ADD events)
 outstanding_searches = {}
 
 # list of completed searches
@@ -31,6 +34,8 @@ def convert_timestamp(t):
 	posix = time.strptime(parts[0], '%H:%M:%S')
 	return (posix.tm_hour * 3600 + posix.tm_min * 60 + posix.tm_sec) * 1000 + int(parts[1])
 
+last_incoming = ''
+
 for line in f:
 	counter += 1
 #	if counter % 1000 == 0:
@@ -57,18 +62,36 @@ for line in f:
 		ts = l[0]
 		event = l[3]
 
-		if event == 'NEW':
+		if event == 'RESPONSE':
-			outstanding_searches[search_id] = [{ 't': ts, 'd': 160, 'o': 0, 'e': 'NEW'}]
+			outstanding = int(l[l.index('invoke-count:')+1])
-		elif event == 'INVOKE' or event == 'ADD' or event == '1ST_TIMEOUT' or event == 'TIMEOUT' or event == 'PEERS':
+			nid = l[l.index('id:')+1]
+			addr = l[l.index('addr:')+1]
+			last_response = addr
+			outstanding_searches[search_id].append({ 't': ts, 'd': distance,
+				'o': outstanding + 1, 'a':addr, 'e': event,'i':nid, 's':source})
+		elif event == 'NEW':
+			outstanding_searches[search_id] = [{ 't': ts, 'd': 0, 'o': 0, 'e': 'NEW', 'i': ''}]
+			last_response = ''
+		elif event == 'INVOKE' or event == 'ADD' or event == '1ST_TIMEOUT' or \
+			event == 'TIMEOUT' or event == 'PEERS':
 			if not search_id in outstanding_searches:
 				print 'orphaned event: %s' % line
 			else:
 				outstanding = int(l[l.index('invoke-count:')+1])
 				distance = int(l[l.index('distance:')+1])
-				outstanding_searches[search_id].append({ 't': ts, 'd': distance, 'o': outstanding + 1, 'e': event})
+				nid = l[l.index('id:')+1]
+				addr = l[l.index('addr:')+1]
+				source = ''
+				if event == 'ADD':
+					if last_response == '': continue
+					source = last_response
+
+				outstanding_searches[search_id].append({ 't': ts, 'd': distance,
+					'o': outstanding + 1, 'a':addr, 'e': event,'i':nid, 's':source})
 		elif event == 'COMPLETED':
 				distance = int(l[l.index('distance:')+1])
-				outstanding_searches[search_id].append({ 't': ts, 'd': distance, 'o': 0, 'e': event})
+				outstanding_searches[search_id].append({ 't': ts, 'd': distance,
+					'o': 0, 'e': event,'i':''})
 
 				s = outstanding_searches[search_id]
 
@@ -81,9 +104,8 @@ for line in f:
 				searches.append(s)
 				del outstanding_searches[search_id]
 
-				
-
 	except Exception, e:
+		print e
 		print line.split(' ')
 
 lookup_times_min = []
@@ -141,13 +163,17 @@ out = open('dht_lookups.txt', 'w+')
 for s in searches:
 	for i in s:
 		if i['e'] == 'INVOKE':
-			print >>out, ' ->', i['t'], 160 - i['d']
+			print >>out, ' ->', i['t'], 160 - i['d'], i['i'], i['a']
 		elif i['e'] == '1ST_TIMEOUT':
-			print >>out, ' x ', i['t'], 160 - i['d']
+			print >>out, ' x ', i['t'], 160 - i['d'], i['i'], i['a']
 		elif i['e'] == 'TIMEOUT':
-			print >>out, ' X ', i['t'], 160 - i['d']
+			print >>out, ' X ', i['t'], 160 - i['d'], i['i'], i['a']
+		elif i['e'] == 'ADD':
+			print >>out, ' + ', i['t'], 160 - i['d'], i['i'], i['a'], i['s']
+		elif i['e'] == 'RESPONSE':
+			print >>out, ' <-', i['t'], 160 - i['d'], i['i'], i['a']
 		elif i['e'] == 'PEERS':
-			print >>out, ' <-', i['t'], 160 - i['d']
+			print >>out, ' <-', i['t'], 160 - i['d'], i['i'], i['a']
 		elif i['e'] == 'COMPLETED':
 			print >>out, '***', i['t'], 160 - i['d'], '\n'
 			break