PowerShell · TravisEz13 · Aug 21, 2018 · Aug 21, 2018 · Aug 21, 2018 · dantraMSFT
diff --git 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 {

@@ -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 "Skipping 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'
     }
 }