Tweak log message template to separate path from line num with ':'

rkeithhill · rkeithhill · commit 1cc9e5752dfa · 2018-11-27T22:44:38.000-07:00
This is probably a legal path char on Linux but on Windows it isn't.
Also, Pester uses a similar format: &lt;path&gt;: line &lt;num&gt;

Update PSES log analyzer to parse template.

Add some more analysis commands.
diff --git a/src/PowerShellEditorServices/Utility/PsesLogger.cs b/src/PowerShellEditorServices/Utility/PsesLogger.cs
@@ -15,7 +15,7 @@ public class PsesLogger : ILogger
         /// The standard log template for all log entries.
         /// </summary>
         private static readonly string s_logMessageTemplate =
-            "[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l} (line {CallerLineNumber}):{IndentedLogMsg:l}";
+            "[{LogLevelName:l}] tid:{ThreadId} in '{CallerName:l}' {CallerSourceFile:l}: line {CallerLineNumber}{IndentedLogMsg:l}";
 
         /// <summary>
         /// The name of the ERROR log level.
diff --git a/tools/PsesLogAnalyzer/Analyze.ps1 b/tools/PsesLogAnalyzer/Analyze.ps1
@@ -1,3 +1,47 @@
+function Get-PsesRpcNotificationMessage {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry,
+
+        # Specifies a filter for either client or server sourced notifications.  By default both are output.
+        [Parameter()]
+        [ValidateSet('Client', 'Server')]
+        [string]
+        $Source
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            if ($entry.LogMessageType -eq 'Notification') {
+                if (!$Source -or ($entry.Message.Source -eq $Source)) {
+                    $entry
+                }
+            }
+        }
+    }
+}
+
 function Get-PsesRpcMessageResponseTime {
     [CmdletBinding(DefaultParameterSetName="Path")]
     param(
@@ -31,11 +75,11 @@ function Get-PsesRpcMessageResponseTime {
         # Populate $requests hashtable with request timestamps
         $requests = @{}
         $logEntries |
-            Where-Object MessageType -match Request |
+            Where-Object LogMessageType -match Request |
             Foreach-Object { $requests[$_.Message.Id] = $_.Timestamp }
 
         $res = $logEntries |
-            Where-Object MessageType -match Response |
+            Where-Object LogMessageType -match Response |
             Foreach-Object {
                 $elapsedMilliseconds = [int]($_.Timestamp - $requests[$_.Message.Id]).TotalMilliseconds
                 [PsesLogEntryElapsed]::new($_, $elapsedMilliseconds)
@@ -44,3 +88,78 @@ function Get-PsesRpcMessageResponseTime {
         $res
     }
 }
+
+function Get-PsesScriptAnalysisCompletionTime {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*Script analysis of.*\[(?<ms>\d+)ms\]\s*$')) {
+                $elapsedMilliseconds = [int]$matches["ms"]
+                [PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
+            }
+        }
+    }
+}
+
+function Get-PsesIntelliSenseCompletionTime {
+    [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")]
+    param(
+        # Specifies a path to one or more PSES EditorServices log files.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "Path")]
+        [Alias("PSPath")]
+        [ValidateNotNullOrEmpty()]
+        [string]
+        $Path,
+
+        # Specifies PsesLogEntry objects to analyze.
+        [Parameter(Mandatory = $true, Position = 0, ParameterSetName = "PsesLogEntry", ValueFromPipeline = $true)]
+        [ValidateNotNull()]
+        [psobject[]]
+        $LogEntry
+    )
+
+    begin {
+        if ($PSCmdlet.ParameterSetName -eq "Path") {
+            $logEntries = Parse-PsesLog $Path
+        }
+    }
+
+    process {
+        if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") {
+            $logEntries = $LogEntry
+        }
+
+        foreach ($entry in $logEntries) {
+            # IntelliSense completed in 320ms. 
+            if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*IntelliSense completed in\s+(?<ms>\d+)ms.\s*$')) {
+                $elapsedMilliseconds = [int]$matches["ms"]
+                [PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds)
+            }
+        }
+    }
+}
diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1
@@ -1,6 +1,6 @@
 
 $peekBuf = $null
