From 9215db30fccc0c83ba14435efa3e54c44e7e24b1 Mon Sep 17 00:00:00 2001 From: mischa Date: Sat, 28 Oct 2023 15:14:09 +0200 Subject: [PATCH] KcpPeer: explicit logging with identifier for easier debugging --- kcp2k/kcp2k.Tests/KcpPeerTests.cs | 1 + kcp2k/kcp2k/highlevel/KcpClient.cs | 2 +- kcp2k/kcp2k/highlevel/KcpPeer.cs | 63 +++++++++++++++++------------- kcp2k/kcp2k/highlevel/KcpServer.cs | 2 +- 4 files changed, 39 insertions(+), 29 deletions(-) diff --git a/kcp2k/kcp2k.Tests/KcpPeerTests.cs b/kcp2k/kcp2k.Tests/KcpPeerTests.cs index dc8dda7..f064776 100644 --- a/kcp2k/kcp2k.Tests/KcpPeerTests.cs +++ b/kcp2k/kcp2k.Tests/KcpPeerTests.cs @@ -11,6 +11,7 @@ public MockPeer(KcpConfig config) : base( () => {}, (_, _) => {}, config, + "KcpMockPeer", 0) {} } diff --git a/kcp2k/kcp2k/highlevel/KcpClient.cs b/kcp2k/kcp2k/highlevel/KcpClient.cs index d275e01..056ae60 100644 --- a/kcp2k/kcp2k/highlevel/KcpClient.cs +++ b/kcp2k/kcp2k/highlevel/KcpClient.cs @@ -83,7 +83,7 @@ public void Connect(string address, ushort port) // create fresh peer for each new session // client doesn't need secure cookie. - peer = new KcpPeer(RawSend, OnAuthenticatedWrap, OnData, OnDisconnectedWrap, OnError, config, 0); + peer = new KcpPeer(RawSend, OnAuthenticatedWrap, OnData, OnDisconnectedWrap, OnError, config, "KcpClientPeer", 0); // some callbacks need to wrapped with some extra logic void OnAuthenticatedWrap() diff --git a/kcp2k/kcp2k/highlevel/KcpPeer.cs b/kcp2k/kcp2k/highlevel/KcpPeer.cs index e78261e..7d01c91 100644 --- a/kcp2k/kcp2k/highlevel/KcpPeer.cs +++ b/kcp2k/kcp2k/highlevel/KcpPeer.cs @@ -12,6 +12,11 @@ enum KcpState { Connected, Authenticated, Disconnected } public class KcpPeer { + // identifier for logging. + // we don't just want to show "KcpPeer" on server and client. + // name it "KcpClient/ServerPeer". + readonly string identifier; + // kcp reliability algorithm internal Kcp kcp; @@ -171,8 +176,12 @@ public KcpPeer( Action OnDisconnected, Action OnError, KcpConfig config, + String identifier, uint cookie) { + // initialize logging identifier + this.identifier = identifier; + // initialize callbacks first to ensure they can be used safely. this.OnAuthenticated = OnAuthenticated; this.OnData = OnData; @@ -225,7 +234,7 @@ void HandleTimeout(uint time) { // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.Timeout, $"KcpPeer: Connection timed out after not receiving any message for {timeout}ms. Disconnecting."); + OnError(ErrorCode.Timeout, $"{identifier}: Connection timed out after not receiving any message for {timeout}ms. Disconnecting."); Disconnect(); } } @@ -237,7 +246,7 @@ void HandleDeadLink() { // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.Timeout, $"KcpPeer: dead_link detected: a message was retransmitted {kcp.dead_link} times without ack. Disconnecting."); + OnError(ErrorCode.Timeout, $"{identifier}: dead_link detected: a message was retransmitted {kcp.dead_link} times without ack. Disconnecting."); Disconnect(); } } @@ -267,7 +276,7 @@ void HandleChoked() // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. OnError(ErrorCode.Congestion, - $"KcpPeer: disconnecting connection because it can't process data fast enough.\n" + + $"{identifier}: disconnecting connection because it can't process data fast enough.\n" + $"Queue total {total}>{QueueDisconnectThreshold}. rcv_queue={kcp.rcv_queue.Count} snd_queue={kcp.snd_queue.Count} rcv_buf={kcp.rcv_buf.Count} snd_buf={kcp.snd_buf.Count}\n" + $"* Try to Enable NoDelay, decrease INTERVAL, disable Congestion Window (= enable NOCWND!), increase SEND/RECV WINDOW or compress data.\n" + $"* Or perhaps the network is simply too slow on our end, or on the other end."); @@ -299,7 +308,7 @@ bool ReceiveNextReliable(out KcpHeader header, out ArraySegment message) // we don't allow sending messages > Max, so this must be an // attacker. let's disconnect to avoid allocation attacks etc. // pass error to user callback. no need to log it manually. - OnError(ErrorCode.InvalidReceive, $"KcpPeer: possible allocation attack for msgSize {msgSize} > buffer {kcpMessageBuffer.Length}. Disconnecting the connection."); + OnError(ErrorCode.InvalidReceive, $"{identifier}: possible allocation attack for msgSize {msgSize} > buffer {kcpMessageBuffer.Length}. Disconnecting the connection."); Disconnect(); return false; } @@ -311,7 +320,7 @@ bool ReceiveNextReliable(out KcpHeader header, out ArraySegment message) // if receive failed, close everything // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidReceive, $"KcpPeer: Receive failed with error={received}. closing connection."); + OnError(ErrorCode.InvalidReceive, $"{identifier}: Receive failed with error={received}. closing connection."); Disconnect(); return false; } @@ -346,7 +355,7 @@ void TickIncoming_Connected(uint time) if (message.Count != 4) { // pass error to user callback. no need to log it manually. - OnError(ErrorCode.InvalidReceive, $"KcpPeer: received invalid handshake message with size {message.Count} != 4. Disconnecting the connection."); + OnError(ErrorCode.InvalidReceive, $"{identifier}: received invalid handshake message with size {message.Count} != 4. Disconnecting the connection."); Disconnect(); return; } @@ -356,7 +365,7 @@ void TickIncoming_Connected(uint time) Buffer.BlockCopy(message.Array, message.Offset, receivedCookie, 0, 4); uint prettyCookie = BitConverter.ToUInt32(message.Array, message.Offset); - Log.Info($"KcpPeer: received handshake with cookie={prettyCookie}"); + Log.Info($"{identifier}: received handshake with cookie={prettyCookie}"); state = KcpState.Authenticated; OnAuthenticated?.Invoke(); break; @@ -372,7 +381,7 @@ void TickIncoming_Connected(uint time) // everything else is not allowed during handshake! // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidReceive, $"KcpPeer: received invalid header {header} while Connected. Disconnecting the connection."); + OnError(ErrorCode.InvalidReceive, $"{identifier}: received invalid header {header} while Connected. Disconnecting the connection."); Disconnect(); break; } @@ -398,7 +407,7 @@ void TickIncoming_Authenticated(uint time) { // should never receive another handshake after auth // GetType() shows Server/ClientConn instead of just Connection. - Log.Warning($"KcpPeer: received invalid header {header} while Authenticated. Disconnecting the connection."); + Log.Warning($"{identifier}: received invalid header {header} while Authenticated. Disconnecting the connection."); Disconnect(); break; } @@ -415,7 +424,7 @@ void TickIncoming_Authenticated(uint time) { // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidReceive, $"KcpPeer: received empty Data message while Authenticated. Disconnecting the connection."); + OnError(ErrorCode.InvalidReceive, $"{identifier}: received empty Data message while Authenticated. Disconnecting the connection."); Disconnect(); } break; @@ -429,7 +438,7 @@ void TickIncoming_Authenticated(uint time) { // disconnect might happen // GetType() shows Server/ClientConn instead of just Connection. - Log.Info($"KcpPeer: received disconnect message"); + Log.Info($"{identifier}: received disconnect message"); Disconnect(); break; } @@ -468,7 +477,7 @@ public void TickIncoming() // this is ok, the connection was closed // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.ConnectionClosed, $"KcpPeer: Disconnecting because {exception}. This is fine."); + OnError(ErrorCode.ConnectionClosed, $"{identifier}: Disconnecting because {exception}. This is fine."); Disconnect(); } catch (ObjectDisposedException exception) @@ -476,7 +485,7 @@ public void TickIncoming() // fine, socket was closed // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.ConnectionClosed, $"KcpPeer: Disconnecting because {exception}. This is fine."); + OnError(ErrorCode.ConnectionClosed, $"{identifier}: Disconnecting because {exception}. This is fine."); Disconnect(); } catch (Exception exception) @@ -484,7 +493,7 @@ public void TickIncoming() // unexpected // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.Unexpected, $"KcpPeer: unexpected Exception: {exception}"); + OnError(ErrorCode.Unexpected, $"{identifier}: unexpected Exception: {exception}"); Disconnect(); } } @@ -517,7 +526,7 @@ public void TickOutgoing() // this is ok, the connection was closed // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.ConnectionClosed, $"KcpPeer: Disconnecting because {exception}. This is fine."); + OnError(ErrorCode.ConnectionClosed, $"{identifier}: Disconnecting because {exception}. This is fine."); Disconnect(); } catch (ObjectDisposedException exception) @@ -525,7 +534,7 @@ public void TickOutgoing() // fine, socket was closed // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.ConnectionClosed, $"KcpPeer: Disconnecting because {exception}. This is fine."); + OnError(ErrorCode.ConnectionClosed, $"{identifier}: Disconnecting because {exception}. This is fine."); Disconnect(); } catch (Exception exception) @@ -533,7 +542,7 @@ public void TickOutgoing() // unexpected // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.Unexpected, $"KcpPeer: unexpected exception: {exception}"); + OnError(ErrorCode.Unexpected, $"{identifier}: unexpected exception: {exception}"); Disconnect(); } } @@ -545,7 +554,7 @@ void OnRawInputReliable(ArraySegment message) if (input != 0) { // GetType() shows Server/ClientConn instead of just Connection. - Log.Warning($"KcpPeer: Input failed with error={input} for buffer with length={message.Count - 1}"); + Log.Warning($"{identifier}: Input failed with error={input} for buffer with length={message.Count - 1}"); } } @@ -596,7 +605,7 @@ void OnRawInputUnreliable(ArraySegment message) // add another 'round trip time' of latency to the handshake. // // it's best to simply ignore invalid unreliable messages here. - // Log.Info($"KcpPeer: received unreliable message while not authenticated."); + // Log.Info($"{identifier}: received unreliable message while not authenticated."); } } @@ -621,7 +630,7 @@ public void RawInput(ArraySegment segment) // simply drop the message if the cookie doesn't match. if (state == KcpState.Authenticated && messageCookie != cookie) { - Log.Warning($"KcpPeer: dropped message with invalid cookie: {messageCookie} expected: {cookie}."); + Log.Warning($"{identifier}: dropped message with invalid cookie: {messageCookie} expected: {cookie}."); return; } @@ -645,7 +654,7 @@ public void RawInput(ArraySegment segment) // invalid channel indicates random internet noise. // servers may receive random UDP data. // just ignore it, but log for easier debugging. - Log.Warning($"KcpPeer: invalid channel header: {channel}, likely internet noise"); + Log.Warning($"{identifier}: invalid channel header: {channel}, likely internet noise"); break; } } @@ -678,7 +687,7 @@ void SendReliable(KcpHeader header, ArraySegment content) { // otherwise content is larger than MaxMessageSize. let user know! // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidSend, $"KcpPeer: Failed to send reliable message of size {content.Count} because it's larger than ReliableMaxMessageSize={reliableMax}"); + OnError(ErrorCode.InvalidSend, $"{identifier}: Failed to send reliable message of size {content.Count} because it's larger than ReliableMaxMessageSize={reliableMax}"); return; } @@ -694,7 +703,7 @@ void SendReliable(KcpHeader header, ArraySegment content) if (sent < 0) { // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidSend, $"KcpPeer: Send failed with error={sent} for content with length={content.Count}"); + OnError(ErrorCode.InvalidSend, $"{identifier}: Send failed with error={sent} for content with length={content.Count}"); } } @@ -705,7 +714,7 @@ void SendUnreliable(ArraySegment message) { // otherwise content is larger than MaxMessageSize. let user know! // GetType() shows Server/ClientConn instead of just Connection. - Log.Error($"KcpPeer: Failed to send unreliable message of size {message.Count} because it's larger than UnreliableMaxMessageSize={unreliableMax}"); + Log.Error($"{identifier}: Failed to send unreliable message of size {message.Count} because it's larger than UnreliableMaxMessageSize={unreliableMax}"); return; } @@ -744,7 +753,7 @@ public void SendHandshake() byte[] cookieBytes = BitConverter.GetBytes(cookie); // GetType() shows Server/ClientConn instead of just Connection. - Log.Info($"KcpPeer: sending Handshake to other end with cookie={cookie}!"); + Log.Info($"{identifier}: sending Handshake to other end with cookie={cookie}!"); SendReliable(KcpHeader.Handshake, new ArraySegment(cookieBytes)); } @@ -758,7 +767,7 @@ public void SendData(ArraySegment data, KcpChannel channel) { // pass error to user callback. no need to log it manually. // GetType() shows Server/ClientConn instead of just Connection. - OnError(ErrorCode.InvalidSend, $"KcpPeer: tried sending empty message. This should never happen. Disconnecting."); + OnError(ErrorCode.InvalidSend, $"{identifier}: tried sending empty message. This should never happen. Disconnecting."); Disconnect(); return; } @@ -811,7 +820,7 @@ public void Disconnect() // set as Disconnected, call event // GetType() shows Server/ClientConn instead of just Connection. - Log.Info($"KcpPeer: Disconnected."); + Log.Info($"{identifier}: Disconnected."); state = KcpState.Disconnected; OnDisconnected?.Invoke(); } diff --git a/kcp2k/kcp2k/highlevel/KcpServer.cs b/kcp2k/kcp2k/highlevel/KcpServer.cs index 9b9e1a3..2942e18 100644 --- a/kcp2k/kcp2k/highlevel/KcpServer.cs +++ b/kcp2k/kcp2k/highlevel/KcpServer.cs @@ -213,7 +213,7 @@ protected virtual KcpServerConnection CreateConnection(int connectionId) uint cookie = Common.GenerateCookie(); // set up peer with callbacks - KcpPeer peer = new KcpPeer(RawSendWrap, OnAuthenticatedWrap, OnDataWrap, OnDisconnectedWrap, OnErrorWrap, config, cookie); + KcpPeer peer = new KcpPeer(RawSendWrap, OnAuthenticatedWrap, OnDataWrap, OnDisconnectedWrap, OnErrorWrap, config, "KcpServerPeer", cookie); // assign peer to connection connection.peer = peer;