From 5dc1e99f5deaf7a96f3cc7b586ebbd0847b04cbb Mon Sep 17 00:00:00 2001 From: Travis Plunk Date: Mon, 20 Aug 2018 19:05:20 -0700 Subject: [PATCH 1/2] Add test for scriptblock logging --- test/powershell/Host/Logging.Tests.ps1 | 75 ++++++++++++++++++++++- test/tools/Modules/PSSysLog/PSSysLog.psm1 | 32 ++++++++-- 2 files changed, 100 insertions(+), 7 deletions(-) diff --git a/test/powershell/Host/Logging.Tests.ps1 b/test/powershell/Host/Logging.Tests.ps1 index fcad56fc59d..39400a0ec49 100644 --- a/test/powershell/Host/Logging.Tests.ps1 +++ b/test/powershell/Host/Logging.Tests.ps1 @@ -71,7 +71,9 @@ function WriteLogSettings [LogChannel[]] $LogChannels = $null, - [LogKeyword[]] $LogKeywords = $null + [LogKeyword[]] $LogKeywords = $null, + + [switch] $ScriptBlockLogging ) $filename = [Guid]::NewGuid().ToString('N') @@ -95,10 +97,37 @@ function WriteLogSettings $values['LogLevel'] = $LogLevel.ToString() } + if($ScriptBlockLogging.IsPresent) + { + $powerShellPolicies = @{ + ScriptBlockLogging = @{ + EnableScriptBlockLogging = $ScriptBlockLogging.IsPresent + EnableScriptBlockInvocationLogging = $true + } + } + + $values['PowerShellPolicies'] = $powerShellPolicies + } + ConvertTo-Json -InputObject $values | Set-Content -Path $fullPath -ErrorAction Stop return $fullPath } +function Get-RegEx +{ + param($SimpleMatch) + + $regex = $SimpleMatch -replace '\\', '\\' + $regex = $regex -replace '\(', '\(' + $regex = $regex -replace '\)', '\)' + $regex = $regex -replace '\[', '\[' + $regex = $regex -replace '\]', '\]' + $regex = $regex -replace '\-', '\-' + $regex = $regex -replace '\$', '\$' + $regex = $regex -replace '\^', '\^' + return $regex +} + Describe 'Basic SysLog tests on Linux' -Tag @('CI','RequireSudoOnUnix') { BeforeAll { [bool] $IsSupportedEnvironment = $IsLinux @@ -176,6 +205,12 @@ Describe 'Basic os_log tests on MacOS' -Tag @('Feature','RequireSudoOnUnix') { } } [string] $powershell = Join-Path -Path $PSHome -ChildPath 'pwsh' + $scriptBlockCreatedRegExTemplate = @' +Creating Scriptblock text \(1 of 1\): +{0} +ScriptBlock ID: [0-9a-z\-]* +Path:.* +'@ } BeforeEach { @@ -230,6 +265,44 @@ Describe 'Basic os_log tests on MacOS' -Tag @('Feature','RequireSudoOnUnix') { } } + It 'Verifies scriptblock logging' -Skip:(!$IsSupportedEnvironment) { + try { + $script = @' +$pid +& ([scriptblock]::create("Write-Verbose 'testheader123' ;Write-verbose 'after'")) +'@ + $configFile = WriteLogSettings -ScriptBlockLogging -LogId $logId -LogLevel Verbose + $testFileName = 'test01.ps1' + $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 18 | + Set-Content -Path $contentFile + $items = @(Get-PSOsLog -Path $contentFile -Id $logId -After $after -Verbose) + + $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)) + + # Verify we log that we are excuting the created scriptblock + $createdEvents[2].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f "Write\-Verbose 'testheader123' ;Write\-verbose 'after'") + } + catch { + if (Test-Path $contentFile) { + Send-VstsLogFile -Path $contentFile + } + throw + } + } + # This is pending because it results in false postitives (-Skip:(!$IsSupportedEnvironment) ) It 'Verifies logging level filtering works' -Pending { try { diff --git a/test/tools/Modules/PSSysLog/PSSysLog.psm1 b/test/tools/Modules/PSSysLog/PSSysLog.psm1 index 27f4b5e4ce3..e54bdad533b 100644 --- a/test/tools/Modules/PSSysLog/PSSysLog.psm1 +++ b/test/tools/Modules/PSSysLog/PSSysLog.psm1 @@ -406,12 +406,28 @@ class PSLogItem $osLogIds.UseOldIds() } - $item.Message = $parts[$osLogIds.Message] + if($parts.Length -gt ($osLogIds.Message +1)) + { + # The message got split into multiple parts, put it back together + $item.Message = $parts[$osLogIds.Message..($parts.Length-1)] -join ' ' + } + else + { + $item.Message = $parts[$osLogIds.Message] -join ' ' + } # [com.microsoft.powershell.logid] $splitChars = ('[', '.', ']') $item.LogId = $parts[$osLogIds.Id] + + if($item.LogId -notmatch '^\[com\.microsoft\.powershell') + { + Write-Verbose "logId: $($item.LogId)" -Verbose + $result = $null + break + } + $subparts = $item.LogId.Split($splitChars, [StringSplitOptions]::RemoveEmptyEntries) if ($subparts.Length -eq 4) { @@ -789,12 +805,13 @@ function Get-PSOsLog if ($TotalCount -eq 0) { - Get-Content @contentParms | ConvertFrom-OsLog -After $After -Id $Id + Get-Content @contentParms | Where-Object {![string]::IsNullOrEmpty($_)} | ConvertFrom-OsLog -After $After -Id $Id } else { [string] $filter = [string]::Format("com.microsoft.powershell.{0}: (", $id) - Get-Content @contentParms -filter {$_.Contains($filter)} | ConvertFrom-OsLog -Id $Id -After $After | Select-Object -First $maxItems + Write-Warning "this code path `Get-PSOsLog -TotalCount` should not be used if the message field is needed!" + Get-Content @contentParms -filter {$_.Contains($filter)} | Where-Object {![string]::IsNullOrEmpty($_)} | ConvertFrom-OsLog -Id $Id -After $After | Select-Object -First $maxItems } } @@ -875,16 +892,19 @@ function Export-PSOsLog Wait-UntilSuccess { # Leaving this in an turned on by default until the tests are stabilized. Write-Verbose "Exporting macOS logs..." -Verbose - $log = @(Start-NativeExecution -command {log show --info @extraParams} | Select-String -SimpleMatch 'com.microsoft.powershell') + $log = @(Start-NativeExecution -command {log show --info @extraParams}) + + # Only count line with `[com.microsoft.powershell` as matching rows + $logToCount = $log | Select-String -SimpleMatch '[com.microsoft.powershell' - if($log.Count -ge $MinimumCount){ + if($logToCount.Count -ge $MinimumCount){ Write-Output $log } else { throw "did not recieve at least $MinimumCount records but $($log.Count) instead." } } -TimeoutInMilliseconds $TimeoutInMilliseconds -IntervalInMilliseconds $IntervalInMilliseconds -LogErrorSb { - $log = Start-NativeExecution -command {log show --info @extraParams} | Select-String -SimpleMatch 'com.microsoft.powershell' + $log = Start-NativeExecution -command {log show --info @extraParams} Send-VstsLogFile -Contents $log -LogName 'Export-PSOsLog-Failure' } } From 5cd6c5552efae8e9fb41bd8ec612eb32ec1c1c1c Mon Sep 17 00:00:00 2001 From: Travis Plunk Date: Tue, 21 Aug 2018 12:21:01 -0700 Subject: [PATCH 2/2] Address PR comment about improving verbose message --- test/tools/Modules/PSSysLog/PSSysLog.psm1 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/tools/Modules/PSSysLog/PSSysLog.psm1 b/test/tools/Modules/PSSysLog/PSSysLog.psm1 index e54bdad533b..d90d204f7fe 100644 --- a/test/tools/Modules/PSSysLog/PSSysLog.psm1 +++ b/test/tools/Modules/PSSysLog/PSSysLog.psm1 @@ -423,7 +423,7 @@ class PSLogItem if($item.LogId -notmatch '^\[com\.microsoft\.powershell') { - Write-Verbose "logId: $($item.LogId)" -Verbose + Write-Verbose "Skipping logId: $($item.LogId)" -Verbose $result = $null break }