Skip to content

Commit

Permalink
Rewrite the mac syslog tests to make them less flaky (PowerShell#21174)
Browse files Browse the repository at this point in the history
  • Loading branch information
@JamesWTruher
JamesWTruher committed Feb 7, 2024
1 parent 7963982 commit 0919240
Show file tree
Hide file tree
Showing 2 changed files with 54 additions and 57 deletions.
108 changes: 52 additions & 56 deletions test/powershell/Host/Logging.Tests.ps1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,29 @@ enum LogKeyword
ManagedPlugin = 0x100
}

# mac log command can emit json, so just use that
# we need to deconstruct the eventmessage to get the event id
# we also need to filter out the non-default messages
function Get-MacOsSyslogItems {
param ([int]$processId, [string]$logId)
$logArgs = "show", "--process", "$processId", "--style", "json"
log $logArgs |
ConvertFrom-Json |
Where-Object { $_.category -eq "$logId" -and $_.messageType -eq "Default" } |
ForEach-Object {
$s = $_.eventMessage.IndexOf('[') + 1
$e = $_.EventMessage.IndexOf(']')
$l = $e - $s
if ($l -gt 0) {
$eventId = $_.eventMessage.SubString($s, $l)
}
else {
$eventId = "unknown"
}
$_ | Add-Member -MemberType NoteProperty -Name EventId -Value $eventId -PassThru
}
}

<#
.SYNOPSIS
Creates a powershell.config.json file with syslog settings
Expand Down Expand Up @@ -317,26 +340,19 @@ Path:.*
}
}

It 'Verifies basic logging with no customizations' -Skip:(!$IsSupportedEnvironment) {
It 'Verifies basic logging with no customizations' -Skip:(!$IsMacOS) {
try {
$timeString = [DateTime]::Now.ToString('yyyy-MM-dd HH:mm:ss')
$configFile = WriteLogSettings -LogId $logId
copy-item $configFile /tmp/pwshtest.config.json
$testPid = & $powershell -NoProfile -SettingsFile $configFile -Command '$PID'

Export-PSOsLog -After $after -LogPid $testPid -TimeoutInMilliseconds 30000 -IntervalInMilliseconds 3000 -MinimumCount 3 |
Set-Content -Path $contentFile
$items = @(Get-PSOsLog -Path $contentFile -Id $logId -After $after -TotalCount 3 -Verbose)
$items = Get-MacOsSyslogItems -processId $testPid -logId $logId

$items | Should -Not -Be $null
$items.Count | Should -BeGreaterThan 2
$items[0].EventId | Should -BeExactly 'Perftrack_ConsoleStartupStart:PowershellConsoleStartup.WinStart.Informational'
$items[1].EventId | Should -BeExactly 'NamedPipeIPC_ServerListenerStarted:NamedPipe.Open.Informational'
$items[2].EventId | Should -BeExactly 'Perftrack_ConsoleStartupStop:PowershellConsoleStartup.WinStop.Informational'
# if there are more items than expected...
if ($items.Count -gt 3)
{
# Force reporting of the first unexpected item to help diagnosis
$items[3] | Should -Be $null
}
$items.EventId | Should -Contain 'Perftrack_ConsoleStartupStart:PowershellConsoleStartup.WinStart.Informational'
$items.EventId | Should -Contain 'NamedPipeIPC_ServerListenerStarted:NamedPipe.Open.Informational'
$items.EventId | Should -Contain 'Perftrack_ConsoleStartupStop:PowershellConsoleStartup.WinStop.Informational'
}
catch {
if (Test-Path $contentFile) {
Expand All @@ -346,7 +362,7 @@ Path:.*
}
}

It 'Verifies scriptblock logging' -Skip:(!$IsSupportedEnvironment) {
It 'Verifies scriptblock logging' -Skip:(!$IsMacOS) {
try {
$script = @'
$PID
Expand All @@ -357,24 +373,23 @@ $PID
$testScriptPath = Join-Path -Path $TestDrive -ChildPath $testFileName
$script | Out-File -FilePath $testScriptPath -Force
$testPid = & $powershell -NoProfile -SettingsFile $configFile -Command $testScriptPath

Export-PSOsLog -After $after -LogPid $testPid -TimeoutInMilliseconds 30000 -IntervalInMilliseconds 3000 -MinimumCount 17 |
Set-Content -Path $contentFile
$items = @(Get-PSOsLog -Path $contentFile -Id $logId -After $after -Verbose)
$items = Get-MacOsSyslogItems -processId $testPid -logId $logId

$items | Should -Not -Be $null
$items.Count | Should -BeGreaterThan 2
$createdEvents = $items | Where-Object {$_.EventId -eq 'ScriptBlock_Compile_Detail:ExecuteCommand.Create.Verbose'}
$createdEvents.Count | Should -BeGreaterOrEqual 3

$createdEvents | ConvertTo-Json | set-content /tmp/createdEvents.json

# Verify we log that we are executing a file
$createdEvents[0].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f ".*/$testFileName")
$createdEvents[0].EventMessage | Should -Match $testFileName

# Verify we log that we are the script to create the scriptblock
$createdEvents[1].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f (Get-RegEx -SimpleMatch $Script))
$createdEvents[1].EventMessage | Should -Match (Get-RegEx -SimpleMatch $Script)

# Verify we log that we are executing the created scriptblock
$createdEvents[2].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f "Write\-Verbose 'testheader123' ;Write\-verbose 'after'")
$createdEvents[2].EventMessage | Should -Match "Write-Verbose 'testheader123' ;Write-verbose 'after'"
}
catch {
if (Test-Path $contentFile) {
Expand All @@ -384,35 +399,28 @@ $PID
}
}

It 'Verifies scriptblock logging with null character' -Skip:(!$IsSupportedEnvironment) {
It 'Verifies scriptblock logging with null character' -Skip:(!$IsMacOS) {
try {
$script = @'
$PID
& ([scriptblock]::create("Write-Verbose 'testheader123$([char]0x0000)' ;Write-verbose 'after'"))
'@
$configFile = WriteLogSettings -ScriptBlockLogging -LogId $logId -LogLevel Verbose
$testFileName = 'test01.ps1'
$testFileName = 'test02.ps1'
$testScriptPath = Join-Path -Path $TestDrive -ChildPath $testFileName
$script | Out-File -FilePath $testScriptPath -Force
$testPid = & $powershell -NoProfile -SettingsFile $configFile -Command $testScriptPath
$testPid = & $powershell -NoProfile -SettingsFile $configFile -Command $testScriptPath | Select-Object -First 1

Export-PSOsLog -After $after -LogPid $testPid -TimeoutInMilliseconds 30000 -IntervalInMilliseconds 3000 -MinimumCount 17 |
Set-Content -Path $contentFile
$items = @(Get-PSOsLog -Path $contentFile -Id $logId -After $after -Verbose)
$items = Get-MacOsSyslogItems -processId $testPid -logId $logId
$items | convertto-json | set-content /tmp/items.json

$items | Should -Not -Be $null
$items.Count | Should -BeGreaterThan 2
$createdEvents = $items | Where-Object {$_.EventId -eq 'ScriptBlock_Compile_Detail:ExecuteCommand.Create.Verbose'}
$createdEvents.Count | Should -BeGreaterOrEqual 3

# Verify we log that we are executing a file
$createdEvents[0].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f ".*/$testFileName")

# Verify we log that we are the script to create the scriptblock
$createdEvents[1].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f (Get-RegEx -SimpleMatch $Script))
$createdEvents[0].EventMessage | Should -Match $testFileName

# Verify we log that we are executing the created scriptblock
$createdEvents[2].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f "Write\-Verbose 'testheader123␀' ;Write\-verbose 'after'")
# Verify we log the null in the message
$createdEvents[1].EventMessage | Should -Match "Write-Verbose 'testheader123\`$\(\[char\]0x0000\)' ;Write-verbose 'after'"
}
catch {
if (Test-Path $contentFile) {
Expand All @@ -422,25 +430,13 @@ $PID
}
}

