fix(SWT): Reduced allocations in logging

This commit is contained in:
MrGadget 2024-09-20 04:24:04 -04:00
parent 8cf164055b
commit 0543e0abf3
14 changed files with 118 additions and 60 deletions

View File

@ -97,7 +97,7 @@ public void ProcessMessageQueue(MonoBehaviour behaviour)
}
}
if (receiveQueue.Count > 0)
Log.Warn($"[SWT-SimpleWebClient]: ProcessMessageQueue has {receiveQueue.Count} remaining.");
Log.Warn($"[SWT-SimpleWebClient]: ProcessMessageQueue has {0} remaining.", receiveQueue.Count);
}
}
}

View File

@ -24,7 +24,7 @@ public bool TryHandshake(Connection conn, Uri uri)
string key = Convert.ToBase64String(keyBuffer);
string keySum = key + Constants.HandshakeGUID;
byte[] keySumBytes = Encoding.ASCII.GetBytes(keySum);
Log.Verbose($"[SWT-ClientHandshake]: Handshake Hashing {Encoding.ASCII.GetString(keySumBytes)}");
Log.Verbose($"[SWT-ClientHandshake]: Handshake Hashing {0}", Encoding.ASCII.GetString(keySumBytes));
// SHA-1 is the websocket standard:
// https://www.rfc-editor.org/rfc/rfc6455
@ -55,14 +55,14 @@ public bool TryHandshake(Connection conn, Uri uri)
}
string responseString = Encoding.ASCII.GetString(responseBuffer, 0, lengthOrNull.Value);
Log.Verbose($"[SWT-ClientHandshake]: Handshake Response {responseString}");
Log.Verbose($"[SWT-ClientHandshake]: Handshake Response {0}", responseString);
string acceptHeader = "Sec-WebSocket-Accept: ";
int startIndex = responseString.IndexOf(acceptHeader, StringComparison.InvariantCultureIgnoreCase);
if (startIndex < 0)
{
Log.Error($"[SWT-ClientHandshake]: Unexpected Handshake Response {responseString}");
Log.Error($"[SWT-ClientHandshake]: Unexpected Handshake Response {0}", responseString);
return false;
}
@ -73,9 +73,9 @@ public bool TryHandshake(Connection conn, Uri uri)
if (responseKey != expectedResponse)
{
Log.Error($"[SWT-ClientHandshake]: Response key incorrect\n" +
$"Expected:{expectedResponse}\n" +
$"Response:{responseKey}\n" +
$"This can happen if Websocket Protocol is not installed in Windows Server Roles.");
$"Expected:{0}\n" +
$"Response:{1}\n" +
$"This can happen if Websocket Protocol is not installed in Windows Server Roles.", expectedResponse, responseKey);
return false;
}

View File

@ -24,7 +24,7 @@ internal bool TryCreateStream(Connection conn, Uri uri)
}
catch (Exception e)
{
Log.Error($"[SWT-ClientSslHelper]: Create SSLStream Failed: {e.Message}\n{e.StackTrace}\n\n");
Log.Error($"[SWT-ClientSslHelper]: Create SSLStream Failed: {0}\n{1}\n\n", e.Message, e.StackTrace);
return false;
}
}

View File

@ -60,7 +60,7 @@ void ConnectAndReceiveLoop(Uri serverAddress)
bool success = sslHelper.TryCreateStream(conn, serverAddress);
if (!success)
{
Log.Warn($"[SWT-WebSocketClientStandAlone]: Failed to create Stream with {serverAddress}");
Log.Warn($"[SWT-WebSocketClientStandAlone]: Failed to create Stream with {0}", serverAddress);
conn.Dispose();
return;
}
@ -68,12 +68,12 @@ void ConnectAndReceiveLoop(Uri serverAddress)
success = handshake.TryHandshake(conn, serverAddress);
if (!success)
{
Log.Warn($"[SWT-WebSocketClientStandAlone]: Failed Handshake with {serverAddress}");
Log.Warn($"[SWT-WebSocketClientStandAlone]: Failed Handshake with {0}", serverAddress);
conn.Dispose();
return;
}
Log.Info($"[SWT-WebSocketClientStandAlone]: HandShake Successful with {serverAddress}");
Log.Info($"[SWT-WebSocketClientStandAlone]: HandShake Successful with {0}", serverAddress);
state = ClientState.Connected;

