Write-Debug ignores Debug switch in Foreach-Object Parallel block

[drstonephd]

Prerequisites

• [X] Write a descriptive title.
• [X] Make sure you are able to repro it on the latest released version
• [X] Search the existing issues.
• [X] Refer to the FAQ.
• [X] Refer to Differences between Windows PowerShell 5.1 and PowerShell.

Steps to reproduce

Run this script with two identical blocks of code except for the "Parallel" option.

Write-Host 'Test 1 - non-parallel'
$DebugPreference = 'SilentlyContinue'
1..2 |
ForEach-Object {
    Write-Debug "Item $_`: Write-Debug" 
    Write-Debug "Item $_`: Write-Debug -Debug" -Debug 
    Write-Debug "Item $_`: Write-Debug -Debug:`$true" -Debug:$true 
    Write-Debug "Item $_`: Write-Debug -Debug:`$false" -Debug:$false 
} 

Write-Host 'Test 2 - parallel'
$DebugPreference = 'SilentlyContinue'
1..2 |
ForEach-Object -Parallel {
    Write-Debug "Item $_`: Write-Debug"
    Write-Debug "Item $_`: Write-Debug -Debug" -Debug
    Write-Debug "Item $_`: Write-Debug -Debug:`$true" -Debug:$true
    Write-Debug "Item $_`: Write-Debug -Debug:`$false" -Debug:$false
}

Write-Host 'Done'

Expected behavior

Test 1 - non-parallel
DEBUG: Item 1: Write-Debug -Debug
DEBUG: Item 1: Write-Debug -Debug:$true
DEBUG: Item 2: Write-Debug -Debug
DEBUG: Item 2: Write-Debug -Debug:$true
Test 2 - parallel
DEBUG: Item 1: Write-Debug -Debug
DEBUG: Item 1: Write-Debug -Debug:$true
DEBUG: Item 2: Write-Debug -Debug
DEBUG: Item 2: Write-Debug -Debug:$true
Done

Actual behavior

Test 1 - non-parallel
DEBUG: Item 1: Write-Debug -Debug
DEBUG: Item 1: Write-Debug -Debug:$true
DEBUG: Item 2: Write-Debug -Debug
DEBUG: Item 2: Write-Debug -Debug:$true
Test 2 - parallel
Done

Error details

NA

Environment data

Name                           Value
----                           -----
PSVersion                      7.4.3
PSEdition                      Core
GitCommitId                    7.4.3
OS                             Microsoft Windows 10.0.19045
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Visuals

No response

[drstonephd]

If I set $DebugPreference = 'Continue' in the block, it makes no difference. I have to change the parent thread's global $DebugPreference from the block. That's a sperate problem - an irritating one. However, all other issues aside, there is a fundamental expectation that a function will honor its switches. I think this is a coding issue with how Write-Debug parses parameters from another thread.

When I use a module like DBATools, I understand that the module is loaded on each thread the first time it's used. (It's not loaded every time the thread in the thread pool is used, just the first.) I can see where it might not be safe to do so when a single resource (e.g., config file) is locked by each thread. I suppose it's the same any module. Is the issue with Write-Debug a coding issue or an issue with using the module by more than one thread? Is microsoft.powershell.utility safe to use by more than one thread? Do I need a mutex to call its methods? Is it already thread safe and there is some odd problem with getting the parameters from the context of another thread?

[drstonephd]

BTW If I set the global debug preference to continue, Write-Debug does honor -Debug:$false. So, it appears to be a coding issue, not an issue with threads.

[drstonephd]

I can't resist making the comment for the bug fix. "Warning, a breaking change has been introduced. The expected output from write-debug will be generated when output is expected. This can be unexpected."

[rhubarb-geek-nz]

I have a theory and it boils down to how the response from the thread is written to the main output

Consider

$DebugPreference = 'SilentlyContinue'

$job = Start-Job {
	Write-Output 'foo 1'
	Write-Debug 'bar 1' -Debug
}

$job | Receive-Job -Wait

$job = Start-ThreadJob {
	Write-Output 'foo 2'
	Write-Debug 'bar 2' -Debug
}

$job | Receive-Job -Wait

$job = Start-ThreadJob {
	Write-Output 'foo 3'
	Write-Debug 'bar 3' -Debug
}

$job | Receive-Job -Wait -Debug

