Improve some protocol code log messages

also get rid of the very noisy socket debug message that are
useless in a world where Wireshark exists.

src/main.cpp

@@ -531,7 +531,6 @@ static bool setup_log_params(const Settings &cmd_args)
 	if (cmd_args.getFlag("trace")) {
 		dstream << _("Enabling trace level debug output") << std::endl;
 		g_logger.addOutput(&stderr_output, LL_TRACE);
-		socket_enable_debug_output = true;
 	}
 
 	return true;

src/network/connection.cpp

@@ -1009,7 +1009,13 @@ void UDPPeer::reportRTT(float rtt)
 	if (timeout > RESEND_TIMEOUT_MAX)
 		timeout = RESEND_TIMEOUT_MAX;
 
+	float timeout_old = getResendTimeout();
 	setResendTimeout(timeout);
+
+	if (std::abs(timeout - timeout_old) >= 0.001f) {
+		dout_con << m_connection->getDesc() << " set resend timeout " << timeout
+			<< " (rtt=" << rtt_stat << ") for peer id: " << id << std::endl;
+	}
 }
 
 bool UDPPeer::Ping(float dtime,SharedBuffer<u8>& data)
@@ -1129,7 +1135,7 @@ bool UDPPeer::processReliableSendCommand(
 	u16 packets_available = toadd.size();
 	/* we didn't get a single sequence number no need to fill queue */
 	if (!have_initial_sequence_number) {
-		LOG(derr_con << m_connection->getDesc() << "Ran out of sequence numbers!" << std::endl);
+		dout_con << m_connection->getDesc() << " No sequence numbers available!" << std::endl;
 		return false;
 	}
 

src/network/connectionthreads.cpp

@@ -35,7 +35,6 @@ namespace con
 #define PROFILE(a)
 #undef DEBUG_CONNECTION_KBPS
 #else
-/* this mutex is used to achieve log message consistency */
 #define PROFILE(a) a
 //#define DEBUG_CONNECTION_KBPS
 #undef DEBUG_CONNECTION_KBPS
@@ -211,7 +210,8 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
 		}
 
 		float resend_timeout = udpPeer->getResendTimeout();
-		for (Channel &channel : udpPeer->channels) {
+		for (int ch = 0; ch < CHANNEL_COUNT; ch++) {
+			auto &channel = udpPeer->channels[ch];
 
 			// Remove timed out incomplete unreliable split packets
 			channel.incoming_splits.removeUnreliableTimedOuts(dtime, peer_timeout);
@@ -232,8 +232,8 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
 				if (!timed_outs.empty()) {
 					dout_con << m_connection->getDesc() <<
 						"Skipping re-send of " << timed_outs.size() <<
-						" timed-out reliables to peer_id " << udpPeer->id
+						" timed-out reliables to peer_id=" << udpPeer->id
-						<< " (half-open)." << std::endl;
+						<< " channel=" << ch << " (half-open)." << std::endl;
 				}
 				continue;
 			}
@@ -246,7 +246,14 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
 			for (const auto &k : timed_outs)
 				resendReliable(channel, k.get(), resend_timeout);
 
+			auto ws_old = channel.getWindowSize();
 			channel.UpdateTimers(dtime);
+			auto ws_new = channel.getWindowSize();
+			if (ws_old != ws_new) {
+				dout_con << m_connection->getDesc() <<
+					"Window size adjusted to " << ws_new << " for peer_id="
+					<< udpPeer->id << " channel=" << ch << std::endl;
+			}
 		}
 
 		/* send ping if necessary */
@@ -299,12 +306,12 @@ void ConnectionSendThread::rawSend(const BufferedPacket *p)
 	assert(p);
 	try {
 		m_connection->m_udpSocket.Send(p->address, p->data, p->size());
-		LOG(dout_con << m_connection->getDesc()
+		//LOG(dout_con << m_connection->getDesc()
-			<< " rawSend: " << p->size()
+		//	<< " rawSend: " << p->size()
-			<< " bytes sent" << std::endl);
+		//	<< " bytes sent" << std::endl);
 	} catch (SendFailedException &e) {
 		LOG(derr_con << m_connection->getDesc()
-			<< "Connection::rawSend(): SendFailedException: "
+			<< "SendFailedException: " << e.what() << " to "
 			<< p->address.serializeString() << std::endl);
 	}
 }
@@ -676,9 +683,9 @@ void ConnectionSendThread::sendPackets(float dtime, u32 peer_packet_quota)
 		PROFILE(ScopeProfiler
 		peerprofiler(g_profiler, peerIdentifier.str(), SPT_AVG));
 
