Simultaneous pwsh instance start Mutex.CreateMutexCore IOException race condition

[darthwalsh]

Environment

PSReadLine: 2.1.0
PowerShell: 7.1.3
OS: Darwin 20.5.0 Darwin Kernel Version 20.5.0: Sat May  8 05:10:33 PDT 2021; root:xnu-7195.121.3~9/RELEASE_X86_64
BufferWidth: 176
BufferHeight: 91

Exception report

iTerm session 3:

System.IO.IOException: The system cannot open the device or file specified. : 'PSReadLineHistoryFile_2886463743'
   at System.Threading.Mutex.CreateMutexCore(Boolean initiallyOwned, String name, Boolean& createdNew)
   at System.Threading.Mutex..ctor(Boolean initiallyOwned, String name)
   at Microsoft.PowerShell.PSConsoleReadLine.DelayedOneTimeInitialize()
   at Microsoft.PowerShell.PSConsoleReadLine.Initialize(Runspace runspace, EngineIntrinsics engineIntrinsics)
   at Microsoft.PowerShell.PSConsoleReadLine.ReadLine(Runspace runspace, EngineIntrinsics engineIntrinsics, CancellationToken cancellationToken)

iTerm session 4:

System.IO.IOException: The system cannot open the device or file specified. : 'PSReadLineHistoryFile_2886463743'
   at System.Threading.Mutex.CreateMutexCore(Boolean initiallyOwned, String name, Boolean& createdNew)
   at System.Threading.Mutex..ctor(Boolean initiallyOwned, String name)
   at Microsoft.PowerShell.PSConsoleReadLine.DelayedOneTimeInitialize()
   at Microsoft.PowerShell.PSConsoleReadLine.Initialize(Runspace runspace, EngineIntrinsics engineIntrinsics)
   at Microsoft.PowerShell.PSConsoleReadLine.ReadLine(Runspace runspace, EngineIntrinsics engineIntrinsics, CancellationToken cancellationToken)

Steps to reproduce

