v1.0.0: Handle Logs with Overlapping Threads (#14)

* v1.0.0: Handle Logs with Overlapping Threads

* Bump Pester. Fix tests.

* Tweak test verbs

Author: HeyItsGilbert

.vscode/launch.json

@@ -10,7 +10,8 @@
         "-Task Test",
         "-Verbose"
       ],
-      "cwd": "${workspaceFolder}"
+      "cwd": "${workspaceFolder}",
+      "createTemporaryIntegratedConsole": true
     }
   ]
 }

.vscode/tasks.json

@@ -2,33 +2,42 @@
     // See https://go.microsoft.com/fwlink/?LinkId=733558
     // for the documentation about the tasks.json format
     "version": "2.0.0",
-
     // Start PowerShell (pwsh on *nix)
     "windows": {
         "options": {
             "shell": {
-                "executable": "powershell.exe",
-                "args": [ "-NoProfile", "-ExecutionPolicy", "Bypass", "-Command" ]
+                "executable": "pwsh.exe",
+                "args": [
+                    "-NoProfile",
+                    "-ExecutionPolicy",
+                    "Bypass",
+                    "-Command"
+                ]
             }
         }
     },
     "linux": {
         "options": {
             "shell": {
                 "executable": "/usr/bin/pwsh",
-                "args": [ "-NoProfile", "-Command" ]
+                "args": [
+                    "-NoProfile",
+                    "-Command"
+                ]
             }
         }
     },
     "osx": {
         "options": {
             "shell": {
                 "executable": "/usr/local/bin/pwsh",
-                "args": [ "-NoProfile", "-Command" ]
+                "args": [
+                    "-NoProfile",
+                    "-Command"
+                ]
             }
         }
     },
