diff --git a/Vocaluxe/Base/CGraphics.cs b/Vocaluxe/Base/CGraphics.cs index 97ca9131..0c63169e 100644 --- a/Vocaluxe/Base/CGraphics.cs +++ b/Vocaluxe/Base/CGraphics.cs @@ -20,6 +20,8 @@ using System.Collections.Generic; using System.Diagnostics; using System.Drawing; using System.Windows.Forms; +using Serilog.Events; +using SerilogTimings; using Vocaluxe.Base.Fonts; using Vocaluxe.Base.ThemeSystem; using Vocaluxe.Screens; @@ -61,36 +63,35 @@ namespace Vocaluxe.Base public static void Init() { // Add Screens, must be the same order as in EScreens! - CLog.StartBenchmark("Build Screen List"); + CLog.LogInformation("Build Screen List"); + using (Operation.At(LogEventLevel.Information).Time("Build Screen List")) + { + _Screens.Add(new CScreenTest()); + _Screens.Add(new CScreenLoad()); + _Screens.Add(new CScreenMain()); + _Screens.Add(new CScreenSong()); + _Screens.Add(new CScreenOptions()); + _Screens.Add(new CScreenSing()); + _Screens.Add(new CScreenProfiles()); + _Screens.Add(new CScreenScore()); + _Screens.Add(new CScreenHighscore()); + _Screens.Add(new CScreenOptionsGame()); + _Screens.Add(new CScreenOptionsSound()); + _Screens.Add(new CScreenOptionsRecord()); + _Screens.Add(new CScreenOptionsVideo()); + _Screens.Add(new CScreenOptionsVideoAdjustments()); + _Screens.Add(new CScreenOptionsLyrics()); + _Screens.Add(new CScreenOptionsTheme()); + _Screens.Add(new CScreenNames()); + _Screens.Add(new CScreenCredits()); + _Screens.Add(new CScreenParty()); - _Screens.Add(new CScreenTest()); - _Screens.Add(new CScreenLoad()); - _Screens.Add(new CScreenMain()); - _Screens.Add(new CScreenSong()); - _Screens.Add(new CScreenOptions()); - _Screens.Add(new CScreenSing()); - _Screens.Add(new CScreenProfiles()); - _Screens.Add(new CScreenScore()); - _Screens.Add(new CScreenHighscore()); - _Screens.Add(new CScreenOptionsGame()); - _Screens.Add(new CScreenOptionsSound()); - _Screens.Add(new CScreenOptionsRecord()); - _Screens.Add(new CScreenOptionsVideo()); - _Screens.Add(new CScreenOptionsVideoAdjustments()); - _Screens.Add(new CScreenOptionsLyrics()); - _Screens.Add(new CScreenOptionsTheme()); - _Screens.Add(new CScreenNames()); - _Screens.Add(new CScreenCredits()); - _Screens.Add(new CScreenParty()); - - Debug.Assert(_Screens.Count == (int)EScreen.CountEntry, "Screen list and screens enum do not match"); - - _PopupScreens.Add(new CPopupScreenPlayerControl()); - _PopupScreens.Add(new CPopupScreenVolumeControl()); - _PopupScreens.Add(new CPopupScreenServerQR()); - - CLog.StopBenchmark("Build Screen List"); + Debug.Assert(_Screens.Count == (int)EScreen.CountEntry, "Screen list and screens enum do not match"); + _PopupScreens.Add(new CPopupScreenPlayerControl()); + _PopupScreens.Add(new CPopupScreenVolumeControl()); + _PopupScreens.Add(new CPopupScreenServerQR()); + } CurrentScreen = _Screens[(int)EScreen.Load]; NextScreen = null; _CurrentPopupScreen = EPopupScreens.NoPopup; @@ -99,9 +100,11 @@ namespace Vocaluxe.Base GlobalAlpha = 1f; ZOffset = 0f; - CLog.StartBenchmark("Load Theme"); - LoadTheme(); - CLog.StopBenchmark("Load Theme"); + CLog.LogInformation("Load Theme"); + using (Operation.At(LogEventLevel.Information).Time("Load Theme")) + { + LoadTheme(); + } } public static void Close() @@ -118,10 +121,12 @@ namespace Vocaluxe.Base for (int i = 0; i < _Screens.Count; i++) { - CLog.StartBenchmark("Load Theme " + Enum.GetNames(typeof(EScreen))[i]); - _Screens[i].Init(); - _Screens[i].LoadTheme(CThemes.GetThemeScreensPath(_Screens[i].PartyModeID)); - CLog.StopBenchmark("Load Theme " + Enum.GetNames(typeof(EScreen))[i]); + CLog.LogInformation("Load Theme " + Enum.GetNames(typeof(EScreen))[i]); + using (Operation.At(LogEventLevel.Information).Time("Load Theme " + Enum.GetNames(typeof(EScreen))[i])) + { + _Screens[i].Init(); + _Screens[i].LoadTheme(CThemes.GetThemeScreensPath(_Screens[i].PartyModeID)); + } } foreach (IMenu popup in _PopupScreens) diff --git a/Vocaluxe/Base/CLog.cs b/Vocaluxe/Base/CLog.cs index f91b9d00..7b8af970 100644 --- a/Vocaluxe/Base/CLog.cs +++ b/Vocaluxe/Base/CLog.cs @@ -16,210 +16,262 @@ #endregion using System; +using System.Collections.Generic; using System.Diagnostics; using System.IO; +using System.Runtime.CompilerServices; using System.Text; +using System.Text.RegularExpressions; using System.Windows.Forms; +using Serilog; +using Serilog.Configuration; +using Serilog.Core; +using Serilog.Context; +using Serilog.Events; +using Serilog.Formatting.Compact; namespace Vocaluxe.Base { - class CLogFile : IDisposable - { - private readonly string _LogFileName; - private readonly string _LogName; - private StreamWriter _LogFile; - private readonly Object _FileMutex = new Object(); - - public CLogFile(string fileName, string logName) - { - _LogName = logName; - _LogFileName = fileName; - } - - private void _Open() - { - lock (_FileMutex) - { - if (_LogFile != null) - return; - _LogFile = new StreamWriter(Path.Combine(CSettings.DataFolder, _LogFileName), false, Encoding.UTF8); - - _LogFile.WriteLine(_LogName + " " + CSettings.GetFullVersionText() + " " + DateTime.Now); - _LogFile.WriteLine("----------------------------------------"); - _LogFile.WriteLine(); - } - } - - public void Close() - { - lock (_FileMutex) - { - if (_LogFile == null) - return; - try - { - _LogFile.Flush(); - _LogFile.Close(); - } - catch (Exception) {} - } - } - - public virtual void Add(string text) - { - if (_LogFile == null) - _Open(); - - // ReSharper disable PossibleNullReferenceException - _LogFile.WriteLine(text); - // ReSharper restore PossibleNullReferenceException - _LogFile.Flush(); - } - - public void Dispose() - { - Close(); - GC.SuppressFinalize(this); - } - } - - class CErrorLogFile : CLogFile - { - private int _NumErrors; - private readonly Object _WriteMutex = new Object(); - - public CErrorLogFile(string fileName, string logName) : base(fileName, logName) {} - - public override void Add(string errorText) - { - lock (_WriteMutex) - { - _NumErrors++; - base.Add(_NumErrors + ") " + errorText); - } - } - } - static class CLog { - private const int _MaxBenchmarks = 10; - private static int _BenchmarksRunning; private static bool _Initialized; - private static CLogFile _ErrorLog; - private static CLogFile _PerformanceLog; - private static CLogFile _BenchmarkLog; - private static CLogFile _DebugLog; - private static CLogFile _SongInfoLog; + private static readonly StringBuilder _MainLogStringBuilder = new StringBuilder(); + private static readonly StringWriter _MainLogStringWriter = new StringWriter(_MainLogStringBuilder); - private static Stopwatch[] _BenchmarkTimer; - private static readonly double _NanosecPerTick = (1000.0 * 1000.0 * 1000.0) / Stopwatch.Frequency; + private static Logger _MainLog; + private static Logger _SongInfoLog; + private static string _LogFolder; - public static void Init() + private const string _MainLogTemplate = "[{TimeStampFromStart}] [{Level}] {Message}{NewLine}{Properties}{NewLine}{Exception}"; + private const string _SongInfoLogTemplate = "{Message}{NewLine}Additional info:{Properties}{NewLine}{Exception}"; + + public static void Init(string logFolder) { - _ErrorLog = new CErrorLogFile(CSettings.FileNameErrorLog, "Error-Log"); - _PerformanceLog = new CLogFile(CSettings.FileNamePerformanceLog, "Performance-Log"); - _BenchmarkLog = new CLogFile(CSettings.FileNameBenchmarkLog, "Benchmark-Log"); - _DebugLog = new CLogFile(CSettings.FileNameDebugLog, "Debug-Log"); - _SongInfoLog = new CLogFile(CSettings.FileNameSongInfoLog, "Song-Information-Log"); + _LogFolder = logFolder; - _BenchmarkTimer = new Stopwatch[_MaxBenchmarks]; - for (int i = 0; i < _BenchmarkTimer.Length; i++) - _BenchmarkTimer[i] = new Stopwatch(); - _BenchmarksRunning = 0; + _RollLogs(Path.Combine(_LogFolder, CSettings.FileNameMainLog), 2); + _RollLogs(Path.Combine(_LogFolder, CSettings.FileNameSongInfoLog), 2); + + _MainLog = new LoggerConfiguration() + .Enrich.WithThreadId() + .Enrich.FromLogContext() + .Enrich.WithTimeStampFromStart() + .WriteTo.TextWriter(_MainLogStringWriter, outputTemplate: _MainLogTemplate) + // Json can be activated by adding "new CompactJsonFormatter()" as first argument + .WriteTo.File(Path.Combine(_LogFolder, CSettings.FileNameMainLog), flushToDiskInterval: TimeSpan.FromSeconds(30), outputTemplate: _MainLogTemplate) +#if DEBUG + .WriteTo.Console(outputTemplate: _MainLogTemplate) +#endif + .CreateLogger(); + + Log.Logger = _MainLog; + + _SongInfoLog = new LoggerConfiguration() + .WriteTo.File(Path.Combine(_LogFolder, CSettings.FileNameSongInfoLog), flushToDiskInterval: TimeSpan.FromSeconds(60), outputTemplate: _SongInfoLogTemplate) +#if DEBUG + .WriteTo.Console(outputTemplate: "[SongInfo] " + _SongInfoLogTemplate) +#endif + .CreateLogger(); + _Initialized = true; } + public static void Close() { if (_Initialized) { - _ErrorLog.Dispose(); - _ErrorLog = null; - _PerformanceLog.Dispose(); - _PerformanceLog = null; - _BenchmarkLog.Dispose(); - _BenchmarkLog = null; - _DebugLog.Dispose(); - _DebugLog = null; + + _MainLog.Dispose(); + _MainLog = null; _SongInfoLog.Dispose(); _SongInfoLog = null; _Initialized = false; } } - #region LogError - public static void LogError(string errorText, bool show = false, bool exit = false, Exception e = null) + public static string MainLogEntries { - if (show) - MessageBox.Show(errorText, CSettings.ProgramName, MessageBoxButtons.OK, MessageBoxIcon.Error); - if (e != null) - errorText += ": " + e; - _ErrorLog.Add(errorText); - if (exit) - Environment.Exit(Environment.ExitCode); - } - #endregion LogError - - public static void LogDebug(string text) - { - _DebugLog.Add(String.Format("{0:HH:mm:ss.ffff}", DateTime.Now) + ":" + text); -#if DEBUG - Console.WriteLine(text); -#endif - } - - public static void LogSongInfo(string text) - { - _SongInfoLog.Add(text); - } - - public static void LogPerformance(string text) - { - _PerformanceLog.Add(text); - _PerformanceLog.Add("-------------------------------"); - } - - #region LogBenchmark - public static void StartBenchmark(string text) - { - if (_BenchmarksRunning < _MaxBenchmarks) - { - string space = String.Empty; - for (int i = 0; i < _BenchmarksRunning; i++) - space += " "; - _BenchmarkLog.Add(space + "Start " + text); - - _BenchmarkTimer[_BenchmarksRunning].Restart(); + get { + _MainLogStringWriter.Flush(); + return _MainLogStringBuilder.ToString(); } - else - LogError("Tried to start to many benchmarks at once"); //Log and ignore - _BenchmarksRunning++; //Inc even if not started to correct right Stop() call } - public static void StopBenchmark(string text) + public static void LogError(Exception exception, string errorText, bool show = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", + [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) { - if (_BenchmarksRunning > 0 && _BenchmarksRunning <= _MaxBenchmarks) + using (LogContext.PushProperty("CallingContext", new { callerMethodeName = callerMethodeName, callerFilePath = callerFilePath, callerLineNumer = callerLineNumer })) { - _BenchmarksRunning--; - _BenchmarkTimer[_BenchmarksRunning].Stop(); - - string space = String.Empty; - for (int i = 0; i < _BenchmarksRunning; i++) - space += " "; - - float ms; - if (Stopwatch.IsHighResolution && _NanosecPerTick > 0) - ms = (float)((_NanosecPerTick * _BenchmarkTimer[_BenchmarksRunning].ElapsedTicks) / (1000.0 * 1000.0)); + if (exit) + { + _MainLog.Fatal(exception, errorText, propertyValues); + } else - ms = _BenchmarkTimer[_BenchmarksRunning].ElapsedMilliseconds; + { + _MainLog.Error(exception, errorText, propertyValues); + } + } - _BenchmarkLog.Add(space + "Stop " + text + ", Elapsed Time: " + ms.ToString("0.000") + "ms"); - _BenchmarkLog.Add(String.Empty); + if (show) + { + //Todo: Logsend assistent + MessageBox.Show(errorText, CSettings.ProgramName, MessageBoxButtons.OK, MessageBoxIcon.Error); + } + + + if (exit) + { + // Flush the logging piplines before exiting + _MainLog.Dispose(); + _SongInfoLog.Dispose(); + // Close the Programm + Environment.Exit(Environment.ExitCode); } - else - _BenchmarksRunning--; } - #endregion LogBenchmark + + public static void LogError(string errorText, bool show = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", + [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) + { + // ReSharper disable ExplicitCallerInfoArgument + LogError(null, errorText, show, exit, callerMethodeName, callerFilePath, callerLineNumer, propertyValues); + } + + public static void LogWarning(string text, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) + { + using (LogContext.PushProperty("CallingContext", new { callerMethodeName = callerMethodeName, callerFilePath = callerFilePath, callerLineNumer = callerLineNumer })) + { + _MainLog.Warning(text, propertyValues); + } + } + + public static void LogInformation(string text, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) + { + using (LogContext.PushProperty("CallingContext", new { callerMethodeName = callerMethodeName, callerFilePath = callerFilePath, callerLineNumer = callerLineNumer })) + { + _MainLog.Information(text, propertyValues); + } + } + + public static void LogDebug(string text, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) + { + using (LogContext.PushProperty("CallingContext", new { callerMethodeName = callerMethodeName, callerFilePath = callerFilePath, callerLineNumer = callerLineNumer })) + { + _MainLog.Debug(text, propertyValues); + } + } + + public static void LogSongError(Exception exception, string text, params object[] propertyValues) + { + _SongInfoLog.Error(exception, text, propertyValues); + } + public static void LogSongError(string text, params object[] propertyValues) + { + _SongInfoLog.Error(text, propertyValues); + } + + public static void LogSongWaring(string text, params object[] propertyValues) + { + _SongInfoLog.Warning(text, propertyValues); + } + + #region Log rolling + + private static void _RollLogs(string mainLogFile, int numLogsToKeep) + { + _DeleteOldLogs(mainLogFile, numLogsToKeep); + + string currentSourceFile = _GenerateRollLogFileName(mainLogFile, numLogsToKeep); + + + for (var i = numLogsToKeep; i > 1; i--) + { + string currentTargetFile = currentSourceFile; + currentSourceFile = _GenerateRollLogFileName(mainLogFile, i - 1); + + if (File.Exists(currentSourceFile)) + { + try + { + File.Move(currentSourceFile, currentTargetFile); + } + catch (Exception) + { + // Cant log anything here as the log isn't initialized yet + } + } + } + + if (File.Exists(mainLogFile)) + { + try { + if(numLogsToKeep > 0) + File.Move(mainLogFile, currentSourceFile); + else + File.Delete(mainLogFile); + } + catch (Exception) + { + // Cant log anything here as the log isn't initialized yet + } + } + } + + private static void _DeleteOldLogs(string mainLogFile, int numLogsToKeep) + { + Regex r = new Regex($"{Path.GetDirectoryName(mainLogFile)}\\\\{Path.GetFileNameWithoutExtension(mainLogFile)}_([0-9]+){Path.GetExtension(mainLogFile)}", RegexOptions.IgnoreCase); + IEnumerable logFiles = Directory.EnumerateFiles($"{Path.GetDirectoryName(mainLogFile)}", $"{Path.GetFileNameWithoutExtension(mainLogFile)}*{Path.GetExtension(mainLogFile)}"); + foreach (string file in logFiles) + { + Match m = r.Match(file); + if (m.Success) + { + int logNum = -1; + Int32.TryParse(m.Groups[1].Value, out logNum); + + if (logNum < 0 || logNum > numLogsToKeep - 1) + { + try + { + File.Delete(file); + } + catch (Exception) + { + // Cant log anything here as the log isn't initialized yet + } + + } + } + } + } + + private static string _GenerateRollLogFileName(string mainLogFile, int number) + { + return $"{Path.GetDirectoryName(mainLogFile)}\\{Path.GetFileNameWithoutExtension(mainLogFile)}_{number}{Path.GetExtension(mainLogFile)}"; + } + + #endregion + + #region CTimeStampFromStartEnricher + + // ReSharper disable once InconsistentNaming + private static LoggerConfiguration WithTimeStampFromStart(this LoggerEnrichmentConfiguration enrich) + { + return enrich.With(new CTimeStampFromStartEnricher()); + } + + private class CTimeStampFromStartEnricher : ILogEventEnricher + { + private readonly DateTimeOffset _Start = DateTimeOffset.Now; + + public void Enrich(LogEvent logEvent, ILogEventPropertyFactory lepf) + { + logEvent.AddPropertyIfAbsent( + lepf.CreateProperty("TimeStampFromStart", logEvent.Timestamp - _Start)); + } + } + + #endregion } } \ No newline at end of file diff --git a/Vocaluxe/Base/CMain.cs b/Vocaluxe/Base/CMain.cs index 61bfcf69..b4256fa0 100644 --- a/Vocaluxe/Base/CMain.cs +++ b/Vocaluxe/Base/CMain.cs @@ -19,6 +19,7 @@ using System; using System.Collections.Generic; using System.Collections.ObjectModel; using System.Drawing; +using System.Runtime.CompilerServices; using Vocaluxe.Base.Fonts; using Vocaluxe.Base.ThemeSystem; using VocaluxeLib; @@ -507,21 +508,38 @@ namespace Vocaluxe.Base } } + // ReSharper disable ExplicitCallerInfoArgument class CBlog : ILog { - public void LogError(string errorText, bool showMsg = false, bool exit = false) + public void LogError(Exception exeption, string errorText, bool showMsg = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) { - CLog.LogError(errorText, showMsg, exit); + CLog.LogError(exeption, errorText, showMsg, exit, callerMethodeName, callerFilePath, callerLineNumer, propertyValues); } - public void LogDebug(string text) + public void LogError(string errorText, bool showMsg = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) { - CLog.LogDebug(text); + CLog.LogError(null, errorText, showMsg, exit, callerMethodeName, callerFilePath, callerLineNumer, propertyValues); } - public void LogSongInfo(string text) + public void LogDebug(string text, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues) { - CLog.LogSongInfo(text); + + CLog.LogDebug(text, callerMethodeName, callerFilePath, callerLineNumer, propertyValues); + } + + public void LogSongWarning(string text, params object[] propertyValues) + { + CLog.LogSongWaring(text, propertyValues); + } + + public void LogSongError(Exception exception, string text, params object[] propertyValues) + { + CLog.LogSongError(exception, text, propertyValues); + } + + public void LogSongError(string text, params object[] propertyValues) + { + CLog.LogSongError(text, propertyValues); } } diff --git a/Vocaluxe/Base/CSettings.cs b/Vocaluxe/Base/CSettings.cs index 8bc61828..5a6a8998 100644 --- a/Vocaluxe/Base/CSettings.cs +++ b/Vocaluxe/Base/CSettings.cs @@ -111,11 +111,8 @@ namespace Vocaluxe.Base public const string FileNameOldHighscoreDB = "Ultrastar.db"; public const string FileNameCoverDB = "CoverDB.sqlite"; public const string FileNameCreditsRessourcesDB = "CreditsRessourcesDB.sqlite"; - - public const string FileNamePerformanceLog = "Performance.log"; - public const string FileNameErrorLog = "Error.log"; - public const string FileNameBenchmarkLog = "Benchmark.log"; - public const string FileNameDebugLog = "Debug.log"; + + public const string FileNameMainLog = "Vocaluxe.log"; public const string FileNameSongInfoLog = "SongInformation.log"; public const string FileNameRequiredSkinElements = "RequiredSkinElements.xml"; @@ -135,6 +132,7 @@ namespace Vocaluxe.Base public const string FolderNameLanguages = "Languages"; public const string FolderNameScreenshots = "Screenshots"; public const string FolderNameBackgroundMusic = "BackgroundMusic"; + public const string FolderNameLogs = "Logs"; public const string FolderNamePartyModes = "PartyModes"; public const string FolderNamePartyModeCode = "Code"; diff --git a/Vocaluxe/Base/CSongs.cs b/Vocaluxe/Base/CSongs.cs index ce0fbb66..5429b65b 100644 --- a/Vocaluxe/Base/CSongs.cs +++ b/Vocaluxe/Base/CSongs.cs @@ -22,6 +22,8 @@ using System.Linq; using System.Threading; using System.IO; using System.Threading.Tasks; +using Serilog.Events; +using SerilogTimings; using VocaluxeLib; using VocaluxeLib.Songs; @@ -333,54 +335,65 @@ namespace Vocaluxe.Base public static void LoadSongs() { - CLog.StartBenchmark("Load Songs"); - SongsLoaded = false; - _Songs.Clear(); - - CLog.StartBenchmark("List Songs"); - var files = new List(); - foreach (string p in CConfig.SongFolders) + CLog.LogInformation("Load Songs"); + using (Operation.At(LogEventLevel.Information).Time("Load Songs")) { - if (Directory.Exists(p)) + SongsLoaded = false; + _Songs.Clear(); + + var files = new List(); + + CLog.LogInformation("List Songs"); + using (Operation.At(LogEventLevel.Information).Time("List Songs")) { - string path = p; - files.AddRange(CHelper.ListFiles(path, "*.txt", true, true)); - files.AddRange(CHelper.ListFiles(path, "*.txd", true, true)); + + foreach (string p in CConfig.SongFolders) + { + if (Directory.Exists(p)) + { + string path = p; + files.AddRange(CHelper.ListFiles(path, "*.txt", true, true)); + files.AddRange(CHelper.ListFiles(path, "*.txd", true, true)); + } + } + } + + CLog.LogInformation("Read TXTs"); + using (Operation.At(LogEventLevel.Information).Time("Read TXTs")) + { + foreach (string file in files) + { + CSong song = CSong.LoadSong(file); + if (song == null) + continue; + song.ID = _Songs.Count; + if (song.LoadNotes()) + _Songs.Add(song); + } + } + + CLog.LogInformation("Sort Songs"); + using (Operation.At(LogEventLevel.Information).Time("Sorted Songs")) + { + Sorter.SongSorting = CConfig.Config.Game.SongSorting; + Sorter.IgnoreArticles = CConfig.Config.Game.IgnoreArticles; + Categorizer.Tabs = CConfig.Config.Game.Tabs; + Categorizer.ObjectChanged += _HandleCategoriesChanged; + } + + Category = -1; + SongsLoaded = true; + + switch (CConfig.Config.Theme.CoverLoading) + { + case ECoverLoading.TR_CONFIG_COVERLOADING_ATSTART: + _LoadCovers(); + break; + case ECoverLoading.TR_CONFIG_COVERLOADING_DYNAMIC: + _LoadCoversAsync(); + break; } } - CLog.StopBenchmark("List Songs"); - - CLog.StartBenchmark("Read TXTs"); - foreach (string file in files) - { - CSong song = CSong.LoadSong(file); - if (song == null) - continue; - song.ID = _Songs.Count; - if (song.LoadNotes()) - _Songs.Add(song); - } - CLog.StopBenchmark("Read TXTs"); - - CLog.StartBenchmark("Sort Songs"); - Sorter.SongSorting = CConfig.Config.Game.SongSorting; - Sorter.IgnoreArticles = CConfig.Config.Game.IgnoreArticles; - Categorizer.Tabs = CConfig.Config.Game.Tabs; - Categorizer.ObjectChanged += _HandleCategoriesChanged; - CLog.StopBenchmark("Sort Songs"); - Category = -1; - SongsLoaded = true; - - switch (CConfig.Config.Theme.CoverLoading) - { - case ECoverLoading.TR_CONFIG_COVERLOADING_ATSTART: - _LoadCovers(); - break; - case ECoverLoading.TR_CONFIG_COVERLOADING_DYNAMIC: - _LoadCoversAsync(); - break; - } - CLog.StopBenchmark("Load Songs"); } private static void _LoadCoversAsync() @@ -396,25 +409,28 @@ namespace Vocaluxe.Base private static void _LoadCovers() { - CLog.StartBenchmark("Load Covers"); - int songCount = _Songs.Count; - AutoResetEvent ev = new AutoResetEvent(songCount == 0); - - NumSongsWithCoverLoaded = 0; - foreach (CSong song in _Songs) + CLog.LogInformation("Load Covers"); + using (Operation.At(LogEventLevel.Information).Time("Loaded Covers")) { - CSong tmp = song; - Task.Factory.StartNew(() => + int songCount = _Songs.Count; + AutoResetEvent ev = new AutoResetEvent(songCount == 0); + + NumSongsWithCoverLoaded = 0; + foreach (CSong song in _Songs) + { + CSong tmp = song; + Task.Factory.StartNew(() => { tmp.LoadSmallCover(); if (Interlocked.Increment(ref _NumSongsWithCoverLoaded) >= songCount) ev.Set(); }); + } + + ev.WaitOne(); + _CoverLoaded = true; + CDataBase.CommitCovers(); } - ev.WaitOne(); - _CoverLoaded = true; - CDataBase.CommitCovers(); - CLog.StopBenchmark("Load Covers"); } } } \ No newline at end of file diff --git a/Vocaluxe/Base/Fonts/CFonts.cs b/Vocaluxe/Base/Fonts/CFonts.cs index 5e242e2c..ae9d1af9 100644 --- a/Vocaluxe/Base/Fonts/CFonts.cs +++ b/Vocaluxe/Base/Fonts/CFonts.cs @@ -21,6 +21,8 @@ using System.Diagnostics; using System.Drawing; using System.IO; using System.Linq; +using Serilog.Events; +using SerilogTimings; using VocaluxeLib; using VocaluxeLib.Menu; using VocaluxeLib.Xml; @@ -217,7 +219,7 @@ namespace Vocaluxe.Base.Fonts } } else - CLog.LogError("Empty fontName requested", false, false, new Exception()); + CLog.LogError("Empty fontName requested"); if (_FontFamilies.Count == 0) CLog.LogError("No fonts found!", true, true); @@ -265,7 +267,7 @@ namespace Vocaluxe.Base.Fonts } catch (Exception e) { - CLog.LogError("Error loading default Fonts", false, false, e); + CLog.LogError(e, "Error loading default Fonts"); return false; } @@ -287,9 +289,13 @@ namespace Vocaluxe.Base.Fonts return false; } } - CLog.StartBenchmark("BuildGlyphs"); - _BuildGlyphs(); - CLog.StopBenchmark("BuildGlyphs"); + + CLog.LogInformation("Build Glyphs"); + using (Operation.At(LogEventLevel.Information).Time("Build Glyphs")) + { + _BuildGlyphs(); + } + return true; } diff --git a/Vocaluxe/Base/ThemeSystem/CSkin.cs b/Vocaluxe/Base/ThemeSystem/CSkin.cs index 6e04b079..379ed66a 100644 --- a/Vocaluxe/Base/ThemeSystem/CSkin.cs +++ b/Vocaluxe/Base/ThemeSystem/CSkin.cs @@ -147,7 +147,7 @@ namespace Vocaluxe.Base.ThemeSystem } catch (Exception e) { - CLog.LogError("Can't load skin file \"" + Path.Combine(_Folder, _FileName) + "\". Invalid file!", false, false, e); + CLog.LogError(e, "Can't load skin file \"" + Path.Combine(_Folder, _FileName) + "\". Invalid file!"); return false; } diff --git a/Vocaluxe/Base/ThemeSystem/CTheme.cs b/Vocaluxe/Base/ThemeSystem/CTheme.cs index ef37438e..6014da02 100644 --- a/Vocaluxe/Base/ThemeSystem/CTheme.cs +++ b/Vocaluxe/Base/ThemeSystem/CTheme.cs @@ -80,7 +80,7 @@ namespace Vocaluxe.Base.ThemeSystem } catch (Exception e) { - CLog.LogError("Can't load theme \"" + _FileName + "\". Invalid file!", false, false, e); + CLog.LogError(e, "Can't load theme \"" + _FileName + "\". Invalid file!"); return false; } diff --git a/Vocaluxe/Lib/Draw/CDirect3D.cs b/Vocaluxe/Lib/Draw/CDirect3D.cs index 9960e86f..11dd3c22 100644 --- a/Vocaluxe/Lib/Draw/CDirect3D.cs +++ b/Vocaluxe/Lib/Draw/CDirect3D.cs @@ -94,7 +94,7 @@ namespace Vocaluxe.Lib.Draw } catch (Direct3DX9NotFoundException e) { - CLog.LogError("No DirectX runtimes were found, please download and install them from http://www.microsoft.com/download/en/details.aspx?id=8109", true, true, e); + CLog.LogError(e, "No DirectX runtimes were found, please download and install them from http://www.microsoft.com/download/en/details.aspx?id=8109"); } _Form.KeyDown += _OnKeyDown; @@ -177,7 +177,7 @@ namespace Vocaluxe.Lib.Draw } catch (Exception e) { - CLog.LogError("Error during D3D device creation.", false, false, e); + CLog.LogError(e, "Error during D3D device creation."); } finally { diff --git a/Vocaluxe/Lib/Sound/CPortAudioHandle.cs b/Vocaluxe/Lib/Sound/CPortAudioHandle.cs index 81c4d9b0..355b4b45 100644 --- a/Vocaluxe/Lib/Sound/CPortAudioHandle.cs +++ b/Vocaluxe/Lib/Sound/CPortAudioHandle.cs @@ -86,7 +86,7 @@ namespace Vocaluxe.Lib.Sound } catch (Exception ex) { - CLog.LogError(errorText: $"Error disposing PortAudio: {ex.Message}", e: ex); + CLog.LogError(ex, "Error disposing PortAudio"); } } _Disposed = true; @@ -179,7 +179,7 @@ namespace Vocaluxe.Lib.Sound } catch (Exception ex) { - CLog.LogError(errorText:$"Error closing stream: {ex.Message}", e:ex); + CLog.LogError(ex, "Error closing stream:"); } _Streams.Remove(stream); } diff --git a/Vocaluxe/Lib/Video/Acinerella/CDecoderThread.cs b/Vocaluxe/Lib/Video/Acinerella/CDecoderThread.cs index 3d7229d0..64385abe 100644 --- a/Vocaluxe/Lib/Video/Acinerella/CDecoderThread.cs +++ b/Vocaluxe/Lib/Video/Acinerella/CDecoderThread.cs @@ -437,7 +437,7 @@ namespace Vocaluxe.Lib.Video.Acinerella } catch (Exception e) { - CLog.LogError("Couldn't copy the frame to the managed environment.", false, false, e); + CLog.LogError(e, "Couldn't copy the frame to the managed environment."); return false; } diff --git a/Vocaluxe/Program.cs b/Vocaluxe/Program.cs index 136508fd..590a0127 100644 --- a/Vocaluxe/Program.cs +++ b/Vocaluxe/Program.cs @@ -24,6 +24,8 @@ using System.Runtime.CompilerServices; using System.Runtime.ExceptionServices; using System.Threading; using System.Windows.Forms; +using Serilog.Events; +using SerilogTimings; using Vocaluxe.Base; using Vocaluxe.Base.Fonts; using Vocaluxe.Base.Server; @@ -96,170 +98,210 @@ namespace Vocaluxe Directory.CreateDirectory(CSettings.DataFolder); // Init Log - CLog.Init(); + CLog.Init(CSettings.FolderNameLogs); if (!CProgrammHelper.CheckRequirements()) return; CProgrammHelper.Init(); - CLog.StartBenchmark("Init Program"); - CMain.Init(); - Application.DoEvents(); + CLog.LogInformation("Init Program"); + using (Operation.At(LogEventLevel.Information).Time("Init Program")) + { + CMain.Init(); + Application.DoEvents(); - // Init Language - CLog.StartBenchmark("Init Language"); - if (!CLanguage.Init()) - throw new CLoadingException("Language"); - CLog.StopBenchmark("Init Language"); + // Init Language + CLog.LogInformation("Init Language"); + using (Operation.At(LogEventLevel.Information).Time("Init Language")) + { + if (!CLanguage.Init()) + throw new CLoadingException("Language"); + } - Application.DoEvents(); + Application.DoEvents(); - // load config - CLog.StartBenchmark("Init Config"); - CConfig.LoadCommandLineParams(args); - CConfig.UseCommandLineParamsBefore(); - CConfig.Init(); - CConfig.UseCommandLineParamsAfter(); - CLog.StopBenchmark("Init Config"); + // load config + CLog.LogInformation("Init Config"); + using (Operation.At(LogEventLevel.Information).Time("Init Config")) + { + CConfig.LoadCommandLineParams(args); + CConfig.UseCommandLineParamsBefore(); + CConfig.Init(); + CConfig.UseCommandLineParamsAfter(); + } - // Create folders - CSettings.CreateFolders(); + // Create folders + CSettings.CreateFolders(); - _SplashScreen = new CSplashScreen(); - Application.DoEvents(); + _SplashScreen = new CSplashScreen(); + Application.DoEvents(); - // Init Draw - CLog.StartBenchmark("Init Draw"); - if (!CDraw.Init()) - throw new CLoadingException("drawing"); - CLog.StopBenchmark("Init Draw"); + // Init Draw + CLog.LogInformation("Init Draw"); + using (Operation.At(LogEventLevel.Information).Time("Init Draw")) + { + if (!CDraw.Init()) + throw new CLoadingException("drawing"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Playback - CLog.StartBenchmark("Init Playback"); - if (!CSound.Init()) - throw new CLoadingException("playback"); - CLog.StopBenchmark("Init Playback"); + // Init Playback + CLog.LogInformation("Init Playback"); + using (Operation.At(LogEventLevel.Information).Time("Init Playback")) + { + if (!CSound.Init()) + throw new CLoadingException("playback"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Record - CLog.StartBenchmark("Init Record"); - if (!CRecord.Init()) - throw new CLoadingException("record"); - CLog.StopBenchmark("Init Record"); + // Init Record + CLog.LogInformation("Init Record"); + using (Operation.At(LogEventLevel.Information).Time("Init Record")) + { + if (!CRecord.Init()) + throw new CLoadingException("record"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init VideoDecoder - CLog.StartBenchmark("Init Videodecoder"); - if (!CVideo.Init()) - throw new CLoadingException("video"); - CLog.StopBenchmark("Init Videodecoder"); + // Init VideoDecoder + CLog.LogInformation("Init Videodecoder"); + using (Operation.At(LogEventLevel.Information).Time("Init Videodecoder")) + { + if (!CVideo.Init()) + throw new CLoadingException("video"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Database - CLog.StartBenchmark("Init Database"); - if (!CDataBase.Init()) - throw new CLoadingException("database"); - CLog.StopBenchmark("Init Database"); + // Init Database + CLog.LogInformation("Init Database"); + using (Operation.At(LogEventLevel.Information).Time("Init Database")) + { + if (!CDataBase.Init()) + throw new CLoadingException("database"); + } - Application.DoEvents(); + Application.DoEvents(); - //Init Webcam - CLog.StartBenchmark("Init Webcam"); - if (!CWebcam.Init()) - throw new CLoadingException("webcam"); - CLog.StopBenchmark("Init Webcam"); + //Init Webcam + CLog.LogInformation("Init Webcam"); + using (Operation.At(LogEventLevel.Information).Time("Init Webcam")) + { + if (!CWebcam.Init()) + throw new CLoadingException("webcam"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Background Music - CLog.StartBenchmark("Init Background Music"); - CBackgroundMusic.Init(); - CLog.StopBenchmark("Init Background Music"); + // Init Background Music + CLog.LogInformation("Init Background Music"); + using (Operation.At(LogEventLevel.Information).Time("Init Background Music")) + { + CBackgroundMusic.Init(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Profiles - CLog.StartBenchmark("Init Profiles"); - CProfiles.Init(); - CLog.StopBenchmark("Init Profiles"); + // Init Profiles + CLog.LogInformation("Init Profiles"); + using (Operation.At(LogEventLevel.Information).Time("Init Profiles")) + { + CProfiles.Init(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Fonts - CLog.StartBenchmark("Init Fonts"); - if (!CFonts.Init()) - throw new CLoadingException("fonts"); - CLog.StopBenchmark("Init Fonts"); + // Init Fonts + CLog.LogInformation("Init Fonts"); + using (Operation.At(LogEventLevel.Information).Time("Init Fonts")) + { + if (!CFonts.Init()) + throw new CLoadingException("fonts"); + } - Application.DoEvents(); + Application.DoEvents(); - // Theme System - CLog.StartBenchmark("Init Theme"); - if (!CThemes.Init()) - throw new CLoadingException("theme"); - CLog.StopBenchmark("Init Theme"); + // Theme System + CLog.LogInformation("Init Theme"); + using (Operation.At(LogEventLevel.Information).Time("Init Theme")) + { + if (!CThemes.Init()) + throw new CLoadingException("theme"); + } - CLog.StartBenchmark("Load Theme"); - CThemes.Load(); - CLog.StopBenchmark("Load Theme"); + CLog.LogInformation("Load Theme"); + using (Operation.At(LogEventLevel.Information).Time("Load Theme")) + { + CThemes.Load(); + } - Application.DoEvents(); + Application.DoEvents(); - // Load Cover - CLog.StartBenchmark("Init Cover"); - if (!CCover.Init()) - throw new CLoadingException("covertheme"); - CLog.StopBenchmark("Init Cover"); + // Load Cover + CLog.LogInformation("Init Cover"); + using (Operation.At(LogEventLevel.Information).Time("Init Cover")) + { + if (!CCover.Init()) + throw new CLoadingException("covertheme"); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Screens - CLog.StartBenchmark("Init Screens"); - CGraphics.Init(); - CLog.StopBenchmark("Init Screens"); + // Init Screens + CLog.LogInformation("Init Screens"); + using (Operation.At(LogEventLevel.Information).Time("Init Screens")) + { + CGraphics.Init(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Server - CLog.StartBenchmark("Init Server"); - CVocaluxeServer.Init(); - CLog.StopBenchmark("Init Server"); + // Init Server + CLog.LogInformation("Init Server"); + using (Operation.At(LogEventLevel.Information).Time("Init Server")) + { + CVocaluxeServer.Init(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Input - CLog.StartBenchmark("Init Input"); - CController.Init(); - CController.Connect(); - CLog.StopBenchmark("Init Input"); + // Init Input + CLog.LogInformation("Init Input"); + using (Operation.At(LogEventLevel.Information).Time("Init Input")) + { + CController.Init(); + CController.Connect(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Game; - CLog.StartBenchmark("Init Game"); - CGame.Init(); - CProfiles.Update(); - CConfig.UsePlayers(); - CLog.StopBenchmark("Init Game"); + // Init Game; + CLog.LogInformation("Init Game"); + using (Operation.At(LogEventLevel.Information).Time("Init Game")) + { + CGame.Init(); + CProfiles.Update(); + CConfig.UsePlayers(); + } - Application.DoEvents(); + Application.DoEvents(); - // Init Party Modes; - CLog.StartBenchmark("Init Party Modes"); - if (!CParty.Init()) - throw new CLoadingException("Party Modes"); - CLog.StopBenchmark("Init Party Modes"); + // Init Party Modes; + CLog.LogInformation("Init Party Modes"); + using (Operation.At(LogEventLevel.Information).Time("Init Party Modes")) + { + if (!CParty.Init()) + throw new CLoadingException("Party Modes"); + } - Application.DoEvents(); - //Only reasonable point to call GC.Collect() because initialization may cause lots of garbage - //Rely on GC doing its job afterwards and call Dispose methods where appropriate - GC.Collect(); - CLog.StopBenchmark("Init Program"); + Application.DoEvents(); + //Only reasonable point to call GC.Collect() because initialization may cause lots of garbage + //Rely on GC doing its job afterwards and call Dispose methods where appropriate + GC.Collect(); + } } catch (Exception e) { @@ -288,7 +330,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CController)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CController)"); } try @@ -297,7 +339,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CVocaluxeServer)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CVocaluxeServer)"); } try @@ -306,7 +348,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CGraphics)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CGraphics)"); } try @@ -315,7 +357,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CThemes)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CThemes)"); } try @@ -324,7 +366,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CCover)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CCover)"); } try @@ -333,7 +375,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CFonts)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CFonts)"); } try @@ -342,7 +384,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CBackgroundMusic)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CBackgroundMusic)"); } try @@ -351,7 +393,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CWebcam)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CWebcam)"); } try @@ -360,7 +402,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CDataBase)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CDataBase)"); } try @@ -369,7 +411,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CVideo)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CVideo)"); } try @@ -378,7 +420,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CRecord)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CRecord)"); } try @@ -387,7 +429,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CSound)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CSound)"); } try @@ -396,7 +438,7 @@ namespace Vocaluxe } catch (Exception e) { - CLog.LogError("Error during shutdown! (CDraw)", false, false, e); + CLog.LogError(e, "Error during shutdown! (CDraw)"); } GC.Collect(); // Do a GC run here before we close logs to have finalizers run diff --git a/Vocaluxe/Properties/AssemblyInfo.cs b/Vocaluxe/Properties/AssemblyInfo.cs index 5ab36484..856b5d45 100644 --- a/Vocaluxe/Properties/AssemblyInfo.cs +++ b/Vocaluxe/Properties/AssemblyInfo.cs @@ -27,7 +27,7 @@ using System.Runtime.InteropServices; [assembly: AssemblyConfiguration("")] [assembly: AssemblyCompany("")] [assembly: AssemblyProduct("Vocaluxe")] -[assembly: AssemblyCopyright("Copyright © 2017")] +[assembly: AssemblyCopyright("Copyright © 2018")] [assembly: AssemblyTrademark("")] [assembly: AssemblyCulture("")] diff --git a/Vocaluxe/Screens/CScreenLoad.cs b/Vocaluxe/Screens/CScreenLoad.cs index 641bad44..61b9e39e 100644 --- a/Vocaluxe/Screens/CScreenLoad.cs +++ b/Vocaluxe/Screens/CScreenLoad.cs @@ -15,8 +15,11 @@ // along with Vocaluxe. If not, see . #endregion +using System; using System.Threading; using System.Windows.Forms; +using Serilog.Events; +using SerilogTimings; using Vocaluxe.Base; using VocaluxeLib; using VocaluxeLib.Menu; @@ -42,6 +45,8 @@ namespace Vocaluxe.Screens private bool _IntroOutPlayed; private CVideoPlayer[] _Intros; + private IDisposable _TimerLoadSongsFull; + public override void Init() { base.Init(); @@ -123,7 +128,9 @@ namespace Vocaluxe.Screens videoPlayer.PreLoad(); } - CLog.StartBenchmark("Load Songs Full"); + CLog.LogInformation("Load Songs Full"); + _TimerLoadSongsFull = Operation.At(LogEventLevel.Information).Time("Loaded Songs Full"); + _SongLoaderThread = new Thread(CSongs.LoadSongs) {Name = "SongLoader", IsBackground = true}; _SongLoaderThread.Start(); CBackgroundMusic.OwnSongsAvailable = false; @@ -176,12 +183,15 @@ namespace Vocaluxe.Screens foreach (CVideoPlayer videoPlayer in _Intros) videoPlayer.Close(); - CLog.StopBenchmark("Load Songs Full"); + // Stop the song full load timer + _TimerLoadSongsFull.Dispose(); //Init Playlists - CLog.StartBenchmark("Init Playlists"); - CPlaylists.Init(); - CLog.StopBenchmark("Init Playlists"); + CLog.LogInformation("Init Playlists"); + using (Operation.At(LogEventLevel.Information).Time("Init Playlists")) + { + CPlaylists.Init(); + } } private void _CheckStartIntroVideos() diff --git a/Vocaluxe/Vocaluxe.csproj b/Vocaluxe/Vocaluxe.csproj index e21a0817..4b64c235 100644 --- a/Vocaluxe/Vocaluxe.csproj +++ b/Vocaluxe/Vocaluxe.csproj @@ -158,6 +158,35 @@ true + + + ..\packages\Serilog.2.5.0\lib\net46\Serilog.dll + True + + + ..\packages\Serilog.Enrichers.Thread.3.0.0\lib\net45\Serilog.Enrichers.Thread.dll + True + + + ..\packages\Serilog.Formatting.Compact.1.0.0\lib\net45\Serilog.Formatting.Compact.dll + True + + + ..\packages\Serilog.Sinks.Console.3.1.1\lib\net45\Serilog.Sinks.Console.dll + True + + + ..\packages\Serilog.Sinks.File.3.1.0\lib\net45\Serilog.Sinks.File.dll + True + + + ..\packages\Serilog.Sinks.TextWriter.2.1.0\lib\net45\Serilog.Sinks.TextWriter.dll + True + + + ..\packages\SerilogTimings.2.2.0\lib\net45\SerilogTimings.dll + True + diff --git a/Vocaluxe/packages.config b/Vocaluxe/packages.config index 437d7321..01998c23 100644 --- a/Vocaluxe/packages.config +++ b/Vocaluxe/packages.config @@ -1,5 +1,12 @@  + + + + + + + diff --git a/VocaluxeLib/IBasic.cs b/VocaluxeLib/IBasic.cs index fd779e59..d730db8b 100644 --- a/VocaluxeLib/IBasic.cs +++ b/VocaluxeLib/IBasic.cs @@ -19,6 +19,7 @@ using System; using System.Collections.Generic; using System.Collections.ObjectModel; using System.Drawing; +using System.Runtime.CompilerServices; using VocaluxeLib.Draw; using VocaluxeLib.Game; using VocaluxeLib.Menu; @@ -167,9 +168,12 @@ namespace VocaluxeLib public interface ILog { - void LogError(string errorText, bool showMsg = false, bool exit = false); - void LogDebug(string text); - void LogSongInfo(string text); + void LogError(Exception exeption, string errorText, bool showMsg = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues); + void LogError(string errorText, bool showMsg = false, bool exit = false, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues); + void LogDebug(string text, [CallerMemberName] string callerMethodeName = "", [CallerFilePath] string callerFilePath = "", [CallerLineNumber] int callerLineNumer = -1, params object[] propertyValues); + void LogSongWarning(string text, params object[] propertyValues); + void LogSongError(Exception exception, string text, params object[] propertyValues); + void LogSongError(string text, params object[] propertyValues); } public interface IFonts diff --git a/VocaluxeLib/Songs/CSongLoader.cs b/VocaluxeLib/Songs/CSongLoader.cs index b2374e1d..17a7bc7a 100644 --- a/VocaluxeLib/Songs/CSongLoader.cs +++ b/VocaluxeLib/Songs/CSongLoader.cs @@ -69,30 +69,7 @@ namespace VocaluxeLib.Songs _Song.FileName = Path.GetFileName(filePath); return true; } - - /// - /// Logs a given message with file name and line# - /// - /// Message - /// True prepends "Error: "; False prepends "Warning: " - /// Adds line# - private void _LogMsg(string msg, bool error, bool withLineNr) - { - msg = (error ? "Error: " : "Warning: ") + msg; - if (withLineNr) - msg += " in line #" + _LineNr; - CBase.Log.LogSongInfo(msg + " (" + Path.Combine(_Song.Folder, _Song.FileName) + ")"); - } - - private void _LogError(string msg, bool withLineNr = true) - { - _LogMsg(msg, true, withLineNr); - } - - private void _LogWarning(string msg, bool withLineNr = true) - { - _LogMsg(msg, false, withLineNr); - } + public bool ReadHeader(bool useSetEncoding = false) { @@ -144,7 +121,8 @@ namespace VocaluxeLib.Songs if (value == "") { _Song.UnknownTags.Add(line); - _LogWarning("Empty value skipped"); + CBase.Log.LogSongWarning("[{SongFileName}] Empty value skipped", _Song.FileName); + continue; } @@ -157,7 +135,7 @@ namespace VocaluxeLib.Songs { if (useSetEncoding) { - _LogWarning("Duplicate encoding ignored"); + CBase.Log.LogSongWarning("[{SongFileName}] Duplicate encoding ignored", _Song.FileName); continue; } sr.Dispose(); @@ -203,7 +181,7 @@ namespace VocaluxeLib.Songs } else { - _LogError("Can't find audio file: " + Path.Combine(_Song.Folder, value)); + CBase.Log.LogSongError("[{SongFileName}] Can't find audio file: {AudioFile}", _Song.FileName, Path.Combine(_Song.Folder, value)); return false; } break; @@ -214,19 +192,19 @@ namespace VocaluxeLib.Songs headerFlags |= EHeaderFlags.BPM; } else - _LogWarning("Invalid BPM value"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid BPM value: {Value}", _Song.FileName, value); break; case "EDITION": if (value.Length > 1) _Song.Editions.Add(value); else - _LogWarning("Invalid edition"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid edition: {Value}", _Song.FileName, value); break; case "GENRE": if (value.Length > 1) _Song.Genres.Add(value); else - _LogWarning("Invalid genre"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid genre: {Value}", _Song.FileName, value); break; case "ALBUM": _Song.Album = value; @@ -236,13 +214,13 @@ namespace VocaluxeLib.Songs if (value.Length == 4 && int.TryParse(value, out num) && num > 0) _Song.Year = value; else - _LogWarning("Invalid year"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid year: {Value}", _Song.FileName, value); break; case "LANGUAGE": if (value.Length > 1) _Song.Languages.Add(_UnifyLanguage(value)); else - _LogWarning("Invalid language"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid language: {Value}", _Song.FileName, value); break; case "COMMENT": if (!String.IsNullOrEmpty(_Song._Comment)) @@ -253,49 +231,49 @@ namespace VocaluxeLib.Songs if (CHelper.TryParse(value, out _Song.Gap)) _Song.Gap /= 1000f; else - _LogWarning("Invalid gap"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid gap: {Value}", _Song.FileName, value); break; case "COVER": if (File.Exists(Path.Combine(_Song.Folder, value))) _Song.CoverFileName = value; else - _LogWarning("Can't find cover file: " + Path.Combine(_Song.Folder, value)); + CBase.Log.LogSongWarning("[{SongFileName}] Can't find cover file: {MissingFile}", _Song.FileName, Path.Combine(_Song.Folder, value)); break; case "BACKGROUND": if (File.Exists(Path.Combine(_Song.Folder, value))) _Song.BackgroundFileNames.Add(value); else - _LogWarning("Can't find background file: " + Path.Combine(_Song.Folder, value)); + CBase.Log.LogSongWarning("[{SongFileName}] Can't find background file: {MissingFile}", _Song.FileName, Path.Combine(_Song.Folder, value)); break; case "VIDEO": if (File.Exists(Path.Combine(_Song.Folder, value))) _Song.VideoFileName = value; else - _LogWarning("Can't find video file: " + Path.Combine(_Song.Folder, value)); + CBase.Log.LogSongWarning("[{SongFileName}] Can't find video file: {MissingFile}", _Song.FileName, Path.Combine(_Song.Folder, value)); break; case "VIDEOGAP": if (!CHelper.TryParse(value, out _Song.VideoGap)) - _LogWarning("Invalid videogap"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid videogap: {Value}", _Song.FileName, value); break; case "VIDEOASPECT": if (!CHelper.TryParse(value, out _Song.VideoAspect, true)) - _LogWarning("Invalid videoaspect"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid videoaspect: {Value}", _Song.FileName, value); break; case "START": if (!CHelper.TryParse(value, out _Song.Start)) - _LogWarning("Invalid start"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid start: {Value}", _Song.FileName, value); break; case "END": if (CHelper.TryParse(value, out _Song.Finish)) _Song.Finish /= 1000f; else - _LogWarning("Invalid end"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid end: {Value}", _Song.FileName, value); break; case "PREVIEWSTART": if (CHelper.TryParse(value, out _Song.Preview.StartTime) && _Song.Preview.StartTime >= 0f) _Song.Preview.Source = EDataSource.Tag; else - _LogWarning("Invalid previewstart"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid previewstart: {Value}", _Song.FileName, value); break; case "PREVIEW": if (CHelper.TryParse(value, out _Song.Preview.StartTime) && _Song.Preview.StartTime >= 0f) @@ -305,19 +283,19 @@ namespace VocaluxeLib.Songs _Song.Preview.Source = EDataSource.Tag; } else - _LogWarning("Invalid previewstart"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid previewstart: {Value}", _Song.FileName, value); break; case "MEDLEYSTARTBEAT": if (int.TryParse(value, out _Song.Medley.StartBeat)) headerFlags |= EHeaderFlags.MedleyStartBeat; else - _LogWarning("Invalid medleystartbeat"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid medleystartbeat: {Value}", _Song.FileName, value); break; case "MEDLEYENDBEAT": if (int.TryParse(value, out _Song.Medley.EndBeat)) headerFlags |= EHeaderFlags.MedleyEndBeat; else - _LogWarning("Invalid medleyendbeat"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid medleyendbeat: {Value}", _Song.FileName, value); break; case "ENDSHORT": if ((headerFlags & EHeaderFlags.BPM) != 0) @@ -329,7 +307,7 @@ namespace VocaluxeLib.Songs _Song.ShortEnd.Source = EDataSource.Tag; } else - _LogWarning("Invalid shortendbeat"); + CBase.Log.LogSongWarning("[{SongFileName}] Invalid shortendbeat: {Value}", _Song.FileName, value); } break; case "CALCMEDLEY": @@ -364,7 +342,7 @@ namespace VocaluxeLib.Songs else { _Song.UnknownTags.Add(line); - _LogWarning("Unknown tag: #" + identifier); + CBase.Log.LogSongWarning("[{SongFileName}] Unknown tag: #{Identifier}", _Song.FileName, identifier); } break; @@ -374,31 +352,32 @@ namespace VocaluxeLib.Songs if (sr.EndOfStream) { //No other data then header - _LogError("Lyrics/Notes missing", false); + CBase.Log.LogSongError("[{SongFileName}] Lyrics/Notes missing", _Song.FileName); + return false; } if ((headerFlags & EHeaderFlags.Title) == 0) { - _LogError("Title tag missing", false); + CBase.Log.LogSongError("[{SongFileName}] Title tag missing", _Song.FileName); return false; } if ((headerFlags & EHeaderFlags.Artist) == 0) { - _LogError("Artist tag missing", false); + CBase.Log.LogSongError("[{SongFileName}] Artist tag missing", _Song.FileName); return false; } if ((headerFlags & EHeaderFlags.MP3) == 0) { - _LogError("MP3 tag missing", false); + CBase.Log.LogSongError("[{SongFileName}] MP3 tag missing", _Song.FileName); return false; } if ((headerFlags & EHeaderFlags.BPM) == 0) { - _LogError("BPM tag missing", false); + CBase.Log.LogSongError("[{SongFileName}] BPM tag missing", _Song.FileName); return false; } @@ -407,7 +386,7 @@ namespace VocaluxeLib.Songs { if (_Song.Medley.StartBeat > _Song.Medley.EndBeat) { - _LogError("MedleyStartBeat is bigger than MedleyEndBeat in file", false); + CBase.Log.LogSongError("[{SongFileName}] MedleyStartBeat is bigger than MedleyEndBeat in file: {StartBeat} > {EndBeat}", _Song.FileName, _Song.Medley.StartBeat > _Song.Medley.EndBeat); headerFlags = headerFlags - EHeaderFlags.MedleyStartBeat - EHeaderFlags.MedleyEndBeat; } } @@ -433,7 +412,7 @@ namespace VocaluxeLib.Songs { if (sr != null) sr.Dispose(); - _LogError("Error reading txt header" + e.Message, false); + CBase.Log.LogSongError(e, "[{SongFileName}] Error reading txt header with Message: {ExceptionMessage}", e.Message, _Song.FileName); return false; } _Song.Encoding = sr.CurrentEncoding; @@ -530,7 +509,7 @@ namespace VocaluxeLib.Songs if (!File.Exists(filePath)) { - _LogError("The file does not exist", false); + CBase.Log.LogSongError("[{SongFileName}] The file songfile does not exist", _Song.FileName); return false; } @@ -579,7 +558,7 @@ namespace VocaluxeLib.Songs if (!int.TryParse(line, out player)) { - _LogError("Wrong or missing number after \"P\""); + CBase.Log.LogSongError("[{SongFileName}] Wrong or missing number after \"P\" (in line {LineNr})", _Song.FileName, _LineNr); return false; } currentBeat = 0; @@ -593,25 +572,25 @@ namespace VocaluxeLib.Songs { if (noteData.Length == 3) { - _LogWarning("Ignored note without text"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored note without text (in line {LineNr})", _Song.FileName, _LineNr); changesMade.NoTextNoteCt++; continue; } - _LogError("Invalid note found"); + CBase.Log.LogSongError("[{SongFileName}] Invalid note found (in line {LineNr}): {noteData}", _Song.FileName, _LineNr, noteData); sr.Dispose(); return false; } int tone; if (!int.TryParse(noteData[0], out beat) || !int.TryParse(noteData[1], out length) || !int.TryParse(noteData[2], out tone)) { - _LogError("Invalid note found (non-numeric values)"); + CBase.Log.LogSongError("[{SongFileName}] Invalid note found (non-numeric values) (in line {LineNr}): {noteData}", _Song.FileName, _LineNr, noteData); sr.Dispose(); return false; } string text = noteData[3].TrimMultipleWs(); if (text == "") { - _LogWarning("Ignored note without text"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored note without text (in line {LineNr})", _Song.FileName, _LineNr); changesMade.NoTextNoteCt++; continue; } @@ -622,12 +601,12 @@ namespace VocaluxeLib.Songs changesMade.ZeroLengthNoteCt++; if (_CurrentReadMode == ENoteReadMode.Normal && changesMade.ZeroLengthNoteCt > _MaxZeroNoteCt && changesMade.OverlapNoteCt <= _MaxOverlapNoteCt) { - _LogWarning("Found more than " + _MaxZeroNoteCt + " note with length < 1. Trying alternative read mode."); + CBase.Log.LogSongWarning("[{SongFileName}] Found more than {MaxZeroNoteCt} notes with length < 1. Trying alternative read mode.", _Song.FileName, _MaxZeroNoteCt); _CurrentReadMode = ENoteReadMode.ZeroBased; sr.Dispose(); return ReadNotes(true); } - _LogWarning("Ignored note with length < 1"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored note with length < 1 (in line {LineNr})", _Song.FileName, _LineNr); } else { @@ -656,13 +635,13 @@ namespace VocaluxeLib.Songs changesMade.OverlapNoteCt++; if (changesMade.OverlapNoteCt > _MaxOverlapNoteCt && _CurrentReadMode == ENoteReadMode.ZeroBased) { - _LogWarning("Found more than " + _MaxOverlapNoteCt + " overlapping notes. Using standard mode."); + CBase.Log.LogSongWarning("[{SongFileName}] Found more than {MaxOverlapNoteCt} overlapping notes. Using standard mode.", _Song.FileName, _MaxOverlapNoteCt); _CurrentReadMode = ENoteReadMode.OneBased; sr.Dispose(); return ReadNotes(true); } } - _LogWarning("Ignored note for player " + (curPlayer + 1) + " because it overlaps with other note"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored note for player {CurrentPlayerNumber} because it overlaps with other note (in line {LineNr})", _Song.FileName, (curPlayer + 1), _LineNr); } } } @@ -671,13 +650,13 @@ namespace VocaluxeLib.Songs string[] lineBreakData = line.Split(splitChars); if (lineBreakData.Length < 1) { - _LogError("Invalid line break found (No beat)"); + CBase.Log.LogSongError("[{SongFileName}] Invalid line break found (No beat) (in line {LineNr}): {LineBreakData}", _Song.FileName, _LineNr, lineBreakData); sr.Dispose(); return false; } if (!int.TryParse(lineBreakData[0], out beat)) { - _LogError("Invalid line break found (Non-numeric value)"); + CBase.Log.LogSongError("[{SongFileName}] Invalid line break found (Non-numeric value) (in line {LineNr}): {LineBreakData}", _Song.FileName, _LineNr, lineBreakData); sr.Dispose(); return false; } @@ -687,7 +666,7 @@ namespace VocaluxeLib.Songs beat += currentBeat; if (lineBreakData.Length < 2 || !int.TryParse(lineBreakData[1], out length)) { - _LogWarning("Missing line break length"); + CBase.Log.LogSongWarning("[{SongFileName}] Missing line break length (in line {LineNr}):{LineBreakData}", _Song.FileName, _LineNr, lineBreakData); changesMade.NoLengthBreakCt++; currentBeat = beat; } @@ -697,7 +676,8 @@ namespace VocaluxeLib.Songs if (lastNote != null && beat <= lastNote.EndBeat) { - _LogWarning("Line break is before previous note end. Adjusted."); + CBase.Log.LogSongWarning("[{SongFileName}] Line break is before previous note end. Adjusted. (in line {LineNr})", _Song.FileName, _LineNr); + changesMade.AjustedBreakCt++; if (_Song.Relative) currentBeat += lastNote.EndBeat - beat + 1; @@ -706,7 +686,7 @@ namespace VocaluxeLib.Songs if (beat < 1) { - _LogWarning("Ignored line break because position is < 1"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored line break because position is < 1 (in line {LineNr})", _Song.FileName, _LineNr); changesMade.InvalidPosBreakCt++; } else @@ -714,12 +694,12 @@ namespace VocaluxeLib.Songs foreach (int curPlayer in player.GetSetBits()) { if (!_NewSentence(curPlayer, beat)) - _LogWarning("Ignored line break for player " + (curPlayer + 1) + " (Overlapping or duplicate)"); + CBase.Log.LogSongWarning("[{SongFileName}] Ignored line break for player {CurPlayerNr} (Overlapping or duplicate) (in line {LineNr})", _Song.FileName, (curPlayer + 1) , _LineNr); } } break; default: - _LogError("Unexpected or missing character (" + tag + ")"); + CBase.Log.LogSongError("[{SongFileName}] Unexpected or missing character ({Tag})", _Song.FileName, tag); return false; } } @@ -729,13 +709,13 @@ namespace VocaluxeLib.Songs CVoice voice = _Song.Notes.GetVoice(i); int emptyLines = voice.RemoveEmptyLines(); if (emptyLines > 0) - _LogWarning("Removed " + emptyLines + " empty lines from P" + ". This often indicates a problem with the line breaks in the file", false); + CBase.Log.LogSongWarning("[{SongFileName}] Removed {NumEmptyLines} empty lines from P .This often indicates a problem with the line breaks in the file", _Song.FileName, emptyLines); voice.UpdateTimings(); } } catch (Exception e) { - _LogError("An unhandled exception occured (" + e.Message + ")"); + CBase.Log.LogSongError(e, "[{SongFileName}] An unhandled exception occured: {ExceptionMessage}", _Song.FileName, e.Message); if (sr != null) sr.Dispose(); return false; @@ -752,7 +732,7 @@ namespace VocaluxeLib.Songs } catch (Exception e) { - _LogError("An unhandled exception occured (" + e.Message + ")", false); + CBase.Log.LogSongError(e, "[{SongFileName}] An unhandled exception occured: {ExceptionMessage}", _Song.FileName, e.Message); return false; } diff --git a/VocaluxeTests/PartyModeTests.cs b/VocaluxeTests/PartyModeTests.cs index c0363123..4108e8df 100644 --- a/VocaluxeTests/PartyModeTests.cs +++ b/VocaluxeTests/PartyModeTests.cs @@ -46,7 +46,7 @@ namespace VocaluxeTests public void TestRoundGeneration() { CBase.Game = new CBGame(); - CLog.Init(); + CLog.Init(CSettings.FolderNameLogs); CBase.Log = new CBlog(); for (int i = 0; i < 10; i++) {