fix: Makes logging more consistent (#1246)

This commit is contained in:
Kamron Batman 2022-11-13 00:36:23 -08:00 • committed by GitHub
parent 8e0d01d4be
commit d8cfb6b935
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
15 changed files with 90 additions and 69 deletions

View file

@ -228,7 +228,7 @@ public static class ServerConfiguration
throw new FileNotFoundException($"Failed to deserialize {m_FilePath}."); throw new FileNotFoundException($"Failed to deserialize {m_FilePath}.");
} }
logger.Information("Reading server configuration done"); logger.Information("Reading server configuration {Status}", "done");
} }
else else
{ {

View file

@ -350,7 +350,7 @@ public static class Core
_ => "CTRL+C" _ => "CTRL+C"
}; };
logger.Information($"Detected {keypress} pressed."); logger.Information("Detected {Key} pressed.", keypress);
e.Cancel = true; e.Cancel = true;
Kill(); Kill();
} }
@ -471,27 +471,20 @@ public static class Core
ServerConfiguration.Load(); ServerConfiguration.Load();
logger.Information($"Running on {RuntimeInformation.FrameworkDescription}"); logger.Information("Running on {Framework}", RuntimeInformation.FrameworkDescription);
var s = Arguments; var s = Arguments;
if (s.Length > 0) if (s.Length > 0)
{ {
logger.Information($"Running with arguments: {s}"); logger.Information("Running with arguments: {Args}", s);
} }
if (MultiProcessor) if (MultiProcessor)
{ {
logger.Information($"Optimizing for {ProcessorCount} processor{(ProcessorCount == 1 ? "" : "s")}"); logger.Information($"Optimizing for {{ProcessorCount}} processor{(ProcessorCount == 1 ? "" : "s")}", ProcessorCount);
} }
if (GCSettings.IsServerGC)
{
logger.Information("Server garbage collection mode enabled");
}
logger.Information($"High resolution timing ({(Stopwatch.IsHighResolution ? "Supported" : "Unsupported")})");
var assemblyPath = Path.Join(BaseDirectory, AssembliesConfiguration); var assemblyPath = Path.Join(BaseDirectory, AssembliesConfiguration);
// Load UOContent.dll // Load UOContent.dll
@ -674,7 +667,7 @@ public static class Core
if (errors.Length > 0) if (errors.Length > 0)
{ {
Utility.PushColor(ConsoleColor.Red); Utility.PushColor(ConsoleColor.Red);
Console.WriteLine($"{type}\n{errors.ToString()}"); Console.WriteLine($"{type}{Environment.NewLine}{errors.ToString()}");
Utility.PopColor(); Utility.PopColor();
} }
} }

View file