-
     "tasks": [
         {
             "label": "Clean",

CHANGELOG.md

@@ -5,6 +5,23 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/)
 and this project adheres to [Semantic Versioning](http://semver.org/).
 
+## [1.0.0] Handle Logs with Out of Order Threads
+
+### Added
+
+- Bump Log4NetParse dependency to 1.1.1 which handles threads better.
+- Add TypeAccelerator for ChocoLog
+
+## Removed
+
+- Logs no longer returned for Log4NetLog format. It was suggested that
+  this was noisy.
+
+### Fixes
+
+- Handle when logs that have thread lines that overlap.
+- Fix tests to handle logs dates and ordering.
+
 ## [0.5.0] Add Get-ChocoLogEntry
 
 - Add a new cmdlet that grabs the latest log.

ChocoLogParse/ChocoLog.format.ps1xml

@@ -23,9 +23,6 @@
           <TableColumnHeader>
             <Label>Command Line</Label>
           </TableColumnHeader>
-          <TableColumnHeader>
-            <Label>Log Lines</Label>
-          </TableColumnHeader>
         </TableHeaders>
         <TableRowEntries>
           <TableRowEntry>
@@ -52,9 +49,6 @@
                 [String]::Format("{0}", ($_.cli -replace '"C:\\ProgramData\\chocolatey\\choco.exe"', 'choco'))
                 </ScriptBlock>
               </TableColumnItem>
-              <TableColumnItem>
-                <PropertyName>logs</PropertyName>
-              </TableColumnItem>
             </TableColumnItems>
             <Wrap/>
           </TableRowEntry>

ChocoLogParse/ChocoLogParse.psd1

@@ -12,7 +12,7 @@
   RootModule = 'ChocoLogParse.psm1'
 
   # Version number of this module.
-  ModuleVersion = '0.5.0'
+  ModuleVersion = '1.0.0'
 
   # Supported PSEditions
   # CompatiblePSEditions = @()
@@ -24,7 +24,7 @@
   Author = 'Gilbert Sanchez'
 
   # Company or vendor of this module
-  CompanyName = 'Unknown'
+  CompanyName = 'Gilbert Sanchez'
 
   # Copyright statement for this module
   Copyright = '(c) Gilbert Sanchez. All rights reserved.'
@@ -51,7 +51,7 @@
   # ProcessorArchitecture = ''
 
   # Modules that must be imported into the global environment prior to importing this module
-  RequiredModules = @(@{ModuleName = "Log4NetParse"; ModuleVersion = "0.3.0"; })
+  RequiredModules = @(@{ModuleName = "Log4NetParse"; ModuleVersion = "1.1.1"; })
 
   # Assemblies that must be loaded prior to importing this module
   # RequiredAssemblies = @()

ChocoLogParse/ChocoLogParse.psm1

@@ -15,3 +15,42 @@ $format = Join-Path -Path $PSScriptRoot -ChildPath 'ChocoLog.format.ps1xml'
 Update-FormatData -PrependPath $format
 
 Export-ModuleMember -Function $public.Basename
+
+# This module is combined. Any code in this file as added to the very end.
+
+# Define the types to export with type accelerators.
+$ExportableTypes = @(
+  [ChocoLog]
+)
+# Get the internal TypeAccelerators class to use its static methods.
+$TypeAcceleratorsClass = [psobject].Assembly.GetType(
+  'System.Management.Automation.TypeAccelerators'
+)
+# Ensure none of the types would clobber an existing type accelerator.
+# If a type accelerator with the same name exists, throw an exception.
+$ExistingTypeAccelerators = $TypeAcceleratorsClass::Get
+foreach ($Type in $ExportableTypes) {
+  if ($Type.FullName -in $ExistingTypeAccelerators.Keys) {
+    $Message = @(
+      "Unable to register type accelerator '$($Type.FullName)'"
+      'Accelerator already exists.'
+    ) -join ' - '
+
+    throw [System.Management.Automation.ErrorRecord]::new(
+      [System.InvalidOperationException]::new($Message),
+      'TypeAcceleratorAlreadyExists',
+      [System.Management.Automation.ErrorCategory]::InvalidOperation,
+      $Type.FullName
+    )
+  }
+}
+# Add type accelerators for every exportable type.
+foreach ($Type in $ExportableTypes) {
+  [void]$TypeAcceleratorsClass::Add($Type.FullName, $Type)
+}
+# Remove type accelerators when the module is removed.
+$MyInvocation.MyCommand.ScriptBlock.Module.OnRemove = {
+  foreach ($Type in $ExportableTypes) {
+    [void]$TypeAcceleratorsClass::Remove($Type.FullName)
+  }
+}.GetNewClosure()

ChocoLogParse/Classes/ChocoLog.ps1

@@ -1,24 +1,20 @@
 using module Log4NetParse
 
 class ChocoLog : Log4NetLog {
-  [string]$cli
-  [string]$exitCode
-  [LogType]$logType
+  [string]$CLI
+  [string]$ExitCode
+  [LogType]$LogType
   [hashtable]$Configuration
 
   ChocoLog(
     [int]$Thread,
-    [datetime]$startTime,
     [string]$filePath
   ) : base (
     $Thread,
-    $startTime,
     $filePath
   ) {
-    $this.thread = $Thread
-    $this.startTime = $startTime
-    $this.logs = [System.Collections.Generic.List[Log4NetLogLine]]::new()
-    $this.filePath = $filePath
+    $this.Thread = $Thread
+    $this.FilePath = $filePath
     $this.Configuration = @{}
     if ($filePath -like "*summary*") {
       $this.logType = [LogType]::Summary
@@ -30,10 +26,12 @@ class ChocoLog : Log4NetLog {
   # This parses all the logs for entries that are part of the class
   [void] ParseSpecialLogs() {
     # Set the end time here since we are done parsing
-    $this.endTime = $this.logs[-1].time
+    $this._logs.Sort()
+    $this.StartTime = $this._logs[0].time
+    $this.EndTime = $this._logs[-1].time
 
     # Detect known patterns
-    $this.logs | ForEach-Object {
+    $this._logs | ForEach-Object {
       switch ($_.message) {
         { $_.StartsWith('Command line: ') } { $this.SetCli($_) }
         { $_.StartsWith('Exiting with ') } { $this.SetExitCode($_) }
@@ -42,7 +40,6 @@ class ChocoLog : Log4NetLog {
         }
         Default {}
       }
-
     }
   }
 

ChocoLogParse/Public/Read-ChocoLog.ps1

@@ -43,61 +43,56 @@ function Read-ChocoLog {
     [string]
     $PatternLayout = '%date %thread [%-5level] - %message'
   )
-
   $files = Get-Item -Path $Path
   if ($files.PSIsContainer) {
-    $files = Get-ChildItem -Path $Path -Filter $Filter | Sort-Object -Property LastWriteTime | Select-Object -Last $FileLimit
+    $files = Get-ChildItem -Path $Path -Filter $Filter |
+      Sort-Object -Property LastWriteTime | Select-Object -Last $FileLimit
   }
+  Write-Verbose "Found files: $($files -join ',')"
 
-  [System.Collections.Generic.List[ChocoLog]]$parsed = @()
-  $detected = [System.Collections.Generic.List[int]]::new()
-
-  $RegularExpression = Convert-PatternLayout $PatternLayout
+  $parsed = @{}
 
+  # Get the regex for the Log4Net PatternLayout
+  $RegularExpression = Convert-PatternLayout -PatternLayout $PatternLayout
   $files | ForEach-Object -Process {
     $file = $_
+    Write-Verbose "Reading over file: $file"
     $raw = [System.IO.File]::ReadAllLines($file.FullName)
-
+    Write-Verbose "Lines read: $($raw.Count)"
     # Iterate over each line
     foreach ($line in $raw) {
-      # Write-Debug $line
+      Write-Debug $line
       $m = $RegularExpression.match($line)
       if ($m.Success) {
-        $threadMatch = $m.Groups['thread'].Value
-        # If it matches the regex, tag it
-        if ($threadMatch -ne $currentSession.thread) {
-          # This is a different thread
-
-          # Save the current session to the parsed list
-          if ($currentSession) {
-            $parsed.Add($currentSession) > $null
-          }
-
-          # Look up if current thread exists in Parsed and append to that if so
-          if ($detected.Contains($threadMatch)) {
-            $currentSession = $parsed | Where-Object { $_.Thread -eq $threadMatch }
-          } else {
-            # We haven't seen this thread before, let's make a new object
-            $detected.Add($threadMatch) > $null
-            $currentSession = [ChocoLog]::new(
+        [int]$threadMatch = $m.Groups['thread'].Value
+        # Replace comma with period to make it a valid datetime
+        [datetime]$currentDateTime = $m.Groups['date'].Value -replace ',', '.'
+        # Check if thread exists, if not make it.
+        if (-not ($parsed.ContainsKey($threadMatch))) {
+          Write-Verbose "New thread detected: $threadMatch"
+          $null = $parsed.Add(
+            $threadMatch,
+            [ChocoLog]::new(
               $threadMatch,
-              ($m.Groups['date'].Value -replace ',', '.'),
               $file
             )
-          }
+          )
         }
-
-        $currentSession.logs.Add(
+        Write-Verbose "Adding new log line to thread $threadMatch"
+        $parsed.Item($threadMatch).AddLogLine(
           [Log4NetLogLine]::new(
-            [Datetime]($m.Groups['date'].Value -replace ',', '.'),
+            $currentDateTime,
             $threadMatch,
             $m.Groups['level'].Value,
             $m.Groups['message'].Value
-          )) > $null
+          ))
       } else {
+        Write-Verbose "Line did not match regex"
+        Write-Debug $line
         # if it doesn't match regex, append to the previous
-        if ($currentSession) {
-          $currentSession.logs[-1].AppendMessage($line)
+        if ($threadMatch) {
+          Write-Verbose "Appending to existing thread: $threadMatch"
+          $parsed.Item($threadMatch).AppendLastLogLine($line)
         } else {
           # This might happen if the log starts on what should have been a
           # multiline entry... Not very likely
@@ -106,17 +101,15 @@ function Read-ChocoLog {
       }
     }
   }
-  # Write out the last log line!
-  if (-Not $parsed.Contains($currentSession)) {
-    $parsed.Add($currentSession) > $null
-  }
 
   # Doing this at the end since threads can get mixed
-  $parsed | ForEach-Object {
+  $parsed.Keys | ForEach-Object {
+    Write-Verbose "Parsing special logs for: $_"
     # This updates fields like: cli, environment, and configuration
-    $_.ParseSpecialLogs()
+    $parsed.Item($_).ParseSpecialLogs()
   }
 
   # Return the whole parsed object
-  $parsed
+  Write-Verbose "Returning results in desceding order. Count: $($parsed.Count)"
+  $parsed.Values | Sort-Object -Descending Time
 }