warrentyexpired/ModernUO
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

fix: Fixes structured logging (#1043)

Browse source 
- [X] Fixes various bugs in logging.
This commit is contained in:
Kamron Batman 2022-06-05 01:00:22 -07:00 • committed by GitHub
parent 78bb4f4bb2
commit 6e69d25e33
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
31 changed files with 96 additions and 102 deletions
Download patch file Download diff file Expand all files Collapse all files

7
Projects/Server/Client/UOClient.cs
View file

@ -54,13 +54,14 @@ public static class UOClient
{
logger.Information(
CuoSettings?.ClientVersion == ServerClientVersion
? $"Automatically detected client version {ServerClientVersion} from CUO settings."
: $"Automatically detected client version {ServerClientVersion}"
? "Automatically detected client version {ServerClientVersion} from CUO settings."
: "Automatically detected client version {ServerClientVersion}",
ServerClientVersion
);
return;
}
logger.Information($"Manually configured to use client version {ServerClientVersion}");
logger.Information("Manually configured to use client version {ServerClientVersion}", ServerClientVersion);
}
private static ClientVersion DetectCUOClient()

2
Projects/Server/Configuration/ServerConfiguration.cs
View file

@ -217,7 +217,7 @@ public static class ServerConfiguration
if (File.Exists(m_FilePath))
{
logger.Information($"Reading server configuration from {_relPath}...");
logger.Information("Reading server configuration from {Path}...", _relPath);
m_Settings = JsonConfig.Deserialize<ServerSettings>(m_FilePath);
if (m_Settings == null)

12
Projects/Server/Maps/Map.cs
View file

@ -320,8 +320,7 @@ public sealed class Map : IComparable<Map>
public const int SectorShift = 4;
public const int SectorActiveRange = 2;
private static ILogger _logger;
private static ILogger Logger => _logger ??= LogFactory.GetLogger(typeof(Map));
private static ILogger logger = LogFactory.GetLogger(typeof(Map));
private readonly int m_FileIndex;
private readonly Sector[][] m_Sectors;
@ -409,7 +408,7 @@ public sealed class Map : IComparable<Map>
{
if (this == Internal && m_Name != "Internal")
{
Logger.Warning($"Internal map name was '{m_Name}'\n{new StackTrace()}");
logger.Warning("Internal map name was '{Name}'\n{StackTrace}", m_Name, new StackTrace());
m_Name = "Internal";
}
@ -419,8 +418,7 @@ public sealed class Map : IComparable<Map>
{
if (this == Internal && value != "Internal")
{
Logger.Warning($"Attempted to set internal map name to '{value}'\n{new StackTrace()}");
logger.Warning("Attempted to set internal map name to '{Value}'\n{StackTrace}", value, new StackTrace());
value = "Internal";
}
@ -1045,7 +1043,7 @@ public sealed class Map : IComparable<Map>
if (Regions.ContainsKey(regName))
{
Logger.Warning($"Duplicate region name '{regName}' for map '{Name}'");
logger.Warning("Duplicate region name '{RegionName}' for map '{MapName}'", regName, Name);
}
else
{
@ -1101,7 +1099,7 @@ public sealed class Map : IComparable<Map>
}
else
{
Logger.Warning($"Warning: Invalid object ({o}) in line of sight");
logger.Warning("Warning: Invalid object ({Object}) in line of sight", o);
p = Point3D.Zero;
}

6
Projects/Server/Maps/MapLoader.cs
View file

@ -80,18 +80,18 @@ namespace Server
if (failures.Count > 0)
{
logger.Warning(
"Map Definitions loaded with failures ({0} maps, {1} failures) ({2:F2} seconds)",
"Map Definitions loaded with failures ({Count} maps, {FailureCount} failures) ({Duration:F2} seconds)",
count,
failures.Count,
stopwatch.Elapsed.TotalSeconds
);
logger.Warning(string.Join(Environment.NewLine, failures));
logger.Warning("Map load failures: {Failure}", failures);
}
else
{
logger.Information(
"Map Definitions loaded successfully ({0} maps, {1} failures) ({2:F2} seconds)",
"Map Definitions loaded successfully ({Count} maps, {FailureCount} failures) ({Duration:F2} seconds)",
count,
failures.Count,
stopwatch.Elapsed.TotalSeconds

7
Projects/Server/Mobiles/Mobile.cs
View file

@ -5190,7 +5190,12 @@ namespace Server
if (oldAmount <= 0)
{
logger.Error($"Item {item.GetType()} ({item.Serial}) has amount of {oldAmount}, but must be at least 1");
logger.Error(
"Item {Type} ({Serial}) has amount of {OldAmount}, but must be at least 1",
item.GetType(),
item.Serial,
oldAmount
);
}
else
{

19
Projects/Server/Network/NetState/NetState.cs
View file

@ -343,13 +343,7 @@ public partial class NetState : IComparable<NetState>
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public void LogInfo(string text)
{
logger.Information("Client: {0}: {1}", this, text);
}
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public void LogInfo(string format, params object[] args)
{
LogInfo(string.Format(format, args));
logger.Information("Client: {NetState}: {Message}", this, text);
}
public void AddMenu(IMenu menu)
@ -861,7 +855,7 @@ public partial class NetState : IComparable<NetState>
{
if (ex.SocketErrorCode != SocketError.WouldBlock)
{
logger.Debug(ex, "Disconnected due to socket exception");
logger.Debug(ex, "Disconnected due to a socket exception");
Disconnect(string.Empty);
}
}
@ -1127,13 +1121,6 @@ public partial class NetState : IComparable<NetState>
var count = TcpServer.Instances.Count;
if (a != null)
{
LogInfo("Disconnected. [{0} Online] [{1}]", count, a);
}
else
{
LogInfo("Disconnected. [{0} Online]", count);
}
LogInfo(a != null ? $"Disconnected. [{count} Online] [{a}]" : $"Disconnected. [{count} Online]");
}
}

3
Projects/Server/Network/Packets/IncomingExtendedCommandPackets.cs
View file

@ -103,8 +103,7 @@ public static class IncomingExtendedCommandPackets
if (state.Mobile == null)
{
state.LogInfo(
"Sent in-game packet (0xBFx{0:X2}) before having been attached to a mobile",
packetId
$"Sent in-game packet (0xBFx{packetId:X2}) before having been attached to a mobile"
);
}

2
Projects/Server/Network/Packets/IncomingPlayerPackets.cs
View file

@ -202,7 +202,7 @@ public static class IncomingPlayerPackets
}
default:
{
state.LogInfo("Unknown text-command type 0x{0:X2}: {1}", state, type, command);
state.LogInfo($"Unknown text-command type 0x{state:X2}: {type} ({command})");
break;
}
}

2
Projects/Server/Network/Packets/OutgoingGumpPackets.cs
View file

@ -78,7 +78,7 @@ public static class OutgoingGumpPackets
if (error != ZlibError.Okay)
{
logger.Warning($"Gump compression failed {error}");
logger.Warning("Gump compression failed: {Error}", error);
writer.Write(4);
writer.Write(0);

10
Projects/Server/Network/TcpServer.cs
View file

@ -77,7 +77,7 @@ namespace Server.Network
foreach (var ipep in listeningAddresses)
{
logger.Information("Listening: {0}:{1}", ipep.Address, ipep.Port);
logger.Information("Listening: {Address}:{Port}", ipep.Address, ipep.Port);
}
ListeningAddresses = listeningAddresses.ToArray();
@ -119,12 +119,12 @@ namespace Server.Network
// WSAEADDRINUSE
if (se.ErrorCode == 10048)
{
logger.Warning("Listener: {0}:{1}: Failed (In Use)", ipep.Address, ipep.Port);
logger.Warning("Listener: {Address}:{Port}: Failed (In Use)", ipep.Address, ipep.Port);
}
// WSAEADDRNOTAVAIL
else if (se.ErrorCode == 10049)
{
logger.Warning("Listener {0}:{1}: Failed (Unavailable)", ipep.Address, ipep.Port);
logger.Warning("Listener {Address}:{Port}: Failed (Unavailable)", ipep.Address, ipep.Port);
}
else
{
@ -142,7 +142,7 @@ namespace Server.Network
while (++count <= MaxConnectionsPerLoop && _connectedQueue.TryDequeue(out var ns))
{
Instances.Add(ns);
ns.LogInfo("Connected. [{0} Online]", Instances.Count);
ns.LogInfo($"Connected. [{Instances.Count} Online]");
}
}
@ -166,7 +166,7 @@ namespace Server.Network
if (socket.RemoteEndPoint is IPEndPoint ipep)
{
var ip = ipep.Address.ToString();
logger.Warning("Listener {0}: Failed (Maximum connections reached)", ip);
logger.Warning("Listener {Address}: Failed (Maximum connections reached)", ip);
NetState.TraceDisconnect("Maximum connections reached.", ip);
}

6
Projects/Server/Regions/RegionLoader.cs
View file

@ -64,7 +64,7 @@ namespace Server
if (failures.Count == 0)
{
logger.Information(
"Regions loaded ({0} regions, {1} failures) ({2:F2} seconds)",
"Regions loaded ({Count} regions, {FailureCount} failures) ({Duration:F2} seconds)",
count,
failures.Count,
stopwatch.Elapsed.TotalSeconds
@ -73,13 +73,13 @@ namespace Server
else
{
logger.Warning(
"Failed loading regions ({0} regions, {1} failures) ({2:F2} seconds)",
"Failed loading regions ({Count} regions, {FailureCount} failures) ({Duration:F2} seconds)",
count,
failures.Count,
stopwatch.Elapsed.TotalSeconds
);
logger.Warning(string.Join(Environment.NewLine, failures));
logger.Warning("{Failures}", failures);
}
}
}

6
Projects/Server/TileMatrix/TileMatrix.cs
View file

@ -90,7 +90,7 @@ namespace Server
}
else
{
logger.Warning($"map{mapFileIndex}.mul was not found.");
logger.Warning("{File} was not found.", $"map{mapFileIndex}.mul");
}
}
@ -103,7 +103,7 @@ namespace Server
}
else
{
logger.Warning($"staidx{mapFileIndex}.mul was not found.");
logger.Warning("{File} was not found.", $"staidx{mapFileIndex}.mul");
}
var staticsPath = Core.FindDataFile($"statics{mapFileIndex}.mul", false);
@ -114,7 +114,7 @@ namespace Server
}
else
{
logger.Warning($"statics{fileIndex}.mul was not found.");
logger.Warning("{File} was not found.", $"statics{fileIndex}.mul");
}
}