@ -407,7 +407,11 @@ public sealed class Map : IComparable<Map>, ISpanFormattable, ISpanParsable<Map>
{ {
if (this == Internal && m_Name != "Internal") if (this == Internal && m_Name != "Internal")
{ {
logger.Warning("Internal map name was '{Name}'\n{StackTrace}", m_Name, new StackTrace()); logger.Warning(
$"Internal map name was '{{Name}}'{Environment.NewLine}{{StackTrace}}",
m_Name,
new StackTrace()
);
m_Name = "Internal"; m_Name = "Internal";
} }
@ -417,7 +421,11 @@ public sealed class Map : IComparable<Map>, ISpanFormattable, ISpanParsable<Map>
{ {
if (this == Internal && value != "Internal") if (this == Internal && value != "Internal")
{ {
logger.Warning("Attempted to set internal map name to '{Value}'\n{StackTrace}", value, new StackTrace()); logger.Warning(
$"Attempted to set internal map name to '{{Value}}'{Environment.NewLine}{{StackTrace}}",
value,
new StackTrace()
);
value = "Internal"; value = "Internal";
} }

View file

@ -80,18 +80,19 @@ public static class MapLoader
if (failures.Count > 0) if (failures.Count > 0)
{ {
logger.Warning( logger.Warning(
"Map Definitions loaded with failures ({Count} maps, {FailureCount} failures) ({Duration:F2} seconds)", $"Loading map definitions {{Status}} ({{Count}} maps, {{FailureCount}} failures) ({{Duration:F2}} seconds){Environment.NewLine}{{Failures}}",
"failed",
count, count,
failures.Count, failures.Count,
stopwatch.Elapsed.TotalSeconds stopwatch.Elapsed.TotalSeconds,
failures
); );
logger.Warning("Map load failures: {Failure}", failures);
} }
else else
{ {
logger.Information( logger.Information(
"Map Definitions loaded successfully ({Count} maps, {FailureCount} failures) ({Duration:F2} seconds)", "Loading map definitions {Status} ({Count} maps, {FailureCount} failures) ({Duration:F2} seconds)",
"done",
count, count,
failures.Count, failures.Count,
stopwatch.Elapsed.TotalSeconds stopwatch.Elapsed.TotalSeconds

View file

@ -13,6 +13,7 @@
* along with this program. If not, see <http://www.gnu.org/licenses/>. * * along with this program. If not, see <http://www.gnu.org/licenses/>. *
*************************************************************************/ *************************************************************************/
using System;
using System.Collections.Generic; using System.Collections.Generic;
using System.Diagnostics; using System.Diagnostics;
using System.IO; using System.IO;
@ -63,7 +64,8 @@ internal static class RegionLoader
if (failures.Count == 0) if (failures.Count == 0)
{ {
logger.Information( logger.Information(
"Regions loaded ({Count} regions, {FailureCount} failures) ({Duration:F2} seconds)", "Loading regions {Status} ({Count} regions, {FailureCount} failures) ({Duration:F2} seconds)",
"done",
count, count,
failures.Count, failures.Count,
stopwatch.Elapsed.TotalSeconds stopwatch.Elapsed.TotalSeconds
@ -72,13 +74,13 @@ internal static class RegionLoader
else else
{ {
logger.Warning( logger.Warning(
"Failed loading regions ({Count} regions, {FailureCount} failures) ({Duration:F2} seconds)", $"Loading regions {{Status}} ({{Count}} regions, {{FailureCount}} failures) ({{Duration:F2}} seconds){Environment.NewLine}{{Failures}}",
"failed",
count, count,
failures.Count, failures.Count,
stopwatch.Elapsed.TotalSeconds stopwatch.Elapsed.TotalSeconds,
failures
); );
logger.Warning("{Failures}", failures);
} }
} }
} }

View file

@ -46,11 +46,16 @@ internal static class TileMatrixLoader
if (exception == null) if (exception == null)
{ {
logger.Information("Maps loaded ({Duration:F2} seconds)", stopwatch.Elapsed.TotalSeconds); logger.Information("Loading maps {Status} ({Duration:F2} seconds)", "done", stopwatch.Elapsed.TotalSeconds);
} }
else else
{ {
logger.Error(exception, "Loading maps failed ({Duration:F2} seconds)", stopwatch.Elapsed.TotalSeconds); logger.Error(
exception,
"Loading maps {Status} ({Duration:F2} seconds)",
"failed",
stopwatch.Elapsed.TotalSeconds
);
throw exception; throw exception;
} }
} }

View file

@ -75,7 +75,7 @@ public partial class Timer
t.Start(); t.Start();
#if DEBUG_TIMERS #if DEBUG_TIMERS
DelayCallTimer._stackTraces[t.GetHashCode()] = $"{callback.Method.Name}\n{new StackTrace()}"; DelayCallTimer._stackTraces[t.GetHashCode()] = $"{callback.Method.Name}{Environment.NewLine}{new StackTrace()}";
#endif #endif
} }
@ -102,7 +102,7 @@ public partial class Timer
t.Start(); t.Start();
#if DEBUG_TIMERS #if DEBUG_TIMERS
DelayCallTimer._stackTraces[t.GetHashCode()] = $"{callback.Method.Name}\n{new StackTrace()}"; DelayCallTimer._stackTraces[t.GetHashCode()] = $"{callback.Method.Name}{Environment.NewLine}{new StackTrace()}";
#endif #endif
token = new TimerExecutionToken(t); token = new TimerExecutionToken(t);
} }
@ -184,7 +184,7 @@ public partial class Timer
} }
#if DEBUG_TIMERS #if DEBUG_TIMERS
logger.Warning("Timer pool depleted and timer was allocated.\n{StackTrace}", new StackTrace()); logger.Warning($"Timer pool depleted and timer was allocated.{Environment.NewLine}{{StackTrace}}", new StackTrace());
#endif #endif
return new DelayCallTimer(delay, interval, count, callback); return new DelayCallTimer(delay, interval, count, callback);
} }
@ -198,7 +198,7 @@ public partial class Timer
{ {
if (!_allowFinalization) if (!_allowFinalization)
{ {
logger.Warning("Pooled timer was not returned to the pool.\n{StackTrace}", _stackTraces[GetHashCode()]); logger.Warning($"Pooled timer was not returned to the pool.{Environment.NewLine}{{StackTrace}}", _stackTraces[GetHashCode()]);
} }
} }
#endif #endif

