rpc_manager log optimization and minor refactor (#1095)

more on log optimization

include/libtorrent/kademlia/msg.hpp

@@ -51,6 +51,7 @@ typedef std::vector<tcp::endpoint> peers_t;
 struct msg
 {
 	msg(bdecode_node const& m, udp::endpoint const& ep): message(m), addr(ep) {}
+
 	// the message
 	bdecode_node const& message;
 

include/libtorrent/udp_socket.hpp

@@ -100,6 +100,13 @@ namespace libtorrent
 		bool is_closed() const { return m_abort; }
 		udp::endpoint local_endpoint(error_code& ec) const
 		{ return m_socket.local_endpoint(ec); }
+		// best effort, if you want to know the error, use
+		// ``local_endpoint(error_code& ec)``
+		udp::endpoint local_endpoint() const
+		{
+			error_code ec;
+			return local_endpoint(ec);
+		}
 
 		typedef udp::socket::receive_buffer_size receive_buffer_size;
 		typedef udp::socket::send_buffer_size send_buffer_size;

src/kademlia/rpc_manager.cpp

@@ -209,8 +209,11 @@ void rpc_manager::check_invariant() const
 void rpc_manager::unreachable(udp::endpoint const& ep)
 {
 #ifndef TORRENT_DISABLE_LOGGING
-	m_log->log(dht_logger::rpc_manager, "PORT_UNREACHABLE [ ip: %s ]"
-		, print_endpoint(ep).c_str());
+	if (m_log->should_log(dht_logger::rpc_manager))
+	{
+		m_log->log(dht_logger::rpc_manager, "PORT_UNREACHABLE [ ip: %s ]"
+			, print_endpoint(ep).c_str());
+	}
 #endif
 
 	for (auto i = m_transactions.begin(); i != m_transactions.end();)
@@ -261,7 +264,7 @@ bool rpc_manager::incoming(msg const& m, node_id* id)
 	if (!o)
 	{
 #ifndef TORRENT_DISABLE_LOGGING
-		if (m_table.native_endpoint(m.addr))
+		if (m_table.native_endpoint(m.addr) && m_log->should_log(dht_logger::rpc_manager))
 		{
 			m_log->log(dht_logger::rpc_manager, "reply with unknown transaction id size: %d from %s"
 				, int(transaction_id.size()), print_endpoint(m.addr).c_str());
@@ -281,28 +284,34 @@ bool rpc_manager::incoming(msg const& m, node_id* id)
 	time_point now = clock_type::now();
 
 #ifndef TORRENT_DISABLE_LOGGING
-	m_log->log(dht_logger::rpc_manager, "round trip time(ms): %" PRId64 " from %s"
-		, total_milliseconds(now - o->sent()), print_endpoint(m.addr).c_str());
+	if (m_log->should_log(dht_logger::rpc_manager))
+	{
+		m_log->log(dht_logger::rpc_manager, "round trip time(ms): %" PRId64 " from %s"
+			, total_milliseconds(now - o->sent()), print_endpoint(m.addr).c_str());
+	}
 #endif
 
 	if (m.message.dict_find_string_value("y") == "e")
 	{
 		// It's an error.
 #ifndef TORRENT_DISABLE_LOGGING
-		bdecode_node err = m.message.dict_find_list("e");
-		if (err && err.list_size() >= 2
-			&& err.list_at(0).type() == bdecode_node::int_t
-			&& err.list_at(1).type() == bdecode_node::string_t)
+		if (m_log->should_log(dht_logger::rpc_manager))
 		{
-			m_log->log(dht_logger::rpc_manager, "reply with error from %s: (%" PRId64 ") %s"
-				, print_endpoint(m.addr).c_str()
-				, err.list_int_value_at(0)
-				, err.list_string_value_at(1).to_string().c_str());
-		}
-		else
-		{
-			m_log->log(dht_logger::rpc_manager, "reply with (malformed) error from %s"
-				, print_endpoint(m.addr).c_str());
+			bdecode_node err = m.message.dict_find_list("e");
+			if (err && err.list_size() >= 2
+				&& err.list_at(0).type() == bdecode_node::int_t
+				&& err.list_at(1).type() == bdecode_node::string_t)
+			{
+				m_log->log(dht_logger::rpc_manager, "reply with error from %s: (%" PRId64 ") %s"
+					, print_endpoint(m.addr).c_str()
+					, err.list_int_value_at(0)
+					, err.list_string_value_at(1).to_string().c_str());
+			}
+			else
+			{
+				m_log->log(dht_logger::rpc_manager, "reply with (malformed) error from %s"
+					, print_endpoint(m.addr).c_str());
+			}
 		}
 #endif
 		// Logically, we should call o->reply(m) since we get a reply.
@@ -340,9 +349,12 @@ bool rpc_manager::incoming(msg const& m, node_id* id)
 	}
 
 #ifndef TORRENT_DISABLE_LOGGING
-	m_log->log(dht_logger::rpc_manager, "[%p] reply with transaction id: %d from %s"
-		, static_cast<void*>(o->algorithm()), int(transaction_id.size())
-		, print_endpoint(m.addr).c_str());
+	if (m_log->should_log(dht_logger::rpc_manager))
+	{
+		m_log->log(dht_logger::rpc_manager, "[%p] reply with transaction id: %d from %s"
+			, static_cast<void*>(o->algorithm()), int(transaction_id.size())
+			, print_endpoint(m.addr).c_str());
+	}
 #endif
 	o->reply(m);
 	*id = nid;
@@ -379,9 +391,12 @@ time_duration rpc_manager::tick()
 		if (diff >= seconds(timeout))
 		{
 #ifndef TORRENT_DISABLE_LOGGING
-			m_log->log(dht_logger::rpc_manager, "[%p] timing out transaction id: %d from: %s"
-				, static_cast<void*>(o->algorithm()), o->transaction_id()
-				, print_endpoint(o->target_ep()).c_str());
+			if (m_log->should_log(dht_logger::rpc_manager))
+			{
+				m_log->log(dht_logger::rpc_manager, "[%p] timing out transaction id: %d from: %s"
+					, static_cast<void*>(o->algorithm()), o->transaction_id()
+					, print_endpoint(o->target_ep()).c_str());
+			}
 #endif
 			m_transactions.erase(i++);
 			timeouts.push_back(o);
@@ -393,9 +408,12 @@ time_duration rpc_manager::tick()
 		if (diff >= seconds(short_timeout) && !o->has_short_timeout())
 		{
 #ifndef TORRENT_DISABLE_LOGGING
-			m_log->log(dht_logger::rpc_manager, "[%p] short-timing out transaction id: %d from: %s"
-				, static_cast<void*>(o->algorithm()), o->transaction_id()
-				, print_endpoint(o->target_ep()).c_str());
+			if (m_log->should_log(dht_logger::rpc_manager))
+			{
+				m_log->log(dht_logger::rpc_manager, "[%p] short-timing out transaction id: %d from: %s"
+					, static_cast<void*>(o->algorithm()), o->transaction_id()
+					, print_endpoint(o->target_ep()).c_str());
+			}
 #endif
 			++i;
 

src/session_impl.cpp

@@ -1983,9 +1983,8 @@ namespace aux {
 	void session_impl::remap_ports(remap_port_mask_t const mask
 		, listen_socket_t& s)
 	{
-		error_code ec;
-		tcp::endpoint const tcp_ep = s.sock ? s.sock->local_endpoint(ec) : tcp::endpoint();
-		udp::endpoint const udp_ep = s.udp_sock ? s.udp_sock->local_endpoint(ec) : udp::endpoint();
+		tcp::endpoint const tcp_ep = s.sock ? s.sock->local_endpoint() : tcp::endpoint();
+		udp::endpoint const udp_ep = s.udp_sock ? s.udp_sock->local_endpoint() : udp::endpoint();
 
 		if ((mask & remap_natpmp) && m_natpmp)
 		{
@@ -2277,8 +2276,7 @@ namespace aux {
 		{
 			std::shared_ptr<udp_socket> s = socket.lock();
 			udp::endpoint ep;
-			error_code best_effort;
-			if (s) ep = s->local_endpoint(best_effort);
+			if (s) ep = s->local_endpoint();
 
 			// don't bubble up operation aborted errors to the user
 			if (ec != boost::asio::error::operation_aborted
@@ -2364,8 +2362,7 @@ namespace aux {
 
 			if (err)
 			{
-				error_code best_effort;
-				udp::endpoint ep = s->local_endpoint(best_effort);
+				udp::endpoint const ep = s->local_endpoint();
 
 				if (err != boost::asio::error::operation_aborted
 					&& m_alerts.should_post<udp_error_alert>())
@@ -6009,31 +6006,28 @@ namespace aux {
 	void session_impl::update_peer_tos()
 	{
 		int const tos = m_settings.get_int(settings_pack::peer_tos);
-		for (std::list<listen_socket_t>::iterator i = m_listen_sockets.begin()
-			, end(m_listen_sockets.end()); i != end; ++i)
+		for (auto const& l : m_listen_sockets)
 		{
 			error_code ec;
-			set_tos(*i->sock, tos, ec);
+			set_tos(*l.sock, tos, ec);
 
 #ifndef TORRENT_DISABLE_LOGGING
 			if (should_log())
 			{
-				error_code err;
 				session_log(">>> SET_TOS [ tcp (%s %d) tos: %x e: %s ]"
-					, i->sock->local_endpoint(err).address().to_string().c_str()
-					, i->sock->local_endpoint(err).port(), tos, ec.message().c_str());
+					, l.sock->local_endpoint().address().to_string().c_str()
+					, l.sock->local_endpoint().port(), tos, ec.message().c_str());
 			}
 #endif
 			ec.clear();
-			set_tos(*i->udp_sock, tos, ec);
+			set_tos(*l.udp_sock, tos, ec);
 
 #ifndef TORRENT_DISABLE_LOGGING
 			if (should_log())
 			{
-				error_code err;
 				session_log(">>> SET_TOS [ udp (%s %d) tos: %x e: %s ]"
-					, i->udp_sock->local_endpoint(err).address().to_string().c_str()
-					, i->udp_sock->local_port()
+					, l.udp_sock->local_endpoint().address().to_string().c_str()
+					, l.udp_sock->local_port()
 					, tos, ec.message().c_str());
 			}
 #endif
@@ -6179,29 +6173,28 @@ namespace aux {
 
 	void session_impl::update_socket_buffer_size()
 	{
-		for (std::list<listen_socket_t>::iterator i = m_listen_sockets.begin()
-			, end(m_listen_sockets.end()); i != end; ++i)
+		for (auto const& l : m_listen_sockets)
 		{
 			error_code ec;
-			set_socket_buffer_size(*i->udp_sock, m_settings, ec);
+			set_socket_buffer_size(*l.udp_sock, m_settings, ec);
 #ifndef TORRENT_DISABLE_LOGGING
 			if (ec && should_log())
 			{
 				error_code err;
 				session_log("socket buffer size [ udp %s %d]: (%d) %s"
-				, i->udp_sock->local_endpoint(err).address().to_string(err).c_str()
-				, i->udp_sock->local_port(), ec.value(), ec.message().c_str());
+					, l.udp_sock->local_endpoint().address().to_string(err).c_str()
+					, l.udp_sock->local_port(), ec.value(), ec.message().c_str());
 			}
 #endif
 			ec.clear();
-			set_socket_buffer_size(*i->sock, m_settings, ec);
+			set_socket_buffer_size(*l.sock, m_settings, ec);
 #ifndef TORRENT_DISABLE_LOGGING
 			if (ec && should_log())
 			{
 				error_code err;
 				session_log("socket buffer size [ udp %s %d]: (%d) %s"
-				, i->sock->local_endpoint(err).address().to_string(err).c_str()
-				, i->sock->local_endpoint(err).port(), ec.value(), ec.message().c_str());
+					, l.sock->local_endpoint().address().to_string(err).c_str()
+					, l.sock->local_endpoint().port(), ec.value(), ec.message().c_str());
 			}
 #endif
 		}