View File

@ -76,7 +76,7 @@ public override void Send(ArraySegment<byte> segment)
{
if (segment.Count > maxMessageSize)
{
Log.Error($"[SWT-WebSocketClientWebGl]: Cant send message with length {segment.Count} because it is over the max size of {maxMessageSize}");
Log.Error($"[SWT-WebSocketClientWebGl]: Cant send message with length {0} because it is over the max size of {1}", segment.Count, maxMessageSize);
return;
}
@ -128,7 +128,7 @@ void onMessage(IntPtr bufferPtr, int count)
}
catch (Exception e)
{
Log.Error($"[SWT-WebSocketClientWebGl]: onMessage {e.GetType()}: {e.Message}\n{e.StackTrace}");
Log.Error($"[SWT-WebSocketClientWebGl]: onMessage {0}: {1}\n{2}", e.GetType(), e.Message, e.StackTrace);
receiveQueue.Enqueue(new Message(e));
}
}

View File

@ -226,12 +226,12 @@ public BufferPool(int bucketCount, int smallest, int largest)
void Validate()
{
if (buckets[0].arraySize != smallest)
Log.Error($"[SWT-BufferPool]: BufferPool Failed to create bucket for smallest. bucket:{buckets[0].arraySize} smallest:{smallest}");
Log.Error($"[SWT-BufferPool]: BufferPool Failed to create bucket for smallest. bucket:{0} smallest:{1}", buckets[0].arraySize, smallest);
int largestBucket = buckets[bucketCount - 1].arraySize;
// rounded using Ceiling, so allowed to be 1 more that largest
if (largestBucket != largest && largestBucket != largest + 1)
Log.Error($"[SWT-BufferPool]: BufferPool Failed to create bucket for largest. bucket:{largestBucket} smallest:{largest}");
Log.Error($"[SWT-BufferPool]: BufferPool Failed to create bucket for largest. bucket:{0} smallest:{1}", largestBucket, largest);
}
public ArrayBuffer Take(int size)

View File

