From 0276fbaf062099e9122b62b39f85c12441e039de Mon Sep 17 00:00:00 2001 From: fadwen <110697945+fadwen@users.noreply.github.com> Date: Tue, 6 Oct 2026 01:06:39 -0700 Subject: [PATCH] perf(logs): filters before the entry is built, one expression for the event table Get-IntuneAgentLog built an object for every record of every log, then filtered, then classified each entry with a call that tried 44 regular expressions one by one. Each of those is a PowerShell statement run 80,000 times for a 15 MB log, and together they were most of what a read cost: 62 s for every entry, 25 s for one policy's entries, 90 s for an event filter with -Last. ConvertFrom-IslCmTraceLog takes the filters Get-IntuneAgentLog offers (-Level, -After, -Before, -Pattern, -Id, and -Contains for the literal text the wanted events' patterns start with) and applies them to the raw record, so an entry nobody wants is never built; the line number is counted over the skipped text in one call per kept entry. The attribute regexes are compiled once; the timestamp is one TryParseExact instead of two regexes and six conversions. Get-IslAgentLogEvent takes a batch of messages and matches one combined expression per message, every group named, the matched alternative found with Enumerable.FirstOrDefault rather than a loop over 44 candidates; alternation keeps the table's order at a position, so a message two patterns fit resolves as before. Get-IntuneAgentLog classifies a file's kept messages in one call and skips a rolled-over file last written before -After. Measured on the 15 MB log, fresh process, PowerShell 7.6: every entry 30 s against 62 s; -Id 5 s against 25 s; -EventName -Last 12 s against 90 s; a timeline by id 5 s against 26 s. Same entries in every case. --- CHANGELOG.md | 6 + Private/ConvertFrom-IslCmTraceLog.ps1 | 124 ++++++++++-- Private/ConvertTo-IslCmTraceTime.ps1 | 25 +-- Private/Get-IslAgentLogEvent.ps1 | 183 +++++++++++++++--- Public/Get-IntuneAgentLog.ps1 | 49 +++-- .../ConvertFrom-IslCmTraceLog.Tests.ps1 | 17 ++ .../Private/Get-IslAgentLogEvent.Tests.ps1 | 35 ++++ .../Unit/Public/Get-IntuneAgentLog.Tests.ps1 | 13 ++ 8 files changed, 377 insertions(+), 75 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 056e373..4484a2b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -65,6 +65,12 @@ release notes. detection, 60 scripts in 5.4 s against 14.0 s. Every rule walked the syntax tree itself, some once per command name they look for; the tree is now walked once per script and the nodes indexed by type and the commands by name, and the rules read the index. Findings are unchanged. +- `Get-IntuneAgentLog` and `Get-IntuneAgentTimeline` read a large log in a fraction of the time. On a 15 MB + agent log of 80,000 entries: every entry in 30 s against 62 s; the entries of one policy, by `-Id`, in + 5 s against 25 s; `-EventName` with `-Last` in 12 s against 90 s; a timeline by id in 5 s against 26 s. + The filters now run on the raw record before an entry is built, which was most of an entry's cost; the + 44 event patterns are one expression matched once per message instead of 44 statements; a rolled-over + file last written before `-After` is not read at all. Results are unchanged. ## [0.27.0] - 2026-10-05 Fixes to the runtime harness and to four rules, each rule change backed by a tenth validation diff --git a/Private/ConvertFrom-IslCmTraceLog.ps1 b/Private/ConvertFrom-IslCmTraceLog.ps1 index 12d872b..51ec34a 100644 --- a/Private/ConvertFrom-IslCmTraceLog.ps1 +++ b/Private/ConvertFrom-IslCmTraceLog.ps1 @@ -15,19 +15,62 @@ function ConvertFrom-IslCmTraceLog { Message, Log (the file's base name) and Line (the line the entry starts on). Event, Detail and Id are left empty for Get-IntuneAgentLog to fill. + The filters are the ones Get-IntuneAgentLog offers, applied to the raw record before an + object is built for it. Building the object is most of what an entry costs, so a filtered + read of a 22 MB log takes seconds where building every entry takes a minute. + .PARAMETER Path The log file to parse. + .PARAMETER Level + Keep entries of these levels only: Information, Warning, Error. + + .PARAMETER After + Keep entries at or after this local time. + + .PARAMETER Before + Keep entries before this local time. + + .PARAMETER Pattern + Keep entries whose message matches this regular expression, case-insensitive like -match. + + .PARAMETER Id + Keep entries whose message contains any of these strings, case-insensitive; a policy or + app id, usually. + + .PARAMETER Contains + Keep entries whose message contains any of these strings, case-sensitive. Get-IntuneAgentLog + passes the literal text the wanted events' patterns start with, so a message that can match + none of them is dropped before the pattern runs. + .EXAMPLE ConvertFrom-IslCmTraceLog -Path 'C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\HealthScripts.log' Every entry of the remediation log as objects. + + .EXAMPLE + ConvertFrom-IslCmTraceLog -Path .\AppWorkload.log -Id 9b6543c3-6d66-4cfb-a8fb-d780079278f6 -Level Error + + The error entries that mention the app, without building the others. #> [CmdletBinding()] [OutputType('IntuneScriptLab.AgentLogEntry')] param( [Parameter(Mandatory)] - [string]$Path + [string]$Path, + + [ValidateSet('Information', 'Warning', 'Error')] + [string[]]$Level, + + [datetime]$After, + + [datetime]$Before, + + [string]$Pattern, + + [string[]]$Id, + + [string[]]$Contains ) $file = (Resolve-Path -LiteralPath $Path -ErrorAction Stop).ProviderPath @@ -42,38 +85,83 @@ function ConvertFrom-IslCmTraceLog { } $levels = @{ '1' = 'Information'; '2' = 'Warning'; '3' = 'Error' } + $wantedTypes = if ($Level) { @($levels.Keys | Where-Object { $levels[$_] -in $Level }) } else { $null } + $hasAfter = $PSBoundParameters.ContainsKey('After') + $hasBefore = $PSBoundParameters.ContainsKey('Before') + $ordinalIgnoreCase = [System.StringComparison]::OrdinalIgnoreCase + $ordinal = [System.StringComparison]::Ordinal + + # An agent log of 22 MB is 80,000 entries, and every statement here runs once per entry. The + # attributes come out of one compiled regex in the order the agent writes them, the timestamp + # is read the way ConvertTo-IslCmTraceTime reads it without the call, and the filters run on + # the raw strings before anything is built. Lines are counted only up to an entry that is kept + $attributeRegex = $script:IslCmTraceAttributeRegex + $timeFormat = $script:IslCmTraceTimeFormat + $invariant = [cultureinfo]::InvariantCulture + $noStyle = [System.Globalization.DateTimeStyles]::None + $biasChars = [char[]]@('+', '-') $logName = [System.IO.Path]::GetFileNameWithoutExtension($file) $entryPattern = '.*?)\]LOG\]!>[^"]*)" date="(?[^"]*)"' + '(?[^>]*)>' $entryRegex = [regex]::new($entryPattern, [System.Text.RegularExpressions.RegexOptions]::Singleline) $line = 1 - $scanned = 0 + $counted = 0 foreach ($match in $entryRegex.Matches($text)) { - # Line numbers accumulate as the matches advance, so the text is scanned once - while ($true) { - $newline = $text.IndexOf("`n", $scanned, $match.Index - $scanned) - if ($newline -lt 0) { break } - $line++ - $scanned = $newline + 1 + $groups = $match.Groups + $attributeMatch = $attributeRegex.Match($groups['attributes'].Value) + $type = if ($attributeMatch.Success) { $attributeMatch.Groups[2].Value } else { '1' } + if ($wantedTypes -and $type -notin $wantedTypes) { continue } + + $message = $groups['message'].Value + if ($Pattern -and $message -notmatch $Pattern) { continue } + if ($Id) { + $mentioned = $false + foreach ($value in $Id) { + if ($message.IndexOf($value, $ordinalIgnoreCase) -ge 0) { $mentioned = $true; break } + } + if (-not $mentioned) { continue } + } + if ($Contains) { + $present = $false + foreach ($value in $Contains) { + if ($message.IndexOf($value, $ordinal) -ge 0) { $present = $true; break } + } + if (-not $present) { continue } + } + + $timeText = $groups['time'].Value + $bias = $timeText.IndexOfAny($biasChars, [Math]::Min(7, $timeText.Length)) + if ($bias -ge 0) { $timeText = $timeText.Substring(0, $bias) } + $time = [datetime]::MinValue + $stamp = "$($groups['date'].Value) $timeText" + if (-not [datetime]::TryParseExact($stamp, $timeFormat, $invariant, $noStyle, [ref]$time)) { + throw "Not a CMTrace timestamp: $stamp ($file)" + } + if ($hasAfter -and $time -lt $After) { continue } + if ($hasBefore -and $time -ge $Before) { continue } + + # The newlines between the last kept entry and this one, in one .NET call + if ($match.Index -gt $counted) { + $line += $text.Substring($counted, $match.Index - $counted).Split("`n").Length - 1 + $counted = $match.Index } - $scanned = $match.Index - $attributes = $match.Groups['attributes'].Value - $component = if ($attributes -match 'component="([^"]*)"') { $Matches[1] } else { '' } - $type = if ($attributes -match 'type="(\d)"') { $Matches[1] } else { '1' } - $thread = if ($attributes -match 'thread="(\d+)"') { [int]$Matches[1] } else { $null } - $timeSplat = @{ Time = $match.Groups['time'].Value; Date = $match.Groups['date'].Value } [pscustomobject]@{ PSTypeName = 'IntuneScriptLab.AgentLogEntry' - Time = ConvertTo-IslCmTraceTime @timeSplat + Time = $time Level = if ($levels.ContainsKey($type)) { $levels[$type] } else { 'Information' } - Component = $component - Thread = $thread + Component = if ($attributeMatch.Success) { $attributeMatch.Groups[1].Value } else { '' } + Thread = if ($attributeMatch.Success) { [int]$attributeMatch.Groups[3].Value } else { $null } Event = $null Detail = $null Id = $null - Message = $match.Groups['message'].Value.TrimEnd("`r", "`n") + Message = $message.TrimEnd("`r", "`n") Log = $logName Line = $line } } } + +# component, then type, then thread, in the order every agent log writes them; context and file +# sit between and after them and are not read +$script:IslCmTraceAttributeRegex = [regex]::new('component="([^"]*)".*?type="(\d)".*?thread="(\d+)"', + [System.Text.RegularExpressions.RegexOptions]::Compiled) diff --git a/Private/ConvertTo-IslCmTraceTime.ps1 b/Private/ConvertTo-IslCmTraceTime.ps1 index 49c846e..d573c6b 100644 --- a/Private/ConvertTo-IslCmTraceTime.ps1 +++ b/Private/ConvertTo-IslCmTraceTime.ps1 @@ -30,17 +30,18 @@ function ConvertTo-IslCmTraceTime { [string]$Date ) - $timeMatch = [regex]::Match($Time, '^(\d{1,2}):(\d{2}):(\d{2})(?:\.(\d{1,7}))?') - $dateMatch = [regex]::Match($Date, '^(\d{1,2})-(\d{1,2})-(\d{4})$') - if (-not $timeMatch.Success -or -not $dateMatch.Success) { - throw "Not a CMTrace timestamp: date=$Date time=$Time" - } - $timeParts = $timeMatch.Groups - $dateParts = $dateMatch.Groups - $value = [datetime]::new([int]$dateParts[3].Value, [int]$dateParts[1].Value, [int]$dateParts[2].Value, - [int]$timeParts[1].Value, [int]$timeParts[2].Value, [int]$timeParts[3].Value) - if ($timeParts[4].Success) { - $value = $value.AddTicks([long]$timeParts[4].Value.PadRight(7, '0')) - } + # This runs once per log entry. The bias is cut off at the first + or - after the seconds, and + # one TryParseExact reads the rest: the F specifiers take any number of fraction digits up to + # seven, and none at all + $bias = $Time.IndexOfAny([char[]]@('+', '-'), [Math]::Min(7, $Time.Length)) + $plain = if ($bias -ge 0) { $Time.Substring(0, $bias) } else { $Time } + $value = [datetime]::MinValue + $parsed = [datetime]::TryParseExact("$Date $plain", $script:IslCmTraceTimeFormat, + [cultureinfo]::InvariantCulture, [System.Globalization.DateTimeStyles]::None, [ref]$value) + if (-not $parsed) { throw "Not a CMTrace timestamp: date=$Date time=$Time" } $value } + +# M-d-yyyy and H:mm:ss as the agent writes them: no leading zero on the month, day or hour is +# required, and the fraction is optional +$script:IslCmTraceTimeFormat = 'M-d-yyyy H:mm:ss.FFFFFFF' diff --git a/Private/Get-IslAgentLogEvent.ps1 b/Private/Get-IslAgentLogEvent.ps1 index 6fb1981..6991b95 100644 --- a/Private/Get-IslAgentLogEvent.ps1 +++ b/Private/Get-IslAgentLogEvent.ps1 @@ -18,7 +18,8 @@ function Get-IslAgentLogEvent { in the module scope as IslAgentLogEvents for Get-IntuneAgentLog -ListEvent. .PARAMETER Message - The log entry's message. + The log entries' messages; one result per message, in the same order. A call per entry + costs more than the classification, so Get-IntuneAgentLog sends a log's messages in one. .EXAMPLE Get-IslAgentLogEvent -Message 'Powershell execution is done, exitCode = 1' @@ -30,7 +31,8 @@ function Get-IslAgentLogEvent { param( [Parameter(Mandatory)] [AllowEmptyString()] - [string]$Message + [AllowEmptyCollection()] + [string[]]$Message ) if (-not $script:IslAgentLogEvents) { @@ -157,40 +159,167 @@ function Get-IslAgentLogEvent { } @{ Event = 'ExecutorError'; Pattern = '^error from script =(.*)$' } ) + # The literal text a pattern starts with, which a matching message must contain somewhere: + # cheaper to look for than to run the pattern, and most messages match no pattern at all. + # Read up to the first metacharacter; an escaped punctuation character is a literal, an + # escaped letter is a class. A quantifier would make the last literal optional, so it goes + function Get-LiteralPrefix { + param([string]$Pattern) + $literal = [System.Text.StringBuilder]::new() + $index = if ($Pattern.StartsWith('^')) { 1 } else { 0 } + while ($index -lt $Pattern.Length) { + $character = $Pattern[$index] + if ($character -eq '\') { + if ($index + 1 -ge $Pattern.Length) { break } + $next = $Pattern[$index + 1] + if ([char]::IsLetterOrDigit($next)) { break } + $null = $literal.Append($next) + $index += 2 + continue + } + if ('()[]{}.*+?|^$'.IndexOf($character) -ge 0) { break } + $null = $literal.Append($character) + $index++ + } + if ($index -lt $Pattern.Length -and '*?{'.IndexOf($Pattern[$index]) -ge 0 -and $literal.Length) { + $literal.Length-- + } + $literal.ToString() + } + # The same pattern with its capturing groups named , so every group of the + # combined expression below has a name and the matched alternative is the first group that + # succeeded. A "(" opens a capture unless it is escaped, inside a class, or followed by "?" + function ConvertTo-NamedGroup { + param([string]$Pattern, [string]$Prefix) + $named = [System.Text.StringBuilder]::new() + $count = 0 + $inClass = $false + for ($index = 0; $index -lt $Pattern.Length; $index++) { + $character = $Pattern[$index] + if ($character -eq '\' -and $index + 1 -lt $Pattern.Length) { + $null = $named.Append($character).Append($Pattern[$index + 1]) + $index++ + continue + } + if ($inClass) { + if ($character -eq ']') { $inClass = $false } + $null = $named.Append($character) + continue + } + if ($character -eq '[') { $inClass = $true } + $opensCapture = $character -eq '(' -and + ($index + 1 -ge $Pattern.Length -or $Pattern[$index + 1] -ne '?') + if ($opensCapture) { + $count++ + $null = $named.Append("(?<$Prefix$count>") + continue + } + $null = $named.Append($character) + } + @{ Pattern = $named.ToString(); Count = $count } + } + # One expression for the whole table: 44 patterns tried one by one cost 44 statements a + # message, which was most of what reading a log cost; one Match is one. Alternation keeps + # the table's order at a given position, so two patterns that fit the same text still + # resolve to the earlier one $singleline = [System.Text.RegularExpressions.RegexOptions]::Singleline + $combined = [System.Text.StringBuilder]::new() + $position = 0 $script:IslAgentLogEvents = @(foreach ($definition in $definitions) { + $prefix = Get-LiteralPrefix -Pattern $definition.Pattern + $group = "e$position" + $renamed = ConvertTo-NamedGroup -Pattern $definition.Pattern -Prefix "${group}g" + if ($position -gt 0) { $null = $combined.Append('|') } + $null = $combined.Append("(?<$group>").Append($renamed.Pattern).Append(')') + $position++ [pscustomobject]@{ - Event = $definition.Event - Regex = [regex]::new($definition.Pattern, $singleline) + Event = $definition.Event + Regex = [regex]::new($definition.Pattern, $singleline) + Needle = if ($prefix.Length -ge 3) { $prefix } else { $null } + Group = $group + Captures = $renamed.Count } }) + $script:IslAgentLogEventByGroup = @{} + foreach ($definition in $script:IslAgentLogEvents) { + $script:IslAgentLogEventByGroup[$definition.Group] = $definition + } + $compiled = $singleline -bor [System.Text.RegularExpressions.RegexOptions]::Compiled + $script:IslAgentLogEventRegex = [regex]::new($combined.ToString(), $compiled) } - $eventName = $null - $detail = $null - foreach ($candidate in $script:IslAgentLogEvents) { - $match = $candidate.Regex.Match($Message) - if (-not $match.Success) { continue } - $eventName = $candidate.Event - $groups = @(for ($i = 1; $i -lt $match.Groups.Count; $i++) { $match.Groups[$i].Value.Trim() }) - $detail = ($groups | Where-Object { $_ }) -join ' ' - if (-not $detail) { $detail = $null } - break - } + $combinedRegex = $script:IslAgentLogEventRegex + $byGroup = $script:IslAgentLogEventByGroup + $firstSuccess = $script:IslAgentLogFirstSuccess # The policy or app id is the first GUID that is not the empty one: the device's user id on a # userless check-in is 00000000-... and comes before the policy id on some lines - $guidPattern = '[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}' - $id = $null - foreach ($match in [regex]::Matches($Message, $guidPattern)) { - $candidate = $match.Value.ToLower() - if ($null -eq $id) { $id = $candidate } - if ($candidate -ne '00000000-0000-0000-0000-000000000000') { $id = $candidate; break } - } + $guidRegex = $script:IslAgentLogGuidRegex + foreach ($text in $Message) { + $eventName = $null + $detail = $null + $match = $combinedRegex.Match($text) + if ($match.Success) { + # Group 0 is the whole match; the first successful group after it is the alternative + $winner = & $firstSuccess $match.Groups + $definition = $byGroup[$winner.Name] + $eventName = $definition.Event + $groups = @(for ($i = 1; $i -le $definition.Captures; $i++) { + $match.Groups["$($definition.Group)g$i"].Value.Trim() + }) + $detail = ($groups | Where-Object { $_ }) -join ' ' + if (-not $detail) { $detail = $null } + } + $id = $null + # A GUID has four hyphens; a message without one has no id to look for + if ($text.IndexOf('-') -ge 0) { + foreach ($match in $guidRegex.Matches($text)) { + $candidate = $match.Value.ToLower() + if ($null -eq $id) { $id = $candidate } + if ($candidate -ne '00000000-0000-0000-0000-000000000000') { $id = $candidate; break } + } + } - [pscustomobject]@{ - PSTypeName = 'IntuneScriptLab.AgentLogEvent' - Event = $eventName - Detail = $detail - Id = $id + [pscustomobject]@{ + PSTypeName = 'IntuneScriptLab.AgentLogEvent' + Event = $eventName + Detail = $detail + Id = $id + } } } + +$script:IslAgentLogGuidRegex = [regex]::new( + '[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}', + [System.Text.RegularExpressions.RegexOptions]::Compiled) + +# The first group after group 0 that took part in a match, found without a PowerShell loop over the +# groups: Enumerable.Skip(1) then FirstOrDefault with Group.Success as the predicate. The generic +# methods are closed by reflection once, because Windows PowerShell 5.1 has no syntax for it, and +# GroupCollection is cast to IEnumerable first because .NET Framework's is not one +$script:IslAgentLogFirstSuccess = & { + $groupType = [System.Text.RegularExpressions.Group] + $enumerable = [System.Linq.Enumerable] + $cast = $enumerable.GetMethod('Cast').MakeGenericMethod($groupType) + $skip = ($enumerable.GetMethods() | Where-Object { + $_.Name -eq 'Skip' -and $_.GetParameters()[1].ParameterType -eq [int] + } | Select-Object -First 1).MakeGenericMethod($groupType) + $first = ($enumerable.GetMethods() | Where-Object { + $_.Name -eq 'FirstOrDefault' -and $_.GetParameters().Count -eq 2 -and + $_.GetParameters()[1].ParameterType.Name -like 'Func*' + } | Select-Object -First 1).MakeGenericMethod($groupType) + $success = [System.Delegate]::CreateDelegate([System.Func[System.Text.RegularExpressions.Group, bool]], + $groupType.GetProperty('Success').GetGetMethod()) + { + param($Groups) + # Argument arrays built by hand: PowerShell would enumerate the collection into @() + $castArguments = [object[]]::new(1) + $castArguments[0] = $Groups + $skipArguments = [object[]]::new(2) + $skipArguments[0] = $cast.Invoke($null, $castArguments) + $skipArguments[1] = 1 + $firstArguments = [object[]]::new(2) + $firstArguments[0] = $skip.Invoke($null, $skipArguments) + $firstArguments[1] = $success + $first.Invoke($null, $firstArguments) + }.GetNewClosure() +} diff --git a/Public/Get-IntuneAgentLog.ps1 b/Public/Get-IntuneAgentLog.ps1 index bfc5899..f572748 100644 --- a/Public/Get-IntuneAgentLog.ps1 +++ b/Public/Get-IntuneAgentLog.ps1 @@ -87,26 +87,39 @@ function Get-IntuneAgentLog { return } - $idPatterns = @(foreach ($value in $Id) { [regex]::Escape($value) }) + # The parser applies the filters to the raw record, before it builds an entry; the event filter + # waits for the classification, which runs once per file over every kept message rather than + # once per entry + $parseSplat = @{} + foreach ($name in 'Level', 'After', 'Before', 'Pattern', 'Id') { + if ($PSBoundParameters.ContainsKey($name)) { $parseSplat[$name] = $PSBoundParameters[$name] } + } + if ($EventName) { + # A message that holds none of the wanted events' leading literals cannot be one of them. + # One event without a literal (its pattern starts with a group) means no such shortcut + $needles = @(foreach ($definition in $script:IslAgentLogEvents) { + if ($definition.Event -in $EventName) { $definition.Needle } + }) + if ($needles.Count -eq @($EventName | Select-Object -Unique).Count) { $parseSplat.Contains = $needles } + } $entries = foreach ($file in $files) { + # A file's last write is at or after its newest entry, so a rolled-over file written + # before -After has nothing to give and is not read + if ($PSBoundParameters.ContainsKey('After') -and (Get-Item -LiteralPath $file).LastWriteTime -lt $After) { + Write-Verbose "Skipping $file, last written before $After" + continue + } Write-Verbose "Reading $file" - foreach ($entry in ConvertFrom-IslCmTraceLog -Path $file) { - if ($Level -and $entry.Level -notin $Level) { continue } - if ($PSBoundParameters.ContainsKey('After') -and $entry.Time -lt $After) { continue } - if ($PSBoundParameters.ContainsKey('Before') -and $entry.Time -ge $Before) { continue } - if ($Pattern -and $entry.Message -notmatch $Pattern) { continue } - if ($idPatterns.Count) { - $found = $false - foreach ($idPattern in $idPatterns) { - if ($entry.Message -imatch $idPattern) { $found = $true; break } - } - if (-not $found) { continue } - } - $classified = Get-IslAgentLogEvent -Message $entry.Message - if ($EventName -and $classified.Event -notin $EventName) { continue } - $entry.Event = $classified.Event - $entry.Detail = $classified.Detail - $entry.Id = $classified.Id + $kept = @(ConvertFrom-IslCmTraceLog -Path $file @parseSplat) + if (-not $kept.Count) { continue } + $classified = @(Get-IslAgentLogEvent -Message @($kept | ForEach-Object { $_.Message })) + for ($index = 0; $index -lt $kept.Count; $index++) { + $entry = $kept[$index] + $classification = $classified[$index] + if ($EventName -and $classification.Event -notin $EventName) { continue } + $entry.Event = $classification.Event + $entry.Detail = $classification.Detail + $entry.Id = $classification.Id $entry } } diff --git a/Tests/Unit/Private/ConvertFrom-IslCmTraceLog.Tests.ps1 b/Tests/Unit/Private/ConvertFrom-IslCmTraceLog.Tests.ps1 index 9cd1b5b..685e7f2 100644 --- a/Tests/Unit/Private/ConvertFrom-IslCmTraceLog.Tests.ps1 +++ b/Tests/Unit/Private/ConvertFrom-IslCmTraceLog.Tests.ps1 @@ -97,6 +97,23 @@ Describe 'ConvertFrom-IslCmTraceLog' -Tag 'Unit', 'Private' { } } + It 'applies to the raw record and still numbers the kept entries by their file line' -ForEach @( + @{ Name = '-Level'; Filter = @{ Level = 'Warning', 'Error' }; Lines = @(2, 5) } + @{ Name = '-After'; Filter = @{ After = [datetime]'2026-09-25 08:45:19.5' }; Lines = @(2, 5) } + @{ Name = '-Before'; Filter = @{ Before = [datetime]'2026-09-25 08:45:19.5' }; Lines = @(1) } + @{ Name = '-Pattern'; Filter = @{ Pattern = 'compliance result is \w+' }; Lines = @(5) } + @{ Name = '-Id'; Filter = @{ Id = 'BBF7E139-FE9D-4783-80DF-627B8E084059' }; Lines = @(1) } + @{ Name = '-Contains'; Filter = @{ Contains = 'error from script =', 'nothing' }; Lines = @(2) } + @{ Name = 'two filters'; Filter = @{ Level = 'Error', 'Warning'; Pattern = 'compliance' }; Lines = @(5) } + ) { + # The filters Get-IntuneAgentLog offers run here on the raw match, so an entry nobody wants + # is never built; lines are counted over the skipped text all the same + $entries = @(InModuleScope IntuneScriptLab -Parameters @{ Path = $script:LogPath; Filter = $Filter } { + ConvertFrom-IslCmTraceLog -Path $Path @Filter + }) + @($entries.Line) | Should-BeCollection $Lines + } + It 'returns nothing for an empty file and fails for a missing one' { $empty = Join-Path $TestDrive 'empty.log' [System.IO.File]::WriteAllText($empty, '') diff --git a/Tests/Unit/Private/Get-IslAgentLogEvent.Tests.ps1 b/Tests/Unit/Private/Get-IslAgentLogEvent.Tests.ps1 index 7d413cc..71b4084 100644 --- a/Tests/Unit/Private/Get-IslAgentLogEvent.Tests.ps1 +++ b/Tests/Unit/Private/Get-IslAgentLogEvent.Tests.ps1 @@ -260,6 +260,41 @@ Describe 'Get-IslAgentLogEvent' -Tag 'Unit', 'Private' { if ($null -eq $Detail) { $result.Detail | Should-BeNull } else { $result.Detail | Should-Be $Detail } } + It 'classifies a batch of messages in one call, one result per message in order' { + # Get-IntuneAgentLog sends a file's messages at once; a call per entry cost more than + # the classification + $results = @(InModuleScope IntuneScriptLab { + Get-IslAgentLogEvent -Message @( + 'Powershell execution is done, exitCode = 1' + 'nothing the table knows' + '' + '[HS] Runner: script bbf7e139-fe9d-4783-80df-627b8e084059 will try to execute now.' + ) + }) + $results.Count | Should-Be 4 + @($results.Event) | Should-BeCollection @('ScriptExit', $null, $null, 'RemediationStart') + $results[0].Detail | Should-Be '1' + $results[3].Id | Should-Be 'bbf7e139-fe9d-4783-80df-627b8e084059' + @(InModuleScope IntuneScriptLab { Get-IslAgentLogEvent -Message @() }).Count | Should-Be 0 + } + + It 'resolves a message two patterns fit to the earlier one in the table' { + # The relationship report fits AppRelationshipReport and, being a status report too, AppReport, + # which is later in the table. Alternation keeps the table's order at a position, which is + # what the one-by-one match did + $text = '[Win32App][ReportingManager] Sending status to company portal based on report: ' + + '{"ApplicationId":"ec9586f0-3333-4cfb-a8fb-d780079278f6","ResultantAppState":3,' + + '"ReportingImpact":{"DesiredState":3,"Classification":1,"ConflictReason":2,"ImpactingApps":' + + '[{"AppId":"b107041b-4444-4cfb-a8fb-d780079278f6","RelationshipType":0}]},"ReportingImpact2":{}}' + $table = InModuleScope IntuneScriptLab { $script:IslAgentLogEvents } + $fitting = @($table | Where-Object { $_.Regex.IsMatch($text) } | ForEach-Object { $_.Event }) + $fitting | Should-BeCollection @('AppRelationshipReport', 'AppReport') + $result = InModuleScope IntuneScriptLab -Parameters @{ Text = $text } { + Get-IslAgentLogEvent -Message $Text + } + $result.Event | Should-Be 'AppRelationshipReport' + } + It 'takes the first GUID in the message as the policy or app id, lower-cased' { $upper = '[HS] Runner: script BBF7E139-FE9D-4783-80DF-627B8E084059 will try to execute now.' $result = InModuleScope IntuneScriptLab -Parameters @{ Message = $upper } { diff --git a/Tests/Unit/Public/Get-IntuneAgentLog.Tests.ps1 b/Tests/Unit/Public/Get-IntuneAgentLog.Tests.ps1 index 8164b26..de701fc 100644 --- a/Tests/Unit/Public/Get-IntuneAgentLog.Tests.ps1 +++ b/Tests/Unit/Public/Get-IntuneAgentLog.Tests.ps1 @@ -153,6 +153,19 @@ Describe 'Get-IntuneAgentLog' -Tag 'Unit', 'Public' { @(Get-IntuneAgentLog -Path $script:Logs -Pattern 'Get \d+ policies').Count | Should-Be 2 } + It 'does not read a rolled-over file whose last write is before -After' { + # The rolled-over agent log in the fixture is written on 9-24; its entries cannot be after + # the 25th, so the file is skipped on its timestamp alone + $rolled = Join-Path $script:Logs 'IntuneManagementExtension-20260924-131114.log' + (Get-Item $rolled).LastWriteTime = [datetime]'2026-09-24 13:11:14' + Mock ConvertFrom-IslCmTraceLog -ModuleName IntuneScriptLab { @() } + $null = Get-IntuneAgentLog -Path $script:Logs -Log Agent -After ([datetime]'2026-09-25') + $invokeSplat = @{ ModuleName = 'IntuneScriptLab'; Exactly = $true; Times = 1 } + Should-Invoke ConvertFrom-IslCmTraceLog @invokeSplat -ParameterFilter { + $Path -like '*\IntuneManagementExtension.log' + } + } + It 'keeps the most recent entries with -Last, after the other filters' { $last = @(Get-IntuneAgentLog -Path $script:Logs -Last 2) $last.Message | Should-BeCollection @(