From 96fbc520717d264c62de424a206c9cd82ec91103 Mon Sep 17 00:00:00 2001 From: sfan5 Date: Sat, 31 Aug 2024 17:16:48 +0200 Subject: [PATCH] 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 | 1 - src/network/connection.cpp | 8 +++- src/network/connectionthreads.cpp | 37 +++++++++--------- src/network/socket.cpp | 64 ------------------------------- src/network/socket.h | 2 - 5 files changed, 26 insertions(+), 86 deletions(-) diff --git a/src/main.cpp b/src/main.cpp index 7474ae84c..5b5243be8 100644 --- a/src/main.cpp +++ b/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; diff --git a/src/network/connection.cpp b/src/network/connection.cpp index 9d0d57e23..304844862 100644 --- a/src/network/connection.cpp +++ b/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& 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; } diff --git a/src/network/connectionthreads.cpp b/src/network/connectionthreads.cpp index 543d93d8d..73a9207ed 100644 --- a/src/network/connectionthreads.cpp +++ b/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 - << " (half-open)." << std::endl; + " timed-out reliables to peer_id=" << udpPeer->id + << " 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() - << " rawSend: " << p->size() - << " bytes sent" << std::endl); + //LOG(dout_con << m_connection->getDesc() + // << " rawSend: " << p->size() + // << " 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() - << " Handle per peer queues: peer_id=" << peerId - << " packet quota: " << peer->m_increment_packets_remaining << std::endl); + //LOG(dout_con << m_connection->getDesc() + // << " Handle per peer queues: peer_id=" << peerId + // << " 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 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 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(&peer)-> - // reportRTT(dynamic_cast(&peer)->getResendTimeout()); - throw ProcessedSilentlyException("Retransmitting ack for old packet"); } } diff --git a/src/network/socket.cpp b/src/network/socket.cpp index 9fbbaa34e..17e71d860 100644 --- a/src/network/socket.cpp +++ b/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; } diff --git a/src/network/socket.h b/src/network/socket.h index c3758a9d8..28b69c7b8 100644 --- a/src/network/socket.h +++ b/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();