Powershell Remoting: Console output is out of order

PowerShell Help
1

Scenario. Script A runs on my host machine and it is invoking script B on remote machine. Script B invokes other scripts (say script C, D, E in sequence) on remote machine. When I look at the console output at host machine, it is not displayed in sequence.

I am intentionally throwing exception in script D. I see the below console output in host machine:

Exception thrown by D

Logs of script C

Logs of script D

Logs of script E.

I was expecting exception thrown by D to be displayed after “Logs of script D”. Does anyone know why the logs are appearing out of order? How can I fix it?

Thanks

 

2

Hi there Ramona. Would you be willing to share code? It’ll greatly help us out in figuring out what the issue is.

3

Exceptions tend to propagate up the stack and display as soon as they occur, unless you deliberately include some code to delay them showing up by catching or storing errors as they occur.

This is due to the error and output streams being completely separated in PowerShell. See Get-Help about_Redirection for more detailed information. :slight_smile:

4

Snip of Script A:

    $job = Invoke-Command -ComputerName $SlaveMachine -ScriptBlock {
        param([string] $RemoteScript,
              [string] $Location,
              [string] $LogDest,
              [string] $controller
        )
        Set-ExecutionPolicy -Scope Process -ExecutionPolicy Bypass
        # Following has errors
        # & cmd.exe /c powershell.exe -File $RemoteScript -cmd $Runnable
        & powershell.exe -File $RemoteScript -Location $Location -LogDest $LogDest -initiator $controller

        # Following completes cleanly
        # & $RemoteScript -cmd $Runnable > "C:\drop\out.txt"
    } -ArgumentList $ScriptB, $Location, $LogDest, $thisMachine -Credential $C -AsJob

    Wait-Job $job | Out-Null
    $r = Receive-Job $job

Snip of Script B:

    for ($index= 0; $index -lt $length; $index++)
    {
     ...
        & $Script[index]  // Execute scripts C, D, E in sequence
    }

Snip of Script D:

   Write-Warning "This is warning message"
   throw "Could not complete operation"
   Write-Error "Writing error message to error stream"

I see the below output on console:

Error: Could not complete operation
+ CategoryInfo : NotSpecified: (… operation:String) , RemoteException
+ FullyQualifiedErrorId : NativeCommandError

Log of script C
WARNING: This is warning message // Log of Script D
Log of script E

If I run the script B directly on my host machine, I see the results in expected order as below:
Log of Script C
WARNING: This is warning message
Process-ConfigData : Error: Could not complete operation

+ CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
+ FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,

Log of script E

I am not sure why in case of remoting. Logs appear out of order.

5

Hi Will, I have shared relevant code snippet. I hope it helps. Thanks

6

If you would like to capture errors from the invocation, I would recommend against running a nested powershell instance; Invoke-Command is already running PowerShell. Provided the $RemoteScript file(s) implement the [CmdletBinding()] attribute, you can use -ErrorVariable to store errors and output them later.

$job = Invoke-Command -ComputerName $SlaveMachine -ScriptBlock {
    [CmdletBinding()]
    param(
        [string] $RemoteScript,
        [string] $Location,
        [string] $LogDest,
        [string] $controller
    )
    Set-ExecutionPolicy -Scope Process -ExecutionPolicy Bypass
    $RemoteParams = $PSBoundParameters.Clone()
    $RemoteParams.Remove('RemoteScript')
    $Output = & $RemoteScript @RemoteParams -ErrorVariable Errors
    # You can do whatever you need with $Output and $Errors after this point
} -ArgumentList $ScriptB, $Location, $LogDest, $thisMachine -Credential $C -AsJob

Wait-Job $job | Out-Null
$r = Receive-Job $job
7

Hi Joel, as per my understanding $Errors and $Output will capture the output and error logs separately, right? I want to capture the errors as part of output logs so that I know the log sequence which led upto the error. It helps in debugging the issues. Please correct me if I am wrong. Thanks

8

That’s correct, yes.

In that case you can redirect the error stream to be part of the output:

$Output = & $RemoteScript @RemoteParams 2>&1

However… keep in mind that unless you directly emit output from the script at the same point as the error would be emitted, there will still be a disconnect. Errors will natively contain line number and other data that you can use for debugging.

Beyond that, you will need to modify the called scripts to ensure they are handling their errors internally and outputting them in the correct places that you want to see them.