Write-Verbose from Pester cannot be invoked by the System.Debug flag within Azure DevOps

[almmechanics]

1. General summary of the issue

Enabling System.Debug in Azure DevOps allows Verbose logging within PowerShell, with the exception of the Pester Module.

2. Describe Your Environment

This is executed via a default windows-2019 Hosted agent.

3. Expected Behavior

Any output from Write-Verbose with Pester would be visible if the System.Debug flag is set in Azure DevOps.

4.Current Behavior

Unless $VerbosePreference is explicitly set, then Pester will not log anything for the Verbose log. Taken from the following sample.

An example of this is shown by the following invocation script and test suite:

Wrapper.ps1

This file allows the current runtime variables to be seen from powershell before the invocation of Pester:

write-host ('Number of Environment Variables: {0}' -f (Get-ChildItem env:).count)
write-host ('VerbosePreference set to: {0}' -f $VerbosePreference)
write-host ('System Debug set to: {0}' -f $env:system_debug)

Import-Module pester -Verbose

write-host ('Pester Version: {0}' -f (Get-Module 'Pester').Version.ToString())

# cast from empty hashtable to get default
$configuration = [PesterConfiguration]@{}
$configuration.Run.Path = 'tests'
$configuration.TestResult.OutputPath = 'TEST-Environment.nunit.xml'
$configuration.TestResult.OutputFormat = 'NUnitXml'
$configuration.TestResult.Enabled = $False
$configuration.Run.PassThru = $True
$configuration.Run.Exit = $True

Invoke-Pester -Configuration $configuration

Env.Tests.ps1

The following set of Pester tests show the Azure DevOps variables are carried across, however Write-Verbose logging is not available.

BeforeAll {
    (Get-ChildItem env:).Name | foreach-object {Write-Verbose $_}
}

Describe "Get Environment Configuration" {
    It "All Environment variables carried across" {
        (Get-ChildItem env:).count | Should -Be 193
    }

    It "System Debug enabled" {
        $env:system_debug | should -be $True
    }

    It "Verbose Preference is set to Continue" {
        $VerbosePreference | Should -Be 'Continue'
    }
}

5. Possible Solution

Allow the value of System.Debug to override the $VerbosePreference variable within Pester

6. Context

A separate project to analyse AzSK output is proving difficult to debug without this capability being available.

[nohwnd]

Does this work with a normal powershell script, that is if a script calls a function that has write-verbose in it, and cmdletbinding, does the script get the verbosity set correctly?

Trying to understand if this is a Pester only issue. I don't think we set the verbosity preference anywhere, so we should not be overriding what was set by powershell itself.

[fflaten]

Pester forgets the InformationPreferenceand VerbosePreference values provided to Invoke-Pester at some point. It's correct inside Invoke-Pester, but gone (back to script/global variables) when it reaches the tests.

Verbose.Tests.ps1

Describe "Testing Verbose Preference" {
    It "Information test" {
        Write-Host "InformationPreference = $InformationPreference"
        Write-Information 'Show me with -InformationAction Continue or $VerbosePreference = Continue.'
    }

    It "Verbose test" {
        Write-Host "VerbosePreference = $VerbosePreference"
        Write-Verbose 'Show me with -Verbose or $VerbosePreference = Continue.'
    }
}

Use common parameters to set per function call = Doesn't work

PS /workspaces/Pester> Invoke-Pester ./Verbose.Tests.ps1 -InformationAction Continue -Verbose -Output Detailed

Starting discovery in 1 files.
Discovering in /workspaces/Pester/SampleProject/Verbose.Tests.ps1.
Found 2 tests. 8ms
Discovery finished in 13ms.

Running tests from '/workspaces/Pester/SampleProject/Verbose.Tests.ps1'
Describing Testing Verbose Preference
InformationPreference = SilentlyContinue
  [+] Information test 2ms (1ms|1ms)
VerbosePreference = SilentlyContinue
  [+] Verbose test 2ms (1ms|1ms)
Tests completed in 55ms
Tests Passed: 2, Failed: 0, Skipped: 0 NotRun: 0

Modify session variables = Works

PS /workspaces/Pester> $InformationPreference = "Continue"; $VerbosePreference = "Continue"                   

PS /workspaces/Pester> Invoke-Pester ./Verbose.Tests.ps1 -Output Detailed                                     

Starting discovery in 1 files.
Discovering in /workspaces/Pester/SampleProject/Verbose.Tests.ps1.
Found 2 tests. 7ms
Discovery finished in 10ms.

