make dht logging deterministic (#1460)

make dht logging deterministic (ues an id instead of this-pointer to identify a traversal algorithm)

try with more DHT nodes
This commit is contained in:
Arvid Norberg 2016-12-27 07:12:57 -08:00 committed by GitHub
parent 1ec5c69dcd
commit b74bdfa7db
10 changed files with 81 additions and 61 deletions

View File

@ -114,6 +114,10 @@ public:
node_id const& nid() const { return m_id; }
#ifndef TORRENT_DISABLE_LOGGING
std::uint32_t search_id() { return m_search_id++; }
#endif
std::tuple<int, int, int> size() const { return m_table.size(); }
std::int64_t num_global_nodes() const
{ return m_table.num_global_nodes(); }
@ -259,6 +263,10 @@ private:
counters& m_counters;
dht_storage_interface& m_storage;
#ifndef TORRENT_DISABLE_LOGGING
std::uint32_t m_search_id = 0;
#endif
};
} } // namespace libtorrent::dht

View File

@ -78,6 +78,10 @@ struct TORRENT_EXTRA_EXPORT traversal_algorithm : boost::noncopyable
node& get_node() const { return m_node; }
#ifndef TORRENT_DISABLE_LOGGING
std::uint32_t id() const { return m_id; }
#endif
protected:
std::shared_ptr<traversal_algorithm> self()
@ -110,6 +114,11 @@ private:
std::int16_t m_branch_factor = 3;
std::int16_t m_responses = 0;
std::int16_t m_timeouts = 0;
#ifndef TORRENT_DISABLE_LOGGING
// this is a unique ID for this specific traversal_algorithm instance,
// just used for logging
std::uint32_t m_id;
#endif
// the IP addresses of the nodes in m_results
std::set<std::uint32_t> m_peer4_prefixes;

View File

@ -100,7 +100,7 @@ TORRENT_TEST(dht_bootstrap)
sim::default_config cfg;
sim::simulation sim{cfg};
dht_network dht(sim, 1200);
dht_network dht(sim, 2000);
int routing_table_depth = 0;
int num_nodes = 0;

View File

@ -71,6 +71,11 @@ struct obs : dht::dht_observer
, sha1_hash const& /* sent_target */, udp::endpoint const& /* ep */) override {}
void announce(sha1_hash const& /* ih */
, address const& /* addr */, int /* port */) override {}
bool on_dht_request(string_view /* query */
, dht::msg const& /* request */, entry& /* response */) override
{ return false; }
#ifndef TORRENT_DISABLE_LOGGING
bool should_log(module_t) const override { return true; }
void log(dht_logger::module_t l, char const* fmt, ...) override
{
@ -83,9 +88,7 @@ struct obs : dht::dht_observer
void log_packet(message_direction_t /* dir */
, span<char const> /* pkt */
, udp::endpoint const& /* node */) override {}
bool on_dht_request(string_view /* query */
, dht::msg const& /* request */, entry& /* response */) override
{ return false; }
#endif
};
#endif // #if !defined TORRENT_DISABLE_DHT

View File