# This is pending because it results in false postitives (-Skip:(!$IsSupportedEnvironment) )
It 'Verifies logging level filtering works' -Pending {
try {
$configFile = WriteLogSettings -LogId $logId -LogLevel Warning
$testPid = & $powershell -NoLogo -NoProfile -SettingsFile $configFile -Command '$PID'

Export-PSOsLog -After $after -LogPid $testPid |
Set-Content -Path $contentFile
# by default, powershell startup should only logs informational events.
# With Level = Warning, nothing should be logged.
$items = Get-PSOsLog -Path $contentFile -Id $logId -After $after -TotalCount 3
$items | Should -Be $null
}
catch {
if (Test-Path $contentFile) {
Send-VstsLogFile -Path $contentFile
}
throw
}
# this is now specific to MacOS
It 'Verifies logging level filtering works' -skip:(!$IsMacOs) {
$configFile = WriteLogSettings -LogId $logId -LogLevel Warning
$testPid = & $powershell -NoLogo -NoProfile -SettingsFile $configFile -Command '$PID'

$items = Get-MacOsSyslogItems -processId $testPid -logId $logId
$items | Should -Be $null -Because ("{0} Warning event logs were found" -f @($items).Count)
}
}

Expand Down
3 changes: 2 additions & 1 deletion test/tools/Modules/PSSysLog/PSSysLog.psm1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -438,7 +438,8 @@ class PSLogItem

if($item.LogId -notmatch '^\[com\.microsoft\.powershell')
{
Write-Verbose "Skipping logId: $($item.LogId)" -Verbose
# this is really a lot of output, so we'll skip it for now.
# Write-Verbose "Skipping logId: $($item.LogId)" -Verbose
$result = $null
break
}
Expand Down

0 comments on commit 0919240

Please sign in to comment.