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.
This commit is contained in:
sfan5 2024-08-31 17:16:48 +02:00
parent f54f2c1601
commit 72c306d920
5 changed files with 26 additions and 86 deletions

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

@ -1009,7 +1009,13 @@ void UDPPeer::reportRTT(float rtt)
if (timeout > RESEND_TIMEOUT_MAX) if (timeout > RESEND_TIMEOUT_MAX)
timeout = RESEND_TIMEOUT_MAX; timeout = RESEND_TIMEOUT_MAX;
float timeout_old = getResendTimeout();
setResendTimeout(timeout); 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) bool UDPPeer::Ping(float dtime,SharedBuffer<u8>& data)
@ -1129,7 +1135,7 @@ bool UDPPeer::processReliableSendCommand(
u16 packets_available = toadd.size(); u16 packets_available = toadd.size();
/* we didn't get a single sequence number no need to fill queue */ /* we didn't get a single sequence number no need to fill queue */
if (!have_initial_sequence_number) { 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; return false;
} }

@ -35,7 +35,6 @@ namespace con
#define PROFILE(a) #define PROFILE(a)
#undef DEBUG_CONNECTION_KBPS #undef DEBUG_CONNECTION_KBPS
#else #else
/* this mutex is used to achieve log message consistency */
#define PROFILE(a) a #define PROFILE(a) a
//#define DEBUG_CONNECTION_KBPS //#define DEBUG_CONNECTION_KBPS
#undef DEBUG_CONNECTION_KBPS #undef DEBUG_CONNECTION_KBPS
@ -221,7 +220,8 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
} }
float resend_timeout = udpPeer->getResendTimeout(); 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 // Remove timed out incomplete unreliable split packets
channel.incoming_splits.removeUnreliableTimedOuts(dtime, peer_timeout); channel.incoming_splits.removeUnreliableTimedOuts(dtime, peer_timeout);
@ -242,8 +242,8 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
if (!timed_outs.empty()) { if (!timed_outs.empty()) {
dout_con << m_connection->getDesc() << dout_con << m_connection->getDesc() <<
"Skipping re-send of " << timed_outs.size() << "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; continue;
} }
@ -256,7 +256,14 @@ void ConnectionSendThread::runTimeouts(float dtime, u32 peer_packet_quota)
for (const auto &k : timed_outs) for (const auto &k : timed_outs)
resendReliable(channel, k.get(), resend_timeout); resendReliable(channel, k.get(), resend_timeout);
auto ws_old = channel.getWindowSize();
channel.UpdateTimers(dtime); 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 */ /* send ping if necessary */
@ -309,12 +316,12 @@ void ConnectionSendThread::rawSend(const BufferedPacket *p)
assert(p); assert(p);
try { try {
m_connection->m_udpSocket.Send(p->address, p->data, p->size()); 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) { } catch (SendFailedException &e) {
LOG(derr_con << m_connection->getDesc() LOG(derr_con << m_connection->getDesc()
<< "Connection::rawSend(): SendFailedException: " << "SendFailedException: " << e.what() << " to "
<< p->address.serializeString() << std::endl); << p->address.serializeString() << std::endl);
} }
} }
@ -686,9 +693,9 @@ void ConnectionSendThread::sendPackets(float dtime, u32 peer_packet_quota)
PROFILE(ScopeProfiler PROFILE(ScopeProfiler
peerprofiler(g_profiler, peerIdentifier.str(), SPT_AVG)); 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) // first send queued reliable packets for all peers (if possible)
for (unsigned int i = 0; i < CHANNEL_COUNT; i++) { for (unsigned int i = 0; i < CHANNEL_COUNT; i++) {
@ -1191,7 +1198,7 @@ SharedBuffer<u8> ConnectionReceiveThread::handlePacketType_Control(Channel *chan
// an overflow is quite unlikely but as it'd result in major // an overflow is quite unlikely but as it'd result in major
// rtt miscalculation we handle it here // rtt miscalculation we handle it here
if (current_time > p->absolute_send_time) { 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 // Let peer calculate stuff according to it
// (avg_rtt and resend_timeout) // (avg_rtt and resend_timeout)
@ -1336,12 +1343,6 @@ SharedBuffer<u8> ConnectionReceiveThread::handlePacketType_Reliable(Channel *cha
<< ", seqnum: " << seqnum << std::endl;) << ", seqnum: " << seqnum << std::endl;)
m_connection->sendAck(peer->id, channelnum, seqnum); 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"); throw ProcessedSilentlyException("Retransmitting ack for old packet");
} }
} }

@ -50,9 +50,6 @@ typedef int socklen_t;
#define SOCKET_ERR_STR(e) strerror(e) #define SOCKET_ERR_STR(e) strerror(e)
#endif #endif
// Set to true to enable verbose debug output
bool socket_enable_debug_output = false; // yuck
static bool g_sockets_initialized = false; static bool g_sockets_initialized = false;
// Initialize sockets // Initialize sockets
@ -104,12 +101,6 @@ bool UDPSocket::init(bool ipv6, bool noExceptions)
m_addr_family = ipv6 ? AF_INET6 : AF_INET; m_addr_family = ipv6 ? AF_INET6 : AF_INET;
m_handle = socket(m_addr_family, SOCK_DGRAM, IPPROTO_UDP); 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 (m_handle < 0) {
if (noExceptions) { if (noExceptions) {
return false; return false;
@ -135,11 +126,6 @@ bool UDPSocket::init(bool ipv6, bool noExceptions)
UDPSocket::~UDPSocket() UDPSocket::~UDPSocket()
{ {
if (socket_enable_debug_output) {
tracestream << "UDPSocket( " << (int)m_handle << ")::~UDPSocket()"
<< std::endl;
}
if (m_handle >= 0) { if (m_handle >= 0) {
#ifdef _WIN32 #ifdef _WIN32
closesocket(m_handle); closesocket(m_handle);
@ -151,12 +137,6 @@ UDPSocket::~UDPSocket()
void UDPSocket::Bind(Address addr) 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) { if (addr.getFamily() != m_addr_family) {
const char *errmsg = const char *errmsg =
"Socket and bind address families do not match"; "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) if (INTERNET_SIMULATOR)
dumping_packet = myrand() % INTERNET_SIMULATOR_PACKET_LOSS == 0; 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) { if (dumping_packet) {
// Lol let's forget it // Lol let's forget it
tracestream << "UDPSocket::Send(): INTERNET_SIMULATOR: dumping packet." 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); 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; return received;
} }

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