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