View file

@ -199,7 +199,7 @@ public partial class Timer
if (lastRing && slot > _ringSize) if (lastRing && slot > _ringSize)
{ {
logger.Error( logger.Error(
"Timer {Timer} has a duration of {Duration}ms, more than max capacity of {MaxDuration}ms.\n{StackTrace}", $"Timer {{Timer}} has a duration of {{Duration}}ms, more than max capacity of {{MaxDuration}}ms.{Environment.NewLine}{{StackTrace}}",
timer.GetType(), timer.GetType(),
originalDelay, originalDelay,
_maxDuration, _maxDuration,
@ -228,8 +228,8 @@ public partial class Timer
public static void DumpInfo(TextWriter tw) public static void DumpInfo(TextWriter tw)
{ {
tw.WriteLine($"Date: {Core.Now.ToLocalTime()}\n"); tw.WriteLine($"Date: {Core.Now.ToLocalTime()}{Environment.NewLine}");
tw.WriteLine($"Pool - Count: {_poolCount}; Capacity {_poolCapacity}\n"); tw.WriteLine($"Pool - Count: {_poolCount}; Capacity {_poolCapacity}{Environment.NewLine}");
var total = 0.0; var total = 0.0;
var hash = new Dictionary<string, int>(); var hash = new Dictionary<string, int>();

View file

@ -82,7 +82,7 @@ public partial class Timer
if (World.WorldState is WorldState.Saving) if (World.WorldState is WorldState.Saving)
{ {
logger.Error( logger.Error(
"Attempted to start timer {Timer} ({HashCode}) while world is {State}\n{StackTrace}", $"Attempted to start timer {{Timer}} ({{HashCode}}) while world is {{State}}{Environment.NewLine}{{StackTrace}}",
GetType(), GetType(),
GetHashCode(), GetHashCode(),
World.WorldState, World.WorldState,
@ -94,7 +94,7 @@ public partial class Timer
if (Thread.CurrentThread != Core.Thread) if (Thread.CurrentThread != Core.Thread)
{ {
logger.Error( logger.Error(
"Attempted to start timer {Timer} ({HashCode}) from an invalid thread!\n{StackTrace}", $"Attempted to start timer {{Timer}} ({{HashCode}}) from an invalid thread!{Environment.NewLine}{{StackTrace}}",
GetType(), GetType(),
GetHashCode(), GetHashCode(),
new StackTrace() new StackTrace()
@ -126,7 +126,7 @@ public partial class Timer
if (World.WorldState is WorldState.Saving) if (World.WorldState is WorldState.Saving)
{ {
logger.Error( logger.Error(
"Attempted to stop timer {Timer} ({HashCode}) while world is {State}\n{StackTrace}", $"Attempted to stop timer {{Timer}} ({{HashCode}}) while world is {{State}}{Environment.NewLine}{{StackTrace}}",
GetType(), GetType(),
GetHashCode(), GetHashCode(),
World.WorldState, World.WorldState,
@ -138,7 +138,7 @@ public partial class Timer
if (Thread.CurrentThread != Core.Thread) if (Thread.CurrentThread != Core.Thread)
{ {
logger.Error( logger.Error(
"Attempted to stop timer {Timer} ({HashCode}) from an invalid thread!\n{StackTrace}", $"Attempted to stop timer {{Timer}} ({{HashCode}}) from an invalid thread!{Environment.NewLine}{{StackTrace}}",
GetType(), GetType(),
GetHashCode(), GetHashCode(),
new StackTrace() new StackTrace()
@ -231,7 +231,11 @@ public partial class Timer
{ {
if (Running) if (Running)
{ {
logger.Error("{Timer} detached while still running!\n{StackTrace}", this, new StackTrace()); logger.Error(
$"{{Timer}} detached while still running!{Environment.NewLine}{{StackTrace}}",
this,
new StackTrace()
);
return; return;
} }

View file

@ -302,7 +302,8 @@ public static class World
watch.Stop(); watch.Stop();
logger.Information("World loaded ({ItemCount} items, {MobileCount} mobiles) ({Duration:F2} seconds)", logger.Information("Loading world {Status} ({ItemCount} items, {MobileCount} mobiles) ({Duration:F2} seconds)",
"done",
Items.Count, Items.Count,
Mobiles.Count, Mobiles.Count,
watch.Elapsed.TotalSeconds watch.Elapsed.TotalSeconds
@ -330,9 +331,9 @@ public static class World
private static void AppendSafetyLog(string action, ISerializable entity) private static void AppendSafetyLog(string action, ISerializable entity)
{ {
var message = var message =
$"Warning: Attempted to {action} {entity} during world save.{Environment.NewLine}This action could cause inconsistent state.{Environment.NewLine}It is strongly advised that the offending scripts be corrected."; $"Warning: Attempted to {{Action}} {{Entity}} during world save.{Environment.NewLine}This action could cause inconsistent state.{Environment.NewLine}It is strongly advised that the offending scripts be corrected.";
logger.Information(message); logger.Information(message, action, entity);
try try
{ {
@ -418,7 +419,7 @@ public static class World
watch.Stop(); watch.Stop();
logger.Information("Writing world save snapshot done ({Duration:F2} seconds)", watch.Elapsed.TotalSeconds); logger.Information("Writing world save snapshot {Status} ({Duration:F2} seconds)", "done", watch.Elapsed.TotalSeconds);
} }
catch (Exception ex) catch (Exception ex)
{ {
@ -427,7 +428,7 @@ public static class World
if (exception != null) if (exception != null)
{ {
logger.Error(exception, "Writing world save snapshot failed."); logger.Error(exception, "Writing world save snapshot {Status}.", "failed");
Persistence.TraceException(exception); Persistence.TraceException(exception);
BroadcastStaff(0x35, true, "Writing world save snapshot failed."); BroadcastStaff(0x35, true, "Writing world save snapshot failed.");
@ -565,7 +566,7 @@ public static class World
if (exception == null) if (exception == null)
{ {
var duration = watch.Elapsed.TotalSeconds; var duration = watch.Elapsed.TotalSeconds;
logger.Information("World save completed ({Duration:F2} seconds)", duration); logger.Information("Saving world {Status} ({Duration:F2} seconds)", "done", duration);
// Only broadcast if it took at least 150ms // Only broadcast if it took at least 150ms
if (duration >= 0.15) if (duration >= 0.15)
@ -575,7 +576,7 @@ public static class World
} }
else else
{ {
logger.Error(exception, "World save failed"); logger.Error(exception, "Saving world {Status}", "failed");
Persistence.TraceException(exception); Persistence.TraceException(exception);
BroadcastStaff(0x35, true, "World save failed."); BroadcastStaff(0x35, true, "World save failed.");
@ -643,7 +644,7 @@ public static class World
{ {
default: // Not Running default: // Not Running
{ {
throw new Exception($"Added {entity.GetType().Name} before world load.\n"); throw new Exception($"Added {entity.GetType().Name} before world load.");
} }
case WorldState.Saving: case WorldState.Saving:
{ {
@ -671,7 +672,7 @@ public static class World
if (existing == entity) if (existing == entity)
{ {
logger.Error( logger.Error(
"Attempted to add '{Entity}' ({Serial}) to World.Items but it already exists in the collection.\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Items but it already exists in the collection.{Environment.NewLine}{{StackTrace}}",
entity.GetType().FullName, entity.GetType().FullName,
entity.Serial, entity.Serial,
new StackTrace() new StackTrace()
@ -680,7 +681,7 @@ public static class World
else else
{ {
logger.Error( logger.Error(
"Attempted to add '{Entity}' ({Serial}) to World.Items but found '{ExistingEntity}' ({ExistingSerial}).\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Items but found '{{ExistingEntity}}' ({{ExistingSerial}}).{Environment.NewLine}{{StackTrace}}",
entity.GetType().FullName, entity.GetType().FullName,
entity.Serial, entity.Serial,
existing.GetType().FullName, existing.GetType().FullName,
@ -700,7 +701,7 @@ public static class World
if (existing == entity) if (existing == entity)
{ {
logger.Error( logger.Error(
"Attempted to add '{Entity}' ({Serial}) to World.Mobiles but it already exists in the collection.\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Mobiles but it already exists in the collection.{Environment.NewLine}{{StackTrace}}",
entity.GetType().FullName, entity.GetType().FullName,
entity.Serial, entity.Serial,
new StackTrace() new StackTrace()
@ -709,7 +710,7 @@ public static class World
else else
{ {
logger.Error( logger.Error(
"Attempted to add '{{Entity}}' ({{Serial}}) to World.Mobiles but found '{{ExistingEntity}}' ({{ExistingSerial}}).\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Mobiles but found '{{ExistingEntity}}' ({{ExistingSerial}}).{Environment.NewLine}{{StackTrace}}",
entity.GetType().FullName, entity.GetType().FullName,
entity.Serial, entity.Serial,
existing.GetType().FullName, existing.GetType().FullName,
@ -733,7 +734,7 @@ public static class World
if (existing == guild) if (existing == guild)
{ {
logger.Error( logger.Error(
"Attempted to add '{Entity}' ({Serial}) to World.Guilds but it already exists in the collection.\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Guilds but it already exists in the collection.{Environment.NewLine}{{StackTrace}}",
guild.GetType().FullName, guild.GetType().FullName,
guild.Serial, guild.Serial,
new StackTrace() new StackTrace()
@ -742,7 +743,7 @@ public static class World
else else
{ {
logger.Error( logger.Error(
"Attempted to add '{{Entity}}' ({{Serial}}) to World.Guilds but found '{{ExistingEntity}}' ({{ExistingSerial}}).\n{StackTrace}", $"Attempted to add '{{Entity}}' ({{Serial}}) to World.Guilds but found '{{ExistingEntity}}' ({{ExistingSerial}}).{Environment.NewLine}{{StackTrace}}",
guild.GetType().FullName, guild.GetType().FullName,
guild.Serial, guild.Serial,
existing.GetType().FullName, existing.GetType().FullName,
@ -759,7 +760,7 @@ public static class World
{ {
default: // Not Running default: // Not Running
{ {
throw new Exception($"Removed {entity.GetType().Name} before world load.\n"); throw new Exception($"Removed {entity.GetType().Name} before world load.");
} }
case WorldState.Saving: case WorldState.Saving:
{ {

View file

@ -51,17 +51,17 @@ namespace Server.Configurations
if (settings == null) if (settings == null)
{ {
logger.Error($"Failed reading email configuration from {m_RelPath}"); logger.Error("Failed reading email configuration from {Path}", m_RelPath);
throw new JsonException($"Failed to deserialize {path}."); throw new JsonException($"Failed to deserialize {path}.");
} }
logger.Information($"Email configuration read from {m_RelPath}"); logger.Information("Email configuration read from {Path}", m_RelPath);
} }
else else
{ {
settings = new Settings(); settings = new Settings();
JsonConfig.Serialize(path, settings); JsonConfig.Serialize(path, settings);
logger.Information($"Email configuration saved to {m_RelPath}."); logger.Information("Email configuration saved to {}.", m_RelPath);
} }
EmailEnabled = settings.enabled; EmailEnabled = settings.enabled;

View file

@ -85,7 +85,7 @@ namespace Server.Engines.Spawners
{ {
var file = files[i]; var file = files[i];
from.SendMessage("GenerateSpawners: Generating spawners from {0}...", file.Name); from.SendMessage("GenerateSpawners: Generating spawners from {0}...", file.Name);
logger.Information($"{from} is generating spawners from {file.FullName}"); logger.Information("{User} is generating spawners from {File}", from, file.FullName);
NetState.FlushAll(); NetState.FlushAll();
@ -213,7 +213,7 @@ namespace Server.Engines.Spawners
} }
#if DEBUG #if DEBUG
logger.Error($"{message}\n{ex}"); logger.Error(ex, message);
#endif #endif
} }
} }

View file

@ -53,7 +53,9 @@ namespace Server.Misc
if (MinRequired != null || MaxRequired != null) if (MinRequired != null || MaxRequired != null)
{ {
logger.Information( logger.Information(
$"Restricting client version to {GetVersionExpression()}. Action to be taken: {_invalidClientResponse}" "Restricting client version to {ClientVersion}. Action to be taken: {Action}",
GetVersionExpression(),
_invalidClientResponse
); );
} }
} }

View file

@ -112,11 +112,11 @@ namespace Server.Misc
DirectoryCopy(savePath, backupPath); DirectoryCopy(savePath, backupPath);
} }
logger.Information("Backup done"); logger.Information("Backup {Status}", "done");
} }
catch catch
{ {
logger.Error("Backup failed"); logger.Error("Backup {Status}", "failed");
} }
} }

View file

@ -99,7 +99,7 @@ namespace Server.Saves
var backupPath = Path.Combine(AutomaticBackupPath, Utility.GetTimeStamp()); var backupPath = Path.Combine(AutomaticBackupPath, Utility.GetTimeStamp());
PathUtility.MoveDirectory(args.OldSavePath, backupPath); PathUtility.MoveDirectory(args.OldSavePath, backupPath);
logger.Information($"Created backup at {backupPath}"); logger.Information("Created backup at {Path}", backupPath);
Archive?.Invoke(); Archive?.Invoke();
} }
@ -132,7 +132,7 @@ namespace Server.Saves
return false; return false;
} }
logger.Information($"Restoring latest world save from archive {fileName}"); logger.Information("Restoring latest world save from archive {File}", fileName);
var tempPath = PathUtility.EnsureRandomPath(_tempArchivePath); var tempPath = PathUtility.EnsureRandomPath(_tempArchivePath);
var successful = fileName.EndsWithOrdinal(".tar.zst") var successful = fileName.EndsWithOrdinal(".tar.zst")
@ -141,7 +141,7 @@ namespace Server.Saves
if (!successful) if (!successful)
{ {
logger.Information($"Failed to extract {fi.Name}"); logger.Information("Failed to extract {File}", fi.Name);
return false; return false;
} }
@ -149,7 +149,7 @@ namespace Server.Saves
{ {
Directory.Delete(savePath, true); Directory.Delete(savePath, true);
var dirInfo = new DirectoryInfo(folder); var dirInfo = new DirectoryInfo(folder);
logger.Information($"Restoring backup {dirInfo.Name}"); logger.Information("Restoring backup {Directory}", dirInfo.Name);
PathUtility.MoveDirectory(folder, savePath); PathUtility.MoveDirectory(folder, savePath);
break; break;
} }
@ -188,7 +188,7 @@ namespace Server.Saves
if (date < threshold) if (date < threshold)
{ {
logger.Information($"Pruning old backup {folder}"); logger.Information("Pruning old backup {Directory}", folder);
Directory.Delete(folder, true); Directory.Delete(folder, true);
} }
} }
@ -213,7 +213,7 @@ namespace Server.Saves
} }
var fi = new FileInfo(archive); var fi = new FileInfo(archive);
logger.Information($"Pruning {periodLowerStr} archive {fi.Name}"); logger.Information("Pruning {Period} archive {File}", periodLowerStr, fi.Name);
File.Delete(archive); File.Delete(archive);
} }
} }
@ -331,7 +331,12 @@ namespace Server.Saves
if (archiveCreated) if (archiveCreated)
{ {
var elapsed = stopWatch.Elapsed.TotalSeconds; var elapsed = stopWatch.Elapsed.TotalSeconds;
logger.Information($"Created {archivePeriodStrLower} archive at {archiveFilePath} ({elapsed:F2} seconds)"); logger.Information(
"Created {Period} archive at {Path} ({Elapsed:F2} seconds)",
archivePeriodStrLower,
archiveFilePath,
elapsed
);
var i = minimum; var i = minimum;
foreach (var backup in backups) foreach (var backup in backups)