-$currentLineNum = 1
+$currentLineNum = 0
 $logEntryIndex = 0
 
 function Parse-PsesLog {
@@ -44,7 +44,7 @@ function Parse-PsesLog {
         $script:logEntryIndex = 0
 
         if ($OldLogFormat) {
-            # Example old log entry start
+            # Example old log entry start:
             # 2018-11-15 19:49:06.979 [NORMAL] C:\PowerShellEditorServices\src\PowerShellEditorServices.Host\EditorServicesHost.cs: In method 'StartLogging', line 160:
             $logEntryRegex =
                 [regex]::new(
@@ -53,10 +53,10 @@ function Parse-PsesLog {
         }
         else {
             # Example new log entry start:
-            # 2018-11-24 12:26:58.302 [DIAGNOSTIC] tid:28 in 'ReadMessage' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageReader.cs:114:
+            # 2018-11-24 12:26:58.302 [DIAGNOSTIC] tid:28 in 'ReadMessage' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageReader.cs: line 114
             $logEntryRegex =
                 [regex]::new(
-                    '^(?<ts>[^\[]+)\[(?<lev>([^\]]+))\]\s+tid:(?<tid>\d+)\s+in\s+''(?<meth>\w+)''\s+(?<file>..[^:]+):(?<line>\d+)',
+                    '^(?<ts>[^\[]+)\[(?<lev>([^\]]+))\]\s+tid:(?<tid>\d+)\s+in\s+''(?<meth>\w+)''\s+(?<file>..[^:]+):\s+line\s+(?<line>\d+)',
                     [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase)
         }
 
@@ -101,7 +101,7 @@ function Parse-PsesLog {
             }
 
             while ($line -notmatch $logEntryRegex) {
-                Write-Warning "Ignoring line: '$line'"
+                Write-Warning "Ignoring line:${currentLineNum} '$line'"
                 $line = nextLine
             }
 
@@ -117,10 +117,10 @@ function Parse-PsesLog {
             [string]$file = $matches["file"]
             [int]$lineNumber = $matches["line"]
 
-            $message = parseMessage $method
+            $message = parseLogMessage $method
 
             [PsesLogEntry]::new($script:logEntryIndex, $timestamp, $timestampStr, $logLevel, $threadId, $method,
-                $file, $lineNumber, $message.MessageType, $message.Message)
+                $file, $lineNumber, $message.LogMessageType, $message.LogMessage)
 
             if ($DebugTimingInfo) {
                 $sw.Stop()
@@ -132,10 +132,10 @@ function Parse-PsesLog {
             $script:logEntryIndex++
         }
 
-        function parseMessage([string]$Method) {
+        function parseLogMessage([string]$Method) {
             $result = [PSCustomObject]@{
-                MessageType = [PsesMessageType]::Log
-                Message = $null
+                LogMessageType = [PsesLogMessageType]::Log
+                LogMessage = $null
             }
 
             $line = nextLine
@@ -145,45 +145,54 @@ function Parse-PsesLog {
             }
 
             if (($Method -eq 'ReadMessage') -and
-                ($line -match '\s+Received Request ''(?<msg>[^'']+)'' with id (?<id>\d+)')) {
-                $result.MessageType = [PsesMessageType]::Request
+                ($line -match '^\s+Received Request ''(?<msg>[^'']+)'' with id (?<id>\d+)')) {
+                $result.LogMessageType = [PsesLogMessageType]::Request
                 $msg = $matches["msg"]
                 $id = $matches["id"]
-                $json = parseJsonMessageBody
-                $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
+                $json = parseLogMessageBodyAsJson
+                $result.LogMessage = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
             }
             elseif (($Method -eq 'ReadMessage') -and
-                    ($line -match '\s+Received event ''(?<msg>[^'']+)''')) {
-                $result.MessageType = [PsesMessageType]::Notification
+                    ($line -match '^\s+Received event ''(?<msg>[^'']+)''')) {
+                $result.LogMessageType = [PsesLogMessageType]::Notification
                 $msg = $matches["msg"]
-                $json = parseJsonMessageBody
-                $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json.Data, $json.DataSize)
+                $json = parseLogMessageBodyAsJson
+                $result.LogMessage = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json.Data, $json.DataSize)
             }
             elseif (($Method -eq 'WriteMessage') -and
-                    ($line -match '\s+Writing Response ''(?<msg>[^'']+)'' with id (?<id>\d+)')) {
-                $result.MessageType = [PsesMessageType]::Response
+                    ($line -match '^\s+Writing Response ''(?<msg>[^'']+)'' with id (?<id>\d+)')) {
+                $result.LogMessageType = [PsesLogMessageType]::Response
                 $msg = $matches["msg"]
                 $id = $matches["id"]
-                $json = parseJsonMessageBody
-                $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
+                $json = parseLogMessageBodyAsJson
+                $result.LogMessage = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize)
             }
             elseif (($Method -eq 'WriteMessage') -and
-                    ($line -match '\s+Writing event ''(?<msg>[^'']+)''')) {
-                $result.MessageType = [PsesMessageType]::Notification
+                    ($line -match '^\s+Writing event ''(?<msg>[^'']+)''')) {
+                $result.LogMessageType = [PsesLogMessageType]::Notification
                 $msg = $matches["msg"]
-                $json = parseJsonMessageBody
-                $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json.Data, $json.DataSize)
+                $json = parseLogMessageBodyAsJson
+                $result.LogMessage = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json.Data, $json.DataSize)
             }
             else {
-                $result.MessageType = [PsesMessageType]::Log
-                $body = parseMessageBody $line
-                $result.Message = [PsesLogMessage]::new($body)
+                if  ($line -match '^\s+Exception: ') {
+                    $result.LogMessageType = [PsesLogMessageType]::Exception
+                }
+                elseif  ($line -match '^\s+Handled exception: ') {
+                    $result.LogMessageType = [PsesLogMessageType]::HandledException
+                }
+                else {
+                    $result.LogMessageType = [PsesLogMessageType]::Log
+                }
+
+                $body = parseLogMessageBody $line
+                $result.LogMessage = [PsesLogMessage]::new($body)
             }
 
             $result
         }
 
-        function parseMessageBody([string]$startLine = '', [switch]$Discard) {
+        function parseLogMessageBody([string]$startLine = '', [switch]$Discard) {
             if (!$Discard) {
                 $strBld = [System.Text.StringBuilder]::new($startLine, 4096)
                 $newLine = "`r`n"
@@ -219,7 +228,7 @@ function Parse-PsesLog {
             }
         }
 
-        function parseJsonMessageBody() {
+        function parseLogMessageBodyAsJson() {
             $result = [PSCustomObject]@{
                 Data = $null
                 DataSize = 0
@@ -228,11 +237,11 @@ function Parse-PsesLog {
             $obj = $null
 
             if ($SkipRpcMessageBody) {
-                parseMessageBody -Discard
+                parseLogMessageBody -Discard
                 return $result
             }
             else {
-                $result.Data = parseMessageBody
+                $result.Data = parseLogMessageBody
                 $result.DataSize = $result.Data.Length
             }
 
diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml
@@ -23,8 +23,8 @@
             <Alignment>right</Alignment>
           </TableColumnHeader>
           <TableColumnHeader>
-            <Label>MessageType</Label>
-            <Width>13</Width>
+            <Label>LogMessageType</Label>
+            <Width>15</Width>
             <Alignment>left</Alignment>
           </TableColumnHeader>
           <TableColumnHeader>
@@ -45,7 +45,7 @@
                 <PropertyName>ThreadId</PropertyName>
               </TableColumnItem>
               <TableColumnItem>
-                <PropertyName>MessageType</PropertyName>
+                <PropertyName>LogMessageType</PropertyName>
               </TableColumnItem>
               <TableColumnItem>
                 <ScriptBlock>($_.Message -split "`r`n")[0]</ScriptBlock>
diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1
@@ -71,7 +71,10 @@ FormatsToProcess = @('PsesLogAnalyzer.format.ps1xml')
 # Functions to export from this module, for best performance, do not use wildcards and do not delete the entry, use an empty array if there are no functions to export.
 FunctionsToExport = @(
     'Parse-PsesLog',
-    'Get-PsesRpcMessageResponseTime'
+    'Get-PsesRpcMessageResponseTime',
+    'Get-PsesRpcNotificationMessage',
+    'Get-PsesScriptAnalysisCompletionTime',
+    'Get-PsesIntelliSenseCompletionTime'
 )
 
 # Cmdlets to export from this module, for best performance, do not use wildcards and do not delete the entry, use an empty array if there are no cmdlets to export.
diff --git a/tools/PsesLogAnalyzer/Types.ps1 b/tools/PsesLogAnalyzer/Types.ps1