Result is

foo 1
DEBUG: bar 1
foo 2
foo 3
DEBUG: bar 3

Now it looks like the behaviour of Write-Debug with Receive-Job behaves differently between threads and process jobs

So lets say that ForEach-Object -Parallel uses a thread pool to handle each input record. It is the behaviour of Receive-Job that determines how the DebugRecord is transferred from the output of the thread to the main output pipeline. So Write-Debug is working correctly, it is the handling of the response from the thread that is stripping the Debug output.

Hence the following now works, by adding the -Debug flag to ForEach-Object to tell it to handle the DebugRecords.

Write-Host 'Test 2 - parallel -debug'
$DebugPreference = 'SilentlyContinue'
1..2 |
ForEach-Object -Parallel {
    Write-Debug "Item $_`: Write-Debug"
    Write-Debug "Item $_`: Write-Debug -Debug" -Debug
    Write-Debug "Item $_`: Write-Debug -Debug:`$true" -Debug:$true
    Write-Debug "Item $_`: Write-Debug -Debug:`$false" -Debug:$false
} -Debug

So it would be interesting to know the reason/justification behind the difference between thread jobs and jobs.

[drstonephd]

@rhubarb-geek-nz thanks for the response. It does - now - make sense that streams are being redirected from the block in the scope of the block. So, within the scope of the block we add debug messages to the debug stream. In the scope of the block, we ignore the debug stream. So, it doing as requested.

I think it's doing the right thing. In any one scope we have one set of preferences controlling both emitting messages to the stream and passing the stream. I think it should honor the setting in the local scope.

It does not seem to be consistent with the non-parallel case. For example, the following two pipelines are identical except for the parallel keyword. (Trickery is used to set the debug preference if running in parallel with code that works in both cases.) The common parameter -Debug:$false is ignored in the non-parallel case. Makes me wonder what a common parameter does for a Foreach-Object. Should it be setting the debug preference when single threaded? Should it be a filter when in parallel? Is the result of these the same? Should it be treated as setting for both? Or both a setting and filter for both? I am confused. Perhaps this is a bug.

# We need a variable that's not initialized automatically on a new thread 
$isParentThread = $true # a trick to test if parent thread

Write-Host 'Test 1 - without parallel keyword'
$DebugPreference = 'Continue'
Write-Host ( '{0}={1}' -f '$DebugPreference', $DebugPreference )
1..10 |
ForEach-Object {
    if ( $_ -gt 1 ) { return }
    Write-Host ( '{0}={1}' -f '$local:DebugPreference', $local:DebugPreference )
    if ( -not $isParentThread )
    { 
        Write-Host ( '{0}={1}' -f '$using:DebugPreference', $using:DebugPreference )
        $DebugPreference = $using:DebugPreference
        Write-Host ( '{0}={1}' -f '$local:DebugPreference', $local:DebugPreference )
    }
    Write-Debug 'debug message'
    Write-Debug 'debug message -Debug' -Debug
} -Debug:$false

Write-Host 'Test 2 - with parallel keyword'
$DebugPreference = 'Continue'
Write-Host ( '{0}={1}' -f '$DebugPreference', $DebugPreference )
1..10 |
ForEach-Object -Parallel {
    if ( $_ -gt 1 ) { return }
    Write-Host ( '{0}={1}' -f '$local:DebugPreference', $local:DebugPreference )
    if ( -not $isParentThread )
    { 
        Write-Host ( '{0}={1}' -f '$using:DebugPreference', $using:DebugPreference )
        $DebugPreference = $using:DebugPreference
        Write-Host ( '{0}={1}' -f '$local:DebugPreference', $local:DebugPreference )
    }
    Write-Debug 'debug message'
    Write-Debug 'debug message -Debug' -Debug
} -Debug:$false

My output shows the -Debug:$false being ignored in the case without the parallel keyword.

Test 1 - without parallel keyword
$DebugPreference=Continue
$local:DebugPreference=Continue
DEBUG: debug message
DEBUG: debug message -Debug
Test 2 - with parallel keyword
$DebugPreference=Continue
$local:DebugPreference=SilentlyContinue
$using:DebugPreference=Continue
$local:DebugPreference=Continue

[rhubarb-geek-nz]

My output shows the -Debug:$false being ignored in the case without the parallel keyword.

