Skip to content

Commit

Permalink
Warning/error logs don't allocate if disabled.
Browse files Browse the repository at this point in the history 
This should completely eliminate all performance overhead from the logging when it's disabled. This proves relevant during DDoS attacks, as the logging is actually a serious amplifier for even low-bandwidth UDP spam.

This is done by moving it to an interpolated string handler, so we can skip running string formatting and such when the log channel is disabled.
  • Loading branch information
@PJB3005
PJB3005 committed May 3, 2024
1 parent 32820c3 commit bc643a1
Show file tree
Hide file tree
Showing 10 changed files with 139 additions and 58 deletions.
10 changes: 6 additions & 4 deletions Lidgren.Network/NetConnection.Handshake.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,7 +89,7 @@ internal void UnconnectedHeartbeat(double now)
case NetConnectionStatus.None:
case NetConnectionStatus.ReceivedInitiation:
default:
m_peer.LogWarning("Time to resend handshake, but status is " + m_status);
m_peer.LogWarning($"Time to resend handshake, but status is {m_status}");
break;
}
}
Expand Down Expand Up @@ -231,7 +231,8 @@ public void Approve()
{
if (m_status != NetConnectionStatus.RespondedAwaitingApproval)
{
m_peer.LogWarning("Approve() called in wrong status; expected RespondedAwaitingApproval; got " + m_status);
m_peer.LogWarning(
$"Approve() called in wrong status; expected RespondedAwaitingApproval; got {m_status}");
return;
}

Expand All @@ -248,7 +249,8 @@ public void Approve(NetOutgoingMessage localHail)
{
if (m_status != NetConnectionStatus.RespondedAwaitingApproval)
{
m_peer.LogWarning("Approve() called in wrong status; expected RespondedAwaitingApproval; got " + m_status);
m_peer.LogWarning(
$"Approve() called in wrong status; expected RespondedAwaitingApproval; got {m_status}");
return;
}

Expand Down Expand Up @@ -468,7 +470,7 @@ private bool ValidateHandshakeData(int ptr, int payloadLength, out byte[]? hail)
{
// whatever; we failed
ExecuteDisconnect("Handshake data validation failed", true);
m_peer.LogWarning("ReadRemoteHandshakeData failed: " + ex.Message);
m_peer.LogWarning($"ReadRemoteHandshakeData failed: {ex.Message}");
return false;
}
return true;
Expand Down
2 changes: 1 addition & 1 deletion Lidgren.Network/NetConnection.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -476,7 +476,7 @@ internal void ReceivedLibraryMessage(NetMessageType tp, int ptr, int payloadLeng
m_peer.HandleNatIntroduction(ptr);
break;
default:
m_peer.LogWarning("Connection received unhandled library message: " + tp);
m_peer.LogWarning($"Connection received unhandled library message: {tp}");
break;
}
}
Expand Down
16 changes: 8 additions & 8 deletions Lidgren.Network/NetPeer.Internal.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -104,7 +104,7 @@ internal void ReleaseMessage(NetIncomingMessage msg)
}
catch (Exception ex)
{
LogWarning("Receive callback exception:" + ex);
LogWarning($"Receive callback exception:{ex}");
}
}
}
Expand Down Expand Up @@ -439,7 +439,7 @@ private void Heartbeat()
return;

default:
LogWarning("Socket exception: " + sx.ToString());
LogWarning($"Socket exception: {sx}");
return;
}
}
Expand Down Expand Up @@ -527,14 +527,14 @@ private void ReceiveSocketData(double now)

if (bytesReceived - ptr < payloadByteLength)
{
LogWarning("Malformed packet from " + (NetEndPoint)senderRemote + "; stated payload length " + payloadByteLength
+ ", remaining bytes " + (bytesReceived - ptr));
LogWarning(
$"Malformed packet from {(NetEndPoint)senderRemote}; stated payload length {payloadByteLength}, remaining bytes {(bytesReceived - ptr)}");
return;
}

if (tp >= NetMessageType.Unused1 && tp <= NetMessageType.Unused29)
{
ThrowOrLog("Unexpected NetMessageType: " + tp);
LogWarning($"Unexpected NetMessageType: {tp}");
return;
}

