diff --git a/ETWAnalyzer/Commands/DumpCommand.cs b/ETWAnalyzer/Commands/DumpCommand.cs index 50635b54..ba0c6a26 100644 --- a/ETWAnalyzer/Commands/DumpCommand.cs +++ b/ETWAnalyzer/Commands/DumpCommand.cs @@ -196,6 +196,7 @@ class DumpCommand : ArgParser " -CutStack dd-yy Remove the first dd lines of the stack. To display all stack frames use \"-CutStack 0-\". Print yy lines or all if -yy is omitted." + Environment.NewLine + " E.g. -CutStack -50 will display the first 50 lines of a stack trace." + Environment.NewLine + " -SortBy [Time / Default] Sorts exceptions by time or use default grouping." + Environment.NewLine + + " -ShowTime Show the time of exception when a -Type filter is active. Time format is controlled by -TimeFmt flag. By default no time is printed." +Environment.NewLine + " For other options [-ZeroTime ..] [-recursive] [-csv] [-NoCSVSeparator] [-TimeFmt] [-NoCmdLine] [-TestsPerRun] [-SkipNTests] [-TestRunIndex] [-TestRunCount] [-MinMaxMsTestTimes] [-ProcessName/pn] " + Environment.NewLine + " [-NewProcess] [-CmdLine] [-ShowFullFileName] refer to help of TestRun, Process and CPU (-ProcessFmt, -ShowModuleInfo). Run \'EtwAnalyzer -help dump\' to get more infos." + Environment.NewLine; @@ -355,9 +356,9 @@ class DumpCommand : ArgParser " ETWAnalyzer -dump CPU -fd xxx.json -topN 2 -topNMethods 50" + Environment.NewLine + "[green]Show common Antivirus drivers vendors besides module information for all modules for which no symbols could be resolved. The dll/driver name is then the \"method\" name.[/green]" + Environment.NewLine + " ETWAnalyzer -dump CPU -fd xxx.json -methods *.dll*;*.sys* -ShowModuleInfo Driver" + Environment.NewLine + - "[green]Show CPU consumption of all executables which match *Trend Micro* in module name, path, product name or description." + Environment.NewLine + + "[green]Show CPU consumption of all executables which match *Trend Micro* in module name, path, product name or description.[/green]" + Environment.NewLine + " ETWAnalyzer -dump CPU -fd xxx.json -smi \"*Trend Micro*\" " + Environment.NewLine + - "[green]Show CPU consumption of *Trend Micro* in module name, path, product name or description at method level" + Environment.NewLine + + "[green]Show CPU consumption of *Trend Micro* in module name, path, product name or description at method level[/green]" + Environment.NewLine + " ETWAnalyzer -dump CPU -fd xxx.json -smi \"*Trend Micro*\" -methods *" + Environment.NewLine + "[green]Show all Import methods but skip file methods. Take only last 35 characters of method and show first last occurrence of method in trace time to relate with WPA timeline.[/green]" + Environment.NewLine + " ETWAnalyzer -dump CPU -methods *import*;!*file* -CutMethod -35 -fld s" + Environment.NewLine + @@ -390,8 +391,10 @@ class DumpCommand : ArgParser " ETWAnalyzer -dump Exception -fd C:\\Extract\\TestRuns -smi" + Environment.NewLine + "[green]Show call stack of all SQLiteExceptions of one or all extracted files. Use -ProcessName and/or -CmdLine to focus on specific process/es. Use -CSV to store data.[/green]" + Environment.NewLine + " ETWAnalyzer -dump Exception -fd xx.json -type *SQLiteException* -ShowStack" + Environment.NewLine + + "[green]Show call stack of all SQLiteExceptions in time appearance. Use -ProcessName and/or -CmdLine to focus on specific process/es. Use -CSV to store data.[/green]" + Environment.NewLine + + " ETWAnalyzer -dump Exception -fd xx.json -type *SQLiteException* -sortBy Time" + Environment.NewLine + "[green]Show all exception times of all extracted files in current folder in UTC time. Default is Local time of the customer.[/green]" + Environment.NewLine + - " ETWAnalyzer -dump Exception -type * -timefmt utc" + Environment.NewLine + + " ETWAnalyzer -dump Exception -type * -ShowTime -timefmt utc" + Environment.NewLine + "[green]Dump all TimeoutExceptions after the first occurrence of method ShowShutdownWindow and write them to a CSV file.[/green]" + Environment.NewLine + " ETWAnalyzer -dump Exception -Type* timeout* -TimeFmt s -ZeroTime First *ShowShutdownWindow* -MinMaxExTime 0 -CSV Exceptions.csv" + Environment.NewLine + "[green]Show stacks of all exceptions of all extracted files in current folder. Print process start/stop/duration besides process name.[/green]" + Environment.NewLine + @@ -636,6 +639,7 @@ internal enum ZeroTimeModes public const int MaxMessageLength = 500; public int MaxMessage { get; private set; } = MaxMessageLength; public MinMaxRange MinMaxExTimeS { get; private set; } = new MinMaxRange(); + public bool ShowTime { get; private set; } // Dump Process specific Flags public bool ShowAllProcesses { get; private set; } @@ -700,7 +704,7 @@ internal enum ZeroTimeModes public Extract.FileIO.FileIOStatistics.FileOperation FileOperation { get; private set; } - // Shared by -dump File and Dns + // Shared by -dump File and Dns public bool ShowDetails { get; private set; } // Dump ThreadPool specific Flags @@ -1134,6 +1138,9 @@ public override void Parse() case "-ss": ShowStack = true; break; + case "-showtime": + ShowTime = true; + break; case "-totalmemory": case "-tm": TotalMemory = true; @@ -1547,9 +1554,11 @@ public override void Run() CommandLineFilter = CmdLineFilter, NewProcessFilter = NewProcess, UsePrettyProcessName = UsePrettyProcessName, - + SortOrder = SortOrder, ShowModuleInfo = ShowModuleInfo, ShowModuleFilter = ShowModuleFilter, + + ShowTime = ShowTime, TypeFilter = TypeFilter, MessageFilter = MessageFilter, StackFilter = StackFilter, @@ -1562,7 +1571,6 @@ public override void Run() ZeroTimeMode = ZeroTimeMode, ZeroTimeFilter = ZeroTimeFilter, ZeroTimeProcessNameFilter = ZeroTimeProcessNameFilter, - SortOrder = SortOrder, }; break; case DumpCommands.Memory: diff --git a/ETWAnalyzer/EventDump/DumpDns.cs b/ETWAnalyzer/EventDump/DumpDns.cs index c6e9c79d..4de4470a 100644 --- a/ETWAnalyzer/EventDump/DumpDns.cs +++ b/ETWAnalyzer/EventDump/DumpDns.cs @@ -40,7 +40,10 @@ class DumpDns : DumpFileDirBase public KeyValuePair> DnsQueryFilter { get; internal set; } = new KeyValuePair>(null, x => true); public bool ShowProcess { get; internal set; } - List myUTestData = null; + /// + /// Unit testing only. ReadFileData will return this list instead of real data + /// + internal List myUTestData = null; public override List ExecuteInternal() { diff --git a/ETWAnalyzer/EventDump/DumpExceptions.cs b/ETWAnalyzer/EventDump/DumpExceptions.cs index 44942731..c18ac25d 100644 --- a/ETWAnalyzer/EventDump/DumpExceptions.cs +++ b/ETWAnalyzer/EventDump/DumpExceptions.cs @@ -7,8 +7,12 @@ using ETWAnalyzer.Extract.Modules; using ETWAnalyzer.Infrastructure; using ETWAnalyzer.ProcessTools; +using Microsoft.Diagnostics.Tracing.Parsers.FrameworkEventSource; +using Microsoft.Windows.EventTracing.Events; using System; using System.Collections.Generic; +using System.Diagnostics; +using System.IO; using System.Linq; namespace ETWAnalyzer.EventDump @@ -26,11 +30,23 @@ class DumpExceptions : DumpFileDirBase public bool NoCmdLine { get; internal set; } public MinMaxRange MinMaxExTimeS { get; internal set; } public int MaxMessage { get; internal set; } = DumpCommand.MaxMessageLength; + + + /// + /// Currently we only support Time as different sort order. + /// public DumpCommand.SortOrders SortOrder { get; internal set; } /// - /// Show module file name and version. In cpu total mode also exe version. + /// By default time is omitted. When you add -ShowTime exception time is printed. /// + public bool ShowTime { get; internal set; } + + string myPreviousProcess = null; + + string myPreviousMsg = null; + + string myPreviousType = null; public class MatchData { @@ -91,8 +107,26 @@ public class MatchData /// public string BaseLine { get; internal set; } + /// + /// Show module file name and version. In cpu total mode also exe version. + /// public ModuleDefinition Module { get; internal set; } + public MatchData Clone() + { + return new MatchData + { + Message = Message, + Type = Type, + TimeStamp = TimeStamp, + Process = Process, + Stack = Stack, + Module = Module, + SourceFile = SourceFile, + ZeroTimeS = ZeroTimeS, + BaseLine = BaseLine, + }; + } } /// @@ -208,8 +242,7 @@ bool IsMatchingException(ExceptionEventForQuery arg) } } - - private void PrintMatches(List matches) + internal void PrintMatches(List matches) { foreach (var byFile in matches.GroupBy(x => x.SourceFile).OrderBy(x => x.First().PerformedAt)) { @@ -225,7 +258,7 @@ private void PrintMatches(List matches) } } } - + private void PrintByTime(IGrouping byFile) { List matches = new List(); @@ -241,13 +274,13 @@ private void PrintByTime(IGrouping byFile) TimeFormats.HereTime => 12, _ => 100, }; - const int expTypeWidth = 60; + const int expTypeWidth = 40; string excheader = "Exception Type"; - const int processWidth = 60; + const int processWidth = 34; string processheader = "Process"; const int expmsgWidth = 90; string expmsgheader = "Exception Message"; - ColorConsole.WriteEmbeddedColorLine($"{timeHeader.WithWidth(timeWidth)}[magenta]{processheader.WithWidth(processWidth)}[/magenta] [green]{excheader.WithWidth(expTypeWidth)}[/green] {expmsgheader.WithWidth(expmsgWidth)}"); + ColorConsole.WriteEmbeddedColorLine($"{timeHeader.WithWidth(timeWidth)} [magenta]{processheader.WithWidth(processWidth)}[/magenta] [green]{excheader.WithWidth(expTypeWidth)}[/green] {expmsgheader.WithWidth(expmsgWidth)}"); string previousExceptionType = null; string previousProcess = null; @@ -260,32 +293,31 @@ private void PrintByTime(IGrouping byFile) string currentMessage = item.Message; string currentExceptiontype = item.Type; string tobePrintedMsg = currentMessage; - string tobePrinted = currentProcess; string tobePrintedType = currentExceptiontype; string tobePrintedProcess = currentProcess; if (currentProcess == previousProcess) { - tobePrinted = "..."; + tobePrintedProcess = "..."; } - string replacedProcess = replaceToCurrentProcess(item.Process.GetProcessWithId(UsePrettyProcessName)); + string replacedProcess = ReplaceToCurrentProcess(item.Process.GetProcessWithId(UsePrettyProcessName)); previousProcess = currentProcess; if (currentMessage == previousMessage) { tobePrintedMsg = "..."; } - string replacedMsg = replaceToCurrentMsg(item.Message); + string replacedMsg = ReplaceToCurrentMsg(item.Message); previousMessage = currentMessage; if (currentExceptiontype == previousExceptionType) { tobePrintedType = "..."; } - string replacedType = replaceToCurrentType(item.Type); + string replacedType = ReplaceToCurrentType(item.Type); previousExceptionType = currentExceptiontype; - if ((replacedType != "...") || (tobePrinted != "...")) + if ((replacedType != "...") || (tobePrintedProcess != "...")) { replacedProcess = tobePrintedProcess; } @@ -298,8 +330,8 @@ private void PrintByTime(IGrouping byFile) } } - string myPreviousProcess = null; - string replaceToCurrentProcess(string currentProcess) + + string ReplaceToCurrentProcess(string currentProcess) { if (currentProcess == myPreviousProcess) { @@ -311,8 +343,8 @@ string replaceToCurrentProcess(string currentProcess) return currentProcess; } } - string myPreviousMsg = null; - string replaceToCurrentMsg(string currentMsg) + + string ReplaceToCurrentMsg(string currentMsg) { if (currentMsg == myPreviousMsg) { @@ -324,8 +356,8 @@ string replaceToCurrentMsg(string currentMsg) return currentMsg; } } - string myPreviousType = null; - string replaceToCurrentType(string currentType) + + string ReplaceToCurrentType(string currentType) { if (currentType == myPreviousType) { @@ -342,10 +374,14 @@ private void PrintByFileAndProcess(List matches) { foreach (var processExceptions in matches.GroupBy(x => x.Process)) { - ModuleDefinition processModule = processExceptions.First().Module; - string moduleInfo = processModule!= null ? GetModuleString(processModule, true) : ""; - ColorConsole.WriteEmbeddedColorLine($"[magenta]{processExceptions.Key.GetProcessWithId(UsePrettyProcessName)} {processExceptions.Key.StartStopTags}[/magenta] {(NoCmdLine ? String.Empty : processExceptions.Key.CommandLineNoExe)}", ConsoleColor.DarkCyan, true); - ColorConsole.WriteEmbeddedColorLine($"[red]{moduleInfo}[/red]"); + MatchData matchData = processExceptions.First(); + ModuleDefinition processModule = matchData.Module; + string moduleInfo = processModule != null ? GetModuleString(processModule, true) : ""; + + + ColorConsole.WriteEmbeddedColorLine($"[magenta]{processExceptions.Key.GetProcessWithId(UsePrettyProcessName)} {GetProcessTags(processExceptions.Key, matchData.SessionStart.AddSeconds(matchData.ZeroTimeS))}[/magenta] {(NoCmdLine ? String.Empty : processExceptions.Key.CommandLineNoExe)}", ConsoleColor.DarkCyan, true); + ColorConsole.WriteEmbeddedColorLine($"[red] {moduleInfo}[/red]"); + foreach (var byType in processExceptions.GroupBy(x => x.Type)) { ColorConsole.WriteLine($"\t{byType.Key}", ConsoleColor.Green); @@ -364,20 +400,23 @@ private void PrintByFileAndProcess(List matches) } } - foreach (MatchData data in byStack.OrderBy(x => x.TimeStamp)) + if (ShowTime) { - if (TypeFilter.Key != null || MessageFilter.Key != null || StackFilter.Key != null) + foreach (MatchData data in byStack.OrderBy(x => x.TimeStamp)) { - if (TimeFormatOption == TimeFormats.s || TimeFormatOption == TimeFormats.second) + if (TypeFilter.Key != null || MessageFilter.Key != null || StackFilter.Key != null) { - ColorConsole.WriteLine($"\t\t\t{GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormatOption)}"); - } - else - { - ColorConsole.WriteLine($"\t\t\t{GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormatOption)} {GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormats.s)}"); + if (TimeFormatOption == TimeFormats.s || TimeFormatOption == TimeFormats.second) + { + ColorConsole.WriteLine($"\t\t\t{GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormatOption)}"); + } + else + { + ColorConsole.WriteLine($"\t\t\t{GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormatOption)} {GetDateTimeString(data.TimeStamp, data.SessionStart, TimeFormats.s)}"); + } } } - } + } } } } diff --git a/ETWAnalyzer_uTest/EventDump/DumpExceptionTests.cs b/ETWAnalyzer_uTest/EventDump/DumpExceptionTests.cs new file mode 100644 index 00000000..9b09c809 --- /dev/null +++ b/ETWAnalyzer_uTest/EventDump/DumpExceptionTests.cs @@ -0,0 +1,194 @@ +using ETWAnalyzer.EventDump; +using ETWAnalyzer.Extract; +using ETWAnalyzer_uTest.TestInfrastructure; +using Microsoft.Windows.EventTracing; +using System; +using System.Collections.Generic; +using System.Drawing; +using System.IO; +using System.Linq; +using System.Runtime.Intrinsics.Arm; +using System.Text; +using System.Threading.Tasks; +using Xunit; +using Xunit.Abstractions; + +namespace ETWAnalyzer_uTest.EventDump +{ + public class DumpExceptionTests + { + const string Exe1 = "Exe1.exe"; + const string Exe1Arg = "-noarg"; + const int Exe1Pid = 1000; + + const string Baseline = "v1.0"; + const string ExceptionMessage1 = "First"; + const string ExceptionType1 = "InvalidOperationExeption"; + const string Stacktrace1 = "no stack"; + const string TestCase1 = "ExceptionTest"; + const string Process = "Process"; + + + static char[] myNewLineSplitChars = Environment.NewLine.ToArray(); + + private ITestOutputHelper myWriter; + public DumpExceptionTests(ITestOutputHelper myWriter) + { + this.myWriter = myWriter; + } + + [Fact] + public void Print_Default() + { + using var testOutput = new ExceptionalPrinter(myWriter); + + DumpExceptions printer = new DumpExceptions(); + + List exceptions = CreateTestData(); + + StringWriter writer = new StringWriter(); + Console.SetOut(writer); + + printer.PrintMatches(exceptions); + + testOutput.Add(writer.ToString()); + + string[] lines = writer.ToString().Split(myNewLineSplitChars, StringSplitOptions.RemoveEmptyEntries); + var lines1 = lines[0]; + + Assert.Equal(4, lines.Length); + Assert.Contains(Baseline, lines[0]); + Assert.Contains(Exe1, lines[1]); + Assert.Contains(ExceptionType1, lines[2]); + Assert.Contains(ExceptionMessage1, lines[3]); + } + + + [Fact] + public void Print_Stacks() + { + using var testOutput = new ExceptionalPrinter(myWriter); + + DumpExceptions printer = new DumpExceptions(); + printer.ShowStack = true; + + List exceptions = CreateTestData(); + + StringWriter writer = new StringWriter(); + Console.SetOut(writer); + + printer.PrintMatches(exceptions); + + testOutput.Add(writer.ToString()); + + string[] lines = writer.ToString().Split(myNewLineSplitChars, StringSplitOptions.RemoveEmptyEntries); + + Assert.Equal(5, lines.Length); + Assert.Contains(Baseline, lines[0]); + Assert.Contains(Exe1, lines[1]); + Assert.Contains(ExceptionType1, lines[2]); + Assert.Contains(ExceptionMessage1, lines[3]); + Assert.Contains(Stacktrace1, lines[4]); + } + + [Fact] + public void Print_ShowTime() + { + using var testOutput = new ExceptionalPrinter(myWriter); + + DumpExceptions printer = new DumpExceptions(); + printer.ShowTime = true; + + List exceptions = CreateTestData(); + + StringWriter writer = new StringWriter(); + Console.SetOut(writer); + + printer.PrintMatches(exceptions); + + testOutput.Add(writer.ToString()); + + string[] lines = writer.ToString().Split(myNewLineSplitChars, StringSplitOptions.RemoveEmptyEntries); + + Assert.Equal(4, lines.Length); + Assert.Contains(Baseline, lines[0]); + Assert.Contains(Exe1, lines[1]); + Assert.Contains(ExceptionType1, lines[2]); + Assert.Contains(ExceptionMessage1, lines[3]); + } + + [Fact] + public void Print_ByTime() + { + using var testOutput = new ExceptionalPrinter(myWriter); + + DumpExceptions printer = new DumpExceptions(); + + printer.SortOrder = ETWAnalyzer.Commands.DumpCommand.SortOrders.Time; + + List exceptions = CreateTestData(); + //DumpExceptions.MatchData other = exceptions[0].Clone(); + + ETWProcess otherprocess = new ETWProcess + { + ProcessName = "Other.exe", + ProcessID = 2000, + }; + + //other.Process = otherprocess; + + //exceptions.Add(other); + + StringWriter writer = new StringWriter(); + Console.SetOut(writer); + + printer.PrintMatches(exceptions); + + testOutput.Add(writer.ToString()); + + string[] lines = writer.ToString().Split(myNewLineSplitChars, StringSplitOptions.RemoveEmptyEntries); + + Assert.Equal(3, lines.Length); + Assert.Contains(Baseline, lines[0]); + Assert.Contains(Process, lines[1]); + Assert.Contains(ExceptionMessage1, lines[2]); + } + + + List CreateTestData(int n=1) + { + ETWProcess process1 = new ETWProcess + { + CmdLine = Exe1Arg, + ProcessID = Exe1Pid, + ProcessName = Exe1, + }; + + List lret = new List() + { + new DumpExceptions.MatchData + { + Message = ExceptionMessage1, + BaseLine = Baseline, + SessionStart = new DateTimeOffset(2000,1,1,1,1,1, TimeSpan.Zero), + SourceFile = "C:\\Json1.json", + PerformedAt = new DateTime(2000,1,1), + Type = ExceptionType1, + Stack = Stacktrace1, + TestCase = TestCase1, + TimeStamp = new DateTimeOffset(2000, 1, 1, 1, 1, 5, TimeSpan.Zero), + Process = process1, + } + }; + + while( lret.Count < n) + { + var copy = lret[lret.Count-1].Clone(); + copy.TimeStamp = copy.TimeStamp.AddSeconds(1.0); + lret.Add(copy); + } + + return lret; + } + } +}