I think we have all been there at some point. We have multiple processes running, either through multiple powershell.exe consoles or using PSJobs (maybe even runspaces ) and we have decided that specific data from our running commands should go to a single logfile. Well what do you think will happen at some point when 2 (or more) commands collide?

Yes, the dreaded “cannot access file…because it is in use by another process” that we have come to know and despise. This little error and cause unnecessary data loss on your file and a lot of frustration when you see it happening.

The answer to this question is using a Mutex (http://msdn.microsoft.com/en-us/library/windows/desktop/ms686927(v=vs.85).aspx | http://msdn.microsoft.com/en-us/library/system.threading.mutex(v=vs.110).aspx). In my case, I am going to show you a named mutex. With a named mutex, we can specify a mutex with a name on one process and then tell it to take the mutex and on another process (yes, another PowerShell console would work) and call the same named mutex and if we attempt to take the mutex, it will create a blocking call until the other process relinquishes control of it. What this allows us to do is have multiple processes that can write to a single file without fear of missing data due to the file being locked.

Note: If working in a Terminal Server, prefix name with “Global\” to make mutex available in all sessions and “Local\” if you wish to make the mutex available in the current working session.

To create a named mutex, we can do the following:

 
$mtx = New-Object System.Threading.Mutex($false, "TestMutex")

This is actually creating the mutex and specifying a name (TestMutex) while specifying $False as I do not want to own this mutex yet. Next up is actually taking control of the mutex so nothing else can attempt to hold it.

 
$mtx.WaitOne()

If nothing else has ownership of the mutex, then it will automatically move on to the next command, otherwise it will perform a blocking call, meaning that you cannot do anything else until the other process gives up the mutex. Note that you can specify a timeout (in milliseconds) that will cause your attempt to return $False (instead of $True) if the timeout has been reached.

 
$mtx.WaitOne(1000)

As you can see, while one process has the mutex, the other process eventually times out while waiting to get the mutex. Now if we do not specify a timeout, we will see the console block…

…Until I release the mutex on the other process. Then I can write the logfile.

 
$mtx.WaitOne()
'other important data' | Out-File C:\importantlogfile.txt -Append
$mtx.ReleaseMutex()

To get a better idea about this, I wrote a little script to run on separate processes. Here is the script code:

 
$Log = "C:\temp\log.txt"
1..10 | ForEach {
    Write-Verbose "Attempting to grab mutex" -Verbose
    $mtx = New-Object System.Threading.Mutex($false, "TestMutex")
    If ($mtx.WaitOne(1000)) { #Calling WaitOne() without parameters creates a blocking call until mutex available
        Write-Verbose "Recieved mutex!" -Verbose
        $Sleep = Get-Random (1..5)
        #Simulate writing data to log file
        Write-Verbose "Writing data $($_) to $log" -Verbose
        Start-Sleep -Seconds $Sleep
        Write-Verbose "Releasing mutex" -Verbose
        [void]$mtx.ReleaseMutex()
    } Else {
        Write-Warning "Timed out acquiring mutex!"
    }
}
$mtx.Dispose()
Write-Verbose 'Finished!' –Verbose

Now I will run it on two PowerShell processes and observe what happens.

Here you can see that both processes will take turn (for the most part) in grabbing the mutex and writing to a logfile. Sometimes though, it will timeout and attempt to grab the mutex again.

That was pretty cool, but let’s overcomplicate this by adding runspaces into the mix and by showing examples of both using mutexs and not using mutexs just to further illustrate why you should use a mutex when writing to a single logfile. Note that the source code will be available at the end of this article due to its length. The name of the script is called Invoke-MutexTestRunspace.ps1.

No Mutexs

 
.\Invoke-MutexTestRunspace.ps1 –NoMutex –Logfile C:\Testlog.txt

Here we see on the right that there were some missed writes to the logfile due to the process on the left currently holding a lock on it. Now to use the mutexs and see what happens.

Using a Mutex

 
.\Invoke-MutexTestRunspace.ps1 –Logfile C:\Testlog.txt

This shows that both processes are sharing time writing to the common logfile by waiting as each one holds onto the mutex and then once it has been released, is taken by the next process and proceeds to write to the logfile.

So with that, you can see how to use a mutex to allow for multiple processes writing to the same logfile (or actually anything else that you can think of) without fear of losing data from a process due to a file lock.

Source Code for Invoke-MutexTestRunspace.ps1

 
Param (
    $LogFile = 'C:\testlog.txt',
    $Throttle = 20,
    $Count = 100,
    [switch]$NoMutex
)

$Parameters = @{
    LogFile = $LogFile
    NoMutex = $NoMutex
}

$DebugPreference = 'Continue'

$RunspacePool = [runspacefactory]::CreateRunspacePool(
    1, #Min Runspaces
    10, #Max Runspaces
    [System.Management.Automation.Runspaces.InitialSessionState]::CreateDefault(), #Initial Session State; defines available commands and Language availability
    $host #PowerShell host
)

$RunspacePool.Open()

$jobs = New-Object System.Collections.ArrayList

1..$Count | ForEach {
    $PowerShell = [powershell]::Create()
    
    $PowerShell.RunspacePool = $RunspacePool
    
    [void]$PowerShell.AddScript({
        Param(
            $LogFile,
            $NoMutex
        )
        If (-Not $NoMutex) {
            $mtx = New-Object System.Threading.Mutex($false, "LogMutex")
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Requesting mutex!" -Verbose
            $mtx.WaitOne()
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Recieved mutex!" -Verbose        
        }
        Try {
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Writing data $($_) to $LogFile" -Verbose
            "[$(Get-Date)] | ThreadID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId) | ProcessID $($PID) | Data: $($_)" | Out-File $LogFile -Append
        } Catch {
            Write-Warning $_
        }
        If (-Not $NoMutex) {
            Write-Verbose "[$(Get-Date)][PID: $($PID)][TID: $([System.Threading.Thread]::CurrentThread.ManagedThreadId)] Releasing mutex" -Verbose
            [void]$mtx.ReleaseMutex()
        }
    })

    [void]$PowerShell.AddParameters($Parameters)

    $Handle = $PowerShell.BeginInvoke()
    $temp = '' | Select PowerShell,Handle
    $temp.PowerShell = $PowerShell
    $temp.handle = $Handle
    [void]$jobs.Add($Temp)
    
    Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
    Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
        $_.handle.iscompleted -ne 'Completed'
    }).Count)
}

#Verify completed
Write-Debug ("Available Runspaces in RunspacePool: {0}" -f $RunspacePool.GetAvailableRunspaces()) 
Write-Debug ("Remaining Jobs: {0}" -f @($jobs | Where {
    $_.handle.iscompleted -ne 'Completed'
}).Count)

$return = $jobs | ForEach {
    $_.powershell.EndInvoke($_.handle);$_.PowerShell.Dispose()
}
$jobs.clear()