Expand Down Expand Up @@ -587,7 +587,7 @@ private void ReceiveSocketData(double now)
}
catch (Exception ex)
{
LogError("Packet parsing error: " + ex.Message + " from " + (NetEndPoint)senderRemote);
LogError($"Packet parsing error: {ex.Message} from {(NetEndPoint)senderRemote}");
}
ptr += payloadByteLength;
}
Expand Down Expand Up @@ -725,7 +725,7 @@ private void ReceivedUnconnectedLibraryMessage(double now, NetEndPoint senderEnd
}
}

LogWarning("Received unhandled library message " + tp + " from " + senderEndPoint);
LogWarning($"Received unhandled library message {tp} from {senderEndPoint}");
return;
case NetMessageType.Connect:
if (m_configuration.AcceptIncomingConnections == false)
Expand Down Expand Up @@ -758,7 +758,7 @@ private void ReceivedUnconnectedLibraryMessage(double now, NetEndPoint senderEnd
LogVerbose("Received Disconnect from unconnected source: " + senderEndPoint);
return;
default:
LogWarning("Received unhandled library message " + tp + " from " + senderEndPoint);
LogWarning($"Received unhandled library message {tp} from {senderEndPoint}");
return;
}
}
Expand Down
12 changes: 6 additions & 6 deletions Lidgren.Network/NetPeer.LatencySimulation.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -183,7 +183,7 @@ internal bool ActuallySendPacket(byte[] data, int numBytes, NetEndPoint target,

int bytesSent = NetFastSocket.SendTo(m_socket, data, 0, numBytes, SocketFlags.None, realTarget);
if (numBytes != bytesSent)
LogWarning("Failed to send the full " + numBytes + "; only " + bytesSent + " bytes sent in packet!");
LogWarning($"Failed to send the full {numBytes}; only {bytesSent} bytes sent in packet!");

// LogDebug("Sent " + numBytes + " bytes");
}
Expand All @@ -201,11 +201,11 @@ internal bool ActuallySendPacket(byte[] data, int numBytes, NetEndPoint target,
connectionReset = true;
return false;
}
LogError("Failed to send packet: " + sx);
LogError($"Failed to send packet: {sx}");
}
catch (Exception ex)
{
LogError("Failed to send packet: " + ex);
LogError($"Failed to send packet: {ex}");
}
finally
{
Expand All @@ -232,7 +232,7 @@ internal bool SendMTUPacket(int numBytes, NetEndPoint target)

int bytesSent = NetFastSocket.SendTo(m_socket, m_sendBuffer, 0, numBytes, SocketFlags.None, target);
if (numBytes != bytesSent)
LogWarning("Failed to send the full " + numBytes + "; only " + bytesSent + " bytes sent in packet!");
LogWarning($"Failed to send the full {numBytes}; only {bytesSent} bytes sent in packet!");

m_statistics.PacketSent(numBytes, 1);
}
Expand All @@ -248,11 +248,11 @@ internal bool SendMTUPacket(int numBytes, NetEndPoint target)
}
if (sx.SocketErrorCode == SocketError.ConnectionReset)
return true;
LogError("Failed to send packet: (" + sx.SocketErrorCode + ") " + sx);
LogError($"Failed to send packet: ({sx.SocketErrorCode}) {sx}");
}
catch (Exception ex)
{
LogError("Failed to send packet: " + ex);
LogError($"Failed to send packet: {ex}");
}
finally
{
Expand Down
139 changes: 109 additions & 30 deletions Lidgren.Network/NetPeer.Logging.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,53 +19,132 @@ USE OR OTHER DEALINGS IN THE SOFTWARE.

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;

namespace Lidgren.Network
namespace Lidgren.Network;

public partial class NetPeer
{
public partial class NetPeer
{
internal event Action<NetIncomingMessageType, string>? LogEvent;
internal event Action<NetIncomingMessageType, string>? LogEvent;

[Conditional("DEBUG")]
internal void LogVerbose(string message)
{
[Conditional("DEBUG")]
internal void LogVerbose(string message)
{
#if __ANDROID__
Android.Util.Log.WriteLine(Android.Util.LogPriority.Verbose, "", message);
Android.Util.Log.WriteLine(Android.Util.LogPriority.Verbose, "", message);
#endif
SendLogBase(NetIncomingMessageType.VerboseDebugMessage, message);
}
SendLogBase(NetIncomingMessageType.VerboseDebugMessage, message);
}

[Conditional("DEBUG")]
internal void LogDebug(string message)
{
[Conditional("DEBUG")]
internal void LogDebug(string message)
{
#if __ANDROID__
Android.Util.Log.WriteLine(Android.Util.LogPriority.Debug, "", message);
Android.Util.Log.WriteLine(Android.Util.LogPriority.Debug, "", message);
#endif
SendLogBase(NetIncomingMessageType.DebugMessage, message);
}
SendLogBase(NetIncomingMessageType.DebugMessage, message);
}

internal void LogWarning(string message)
{
internal void LogWarning(string message)
{
#if __ANDROID__
Android.Util.Log.WriteLine(Android.Util.LogPriority.Warn, "", message);
Android.Util.Log.WriteLine(Android.Util.LogPriority.Warn, "", message);
#endif
SendLogBase(NetIncomingMessageType.WarningMessage, message);
}
SendLogBase(NetIncomingMessageType.WarningMessage, message);
}

internal void LogError(string message)
{
internal void LogError(string message)
{
#if __ANDROID__
Android.Util.Log.WriteLine(Android.Util.LogPriority.Error, "", message);
Android.Util.Log.WriteLine(Android.Util.LogPriority.Error, "", message);
#endif
SendLogBase(NetIncomingMessageType.ErrorMessage, message);
SendLogBase(NetIncomingMessageType.ErrorMessage, message);
}

private void SendLogBase(NetIncomingMessageType type, string text)
{
LogEvent?.Invoke(type, text);

if (m_configuration.IsMessageTypeEnabled(type))
ReleaseMessage(CreateIncomingMessage(type, text));
}

private bool CheckLogEnabled(NetIncomingMessageType type)
{
return m_configuration.IsMessageTypeEnabled(type) || LogEvent != null;
}

#if NET6_0_OR_GREATER && !__ANDROID__
// On supported TFMs, use an interpolated string handler,
// so we can avoid running string formatting if a log level is disabled.
internal void LogWarning([InterpolatedStringHandlerArgument("")] NetWarningLogInterpolatedStringHandler text)
{
SendLogBase(NetIncomingMessageType.WarningMessage, text.Implementation);
}

internal void LogError([InterpolatedStringHandlerArgument("")] NetErrorLogInterpolatedStringHandler text)
{
SendLogBase(NetIncomingMessageType.ErrorMessage, text.Implementation);
}

private void SendLogBase(NetIncomingMessageType type, DefaultInterpolatedStringHandler text)
{
if (!CheckLogEnabled(type))
return;

SendLogBase(type, text.ToStringAndClear());
}

[InterpolatedStringHandler]
internal ref struct NetErrorLogInterpolatedStringHandler
{
public DefaultInterpolatedStringHandler Implementation;

public NetErrorLogInterpolatedStringHandler(
int literalLength,
int formattedCount,
NetPeer peer,
out bool handlerIsValid)
{
handlerIsValid = peer.CheckLogEnabled(NetIncomingMessageType.ErrorMessage);

if (handlerIsValid)
Implementation = new DefaultInterpolatedStringHandler(literalLength, formattedCount);
}

private void SendLogBase(NetIncomingMessageType type, string text)
public void AppendLiteral(string value)
=> Implementation.AppendLiteral(value);

public void AppendFormatted<T>(T t, int alignment = 0, string? format = null)
=> Implementation.AppendFormatted(t, alignment, format);

public string ToStringAndClear() => Implementation.ToStringAndClear();
}

[InterpolatedStringHandler]
internal ref struct NetWarningLogInterpolatedStringHandler
{
public DefaultInterpolatedStringHandler Implementation;

public NetWarningLogInterpolatedStringHandler(
int literalLength,
int formattedCount,
NetPeer peer,
out bool handlerIsValid)
{
LogEvent?.Invoke(type, text);
handlerIsValid = peer.CheckLogEnabled(NetIncomingMessageType.WarningMessage);

if (m_configuration.IsMessageTypeEnabled(type))
ReleaseMessage(CreateIncomingMessage(type, text));
if (handlerIsValid)
Implementation = new DefaultInterpolatedStringHandler(literalLength, formattedCount);
}

public void AppendLiteral(string value)
=> Implementation.AppendLiteral(value);

public void AppendFormatted<T>(T t, int alignment = 0, string? format = null)
=> Implementation.AppendFormatted(t, alignment, format);

public string ToStringAndClear() => Implementation.ToStringAndClear();
}
}
#endif
}
2 changes: 1 addition & 1 deletion Lidgren.Network/NetPeer.MessagePools.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -199,7 +199,7 @@ internal void Recycle(NetOutgoingMessage msg)
#if DEBUG
NetException.Assert(m_outgoingMessagesPool.Contains(msg) == false, "Recyling already recycled outgoing message! Thread race?");
if (msg.m_recyclingCount != 0)
LogWarning("Wrong recycling count! should be zero; found " + msg.m_recyclingCount);
LogWarning($"Wrong recycling count! should be zero; found {msg.m_recyclingCount}");
#endif
// setting m_recyclingCount to zero SHOULD be an unnecessary maneuver, if it's not zero something is wrong
// however, in RELEASE, we'll just have to accept this and move on with life
Expand Down
3 changes: 2 additions & 1 deletion Lidgren.Network/NetPeer.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -347,7 +347,8 @@ public virtual NetConnection Connect(NetEndPoint remoteEndPoint, NetOutgoingMess
break;
default:
// weird
LogWarning("Weird situation; Connect() already in progress to remote endpoint; but hs status is " + hs.m_status);
LogWarning(
$"Weird situation; Connect() already in progress to remote endpoint; but hs status is {hs.m_status}");
break;
}
return hs;
Expand Down
8 changes: 4 additions & 4 deletions Lidgren.Network/NetUPnP.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -261,7 +261,7 @@ public bool ForwardPort(int externalPort, string description, int internalPort =
}
catch (Exception ex)
{
m_peer.LogWarning("UPnP port forward failed: " + ex.Message);
m_peer.LogWarning($"UPnP port forward failed: {ex.Message}");
return false;
}
return true;
Expand Down Expand Up @@ -292,7 +292,7 @@ public bool DeleteForwardingRule(int externalPort, string proto = "UDP")
}
catch (Exception ex)
{
m_peer.LogWarning("UPnP delete forwarding rule failed: " + ex.Message);
m_peer.LogWarning($"UPnP delete forwarding rule failed: {ex.Message}");
return false;
}
}
Expand Down Expand Up @@ -330,7 +330,7 @@ public bool DeleteForwardingRule(int externalPort, string proto = "UDP")
}
catch (Exception ex)
{
m_peer.LogWarning("Failed to get external IP: " + ex.Message);
m_peer.LogWarning($"Failed to get external IP: {ex.Message}");
return null;
}
}
Expand All @@ -357,7 +357,7 @@ public bool DeleteForwardingRule(int externalPort, string proto = "UDP")
}
catch (Exception ex)
{
m_peer.LogWarning("Failed to get connection status: " + ex.Message);
m_peer.LogWarning($"Failed to get connection status: {ex.Message}");
return null;
}
}
Expand Down
4 changes: 1 addition & 3 deletions Lidgren.Network/NetUnreliableSenderChannel.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,9 +63,7 @@ internal override NetSendResult Enqueue(NetOutgoingMessage message)
{
// drop message
this.m_connection.m_peer.LogError(
string.Format("Unreliable message max size exceeded: {0} bits (max {1})",
message.LengthBits,
ushort.MaxValue));
$"Unreliable message max size exceeded: {message.LengthBits} bits (max {ushort.MaxValue})");
return NetSendResult.Dropped;
}

Expand Down
1 change: 1 addition & 0 deletions RELEASE-NOTES.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
## Master

- Revert change to `NetPeer.Connections` so it returns a `List<>` instead of `IReadOnlyList<>` again. Change was introduced in 0.2.7.
- Overhead introduced by warning/error logs is now almost completely gone when they are disabled.

## 0.3.0

Expand Down

0 comments on commit bc643a1

Please sign in to comment.