@ -48,12 +48,12 @@ public Connection(TcpClient client, Action<Connection> onDispose)
/// </summary>
public void Dispose()
{
Log.Verbose($"[SWT-Connection]: Dispose {ToString()}");
Log.Verbose($"[SWT-Connection]: Dispose {0}", ToString());
// check hasDisposed first to stop ThreadInterruptedException on lock
if (hasDisposed) return;
Log.Verbose($"[SWT-Connection]: Connection Close: {ToString()}");
Log.Verbose($"[SWT-Connection]: Connection Close: {0}", ToString());
lock (disposedLock)
{

View File

@ -67,10 +67,10 @@ public static void Flood(string msg)
#if UNITY_SERVER || UNITY_WEBGL
Console.ForegroundColor = ConsoleColor.Gray;
logger.Log(LogType.Log, msg);
logger.Log(LogType.Log, msg.Trim());
Console.ResetColor();
#else
logger.Log(LogType.Log, msg);
logger.Log(LogType.Log, msg.Trim());
#endif
}
@ -126,35 +126,57 @@ public static void Verbose(string msg)
#if DEBUG
// Debug builds and Unity Editor
logger.Log(LogType.Log, msg);
logger.Log(LogType.Log, msg.Trim());
#else
// Server or WebGL
Console.ForegroundColor = ConsoleColor.Blue;
Console.WriteLine(msg);
Console.WriteLine(msg.Trim());
Console.ResetColor();
#endif
}
public static void Verbose<T>(string msg, T arg1)
{
if (minLogLevel > Levels.Verbose) return;
Verbose($"{msg} {arg1}");
}
public static void Verbose<T1, T2>(string msg, T1 arg1, T2 arg2)
{
if (minLogLevel > Levels.Verbose) return;
Verbose($"{msg} {arg1} {arg2}");
}
/// <summary>
/// Logs info to console if minLogLevel is set to Info or lower
/// </summary>
/// <param name="msg">Message text to log</param>
/// <param name="consoleColor">Default Cyan works in server and browser consoles</param>
public static void Info(string msg, ConsoleColor consoleColor = ConsoleColor.Cyan)
static void Info(string msg, ConsoleColor consoleColor = ConsoleColor.Cyan)
{
if (minLogLevel > Levels.Info) return;
#if DEBUG
// Debug builds and Unity Editor
logger.Log(LogType.Log, msg);
logger.Log(LogType.Log, msg.Trim());
#else
// Server or WebGL
Console.ForegroundColor = consoleColor;
Console.WriteLine(msg);
Console.WriteLine(msg.Trim());
Console.ResetColor();
#endif
}
public static void Info<T>(string msg, T arg1, ConsoleColor consoleColor = ConsoleColor.Cyan)
{
if (minLogLevel > Levels.Info) return;
Info($"{msg} {arg1}", consoleColor);
}
public static void Info<T1, T2>(string msg, T1 arg1, T2 arg2, ConsoleColor consoleColor = ConsoleColor.Cyan)
{
if (minLogLevel > Levels.Info) return;
Info($"{msg} {arg1} {arg2}", consoleColor);
}
/// <summary>
/// Logs info to console if minLogLevel is set to Info or lower
/// </summary>
@ -184,15 +206,33 @@ public static void Warn(string msg)
#if DEBUG
// Debug builds and Unity Editor
logger.Log(LogType.Warning, msg);
logger.Log(LogType.Warning, msg.Trim());
#else
// Server or WebGL
Console.ForegroundColor = ConsoleColor.Yellow;
Console.WriteLine(msg);
Console.WriteLine(msg.Trim());
Console.ResetColor();
#endif
}
public static void Warn<T>(string msg, T arg1)
{
if (minLogLevel > Levels.Warn) return;
Warn($"{msg} {arg1}");
}
//public static void Warn<T1, T2>(string msg, T1 arg1, T2 arg2)
//{
// if (minLogLevel > Levels.Warn) return;
// Warn($"{msg} {arg1} {arg2}");
//}
//public static void Warn<T1, T2, T3>(string msg, T1 arg1, T2 arg2, T3 arg3)
//{
// if (minLogLevel > Levels.Warn) return;
// Warn($"{msg} {arg1} {arg2} {arg3}");
//}
/// <summary>
/// Logs info to console if minLogLevel is set to Error or lower
/// </summary>
@ -203,15 +243,33 @@ public static void Error(string msg)
#if DEBUG
// Debug builds and Unity Editor
logger.Log(LogType.Error, msg);
logger.Log(LogType.Error, msg.Trim());
#else
// Server or WebGL
Console.ForegroundColor = ConsoleColor.Red;
Console.WriteLine(msg);
Console.WriteLine(msg.Trim());
Console.ResetColor();
#endif
}
public static void Error<T>(string msg, T arg1)
{
if (minLogLevel > Levels.Error) return;
Error($"{msg} {arg1}");
}
public static void Error<T1, T2>(string msg, T1 arg1, T2 arg2)
{
if (minLogLevel > Levels.Error) return;
Error($"{msg} {arg1} {arg2}");
}
public static void Error<T1, T2, T3>(string msg, T1 arg1, T2 arg2, T3 arg3)
{
if (minLogLevel > Levels.Error) return;
Error($"{msg} {arg1} {arg2} {arg3}");
}
/// <summary>
/// Returns a string representation of the byte array starting from offset for length bytes
/// </summary>

View File

