PageRenderTime 58ms CodeModel.GetById 20ms RepoModel.GetById 0ms app.codeStats 0ms

/Utilities/Log.cs

#
C# | 1749 lines | 953 code | 158 blank | 638 comment | 94 complexity | a4fae9a7924d1d1351afe3d79a30e061 MD5 | raw file
Possible License(s): Apache-2.0
  1. using System;
  2. using System.Collections.Generic;
  3. using System.ComponentModel;
  4. using System.Diagnostics;
  5. using System.IO;
  6. using System.Reflection;
  7. using System.Text;
  8. using Delta.Utilities.Helpers;
  9. using Delta.Utilities.Profiling;
  10. using NUnit.Framework;
  11. namespace Delta.Utilities
  12. {
  13. /// <summary>
  14. /// Log, handles all the message logging and storing the messages in an
  15. /// extra file which helps for later tracking and fixing bugs. Some extra
  16. /// functionality is provided by Delta.Engine, which sets up the log server
  17. /// to send log messages to a log server if specified in the application
  18. /// settings. Usually logging happens to the console and a log file.
  19. /// </summary>
  20. public class Log : IDisposable
  21. {
  22. #region Constants
  23. /// <summary>
  24. /// The text encoding format for all our logs.
  25. /// </summary>
  26. private static readonly Encoding TextFormat = Encoding.UTF8;
  27. /// <summary>
  28. /// The default extension for all our log files. Note 2011-04-06: Changed
  29. /// to .txt to make it easier to open by end users (.log is not longer
  30. /// used and has no special behavior anymore).
  31. /// </summary>
  32. private const string FileExtension = "txt";
  33. /// <summary>
  34. /// The maximum file size for a log file is 10 MB, if we go above that
  35. /// (e.g. if too much info is written every frame), then we cut the file
  36. /// in half (5 MB) and append from there. This way we have both the
  37. /// first 5 MB of the application run and the last log entries as well.
  38. /// </summary>
  39. private const int MaxLogFileSize = 10 * 1024 * 1024;
  40. /// <summary>
  41. /// The maximum size for log archive files is 20 MB, if we go above that,
  42. /// we will remove data from the beginning before appending new stuff at
  43. /// the end (the FileHelper.AppendTextToFile handles this all for us).
  44. /// </summary>
  45. private const int MaxArchiveLogFileSize = 20 * 1024 * 1024;
  46. /// <summary>
  47. /// Default log name. Currently set to Engine in case something is logged
  48. /// in DynamicBase or Factory, will be overwritten in Application.Start!
  49. /// </summary>
  50. internal const string DefaultLogName = "Engine";
  51. /// <summary>
  52. /// Helper to figure out when this application was started. This is
  53. /// not really the application start time because we will use the time
  54. /// the Log class is first accessed, but since we do that pretty much
  55. /// always at the application start (just to set the ProgramName, etc.)
  56. /// it will be the correct time. Used for the LogHeader!
  57. /// </summary>
  58. private static readonly DateTime applicationStartTime = DateTime.Now;
  59. /// <summary>
  60. /// Only remember the last 8 logged messages for CheckDuplicateMessage!
  61. /// </summary>
  62. private static readonly Queue<string> lastLoggedMessages = new Queue<string>(8);
  63. /// <summary>
  64. /// Maximum of Console.WriteLines we allow because of poor WriteLine
  65. /// performance in debug mode with debugging window open in Visual Studio!
  66. /// </summary>
  67. private const int MaxConsoleWritesPerSecond = 10;
  68. /// <summary>
  69. /// Only remember the last 10 Console.WriteLines, skip all lines than 10
  70. /// console writes, completely cut of any Console.WriteLines then. This
  71. /// way we should not lose more than 10*5ms = 50ms per second. See unit
  72. /// test below: 6ms for 30 characters writing to an attached debug window.
  73. /// </summary>
  74. private static readonly Queue<long> lastConsoleWriteTimes =
  75. new Queue<long>(MaxConsoleWritesPerSecond);
  76. #endregion
  77. #region Delegates
  78. /// <summary>
  79. /// The log delegate is used for other classes to attach to all log events
  80. /// that happen (both Log.Info and Log.Warning calls, but not Log.Test).
  81. /// It provides an already formated log text string and it used for example
  82. /// in the Delta.Engine.Application class to add Log Server features.
  83. /// </summary>
  84. /// <param name="message">Message</param>
  85. public delegate void LogDelegate(string message);
  86. #endregion
  87. #region Equals (Static)
  88. /// <summary>
  89. /// Equals, just trying to hide it.
  90. /// </summary>
  91. /// <param name="objA">Object A</param>
  92. /// <param name="objB">Object B</param>
  93. [EditorBrowsable(EditorBrowsableState.Never)]
  94. public new static bool Equals(object objA, object objB)
  95. {
  96. return object.Equals(objA, objB);
  97. }
  98. #endregion
  99. #region ReferenceEquals (Static)
  100. /// <summary>
  101. /// ReferenceEquals, just trying to hide it.
  102. /// </summary>
  103. /// <param name="objA">Object A</param>
  104. /// <param name="objB">Object B</param>
  105. [EditorBrowsable(EditorBrowsableState.Never)]
  106. public new static bool ReferenceEquals(object objA, object objB)
  107. {
  108. return object.ReferenceEquals(objA, objB);
  109. }
  110. #endregion
  111. #region ShowCurrentLogInTextEditor (Static)
  112. /// <summary>
  113. /// Show current log in text editor
  114. /// </summary>
  115. public static void ShowCurrentLogInTextEditor()
  116. {
  117. if (currentLogInstance != null &&
  118. File.Exists(currentLogInstance.Filename))
  119. {
  120. try
  121. {
  122. if (CheckIfLogWasCreatedFromNunitTestRunner() == false)
  123. {
  124. Process.Start(currentLogInstance.Filename);
  125. }
  126. }
  127. catch (Exception ex)
  128. {
  129. Debug.WriteLine(
  130. "Failed to open log file in text editor: " + ex.Message);
  131. }
  132. } // if
  133. }
  134. #endregion
  135. #region Test (Static)
  136. /// <summary>
  137. /// Verbose log information that is usually only used for unit tests.
  138. /// Can be disabled in release mode and should be used only for tests
  139. /// anyway. This is not sent to the DeltaEngine.net server and not even
  140. /// put into the log file, just to the console for the debugging
  141. /// console or the TestRunner or TestDriven.net output window!
  142. /// Please note that we will skip logging the same message over and over
  143. /// again because it is REALLY slow in VisualStudio (@see "ToConsole()").
  144. /// If you really want to log everything out and do not care about
  145. /// performance, just use Console.WriteLine yourself (e.g. when just
  146. /// quickly testing if a click event happens). With Log.Test you can even
  147. /// spam millions of messages per second, most of them will be skipped.
  148. /// </summary>
  149. /// <param name="message">Message</param>
  150. public static void Test(string message)
  151. {
  152. Test(message, false);
  153. }
  154. /// <summary>
  155. /// Test
  156. /// </summary>
  157. /// <param name="message">Message</param>
  158. /// <param name="skipRepeatingMessages">
  159. /// If 'true', messages which are repeating will be skipped (recommended
  160. /// for looping calls like in render oder updating) to avoid log spamming.
  161. /// </param>
  162. public static void Test(string message, bool skipRepeatingMessages)
  163. {
  164. // Format the message with a time stamp and pass it to the console only.
  165. ToConsole(FormatMessage(message), skipRepeatingMessages);
  166. }
  167. #endregion
  168. #region Info (Static)
  169. /// <summary>
  170. /// This method logs general information to the log file, to the console,
  171. /// if available to the screen, and finally to the DeltaEngine.net server.
  172. /// These kind of messages are usually for figuring stuff out that is
  173. /// working, but sometimes we need some additional details. On a normal
  174. /// release program run we should still have zero log messages!
  175. /// </summary>
  176. /// <param name="message">Message to show in the log and console</param>
  177. public static void Info(string message)
  178. {
  179. Instance.WriteInfo(message, true);
  180. }
  181. /// <summary>
  182. /// This method logs general information to the log file, to the console,
  183. /// if available to the screen, and finally to the DeltaEngine.net server.
  184. /// These kind of messages are usually for figuring stuff out that is
  185. /// working, but sometimes we need some additional details. On a normal
  186. /// release program run we should still have zero log messages!
  187. /// </summary>
  188. /// <param name="message">Message to show in the log and console</param>
  189. /// <param name="checkForDuplicates">Check if this message already was
  190. /// logged in the last 10 messages, then skip it to prevent log spam.
  191. /// This is on by default.
  192. /// </param>
  193. public static void Info(string message, bool checkForDuplicates)
  194. {
  195. Instance.WriteInfo(message, checkForDuplicates);
  196. }
  197. #endregion
  198. #region Warning (Static)
  199. /// <summary>
  200. /// Outputs a warning, which usually indicates something went really
  201. /// wrong. It could be a required file was missing, an exception occurred
  202. /// and was caught. Sometimes even a dynamic class initialization failed
  203. /// and we provided some fallback, but we want to warn about the initial
  204. /// failure. Non recoverable errors should throw an exception and will end
  205. /// up in Application.HandleUnhandledExceptions (which will still use this
  206. /// method to put the error to the log, but then will abort the
  207. /// application). A programmer or user can sometimes ignore warnings and
  208. /// still continue working without the application crashing, but it might
  209. /// not behave correctly. Note: Warnings always have a stack trace!
  210. /// </summary>
  211. /// <param name="message">Message</param>
  212. public static void Warning(string message)
  213. {
  214. // Note: Same code as in the other Warning overload. This is done to
  215. // prevent bloating the callstack more because we show it for warnings!
  216. // Helpers to display warnings in Scene.Draw!
  217. if (logTimer != null)
  218. {
  219. LastWarningTime =
  220. //too precise/slow: (float)logTimer.ElapsedMilliseconds / 1000.0f;
  221. //(float)logTimer.CachedMilliseconds / 1000.0f;
  222. logTimer.ElapsedMilliseconds;
  223. }
  224. if (String.IsNullOrEmpty(message) == false)
  225. {
  226. LastWarningMessage =
  227. // Only take the first line of the warning
  228. message.SplitMultiLineText()[0];
  229. }
  230. // The default is to display each warning with a stack trace.
  231. Instance.WriteWarning(message, true);
  232. }
  233. /// <summary>
  234. /// Outputs a warning, which usually indicates something went really
  235. /// wrong. It could be a required file was missing, an exception occurred
  236. /// and was caught. Sometimes even a dynamic class initialization failed
  237. /// and we provided some fallback, but we want to warn about the initial
  238. /// failure. Non recoverable errors should throw an exception and will end
  239. /// up in Application.HandleUnhandledExceptions (which will still use this
  240. /// method to put the error to the log, but then will abort the
  241. /// application). A programmer or user can sometimes ignore warnings and
  242. /// still continue working without the application crashing, but it might
  243. /// not behave correctly. Note: Warnings always have a stack trace!
  244. /// </summary>
  245. /// <param name="message">Message</param>
  246. /// <param name="showStackTrace">Show Stack Trace</param>
  247. public static void Warning(string message, bool showStackTrace)
  248. {
  249. // Helpers to display warnings in Scene.Draw!
  250. if (logTimer != null)
  251. {
  252. LastWarningTime =
  253. //too precise/slow: (float)logTimer.ElapsedMilliseconds / 1000.0f;
  254. //(float)logTimer.CachedMilliseconds / 1000.0f;
  255. logTimer.ElapsedMilliseconds;
  256. }
  257. if (String.IsNullOrEmpty(message) == false)
  258. {
  259. LastWarningMessage =
  260. // Only take the first line of the warning
  261. message.SplitMultiLineText()[0];
  262. }
  263. // And normally process the warning.
  264. Instance.WriteWarning(message, showStackTrace);
  265. }
  266. #endregion
  267. #region InvalidVersionWarning (Static)
  268. /// <summary>
  269. /// Logs a warning because of an invalid data version.
  270. /// </summary>
  271. /// <param name="className">Class name</param>
  272. /// <param name="dataVersion">Data version</param>
  273. /// <param name="maxSupportedVersion">Maximum supported version</param>
  274. public static void InvalidVersionWarning(string className,
  275. int dataVersion, int maxSupportedVersion)
  276. {
  277. Warning(
  278. "The version '" + dataVersion + "' of the '" + className +
  279. "' data is currently not supported, the max. possible version is '" +
  280. maxSupportedVersion + "'. Please make sure that the data is correct.");
  281. }
  282. #endregion
  283. #region Close (Static)
  284. /// <summary>
  285. /// Close log, will disconnect from the Log server and even open up the
  286. /// log file in editor in debug mode (if a log was generated at all).
  287. /// </summary>
  288. public static void Close()
  289. {
  290. // Write out the last console message if we had to discard it earlier
  291. // in ToConsole because of Console.WriteLine spam, which is very slow!
  292. if (String.IsNullOrEmpty(lastDiscardedConsoleMessage) == false)
  293. {
  294. Console.WriteLine(lastDiscardedConsoleMessage);
  295. lastDiscardedConsoleMessage = "";
  296. }
  297. // Open log in editor at shutdown, but only in debug mode :) This should
  298. // force us NOT to have any log output (then this won't happen).
  299. // First handle Engine.txt we want to show it!
  300. if (remToLaunchEngineLogAtEndOfProgram != "" &&
  301. File.Exists(remToLaunchEngineLogAtEndOfProgram))
  302. {
  303. try
  304. {
  305. if (CheckIfLogWasCreatedFromNunitTestRunner() == false)
  306. {
  307. Process.Start(remToLaunchEngineLogAtEndOfProgram);
  308. }
  309. }
  310. catch (Exception ex)
  311. {
  312. Console.WriteLine(
  313. "Failed to open engine log file in text editor: " + ex.Message);
  314. }
  315. remToLaunchEngineLogAtEndOfProgram = "";
  316. } // if
  317. // Note: There could be an Setting to disable this launching log file
  318. // feature, but for now we want to show it always in debug mode to the
  319. // programmer (we do not want any logging at all in a functional app)!
  320. if (currentLogInstance != null &&
  321. FileHelper.Exists(currentLogInstance.Filename))
  322. {
  323. // Always close the log file first (if we can and it is still open)!
  324. if (currentLogInstance.logFile != null &&
  325. currentLogInstance.logFile.BaseStream.CanWrite)
  326. {
  327. try
  328. {
  329. currentLogInstance.logFile.Close();
  330. }
  331. catch (ObjectDisposedException)
  332. {
  333. // Ignore this, it can happen when this is called via the
  334. // destructor, which happens if we don't call Close explicitly.
  335. }
  336. } // if
  337. currentLogInstance.logFile = null;
  338. // Show current log in text editor
  339. ShowCurrentLogInTextEditor();
  340. // Make sure the log instance is now gone!
  341. currentLogInstance = null;
  342. } // if
  343. }
  344. #endregion
  345. #region LogHappened (Static)
  346. /// <summary>
  347. /// You can attach delegates to LogHappened to get notified whenever a
  348. /// log message is happening (usually should only happen for testing or
  349. /// when something goes wrong and a log warning is put out). Used
  350. /// in the Delta.Engine.Application class to add Log Server features.
  351. /// </summary>
  352. public static LogDelegate LogHappened;
  353. #endregion
  354. #region LastWarningMessage (Static)
  355. /// <summary>
  356. /// Last warning message we want to display in Scene.Draw, usually not
  357. /// used, only if something bad happened. Set here, used there.
  358. /// </summary>
  359. public static string LastWarningMessage = "";
  360. #endregion
  361. #region LastWarningTime (Static)
  362. /// <summary>
  363. /// Helpers to display warnings in Scene.Draw, will be reduced there.
  364. /// Set here, used there (thus public access is needed).
  365. /// </summary>
  366. public static long LastWarningTime = -10;
  367. #endregion
  368. #region LogName (Static)
  369. /// <summary>
  370. /// Current log name, initially "Engine" until Application.Start is
  371. /// called, then it will be the current game, unit test or tool name.
  372. /// </summary>
  373. public static string LogName
  374. {
  375. get
  376. {
  377. return logName;
  378. }
  379. internal set
  380. {
  381. // Check if the new value is valid
  382. if (String.IsNullOrEmpty(value))
  383. {
  384. throw new ArgumentNullException(
  385. "Invalid ProgramName for the log filename, please set a valid " +
  386. "program name!");
  387. }
  388. // No change? Then just quit here (no need to do all the checking)
  389. if (logName == value)
  390. {
  391. return;
  392. }
  393. // If we have already created a log file, we need to close it and
  394. // create a new log file. This happens in case we had initialization
  395. // log warnings (in the engine usually because loading content,
  396. // rendering and game logic is all delayed until the app has started).
  397. if (currentLogInstance != null &&
  398. currentLogInstance.logFile != null)
  399. {
  400. // Close the old log file.
  401. if (currentLogInstance.logFile.BaseStream != null)
  402. {
  403. currentLogInstance.logFile.Close();
  404. }
  405. currentLogInstance.logFile = null;
  406. // In debug mode we launch the log file that has been created
  407. // because there most likely are warnings or information the
  408. // programmer wants to know about (we have a zero logging policy)
  409. remToLaunchEngineLogAtEndOfProgram = currentLogInstance.Filename;
  410. }
  411. // Set the new programName, if a log is needed, it will be created!
  412. logName = value;
  413. // Make sure the name does not contain any invalid characters
  414. StringHelper.RemoveAnyForbiddenLettersForFilename(ref logName);
  415. // Because our programName has changed, we need to check if we
  416. // should archive the programName.log file!
  417. if (currentLogInstance != null)
  418. {
  419. currentLogInstance.ArchiveLogFile();
  420. }
  421. }
  422. }
  423. #endregion
  424. #region ExtraHardwareInfo (Static)
  425. /// <summary>
  426. /// Platform modules have the ability to add extra hardware information
  427. /// we use the DeviceHardware class to show more information about the
  428. /// </summary>
  429. public static string ExtraHardwareInfo = "";
  430. #endregion
  431. #region Filename (Public)
  432. /// <summary>
  433. /// Returns the complete file name of the current log file.
  434. /// </summary>
  435. public string Filename
  436. {
  437. get
  438. {
  439. return Path.Combine(
  440. Path.Combine(DirectoryHelper.GetBaseDirectory(), Directory),
  441. LogName + "." + FileExtension);
  442. }
  443. }
  444. #endregion
  445. #region ArchivedLogFilename (Public)
  446. /// <summary>
  447. /// Archived log filename
  448. /// </summary>
  449. public string ArchivedLogFilename
  450. {
  451. get
  452. {
  453. return Path.Combine(
  454. Path.Combine(DirectoryHelper.GetBaseDirectory(), Directory),
  455. LogName + "-Archive." + FileExtension);
  456. }
  457. }
  458. #endregion
  459. #region Internal
  460. #region Directory (Internal)
  461. /// <summary>
  462. /// By default no log directory is used, all logs end up in the application
  463. /// directory (named by the program or unit test that was started).
  464. /// Note: This is just a directory, no filename should be specified here.
  465. /// Also note that this must be set before the actual logging happens,
  466. /// so in case you first have some log warnings and then load the settings
  467. /// the initial log directory is not set.
  468. /// </summary>
  469. internal static string Directory = "";
  470. #endregion
  471. #region LogHeader (Internal)
  472. /// <summary>
  473. /// The header information of our log.
  474. /// </summary>
  475. internal static string LogHeader
  476. {
  477. get
  478. {
  479. Version programVersion = new Version(1, 0);
  480. try
  481. {
  482. var programAssembly = Assembly.GetEntryAssembly();
  483. // If getting the programAssembly is not possible (e.g. in the
  484. // SampleBrowser it will return null), then use the current one.
  485. if (programAssembly == null)
  486. {
  487. programAssembly = Assembly.GetCallingAssembly();
  488. }
  489. programVersion = programAssembly.GetName().Version;
  490. }
  491. // Ignore if this does not work (e.g. unit test)
  492. catch
  493. {
  494. }
  495. return
  496. "Program: " + LogName + " v" + programVersion +
  497. Environment.NewLine +
  498. "Modules: " + loadedModules +
  499. Environment.NewLine +
  500. "Start Time: " + applicationStartTime.GetIsoDateTime() +
  501. Environment.NewLine +
  502. "Platform: " + GetPlatformInfo() + ExtraHardwareInfo +
  503. Environment.NewLine +
  504. "User: " + Environment.UserName +
  505. " (" + Environment.MachineName + ")" +
  506. Environment.NewLine;
  507. }
  508. }
  509. #endregion
  510. #region loadedModules (Internal)
  511. /// <summary>
  512. /// This is also set in DynamicBase and will obviously only report
  513. /// the loaded modules if they have been set (Graphics, Sound, Video).
  514. /// </summary>
  515. internal static string loadedModules = "None";
  516. #endregion
  517. #region logTimer (Internal)
  518. /// <summary>
  519. /// Use timer to have more accurate timing (uses PerformanceCounters
  520. /// internally and can return accurate millisecond values for many million
  521. /// years due the use of long integer values). Usually setup in the Time
  522. /// class, but if that is not used or was not called before logging
  523. /// happens we will initialize this on our own with a simple
  524. /// StopwatchTimeSource and update it ourself.
  525. /// </summary>
  526. internal static BaseTimeSource logTimer;
  527. #endregion
  528. #region allowDuplicateLogChecking (Internal)
  529. /// <summary>
  530. /// By default Allow Duplicate Log Checking. This speeds up console writing
  531. /// by a lot (skips messages if too much is going on, making logging
  532. /// 10-100x faster). It also checks for duplicate messages written into
  533. /// the log file (keeping the log file much smaller).
  534. /// <para />
  535. /// But it can be useful if you really want every single log message in
  536. /// the console and log file including duplicates, then disable this
  537. /// feature (via Application Settings or by setting this to false).
  538. /// </summary>
  539. internal static bool allowDuplicateLogChecking = true;
  540. #endregion
  541. #endregion
  542. #region Private
  543. #region logName (Private)
  544. /// <summary>
  545. /// Current log name, will be "Engine" until Application.Start is
  546. /// called, then it will be the current game, unit test or tool name.
  547. /// </summary>
  548. private static string logName = DefaultLogName;
  549. #endregion
  550. #region remToLaunchEngineLogAtEndOfProgram (Private)
  551. /// <summary>
  552. /// Extra helper to show even the Engine.txt file when closing the
  553. /// program in case there were Engine warnings we need to know about!
  554. /// </summary>
  555. private static string remToLaunchEngineLogAtEndOfProgram = "";
  556. #endregion
  557. #region isLogFileCreatable (Private)
  558. /// <summary>
  559. /// Can the log file be created, helps us to remember if we have already
  560. /// tried to create a log file and was it successful.
  561. /// </summary>
  562. private bool isLogFileCreatable;
  563. #endregion
  564. #region remOurSetupLogTimer (Private)
  565. /// <summary>
  566. /// Helper to remember which timer we have setup (if we have done so at
  567. /// all). If this is null or not equal to logTimer than the engine has
  568. /// changed this and is now started. It is save to use the retrying
  569. /// connection feature of the Client class if so because Close is
  570. /// called by force when the application quits (otherwise not).
  571. /// </summary>
  572. private static BaseTimeSource remOurSetupLogTimer;
  573. #endregion
  574. #region logFile (Private)
  575. /// <summary>
  576. /// The handle to our (local) log file.
  577. /// </summary>
  578. private StreamWriter logFile;
  579. #endregion
  580. #region currentLogInstance (Private)
  581. /// <summary>
  582. /// Current log instance.
  583. /// </summary>
  584. private static Log currentLogInstance;
  585. #endregion
  586. /// <summary>
  587. /// Remember if the log creation in Instance was done from a test runner.
  588. /// </summary>
  589. private static bool rememberLogWasCreatedFromNunitTestRunner = false;
  590. /// <summary>
  591. /// Helper method to find out if the log instance was created by the NUnit
  592. /// test runner or by ReSharpers Unit Test Sessions. This is important
  593. /// because if the log class is being disposed by a finalizer (e.g. from
  594. /// WPF) and we need to show the log file in a text editor it will crash
  595. /// with an System.Runtime.InteropServices.InvalidComObjectException: COM
  596. /// object that has been separated from its underlying RCW cannot be used.
  597. /// We can prevent this from happening by setting this to true in the
  598. /// Instance property. Since we see the output in the test runner anyway
  599. /// opening the text editor is not important anyway.
  600. /// </summary>
  601. private static bool CheckIfLogWasCreatedFromNunitTestRunner()
  602. {
  603. if (rememberLogWasCreatedFromNunitTestRunner)
  604. {
  605. return true;
  606. }
  607. // Check if we are coming from NUnit or ReSharper test runner. Note: If
  608. // we only get a Finalize stack frame (4 calls long) this won't work!
  609. foreach (StackFrame frame in new StackTrace().GetFrames())
  610. {
  611. Type frameClass = frame.GetMethod().DeclaringType;
  612. if (frameClass.Name.StartsWith("NUnit") ||
  613. frameClass.Name.StartsWith("ReSharper"))
  614. {
  615. rememberLogWasCreatedFromNunitTestRunner = true;
  616. return true;
  617. }
  618. }
  619. // Otherwise nothing was found, return false
  620. return false;
  621. }
  622. #region Instance (Private)
  623. /// <summary>
  624. /// Current log instance we are using, if there is no instance, we will
  625. /// create one with the current program name (defaults to Engine.txt).
  626. /// </summary>
  627. private static Log Instance
  628. {
  629. get
  630. {
  631. // Got no log instance yet? Then create it ourselves.
  632. if (currentLogInstance == null)
  633. {
  634. currentLogInstance = new Log();
  635. CheckIfLogWasCreatedFromNunitTestRunner();
  636. }
  637. // But usually it is set in the constructor anyway!
  638. return currentLogInstance;
  639. }
  640. }
  641. #endregion
  642. #region lastDiscardedConsoleMessage (Private)
  643. /// <summary>
  644. /// Remember the last discarded console message. Show it when the app
  645. /// quits. It often contains interesting information about performance.
  646. /// </summary>
  647. private static string lastDiscardedConsoleMessage = "";
  648. #endregion
  649. #endregion
  650. #region Constructors
  651. /// <summary>
  652. /// Create log
  653. /// </summary>
  654. public Log()
  655. {
  656. // Start our own time counting if it has not been setup yet, usually
  657. // the Time module from the Delta project should have set this up!
  658. if (logTimer == null)
  659. {
  660. remOurSetupLogTimer = logTimer = new StopwatchTimeSource();
  661. }
  662. // We assume always that we can create a log file. For some platforms
  663. // application directory, so do not create a log file there (just use
  664. // LogService).
  665. isLogFileCreatable = true;
  666. // From now on static methods can use this log instance :)
  667. currentLogInstance = this;
  668. // Archive always the last log file (if exists) to have a completely
  669. // fresh new log for every new session
  670. ArchiveLogFile();
  671. }
  672. #endregion
  673. #region Destructor
  674. /// <summary>
  675. /// ~Log destructor, just calls Dispose, which calls Close.
  676. /// Note: Not often helpful because this is only called when everything
  677. /// else was killed and this only cleans up after all threads and objects
  678. /// are gone anyway.
  679. /// </summary>
  680. ~Log()
  681. {
  682. Dispose();
  683. }
  684. #endregion
  685. #region IDisposable Members
  686. /// <summary>
  687. /// Dispose, just calls Close to make sure we dispose stuff if the
  688. /// application is quitting (either forcefully or normally via
  689. /// Application.Quit).
  690. /// </summary>
  691. public void Dispose()
  692. {
  693. Close();
  694. }
  695. #endregion
  696. #region ArchiveLogFile (Public)
  697. /// <summary>
  698. /// Archives a log file to an existing log-file-archive or creates a new
  699. /// log-file-archive, if the archive-file doesn't exist yet. However in any
  700. /// case the current log file will be deleted after processing to the
  701. /// archive. This is used for in the LogService too.
  702. /// </summary>
  703. public void ArchiveLogFile()
  704. {
  705. // Log file that should be archived is Filename (current log file)
  706. // Filename of the (new/existing) log-archive: ArchivedLogFilename
  707. // We only need to archive an existing log file
  708. if (FileHelper.Exists(Filename) == false)
  709. {
  710. return;
  711. }
  712. // Grab all the logged text from last session log for adding that to the
  713. // log archive file
  714. string appendLogText = FileHelper.GetText(Filename);
  715. // If the archive file already exists
  716. if (FileHelper.Exists(ArchivedLogFilename))
  717. {
  718. // Add some empty lines
  719. appendLogText = Environment.NewLine +
  720. Environment.NewLine +
  721. // Before the real text to separate this in log sessions
  722. appendLogText;
  723. }
  724. try
  725. {
  726. // Finally we write this to the archive file. This file will be created
  727. // automatically if it does not exist yet (only for the first time)
  728. FileHelper.AppendTextToFile(ArchivedLogFilename, appendLogText,
  729. // If the existing data is more than 20 MB already, remove data from
  730. // the beginning and then append the appendLogText.
  731. MaxArchiveLogFileSize);
  732. }
  733. catch
  734. {
  735. // We should not use Info or Warning here, the log file has not
  736. // been deleted yet, so only warn in the console if appending failed.
  737. Console.WriteLine("Warning: Appending to the log archive failed: " +
  738. ArchivedLogFilename);
  739. }
  740. // And delete the original file
  741. FileHelper.SafeDelete(Filename);
  742. }
  743. #endregion
  744. #region Methods (Private)
  745. #region GetPlatformInfo
  746. /// <summary>
  747. /// Get platform info helper method for LogHeader to output some useful
  748. /// information about the currently running platform (especially nice for
  749. /// the log server, which shows this info in the logs too).
  750. /// </summary>
  751. private static string GetPlatformInfo()
  752. {
  753. string platform = "Windows";
  754. // Add some extra information about the environment (might not be
  755. // complete on all platforms, but on Windows this shows good stuff)
  756. platform +=
  757. ", " + Environment.ProcessorCount + " CPU Cores, " +
  758. // This functionality is only available on Windows!
  759. (Environment.Is64BitProcess
  760. ? "64 bit"
  761. : Environment.Is64BitOperatingSystem
  762. ? "32 bit (on 64 bit OS)"
  763. : "32 bit") + ", " +
  764. // This shows lots of detailed information about the OS version,
  765. // e.g. Windows NT 6.1.7600.0 means Windows 7, 7600 is the SP!
  766. Environment.OSVersion.VersionString.
  767. Replace("Microsoft ", "").
  768. Replace("Windows NT 6.1.", "Windows 7 v").
  769. Replace("Windows NT 6.0.", "Windows Vista v");
  770. return platform;
  771. }
  772. #endregion
  773. #region CreateLogFile
  774. /// <summary>
  775. /// Create log file
  776. /// </summary>
  777. /// <param name="logFilename">Log filename</param>
  778. private bool CreateLogFile(string logFilename)
  779. {
  780. #region Validation
  781. if (String.IsNullOrEmpty(logFilename))
  782. {
  783. // If the filename is not valid, this is a fatal exception error!
  784. throw new ArgumentException("Sorry, can't create a log file without " +
  785. "a valid filename.", "logFilename");
  786. }
  787. if (isLogFileCreatable == false)
  788. {
  789. // Build error message and write it into the console at least
  790. string errorMessage = FormatMessage(
  791. "Sorry, can't create a log file, because an earlier try failed " +
  792. "already. Maybe you haven't the right to create files here?");
  793. Console.WriteLine(errorMessage);
  794. // If we can't create a log file, then log it to the log server
  795. if (LogHappened != null)
  796. {
  797. LogHappened(errorMessage);
  798. }
  799. return false;
  800. }
  801. #endregion
  802. try
  803. {
  804. // We always create a new log file (the old one will be archived
  805. // automatically at the program start)
  806. FileStream logFileStream = FileHelper.Open(logFilename,
  807. FileMode.OpenOrCreate, FileAccess.Write, FileShare.ReadWrite);
  808. // for the log text we use here the 8-bit unicode
  809. logFile = new StreamWriter(logFileStream, TextFormat);
  810. // Activate the "Auto Flush" (to be always "up-to-date" for reading)
  811. logFile.AutoFlush = true;
  812. // and start the log file with the header
  813. logFile.WriteLine(LogHeader);
  814. }
  815. catch (Exception ex)
  816. {
  817. isLogFileCreatable = false;
  818. logFile = null;
  819. // Build error message and write it into the console at least
  820. string errorMessage = FormatMessage(
  821. "Sorry, can't create a log file because: " + ex);
  822. Console.WriteLine(errorMessage);
  823. // And finally send it to the log server (if connected and possible)!
  824. if (LogHappened != null)
  825. {
  826. LogHappened(errorMessage);
  827. }
  828. }
  829. return logFile != null;
  830. }
  831. #endregion
  832. #region CheckDuplicateMessage
  833. /// <summary>
  834. /// Returns true if we should skip this message in case we are logging it
  835. /// over and over again (prevent log spam). Make sure to call this BEFORE
  836. /// adding the time stamp, which most likely will make every message
  837. /// unique and prevents us from detecting log spam.
  838. /// </summary>
  839. /// <param name="message">Message</param>
  840. private static bool CheckDuplicateMessage(string message)
  841. {
  842. if (allowDuplicateLogChecking == false)
  843. {
  844. return false;
  845. }
  846. // We need to keep this thread safe!
  847. lock (lastLoggedMessages)
  848. {
  849. // Was this logged before? Note: This will need some performance, more
  850. // if we need to check many messages, so keep lastLoggedMessages low.
  851. if (lastLoggedMessages.Contains(message))
  852. {
  853. // Then abort, do not log it again, it costs too much performance!
  854. return true;
  855. }
  856. // Else add it to our queue and check for it next time (and log it).
  857. lastLoggedMessages.Enqueue(message);
  858. }
  859. return false;
  860. }
  861. #endregion
  862. #region ToFile
  863. /// <summary>
  864. /// To file
  865. /// </summary>
  866. /// <param name="message">Message</param>
  867. private void ToFile(string message)
  868. {
  869. // If we don't have a log file created yet
  870. if ((logFile == null ||
  871. logFile.BaseStream == null) &&
  872. isLogFileCreatable)
  873. {
  874. // Then just try to do it now
  875. CreateLogFile(Filename);
  876. }
  877. // Obviously only log if we have a logFile
  878. if (logFile != null)
  879. {
  880. // Keep this thread safe!
  881. lock (logFile)
  882. {
  883. // First just write to the log file
  884. logFile.WriteLine(message);
  885. // Is the log file still above 10 MB now?
  886. if (logFile.BaseStream.Length > MaxLogFileSize)
  887. {
  888. try
  889. {
  890. // Remove the last 5 MB and start from there again!
  891. // For that just close the file, copy half the content to a new
  892. // file and then open that file again to continue logging!
  893. logFile.Close();
  894. string[] logLines = FileHelper.GetLines(Filename);
  895. // Create new log file with half the size
  896. FileStream logFileStream = FileHelper.Open(Filename,
  897. FileMode.Truncate, FileAccess.Write, FileShare.ReadWrite);
  898. // for the log text we use here the 8-bit unicode
  899. logFile = new StreamWriter(logFileStream, TextFormat);
  900. // Activate AutoFlush to be always up-to-date for reading
  901. logFile.AutoFlush = true;
  902. // and dump out half of the previous log lines!
  903. for (int line = 0; line < logLines.Length / 2; line++)
  904. {
  905. logFile.WriteLine(logLines[line]);
  906. }
  907. // Add a note that the file was too big and 5 MB of log data
  908. // was removed!
  909. logFile.WriteLine("");
  910. logFile.WriteLine("****************************");
  911. logFile.WriteLine("Log file was exceeding " +
  912. StringHelper.WriteKbMbGbNumber(MaxLogFileSize) +
  913. ", the " +
  914. "last " +
  915. StringHelper.WriteKbMbGbNumber(MaxLogFileSize / 2) +
  916. " were removed and logging will continue here!");
  917. logFile.WriteLine("****************************");
  918. logFile.WriteLine("");
  919. // And log again what we last tried to log
  920. logFile.WriteLine(message);
  921. }
  922. catch (Exception ex)
  923. {
  924. // Note: We cannot display a dialog here, no assembly, we can
  925. // only spam into the log, which won't be open anyway for that
  926. // much logging (its too slow in Visual Studio).
  927. ToConsole("Failed to resize log file, it won't log anymore: " +
  928. ex, true);
  929. isLogFileCreatable = false;
  930. logFile = null;
  931. }
  932. }
  933. }
  934. }
  935. }
  936. #endregion
  937. #region ToConsole
  938. /// <summary>
  939. /// Print to console, which is horribly slow in Visual Studio, but still
  940. /// very useful for debugging. Instead of logging everything to the
  941. /// console we gonna limit the amount of console writing. Usually we
  942. /// should have less than 10 message lines per second (we don't want to
  943. /// throw any warnings, informational logs or even test messages in
  944. /// a normal application run, it should have zero logging!)
  945. /// For additional details about bad performance of Debug.WriteLine see:
  946. /// http://rdn-consulting.com/blog/2008/05/28/net-consolewriteline-performance-issues/
  947. /// Also see the below unit test, which is horribly slow: 6ms for 30 chars
  948. /// </summary>
  949. /// <param name="message">Message</param>
  950. /// <param name="checkForDuplicates">Check for Duplicates</param>
  951. private static void ToConsole(string message, bool checkForDuplicates)
  952. {
  953. // First check if we have already logged more than 10 messages in the
  954. // last second, skip any new console writes until a second has passed.
  955. if (allowDuplicateLogChecking &&
  956. checkForDuplicates &&
  957. logTimer != null)
  958. {
  959. long thisTime = logTimer.ElapsedMilliseconds;
  960. if (lastConsoleWriteTimes.Count == MaxConsoleWritesPerSecond)
  961. {
  962. long longestTime = lastConsoleWriteTimes.Peek();
  963. // Abort if less than 1000ms have passed since 10 console writes ago
  964. if (thisTime - longestTime < 1000)
  965. {
  966. // Remember this message in case the application quits now, it
  967. // would be really useful to show the last message, it often
  968. // contains interesting information about performance, etc.
  969. lastDiscardedConsoleMessage = message;
  970. return;
  971. }
  972. }
  973. // Add current logging time at the end of the queue
  974. lastConsoleWriteTimes.Enqueue(thisTime);
  975. // And kill the lastDiscardedLogMessage, we are logging now!
  976. lastDiscardedConsoleMessage = "";
  977. }
  978. // Just pass the message directly to the IDE console. This is still slow
  979. // as hell, especially if debugging with the debug window open.
  980. // Might be a little faster with Debug.WriteLine, but we won't see it
  981. // in release mode. Also useful for whatever is listing at the console.
  982. Console.WriteLine(message);
  983. }
  984. #endregion
  985. #region FormatMessage
  986. /// <summary>
  987. /// Format message for use with the log methods (log server, file, console)
  988. /// </summary>
  989. /// <param name="rawMessage">Raw message</param>
  990. private static string FormatMessage(string rawMessage)
  991. {
  992. // Make sure the instance has been created, otherwise we have no timer!
  993. if (Instance != null &&
  994. logTimer == null)
  995. {
  996. return rawMessage;
  997. }
  998. // Note: In threading situations this can sometimes crash ..
  999. try
  1000. {
  1001. return logTimer.ToTimeString(' ', rawMessage);
  1002. }
  1003. catch
  1004. {
  1005. return rawMessage;
  1006. }
  1007. }
  1008. #endregion
  1009. #region WriteInfo
  1010. /// <summary>
  1011. /// Write information string to the log, the console and to the
  1012. /// DeltaEngin.net server. For details see the static Info method.
  1013. /// </summary>
  1014. /// <param name="message">Message to show in the log and console</param>
  1015. /// <param name="checkForDuplicates">Check if this message already was
  1016. /// logged in the last 10 messages, then skip it to prevent log spam.
  1017. /// This is on by default.
  1018. /// </param>
  1019. private void WriteInfo(string message, bool checkForDuplicates)
  1020. {
  1021. // Skip message if we just logging it over and over again (log spam)
  1022. if (message == null ||
  1023. (checkForDuplicates &&
  1024. CheckDuplicateMessage(message)))
  1025. {
  1026. return;
  1027. }
  1028. // Format the message with a time stamp and whatever is needed
  1029. string formattedMessage = FormatMessage(message);
  1030. // Log the formatted message to the console first
  1031. ToConsole(formattedMessage, checkForDuplicates);
  1032. try
  1033. {
  1034. // Also send the message to all attached handlers like the log server
  1035. if (LogHappened != null)
  1036. {
  1037. LogHappened(formattedMessage);
  1038. }
  1039. // And then finally to the current log file
  1040. ToFile(formattedMessage);
  1041. }
  1042. catch (Exception ex)
  1043. {
  1044. // Note: The formattedMessage text was just put into the console!
  1045. Console.WriteLine("Failed to log this info to file: " + ex);
  1046. }
  1047. }
  1048. #endregion
  1049. #region WriteWarning
  1050. /// <summary>
  1051. /// Warning, thought for logging "light errors" which can be handled itself
  1052. /// by the application. For details see the static Warning method!
  1053. /// </summary>
  1054. /// <param name="message">Warning to show in the log and console</param>
  1055. /// <param name="showStackTrace">Show Stack Trace</param>
  1056. private void WriteWarning(string message, bool showStackTrace)
  1057. {
  1058. string[] messageLines = message.SplitMultiLineText();
  1059. message = "";
  1060. bool gotAlreadyStackTrace = false;
  1061. foreach (string line in messageLines)
  1062. {
  1063. // .NET exception stack traces are always formated this way
  1064. if (line.Trim().StartsWith("at ") ||
  1065. line.Trim().StartsWith("bei ") ||
  1066. line.Contains(" Delta."))
  1067. {
  1068. // Fix exception trace by putting file:line at front (to allow
  1069. // clicking on it in VS).
  1070. // First ignore the lines starting with TestRunner or VS process
  1071. // starting stuff (see below):
  1072. if (line.Contains(new[]
  1073. {
  1074. "System.RuntimeMethodHandle", "System.Reflection",
  1075. "TestDriven", "System.Threading", "System.AppDomain",
  1076. "System.Activator", "System.Runtime", "System.Windows.",
  1077. "Delta.Utilities.Testing", "Microsoft.VisualStudio.HostingProcess",
  1078. // Also exclude NUnit, xUnit and ReSharper stack traces
  1079. "NUnit.Core.", "xUnit.", "JetBrains.ReSharper.",
  1080. }))
  1081. {
  1082. continue;
  1083. }
  1084. // Okay, now split up the 5 parts: at method in file line
  1085. string result = line.Trim();
  1086. string trimmedLine = StringHelper.RemoveFirstWord(result);
  1087. string[] methodAndRest = trimmedLine.Split(" in ");
  1088. if (methodAndRest.Length == 2)
  1089. {
  1090. string[] fileAndLine = methodAndRest[1].Split(":line ");
  1091. if (fileAndLine.Length == 2)
  1092. {
  1093. result = fileAndLine[0] + "(" + fileAndLine[1] + ",1): at " +
  1094. methodAndRest[0];
  1095. }
  1096. }
  1097. // Output result (reformatted stack trace line)
  1098. message +=
  1099. (message.Length > 0
  1100. ? "\n"
  1101. : "") + "\t" + result;
  1102. gotAlreadyStackTrace = true;
  1103. }
  1104. else
  1105. {
  1106. message +=
  1107. (message.Length > 0
  1108. ? "\n"
  1109. : "") + line;
  1110. }
  1111. }
  1112. if (gotAlreadyStackTrace == false &&
  1113. showStackTrace)
  1114. {
  1115. // Always show a callstack for warnings to help figure out who called
  1116. // this method and it might (not always of course) help :) But remove
  1117. // the first callstack line (just Log.Warning, we know that we are
  1118. // here). Also remove the last 12 lines for generic
  1119. // TestDriven.TestRunner or Launcher stuff:
  1120. // System.RuntimeMethodHandle._InvokeMethodFast(...)
  1121. // System.RuntimeMethodHandle.InvokeMethodFast(...)
  1122. // System.Reflection.RuntimeMethodInfo.Invoke(...)
  1123. // System.Reflection.RuntimeMethodInfo.Invoke(...)
  1124. // System.Reflection.MethodBase.Invoke(...)
  1125. // TestDriven.AdHoc.TestRunner.AdHocTestRunner.runAdHoc(...)
  1126. // TestDriven.AdHoc.TestRunner.AdHocTestRunner.Run(...)
  1127. // TestDriven.TestRunner.AdaptorTestRunner.Run(...)
  1128. // TestDriven.TestRunner.ThreadTestRunner.Runner.Run()
  1129. // System.Threading.ThreadHelper.ThreadStart_Context(...)
  1130. // System.Threading.ExecutionContext.Run(...)
  1131. // System.Threading.ThreadHelper.ThreadStart()
  1132. // true for file and line info!
  1133. StackTrace trace = new StackTrace(true);
  1134. // This code is from Tools\TestRunner\UnitTestManager.cs:479
  1135. StackFrame[] frames = trace.GetFrames();
  1136. int frameNumber = 0;
  1137. string callstackLines = "";
  1138. foreach (var frame in frames)
  1139. {
  1140. frameNumber++;
  1141. // Ignore the first two lines: this method and its caller
  1142. // Log.Warning, both are not very exciting and always the same.
  1143. if (frameNumber <= 2)
  1144. {
  1145. continue;
  1146. }
  1147. var method = frame.GetMethod();
  1148. // Also exclude TestRunner code and boring invoking stuff
  1149. if (method.DeclaringType.FullName.Contains(new[]
  1150. {
  1151. "System.RuntimeMethodHandle", "System.Reflection",
  1152. "TestDriven", "System.Threading", "System.AppDomain",
  1153. "System.Activator", "System.Runtime", "Delta.Utilities.Testing",
  1154. "Microsoft.VisualStudio.HostingProcess", "System.Windows.",
  1155. "MS.Win32.", "MS.Internal.",
  1156. // Also exclude NUnit, xUnit and ReSharper stack traces
  1157. "NUnit.Core.", "xUnit.", "JetBrains.ReSharper.",
  1158. }))
  1159. {
  1160. continue;
  1161. }
  1162. // Try to get parameters with detailed value info
  1163. string parametersText = "";
  1164. var parameters = method.GetParameters();
  1165. foreach (var parameter in parameters)
  1166. {
  1167. parametersText +=
  1168. (parametersText.Length > 0
  1169. ? ", "
  1170. : "") +
  1171. parameter.ParameterType + " " + parameter.Name;
  1172. }
  1173. // Try to get filename with line and column information
  1174. string filenameAndLine =
  1175. frame.GetFileName() + "(" +
  1176. frame.GetFileLineNumber() + "," +
  1177. frame.GetFileColumnNumber() + "): ";
  1178. // But cut it if we do not have it (e.g. system classes)
  1179. if (filenameAndLine == "(0,0): ")
  1180. {
  1181. filenameAndLine = "";
  1182. }
  1183. callstackLines +=
  1184. "\t" +
  1185. // This is not working, projectPath is relative to the assembly
  1186. // we are investigating, but not the project VS is running
  1187. // sometimes
  1188. //FileHelper.GetRelativeContentFilePath(
  1189. //frame.GetFileName(), projectPath) + "(" +
  1190. filenameAndLine +
  1191. // Class and name should be useful enough :)
  1192. "at " + method.DeclaringType + "." + method.Name +
  1193. "(" + parametersText + ")\n";
  1194. // Abort in release mode for TypeListManager warnings!
  1195. } // foreach
  1196. if (String.IsNullOrEmpty(callstackLines) == false)
  1197. {
  1198. message += "\n" + callstackLines;
  1199. }
  1200. } // if
  1201. // Skip message if we just logging it over and over again (log spam)
  1202. // Note: This will only skip messages that have been written exactly
  1203. // in this same way (full warning with stack trace).
  1204. if (CheckDuplicateMessage(message))
  1205. {
  1206. return;
  1207. }
  1208. // Format the message with a time stamp and whatever is needed
  1209. string formattedMessage = FormatMessage(
  1210. // Only add "Warning: " if this is not already a fatal error.
  1211. message.StartsWith("Error: ")
  1212. ? message
  1213. : "Warning: " + message);
  1214. // Log the formatted message to the console first
  1215. ToConsole(formattedMessage, true);
  1216. try
  1217. {
  1218. // Also send the message to all attached handlers like the log server
  1219. if (LogHappened != null)
  1220. {
  1221. LogHappened(formattedMessage);
  1222. }
  1223. // And then finally to the current log file
  1224. ToFile(formattedMessage);
  1225. }
  1226. catch (Exception ex)
  1227. {
  1228. // Note: The formattedMessage text was just put into the console!
  1229. Console.WriteLine("Failed to log this warning to file: " + ex);
  1230. }
  1231. }
  1232. #endregion
  1233. #endregion
  1234. /// <summary>
  1235. /// Tests
  1236. /// </summary>
  1237. [NUnit.Framework.Category("LongRunning")]
  1238. internal class LogTests
  1239. {
  1240. #region TestLogging (Static)
  1241. /// <summary>
  1242. /// Test logging
  1243. /// </summary>
  1244. [Test]
  1245. public static void TestLogging()
  1246. {
  1247. Info("Just some boring info line...");
  1248. // Open the text editor and make sure the log is sent to the server.
  1249. // Note: If we can connect to the log server quick enough this line
  1250. // is not required, but if we timeout or the connection is slow, this
  1251. // is much better and consistent to test. Also good for opening editor!
  1252. Close();
  1253. }
  1254. #endregion
  1255. #region TestConsoleLog (Static)
  1256. /// <summary>
  1257. /// Test console log
  1258. /// </summary>
  1259. [Test]
  1260. public static void TestConsoleLog()
  1261. {
  1262. // Just printing to the console to see how a log would looks like
  1263. Console.WriteLine(Log.LogHeader);
  1264. Test("Just some boring test line...");
  1265. Console.WriteLine("Current directory: " +
  1266. System.IO.Directory.GetCurrentDirectory());
  1267. //Console.WriteLine("Does " + Log.Instance.Filename + " exists: " +
  1268. // File.Exists(Log.Instance.Filename));
  1269. }
  1270. #endregion
  1271. #region ConsoleWriteLinePerformance (Static)
  1272. /// <summary>
  1273. /// ConsoleWriteLinePerformance
  1274. /// </summary>
  1275. [Test]
  1276. public static void ConsoleWriteLinePerformance()
  1277. {
  1278. // Simple Log.Test performance test
  1279. Stopwatch timer = new Stopwatch();
  1280. timer.Start();
  1281. // Note: Makes no difference if using 1000 messages with 1 line each or
  1282. // 100 messages with 10 lines, both take 5.8s to execute, which is
  1283. // ridiculous. Per line that is 6ms for 30 characters, wtf?
  1284. const int NumOfWriteLines = 1000;
  1285. for (int i = 0; i < NumOfWriteLines; i++)
  1286. {
  1287. Test("Hi ho " + i);
  1288. }
  1289. // Note: About 6-7 times faster with shorter string (less than 1s):
  1290. //Console.WriteLine("Just");
  1291. //Console.WriteLine("Just some boring test line...");
  1292. // Note: Same speed if doing 100 messages with 10 lines each:
  1293. //Console.WriteLine("Just some boring test line...\n"+
  1294. // "Just some boring test line...\n"+
  1295. // "Just some boring test line...\n"+
  1296. // "Just some boring test line...\n"+
  1297. // "Just some boring test line...\n"+
  1298. // "Just some boring test line...\n"+
  1299. // "Just some boring test line...\n"+
  1300. // "Just some boring test line...\n"+
  1301. // "Just some boring test line...\n"+
  1302. // "Just some boring test line...");
  1303. timer.Stop();
  1304. Test("Writing took " + timer.ElapsedMilliseconds + "ms");
  1305. }
  1306. #endregion
  1307. #region TestMassiveLogging2 (Static)
  1308. /// <summary>
  1309. /// Test massive logging 2
  1310. /// </summary>
  1311. [Test]
  1312. public static void TestMassiveLogging2()
  1313. {
  1314. for (int i = 0; i < 50; i++)
  1315. {
  1316. Info("i'm message number " + i);
  1317. }
  1318. }
  1319. #endregion
  1320. #region TestInfoLogging (Static)
  1321. /// <summary>
  1322. /// Test logging
  1323. /// </summary>
  1324. [Test]
  1325. public static void TestInfoLogging()
  1326. {
  1327. Info("Just some boring test line...");
  1328. }
  1329. #endregion
  1330. #region TestWarningLogging (Static)
  1331. /// <summary>
  1332. /// TestWarningLogging
  1333. /// </summary>
  1334. [Test]
  1335. public static void TestWarningLogging()
  1336. {
  1337. Warning("Just some boring warning...");
  1338. }
  1339. #endregion
  1340. #region ArchiveLogFileWhileFileIsOpen (Static)
  1341. /// <summary>
  1342. /// Archive log file while file is open
  1343. /// </summary>
  1344. [Test]
  1345. public static void ArchiveLogFileWhileFileIsOpen()
  1346. {
  1347. Log log = new Log(); //CreateTestLog("Test");
  1348. LogName = "Test";
  1349. // We must log something, else there might be no Test log file!
  1350. log.WriteInfo("Hi log file", false);
  1351. // Okay, archive that
  1352. log.ArchiveLogFile();
  1353. // Now open ArchiveLogFile again
  1354. string archiveText = FileHelper.GetText("Test-Archive." +
  1355. FileExtension);
  1356. Assert.True(archiveText.Length > 0, "We must have some archiveText");
  1357. // Still works, hmm, try to open file manually (but allow writing too)
  1358. FileStream archiveStream = FileHelper.Open("Test-Archive." +
  1359. FileExtension, FileMode.Open,
  1360. FileAccess.Read, FileShare.ReadWrite);
  1361. Assert.NotEqual(0, archiveStream.ReadByte());
  1362. // And try to write it again, but close our archiveStream handle after!
  1363. log.ArchiveLogFile();
  1364. archiveStream.Close();
  1365. // And finally restore the DefaultProgramName again
  1366. logName = DefaultLogName;
  1367. }
  1368. #endregion
  1369. #region CreateLogFile (Static)
  1370. /// <summary>
  1371. /// Create log file. Note: Too slow for a dynamic unit test.
  1372. /// </summary>
  1373. [Test]
  1374. public static void CreateLogFile()
  1375. {
  1376. // At first we want to use an extra test log file to don't get in
  1377. // conflict with the already existing real logs
  1378. string testLogFilename = "CreateLogFile.tst";
  1379. // At the beginning there shouldn't exist this file
  1380. Assert.False(FileHelper.Exists(testLogFilename),
  1381. "log file should exist");
  1382. // Now we create the new (test)log file
  1383. Log log = new Log(); //CreateTestLog("tst");
  1384. LogName = "tst";
  1385. Assert.True(log.CreateLogFile(testLogFilename), "log creation");
  1386. // and expect that the file created successfully too
  1387. Assert.True(FileHelper.Exists(testLogFilename),
  1388. "log file should exist");
  1389. // Finally cleanup our test log file. We have to dispose the log
  1390. // handle explicitly, so we don't open the log in a text editor ^^
  1391. log.logFile.Dispose();
  1392. log.logFile = null;
  1393. FileHelper.SafeDelete(testLogFilename);
  1394. // And finally restore the DefaultProgramName again
  1395. logName = DefaultLogName;
  1396. }
  1397. #endregion
  1398. #region TestLogHeader (Static)
  1399. /// <summary>
  1400. /// Log header
  1401. /// </summary>
  1402. [Test]
  1403. public static void TestLogHeader()
  1404. {
  1405. Assert.True(Log.LogHeader.Contains(
  1406. "Program: Engine"));
  1407. Assert.True(Log.LogHeader.Contains(
  1408. "Modules: None"));
  1409. Assert.True(Log.LogHeader.Contains(
  1410. "Start Time: " + DateTime.Now.GetIsoDateTime()));
  1411. Assert.True(Log.LogHeader.Contains(
  1412. "User: " + Environment.UserName +
  1413. " (" + Environment.MachineName + ")"));
  1414. }
  1415. #endregion
  1416. #region LogToFile (Static)
  1417. /// <summary>
  1418. /// Log to file. Note: Too slow for a dynamic unit test.
  1419. /// </summary>
  1420. [Test]
  1421. public static void LogToFile()
  1422. {
  1423. // We want to use an extra test log file to don't get in conflict with
  1424. // the already existing real logs
  1425. Log log = new Log();
  1426. LogName = "LogToFile";
  1427. // and just make a sanity check that the file doesn't exists
  1428. Assert.False(FileHelper.Exists(log.Filename),
  1429. "log file shouldn't exist");
  1430. // Now we log something to the file
  1431. string testLogMessage = "Hellooo unit test world";
  1432. log.ToFile(testLogMessage);
  1433. // and expect that the file was created (inclusive our log message)
  1434. Assert.True(FileHelper.Exists(log.Filename), "log file should exist");
  1435. try
  1436. {
  1437. // Make sure we got no logFile anymore. Close the log file handle,
  1438. // so that we have the rights to read the file and stop writing.
  1439. log.logFile.Dispose();
  1440. log.logFile = null;
  1441. // Look if our test log was really written
  1442. string expectedLogFileText =
  1443. Log.LogHeader + Environment.NewLine +
  1444. testLogMessage + Environment.NewLine;
  1445. //does not work because we have time now in the header:
  1446. //Assert.Equal(expectedLogFileText, FileHelper.GetText(log.Filename));
  1447. }
  1448. finally
  1449. {
  1450. // We always make sure that we cleanup our testing stuff again
  1451. FileHelper.SafeDelete(log.Filename);
  1452. }
  1453. // And finally restore the DefaultProgramName again
  1454. logName = DefaultLogName;
  1455. }
  1456. #endregion
  1457. #region ArchiveLogFile (Static)
  1458. /// <summary>
  1459. /// Archive log file
  1460. /// </summary>
  1461. [Test]
  1462. public static void ArchiveLogFile()
  1463. {
  1464. // We want to use an extra test log file to don't get in conflict with the
  1465. // already existing real logs
  1466. Log log = new Log(); //CreateTestLog("ArchiveLogFile");
  1467. LogName = "ArchiveLogFile";
  1468. // and just make a sanity check that the file doesn't exists
  1469. Assert.False(FileHelper.Exists(log.Filename), "log file should exist");
  1470. // Just make a unimportant log
  1471. string firstLogText = "Helloo...";
  1472. string firstLogHeader = Log.LogHeader;
  1473. log.ToFile(firstLogText);
  1474. // Now we have to "simulate" an exit and restart the program
  1475. // -> Close the log file (handle) again, so that we have the rights to
  1476. // read the file
  1477. log.logFile.Dispose();
  1478. log.logFile = null;
  1479. // For the first time there shouldn't exist the archive file
  1480. Assert.False(FileHelper.Exists(log.ArchivedLogFilename),
  1481. "archived log file should not exist yet");
  1482. log.ArchiveLogFile();
  1483. // and after completing archive it should
  1484. Assert.True(FileHelper.Exists(log.ArchivedLogFilename),
  1485. "archived log file should exist");
  1486. try
  1487. {
  1488. // but now the "original" log don't
  1489. Assert.False(FileHelper.Exists(log.Filename),
  1490. "log file should not exist");
  1491. // Now we re-spam to the log again
  1492. string secondLogText = "Wo... Unit-Test ^^";
  1493. string secondLogHeader = Log.LogHeader;
  1494. log.ToFile(secondLogText);
  1495. // and "simulate" an exit again too
  1496. log.logFile.Dispose();
  1497. log.logFile = null;
  1498. // to call the archive function a second time
  1499. log.ArchiveLogFile();
  1500. // Finally we look if our complete log information was archived
  1501. // correctly
  1502. string archivedText =
  1503. firstLogHeader + Environment.NewLine +
  1504. firstLogText + Environment.NewLine +
  1505. Environment.NewLine +
  1506. Environment.NewLine +
  1507. secondLogHeader + Environment.NewLine +
  1508. secondLogText + Environment.NewLine;
  1509. //does not work because we have time now in the header:
  1510. //Assert.Equal(archivedText,
  1511. // FileHelper.GetText(log.ArchivedLogFilename));
  1512. // Just for fun we make a sanity check if the original log file was
  1513. // deleted
  1514. Assert.False(FileHelper.Exists(log.Filename),
  1515. "log file should not longer exist");
  1516. }
  1517. finally
  1518. {
  1519. // At the end make sure that we cleanup our testing file stuff again
  1520. // -> Original log file (shouldn't be normally executed here)
  1521. FileHelper.SafeDelete(log.Filename);
  1522. // -> and our archived log
  1523. FileHelper.SafeDelete(log.ArchivedLogFilename);
  1524. }
  1525. // And finally restore the DefaultProgramName again
  1526. logName = DefaultLogName;
  1527. }
  1528. #endregion
  1529. #region MultipleLogFileAccess (Static)
  1530. /// <summary>
  1531. /// Multiple log file access. Will open Notepad.exe and wait until the
  1532. /// user closes it again before this test finishes. Note: If the user
  1533. /// uses another text editor it might return right away and the test
  1534. /// finishes after 100-200ms.
  1535. /// </summary>
  1536. [Test, NUnit.Framework.Category("Visual")]
  1537. public static void MultipleLogFileAccess()
  1538. {
  1539. Console.WriteLine(
  1540. "CurrentPath=" + System.IO.Directory.GetCurrentDirectory());
  1541. string testLogFile = "MultipleLogFileAccess.txt";
  1542. FileHelper.CreateTextFile(testLogFile, "Test - MultipleLogFileAccess");
  1543. Assert.True(FileHelper.Exists(testLogFile),
  1544. "test log file should exist");
  1545. // Open file in external program (Notepad if no other text editor is
  1546. // linked up).
  1547. Process notepad = Process.Start(testLogFile);
  1548. try
  1549. {
  1550. // We create here at first a log with the default name to avoid the
  1551. // automated archiving of current created log above
  1552. Log log = new Log(); //CreateTestLog("tst");
  1553. // Re-set the log filename to already opened one from the other
  1554. // process
  1555. LogName = "MultipleLogFileAccess";
  1556. log.ToFile("ToFile: Test - MultipleLogFileAccess");
  1557. // Wait until we have closed the notepad again
  1558. notepad.WaitForExit();
  1559. // to know when we can close the log file handle for final deleting
  1560. log.logFile.Dispose();
  1561. }
  1562. finally
  1563. {
  1564. FileHelper.SafeDelete(testLogFile);
  1565. }
  1566. // And finally restore the DefaultProgramName again
  1567. logName = DefaultLogName;
  1568. }
  1569. #endregion
  1570. #region TestQueue (Static)
  1571. /// <summary>
  1572. /// Test queue
  1573. /// </summary>
  1574. [Test]
  1575. public static void TestQueue()
  1576. {
  1577. Queue<string> testQueue = new Queue<string>();
  1578. testQueue.Enqueue("First entry");
  1579. testQueue.Enqueue("Second entry");
  1580. testQueue.Enqueue("Third entry");
  1581. int num = 0;
  1582. while (testQueue.Count != 0)
  1583. {
  1584. Console.WriteLine("Process the " + (++num) + ". entry= " +
  1585. testQueue.Dequeue());
  1586. }
  1587. }
  1588. #endregion
  1589. }
  1590. }
  1591. }