4
Projects/Server/TileMatrix/TileMatrixLoader.cs
View file

@ -46,11 +46,11 @@ namespace Server
if (exception == null)
{
logger.Information("Maps loaded ({0:F2} seconds)", stopwatch.Elapsed.TotalSeconds);
logger.Information("Maps loaded ({Duration:F2} seconds)", stopwatch.Elapsed.TotalSeconds);
}
else
{
logger.Error(exception, "Loading maps failed ({0:F2} seconds)", stopwatch.Elapsed.TotalSeconds);
logger.Error(exception, "Loading maps failed ({Duration:F2} seconds)", stopwatch.Elapsed.TotalSeconds);
throw exception;
}
}

10
Projects/Server/Timer/Timer.DelayCall.cs
View file

@ -147,7 +147,7 @@ namespace Server
{
if (Running)
{
logger.Error($"Timer is returned while still running!\n{new StackTrace()}");
logger.Error("Timer is returned while still running!\n{StackTrace}", new StackTrace());
return;
}
@ -163,7 +163,7 @@ namespace Server
if (_poolCount >= _poolCapacity)
{
#if DEBUG_TIMERS
logger.Warning($"DelayCallTimer pool reached maximum of {_poolCapacity} timers");
logger.Warning("DelayCallTimer pool reached maximum of {Capacity} timers", _poolCapacity);
_allowFinalization = true;
#endif
return;
@ -181,7 +181,7 @@ namespace Server
if (timer != null)
{
#if DEBUG_TIMERS
logger.Information($"Getting from pool: ({_poolCount} / {_poolCapacity})");
logger.Information("Getting from pool: ({Count} / {Capacity})", _poolCount, _poolCapacity);
#endif
timer.Init(delay, interval, count);
@ -197,7 +197,7 @@ namespace Server
_timerPoolDepletionAmount++;
#if DEBUG_TIMERS
logger.Warning($"Timer pool depleted and timer was allocated.\n{new StackTrace()}");
logger.Warning("Timer pool depleted and timer was allocated.\n{StackTrace}", new StackTrace());
#endif
return new DelayCallTimer(delay, interval, count, callback);
}
@ -211,7 +211,7 @@ namespace Server
{
if (!_allowFinalization)
{
logger.Warning($"Pooled timer was not returned to the pool.\n{_stackTraces[GetHashCode()]}");
logger.Warning("Pooled timer was not returned to the pool.\n{StackTrace}", _stackTraces[GetHashCode()]);
}
}
#endif

7
Projects/Server/Timer/Timer.Pool.cs
View file

@ -41,8 +41,9 @@ namespace Server
var amountToRefill = Math.Min(_maxPoolCapacity, amountToGrow);
var maximumHit = amountToGrow > amountToRefill ? " Maximum pool size has been reached." : "";
var warningMessage = $"Timer pool depleted by {{Amount}}. Refilling with {{AmountRefill}}.{maximumHit}";
logger.Warning($"Timer pool depleted by {_timerPoolDepletionAmount}. Refilling with {amountToRefill}.{maximumHit}");
logger.Warning(warningMessage, _timerPoolDepletionAmount, amountToRefill);
RefillPoolAsync(amountToRefill);
_timerPoolDepletionAmount = 0;
}
@ -62,7 +63,7 @@ namespace Server
_poolHead = head;
_poolCount += amount;
#if DEBUG_TIMERS
logger.Information($"Returning to pool. ({_poolCount} / {_poolCapacity})");
logger.Information("Returning to pool. ({Count} / {Capacity})", _poolCount, _poolCapacity);
#endif
}
@ -84,7 +85,7 @@ namespace Server
internal static void RefillPool(int amount, out DelayCallTimer head, out DelayCallTimer tail)
{
#if DEBUG_TIMERS
logger.Information($"Filling pool with {amount} timers.");
logger.Information("Filling pool with {Amount} timers.", amount);
#endif
head = null;

8
Projects/Server/Timer/Timer.TimerWheel.cs
View file

@ -199,7 +199,7 @@ namespace Server
// TODO: Handle timers > 17yrs
#if DEBUG_TIMERS
logger.Error($"Timer is more than max duration. ({originalDelay})");
logger.Error("Timer is more than max duration. ({Duration})", originalDelay);
#endif
}
@ -224,12 +224,12 @@ namespace Server
while (t != null)
{
var name = t.ToString();
hash.TryGetValue(name, out var count);
hash[name] = count + 1;
total++;
t = t?._nextTimer;
}
}

