Skip to content

Rewrite the mac syslog tests as they seem somewhat flaky. #21174

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
daxian-dbw merged 3 commits into from
Feb 7, 2024
Merged

Rewrite the mac syslog tests as they seem somewhat flaky. #21174

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
92f9eba
Try a rewrite of the mac syslog tests as they seem somewhat flaky.
JamesWTruher Feb 2, 2024
25ff16e
Change logging level filtering test to be MacOS only.
JamesWTruher Feb 2, 2024
76893e5
Make some logging tests specific to MacOS
JamesWTruher Feb 2, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
108 changes: 52 additions & 56 deletions test/powershell/Host/Logging.Tests.ps1
View file
Open in desktop
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 {
Copy link
Member

@daxian-dbw daxian-dbw Feb 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Given that this is to replace Get-PSOsLog, does it make sense to put this function in PSSysLog.psm1?

Copy link
Collaborator Author

@JamesWTruher JamesWTruher Feb 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@daxian-dbw I did think about that, but wanted to take more time to do a more complete rewrite of this module. I thought this smaller, localized change would be a faster path to stability, so I took this parallel approach.

Copy link
Member

@daxian-dbw daxian-dbw Feb 7, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good to me 👍

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 |
Copy link
Member

@daxian-dbw daxian-dbw Feb 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Export-PSSysLog is no longer used, so maybe we should remove it from the PSSysLog module?

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
Open in desktop
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