@ -62,7 +62,7 @@ public static void Loop(Config config)
while (client.Connected)
ReadOneMessage(config, readBuffer);
Log.Verbose($"[SWT-ReceiveLoop]: {conn} Not Connected");
Log.Verbose($"[SWT-ReceiveLoop]: {0} Not Connected", conn);
}
catch (Exception)
{
@ -81,18 +81,18 @@ public static void Loop(Config config)
catch (SocketException e)
{
// this could happen if wss client closes stream
Log.Warn($"[SWT-ReceiveLoop]: ReceiveLoop SocketException\n{e.Message}");
Log.Warn($"[SWT-ReceiveLoop]: ReceiveLoop SocketException\n{0}", e.Message);
queue.Enqueue(new Message(conn.connId, e));
}
catch (IOException e)
{
// this could happen if client disconnects
Log.Warn($"[SWT-ReceiveLoop]: ReceiveLoop IOException\n{e.Message}");
Log.Warn($"[SWT-ReceiveLoop]: ReceiveLoop IOException\n{0}", e.Message);
queue.Enqueue(new Message(conn.connId, e));
}
catch (InvalidDataException e)
{
Log.Error($"[SWT-ReceiveLoop]: Invalid data from {conn}\n{e.Message}\n{e.StackTrace}\n\n");
Log.Error($"[SWT-ReceiveLoop]: Invalid data from {0}\n{1}\n{2}\n\n", conn, e.Message, e.StackTrace);
queue.Enqueue(new Message(conn.connId, e));
}
catch (Exception e)
@ -239,7 +239,7 @@ static void HandleCloseMessage(Config config, byte[] buffer, int msgOffset, int
// dump after mask off
Log.DumpBuffer($"[SWT-ReceiveLoop]: Message", buffer, msgOffset, payloadLength);
Log.Verbose($"[SWT-ReceiveLoop]: Close: {GetCloseCode(buffer, msgOffset)} message:{GetCloseMessage(buffer, msgOffset, payloadLength)}");
Log.Verbose($"[SWT-ReceiveLoop]: Close: {0} message:{1}", GetCloseCode(buffer, msgOffset), GetCloseMessage(buffer, msgOffset, payloadLength));
conn.Dispose();
}

View File

@ -71,7 +71,7 @@ public static void Loop(Config config)
// check if connected before sending message
if (!client.Connected)
{
Log.Verbose($"[SWT-SendLoop]: SendLoop {conn} not connected");
Log.Verbose($"[SWT-SendLoop]: SendLoop {0} not connected", conn);
msg.Release();
return;
}
@ -101,7 +101,7 @@ public static void Loop(Config config)
// check if connected before sending message
if (!client.Connected)
{
Log.Verbose($"[SWT-SendLoop]: SendLoop {conn} not connected");
Log.Verbose($"[SWT-SendLoop]: SendLoop {0} not connected", conn);
msg.Release();
return;
}
@ -113,7 +113,7 @@ public static void Loop(Config config)
}
}
Log.Verbose($"[SWT-SendLoop]: {conn} Not Connected");
Log.Verbose($"[SWT-SendLoop]: {0} Not Connected", conn);
}
catch (ThreadInterruptedException e) { Log.InfoException(e); }
catch (ThreadAbortException e) { Log.InfoException(e); }

View File