10
Projects/Server/World/World.cs
View file

@ -284,11 +284,11 @@ namespace Server
watch.Stop();
logger.Information(string.Format("World loaded ({1} items, {2} mobiles) ({0:F2} seconds)",
logger.Information("World loaded ({ItemCount} items, {MobileCount} mobiles) ({Duration:F2} seconds)",
watch.Elapsed.TotalSeconds,
Items.Count,
Mobiles.Count
));
);
WorldState = WorldState.Running;
}
@ -304,7 +304,7 @@ namespace Server
{
if (_pendingAdd.ContainsKey(entity.Serial))
{
logger.Warning("Entity {0} was both pending both deletion and addition after save", entity);
logger.Warning("Entity {Entity} was both pending both deletion and addition after save", entity);
}
RemoveEntity(entity);
@ -402,7 +402,7 @@ namespace Server
watch.Stop();
logger.Information("Writing world save snapshot done ({0:F2} seconds)", watch.Elapsed.TotalSeconds);
logger.Information("Writing world save snapshot done ({Duration:F2} seconds)", watch.Elapsed.TotalSeconds);
}
catch (Exception ex)
{
@ -505,7 +505,7 @@ namespace Server
if (exception == null)
{
var duration = watch.Elapsed.TotalSeconds;
logger.Information("World save completed ({0:F2} seconds)", duration);
logger.Information("World save completed ({Duration:F2} seconds)", duration);
// Only broadcast if it took at least 150ms
if (duration >= 0.15)