@ -50,8 +50,8 @@ void find_data_observer::reply(msg const& m)
if (!r)
{
#ifndef TORRENT_DISABLE_LOGGING
get_observer()->log(dht_logger::traversal, "[%p] missing response dict"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] missing response dict"
, algorithm()->id());
#endif
timeout();
return;
@ -61,8 +61,8 @@ void find_data_observer::reply(msg const& m)
if (!id || id.string_length() != 20)
{
#ifndef TORRENT_DISABLE_LOGGING
get_observer()->log(dht_logger::traversal, "[%p] invalid id in response"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] invalid id in response"
, algorithm()->id());
#endif
timeout();
return;
@ -113,8 +113,8 @@ void find_data::got_write_token(node_id const& n, std::string write_token)
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] adding write token '%s' under id '%s'"
, static_cast<void*>(this), aux::to_hex(write_token).c_str()
, "[%u] adding write token '%s' under id '%s'"
, id(), aux::to_hex(write_token).c_str()
, aux::to_hex(n).c_str());
}
#endif
@ -141,8 +141,8 @@ void find_data::done()
auto logger = get_node().observer();
if (logger != nullptr)
{
logger->log(dht_logger::traversal, "[%p] %s DONE"
, static_cast<void*>(this), name());
logger->log(dht_logger::traversal, "[%u] %s DONE"
, id(), name());
}
#endif
@ -157,8 +157,8 @@ void find_data::done()
#ifndef TORRENT_DISABLE_LOGGING
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal, "[%p] not alive: %s"
, static_cast<void*>(this), print_endpoint(o->target_ep()).c_str());
logger->log(dht_logger::traversal, "[%u] not alive: %s"
, id(), print_endpoint(o->target_ep()).c_str());
}
#endif
continue;
@ -169,8 +169,8 @@ void find_data::done()
#ifndef TORRENT_DISABLE_LOGGING
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal, "[%p] no write token: %s"
, static_cast<void*>(this), print_endpoint(o->target_ep()).c_str());
logger->log(dht_logger::traversal, "[%u] no write token: %s"
, id(), print_endpoint(o->target_ep()).c_str());
}
#endif
continue;
@ -179,8 +179,8 @@ void find_data::done()
#ifndef TORRENT_DISABLE_LOGGING
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal, "[%p] %s"
, static_cast<void*>(this), print_endpoint(o->target_ep()).c_str());
logger->log(dht_logger::traversal, "[%u] %s"
, id(), print_endpoint(o->target_ep()).c_str());
}
#endif
--num_results;

View File