@ -50,7 +50,7 @@ public bool TryHandshake(Connection conn)
if (!IsGet(getHeader.array))
{
Log.Warn($"[SWT-ServerHandshake]: First bytes from client was not 'GET' for handshake, instead was {Log.BufferToString(getHeader.array, 0, GetSize)}");
Log.Warn($"[SWT-ServerHandshake]: First bytes from client was not 'GET' for handshake, instead was {0}", Log.BufferToString(getHeader.array, 0, GetSize));
return false;
}
}
@ -66,7 +66,7 @@ public bool TryHandshake(Connection conn)
conn.request = new Request(msg);
conn.remoteAddress = conn.CalculateAddress();
Log.Info($"[SWT-ServerHandshake]: A client connected from {conn}");
Log.Info($"[SWT-ServerHandshake]: A client connected from {0}", conn);
return true;
}
@ -90,7 +90,7 @@ string ReadToEndForHandshake(Stream stream)
string msg = Encoding.ASCII.GetString(readBuffer.array, 0, readCount);
// GET isn't in the bytes we read here, so we need to add it back
msg = $"GET{msg}";
Log.Verbose($"[SWT-ServerHandshake]: Client Handshake Message:\r\n{msg}");
Log.Verbose($"[SWT-ServerHandshake]: Client Handshake Message:\r\n{0}", msg);
return msg;
}
@ -122,7 +122,7 @@ static void GetKey(string msg, byte[] keyBuffer)
{
int start = msg.IndexOf(KeyHeaderString, StringComparison.InvariantCultureIgnoreCase) + KeyHeaderString.Length;
Log.Verbose($"[SWT-ServerHandshake]: Handshake Key: {msg.Substring(start, KeyLength)}");
Log.Verbose($"[SWT-ServerHandshake]: Handshake Key: {0}", msg.Substring(start, KeyLength));
Encoding.ASCII.GetBytes(msg, start, KeyLength, keyBuffer, 0);
}
@ -133,7 +133,7 @@ static void AppendGuid(byte[] keyBuffer)
byte[] CreateHash(byte[] keyBuffer)
{
Log.Verbose($"[SWT-ServerHandshake]: Handshake Hashing {Encoding.ASCII.GetString(keyBuffer, 0, MergedKeyLength)}");
Log.Verbose($"[SWT-ServerHandshake]: Handshake Hashing {0}", Encoding.ASCII.GetString(keyBuffer, 0, MergedKeyLength));
return sha1.ComputeHash(keyBuffer, 0, MergedKeyLength);
}
@ -149,7 +149,7 @@ static void CreateResponse(byte[] keyHash, byte[] responseBuffer)
"Sec-WebSocket-Accept: {0}\r\n\r\n",
keyHashString);
Log.Verbose($"[SWT-ServerHandshake]: Handshake Response length {message.Length}, IsExpected {message.Length == ResponseLength}");
Log.Verbose($"[SWT-ServerHandshake]: Handshake Response length {0}, IsExpected {1}", message.Length, message.Length == ResponseLength);
Encoding.ASCII.GetBytes(message, 0, ResponseLength, responseBuffer, 0);
}
}

View File

@ -33,7 +33,7 @@ public ServerSslHelper(SslConfig sslConfig)
if (config.enabled)
{
certificate = new X509Certificate2(config.certPath, config.certPassword);
Log.Info($"[SWT-ServerSslHelper]: SSL Certificate {certificate.Subject} loaded with expiration of {certificate.GetExpirationDateString()}");
Log.Info($"[SWT-ServerSslHelper]: SSL Certificate {0} loaded with expiration of {1}", certificate.Subject, certificate.GetExpirationDateString());
}
}
@ -49,7 +49,7 @@ internal bool TryCreateStream(Connection conn)
}
catch (Exception e)
{
Log.Error($"[SWT-ServerSslHelper]: Create SSLStream Failed: {e.Message}");
Log.Error($"[SWT-ServerSslHelper]: Create SSLStream Failed: {0}", e.Message);
return false;
}
}

View File

@ -108,7 +108,7 @@ public void ProcessMessageQueue(MonoBehaviour behaviour)
if (server.receiveQueue.Count > 0)
{
Log.Warn($"[SWT-SimpleWebServer]: ProcessMessageQueue has {server.receiveQueue.Count} remaining.");
Log.Warn($"[SWT-SimpleWebServer]: ProcessMessageQueue has {0} remaining.", server.receiveQueue.Count);
}
}
}

View File