(Steps that shouldn't matter: My macbook was asleep in clamshell mode, I unplugged the display connections, and the OS crashed. I logged in and submitted the bug report to Apple, again.)

I saw this message on two tabs when iTerm2 was trying to restore a terminal window with four tab. The first two tabs did not have any error.

iTerm session restore caused 4 pwsh instances to launch at the same time, and got these two crashes from different pwsh instances.

Expected behavior

Launching multiple pwsh instances at the exact same time should not show error.

Actual behavior

Tabs 3 and 4 each showed the exception message above.

---

Running some debug commands, there are a lot of PSReadLineHistoryFile_2886463743 files created at nearly the exact same millisecond:

➜ ~ gci -r /tmp/.dotnet/shm

    Directory: /tmp/.dotnet/shm

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
d----            7/8/2021 10:59 AM                session1999
d----            7/8/2021 12:55 PM                session5595
d----            7/8/2021 10:15 AM                session705
d----            7/8/2021 10:15 AM                session710
d----            7/8/2021 10:15 AM                session715
d----            7/8/2021 10:15 AM                session721

    Directory: /tmp/.dotnet/shm/session715

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 10:15 AM           4096 PSReadLineHistoryFile_2886463743

    Directory: /tmp/.dotnet/shm/session705

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 10:15 AM           4096 PSReadLineHistoryFile_2886463743

    Directory: /tmp/.dotnet/shm/session5595

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 12:44 PM           4096 PSReadLineHistoryFile_2886463743
-----            7/8/2021 12:55 PM           4096 PSReadLineHistoryFile_3946503603

    Directory: /tmp/.dotnet/shm/session1999

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 10:59 AM           4096 PSReadLineHistoryFile_2886463743

    Directory: /tmp/.dotnet/shm/session721

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 10:15 AM           4096 PSReadLineHistoryFile_2886463743

    Directory: /tmp/.dotnet/shm/session710

Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----            7/8/2021 10:15 AM           4096 PSReadLineHistoryFile_2886463743
➜ ~ gci -r -file /tmp/.dotnet/shm | % { $_.LastWriteTime.ToString("MM/dd/yyyy hh:mm:ss.ffffff tt") } | sort-object
07/08/2021 10:15:57.403067 AM
07/08/2021 10:15:57.403165 AM
07/08/2021 10:15:57.425071 AM
07/08/2021 10:15:57.425950 AM
07/08/2021 10:59:23.698350 AM
07/08/2021 12:44:43.666927 PM
07/08/2021 12:55:35.784985 PM

My 2 cents:

• This is not a duplicate of Mutex constructor fails with "system cannot open the device or file specified" #1464. My macOS permissions on /private/tmp are fine, and manually opening a pwsh instances always works.
  • Changing the exception message in Need better error message when it fails to create a Mutex due to no-write permission to the '/tmp' folder on macOS or Linux dotnet/runtime#36823 won't fix the problem of not showing exception message.
• Whatever code that is in charge of picking mutex names is using the same mutex name.
• On Windows, I've seen System.Threading.Mutex throw occasionally if the mutex name is contended.
  • The .ctor() documentation says IOException can happen when some other error happens.
• Maybe pwsh could make the mutex name more unique across instances?
• Maybe pwsh could use a retry loop around mutex code that sometimes throws?

[darthwalsh]

(Issue happened again, after upgrading macOS to 11.5. Had 4 terminal windows that started pwsh simultaneously, and two threw the same way IOException on PSReadLineHistoryFile_2886463743.)

I tried to reproduce the failure by spawning several pwsh from zsh

for i in {1..39}; do; pwsh -nop -c '([datetime]::now).TimeOfDay.TotalMilliseconds' >> b.txt &; done

but even though a few pairs of processes started within the same millisecond, I don't get any IOException. I'm not sure that test loads PSReadLine though. Or, maybe the problem is related to trying to acquire a mutex soon after system startup.

[iSazonov]

It is dup #1464 (comment)

[darthwalsh]

@iSazonov sorry I don't understand why you think it is a duplicate. Here's why I said it is not a duplicate:

• This is not a duplicate of Mutex constructor fails with "system cannot open the device or file specified" #1464. My macOS permissions on /private/tmp are fine, and manually opening a pwsh instances always works.
  • Changing the exception message in Need better error message when it fails to create a Mutex due to no-write permission to the '/tmp' folder on macOS or Linux dotnet/runtime#36823 won't fix the problem of not showing exception message.

[iSazonov]

My bad.

Perhaps it is "by design" in .Net. https://github.com/dotnet/runtime/blob/d019e70d2b7c2f7cd1137fac084dbcdc3d2e05f5/src/libraries/System.Private.CoreLib/src/System/Threading/WaitSubsystem.Unix.cs#L169-L174
The comment says they addresses only thread race conditions but not inter process ones.

I believe it makes sense to open new issue in .Net Runtime repo and ask there.

[darthwalsh]

Oh, good find. Do you have a sense of whether dotnet runtime might fix that bug? Agree it seems likely "by design," but I could open the same bug there.

(I was having some trouble understanding which resource the mutex is guarding. Before I was thinking the resource is i.e. the file /tmp/.dotnet/shm/session5595/PSReadLineHistoryFile_2886463743 -- then the mutex name hash could include the session ID in the name of the mutex, and that should further decrease contention and avoid this error. But I don't see any PSReadLine code interacting with this file, I'm guessing that's literally the dotnet implementation of the named mutex library. Instead 2886463743 looks to be the hash of /Users/walshca/.local/share/powershell/PSReadLine/ConsoleHost_history.txt so my suggestion about making the mutex use a more unique name is wrong.)

I see the other code interacting with the mutex has retry loops. If we understand mutex creation has by-design some chance of throwing, should PSReadLine also use a retry loop when creating the mutex?

[iSazonov]

As for PSRL @daxian-dbw can add more info and make a conclusion about using a loop in the code.
I think it makes sense to open request in .Net Runtime repository. They could add a loop too.

[daxian-dbw]

@darthwalsh and @iSazonov Thank you both for the investigation so far. I will need to get a macOS to try reproducing the issue.
A couple clarification:

1. the mutex is to guard the read/write access of the history file, which is shared by all pwsh instances for a given user.
2. the re-try we have is for abandoned mutex, which we understand why a retry is needed in that case -- the thread owns the mutex, however, it was abandoned by the previous owner thread, so releasing and then retry is needed. But for this IOException, we have no idea what causes it and thus I don't want to blindly add the retry logic.

I'd love to understand the root cause before making any changes in the code.

[SteveL-MSFT]

This issue is quite annoying for dev testing powershell builds on macOS. Workaround is to use -noninteractive so that PSReadLine doesn't automatically get loaded.

It seems the problem is the way a mutex is implemented is different across Windows, Linux, and macOS. On macOS it's a file lock: dotnet/runtime#5211 (comment). So if access to that file can't be retrieved, you get the IOException.

[SteveL-MSFT]

I think an alternative solution is if the mutex can't be created, just have that instance not save to history and put out a warning message.

[SteveL-MSFT]

I have a potential fix, but no longer able to repro the issue. Probably because it's a race condition and my changes have changed the timing, but until I can verify it improves it, I'll hold off on a PR

[darthwalsh]

@SteveL-MSFT Printing a warning message that this powershell instance will not save history isn't much of an improvement (in my opinion) -- if I saw that, I would always manually close and reopen that pwsh instance -- which is what I did after seeing the IOException.

But yeah, being able to reproduce the problem on demand is something I wish was easier. What the steps seem to be:

• having iTerm2 set to reopen tabs after system restart, and 4 tabs open (it could help to open dozens of tabs)
• either crash the operating system, OR do an operating system upgrade
• sometimes this triggers the IOException

(I retried my earlier "tight loop" but with a C# app just calling new Mutex( -- launched 4000 times at once, but didn't have any errors.)