@ -49,8 +49,8 @@ void get_peers_observer::reply(msg const& m)
if (!r)
{
#ifndef TORRENT_DISABLE_LOGGING
get_observer()->log(dht_logger::traversal, "[%p] missing response dict"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] missing response dict"
, algorithm()->id());
#endif
timeout();
return;
@ -96,9 +96,9 @@ void get_peers_observer::log_peers(msg const& m, bdecode_node const& r, int cons
bdecode_node const id = r.dict_find_string("id");
if (id && id.string_length() == 20)
{
logger->log(dht_logger::traversal, "[%p] PEERS "
logger->log(dht_logger::traversal, "[%u] PEERS "
"invoke-count: %d branch-factor: %d addr: %s id: %s distance: %d p: %d"
, static_cast<void*>(algorithm())
, algorithm()->id()
, algorithm()->invoke_count()
, algorithm()->branch_factor()
, print_endpoint(m.addr).c_str()
@ -270,10 +270,9 @@ void obfuscated_get_peers::done()
m_nodes_callback = nullptr;
#ifndef TORRENT_DISABLE_LOGGING
get_node().observer()->log(dht_logger::traversal, "[%p] obfuscated get_peers "
"phase 1 done, spawning get_peers [ %p ]"
, static_cast<void*>(this)
, static_cast<void*>(ta.get()));
get_node().observer()->log(dht_logger::traversal, "[%u] obfuscated get_peers "
"phase 1 done, spawning get_peers [ %u ]"
, id(), ta->id());
#endif
int num_added = 0;
@ -302,8 +301,8 @@ void obfuscated_get_peers_observer::reply(msg const& m)
if (!r)
{
#ifndef TORRENT_DISABLE_LOGGING
get_observer()->log(dht_logger::traversal, "[%p] missing response dict"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] missing response dict"
, algorithm()->id());
#endif
timeout();
return;
@ -313,8 +312,8 @@ void obfuscated_get_peers_observer::reply(msg const& m)
if (!id || id.string_length() != 20)
{
#ifndef TORRENT_DISABLE_LOGGING
get_observer()->log(dht_logger::traversal, "[%p] invalid id in response"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] invalid id in response"
, algorithm()->id());
#endif
timeout();
return;

View File

@ -73,8 +73,8 @@ void put_data::done()
m_done = true;
#ifndef TORRENT_DISABLE_LOGGING
get_node().observer()->log(dht_logger::traversal, "[%p] %s DONE, response %d, timeout %d"
, static_cast<void*>(this), name(), num_responses(), num_timeouts());
get_node().observer()->log(dht_logger::traversal, "[%u] %s DONE, response %d, timeout %d"
, id(), name(), num_responses(), num_timeouts());
#endif
m_put_callback(m_data, num_responses());

View File

@ -101,8 +101,8 @@ void bootstrap::trim_seed_nodes()
void bootstrap::done()
{
#ifndef TORRENT_DISABLE_LOGGING
get_node().observer()->log(dht_logger::traversal, "[%p] bootstrap done, pinging remaining nodes"
, static_cast<void*>(this));
get_node().observer()->log(dht_logger::traversal, "[%u] bootstrap done, pinging remaining nodes"
, id());
#endif
for (auto const& o : m_results)

View File

@ -84,11 +84,12 @@ traversal_algorithm::traversal_algorithm(
, m_target(target)
{
#ifndef TORRENT_DISABLE_LOGGING
m_id = m_node.search_id();
dht_observer* logger = get_node().observer();
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal, "[%p] NEW target: %s k: %d"
, static_cast<void*>(this), aux::to_hex(target).c_str(), m_node.m_table.bucket_size());
logger->log(dht_logger::traversal, "[%u] NEW target: %s k: %d"
, m_id, aux::to_hex(target).c_str(), m_node.m_table.bucket_size());
}
#endif
}
@ -110,8 +111,8 @@ void traversal_algorithm::add_entry(node_id const& id
#ifndef TORRENT_DISABLE_LOGGING
if (get_node().observer() != nullptr)
{
get_node().observer()->log(dht_logger::traversal, "[%p] failed to allocate memory or observer. aborting!"
, static_cast<void*>(this));
get_node().observer()->log(dht_logger::traversal, "[%u] failed to allocate memory or observer. aborting!"
, m_id);
}
#endif
done();
@ -167,8 +168,8 @@ void traversal_algorithm::add_entry(node_id const& id
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] traversal DUPLICATE node. id: %s addr: %s type: %s"
, static_cast<void*>(this), aux::to_hex(o->id()).c_str(), print_address(o->target_addr()).c_str(), name());
, "[%u] traversal DUPLICATE node. id: %s addr: %s type: %s"
, m_id, aux::to_hex(o->id()).c_str(), print_address(o->target_addr()).c_str(), name());
}
#endif
return;
@ -185,8 +186,8 @@ void traversal_algorithm::add_entry(node_id const& id
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] ADD id: %s addr: %s distance: %d invoke-count: %d type: %s"
, static_cast<void*>(this), aux::to_hex(id).c_str(), print_endpoint(addr).c_str()
, "[%u] ADD id: %s addr: %s distance: %d invoke-count: %d type: %s"
, m_id, aux::to_hex(id).c_str(), print_endpoint(addr).c_str()
, distance_exp(m_target, id), m_invoke_count, name());
}
#endif
@ -242,8 +243,8 @@ void traversal_algorithm::traverse(node_id const& id, udp::endpoint const& addr)
if (logger != nullptr && logger->should_log(dht_logger::traversal) && id.is_all_zeros())
{
logger->log(dht_logger::traversal
, "[%p] WARNING node returned a list which included a node with id 0"
, static_cast<void*>(this));
, "[%u] WARNING node returned a list which included a node with id 0"
, m_id);
}
#endif
@ -349,9 +350,9 @@ void traversal_algorithm::log_timeout(observer_ptr const& o, char const* prefix)
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] %sTIMEOUT id: %s distance: %d addr: %s branch-factor: %d "
, "[%u] %sTIMEOUT id: %s distance: %d addr: %s branch-factor: %d "
"invoke-count: %d type: %s"
, static_cast<void const*>(this), prefix, aux::to_hex(o->id()).c_str(), distance_exp(m_target, o->id())
, m_id, prefix, aux::to_hex(o->id()).c_str(), distance_exp(m_target, o->id())
, print_address(o->target_addr()).c_str(), m_branch_factor
, m_invoke_count, name());
}
@ -383,8 +384,8 @@ void traversal_algorithm::done()
{
TORRENT_ASSERT(o->flags & observer::flag_queried);
logger->log(dht_logger::traversal
, "[%p] id: %s distance: %d addr: %s"
, static_cast<void*>(this), aux::to_hex(o->id()).c_str(), closest_target
, "[%u] id: %s distance: %d addr: %s"
, m_id, aux::to_hex(o->id()).c_str(), closest_target
, print_endpoint(o->target_ep()).c_str());
--results_target;
@ -398,8 +399,8 @@ void traversal_algorithm::done()
if (get_node().observer() != nullptr)
{
get_node().observer()->log(dht_logger::traversal
, "[%p] COMPLETED distance: %d type: %s"
, static_cast<void*>(this), closest_target, name());
, "[%u] COMPLETED distance: %d type: %s"
, m_id, closest_target, name());
}
#endif
@ -462,10 +463,10 @@ bool traversal_algorithm::add_requests()
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] INVOKE nodes-left: %d top-invoke-count: %d "
, "[%u] INVOKE nodes-left: %d top-invoke-count: %d "
"invoke-count: %d branch-factor: %d "
"distance: %d id: %s addr: %s type: %s"
, static_cast<void*>(this), int(m_results.end() - i), outstanding, int(m_invoke_count)
, m_id, int(m_results.end() - i), outstanding, int(m_invoke_count)
, int(m_branch_factor), distance_exp(m_target, o->id()), aux::to_hex(o->id()).c_str()
, print_address(o->target_addr()).c_str(), name());
}
@ -499,8 +500,8 @@ void traversal_algorithm::add_router_entries()
if (logger != nullptr && logger->should_log(dht_logger::traversal))
{
logger->log(dht_logger::traversal
, "[%p] using router nodes to initiate traversal algorithm %d routers"
, static_cast<void*>(this), int(std::distance(m_node.m_table.begin(), m_node.m_table.end())));
, "[%u] using router nodes to initiate traversal algorithm %d routers"
, m_id, int(std::distance(m_node.m_table.begin(), m_node.m_table.end())));
}
#endif
for (auto const& n : m_node.m_table)
@ -554,8 +555,8 @@ void traversal_observer::reply(msg const& m)
if (get_observer() != nullptr)
{
get_observer()->log(dht_logger::traversal
, "[%p] missing response dict"
, static_cast<void*>(algorithm()));
, "[%u] missing response dict"
, algorithm()->id());
}
#endif
return;
@ -569,8 +570,8 @@ void traversal_observer::reply(msg const& m)
char hex_id[41];
aux::to_hex({nid.string_ptr(), 20}, hex_id);
logger->log(dht_logger::traversal
, "[%p] RESPONSE id: %s invoke-count: %d addr: %s type: %s"
, static_cast<void*>(algorithm()), hex_id, algorithm()->invoke_count()
, "[%u] RESPONSE id: %s invoke-count: %d addr: %s type: %s"
, algorithm()->id(), hex_id, algorithm()->invoke_count()
, print_endpoint(target_ep()).c_str(), algorithm()->name());
}
#endif
@ -598,8 +599,8 @@ void traversal_observer::reply(msg const& m)
#ifndef TORRENT_DISABLE_LOGGING
if (get_observer() != nullptr)
{
get_observer()->log(dht_logger::traversal, "[%p] invalid id in response"
, static_cast<void*>(algorithm()));
get_observer()->log(dht_logger::traversal, "[%u] invalid id in response"
, algorithm()->id());
}
#endif
return;