#nullable enable using IPA.Config; using IPA.Logging.Printers; using IPA.Utilities; using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; using System.Threading; namespace IPA.Logging { /// /// The default (and standard) implementation. /// /// /// uses a multi-threaded approach to logging. All actual I/O is done on another thread, /// where all messaged are guaranteed to be logged in the order they appeared. It is up to the printers to format them. /// /// This logger supports child loggers. Use to safely get a child. /// The modification of printers on a parent are reflected down the chain. /// public class StandardLogger : Logger { private static readonly List defaultPrinters = new() { new GlobalLogFilePrinter() }; static StandardLogger() { ConsoleColorSupport(); } private static bool addedConsolePrinters; private static bool finalizedDefaultPrinters; internal static void ConsoleColorSupport() { if (!addedConsolePrinters && !finalizedDefaultPrinters && WinConsole.IsInitialized ) { defaultPrinters.AddRange(new [] { new ColoredConsolePrinter() { Filter = LogLevel.TraceOnly, Color = ConsoleColor.DarkMagenta, }, new ColoredConsolePrinter() { Filter = LogLevel.DebugOnly, Color = ConsoleColor.Green, }, new ColoredConsolePrinter() { Filter = LogLevel.InfoOnly, Color = ConsoleColor.White, }, new ColoredConsolePrinter() { Filter = LogLevel.NoticeOnly, Color = ConsoleColor.Cyan }, new ColoredConsolePrinter() { Filter = LogLevel.WarningOnly, Color = ConsoleColor.Yellow, }, new ColoredConsolePrinter() { Filter = LogLevel.ErrorOnly, Color = ConsoleColor.Red, }, new ColoredConsolePrinter() { Filter = LogLevel.CriticalOnly, Color = ConsoleColor.Magenta, } }); addedConsolePrinters = true; } } /// /// The for writing directly to the console window, or stdout if no window open. /// /// a for the current primary text output public static TextWriter ConsoleWriter { get; internal set; } = Console.Out; /// /// Adds to the default printer pool that all printers inherit from. Printers added this way will be passed every message from every logger. /// /// the printer to add internal static void AddDefaultPrinter(LogPrinter printer) { defaultPrinters.Add(printer); } private readonly string logName; private static bool showSourceClass; /// /// All levels defined by this filter will be sent to loggers. All others will be ignored. /// /// the global filter level public static LogLevel PrintFilter { get; internal set; } = LogLevel.All; private static bool showTrace = false; private static volatile bool syncLogging = false; private readonly List printers = new(); private readonly StandardLogger? parent; private readonly Dictionary children = new(); /// /// Configures internal debug settings based on the config passed in. /// internal static void Configure() { showSourceClass = SelfConfig.Debug_.ShowCallSource_; PrintFilter = SelfConfig.Debug_.ShowDebug_ ? LogLevel.All : LogLevel.InfoUp; showTrace = SelfConfig.Debug_.ShowTrace_; syncLogging = SelfConfig.Debug_.SyncLogging_; } private StandardLogger(StandardLogger parent, string subName) { logName = $"{parent.logName}/{subName}"; this.parent = parent; printers = new List(); if (SelfConfig.Debug_.CreateModLogs_ && !SelfConfig.Debug_.CondenseModLogs_) printers.Add(new PluginSubLogPrinter(parent.logName, subName)); if (logThread == null || !logThread.IsAlive) { logThread = new Thread(LogThread); logThread.Start(); } } internal StandardLogger(string name) { ConsoleColorSupport(); if (!finalizedDefaultPrinters) { if (!addedConsolePrinters) AddDefaultPrinter(new ColorlessConsolePrinter()); finalizedDefaultPrinters = true; } logName = name; if (SelfConfig.Debug_.CreateModLogs_) printers.Add(new PluginLogFilePrinter(name)); if (logThread == null || !logThread.IsAlive) { logThread = new Thread(LogThread); logThread.Start(); } } /// /// Gets a child printer with the given name, either constructing a new one or using one that was already made. /// /// /// a child with the given sub-name internal StandardLogger GetChild(string name) { if (!children.TryGetValue(name, out var child)) { child = new StandardLogger(this, name); children.Add(name, child); } return child; } /// /// Adds a log printer to the logger. /// /// the printer to add public void AddPrinter(LogPrinter printer) { printers.Add(printer); } /// /// Logs a specific message at a given level. /// /// the message level /// the message to log public override void Log(Level level, string message) { if (message == null) throw new ArgumentNullException(nameof(message)); // FIXME: trace doesn't seem to ever actually appear if (!showTrace && level == Level.Trace) return; // make sure that the queue isn't being cleared logWaitEvent.Wait(); try { var sync = syncLogging && !IsOnLoggerThread; if (sync) { threadSync ??= new ManualResetEventSlim(); threadSync.Reset(); } logQueue.Add(new LogMessage { Level = level, Message = message, Logger = this, Time = Utils.CurrentTime(), Sync = threadSync }); if (sync) threadSync!.Wait(); } catch (InvalidOperationException) { // the queue has been closed, so we leave it } } [ThreadStatic] private static ManualResetEventSlim? threadSync; /// /// /// An override to which shows the method that called it. /// /// the message to log public override void Debug(string message) { if (showSourceClass) { // add source to message var stackFrame = new StackTrace(true).GetFrame(1); var lineNo = stackFrame.GetFileLineNumber(); if (lineNo == 0) { // no debug info var method = stackFrame.GetMethod(); var paramString = string.Join(", ", method.GetParameters().Select(p => p.ParameterType.FullName).StrJP()); message = $"{{{method.DeclaringType?.FullName}::{method.Name}({paramString})}} {message}"; } else message = $"{{{stackFrame.GetFileName()}:{lineNo}}} {message}"; } base.Debug(message); } private struct LogMessage { public Level Level; public StandardLogger Logger; public string Message; public DateTime Time; public ManualResetEventSlim? Sync; } [ThreadStatic] private static bool? isOnLoggerThread = null; /// /// Whether or not the calling thread is the logger thread. /// /// if the current thread is the logger thread, otherwise public static bool IsOnLoggerThread => isOnLoggerThread ??= Thread.CurrentThread.ManagedThreadId == logThread?.ManagedThreadId; private static readonly ManualResetEventSlim logWaitEvent = new(true); private static readonly BlockingCollection logQueue = new(); private static Thread? logThread; private static StandardLogger? loggerLogger; private const int LogCloseTimeout = 250; /// /// The log printer thread for . /// private static void LogThread() { AppDomain.CurrentDomain.ProcessExit += (sender, args) => { StopLogThread(); }; loggerLogger = new StandardLogger("Log Subsystem"); loggerLogger.printers.Clear(); // don't need a log file for this one var timeout = TimeSpan.FromMilliseconds(LogCloseTimeout); try { var started = new HashSet(); while (logQueue.TryTake(out var msg, Timeout.Infinite)) { StdoutInterceptor.Intercept(); // only runs once, after the first message is queued do { var logger = msg.Logger; IEnumerable printers = logger.printers; do { // aggregate all printers in the inheritance chain logger = logger.parent; if (logger != null) printers = printers.Concat(logger.printers); } while (logger != null); foreach (var printer in printers.Concat(defaultPrinters)) { try { // print to them all if (((byte)msg.Level & (byte)printer.Filter) != 0) { if (!started.Contains(printer)) { // start printer if not started printer.StartPrint(); _ = started.Add(printer); } // update last use time and print printer.LastUse = Utils.CurrentTime(); printer.Print(msg.Level, msg.Time, msg.Logger.logName, msg.Message); } } catch (Exception e) { // do something sane in the face of an error Console.WriteLine($"printer errored: {e}"); } } msg.Sync?.Set(); var debugConfig = SelfConfig.Instance?.Debug; if (debugConfig != null && debugConfig.HideMessagesForPerformance && logQueue.Count > debugConfig.HideLogThreshold) { // spam filtering (if queue has more than HideLogThreshold elements) logWaitEvent.Reset(); // pause incoming log requests // clear loggers for this instance, to print the message to all affected logs loggerLogger.printers.Clear(); var prints = new HashSet(); // clear the queue while (logQueue.TryTake(out var message)) { // aggregate loggers in the process var messageLogger = message.Logger; foreach (var print in messageLogger.printers) _ = prints.Add(print); do { messageLogger = messageLogger.parent; if (messageLogger != null) foreach (var print in messageLogger.printers) _ = prints.Add(print); } while (messageLogger != null); message.Sync?.Set(); } // print using logging subsystem to all logger printers loggerLogger.printers.AddRange(prints); logQueue.Add(new LogMessage { // manually adding to the queue instead of using Warn() because calls to the logger are suspended here Level = Level.Warning, Logger = loggerLogger, Message = $"{loggerLogger.logName.ToUpper()}: Messages omitted to improve performance", Time = Utils.CurrentTime() }); // resume log calls logWaitEvent.Set(); } var now = Utils.CurrentTime(); var copy = new List(started); foreach (var printer in copy) { // close printer after 500ms from its last use if (now - printer.LastUse > timeout) { try { printer.EndPrint(); } catch (Exception e) { Console.WriteLine($"printer errored: {e}"); } _ = started.Remove(printer); } } } // wait for messages for 500ms before ending the prints while (logQueue.TryTake(out msg, timeout)); if (logQueue.Count == 0) { // when the queue has been empty for 500ms, end all prints foreach (var printer in started) { try { printer.EndPrint(); } catch (Exception e) { Console.WriteLine($"printer errored: {e}"); } } started.Clear(); } } } catch (InvalidOperationException) { } } /// /// Stops and joins the log printer thread. /// internal static void StopLogThread() { logQueue.CompleteAdding(); logThread!.Join(); } } /// /// A class providing extensions for various loggers. /// public static class LoggerExtensions { /// /// Gets a child logger, if supported. Currently the only defined and supported logger is , and most plugins will only ever receive this anyway. /// /// the parent /// the name of the child /// the child logger public static Logger GetChildLogger(this Logger logger, string name) => logger switch { StandardLogger l => l.GetChild(name), _ => throw new InvalidOperationException() }; } }