Messages to host get jumbled when logging from parallel tasks

[chadbaldwin]

As the title suggests, when I try to log messages from a parallel process, the messages become jumbled when written to the host.

Sample script:

1..10 | ForEach-Object -Parallel {
    1..3 | ForEach-Object -Parallel {
        Write-PSFMessage -Level Host '[SomeInfo] This is a test'
    } -ThrottleLimit 2
} -ThrottleLimit 3

(the parallel nesting here is not required to cause the issue, but it makes the issue much more prevalent)

Sample output:

[[[[15:14:0515:14:05][<ScriptBlock>] [SomeInfo] This is a test
[15:14:05[][<ScriptBlock>] [SomeInfo] This is a test
][<ScriptBlock>15:14:05] [SomeInfo] This is a test
][<ScriptBlock>] [SomeInfo] This is a test
15:14:05][<ScriptBlock>] [SomeInfo] This is a test
[15:14:05][<ScriptBlock>] [SomeInfo] This is a test
[15:14:05][<ScriptBlock>] [SomeInfo] This is a test
15:14:05][<ScriptBlock>] [SomeInfo] This is a test
[15:14:05][<ScriptBlock>] [SomeInfo] This is a test
[[15:14:0715:14:07][][<ScriptBlock><ScriptBlock>] [SomeInfo] This is a test
] [SomeInfo] This is a test
[15:14:07[][<ScriptBlock>] [SomeInfo] This is a test
15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:07][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[15:14:08][<ScriptBlock>] [SomeInfo] This is a test
[[15:14:09][<ScriptBlock>] [SomeInfo] This is a test
15:14:09][<ScriptBlock>] [SomeInfo] This is a test
[15:14:09][<ScriptBlock>] [SomeInfo] This is a test

Not sure if there's anything I can do here to help prevent the messages from being jumbled up.

I'm currently in the process of migrating to PSFramework for my logging. Prior to using PSFramework, I ran into this same issue when trying to handle logging myself, and the solution I had come up with at the time was to write log messages as output and then place my log writer function in the pipeline to capture the output of ForEach-Object.

Example:

1..10 | ForEach-Object -Parallel {
    1..3 | ForEach-Object -Parallel {
        Write-Output '[SomeInfo] This is a test'
    } -ThrottleLimit 2
} -ThrottleLimit 3 *>&1 | Write-Log

This way it was always logged serially. But it's kind of a dirty solution that I'm hoping PSFramework can resolve.

I realize that there is a console logging provider, but I want to use the message provider so that I can include colors.

[FriedrichWeinmann]

Thanks for reporting this.

[FriedrichWeinmann]

Sorry about the accidental close there - live and learn, CTRL+SHIFT+Enter are a bad combination to hit as you type in Github ^^
The issue here is that behind the scenes, what happens is, that Write-PSFMessage calls Write-PSFHostColor, which does its coloring with multiple Write-Host calls.
And since they happen in parallel, they can interfere. The same risk is with simple ForEach-Object -Parallel, it's just that very specific timing is needed to hit this issue.

There is a way around this - with the "new" color-codes this can become a single Write-Host - I just never bothered to implement it.
Adding it to the pile for the next version.

PS:
You may want to switch over to Invoke-PSFRunspace - it works mostly the same, but also runs on WinPS 5.1 (and has more, shiny features ;) )