@ -37,7 +37,7 @@ public void Listen(int port)
listener = TcpListener.Create(port);
listener.Start();
Log.Verbose($"[SWT-WebSocketServer]: Server Started on {port}");
Log.Verbose($"[SWT-WebSocketServer]: Server Started on {0}", port);
acceptThread = new Thread(acceptLoop);
acceptThread.IsBackground = true;
@ -78,7 +78,7 @@ void acceptLoop()
// this might not be a problem as HandshakeAndReceiveLoop checks for stop
// and returns/disposes before sending message to queue
Connection conn = new Connection(client, AfterConnectionDisposed);
Log.Verbose($"[SWT-WebSocketServer]: A client connected from {conn}");
Log.Verbose($"[SWT-WebSocketServer]: A client connected from {0}", conn);
// handshake needs its own thread as it needs to wait for message from client
Thread receiveThread = new Thread(() => HandshakeAndReceiveLoop(conn));
@ -108,7 +108,7 @@ void HandshakeAndReceiveLoop(Connection conn)
bool success = sslHelper.TryCreateStream(conn);
if (!success)
{
Log.Warn($"[SWT-WebSocketServer]: Failed to create SSL Stream {conn}");
Log.Warn($"[SWT-WebSocketServer]: Failed to create SSL Stream {0}", conn);
conn.Dispose();
return;
}
@ -116,10 +116,10 @@ void HandshakeAndReceiveLoop(Connection conn)
success = handShake.TryHandshake(conn);
if (success)
Log.Verbose($"[SWT-WebSocketServer]: Sent Handshake {conn}, false");
Log.Verbose($"[SWT-WebSocketServer]: Sent Handshake {0}, false", conn);
else
{
Log.Warn($"[SWT-WebSocketServer]: Handshake Failed {conn}");
Log.Warn($"[SWT-WebSocketServer]: Handshake Failed {0}", conn);
conn.Dispose();
return;
}
@ -162,15 +162,15 @@ void HandshakeAndReceiveLoop(Connection conn)
}
catch (ThreadInterruptedException e)
{
Log.Error($"[SWT-WebSocketServer]: Handshake ThreadInterruptedException {e.Message}");
Log.Error($"[SWT-WebSocketServer]: Handshake ThreadInterruptedException {0}", e.Message);
}
catch (ThreadAbortException e)
{
Log.Error($"[SWT-WebSocketServer]: Handshake ThreadAbortException {e.Message}");
Log.Error($"[SWT-WebSocketServer]: Handshake ThreadAbortException {0}", e.Message);
}
catch (Exception e)
{
Log.Error($"[SWT-WebSocketServer]: Handshake Exception {e.Message}");
Log.Error($"[SWT-WebSocketServer]: Handshake Exception {0}", e.Message);
}
finally
{
@ -196,20 +196,20 @@ public void Send(int id, ArrayBuffer buffer)
conn.sendPending.Set();
}
else
Log.Warn($"[SWT-WebSocketServer]: Cannot send message to {id} because connection was not found in dictionary. Maybe it disconnected.");
Log.Warn($"[SWT-WebSocketServer]: Cannot send message to {0} because connection was not found in dictionary. Maybe it disconnected.", id);
}
public bool CloseConnection(int id)
{
if (connections.TryGetValue(id, out Connection conn))
{
Log.Info($"[SWT-WebSocketServer]: Disconnecting connection {id}");
Log.Info($"[SWT-WebSocketServer]: Disconnecting connection {0}", id);
conn.Dispose();
return true;
}
else
{
Log.Warn($"[SWT-WebSocketServer]: Failed to kick {id} because id not found.");
Log.Warn($"[SWT-WebSocketServer]: Failed to kick {0} because id not found.", id);
return false;
}
}
@ -218,7 +218,7 @@ public string GetClientAddress(int id)
{
if (!connections.TryGetValue(id, out Connection conn))
{
Log.Warn($"[SWT-WebSocketServer]: Cannot get address of connection {id} because connection was not found in dictionary.");
Log.Warn($"[SWT-WebSocketServer]: Cannot get address of connection {0} because connection was not found in dictionary.", id);
return null;
}
@ -229,7 +229,7 @@ public Request GetClientRequest(int id)
{
if (!connections.TryGetValue(id, out Connection conn))
{
Log.Warn($"[SWT-WebSocketServer]: Cannot get request of connection {id} because connection was not found in dictionary.");
Log.Warn($"[SWT-WebSocketServer]: Cannot get request of connection {0} because connection was not found in dictionary.", id);
return null;
}