You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

462 lines
18 KiB

4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
4 years ago
  1. #nullable enable
  2. using IPA.Config;
  3. using IPA.Logging.Printers;
  4. using IPA.Utilities;
  5. using System;
  6. using System.Collections.Concurrent;
  7. using System.Collections.Generic;
  8. using System.Diagnostics;
  9. using System.IO;
  10. using System.Linq;
  11. using System.Threading;
  12. namespace IPA.Logging
  13. {
  14. /// <summary>
  15. /// The default (and standard) <see cref="Logger"/> implementation.
  16. /// </summary>
  17. /// <remarks>
  18. /// <see cref="StandardLogger"/> uses a multi-threaded approach to logging. All actual I/O is done on another thread,
  19. /// where all messaged are guaranteed to be logged in the order they appeared. It is up to the printers to format them.
  20. ///
  21. /// This logger supports child loggers. Use <see cref="LoggerExtensions.GetChildLogger"/> to safely get a child.
  22. /// The modification of printers on a parent are reflected down the chain.
  23. /// </remarks>
  24. public class StandardLogger : Logger
  25. {
  26. private static readonly List<LogPrinter> defaultPrinters = new();
  27. static StandardLogger()
  28. {
  29. ConsoleColorSupport();
  30. }
  31. private static bool addedConsolePrinters;
  32. private static bool finalizedDefaultPrinters;
  33. internal static void ConsoleColorSupport()
  34. {
  35. if (!addedConsolePrinters && !finalizedDefaultPrinters && WinConsole.IsInitialized )
  36. {
  37. defaultPrinters.AddRange(new []
  38. {
  39. new ColoredConsolePrinter()
  40. {
  41. Filter = LogLevel.TraceOnly,
  42. Color = ConsoleColor.DarkMagenta,
  43. },
  44. new ColoredConsolePrinter()
  45. {
  46. Filter = LogLevel.DebugOnly,
  47. Color = ConsoleColor.Green,
  48. },
  49. new ColoredConsolePrinter()
  50. {
  51. Filter = LogLevel.InfoOnly,
  52. Color = ConsoleColor.White,
  53. },
  54. new ColoredConsolePrinter()
  55. {
  56. Filter = LogLevel.NoticeOnly,
  57. Color = ConsoleColor.Cyan
  58. },
  59. new ColoredConsolePrinter()
  60. {
  61. Filter = LogLevel.WarningOnly,
  62. Color = ConsoleColor.Yellow,
  63. },
  64. new ColoredConsolePrinter()
  65. {
  66. Filter = LogLevel.ErrorOnly,
  67. Color = ConsoleColor.Red,
  68. },
  69. new ColoredConsolePrinter()
  70. {
  71. Filter = LogLevel.CriticalOnly,
  72. Color = ConsoleColor.Magenta,
  73. }
  74. });
  75. addedConsolePrinters = true;
  76. }
  77. }
  78. /// <summary>
  79. /// The <see cref="TextWriter"/> for writing directly to the console window, or stdout if no window open.
  80. /// </summary>
  81. /// <value>a <see cref="TextWriter"/> for the current primary text output</value>
  82. public static TextWriter ConsoleWriter { get; internal set; } = Console.Out;
  83. /// <summary>
  84. /// Adds to the default printer pool that all printers inherit from. Printers added this way will be passed every message from every logger.
  85. /// </summary>
  86. /// <param name="printer">the printer to add</param>
  87. internal static void AddDefaultPrinter(LogPrinter printer)
  88. {
  89. defaultPrinters.Add(printer);
  90. }
  91. private readonly string logName;
  92. private static bool showSourceClass;
  93. /// <summary>
  94. /// All levels defined by this filter will be sent to loggers. All others will be ignored.
  95. /// </summary>
  96. /// <value>the global filter level</value>
  97. public static LogLevel PrintFilter { get; internal set; } = LogLevel.All;
  98. private static bool showTrace = false;
  99. private static volatile bool syncLogging = false;
  100. private readonly List<LogPrinter> printers = new();
  101. private readonly StandardLogger? parent;
  102. private readonly Dictionary<string, StandardLogger> children = new();
  103. private static bool addedFilePrinter = false;
  104. /// <summary>
  105. /// Configures internal debug settings based on the config passed in.
  106. /// </summary>
  107. internal static void Configure()
  108. {
  109. showSourceClass = SelfConfig.Debug_.ShowCallSource_;
  110. PrintFilter = SelfConfig.Debug_.ShowDebug_ ? LogLevel.All : LogLevel.InfoUp;
  111. showTrace = SelfConfig.Debug_.ShowTrace_;
  112. syncLogging = SelfConfig.Debug_.SyncLogging_;
  113. if(SelfConfig.CommandLineValues.WriteLogs && !addedFilePrinter) {
  114. addedFilePrinter = true;
  115. AddDefaultPrinter(new GlobalLogFilePrinter());
  116. }
  117. }
  118. private StandardLogger(StandardLogger parent, string subName)
  119. {
  120. logName = $"{parent.logName}/{subName}";
  121. this.parent = parent;
  122. printers = new List<LogPrinter>();
  123. if (SelfConfig.Debug_.CreateModLogs_ && !SelfConfig.Debug_.CondenseModLogs_)
  124. printers.Add(new PluginSubLogPrinter(parent.logName, subName));
  125. if (logThread == null || !logThread.IsAlive)
  126. {
  127. logThread = new Thread(LogThread);
  128. logThread.Start();
  129. }
  130. }
  131. internal StandardLogger(string name)
  132. {
  133. ConsoleColorSupport();
  134. if (!finalizedDefaultPrinters)
  135. {
  136. if (!addedConsolePrinters)
  137. AddDefaultPrinter(new ColorlessConsolePrinter());
  138. finalizedDefaultPrinters = true;
  139. }
  140. logName = name;
  141. if (SelfConfig.Debug_.CreateModLogs_)
  142. printers.Add(new PluginLogFilePrinter(name));
  143. if (logThread == null || !logThread.IsAlive)
  144. {
  145. logThread = new Thread(LogThread);
  146. logThread.Start();
  147. }
  148. }
  149. /// <summary>
  150. /// Gets a child printer with the given name, either constructing a new one or using one that was already made.
  151. /// </summary>
  152. /// <param name="name"></param>
  153. /// <returns>a child <see cref="StandardLogger"/> with the given sub-name</returns>
  154. internal StandardLogger GetChild(string name)
  155. {
  156. if (!children.TryGetValue(name, out var child))
  157. {
  158. child = new StandardLogger(this, name);
  159. children.Add(name, child);
  160. }
  161. return child;
  162. }
  163. /// <summary>
  164. /// Adds a log printer to the logger.
  165. /// </summary>
  166. /// <param name="printer">the printer to add</param>
  167. public void AddPrinter(LogPrinter printer)
  168. {
  169. printers.Add(printer);
  170. }
  171. /// <summary>
  172. /// Logs a specific message at a given level.
  173. /// </summary>
  174. /// <param name="level">the message level</param>
  175. /// <param name="message">the message to log</param>
  176. public override void Log(Level level, string message)
  177. {
  178. if (message == null)
  179. throw new ArgumentNullException(nameof(message));
  180. // FIXME: trace doesn't seem to ever actually appear
  181. if (!showTrace && level == Level.Trace) return;
  182. // make sure that the queue isn't being cleared
  183. logWaitEvent.Wait();
  184. try
  185. {
  186. var sync = syncLogging && !IsOnLoggerThread;
  187. if (sync)
  188. {
  189. threadSync ??= new ManualResetEventSlim();
  190. threadSync.Reset();
  191. }
  192. logQueue.Add(new LogMessage
  193. {
  194. Level = level,
  195. Message = message,
  196. Logger = this,
  197. Time = Utils.CurrentTime(),
  198. Sync = threadSync
  199. });
  200. if (sync) threadSync!.Wait();
  201. }
  202. catch (InvalidOperationException)
  203. {
  204. // the queue has been closed, so we leave it
  205. }
  206. }
  207. [ThreadStatic]
  208. private static ManualResetEventSlim? threadSync;
  209. /// <inheritdoc />
  210. /// <summary>
  211. /// An override to <see cref="M:IPA.Logging.Logger.Debug(System.String)" /> which shows the method that called it.
  212. /// </summary>
  213. /// <param name="message">the message to log</param>
  214. public override void Debug(string message)
  215. {
  216. if (showSourceClass)
  217. {
  218. // add source to message
  219. var stackFrame = new StackTrace(true).GetFrame(1);
  220. var lineNo = stackFrame.GetFileLineNumber();
  221. if (lineNo == 0)
  222. { // no debug info
  223. var method = stackFrame.GetMethod();
  224. var paramString = string.Join(", ", method.GetParameters().Select(p => p.ParameterType.FullName).StrJP());
  225. message = $"{{{method.DeclaringType?.FullName}::{method.Name}({paramString})}} {message}";
  226. }
  227. else
  228. message = $"{{{stackFrame.GetFileName()}:{lineNo}}} {message}";
  229. }
  230. base.Debug(message);
  231. }
  232. private struct LogMessage
  233. {
  234. public Level Level;
  235. public StandardLogger Logger;
  236. public string Message;
  237. public DateTime Time;
  238. public ManualResetEventSlim? Sync;
  239. }
  240. [ThreadStatic]
  241. private static bool? isOnLoggerThread = null;
  242. /// <summary>
  243. /// Whether or not the calling thread is the logger thread.
  244. /// </summary>
  245. /// <value><see langword="true"/> if the current thread is the logger thread, <see langword="false"/> otherwise</value>
  246. public static bool IsOnLoggerThread => isOnLoggerThread ??= Thread.CurrentThread.ManagedThreadId == logThread?.ManagedThreadId;
  247. private static readonly ManualResetEventSlim logWaitEvent = new(true);
  248. private static readonly BlockingCollection<LogMessage> logQueue = new();
  249. private static Thread? logThread;
  250. private static StandardLogger? loggerLogger;
  251. private const int LogCloseTimeout = 250;
  252. /// <summary>
  253. /// The log printer thread for <see cref="StandardLogger"/>.
  254. /// </summary>
  255. private static void LogThread()
  256. {
  257. AppDomain.CurrentDomain.ProcessExit += (sender, args) =>
  258. {
  259. StopLogThread();
  260. };
  261. loggerLogger = new StandardLogger("Log Subsystem");
  262. loggerLogger.printers.Clear(); // don't need a log file for this one
  263. var timeout = TimeSpan.FromMilliseconds(LogCloseTimeout);
  264. try
  265. {
  266. var started = new HashSet<LogPrinter>();
  267. while (logQueue.TryTake(out var msg, Timeout.Infinite))
  268. {
  269. StdoutInterceptor.Intercept(); // only runs once, after the first message is queued
  270. do
  271. {
  272. var logger = msg.Logger;
  273. IEnumerable<LogPrinter> printers = logger.printers;
  274. do
  275. { // aggregate all printers in the inheritance chain
  276. logger = logger.parent;
  277. if (logger != null)
  278. printers = printers.Concat(logger.printers);
  279. } while (logger != null);
  280. foreach (var printer in printers.Concat(defaultPrinters))
  281. {
  282. try
  283. { // print to them all
  284. if (((byte)msg.Level & (byte)printer.Filter) != 0)
  285. {
  286. if (!started.Contains(printer))
  287. { // start printer if not started
  288. printer.StartPrint();
  289. _ = started.Add(printer);
  290. }
  291. // update last use time and print
  292. printer.LastUse = Utils.CurrentTime();
  293. printer.Print(msg.Level, msg.Time, msg.Logger.logName, msg.Message);
  294. }
  295. }
  296. catch (Exception e)
  297. {
  298. // do something sane in the face of an error
  299. Console.WriteLine($"printer errored: {e}");
  300. }
  301. }
  302. msg.Sync?.Set();
  303. var debugConfig = SelfConfig.Instance?.Debug;
  304. if (debugConfig != null && debugConfig.HideMessagesForPerformance
  305. && logQueue.Count > debugConfig.HideLogThreshold)
  306. { // spam filtering (if queue has more than HideLogThreshold elements)
  307. logWaitEvent.Reset(); // pause incoming log requests
  308. // clear loggers for this instance, to print the message to all affected logs
  309. loggerLogger.printers.Clear();
  310. var prints = new HashSet<LogPrinter>();
  311. // clear the queue
  312. while (logQueue.TryTake(out var message))
  313. { // aggregate loggers in the process
  314. var messageLogger = message.Logger;
  315. foreach (var print in messageLogger.printers)
  316. _ = prints.Add(print);
  317. do
  318. {
  319. messageLogger = messageLogger.parent;
  320. if (messageLogger != null)
  321. foreach (var print in messageLogger.printers)
  322. _ = prints.Add(print);
  323. } while (messageLogger != null);
  324. message.Sync?.Set();
  325. }
  326. // print using logging subsystem to all logger printers
  327. loggerLogger.printers.AddRange(prints);
  328. logQueue.Add(new LogMessage
  329. { // manually adding to the queue instead of using Warn() because calls to the logger are suspended here
  330. Level = Level.Warning,
  331. Logger = loggerLogger,
  332. Message = $"{loggerLogger.logName.ToUpper()}: Messages omitted to improve performance",
  333. Time = Utils.CurrentTime()
  334. });
  335. // resume log calls
  336. logWaitEvent.Set();
  337. }
  338. var now = Utils.CurrentTime();
  339. var copy = new List<LogPrinter>(started);
  340. foreach (var printer in copy)
  341. {
  342. // close printer after 500ms from its last use
  343. if (now - printer.LastUse > timeout)
  344. {
  345. try
  346. {
  347. printer.EndPrint();
  348. }
  349. catch (Exception e)
  350. {
  351. Console.WriteLine($"printer errored: {e}");
  352. }
  353. _ = started.Remove(printer);
  354. }
  355. }
  356. }
  357. // wait for messages for 500ms before ending the prints
  358. while (logQueue.TryTake(out msg, timeout));
  359. if (logQueue.Count == 0)
  360. { // when the queue has been empty for 500ms, end all prints
  361. foreach (var printer in started)
  362. {
  363. try
  364. {
  365. printer.EndPrint();
  366. }
  367. catch (Exception e)
  368. {
  369. Console.WriteLine($"printer errored: {e}");
  370. }
  371. }
  372. started.Clear();
  373. }
  374. }
  375. }
  376. catch (InvalidOperationException)
  377. {
  378. }
  379. }
  380. /// <summary>
  381. /// Stops and joins the log printer thread.
  382. /// </summary>
  383. internal static void StopLogThread()
  384. {
  385. logQueue.CompleteAdding();
  386. logThread!.Join();
  387. }
  388. }
  389. /// <summary>
  390. /// A class providing extensions for various loggers.
  391. /// </summary>
  392. public static class LoggerExtensions
  393. {
  394. /// <summary>
  395. /// Gets a child logger, if supported. Currently the only defined and supported logger is <see cref="StandardLogger"/>, and most plugins will only ever receive this anyway.
  396. /// </summary>
  397. /// <param name="logger">the parent <see cref="Logger"/></param>
  398. /// <param name="name">the name of the child</param>
  399. /// <returns>the child logger</returns>
  400. public static Logger GetChildLogger(this Logger logger, string name)
  401. => logger switch
  402. {
  403. StandardLogger l => l.GetChild(name),
  404. _ => throw new InvalidOperationException()
  405. };
  406. }
  407. }