My take is that Debug is a SwitchParameter and false is the same as meaning not set/provided so it inherits the current environments effective $DebugPreference.

[drstonephd]

As a switch parameter, it's does make sense to treat as a Boolean for either present or not present. It has no effect unless present. If it's not present, we get the default behavior.

As a common parameter, the documentation has a third possible result, so it's not just a simple Boolean. If it's not present, the current $DebugPreference is used. If -Debug is present, Continue is used. If -Debug:$false is present, something mysterious is done to suppress debug messages if not already SilentlyContinue.

[https://learn.microsoft.com/en-us/powershell/module/microsoft.powershell.core/about/about_commonparameters?view=powershell-7.4]

The Debug parameter overrides the value of the $DebugPreference variable for the current command, setting the value of $DebugPreference to Continue.

-Debug:$true has the same effect as -Debug. Use -Debug:$false to suppress the display of debugging messages when $DebugPreference isn't SilentlyContinue, which is the default.

I have to do a reality check.

$DebugPreference = 'Continue'
write-debug 'I should see this.'
write-debug 'I should see this with "-Debug".' -Debug
write-debug 'I should see this with "-Debug:$true".' -Debug:$true
write-debug 'I should see this with "-Debug:$false if it''s just a switch".' -Debug:$false

It does not behave as a switch.

DEBUG: I should see this.
DEBUG: I should see this with "-Debug".
DEBUG: I should see this with "-Debug:$true".

It does appear there will be a context to determining if it's a switch or a common parameter. Is it a common parameter only in advanced functions and a switch otherwise? If I see a -Debug:$false, it's the same as not present if the function has an explicit switch parameter for Debug?

I can see issues with manually passing the value of a common parameter within an advanced function to another advanced function. I think I would have to dynamically construct a splat that has 3 debug choices: no Debug item, Debug = $true, or a Debug=$false? Even then, I'm not sure the function will treat the Debug=$false as having -Debug:$false.

@rhubarb-geek-nz, because of your help, I do think I'm starting to understand my confusion on the topic... though I'm still confused. If the documentation for a function mentions common parameters, then I expect the -Debug:$false to stop debug messages. I also expect the function to correctly treat -Debug:$false as different than no parameter at all.

[mklement0]

There are several separate aspects to consider, two by design, one inconsistent:

• By design: The common -Debug parameter is a [switch] parameter - but it is used with custom logic in the case of common parameters: omitting -Debug is not the same as -Debug:$false: the latter overrides the value of the equivalent preference variable, and makes SilentlyContinue the effective value. The same applies to the -Confirm parameter.

  • Advanced functions / cmdlets can emulate this behavior by distinguishing the omission of the switch from its having been specified with value $false by using $PSBoundParameters.ContainsKey()

• By design: ForEach-Object -Parallel script blocks run in separate threads, hosting separate PowerShell runspaces, which do not share state with the caller. Sharing state - which is limited to variable values - requires use of the $using: scope.

  • By contrast, without -Parallel, ForEach-Object script blocks run directly in the caller's scope, and therefore by definition use the same state as the caller.

• Inconsistent: ForEach-Object -Parallel, as well as Receive-Job when applied to thread jobs (started with Start-ThreadJob), act as stream filters: that is, they selectively suppress output from the out-of-runspace code (whose output behavior is governed by its state) based on their scope's preference variables / common parameter values.

  • By contrast, as @rhubarb-geek-nz has demonstrated, the output from background jobs (i.e. child process-based jobs created with Start-Job or the post-positional & operator), is not subject to the same stream filtering via Receive-Job (which is the only way to surface output from background jobs).

  • The ForEach-Object -Parallel / thread-job behavior gives you more control over what is ultimately surfaced in the caller's scope, whereas the background-job behavior may be less surprising.

[drstonephd]

@mklement0 I'm still wrapping my head around this. Does my understanding below sound correct?

• The Debug common parameter can be used to initialize $local:DebugPreference in an advanced function, but the code executed within or by the function can change or override the local preference value. In the case where the advanced function executes code in another thread, the local debug preference of the parent thread is not automatically applied in the new thread. The new thread will need to use $using:DebugPreference to set the thread's preference to that of the parent.
• Foreach-Object -Parallel applies $local:DebugPreference to the stream as a filter. This is unrelated to code execution within the code block. A stream filter does not apply with non-parallel usage of Foreach-Object.

In summary, block only if non-parallel and block (optional with using) & stream if parallel. Perhaps I should be using redirection 5> $null if I want to reliably suppress debug output. It's hard coded. I don't see a way to control redirection with a parameter as can be done with Foreach-Object -Parallel. I would need an if-else to handle the logic.

[rhubarb-geek-nz]

Perhaps I should be using redirection 5> $null if I want to reliably suppress debug output. It's hard coded.

You could filter out the DebugRecord

PS> Write-Debug 'foo' -Debug *>&1
DEBUG: foo
PS> Write-Debug 'foo' -Debug *>&1 | Where-Object { $True }
DEBUG: foo
PS> Write-Debug 'foo' -Debug *>&1 | Where-Object { -not ( $_ -is [System.Management.Automation.DebugRecord] ) }

[mklement0]

@drstonephd, yes, that sounds correct.

Yes, you can use 5>$null to quietly discard debug-stream output in both the parallel and the non-parallel scenarios.

Note that passing -Debug to an advanced function automatically results in a function-local $DebugPreference getting defined, with value 'Continue' (try & { [CmdletBinding()] param() $DebugPreference } -Debug); this not only requires extra effort in the case of ForEach-Object -Parallel / Start-ThreadJob, but also when function-internally calling commands from other modules, as such commands also do not see the local preference variable - see #4568

I just realized that I've come across the stream-filtering behavior before; back then I argued that the filtering should not happen (more on that below):

• #13816

As an aside: while Start-Job (child process-based) + Receive-Job do not perform stream filtering, they also unexpectedly prevent redirections (e.g., Start-Job { Write-Verbose -vb hi } | Receive-Job -Wait -AutoRemoveJob 4>$null still prints hi):

• #9585

---

Conceptually, the question is: In cmdlets that execute code passed to them as script blocks:

• (a) Should the common parameters passed to such a cmdlet apply to that code?
• Or (b) should they only apply to stream output generated by the cmdlet itself?

It seems that all such cmdlets, including Invoke-Command, fall into category (b).

The only exceptions are the -*Variable common parameters, i.e. the stream output-collecting parameters (e.g., -ErrorVariable), which do collect output from the executed code (too).

E.g., ForEach-Object { Write-Verbose hi } -Verbose and Invoke-Command { Write-Verbose hi } -Verbose produce no output; that is, the -Verbose switch is not propagated to the code in the script block. Doing so would require behind-the-scenes trickery for code executing in a different runspace, such as injection of a runspace-local preference variable.

The additional, anomalous stream-filtering behavior of ForEach-Object -Parallel and Start-ThreadJob - which applies to whatever stream output the other-runspace code produces - seems to provide no benefit while being both unexpected and necessitating a workaround to ensure that all of the output the other-runspace code produces surfaces.

Thus, I think it should be considered a bug, as argued in #13816. If and when this gets fixed, care should be taken that redirections continue to work (i.e., to ensure that the bug described in #9585 is avoided).

[drstonephd]

Thanks for the remarks.

$DebugPreference Determines how PowerShell responds to debugging messages generated by a script, cmdlet or provider, or by a Write-Debug command at the command line.

Applying the common preferences to stream filtering or consumption of messages seems unexpected and inconsistent. So, perhaps the bug is that the common parameters Debug, Verbose, etc. are applied to streams when they should only apply to statements that generate messages?

Common parameter descriptions -Debug Displays programmer-level detail about the operation done by the command. This parameter works only when the command generates a debugging message. For example, this parameter works when a command contains the Write-Debug cmdlet.

The wording is such that it only has to display debug messages from the command, not messages from the block of code passed to the command. So perhaps ForEach-Object { code } -Verbose not generating a message is not a bug. However, if the cmdlet filters the stream because of that switch, that would be a bug. (Filtering the stream is not a work around to not setting the preferences in the block to cause messages to be generated. However, it can emulate not emitting messages by filtering out those that are generated. This seems problematic, confusing, and inconsistant.)

I can see the need for preferences to control streaming. How about a new set of common parameters that can be used in place of hard coded redirection operators? (Now we can dynamically redirect?) It could work the same for all cases (e.g., parallel and non-parallel, start-threadjob, invoke-command, etc.)?

[drstonephd]

Here is an example that demonstrates that -Debug works as described for a command with a Debug-Message.

function Get-Square {
    [CmdletBinding()]
    param (
        [Parameter(Mandatory=$true, ValueFromPipeline=$true)]
        [Int]$root
    )
    Process {
        Write-Debug "`$root=$root"
        $root * $root    
    }
}

$DebugPreference = 'SilentlyContinue'
1..4 | Get-Square -Debug

DEBUG: $root=1
1
DEBUG: $root=2
4
DEBUG: $root=3
9
DEBUG: $root=4
16

If I updated the function to include a script block parameter and execute the script block in the function, should I be applying the $DebugPreference, -Debug, or the default preference to that code? Should I filter the stream based one or more of these settings? Will others do the same so that it's consistent?

If the common parameter is there for just the command, then I should not be using it to control messaging in the script block or filtering the output. I guess it comes down to the scope of the effect of the Debug parameter. It should be a universal understanding, whatever it happens to be.

@mklement0 I just restated some of what you said. I'm starting to understand this, I think.

[drstonephd]

It's almost like I want each block to be automatically wrapped as an advanced function where I can specify common parameters. That could be a mess with BEGIN, PROCESS, and END blocks each having separate common parameters plus the common parameters for the Foreach-Object command itself. For a Parallel block, perhaps the wrapping might provide a way to pass the preferences to the thread?

[mklement0]

I think we're mostly on the same page; let me try to summarize:

• Stream-un/silencing common parameters generally do NOT apply to code passed to cmdlets such as Invoke-Command, ForEach-Object, Start-Job - they only apply to stream output generated by the cmdlets themselves.

  • ForEach-Object -Parallel and Start-ThreadJob also do not do that, but - unexpectedly, due to a putative bug - filter whatever output the passed code produces based on their effective settings (whether via preference variable or common parameter).
  • Note that ForEach-Object -Parallel (but not Start-ThreadJob) explicitly prevents certain common parameters (for reasons unknown to me), as reflected in the following error message: "The following common parameters are not currently supported in the Parallel parameter set: ErrorAction, WarningAction, InformationAction, PipelineVariable"

• I think it's simplest to stick with this design, which means (assuming the bug gets fixed):

  • Code passed as an argument must control its own output stream un/silencing.
  • Calling code must use redirections to silence unwanted output.

• However, with respect to preference variables and with respect to advanced functions also with respect to common parameters the caller's environment does matter if the code passed in executes in the same scope or a child scope of the caller - and I'm not sure if anything can be done about this:

  • E.g., $WarningPreference='SilentlyContinue'; Invoke-Command { Write-Warning "this won't show" }

  • Because common parameters for advanced functions are implemented in a way that translates them into function-local preference variables, common parameters do therefore affect the code passed; e.g.:

function foo { [CmdletBinding()]param([scriptblock] $sb) & $sb }
foo { Write-Warning "this won't show" } -WarningAction SilentlyContinue

[TobiasPSP]

It has become a complex thread and involves multiple issues, i.e. passing information cross-thread, and different philosophies, i.e. how and where switch parameters should apply.

Can you summarize the conclusions (what you feel is a bug, and how you would want it to work) for the WG review?

[mklement0]

@TobiasPSP, from my perspective, the summary (a condensed version of my previous comment) is:

• Bug:

  • ForEach-Object -Parallel and Start-ThreadJob unexpectedly filter whatever output the code passed via the script block produces, based on their effective settings (whether via preference variable or common parameter), which other out-of-runspace execution methods do not do.

• Need for documentation:

  • Stream-un/silencing common parameters generally do NOT apply to code (script blocks) passed to cmdlets such as Invoke-Command, ForEach-Object, Start-Job - they only apply to stream output generated by the cmdlets themselves. Redirections must be applied to such calls in order to modify the stream output stemming from the execution of the code passed.

  • The above applies invariably to binary cmdlets. However - as a side effect of how common parameters are translated into scope-local preference variables - advanced scripts and functions therefore do in effect apply their common parameters to code they execute that was passed to them as a script block, if that script block is in the same scope domain (session state). Conversely, module functions called from a non-module scope with a script block bound to a non-module / different-module scope behave like binary cmdlets by default.

[TobiasPSP]

Awesome, many thanks