Skip to content

Commit

Permalink
KcpPeer: explicit logging with identifier for easier debugging
Browse files Browse the repository at this point in the history
  • Loading branch information
mischa committed Oct 28, 2023
1 parent f415a84 commit 9215db3
Show file tree
Hide file tree
Showing 4 changed files with 39 additions and 29 deletions.
1 change: 1 addition & 0 deletions kcp2k/kcp2k.Tests/KcpPeerTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ public MockPeer(KcpConfig config) : base(
() => {},
(_, _) => {},
config,
"KcpMockPeer",
0) {}
}

Expand Down
2 changes: 1 addition & 1 deletion kcp2k/kcp2k/highlevel/KcpClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
63 changes: 36 additions & 27 deletions kcp2k/kcp2k/highlevel/KcpPeer.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -171,8 +176,12 @@ public KcpPeer(
Action OnDisconnected,
Action<ErrorCode, string> 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;
Expand Down Expand Up @@ -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();
}
}
Expand All @@ -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();
}
}
Expand Down Expand Up @@ -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.");
Expand Down Expand Up @@ -299,7 +308,7 @@ bool ReceiveNextReliable(out KcpHeader header, out ArraySegment<byte> 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;
}
Expand All @@ -311,7 +320,7 @@ bool ReceiveNextReliable(out KcpHeader header, out ArraySegment<byte> 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;
}
Expand Down Expand Up @@ -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;
}
Expand All @@ -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;
Expand All @@ -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;
}
Expand All @@ -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;
}
Expand All @@ -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;
Expand All @@ -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;
}
Expand Down Expand Up @@ -468,23 +477,23 @@ 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)
{
// 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)
{
// 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();
}
}
Expand Down Expand Up @@ -517,23 +526,23 @@ 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)
{
// 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)
{
// 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();
}
}
Expand All @@ -545,7 +554,7 @@ void OnRawInputReliable(ArraySegment<byte> 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}");
}
}

Expand Down Expand Up @@ -596,7 +605,7 @@ void OnRawInputUnreliable(ArraySegment<byte> 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.");
}
}

Expand All @@ -621,7 +630,7 @@ public void RawInput(ArraySegment<byte> 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;
}

Expand All @@ -645,7 +654,7 @@ public void RawInput(ArraySegment<byte> 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;
}
}
Expand Down Expand Up @@ -678,7 +687,7 @@ void SendReliable(KcpHeader header, ArraySegment<byte> 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;
}

Expand All @@ -694,7 +703,7 @@ void SendReliable(KcpHeader header, ArraySegment<byte> 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}");
}
}

Expand All @@ -705,7 +714,7 @@ void SendUnreliable(ArraySegment<byte> 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;
}

Expand Down Expand Up @@ -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<byte>(cookieBytes));
}

Expand All @@ -758,7 +767,7 @@ public void SendData(ArraySegment<byte> 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;
}
Expand Down Expand Up @@ -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();
}
Expand Down
2 changes: 1 addition & 1 deletion kcp2k/kcp2k/highlevel/KcpServer.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down

0 comments on commit 9215db3

Please sign in to comment.