Sporadic failure in file enumeration tests on Unix #54589

Activity

1. ghost added

   area-System.IO

   on Jun 23, 2021
2. ghost added

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jun 23, 2021
4. danmoseley commented on Jun 23, 2021

   

   danmoseley

   on Jun 23, 2021

   ContributorAuthor

   More actions

   Doh - that's a Windows change, still the date these started seems to be 2021-06-15 21:36:40.9310000

   https://engsrvprod.kusto.windows.net/engineeringdata?query=H4sIAAAAAAAEAG2QQWsCMRCF74L%2fYdiLLay6emthC7YiWKjQKvQo02Tqxt2dSGYWEfzxTdT2VAhMMvky771sSPSDpGtUoN87w947htqxLR0zBfj0oV4qtQKe%2fw5L%2by%2f76r8uWKxLm4BjRYFg4dhJRRaeSrCopK6lu2kxLYbFw3ACxWOR1n2%2fh2xhczoQiGJQOTqtIFufJCqOVqSj7Iq8kVbeQllC9uKjsNHtnGW77owhkRt0zZSgwQJdM%2bj3xuPrYxHcERjPio4FshkDapQ4KBxRoEVLoB40IItTF%2fMgKEqdmgjfjrFJBpVSPAanUKEFbAKhPcW57aEhJZvcnuEQ%2fD4ahHVKRDaHeRcwDc1vMXJ476ijFbY0yX%2fd5Yk39SagiftZ2HUtsUq8R1M5vtA5PEeHpsovX%2fYDIyPQ4McBAAA%3d&web=0

   TestResults
   | join kind=inner WorkItems on WorkItemId
   | join kind=inner Jobs on JobId
   | where Finished >= datetime(2020-09-1 0:00:00)
   and Type startswith "System.Net."
   and Method == "Connect_Dns_Success"
   and Result == 'Fail'
   //and Message contains "An attempt was made to transition a task to a final state when it had already completed."
   | project Started, Duration, Method, QueueName1, Message, StackTrace, Arguments, MachineName, Branch, Type
5. stephentoub

   added this to the 6.0.0 milestone on Jun 23, 2021
6. stephentoub

   added

   bug

   on Jun 23, 2021
7. adamsitnik

   self-assigned this

   on Jun 23, 2021
