Merged PR 5607: Fix issue logging null character in ScriptBlock logging

Fix issue logging null character in ScriptBlock logging

src/System.Management.Automation/engine/runtime/CompiledScriptBlock.cs

@@ -1326,6 +1326,7 @@ namespace System.Management.Automation
             // See if we need to encrypt the event log message. This info is all cached by Utils.GetPolicySetting(),
             // so we're not hitting the configuration file for every script block we compile.
             ProtectedEventLogging logSetting = Utils.GetPolicySetting<ProtectedEventLogging>(Utils.SystemWideOnlyConfig);
+            bool wasEncoded = false;
             if (logSetting != null)
             {
                 lock (s_syncObject)
@@ -1343,6 +1344,7 @@ namespace System.Management.Automation
                     // version.
                     if (s_encryptionRecipients != null)
                     {
+                        // Encrypt the raw Text from the scriptblock.  The user may have to deal with any control characters in the data.
                         ExecutionContext executionContext = LocalPipeline.GetExecutionContextFromTLS();
                         ErrorRecord error = null;
                         byte[] contentBytes = System.Text.Encoding.UTF8.GetBytes(textToLog);
@@ -1364,11 +1366,22 @@ namespace System.Management.Automation
                         else
                         {
                             textToLog = encodedContent;
+                            wasEncoded = true;
                         }
                     }
                 }
             }
 
+            if(!wasEncoded)
+            {
+                // The logging mechanism(s) cannot handle null and rendering may not be able to handle
+                // null as we have the string defined as a null terminated string in the manifest.
+                // So, replace null characters with the Unicode `SYMBOL FOR NULL` 
+                // We don't just remove the characters to preserve the fact that a null character was there.
+
+                textToLog = textToLog.Replace('\u0000','\u2400');
+            }
+
             if (scriptBlock._scriptBlockData.HasSuspiciousContent)
             {
                 PSEtwLog.LogOperationalWarning(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,

test/powershell/Host/Logging.Tests.ps1

@@ -216,6 +216,35 @@ $pid
         $createdEvents[2].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f "Write\-Verbose 'testheader123' ;Write\-verbose 'after'")
     }
 
+    It 'Verifies scriptblock logging with null character' -Skip:(!$IsSupportedEnvironment) {
+        $configFile = WriteLogSettings -LogId $logId -ScriptBlockLogging -LogLevel Verbose
+        $script = @'
+$pid
+& ([scriptblock]::create("Write-Verbose 'testheader123$([char]0x0000)' ;Write-verbose 'after'"))
+'@
+        $testFileName = 'test01.ps1'
+        $testScriptPath = Join-Path -Path $TestDrive -ChildPath $testFileName
+        $script | Out-File -FilePath $testScriptPath -Force
+        $null = & $powershell -NoProfile -SettingsFile $configFile -Command $testScriptPath
+
+        # Get log entries from the last 100 that match our id and are after the time we launched Powershell
+        $items = Get-PSSysLog -Path $SyslogFile -Id $logId -Tail 100 -Verbose -TotalCount 18
+
+        $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.Replace([System.Environment]::NewLine,'#012')))
+
+        # Verify we log that we are excuting the created scriptblock
+        $createdEvents[2].Message | Should -Match ($scriptBlockCreatedRegExTemplate -f "Write\-Verbose 'testheader123␀' ;Write\-verbose 'after'")
+    }
+
     It 'Verifies logging level filtering works' -Skip:(!$IsSupportedEnvironment) {
         $configFile = WriteLogSettings -LogId $logId -LogLevel Warning
         & $powershell -NoProfile -SettingsFile $configFile -Command '$env:PSModulePath | out-null'
@@ -342,6 +371,44 @@ $pid
         }
     }
 
+    It 'Verifies scriptblock logging with null character' -Skip:(!$IsSupportedEnvironment) {
+        try {
+            $script = @'
+$pid
+& ([scriptblock]::create("Write-Verbose 'testheader123$([char]0x0000)' ;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 {
@@ -374,6 +441,11 @@ Describe 'Basic EventLog tests on Windows' -Tag @('CI','RequireAdminOnWindows')
                 script = "Write-Verbose 'testheader123' ;Write-verbose 'after'"
                 expectedText="Write-Verbose 'testheader123' ;Write-verbose 'after'`r`n"
             }
+            @{
+                name = 'script block with Null'
+                script = "Write-Verbose 'testheader123$([char]0x0000)' ;Write-verbose 'after'"
+                expectedText="Write-Verbose 'testheader123␀' ;Write-verbose 'after'`r`n"
+            }
         )
 
         if ($IsSupportedEnvironment)