Message being lost with -Wait-Logging flag

[vandre]

I have a script that does tasks in different threads and I noticed that some messages were being lost. I used the following script to test:

function Config-Logging {
    Set-LoggingDefaultLevel -Level 'INFO'
    Add-LoggingTarget -Name File -Configuration @{Path = 'C:\Temp\example_%{+%Y%m%d}2.csv'}
}
$Level = 'DEBUG', 'INFO', 'WARNING', 'ERROR'

$LoggingDemo = {
    Config-Logging
    foreach ($i in 1..100) {
        Write-Log -Level ($Level | Get-Random) -Message 'Message n. {0} , Job{1} ' -Arguments @($i, $_)
        Start-Sleep -Milliseconds (Get-Random -Min 100 -Max 150)
    }

    Wait-Logging
}

1..5 | Start-RSJob -ScriptBlock $LoggingDemo -ModulesToImport 'Logging', 'PoshRSJob' -VariablesToImport 'Level' -FunctionsToImport 'Config-Logging'

The script above spawns 5 concurrent threads, each one logging 100 message to the log file.

Expected result: 500 lines written to example CSV file Actual result: Number of lines written varies. May need to try different times.

Note: I'm using PoshRSJob for multithreading.

[EsOsO]

I need to take a look into this issue cause my module uses runspace to spawn a thread that actually write the log.

Maybe a runspace inside another runspace is not a good idea for the sanity of the environment in which it runs.

I'll take a look to see if I can work around something

[SilentBob999]

Hi, I also notice that some message appears after Wait-Logging and can be lost at the end of a script. I am using those two target: WinEventLog & Console.

I am having a real hard time to understand the mechanic behind the module as I am not familiar with anything related to “runspace”.

I notice that Wait-Logging is waiting for “LoggingEventQueue.Count -gt 0”. However, is the count goes to Zero as soon as “.GetConsumingEnumerable()” is executed?

As a workaround, I move the sleep in Wait-Logging to be after the Count check. And that does help. However, I need at least 200ms to be somewhat reliable.

https://github.com/SilentBob999/Logging/commit/bd84551b9941296679403de369c284e5f581aeca

[EsOsO]

@SilentBob999 Are you using the logging module with PoshRSJob?

[SilentBob999]

Hi @EsOsO , I do not use PoshRSJob. It is all sequential, no "jobs" of any kind. Just a lot of code fragmentation (dot sourcing, import-module, etc....)

[tosoikea]

GetConsumingEnumerable

The count does not drop to zero just by calling 'GetConsumingEnumerable()'. This can be shown by the following code snippet.

New-Variable -Name LoggingEventQueue    -Scope Script -Value ([System.Collections.Concurrent.BlockingCollection[int]]::new(1000))
New-Variable -Name LoggingRunspace      -Scope Script -Option ReadOnly -Value ([hashtable]::Synchronized(@{ }))

$Script:InitialSessionState = [initialsessionstate]::CreateDefault()

if ($Script:InitialSessionState.psobject.Properties['ApartmentState']) {
    $Script:InitialSessionState.ApartmentState = [System.Threading.ApartmentState]::MTA
}

# Importing variables into runspace
foreach ($sessionVariable in 'LoggingEventQueue') {
    $Value = Get-Variable -Name $sessionVariable -ErrorAction Continue -ValueOnly
    Write-Verbose "Importing variable $sessionVariable`: $Value into runspace"
    $v = New-Object System.Management.Automation.Runspaces.SessionStateVariableEntry -ArgumentList $sessionVariable, $Value, '', ([System.Management.Automation.ScopedItemOptions]::AllScope)
    $Script:InitialSessionState.Variables.Add($v)
}

#Setup runspace
$Script:LoggingRunspace.Runspace = [runspacefactory]::CreateRunspace($Script:InitialSessionState)
$Script:LoggingRunspace.Runspace.Name = 'LoggingQueueConsumer'
$Script:LoggingRunspace.Runspace.Open()

# Spawn Logging Consumer
$Script:LoggingEventQueue.Add(1)
$Script:LoggingEventQueue.Add(2)
$Script:LoggingEventQueue.Add(3)
$Script:LoggingEventQueue.Add(4)
$Script:LoggingEventQueue.Add(5)
$Script:LoggingEventQueue.Add(6)
$Script:LoggingEventQueue.Add(7)
$Script:LoggingEventQueue.Add(8)
$Script:LoggingEventQueue.Add(9)
$Script:LoggingEventQueue.Add(10)

$Consumer = {
    foreach ($Log in $Script:LoggingEventQueue.GetConsumingEnumerable()) {
        Start-Sleep -Milliseconds 200
    }
}

$Script:LoggingRunspace.Powershell = [Powershell]::Create().AddScript($Consumer, $true)
$Script:LoggingRunspace.Powershell.Runspace = $Script:LoggingRunspace.Runspace
$Script:LoggingRunspace.Handle = $Script:LoggingRunspace.Powershell.BeginInvoke()

while ($Script:LoggingEventQueue.Count -gt 0){
    Write-Host $Script:LoggingEventQueue.Count
}

Write-Host "Fin"

Wait-Logging

The last part is about messages being lost, the only portion that should (now) be able to be lost is the last message with Wait-Logging. This could be "fixable" by simply adding another Wait-Sleep after the loop.

(I used my current feature implementation, however this should not alter from the current master.)

function Config-Logging {
    param(
        [Parameter(Mandatory)]
        [String]
        $Name
    )
    Set-LoggingDefaultLevel -Level 'INFO'
    Add-LoggingTarget -Name File -Configuration @{Path = "C:\Users\soennecken\source\repos\private\Logging\ParallelTest\Run_"+$Name+".txt"}
}
$Level = 'DEBUG', 'INFO', 'WARNING', 'ERROR'

$LoggingDemo = {
    Config-Logging -Name ([Guid]::NewGuid())
    foreach ($i in 1..1000) {
        Write-Log -Message 'Message n. {0} , Job{1} ' -Arguments @($i, $_) -Level ERROR
        Start-Sleep -Milliseconds (Get-Random -Min 2 -Max 10)
    }

    Wait-Logging
}

1..5 | Start-RSJob -ScriptBlock $LoggingDemo -ModulesToImport 'Logging', 'PoshRSJob' -VariablesToImport 'Level' -FunctionsToImport 'Config-Logging' | Wait-RSJob | Receive-RSJob

[tosoikea]

@EsOsO I think this issue can now be closed.