-		LOG(dout_con << m_connection->getDesc()
+		//LOG(dout_con << m_connection->getDesc()
-			<< " Handle per peer queues: peer_id=" << peerId
+		//	<< " Handle per peer queues: peer_id=" << peerId
-			<< " packet quota: " << peer->m_increment_packets_remaining << std::endl);
+		//	<< " packet quota: " << peer->m_increment_packets_remaining << std::endl);
 
 		// first send queued reliable packets for all peers (if possible)
 		for (unsigned int i = 0; i < CHANNEL_COUNT; i++) {
@@ -1181,7 +1188,7 @@ SharedBuffer<u8> ConnectionReceiveThread::handlePacketType_Control(Channel *chan
 				// an overflow is quite unlikely but as it'd result in major
 				// rtt miscalculation we handle it here
 				if (current_time > p->absolute_send_time) {
-					float rtt = (current_time - p->absolute_send_time) / 1000.0;
+					float rtt = (current_time - p->absolute_send_time) / 1000.0f;
 
 					// Let peer calculate stuff according to it
 					// (avg_rtt and resend_timeout)
@@ -1326,12 +1333,6 @@ SharedBuffer<u8> ConnectionReceiveThread::handlePacketType_Reliable(Channel *cha
 				<< ", seqnum: " << seqnum << std::endl;)
 			m_connection->sendAck(peer->id, channelnum, seqnum);
 
-			// we already have this packet so this one was on wire at least
-			// the current timeout
-			// we don't know how long this packet was on wire don't do silly guessing
-			// dynamic_cast<UDPPeer*>(&peer)->
-			//     reportRTT(dynamic_cast<UDPPeer*>(&peer)->getResendTimeout());
-
 			throw ProcessedSilentlyException("Retransmitting ack for old packet");
 		}
 	}

src/network/socket.cpp

@@ -50,9 +50,6 @@ typedef int socklen_t;
 #define SOCKET_ERR_STR(e) strerror(e)
 #endif
 
-// Set to true to enable verbose debug output
-bool socket_enable_debug_output = false; // yuck
-
 static bool g_sockets_initialized = false;
 
 // Initialize sockets
@@ -104,12 +101,6 @@ bool UDPSocket::init(bool ipv6, bool noExceptions)
 	m_addr_family = ipv6 ? AF_INET6 : AF_INET;
 	m_handle = socket(m_addr_family, SOCK_DGRAM, IPPROTO_UDP);
 
-	if (socket_enable_debug_output) {
-		tracestream << "UDPSocket(" << (int)m_handle
-			<< ")::UDPSocket(): ipv6 = " << (ipv6 ? "true" : "false")
-			<< std::endl;
-	}
-
 	if (m_handle < 0) {
 		if (noExceptions) {
 			return false;
@@ -135,11 +126,6 @@ bool UDPSocket::init(bool ipv6, bool noExceptions)
 
 UDPSocket::~UDPSocket()
 {
-	if (socket_enable_debug_output) {
-		tracestream << "UDPSocket( " << (int)m_handle << ")::~UDPSocket()"
-			<< std::endl;
-	}
-
 	if (m_handle >= 0) {
 #ifdef _WIN32
 		closesocket(m_handle);
@@ -151,12 +137,6 @@ UDPSocket::~UDPSocket()
 
 void UDPSocket::Bind(Address addr)
 {
-	if (socket_enable_debug_output) {
-		tracestream << "UDPSocket(" << (int)m_handle
-			<< ")::Bind(): " << addr.serializeString() << ":"
-			<< addr.getPort() << std::endl;
-	}
-
 	if (addr.getFamily() != m_addr_family) {
 		const char *errmsg =
 				"Socket and bind address families do not match";
@@ -202,30 +182,6 @@ void UDPSocket::Send(const Address &destination, const void *data, int size)
 	if (INTERNET_SIMULATOR)
 		dumping_packet = myrand() % INTERNET_SIMULATOR_PACKET_LOSS == 0;
 
-	if (socket_enable_debug_output) {
-		// Print packet destination and size
-		tracestream << (int)m_handle << " -> ";
-		destination.print(tracestream);
-		tracestream << ", size=" << size;
-
-		// Print packet contents
-		tracestream << ", data=";
-		for (int i = 0; i < size && i < 20; i++) {
-			if (i % 2 == 0)
-				tracestream << " ";
-			unsigned int a = ((const unsigned char *)data)[i];
-			tracestream << std::hex << std::setw(2) << std::setfill('0') << a;
-		}
-
-		if (size > 20)
-			tracestream << "...";
-
-		if (dumping_packet)
-			tracestream << " (DUMPED BY INTERNET_SIMULATOR)";
-
-		tracestream << std::endl;
-	}
-
 	if (dumping_packet) {
 		// Lol let's forget it
 		tracestream << "UDPSocket::Send(): INTERNET_SIMULATOR: dumping packet."
@@ -302,26 +258,6 @@ int UDPSocket::Receive(Address &sender, void *data, int size)
 		sender = Address(address_ip, address_port);
 	}
 
-	if (socket_enable_debug_output) {
-		// Print packet sender and size
-		tracestream << (int)m_handle << " <- ";
-		sender.print(tracestream);
-		tracestream << ", size=" << received;
-
-		// Print packet contents
-		tracestream << ", data=";
-		for (int i = 0; i < received && i < 20; i++) {
-			if (i % 2 == 0)
-				tracestream << " ";
-			unsigned int a = ((const unsigned char *)data)[i];
-			tracestream << std::hex << std::setw(2) << std::setfill('0') << a;
-		}
-		if (received > 20)
-			tracestream << "...";
-
-		tracestream << std::endl;
-	}
-
 	return received;
 }
 

src/network/socket.h

@@ -25,8 +25,6 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #include "irrlichttypes.h"
 #include "networkexceptions.h"
 
-extern bool socket_enable_debug_output;
-
 void sockets_init();
 void sockets_cleanup();