extend logging of UDP tracker announces (to track down unit test flapping)

This commit is contained in:
Arvid Norberg 2015-01-13 21:34:43 +00:00
parent 9172874b5c
commit d140d71e1a
5 changed files with 114 additions and 45 deletions

View File

@ -363,8 +363,9 @@ namespace libtorrent
mutable mutex_t m_mutex;
// maps transactionid to the udp_tracker_connection
// TODO: 2 this should be unique_ptr in the future
typedef boost::unordered_map<boost::uint32_t, boost::shared_ptr<udp_tracker_connection> > udp_conns_t;
// TODO: this should be unique_ptr in the future
typedef boost::unordered_map<boost::uint32_t
, boost::shared_ptr<udp_tracker_connection> > udp_conns_t;
udp_conns_t m_udp_conns;
typedef std::vector<boost::shared_ptr<http_tracker_connection> > http_conns_t;

View File

@ -310,13 +310,28 @@ namespace libtorrent
, udp::endpoint const& ep, char const* buf, int size)
{
// ignore packets smaller than 8 bytes
if (size < 8) return false;
if (size < 8)
{
#if defined TORRENT_LOGGING
m_ses.debug_log("incoming packet from %s, not a UDP tracker message "
"(%d Bytes)", print_endpoint(*from).c_str(), size);
#endif
return false;
}
const char* ptr = buf + 4;
boost::uint32_t transaction = detail::read_uint32(ptr);
udp_conns_t::iterator i = m_udp_conns.find(transaction);
if (i == m_udp_conns.end()) return false;
if (i == m_udp_conns.end())
{
#if defined TORRENT_LOGGING
m_ses.debug_log("incoming UDP tracker packet from %s has invalid "
"transaction ID (%" PRIu32 ")", print_endpoint(*from).c_str()
, transaction);
#endif
return false;
}
boost::shared_ptr<tracker_connection> p = i->second;
// on_receive() may remove the tracker connection from the list
@ -327,13 +342,27 @@ namespace libtorrent
, char const* hostname, char const* buf, int size)
{
// ignore packets smaller than 8 bytes
if (size < 8) return false;
if (size < 8)
{
#if defined TORRENT_LOGGING
m_ses.debug_log("incoming packet from %s, not a UDP tracker message "
"(%d Bytes)", hostname, size);
#endif
return false;
}
const char* ptr = buf + 4;
boost::uint32_t transaction = detail::read_uint32(ptr);
udp_conns_t::iterator i = m_udp_conns.find(transaction);
if (i == m_udp_conns.end()) return false;
if (i == m_udp_conns.end())
{
#if defined TORRENT_LOGGING
m_ses.debug_log("incoming UDP tracker packet from %s has invalid "
"transaction ID (%x)", hostname, int(transaction));
#endif
return false;
}
boost::shared_ptr<tracker_connection> p = i->second;
// on_receive() may remove the tracker connection from the list

View File

@ -339,25 +339,46 @@ namespace libtorrent
bool udp_tracker_connection::on_receive(error_code const& e
, udp::endpoint const& ep, char const* buf, int size)
{
// ignore resposes before we've sent any requests
if (m_state == action_error) return false;
#if defined TORRENT_LOGGING
boost::shared_ptr<request_callback> cb = requester();
#endif
if (m_abort) return false;
// ignore resposes before we've sent any requests
if (m_state == action_error)
{
#if defined TORRENT_LOGGING
if (cb) cb->debug_log("<== UDP_TRACKER [ m_action == error ]");
#endif
return false;
}
if (m_abort)
{
#if defined TORRENT_LOGGING
if (cb) cb->debug_log("<== UDP_TRACKER [ aborted]");
#endif
return false;
}
// ignore packet not sent from the tracker
// if m_target is inaddr_any, it suggests that we
// sent the packet through a proxy only knowing
// the hostname, in which case this packet might be for us
if (!is_any(m_target.address()) && m_target != ep) return false;
if (!is_any(m_target.address()) && m_target != ep)
{
#if defined TORRENT_LOGGING
if (cb) cb->debug_log("<== UDP_TRACKER [ unexpected source IP: %s "
"expected: %s ]"
, print_endpoint(ep).c_str()
, print_endpoint(m_target).c_str());
#endif
return false;
}
if (e) fail(e);
#if defined TORRENT_LOGGING
boost::shared_ptr<request_callback> cb = requester();
if (cb)
{
cb->debug_log("<== UDP_TRACKER_PACKET [ size: %d ]", size);
}
if (cb) cb->debug_log("<== UDP_TRACKER_PACKET [ size: %d ]", size);
#endif
// ignore packets smaller than 8 bytes
@ -368,14 +389,18 @@ namespace libtorrent
boost::uint32_t transaction = detail::read_uint32(ptr);
#if defined TORRENT_LOGGING
if (cb)
{
cb->debug_log("*** UDP_TRACKER_PACKET [ action: %d ]", action);
}
if (cb) cb->debug_log("*** UDP_TRACKER_PACKET [ action: %d ]", action);
#endif
// ignore packets with incorrect transaction id
if (m_transaction_id != transaction) return false;
if (m_transaction_id != transaction)
{
#if defined TORRENT_LOGGING
if (cb) cb->debug_log("*** UDP_TRACKER_PACKET [ tid: %x ]"
, int(transaction));
#endif
return false;
}
if (action == action_error)
{
@ -384,16 +409,21 @@ namespace libtorrent
}
// ignore packets that's not a response to our message
if (action != m_state) return false;
if (action != m_state)
{
#if defined TORRENT_LOGGING
if (cb) cb->debug_log("*** UDP_TRACKER_PACKET [ unexpected action: %d "
" expected: %d ]", action, m_state);
#endif
return false;
}
restart_read_timeout();
#if defined TORRENT_LOGGING
if (cb)
{
cb->debug_log("*** UDP_TRACKER_RESPONSE [ tid: %x ]"
, int(transaction));
}
#endif
switch (m_state)

View File

@ -64,30 +64,30 @@ struct peer_server
m_acceptor.open(tcp::v4(), ec);
if (ec)
{
fprintf(stderr, "Error opening peer listen socket: %s\n", ec.message().c_str());
fprintf(stderr, "PEER Error opening peer listen socket: %s\n", ec.message().c_str());
return;
}
m_acceptor.bind(tcp::endpoint(address_v4::any(), 0), ec);
if (ec)
{
fprintf(stderr, "Error binding peer socket to port 0: %s\n", ec.message().c_str());
fprintf(stderr, "PEER Error binding peer socket to port 0: %s\n", ec.message().c_str());
return;
}
m_port = m_acceptor.local_endpoint(ec).port();
if (ec)
{
fprintf(stderr, "Error getting local endpoint of peer socket: %s\n", ec.message().c_str());
fprintf(stderr, "PEER Error getting local endpoint of peer socket: %s\n", ec.message().c_str());
return;
}
m_acceptor.listen(10, ec);
if (ec)
{
fprintf(stderr, "Error listening on peer socket: %s\n", ec.message().c_str());
fprintf(stderr, "PEER Error listening on peer socket: %s\n", ec.message().c_str());
return;
}
fprintf(stderr, "%s: peer initialized on port %d\n", time_now_string(), m_port);
fprintf(stderr, "%s: PEER peer initialized on port %d\n", time_now_string(), m_port);
m_thread.reset(new thread(boost::bind(&peer_server::thread_fun, this)));
}
@ -130,11 +130,11 @@ struct peer_server
if (ec)
{
fprintf(stderr, "Error accepting connection on peer socket: %s\n", ec.message().c_str());
fprintf(stderr, "PEER Error accepting connection on peer socket: %s\n", ec.message().c_str());
return;
}
fprintf(stderr, "%s: incoming peer connection\n", time_now_string());
fprintf(stderr, "%s: PEER incoming peer connection\n", time_now_string());
++m_peer_requests;
socket.close(ec);
}
@ -158,8 +158,8 @@ int num_peer_hits()
void stop_peer()
{
fprintf(stderr, "%s: stop_peer()\n", time_now_string());
fprintf(stderr, "%s: PEER stop_peer()\n", time_now_string());
g_peer.reset();
fprintf(stderr, "%s: stop_peer() done\n", time_now_string());
fprintf(stderr, "%s: PEER stop_peer() done\n", time_now_string());
}

