some DHT logging and parsing

src/kademlia/traversal_algorithm.cpp

@@ -574,6 +574,13 @@ void traversal_algorithm::abort()
 		if (o.flags & observer::flag_queried)
 			o.flags |= observer::flag_done;
 	}
+
+#ifdef TORRENT_DHT_VERBOSE_LOGGING
+	TORRENT_LOG(traversal) << "[" << this << "] ABORTED "
+		<< " type: " << name()
+		;
+#endif
+
 	done();
 }
 

tools/parse_dht_log.py

@@ -36,12 +36,17 @@ def convert_timestamp(t):
 
 last_incoming = ''
 
+our_node_id = ''
+
 for line in f:
 	counter += 1
 #	if counter % 1000 == 0:
 #		print '\r%d' % counter,
 	try:
 		l = line.split(' ')
+		if 'starting DHT tracker with node id:' in line:
+			our_node_id = l[l.index('id:') + 1].strip()
+
 		if 'announce-distance:' in line:
 			idx = l.index('announce-distance:')
 
@@ -70,7 +75,9 @@ for line in f:
 			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': ''}]
+			nid = l[l.index('target:')+1]
+			outstanding_searches[search_id] = [{ 't': ts, 'd': 0, 'o': 0, \
+				'e': event, 'abstime': ts, 'i': nid}]
 			last_response = ''
 		elif event == 'INVOKE' or event == 'ADD' or event == '1ST_TIMEOUT' or \
 			event == 'TIMEOUT' or event == 'PEERS':
@@ -88,11 +95,16 @@ for line in f:
 
 				outstanding_searches[search_id].append({ 't': ts, 'd': distance,
 					'o': outstanding + 1, 'a':addr, 'e': event,'i':nid, 's':source})
+		elif event == 'ABORTED':
+				outstanding_searches[search_id].append({ 't': ts, 'e': event})
 		elif event == 'COMPLETED':
 				distance = int(l[l.index('distance:')+1])
+				lookup_type = l[l.index('type:')+1].strip()
 				outstanding_searches[search_id].append({ 't': ts, 'd': distance,
 					'o': 0, 'e': event,'i':''})
 
+				outstanding_searches[search_id][0]['type'] = lookup_type
+
 				s = outstanding_searches[search_id]
 
 				try:
@@ -174,9 +186,13 @@ for s in searches:
 			print >>out, ' <-', i['t'], 160 - i['d'], i['i'], i['a']
 		elif i['e'] == 'PEERS':
 			print >>out, ' <-', i['t'], 160 - i['d'], i['i'], i['a']
+		elif i['e'] == 'ABORTED':
+			print >>out, 'abort'
 		elif i['e'] == 'COMPLETED':
 			print >>out, '***', i['t'], 160 - i['d'], '\n'
-			break
+		elif i['e'] == 'NEW':
+			print >>out, '===', i['abstime'], i['type'], '==='
+			print >>out, '<> ', 0, our_node_id, i['i']
 out.close()
 
 out = open('dht_announce_distribution.dat', 'w+')

tools/parse_lookup_log.py

@@ -0,0 +1,118 @@
+# this is meant to parse the dht_lookups.log generated by parse_dht_log.py
+
+import os
+
+nodes = {}
+
+def get_origin(n):
+	if n in nodes:
+		return list(nodes[n]['conns'])
+	else:
+		return ['0.0.0.0']
+
+def calculate_pos(nid, dist):
+	nid = int(nid[0:7], 16)
+
+	x = 0
+	y = 0
+	for i in range(0, 28, 2):
+		x |= (nid & (1 << i)) >> (i / 2)
+		y |= (nid & (2 << i)) >> (i / 2 + 1)
+
+#	print '%d -> %d %d' % (dist, x, y)
+
+	return (x / 3, y / 3)
+
+def plot_nodes(nodes, frame):
+
+	try: os.mkdir('dht_frames')
+	except: pass
+
+	out = open('dht_frames/plot-%02d.dot' % frame, 'w+')
+	edges = set()
+	print >>out, 'graph swarm {'
+#	print >>out, '"tl" [shape=point pos="0,0!"];'
+#	print >>out, '"tr" [shape=point pos="1638,0!"];'
+#	print >>out, '"ll" [shape=point pos="1638,1638!"];'
+#	print >>out, '"tr" [shape=point pos="0,1638!"];'
+	for dst, n in nodes.items():
+		shape = 'point'
+		if 's' in n: shape = n['s']
+
+		print >>out, '"%s" [shape=%s fillcolor="%s" label="" pos="%d,%d!"];' % (dst, shape, n['c'], n['p'][0], n['p'][1])
+		for e in n['conns']:
+			if (e, dst) in edges: continue
+
+			# only add an edge once to the .dot file
+			edges.add((e, dst))
+			edges.add((dst, e))
+
+			style = 'solid'
+			col = 'gray'
+			if nodes[dst]['c'] != 'white' and nodes[e]['c'] != 'white':
+				style = 'solid'
+				col = 'black'
+				print >>out, '"%s" -- "%s" [style="%s" color="%s"];' % (e, dst, style, col)
+
+	print >>out, '}'
+	out.close()
+	os.system('neato -n dht_frames/plot-%02d.dot -Tpng -o dht_frames/frame-%02d.png' % (frame, frame))
+
+
+frame = 0
+next_render_time = 100
+f = open('dht_lookups.txt')
+for l in f:
+	if l.startswith('***'): break
+
+	kind = l[0:3].strip()
+	l = l[3:].strip().split(' ')
+
+	if kind == '===': continue
+
+	t = int(l[0])
+	if t > next_render_time:
+		plot_nodes(nodes, frame)
+		frame += 1
+		next_render_time += 100
+#		sys.exit(0)
+
+	if kind == '<>':
+		p = calculate_pos(l[1], 0)
+		dst = '0.0.0.0'
+		if not dst in nodes:
+			nodes[dst] = { 'conns': set(), 'p': p, 'c': 'blue', 's': 'circle'}
+		
+		p = calculate_pos(l[2], 25)
+		dst = '255.255.255.255'
+		if not dst in nodes:
+			nodes[dst] = { 'conns': set(), 'p': p, 'c': 'yellow', 's': 'circle'}
+	elif kind == '->':
+		dst = l[3]
+		
+		if not dst in nodes:
+			src = get_origin(dst)
+			p = calculate_pos(l[2], int(l[1]))
+			nodes[dst] = { 'conns': set(src), 'p': p, 'c': 'grey'}
+		nodes[dst]['c'] = 'grey'
+
+	elif kind == '+':
+		dst = l[3]
+		src = l[4]
+		p = calculate_pos(l[2], int(l[1]))
+		if not dst in nodes:
+			nodes[dst] = { 'conns': set(), 'p': p, 'c': 'white'}
+		nodes[dst]['conns'].add(src)
+
+	elif kind == '<-':
+		dst = l[3]
+		nodes[dst]['c'] = 'green'
+	elif kind == 'x':
+		dst = l[3]
+		nodes[dst]['c'] = 'orange'
+	elif kind == 'X':
+		dst = l[3]
+		nodes[dst]['c'] = 'red'
+
+f.close()
+