8. adamsitnik

   removed

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jun 23, 2021
9. adamsitnik commented on Jun 23, 2021

   

   adamsitnik

   on Jun 23, 2021

   Member

   More actions

   The issue seems to be very mysterious. Let's consider following example:

           System.UnauthorizedAccessException : Access to the path '/tmp/Directory_GetFiles_str_str_so_u0xtgtez.eug/PrepareDirectory_539_628354c3/foobar.txt' is denied.
           ---- System.IO.IOException : Bad file descriptor
           Stack Trace:
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/Microsoft/Win32/SafeHandles/SafeFileHandle.Unix.cs(74,0): at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String path, OpenFlags flags, Int32 mode)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/Microsoft/Win32/SafeHandles/SafeFileHandle.Unix.cs(158,0): at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/Strategies/Net5CompatFileStreamStrategy.cs(92,0): at System.IO.Strategies.Net5CompatFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/Strategies/FileStreamHelpers.Unix.cs(16,0): at System.IO.Strategies.FileStreamHelpers.ChooseStrategyCore(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/Strategies/FileStreamHelpers.cs(20,0): at System.IO.Strategies.FileStreamHelpers.ChooseStrategy(FileStream fileStream, String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs(210,0): at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs(146,0): at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
             /home/adam/projects/main/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs(141,0): at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, Boolean useAsync)
   

   The source code:

   runtime/src/libraries/System.Private.CoreLib/src/Microsoft/Win32/SafeHandles/SafeFileHandle.Unix.cs

   Lines 43 to 74 in 0416c34

   	SafeFileHandle handle = Interop.Sys.Open(path, flags, mode);
   	if (handle.IsInvalid)
   	{
   	handle.Dispose();
   	Interop.ErrorInfo error = Interop.Sys.GetLastErrorInfo();
   	// If we fail to open the file due to a path not existing, we need to know whether to blame
   	// the file itself or its directory. If we're creating the file, then we blame the directory,
   	// otherwise we blame the file.
   	//
   	// When opening, we need to align with Windows, which considers a missing path to be
   	// FileNotFound only if the containing directory exists.
   	bool isDirectory = (error.Error == Interop.Error.ENOENT) &&
   	((flags & Interop.Sys.OpenFlags.O_CREAT) != 0
   	|| !DirectoryExists(Path.GetDirectoryName(Path.TrimEndingDirectorySeparator(path!))!));
   	Interop.CheckIo(
   	error.Error,
   	path,
   	isDirectory,
   	errorRewriter: e => (e.Error == Interop.Error.EISDIR) ? Interop.Error.EACCES.Info() : e);
   	}
   	// Make sure it's not a directory; we do this after opening it once we have a file descriptor
   	// to avoid race conditions.
   	Interop.Sys.FileStatus status;
   	if (Interop.Sys.FStat(handle, out status) != 0)
   	{
   	handle.Dispose();
   	throw Interop.GetExceptionForIoErrno(Interop.Sys.GetLastErrorInfo(), path);

   What happens:

   1. The file is being opened and a SafeFileHandle is being created. The result is stored in a local variable, which is not shared with anyone else. (line 43)
   2. We check if handle is valid and it's fine (line 45)
   3. We call FStat using the handle and it fails. (line 71)
   4. The last error returns Bad file descriptor. Descriptor can be bad when it's closed. But how is it possible that it got closed since it has not been shared with anyone yet? (line 74)

   My current reaction:
   

   ❤️React with ❤️1Reacted by Dan Moseley
10. danmoseley commented on Jun 23, 2021

    

    danmoseley

    on Jun 23, 2021

    ContributorAuthor

    More actions

    Brainstorming - are there other possible causes of EBADF? Eg., file is locked by someone using a different fd?
    @tmds
11. tmds commented on Jun 23, 2021

    

    tmds

    on Jun 23, 2021

    Member

    More actions

    A thought about the code @adamsitnik shared:

     if (Interop.Sys.FStat(handle, out status) != 0) 
     { 
         handle.Dispose(); 
         throw Interop.GetExceptionForIoErrno(Interop.Sys.GetLastErrorInfo(), path); 

    We should call GetLastErrorInfo before calling Dispose, otherwise Dispose might change the error.

    I'll look at the issue closer in the coming week.
12. jkotas commented on Jun 24, 2021

    

    jkotas

    on Jun 24, 2021

    Last edited by jkotas

    Member

    More actions

    The last error returns Bad file descriptor. Descriptor can be bad when it's closed. But how is it possible that it got closed since it has not been shared with anyone yet? (line 74)

    The easiest explanation is that some other thread closed the file descriptor in the meantime. File descriptors are small numbers, and get reused heavily. This is a potential sequence of events:

    Thread A: calls close
    Thread B: calls open - returns same fd as Thread A just closed
    Thread A: calls close second time (bug!). It closes fd that Thread B is holding to now.
    Thread B: calls lstat and gets EBADF

    This failure pattern is consistent with what happened in #54615. The code called pipe syscall and immediately got EBADF trying to operate on the pipe file descriptors.

    So I would be looking for a buggy code that is calling close twice.

    ❤️React with ❤️1Reacted by Adam Sitnik
13. jkotas

    added

    blocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

    on Jun 24, 2021
14. danmoseley commented on Jun 24, 2021

    

    danmoseley

    on Jun 24, 2021

    Last edited by danmoseley

    ContributorAuthor

    More actions

    Oh of course. Hmm, interesting, as just about everything uses SafeXHandle, so it should be hard to call close() twice.

    More info from Kusto: first hit is 2021-06-15 21:36:40.9310000 (I assume it's UTC) after which it happens fairly often so I'd guess that's within a few hours of the problem being introduced. 9d771a2 went in at Tue Jun 15 20:59:58 2021 +0200.

    It happens in both release and debug. It only happens when running System.IO.Tests.* - which is consistent with the bug being in the tests, but not conclusive. It hits mostly tests that enumerate files, perhaps because there's a lot of fd's involved. The biggest hitter is System.IO.Tests.DirectoryInfo_EnumerateFiles_str_str but there are many others.

    It's evenly distributed across distros and macOS, but of course never Windows. Both x64 and Arm.

    ❤️React with ❤️1Reacted by Adam Sitnik
15. danmoseley commented on Jun 24, 2021

    

    danmoseley

    on Jun 24, 2021

    ContributorAuthor

    More actions

    Is this problematic?
    

    runtime/src/libraries/System.IO.FileSystem/tests/RandomAccess/Base.cs

    Lines 44 to 53 in 9d771a2

    	[Fact]
    	[SkipOnPlatform(TestPlatforms.Browser, "System.IO.Pipes aren't supported on browser")]
    	public void ThrowsNotSupportedExceptionForUnseekableFile()
    	{
    	using (var server = new AnonymousPipeServerStream(PipeDirection.Out))
    	using (SafeFileHandle handle = new SafeFileHandle(server.SafePipeHandle.DangerousGetHandle(), true))
    	{
    	Assert.Throws<NotSupportedException>(() => MethodUnderTest(handle, Array.Empty<byte>(), 0));
    	}
    	}

    The SafeFileHandle takes ownership of the raw pipe handle. it is disposed and closes it, then the pipe is disposed and closes it again. This was introduce by above change.

    👍React with 👍1Reacted by Jan Kotas
16. danmoseley

    added a commit that references this issue on Jun 24, 2021

    Fix sporadic double fd close

    ...

    14b2cfb
17. ghost added

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Jun 24, 2021
18. stephentoub

    closed this as completedin #54660on Jun 24, 2021
19. stephentoub

    added a commit that references this issue on Jun 24, 2021

    Fix sporadic double fd close (#54660)

    ...

    f55390a
20. ghost removed

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Jun 24, 2021
21. adamsitnik commented on Jun 24, 2021

    

    adamsitnik

    on Jun 24, 2021

    Member

    More actions

    @danmoseley @tmds @jkotas big thanks for your help!!

    With #54660 I can't reproduce it anymore.

    We should call GetLastErrorInfo before calling Dispose, otherwise Dispose might change the error.

    I've opened #54667 to address that
22. danmoseley

    added a commit that references this issue on Jun 25, 2021

    Fix sporadic double fd close (#54660)

    ...

    6deeab0
23. ghost locked as resolved and limited conversation to collaborators on Jul 24, 2021