Running tests from '/workspaces/Pester/SampleProject/Verbose.Tests.ps1'
Describing Testing Verbose Preference
InformationPreference = Continue
Show me with -InformationAction Continue or $VerbosePreference = Continue.
  [+] Information test 2ms (1ms|1ms)
VerbosePreference = Continue
VERBOSE: Show me with -Verbose or $VerbosePreference = Continue.
  [+] Verbose test 3ms (2ms|1ms)
Tests completed in 45ms
Tests Passed: 2, Failed: 0, Skipped: 0 NotRun: 0

[almmechanics]

If i run the Wrapper.ps1 code with the System.Debug flag set I get the output below that shows the PowerShell and Pester Module outputting to the verbose log - but not from within the invocation of Invoke-Pester

Number of Environment Variables:193
VerbosePreference set to: SilentlyContinue
System Debug set to :true
VERBOSE: Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\pester\5.0.4\pester.psd1'.
VERBOSE: Populating RepositorySourceLocation property for module pester.
VERBOSE: Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\pester\5.0.4\Pester.psm1'.
VERBOSE: Importing function 'Add-ShouldOperator'.
VERBOSE: Importing function 'AfterAll'.
VERBOSE: Importing function 'AfterEach'.
VERBOSE: Importing function 'Assert-MockCalled'.
VERBOSE: Importing function 'Assert-VerifiableMock'.
VERBOSE: Importing function 'BeforeAll'.
VERBOSE: Importing function 'BeforeEach'.
VERBOSE: Importing function 'Context'.
VERBOSE: Importing function 'ConvertTo-NUnitReport'.
VERBOSE: Importing function 'ConvertTo-Pester4Result'.
VERBOSE: Importing function 'Describe'.
VERBOSE: Importing function 'Export-NUnitReport'.
VERBOSE: Importing function 'Get-ShouldOperator'.
VERBOSE: Importing function 'InModuleScope'.
VERBOSE: Importing function 'Invoke-Pester'.
VERBOSE: Importing function 'It'.
VERBOSE: Importing function 'Mock'.
VERBOSE: Importing function 'New-MockObject'.
VERBOSE: Importing function 'Set-ItResult'.
VERBOSE: Importing function 'Should'.
VERBOSE: Importing alias 'Add-AssertionOperator'.
VERBOSE: Importing alias 'Get-AssertionOperator'.
Pester Version: 5.0.4

Starting discovery in 1 files.
Discovery finished in 1.02s.
[-] Get Environment Configuration.Verbose Preference is set to Continue 477ms (474ms|3ms)
 Expected 'Continue', but got SilentlyContinue.
 at $VerbosePreference | Should -Be 'Continue', D:\a\1\s\tests\env.tests.ps1:15
 at <ScriptBlock>, D:\a\1\s\tests\env.tests.ps1:15
Tests completed in 5.24s
Tests Passed: 2, Failed: 1, Skipped: 0 NotRun: 0

[nohwnd]

Then we probably need to explicitly set the variables, prior running the tests from the common parameters, because the scriptblocks we execute don't have cmdlet binding and they run in a different session state. On the otherhand, should the tests really be concerned about the parameters that were passed to Pester? What if you have tests that are testing that -Verbose is passed correctly to the function?

Get-Module m | Remove-Module 
New-Module -Name m -ScriptBlock { 
    function Invoke-ScriptBlock { 
        [CmdletBinding()]
        param($sb) 

        Write-Verbose -Message "Running the script:"
        & $sb
    } 
} | Import-Module

$scriptBlock = { Write-Verbose "hello" }

# no output
& $scriptBlock

# no output
Invoke-ScriptBlock $scriptBlock

# output just from the module but not the scriptblock
Invoke-ScriptBlock $scriptBlock -Verbose

[almmechanics]

So, i'm curious where the System.Debug environment variable (from within Azure DevOps pipelines) enables the the verbose log in PowerShell even if $VerbosePreference is set to 'SilentlyContinue'.

As I can see they are separate beasts - and i'd hate to add the following to invoke the verbose log from an Azure DevOps pipeline Invoke-Pester -Verbose:([bool]($env:system_debug))

[nohwnd]

It’s probably the task or the agent directly setting that. You should be able to find it in source if it is in the task.

I am not sure if the agent itself is open source or closed source. But I think it’s closed.

[nohwnd]

Maybe here somewhere? Can’t search it on phone https://github.com/microsoft/azure-pipelines-tasks/blob/master/Tasks/PowerShellV2/powershell.ps1