View File

@ -88,19 +88,24 @@ struct udp_tracker
{
case 0: // connect
fprintf(stderr, "%s: UDP connect from %s\n", time_now_string(), print_endpoint(*from).c_str());
fprintf(stderr, "%s: UDP connect from %s\n", time_now_string()
, print_endpoint(*from).c_str());
ptr = buffer;
detail::write_uint32(0, ptr); // action = connect
detail::write_uint32(transaction_id, ptr); // transaction_id
detail::write_uint64(10, ptr); // connection_id
m_socket.send_to(asio::buffer(buffer, 16), *from, 0, e);
if (e) fprintf(stderr, "%s: send_to failed. ERROR: %s\n", time_now_string(), e.message().c_str());
if (e) fprintf(stderr, "%s: UDP send_to failed. ERROR: %s\n"
, time_now_string(), e.message().c_str());
else fprintf(stderr, "%s: UDP sent response to: %s\n"
, time_now_string(), print_endpoint(*from).c_str());
break;
case 1: // announce
++m_udp_announces;
fprintf(stderr, "%s: UDP announce [%d]\n", time_now_string(), int(m_udp_announces));
fprintf(stderr, "%s: UDP announce [%d]\n", time_now_string()
, int(m_udp_announces));
ptr = buffer;
detail::write_uint32(1, ptr); // action = announce
detail::write_uint32(transaction_id, ptr); // transaction_id
@ -109,14 +114,18 @@ struct udp_tracker
detail::write_uint32(1, ptr); // complete
// 0 peers
m_socket.send_to(asio::buffer(buffer, 20), *from, 0, e);
if (e) fprintf(stderr, "%s: send_to failed. ERROR: %s\n", time_now_string(), e.message().c_str());
if (e) fprintf(stderr, "%s: UDP send_to failed. ERROR: %s\n"
, time_now_string(), e.message().c_str());
else fprintf(stderr, "%s: UDP sent response to: %s\n"
, time_now_string(), print_endpoint(*from).c_str());
break;
case 2:
// ignore scrapes
fprintf(stderr, "%s: UDP scrape\n", time_now_string());
fprintf(stderr, "%s: UDP scrape (ignored)\n", time_now_string());
break;
default:
fprintf(stderr, "%s: UDP unknown message: %d\n", time_now_string(), action);
fprintf(stderr, "%s: UDP unknown message: %d\n", time_now_string()
, action);
break;
}
@ -134,20 +143,20 @@ struct udp_tracker
m_socket.open(udp::v4(), ec);
if (ec)
{
fprintf(stderr, "Error opening listen UDP tracker socket: %s\n", ec.message().c_str());
fprintf(stderr, "UDP Error opening listen UDP tracker socket: %s\n", ec.message().c_str());
return;
}
m_socket.bind(udp::endpoint(address_v4::any(), 0), ec);
if (ec)
{
fprintf(stderr, "Error binding UDP tracker socket to port 0: %s\n", ec.message().c_str());
fprintf(stderr, "UDP Error binding UDP tracker socket to port 0: %s\n", ec.message().c_str());
return;
}
m_port = m_socket.local_endpoint(ec).port();
if (ec)
{
fprintf(stderr, "Error getting local endpoint of UDP tracker socket: %s\n", ec.message().c_str());
fprintf(stderr, "UDP Error getting local endpoint of UDP tracker socket: %s\n", ec.message().c_str());
return;
}
@ -188,11 +197,11 @@ struct udp_tracker
if (ec)
{
fprintf(stderr, "Error running UDP tracker service: %s\n", ec.message().c_str());
fprintf(stderr, "UDP Error running UDP tracker service: %s\n", ec.message().c_str());
return;
}
fprintf(stderr, "exiting UDP tracker thread\n");
fprintf(stderr, "UDP exiting UDP tracker thread\n");
}
};
@ -213,8 +222,8 @@ int num_udp_announces()
void stop_udp_tracker()
{
fprintf(stderr, "%s: stop_udp_tracker()\n", time_now_string());
fprintf(stderr, "%s: UDP stop_udp_tracker()\n", time_now_string());
g_udp_tracker.reset();
fprintf(stderr, "%s: stop_udp_tracker() done\n", time_now_string());
fprintf(stderr, "%s: UDP stop_udp_tracker() done\n", time_now_string());
}