From e9faf1ebd65e3227c24e42900c847e273d2f8e56 Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Sat, 24 Nov 2018 23:24:05 -0700 Subject: [PATCH 1/8] Start of a PSES log file analyzer --- .../MessageProtocol/MessageReader.cs | 37 ++-- .../MessageProtocol/MessageWriter.cs | 37 ++-- tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 178 ++++++++++++++++++ tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 | 123 ++++++++++++ tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 | 112 +++++++++++ 5 files changed, 464 insertions(+), 23 deletions(-) create mode 100644 tools/PsesLogAnalyzer/Parse-PsesLog.ps1 create mode 100644 tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 create mode 100644 tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs index 66f75c375..045c0d385 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs @@ -110,20 +110,33 @@ public async Task ReadMessage() // Get the JObject for the JSON content JObject messageObject = JObject.Parse(messageContent); - // Load the message - this.logger.Write( - LogLevel.Diagnostic, - string.Format( - "READ MESSAGE:\r\n\r\n{0}", - messageObject.ToString(Formatting.Indented))); - - // Return the parsed message + // Deserialize the message from the parsed JSON message Message parsedMessage = this.messageSerializer.DeserializeMessage(messageObject); - this.logger.Write( - LogLevel.Verbose, - $"Received {parsedMessage.MessageType} '{parsedMessage.Method}'" + - (!string.IsNullOrEmpty(parsedMessage.Id) ? $" with id {parsedMessage.Id}" : string.Empty)); + // Log message info + var logStrBld = + new StringBuilder(512) + .Append("Received ") + .Append(parsedMessage.MessageType) + .Append(" '").Append(parsedMessage.Method).Append("'"); + + if (!string.IsNullOrEmpty(parsedMessage.Id)) + { + logStrBld.Append(" with id ").Append(parsedMessage.Id); + } + + if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic) + { + string jsonPayload = messageObject.ToString(Formatting.Indented); + logStrBld.Append("\r\n\r\n").Append(jsonPayload); + + // Log the JSON representation of the message + this.logger.Write(LogLevel.Diagnostic, logStrBld.ToString()); + } + else + { + this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + } return parsedMessage; } diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs index c618fa104..6221bd528 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs @@ -58,20 +58,35 @@ public async Task WriteMessage(Message messageToWrite) this.messageSerializer.SerializeMessage( messageToWrite); - this.logger.Write( - LogLevel.Verbose, - $"Writing {messageToWrite.MessageType} '{messageToWrite.Method}'" + - (!string.IsNullOrEmpty(messageToWrite.Id) ? $" with id {messageToWrite.Id}" : string.Empty)); - - // Log the JSON representation of the message - this.logger.Write( - LogLevel.Diagnostic, - string.Format( - "WRITE MESSAGE:\r\n\r\n{0}", + // Log message info + var logStrBld = + new StringBuilder(512) + .Append("Writing ") + .Append(messageToWrite.MessageType) + .Append(" '").Append(messageToWrite.Method).Append("'"); + + if (!string.IsNullOrEmpty(messageToWrite.Id)) + { + logStrBld.Append(" with id ").Append(messageToWrite.Id); + } + + if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic) + { + string jsonPayload = JsonConvert.SerializeObject( messageObject, Formatting.Indented, - Constants.JsonSerializerSettings))); + Constants.JsonSerializerSettings); + + logStrBld.Append("\r\n\r\n").Append(jsonPayload); + + // Log the JSON representation of the message + this.logger.Write(LogLevel.Diagnostic, logStrBld.ToString()); + } + else + { + this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + } string serializedMessage = JsonConvert.SerializeObject( diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 new file mode 100644 index 000000000..ae5e8948b --- /dev/null +++ b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 @@ -0,0 +1,178 @@ + +$peekBuf = $null +$currentLineNum = 1 + +function Parse-PsesLog { + param( + # Specifies a path to one or more PSES EditorServices log files. + [Parameter(Mandatory=$true, Position=0)] + [Alias("PSPath")] + [ValidateNotNullOrEmpty()] + [string] + $Path + ) + + begin { + + # Example 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: + $logEntryRegex = + [regex]::new( + '(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', + [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase) + + $filestream = + [System.IO.FileStream]::new( + $Path, + [System.IO.FileMode]:: Open, + [System.IO.FileAccess]::Read, + [System.IO.FileShare]::ReadWrite, + 4096, + [System.IO.FileOptions]::SequentialScan) + + $streamReader = [System.IO.StreamReader]::new($filestream, [System.Text.Encoding]::UTF8) + + function nextLine() { + if ($null -ne $peekBuf) { + $line = $peekBuf + $script:peekBuf = $null + } + else { + $line = $streamReader.ReadLine() + } + + $script:currentLineNum += 1 + $line + } + + function peekLine() { + if ($null -ne $peekBuf) { + $line = $peekBuf; + } + else { + $line = $script:peekBuf = $streamReader.ReadLine() + } + + $line + } + + function parseLogEntryStart([string]$line) { + while ($line -notmatch $logEntryRegex) { + Write-Warning "Ignoring line: '$line'" + $line = nextLine + } + + [string]$timestampStr = $matches["ts"] + [DateTime]$timestamp = $timestampStr + [PsesLogLevel]$logLevel = $matches["lev"] + [int]$threadId = $matches["tid"] + [string]$method = $matches["meth"] + [string]$file = $matches["file"] + [int]$lineNumber = $matches["line"] + + $message = parseMessage $method + + [PsesLogEntry]::new($timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber, + $message.MessageType, $message.Message) + } + + function parseMessage([string]$Method) { + $result = [PSCustomObject]@{ + MessageType = [PsesMessageType]::Log + Message = $null + } + + $line = nextLine + if ($null -eq $line) { + Write-Warning "$($MyInvocation.MyCommand.Name) encountered end of file early." + return $result + } + + if (($Method -eq 'ReadMessage') -and + ($line -match '\s+Received Request ''(?[^'']+)'' with id (?\d+)')) { + $result.MessageType = [PsesMessageType]::Request + $msg = $matches["msg"] + $id = $matches["id"] + $json = parseJsonMessageBody + $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) + } + elseif (($Method -eq 'ReadMessage') -and + ($line -match '\s+Received event ''(?[^'']+)''')) { + $result.MessageType = [PsesMessageType]::Notification + $msg = $matches["msg"] + $json = parseJsonMessageBody + $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json) + } + elseif (($Method -eq 'WriteMessage') -and + ($line -match '\s+Writing Response ''(?[^'']+)'' with id (?\d+)')) { + $result.MessageType = [PsesMessageType]::Response + $msg = $matches["msg"] + $id = $matches["id"] + $json = parseJsonMessageBody + $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) + } + elseif (($Method -eq 'WriteMessage') -and + ($line -match '\s+Writing event ''(?[^'']+)''')) { + $result.MessageType = [PsesMessageType]::Notification + $msg = $matches["msg"] + $json = parseJsonMessageBody + $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json) + } + else { + $result.MessageType = [PsesMessageType]::Log + $body = parseMessageBody $line + $result.Message = [PsesLogMessage]::new($body) + } + + $result + } + + function parseMessageBody([string]$startLine = '') { + $result = $startLine + try { + while ($true) { + $peekLine = peekLine + if ($null -eq $peekLine) { + break + } + + if ($peekLine -match $logEntryRegex) { + break + } + + $result += (nextLine) + "`r`n" + } + + } + catch { + Write-Error "Failed parsing message body with error: $_" + } + + $result.Trim() + } + + function parseJsonMessageBody() { + $obj = $null + + try { + $result = parseMessageBody + $obj = $result.Trim() | ConvertFrom-Json + } + catch { + Write-Error "Failed parsing JSON message body with error: $_" + } + + $obj + } + } + + process { + while ($null -ne ($line = nextLine)) { + parseLogEntryStart $line + } + } + + end { + if ($streamReader) { $streamReader.Dispose() } + } +} diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 new file mode 100644 index 000000000..382f706a5 --- /dev/null +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 @@ -0,0 +1,123 @@ +# +# Module manifest for module 'Pses-LogAnalyzer' +# +# Generated by: Keith +# +# Generated on: 11/23/2018 +# + +@{ + +# Script module or binary module file associated with this manifest. +RootModule = 'PsesLogAnalyzer.psm1' + +# Version number of this module. +ModuleVersion = '1.0.0' + +# Supported PSEditions +# CompatiblePSEditions = @() + +# ID used to uniquely identify this module +GUID = '99116548-ad0f-4087-a425-7edab3aa9e57' + +# Author of this module +Author = 'Microsoft' + +# Company or vendor of this module +CompanyName = 'Microsoft' + +# Copyright statement for this module +Copyright = '(c) 2017 Microsoft. All rights reserved.' + +# Description of the functionality provided by this module +# Description = '' + +# Minimum version of the PowerShell engine required by this module +# PowerShellVersion = '' + +# Name of the PowerShell host required by this module +# PowerShellHostName = '' + +# Minimum version of the PowerShell host required by this module +# PowerShellHostVersion = '' + +# Minimum version of Microsoft .NET Framework required by this module. This prerequisite is valid for the PowerShell Desktop edition only. +# DotNetFrameworkVersion = '' + +# Minimum version of the common language runtime (CLR) required by this module. This prerequisite is valid for the PowerShell Desktop edition only. +# CLRVersion = '' + +# Processor architecture (None, X86, Amd64) required by this module +# ProcessorArchitecture = '' + +# Modules that must be imported into the global environment prior to importing this module +# RequiredModules = @() + +# Assemblies that must be loaded prior to importing this module +# RequiredAssemblies = @() + +# Script files (.ps1) that are run in the caller's environment prior to importing this module. +# ScriptsToProcess = @() + +# Type files (.ps1xml) to be loaded when importing this module +# TypesToProcess = @() + +# Format files (.ps1xml) to be loaded when importing this module +# FormatsToProcess = @() + +# Modules to import as nested modules of the module specified in RootModule/ModuleToProcess +# NestedModules = @() + +# 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') + +# 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. +CmdletsToExport = @() + +# Variables to export from this module +VariablesToExport = '' + +# Aliases 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 aliases to export. +AliasesToExport = @() + +# DSC resources to export from this module +# DscResourcesToExport = @() + +# List of all modules packaged with this module +# ModuleList = @() + +# List of all files packaged with this module +# FileList = @() + +# Private data to pass to the module specified in RootModule/ModuleToProcess. This may also contain a PSData hashtable with additional module metadata used by PowerShell. +PrivateData = @{ + + PSData = @{ + + # Tags applied to this module. These help with module discovery in online galleries. + # Tags = @() + + # A URL to the license for this module. + # LicenseUri = '' + + # A URL to the main website for this project. + # ProjectUri = '' + + # A URL to an icon representing this module. + # IconUri = '' + + # ReleaseNotes of this module + # ReleaseNotes = '' + + } # End of PSData hashtable + +} # End of PrivateData hashtable + +# HelpInfo URI of this module +# HelpInfoURI = '' + +# Default prefix for commands exported from this module. Override the default prefix using Import-Module -Prefix. +# DefaultCommandPrefix = '' + +} + diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 new file mode 100644 index 000000000..c56507c21 --- /dev/null +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 @@ -0,0 +1,112 @@ +enum PsesLogLevel { + Diagnostic; + Verbose; + Normal; + Warning; + Error; +} + +enum PsesMessageType { + Log; + Request; + Response; + Notification; +} + +enum PsesNotificationSource { + Unknown; + Client; + Server; +} + +class PsesLogMessage { + [string]$Data + + PsesLogMessage([string]$Data) { + $this.Data = $Data + } + + [string] ToString() { + $ofs = '' + return "$($this.Data[0..100])" + } +} + +class PsesJsonRpcMessage { + [string]$Name + [int]$Id + [psobject]$Data + + PsesJsonRpcMessage([string]$Name, [int]$Id, [psobject]$Data) { + $this.Name = $Name + $this.Id = $Id + $this.Data = $Data + } + + [string] ToString() { + return "Name: $($this.Name) Id: $($this.Id)" + } +} + +class PsesNotificationMessage { + [string]$Name + [PsesNotificationSource]$Source + [psobject]$Data + + PsesNotificationMessage([string]$Name, [PsesNotificationSource]$Source, [psobject]$Data) { + $this.Name = $Name + $this.Source = $Source + $this.Data = $Data + } + + [string] ToString() { + return "Name: $($this.Name) Source: $($this.Source)" + } +} + +class PsesLogEntry { + [DateTime]$Timestamp + [string]$TimestampStr + [PsesLogLevel]$LogLevel + [int]$ThreadId + [string]$Method + [string]$File + [int]$LineNumber + [PsesMessageType]$MessageType + [psobject]$Message + + PsesLogEntry( + [DateTime] + $Timestamp, + [string] + $TimestampStr, + [PsesLogLevel] + $LogLevel, + [int] + $ThreadId, + [string] + $Method, + [string] + $File, + [int] + $LineNumber, + [PsesMessageType] + $MessageType, + [psobject] + $Message) { + + $this.Timestamp = $Timestamp + $this.TimestampStr = $TimestampStr + $this.LogLevel = $LogLevel + $this.ThreadId = $ThreadId + $this.Method = $Method + $this.File = $File + $this.LineNumber = $LineNumber + $this.MessageType = $MessageType + $this.Message = $Message + } +} + +. $PSScriptRoot\Parse-PsesLog.ps1 + +Export-ModuleMember -Function *-* From d88ea99b91a20bb92721f33ad40d21c335ee7441 Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Sun, 25 Nov 2018 12:32:33 -0700 Subject: [PATCH 2/8] Work on parse perf --- tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 104 ++++++++++++++++++------ 1 file changed, 79 insertions(+), 25 deletions(-) diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 index ae5e8948b..b9c694473 100644 --- a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 +++ b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 @@ -1,6 +1,7 @@ $peekBuf = $null $currentLineNum = 1 +$logEntryNum = 1 function Parse-PsesLog { param( @@ -9,24 +10,41 @@ function Parse-PsesLog { [Alias("PSPath")] [ValidateNotNullOrEmpty()] [string] - $Path + $Path, + + # Hides the progress bar. + [Parameter()] + [switch] + $HideProgress, + + # Skips conversion from JSON & storage of the JsonRpc message body which can be large. + [Parameter()] + [switch] + $SkipRpcMessageBody, + + [Parameter()] + [switch] + $DebugTimingInfo, + + [Parameter()] + [int] + $DebugTimingThresholdMs = 100 ) begin { - # Example 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: - $logEntryRegex = + $logEntryRegex = [regex]::new( - '(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', + '(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase) - $filestream = + $filestream = [System.IO.FileStream]::new( - $Path, - [System.IO.FileMode]:: Open, - [System.IO.FileAccess]::Read, - [System.IO.FileShare]::ReadWrite, + $Path, + [System.IO.FileMode]:: Open, + [System.IO.FileAccess]::Read, + [System.IO.FileShare]::ReadWrite, 4096, [System.IO.FileOptions]::SequentialScan) @@ -41,7 +59,7 @@ function Parse-PsesLog { $line = $streamReader.ReadLine() } - $script:currentLineNum += 1 + $script:currentLineNum++ $line } @@ -55,13 +73,21 @@ function Parse-PsesLog { $line } - + function parseLogEntryStart([string]$line) { + if ($DebugTimingInfo) { + $sw = [System.Diagnostics.Stopwatch]::StartNew() + } + while ($line -notmatch $logEntryRegex) { Write-Warning "Ignoring line: '$line'" $line = nextLine } - + + if (!$HideProgress -and ($script:logEntryNum % 50 -eq 0)) { + Write-Progress "Processing log entry ${script:logEntryNum} on line: ${script:currentLineNum}" + } + [string]$timestampStr = $matches["ts"] [DateTime]$timestamp = $timestampStr [PsesLogLevel]$logLevel = $matches["lev"] @@ -69,11 +95,20 @@ function Parse-PsesLog { [string]$method = $matches["meth"] [string]$file = $matches["file"] [int]$lineNumber = $matches["line"] - + $message = parseMessage $method - [PsesLogEntry]::new($timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber, + [PsesLogEntry]::new($timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber, $message.MessageType, $message.Message) + + if ($DebugTimingInfo) { + $sw.Stop() + if ($sw.ElapsedMilliseconds -gt $DebugTimingThresholdMs) { + Write-Warning "Time to parse log entry ${script:logEntryNum} - $($sw.ElapsedMilliseconds) ms" + } + } + + $script:logEntryNum++ } function parseMessage([string]$Method) { @@ -88,7 +123,7 @@ function Parse-PsesLog { return $result } - if (($Method -eq 'ReadMessage') -and + if (($Method -eq 'ReadMessage') -and ($line -match '\s+Received Request ''(?[^'']+)'' with id (?\d+)')) { $result.MessageType = [PsesMessageType]::Request $msg = $matches["msg"] @@ -96,14 +131,14 @@ function Parse-PsesLog { $json = parseJsonMessageBody $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) } - elseif (($Method -eq 'ReadMessage') -and + elseif (($Method -eq 'ReadMessage') -and ($line -match '\s+Received event ''(?[^'']+)''')) { $result.MessageType = [PsesMessageType]::Notification $msg = $matches["msg"] $json = parseJsonMessageBody $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json) } - elseif (($Method -eq 'WriteMessage') -and + elseif (($Method -eq 'WriteMessage') -and ($line -match '\s+Writing Response ''(?[^'']+)'' with id (?\d+)')) { $result.MessageType = [PsesMessageType]::Response $msg = $matches["msg"] @@ -111,7 +146,7 @@ function Parse-PsesLog { $json = parseJsonMessageBody $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) } - elseif (($Method -eq 'WriteMessage') -and + elseif (($Method -eq 'WriteMessage') -and ($line -match '\s+Writing event ''(?[^'']+)''')) { $result.MessageType = [PsesMessageType]::Notification $msg = $matches["msg"] @@ -127,8 +162,12 @@ function Parse-PsesLog { $result } - function parseMessageBody([string]$startLine = '') { - $result = $startLine + function parseMessageBody([string]$startLine = '', [switch]$Discard) { + if (!$Discard) { + $strBld = [System.Text.StringBuilder]::new($startLine, 4096) + $newLine = "`r`n" + } + try { while ($true) { $peekLine = peekLine @@ -136,26 +175,41 @@ function Parse-PsesLog { break } - if ($peekLine -match $logEntryRegex) { + if (($peekLine.Length -gt 0) -and ($peekLine[0] -ne ' ') -and ($peekLine -match $logEntryRegex)) { break } - $result += (nextLine) + "`r`n" + $nextLine = nextLine + if (!$Discard) { + [void]$strBld.Append($nextLine).Append($newLine) + } } - } catch { Write-Error "Failed parsing message body with error: $_" } - $result.Trim() + if (!$Discard) { + $msgBody = $strBld.ToString().Trim() + $msgBody + } + else { + $startLine + } } function parseJsonMessageBody() { $obj = $null - try { + if ($SkipRpcMessageBody) { + parseMessageBody -Discard + return $null + } + else { $result = parseMessageBody + } + + try { $obj = $result.Trim() | ConvertFrom-Json } catch { From a6fdb00296dc2bde575dd1973f3d0b6fa3e0cfad Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Sun, 25 Nov 2018 15:55:18 -0700 Subject: [PATCH 3/8] Add Get-PsesRpcMessageResponseTime command and format file --- tools/PsesLogAnalyzer/.vscode/launch.json | 14 ++ tools/PsesLogAnalyzer/Analyze.ps1 | 46 ++++++ tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 42 +++-- .../PsesLogAnalyzer.format.ps1xml | 115 ++++++++++++++ tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 | 7 +- tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 | 111 +------------ tools/PsesLogAnalyzer/Types.ps1 | 146 ++++++++++++++++++ 7 files changed, 354 insertions(+), 127 deletions(-) create mode 100644 tools/PsesLogAnalyzer/.vscode/launch.json create mode 100644 tools/PsesLogAnalyzer/Analyze.ps1 create mode 100644 tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml create mode 100644 tools/PsesLogAnalyzer/Types.ps1 diff --git a/tools/PsesLogAnalyzer/.vscode/launch.json b/tools/PsesLogAnalyzer/.vscode/launch.json new file mode 100644 index 000000000..cca4ceb41 --- /dev/null +++ b/tools/PsesLogAnalyzer/.vscode/launch.json @@ -0,0 +1,14 @@ +{ + // Use IntelliSense to learn about possible attributes. + // Hover to view descriptions of existing attributes. + // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387 + "version": "0.2.0", + "configurations": [ + { + "type": "PowerShell", + "request": "launch", + "name": "PowerShell Interactive Session", + "cwd": "" + } + ] +} diff --git a/tools/PsesLogAnalyzer/Analyze.ps1 b/tools/PsesLogAnalyzer/Analyze.ps1 new file mode 100644 index 000000000..a715ef39f --- /dev/null +++ b/tools/PsesLogAnalyzer/Analyze.ps1 @@ -0,0 +1,46 @@ +function Get-PsesRpcMessageResponseTime { + [CmdletBinding(DefaultParameterSetName="Path")] + 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 + } + } + + end { + # Populate $requests hashtable with request timestamps + $requests = @{} + $logEntries | + Where-Object MessageType -match Request | + Foreach-Object { $requests[$_.Message.Id] = $_.Timestamp } + + $res = $logEntries | + Where-Object MessageType -match Response | + Foreach-Object { + $elapsedMilliseconds = [int]($_.Timestamp - $requests[$_.Message.Id]).TotalMilliseconds + [PsesLogEntryElapsed]::new($_, $elapsedMilliseconds) + } + + $res + } +} diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 index b9c694473..f6c60ac1b 100644 --- a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 +++ b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 @@ -1,11 +1,11 @@ $peekBuf = $null $currentLineNum = 1 -$logEntryNum = 1 +$logEntryIndex = 0 function Parse-PsesLog { param( - # Specifies a path to one or more PSES EditorServices log files. + # Specifies a path to a PSES EditorServices log file. [Parameter(Mandatory=$true, Position=0)] [Alias("PSPath")] [ValidateNotNullOrEmpty()] @@ -32,6 +32,10 @@ function Parse-PsesLog { ) begin { + $script:peekBuf = $null + $script:currentLineNum = 1 + $script:logEntryIndex = 0 + # Example 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: $logEntryRegex = @@ -84,8 +88,8 @@ function Parse-PsesLog { $line = nextLine } - if (!$HideProgress -and ($script:logEntryNum % 50 -eq 0)) { - Write-Progress "Processing log entry ${script:logEntryNum} on line: ${script:currentLineNum}" + if (!$HideProgress -and ($script:logEntryIndex % 50 -eq 0)) { + Write-Progress "Processing log entry ${script:logEntryIndex} on line: ${script:currentLineNum}" } [string]$timestampStr = $matches["ts"] @@ -98,17 +102,17 @@ function Parse-PsesLog { $message = parseMessage $method - [PsesLogEntry]::new($timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber, - $message.MessageType, $message.Message) + [PsesLogEntry]::new($script:logEntryIndex, $timestamp, $timestampStr, $logLevel, $threadId, $method, + $file, $lineNumber, $message.MessageType, $message.Message) if ($DebugTimingInfo) { $sw.Stop() if ($sw.ElapsedMilliseconds -gt $DebugTimingThresholdMs) { - Write-Warning "Time to parse log entry ${script:logEntryNum} - $($sw.ElapsedMilliseconds) ms" + Write-Warning "Time to parse log entry ${script:logEntryIndex} - $($sw.ElapsedMilliseconds) ms" } } - $script:logEntryNum++ + $script:logEntryIndex++ } function parseMessage([string]$Method) { @@ -129,14 +133,14 @@ function Parse-PsesLog { $msg = $matches["msg"] $id = $matches["id"] $json = parseJsonMessageBody - $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) + $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize) } elseif (($Method -eq 'ReadMessage') -and ($line -match '\s+Received event ''(?[^'']+)''')) { $result.MessageType = [PsesMessageType]::Notification $msg = $matches["msg"] $json = parseJsonMessageBody - $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json) + $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Client, $json.Data, $json.DataSize) } elseif (($Method -eq 'WriteMessage') -and ($line -match '\s+Writing Response ''(?[^'']+)'' with id (?\d+)')) { @@ -144,14 +148,14 @@ function Parse-PsesLog { $msg = $matches["msg"] $id = $matches["id"] $json = parseJsonMessageBody - $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json) + $result.Message = [PsesJsonRpcMessage]::new($msg, $id, $json.Data, $json.DataSize) } elseif (($Method -eq 'WriteMessage') -and ($line -match '\s+Writing event ''(?[^'']+)''')) { $result.MessageType = [PsesMessageType]::Notification $msg = $matches["msg"] $json = parseJsonMessageBody - $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json) + $result.Message = [PsesNotificationMessage]::new($msg, [PsesNotificationSource]::Server, $json.Data, $json.DataSize) } else { $result.MessageType = [PsesMessageType]::Log @@ -199,24 +203,30 @@ function Parse-PsesLog { } function parseJsonMessageBody() { + $result = [PSCustomObject]@{ + Data = $null + DataSize = 0 + } + $obj = $null if ($SkipRpcMessageBody) { parseMessageBody -Discard - return $null + return $result } else { - $result = parseMessageBody + $result.Data = parseMessageBody + $result.DataSize = $result.Data.Length } try { - $obj = $result.Trim() | ConvertFrom-Json + $result.Data = $result.Data.Trim() | ConvertFrom-Json } catch { Write-Error "Failed parsing JSON message body with error: $_" } - $obj + $result } } diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml new file mode 100644 index 000000000..3f6cd2941 --- /dev/null +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml @@ -0,0 +1,115 @@ + + + + PsesLogEntry + + PsesLogEntry + + + + + + 6 + right + + + + 24 + left + + + + 5 + right + + + + 13 + left + + + + left + + + + + + + Index + + + TimestampStr + + + ThreadId + + + MessageType + + + ($_.Message -split "`r`n")[0] + + + + + + + + + PsesLogEntryElapsed + + PsesLogEntryElapsed + + + + + + 6 + right + + + + 24 + left + + + + 5 + right + + + + 13 + right + + + + left + + + + + + + Index + + + TimestampStr + + + ThreadId + + + $_.ElapsedMilliseconds + + + $_.Message + + + + + + + + diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 index 382f706a5..339fe3e92 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 @@ -63,13 +63,16 @@ Copyright = '(c) 2017 Microsoft. All rights reserved.' # TypesToProcess = @() # Format files (.ps1xml) to be loaded when importing this module -# FormatsToProcess = @() +FormatsToProcess = @('PsesLogAnalyzer.format.ps1xml') # Modules to import as nested modules of the module specified in RootModule/ModuleToProcess # NestedModules = @() # 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') +FunctionsToExport = @( + 'Parse-PsesLog', + 'Get-PsesRpcMessageResponseTime' +) # 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. CmdletsToExport = @() diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 index c56507c21..6d36fd33f 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 @@ -1,112 +1,5 @@ -enum PsesLogLevel { - Diagnostic; - Verbose; - Normal; - Warning; - Error; -} - -enum PsesMessageType { - Log; - Request; - Response; - Notification; -} - -enum PsesNotificationSource { - Unknown; - Client; - Server; -} - -class PsesLogMessage { - [string]$Data - - PsesLogMessage([string]$Data) { - $this.Data = $Data - } - - [string] ToString() { - $ofs = '' - return "$($this.Data[0..100])" - } -} - -class PsesJsonRpcMessage { - [string]$Name - [int]$Id - [psobject]$Data - - PsesJsonRpcMessage([string]$Name, [int]$Id, [psobject]$Data) { - $this.Name = $Name - $this.Id = $Id - $this.Data = $Data - } - - [string] ToString() { - return "Name: $($this.Name) Id: $($this.Id)" - } -} - -class PsesNotificationMessage { - [string]$Name - [PsesNotificationSource]$Source - [psobject]$Data - - PsesNotificationMessage([string]$Name, [PsesNotificationSource]$Source, [psobject]$Data) { - $this.Name = $Name - $this.Source = $Source - $this.Data = $Data - } - - [string] ToString() { - return "Name: $($this.Name) Source: $($this.Source)" - } -} - -class PsesLogEntry { - [DateTime]$Timestamp - [string]$TimestampStr - [PsesLogLevel]$LogLevel - [int]$ThreadId - [string]$Method - [string]$File - [int]$LineNumber - [PsesMessageType]$MessageType - [psobject]$Message - - PsesLogEntry( - [DateTime] - $Timestamp, - [string] - $TimestampStr, - [PsesLogLevel] - $LogLevel, - [int] - $ThreadId, - [string] - $Method, - [string] - $File, - [int] - $LineNumber, - [PsesMessageType] - $MessageType, - [psobject] - $Message) { - - $this.Timestamp = $Timestamp - $this.TimestampStr = $TimestampStr - $this.LogLevel = $LogLevel - $this.ThreadId = $ThreadId - $this.Method = $Method - $this.File = $File - $this.LineNumber = $LineNumber - $this.MessageType = $MessageType - $this.Message = $Message - } -} - +. $PSScriptRoot\Types.ps1 . $PSScriptRoot\Parse-PsesLog.ps1 +. $PSScriptRoot\Analyze.ps1 Export-ModuleMember -Function *-* diff --git a/tools/PsesLogAnalyzer/Types.ps1 b/tools/PsesLogAnalyzer/Types.ps1 new file mode 100644 index 000000000..6fced1cf2 --- /dev/null +++ b/tools/PsesLogAnalyzer/Types.ps1 @@ -0,0 +1,146 @@ +enum PsesLogLevel { + Diagnostic; + Verbose; + Normal; + Warning; + Error; +} + +enum PsesMessageType { + Log; + Request; + Response; + Notification; +} + +enum PsesNotificationSource { + Unknown; + Client; + Server; +} + +class PsesLogMessage { + [string]$Data + + PsesLogMessage([string]$Data) { + $this.Data = $Data + } + + [string] ToString() { + $ofs = '' + $ellipsis = if ($this.Data.Length -ge 100) { "..." } else { "" } + return "$($this.Data[0..99])$ellipsis, DataSize: $($this.Data.Length)" + } +} + +class PsesJsonRpcMessage { + [string]$Name + [int]$Id + [psobject]$Data + [int]$DataSize + + PsesJsonRpcMessage([string]$Name, [int]$Id, [psobject]$Data, [int]$DataSize) { + $this.Name = $Name + $this.Id = $Id + $this.Data = $Data + $this.DataSize = $DataSize + } + + [string] ToString() { + return "Name: $($this.Name) Id: $($this.Id), DataSize: $($this.DataSize)" + } +} + +class PsesNotificationMessage { + [string]$Name + [PsesNotificationSource]$Source + [psobject]$Data + [int]$DataSize + + PsesNotificationMessage([string]$Name, [PsesNotificationSource]$Source, [psobject]$Data, [int]$DataSize) { + $this.Name = $Name + $this.Source = $Source + $this.Data = $Data + $this.DataSize = $DataSize + } + + [string] ToString() { + return "Name: $($this.Name) Source: $($this.Source), DataSize: $($this.DataSize)" + } +} + +class PsesLogEntry { + [int]$Index + [DateTime]$Timestamp + [string]$TimestampStr + [PsesLogLevel]$LogLevel + [int]$ThreadId + [string]$Method + [string]$File + [int]$LineNumber + [PsesMessageType]$MessageType + [psobject]$Message + + PsesLogEntry( + [int] + $Index, + [DateTime] + $Timestamp, + [string] + $TimestampStr, + [PsesLogLevel] + $LogLevel, + [int] + $ThreadId, + [string] + $Method, + [string] + $File, + [int] + $LineNumber, + [PsesMessageType] + $MessageType, + [psobject] + $Message) { + + $this.Index = $Index + $this.Timestamp = $Timestamp + $this.TimestampStr = $TimestampStr + $this.LogLevel = $LogLevel + $this.ThreadId = $ThreadId + $this.Method = $Method + $this.File = $File + $this.LineNumber = $LineNumber + $this.MessageType = $MessageType + $this.Message = $Message + } +} + +class PsesLogEntryElapsed { + [int]$Index + [DateTime]$Timestamp + [string]$TimestampStr + [int]$ElapsedMilliseconds + [PsesLogLevel]$LogLevel + [int]$ThreadId + [string]$Method + [string]$File + [int]$LineNumber + [PsesMessageType]$MessageType + [psobject]$Message + + PsesLogEntryElapsed([PsesLogEntry]$LogEntry, [int]$ElapsedMilliseconds) { + $this.Index = $LogEntry.Index + $this.Timestamp = $LogEntry.Timestamp + $this.TimestampStr = $LogEntry.TimestampStr + $this.LogLevel = $LogEntry.LogLevel + $this.ThreadId = $LogEntry.ThreadId + $this.Method = $LogEntry.Method + $this.File = $LogEntry.File + $this.LineNumber = $LogEntry.LineNumber + $this.MessageType = $LogEntry.MessageType + $this.Message = $LogEntry.Message + + $this.ElapsedMilliseconds = $ElapsedMilliseconds + } +} From 2e6564fda77ad7a86d442939044503eb700080c7 Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Mon, 26 Nov 2018 20:47:04 -0700 Subject: [PATCH 4/8] Address PR feedback - use Env.NewLine, comment strbld capacity --- .../MessageProtocol/MessageReader.cs | 19 ++++++------ .../MessageProtocol/MessageWriter.cs | 19 ++++++------ tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 31 ++++++++++++++----- 3 files changed, 42 insertions(+), 27 deletions(-) diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs index 045c0d385..57b9148f0 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs @@ -113,9 +113,12 @@ public async Task ReadMessage() // Deserialize the message from the parsed JSON message Message parsedMessage = this.messageSerializer.DeserializeMessage(messageObject); - // Log message info + // Log message info - initial capacity for StringBuilder varies depending on whether + // the log level is Diagnostic where JsonRpc message payloads are logged and + // vary from 1K up edited file size chars. When not logging message payloads the + // typical request log message is under 250 chars. var logStrBld = - new StringBuilder(512) + new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 250) .Append("Received ") .Append(parsedMessage.MessageType) .Append(" '").Append(parsedMessage.Method).Append("'"); @@ -127,17 +130,13 @@ public async Task ReadMessage() if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic) { + // Log the JSON representation of the message payload at the Diagnostic log level string jsonPayload = messageObject.ToString(Formatting.Indented); - logStrBld.Append("\r\n\r\n").Append(jsonPayload); - - // Log the JSON representation of the message - this.logger.Write(LogLevel.Diagnostic, logStrBld.ToString()); - } - else - { - this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload); } + this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + return parsedMessage; } diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs index 6221bd528..d0db043cf 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs @@ -58,9 +58,12 @@ public async Task WriteMessage(Message messageToWrite) this.messageSerializer.SerializeMessage( messageToWrite); - // Log message info + // Log message info - initial capacity for StringBuilder varies depending on whether + // the log level is Diagnostic where JsonRpc message payloads are logged and + // vary from 1K up 225K chars. When not logging message payloads the typical response + // log message is under 250 chars. var logStrBld = - new StringBuilder(512) + new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 250) .Append("Writing ") .Append(messageToWrite.MessageType) .Append(" '").Append(messageToWrite.Method).Append("'"); @@ -72,22 +75,18 @@ public async Task WriteMessage(Message messageToWrite) if (this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic) { + // Log the JSON representation of the message payload at the Diagnostic log level string jsonPayload = JsonConvert.SerializeObject( messageObject, Formatting.Indented, Constants.JsonSerializerSettings); - logStrBld.Append("\r\n\r\n").Append(jsonPayload); - - // Log the JSON representation of the message - this.logger.Write(LogLevel.Diagnostic, logStrBld.ToString()); - } - else - { - this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + logStrBld.Append(Environment.NewLine).Append(Environment.NewLine).Append(jsonPayload); } + this.logger.Write(LogLevel.Verbose, logStrBld.ToString()); + string serializedMessage = JsonConvert.SerializeObject( messageObject, diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 index f6c60ac1b..97284df74 100644 --- a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 +++ b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 @@ -12,6 +12,11 @@ function Parse-PsesLog { [string] $Path, + # Old log file format <= v1.9.0 + [Parameter()] + [switch] + $OldLogFormat, + # Hides the progress bar. [Parameter()] [switch] @@ -22,10 +27,12 @@ function Parse-PsesLog { [switch] $SkipRpcMessageBody, + # Emit debug timing info on time to parse each log entry [Parameter()] [switch] $DebugTimingInfo, + # Threshold for emitting debug timing info. Default is 100 ms. [Parameter()] [int] $DebugTimingThresholdMs = 100 @@ -36,12 +43,22 @@ function Parse-PsesLog { $script:currentLineNum = 1 $script:logEntryIndex = 0 - # Example 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: - $logEntryRegex = - [regex]::new( - '(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', - [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase) + if ($OldLogFormat) { + # 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( + '^(?[^\[]+)\[(?([^\]]+))\]\s+(?..[^:]+):\s+In method\s+''(?\w+)'',\s+line\s+(?\d+)', + [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase) + } + 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: + $logEntryRegex = + [regex]::new( + '^(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', + [System.Text.RegularExpressions.RegexOptions]::Compiled -bor [System.Text.RegularExpressions.RegexOptions]::IgnoreCase) + } $filestream = [System.IO.FileStream]::new( @@ -102,7 +119,7 @@ function Parse-PsesLog { $message = parseMessage $method - [PsesLogEntry]::new($script:logEntryIndex, $timestamp, $timestampStr, $logLevel, $threadId, $method, + [PsesLogEntry]::new($script:logEntryIndex, $timestamp, $timestampStr, $logLevel, $threadId, $method, $file, $lineNumber, $message.MessageType, $message.Message) if ($DebugTimingInfo) { From 58e8df792e35846f330ba603e2b6e79dab97c6ae Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Tue, 27 Nov 2018 22:44:38 -0700 Subject: [PATCH 5/8] Tweak log message template to separate path from line num with ':' This is probably a legal path char on Linux but on Windows it isn't. Also, Pester uses a similar format: : line Update PSES log analyzer to parse template. Add some more analysis commands. --- .../Utility/PsesLogger.cs | 2 +- tools/PsesLogAnalyzer/Analyze.ps1 | 123 +++++++++++++++++- tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 75 ++++++----- .../PsesLogAnalyzer.format.ps1xml | 6 +- tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 | 5 +- tools/PsesLogAnalyzer/Types.ps1 | 20 ++- 6 files changed, 184 insertions(+), 47 deletions(-) diff --git a/src/PowerShellEditorServices/Utility/PsesLogger.cs b/src/PowerShellEditorServices/Utility/PsesLogger.cs index b60ea603b..e7dd29e9e 100644 --- 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. /// 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}"; /// /// The name of the ERROR log level. diff --git a/tools/PsesLogAnalyzer/Analyze.ps1 b/tools/PsesLogAnalyzer/Analyze.ps1 index a715ef39f..48d53ba8c 100644 --- 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.*\[(?\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+(?\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 index 97284df74..9748f4bec 100644 --- 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( - '^(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):(?\d+)', + '^(?[^\[]+)\[(?([^\]]+))\]\s+tid:(?\d+)\s+in\s+''(?\w+)''\s+(?..[^:]+):\s+line\s+(?\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 ''(?[^'']+)'' with id (?\d+)')) { - $result.MessageType = [PsesMessageType]::Request + ($line -match '^\s+Received Request ''(?[^'']+)'' with 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 ''(?[^'']+)''')) { - $result.MessageType = [PsesMessageType]::Notification + ($line -match '^\s+Received event ''(?[^'']+)''')) { + $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 ''(?[^'']+)'' with id (?\d+)')) { - $result.MessageType = [PsesMessageType]::Response + ($line -match '^\s+Writing Response ''(?[^'']+)'' with 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 ''(?[^'']+)''')) { - $result.MessageType = [PsesMessageType]::Notification + ($line -match '^\s+Writing event ''(?[^'']+)''')) { + $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 index 3f6cd2941..07db78cc2 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml @@ -23,8 +23,8 @@ right - - 13 + + 15 left @@ -45,7 +45,7 @@ ThreadId - MessageType + LogMessageType ($_.Message -split "`r`n")[0] diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 index 339fe3e92..1d6aea845 100644 --- 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 index 6fced1cf2..5497b17e0 100644 --- a/tools/PsesLogAnalyzer/Types.ps1 +++ b/tools/PsesLogAnalyzer/Types.ps1 @@ -6,8 +6,10 @@ enum PsesLogLevel { Error; } -enum PsesMessageType { +enum PsesLogMessageType { Log; + Exception; + HandledException; Request; Response; Notification; @@ -65,6 +67,10 @@ class PsesNotificationMessage { } [string] ToString() { + if (($this.Name -eq '$/cancelRequest') -and ($this.Data -ne $null)) { + return "Name: $($this.Name) Source: $($this.Source), Id: $($this.Data.params.id)" + } + return "Name: $($this.Name) Source: $($this.Source), DataSize: $($this.DataSize)" } } @@ -78,7 +84,7 @@ class PsesLogEntry { [string]$Method [string]$File [int]$LineNumber - [PsesMessageType]$MessageType + [PsesLogMessageType]$LogMessageType [psobject]$Message PsesLogEntry( @@ -98,8 +104,8 @@ class PsesLogEntry { $File, [int] $LineNumber, - [PsesMessageType] - $MessageType, + [PsesLogMessageType] + $LogMessageType, [psobject] $Message) { @@ -111,7 +117,7 @@ class PsesLogEntry { $this.Method = $Method $this.File = $File $this.LineNumber = $LineNumber - $this.MessageType = $MessageType + $this.LogMessageType = $LogMessageType $this.Message = $Message } } @@ -126,7 +132,7 @@ class PsesLogEntryElapsed { [string]$Method [string]$File [int]$LineNumber - [PsesMessageType]$MessageType + [PsesLogMessageType]$LogMessageType [psobject]$Message PsesLogEntryElapsed([PsesLogEntry]$LogEntry, [int]$ElapsedMilliseconds) { @@ -138,7 +144,7 @@ class PsesLogEntryElapsed { $this.Method = $LogEntry.Method $this.File = $LogEntry.File $this.LineNumber = $LogEntry.LineNumber - $this.MessageType = $LogEntry.MessageType + $this.LogMessageType = $LogEntry.LogMessageType $this.Message = $LogEntry.Message $this.ElapsedMilliseconds = $ElapsedMilliseconds From ef04cd6bb255cfb2fcec781574d4b1fa76aaa820 Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Tue, 27 Nov 2018 23:18:27 -0700 Subject: [PATCH 6/8] Change to PsesLogEntry as default parameterset --- tools/PsesLogAnalyzer/Analyze.ps1 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/PsesLogAnalyzer/Analyze.ps1 b/tools/PsesLogAnalyzer/Analyze.ps1 index 48d53ba8c..95629098c 100644 --- a/tools/PsesLogAnalyzer/Analyze.ps1 +++ b/tools/PsesLogAnalyzer/Analyze.ps1 @@ -43,7 +43,7 @@ function Get-PsesRpcNotificationMessage { } function Get-PsesRpcMessageResponseTime { - [CmdletBinding(DefaultParameterSetName="Path")] + [CmdletBinding(DefaultParameterSetName = "PsesLogEntry")] param( # Specifies a path to one or more PSES EditorServices log files. [Parameter(Mandatory=$true, Position=0, ParameterSetName="Path")] From e35b7d2a0130b5673da96ecd4075e6327949b510 Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Fri, 30 Nov 2018 16:48:19 -0700 Subject: [PATCH 7/8] Address PR feedback, adjust string builder size based on log file data --- .../MessageProtocol/MessageReader.cs | 8 +-- .../MessageProtocol/MessageWriter.cs | 8 +-- tools/PsesLogAnalyzer/Analyze.ps1 | 50 ++++++++++++++++++- .../PsesLogAnalyzer.format.ps1xml | 10 +++- tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 | 9 ++-- tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 | 2 - tools/PsesLogAnalyzer/Types.ps1 | 30 +++++------ 7 files changed, 87 insertions(+), 30 deletions(-) diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs index 57b9148f0..dcf7aaa94 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageReader.cs @@ -114,11 +114,11 @@ public async Task ReadMessage() Message parsedMessage = this.messageSerializer.DeserializeMessage(messageObject); // Log message info - initial capacity for StringBuilder varies depending on whether - // the log level is Diagnostic where JsonRpc message payloads are logged and - // vary from 1K up edited file size chars. When not logging message payloads the - // typical request log message is under 250 chars. + // the log level is Diagnostic where JsonRpc message payloads are logged and vary in size + // from 1K up to the edited file size. When not logging message payloads, the typical + // request log message size is under 256 chars. var logStrBld = - new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 250) + new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256) .Append("Received ") .Append(parsedMessage.MessageType) .Append(" '").Append(parsedMessage.Method).Append("'"); diff --git a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs index d0db043cf..f2082efba 100644 --- a/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs +++ b/src/PowerShellEditorServices.Protocol/MessageProtocol/MessageWriter.cs @@ -59,11 +59,11 @@ public async Task WriteMessage(Message messageToWrite) messageToWrite); // Log message info - initial capacity for StringBuilder varies depending on whether - // the log level is Diagnostic where JsonRpc message payloads are logged and - // vary from 1K up 225K chars. When not logging message payloads the typical response - // log message is under 250 chars. + // the log level is Diagnostic where JsonRpc message payloads are logged and vary + // in size from 1K up to 225K chars. When not logging message payloads, the typical + // response log message size is under 256 chars. var logStrBld = - new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 250) + new StringBuilder(this.logger.MinimumConfiguredLogLevel == LogLevel.Diagnostic ? 4096 : 256) .Append("Writing ") .Append(messageToWrite.MessageType) .Append(" '").Append(messageToWrite.Method).Append("'"); diff --git a/tools/PsesLogAnalyzer/Analyze.ps1 b/tools/PsesLogAnalyzer/Analyze.ps1 index 95629098c..19c942845 100644 --- a/tools/PsesLogAnalyzer/Analyze.ps1 +++ b/tools/PsesLogAnalyzer/Analyze.ps1 @@ -155,7 +155,7 @@ function Get-PsesIntelliSenseCompletionTime { } foreach ($entry in $logEntries) { - # IntelliSense completed in 320ms. + # IntelliSense completed in 320ms. if (($entry.LogMessageType -eq 'Log') -and ($entry.Message.Data -match '^\s*IntelliSense completed in\s+(?\d+)ms.\s*$')) { $elapsedMilliseconds = [int]$matches["ms"] [PsesLogEntryElapsed]::new($entry, $elapsedMilliseconds) @@ -163,3 +163,51 @@ function Get-PsesIntelliSenseCompletionTime { } } } + +function Get-PsesMessage { + [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 the log level entries to return. Default returns Normal and above. + # Use StrictMatch to return only the specified log level entries. + [Parameter()] + [PsesLogLevel] + $LogLevel = $([PsesLogLevel]::Normal), + + # Use StrictMatch to return only the specified log level entries. + [Parameter()] + [switch] + $StrictMatch + ) + + begin { + if ($PSCmdlet.ParameterSetName -eq "Path") { + $logEntries = Parse-PsesLog $Path + } + } + + process { + if ($PSCmdlet.ParameterSetName -eq "PsesLogEntry") { + $logEntries = $LogEntry + } + + foreach ($entry in $logEntries) { + if (($StrictMatch -and ($entry.LogLevel -eq $LogLevel)) -or + (!$StrictMatch -and ($entry.LogLevel -ge $LogLevel))) { + $entry + } + } + } +} diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml index 07db78cc2..5c6ba1823 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.format.ps1xml @@ -27,6 +27,11 @@ 15 left + + + 11 + left + left @@ -37,7 +42,7 @@ Index - + TimestampStr @@ -47,6 +52,9 @@ LogMessageType + + LogLevel + ($_.Message -split "`r`n")[0] diff --git a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 index 1d6aea845..10c225ee7 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psd1 @@ -27,13 +27,13 @@ Author = 'Microsoft' CompanyName = 'Microsoft' # Copyright statement for this module -Copyright = '(c) 2017 Microsoft. All rights reserved.' +Copyright = '(c) 2018 Microsoft. All rights reserved.' # Description of the functionality provided by this module -# Description = '' +Description = 'PowerShellEditorServices log file parser and analysis commands.' # Minimum version of the PowerShell engine required by this module -# PowerShellVersion = '' +PowerShellVersion = '5.1' # Name of the PowerShell host required by this module # PowerShellHostName = '' @@ -74,7 +74,8 @@ FunctionsToExport = @( 'Get-PsesRpcMessageResponseTime', 'Get-PsesRpcNotificationMessage', 'Get-PsesScriptAnalysisCompletionTime', - 'Get-PsesIntelliSenseCompletionTime' + 'Get-PsesIntelliSenseCompletionTime', + 'Get-PsesMessage' ) # 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/PsesLogAnalyzer.psm1 b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 index 6d36fd33f..700946c40 100644 --- a/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 +++ b/tools/PsesLogAnalyzer/PsesLogAnalyzer.psm1 @@ -1,5 +1,3 @@ . $PSScriptRoot\Types.ps1 . $PSScriptRoot\Parse-PsesLog.ps1 . $PSScriptRoot\Analyze.ps1 - -Export-ModuleMember -Function *-* diff --git a/tools/PsesLogAnalyzer/Types.ps1 b/tools/PsesLogAnalyzer/Types.ps1 index 5497b17e0..dd7a9fa1a 100644 --- a/tools/PsesLogAnalyzer/Types.ps1 +++ b/tools/PsesLogAnalyzer/Types.ps1 @@ -1,31 +1,33 @@ enum PsesLogLevel { - Diagnostic; - Verbose; - Normal; - Warning; - Error; + Diagnostic + Verbose + Normal + Warning + Error } enum PsesLogMessageType { - Log; - Exception; - HandledException; - Request; - Response; - Notification; + Log + Exception + HandledException + Request + Response + Notification } enum PsesNotificationSource { - Unknown; - Client; - Server; + Unknown + Client + Server } class PsesLogMessage { [string]$Data + [int]$DataSize PsesLogMessage([string]$Data) { $this.Data = $Data + $this.DataSize = $Data.Length } [string] ToString() { From c3dbbbc63bdd90bf8511eddb6fc2ff4ebe84cead Mon Sep 17 00:00:00 2001 From: Keith Hill Date: Mon, 3 Dec 2018 10:01:02 -0700 Subject: [PATCH 8/8] Address PR feedback - remove unnecessary else --- tools/PsesLogAnalyzer/Parse-PsesLog.ps1 | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 index 9748f4bec..83263e2b7 100644 --- a/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 +++ b/tools/PsesLogAnalyzer/Parse-PsesLog.ps1 @@ -240,10 +240,9 @@ function Parse-PsesLog { parseLogMessageBody -Discard return $result } - else { - $result.Data = parseLogMessageBody - $result.DataSize = $result.Data.Length - } + + $result.Data = parseLogMessageBody + $result.DataSize = $result.Data.Length try { $result.Data = $result.Data.Trim() | ConvertFrom-Json