From ba3ffe52f810b687991c816f6cdb62b5e0eb88eb Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Wed, 1 Oct 2014 09:14:49 +0000 Subject: [PATCH] improve DHT logging a bit --- src/kademlia/traversal_algorithm.cpp | 29 +++++++++++------ tools/parse_dht_log.py | 48 +++++++++++++++++++++------- 2 files changed, 57 insertions(+), 20 deletions(-) diff --git a/src/kademlia/traversal_algorithm.cpp b/src/kademlia/traversal_algorithm.cpp index 964bc9b06..1be334a37 100644 --- a/src/kademlia/traversal_algorithm.cpp +++ b/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() - << " address: " << o->target_addr() + << "id: " << to_hex(o->id().to_string()) + << " 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 - << " address: " << addr + TORRENT_LOG(traversal) << "[" << this << "] ADD id: " << to_hex(id.to_string()) + << " 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) diff --git a/tools/parse_dht_log.py b/tools/parse_dht_log.py index 6fb90ec24..fd3618ef6 100755 --- a/tools/parse_dht_log.py +++ b/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': - outstanding_searches[search_id] = [{ 't': ts, 'd': 160, 'o': 0, 'e': 'NEW'}] - elif event == 'INVOKE' or event == 'ADD' or event == '1ST_TIMEOUT' or event == 'TIMEOUT' or event == 'PEERS': + if event == 'RESPONSE': + outstanding = int(l[l.index('invoke-count:')+1]) + 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