SafeHandle use-after-dispose in FileSystemWatcher on OSX #30056

Activity

1. stephentoub commented on Jun 26, 2019

   

   stephentoub

   on Jun 26, 2019

   Last edited by stephentoub

   MemberAuthor

   More actions

   cc: @MaximLipnin
   Maybe related to dotnet/corefx#33865
2. danmoseley commented on Jul 1, 2019

   

   danmoseley

   on Jul 1, 2019

   Contributor

   More actions

   @stephentoub do you know what could cause a NRE in a native call into macOS? Is the interop layer translating some kind of errno returned from the OS here?

   Then I see we get a COR_E_EXECUTIONENGINE while trying to deal with the exception.
3. stephentoub commented on Jul 1, 2019

   

   stephentoub

   on Jul 1, 2019

   MemberAuthor

   More actions

   Not sure; @jkoritzinsky, @AaronRobinsonMSFT, ideas?
4. AaronRobinsonMSFT commented on Jul 1, 2019

   

   AaronRobinsonMSFT

   on Jul 1, 2019

   Member

   More actions

   @danmosemsft and @stephentoub The COR_E_EXECUTIONENGINE can be caused by an invalid P/Invoke stub or invalid translation as well. I did recently fix a few issues in macOS regarding race conditions in shutdown - dotnet/coreclr#24847. How often is this happening? dotnet/corefx#33865 does look promising too. Can someone point to the P/Invoke that is causing this issue?
5. stephentoub commented on Jul 1, 2019

   

   stephentoub

   on Jul 1, 2019

   Last edited by stephentoub

   MemberAuthor

   More actions

   @AaronRobinsonMSFT, I only saw it that once. This is the P/Invoke:
   https://github.com/dotnet/corefx/blob/2aa2518a47c541148e2dc3f9d040942e44395acd/src/Common/src/Interop/OSX/Interop.RunLoop.cs#L33-L35
   where CoreFoundationLibrary is:
   https://github.com/dotnet/corefx/blob/2aa2518a47c541148e2dc3f9d040942e44395acd/src/Common/src/Interop/OSX/Interop.Libraries.cs#L9
6. danmoseley commented on Jul 1, 2019

   

   danmoseley

   on Jul 1, 2019

   Contributor

   More actions

   For future reference, it seems console output cannot directly be queried in Kusto. The best we can easily do is look for 134

   WorkItems 
   | where Started > now(-10d)  
   | where FriendlyName == "System.IO.FileSystem.Watcher.Tests"
   | where ExitCode == 134
   | join kind= inner (
      Jobs  | where Started > now(-10d) | project  QueueName , JobId, Build, Type, Source 
   ) on JobId
   | summarize count() by ExitCode, QueueName
   | order by count_ desc
   

   ExitCode QueueName count_
   134 Ubuntu.1604.Arm32.Open 28
   134 Ubuntu.1604.Arm64.Docker.Open 25
   134 Ubuntu.1804.Amd64.Open 6
   134 OSX.1013.Amd64.Open 1

   compared to ~5000 with 0 exit code.
   
7. AaronRobinsonMSFT commented on Jul 2, 2019

   

   AaronRobinsonMSFT

   on Jul 2, 2019

   Member

   More actions

   @danmosemsft Do we know what version of coreclr is being used to run the tests themselves? Is it possible the coreclr being used in this instance is older than the date at which dotnet/coreclr#24847 was checked in?
8. stephentoub commented on Jul 2, 2019

   

   stephentoub

   on Jul 2, 2019

   MemberAuthor

   More actions

   We'd have to dig to see which exact version, but this was 5 days ago, and corefx ingested a new coreclr 5 days ago, 6 days ago, and 7 days ago, so it definitely has that change from end of May.

   👍React with 👍1Reacted by Aaron R Robinson
9. danmoseley commented on Jul 2, 2019

   

   danmoseley

   on Jul 2, 2019

   Contributor

   More actions

   @mjanecke can you tell from the output at https://mc.dot.net/#/user/dotnet-bot/pr~2Fdotnet~2Fcorefx~2Frefs~2Fpull~2F38953~2Fmerge/test~2Ffunctional~2Fcli~2Finnerloop~2F/20190626.70/workItem/System.IO.FileSystem.Watcher.Tests/wilogs whether a dump got uploaded? I don't see the usual dumpling song and dance.
10. missymessa commented on Jul 2, 2019

    

    missymessa

    on Jul 2, 2019

    Member

    More actions

    @danmosemsft, for that test, it looks like the failure happened on a Mac, which I don't think @epananth has finished implementing for dump collection yet.
11. danmoseley commented on Jul 2, 2019

    

    danmoseley

    on Jul 2, 2019

    Contributor

    More actions

    @mjanecke good point, and last I heard we did not have a way to create a dump on Mac (that could be debugged with managed debuggers). @mikem8361 any update on that? Is our only option to catch this under an attached debugger?

    (It's quite possible this isn't Mac specific actually but I'm interested anyway)
12. mikem8361 commented on Jul 2, 2019

    

    mikem8361

    on Jul 2, 2019 via email

    Contributor

    More actions

    The best way would be to catch this under a managed debugger. There is no “createdump” facility on macOS. You can setup your macOS to generate system core dumps (ulimit -c unlimited, etc.) but there a limitation in lldb that makes SOS on coredumps on macOS difficult. See https://github.com/dotnet/diagnostics/blob/master/documentation/debugging-coredump.md#launch-lldb-under-macos. mikem
13. danmoseley commented on Jul 3, 2019

    

    danmoseley

    on Jul 3, 2019

    Contributor

    More actions

    Since this is clearly mac specific we can confidently say it has only happened 1 time in 10 days.
14. danmoseley commented on Jul 10, 2019

    

    danmoseley

    on Jul 10, 2019

    Contributor

    More actions

    No more hits in the last week. Query:

    WorkItems 
    | where Started > now(-10d)  
    | where FriendlyName == "System.IO.FileSystem.Watcher.Tests"
    | where ExitCode == 134
    | join kind= inner (
       Jobs  | where Started > now(-10d) | project  QueueName , JobId, Build, Type, Source 
    ) on JobId
    | summarize count() by ExitCode, QueueName
    | order by count_ desc
    

    	ExitCode	QueueName	count_
    	134	Ubuntu.1604.Arm32.Open	3
15. carlossanlop commented on Jul 22, 2019

    

    carlossanlop

    on Jul 22, 2019

    Contributor

    More actions

    Seems to be infrastructure related. Moving to 5.0.
16. 94 remaining items

    Load more

17. eerhardt commented on May 4, 2021

    

    eerhardt

    on May 4, 2021

    Member

    More actions

    @jkotas - I see the FileWatcher tests failing on OSX in this PR:

    https://github.com/dotnet/runtime/pull/52252/checks?check_run_id=2502547808

    runtime (Libraries Test Run release coreclr OSX x64 Debug)
    .packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21222.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets#L78
    .packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21222.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(78,5): error : (NETCORE_ENGINEERING_TELEMETRY=Test) Work item System.IO.FileSystem.Watcher.Tests in job d239ae94-91a2-4a9c-b9e1-2191863d7385 has failed.
    Failure log: https://helix.dot.net/api/2019-06-17/jobs/d239ae94-91a2-4a9c-b9e1-2191863d7385/workitems/System.IO.FileSystem.Watcher.Tests/console

    /private/tmp/helix/working/AB6B08F2/w/A87108BA/e /private/tmp/helix/working/AB6B08F2/w/A87108BA/e
      Discovering: System.IO.FileSystem.Watcher.Tests (method display = ClassAndMethod, method display options = None)
      Discovered:  System.IO.FileSystem.Watcher.Tests (found 149 of 183 test cases)
      Starting:    System.IO.FileSystem.Watcher.Tests (parallel test collections = on, max threads = 4)
    Process terminated. Assertion failed.
       at System.IO.FileSystemWatcher.RunningInstance.FileSystemEventCallback(IntPtr streamRef, IntPtr clientCallBackInfo, IntPtr numEvents, Byte** eventPaths, FSEventStreamEventFlags* eventFlags, UInt64* eventIds) in /_/src/libraries/System.IO.FileSystem.Watcher/src/System/IO/FileSystemWatcher.OSX.cs:line 386
       at Interop.RunLoop.CFRunLoopRun()
       at Interop.RunLoop.CFRunLoopRun()
       at System.IO.FileSystemWatcher.RunningInstance.StaticWatcherRunLoopManager.WatchForFileSystemEventsThreadStart(ManualResetEventSlim runLoopStarted, SafeEventStreamHandle eventStream) in /_/src/libraries/System.IO.FileSystem.Watcher/src/System/IO/FileSystemWatcher.OSX.cs:line 254
       at System.IO.FileSystemWatcher.RunningInstance.StaticWatcherRunLoopManager.<>c.<ScheduleEventStream>b__3_0(Object args) in /_/src/libraries/System.IO.FileSystem.Watcher/src/System/IO/FileSystemWatcher.OSX.cs:line 204
       at System.Threading.Thread.StartCallback() in /_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 105
    ./RunTests.sh: line 162:  4690 Abort trap: 6           (core dumped) "$RUNTIME_PATH/dotnet" exec --runtimeconfig System.IO.FileSystem.Watcher.Tests.runtimeconfig.json --depsfile System.IO.FileSystem.Watcher.Tests.deps.json xunit.console.dll System.IO.FileSystem.Watcher.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing $RSP_FILE
    /private/tmp/helix/working/AB6B08F2/w/A87108BA/e
    ----- end Tue May 4 09:55:46 PDT 2021 ----- exit code 134 ----------------------------------------------------------
    exit code 134 means SIGABRT Abort. Managed or native assert, or runtime check such as heap corruption, caused call to abort(). Core dumped.
    ulimit -c value: unlimited
    

    Is that this same issue? I hope we got a dump of the process so we can figure the issue out.
18. jkotas commented on May 4, 2021

    

    jkotas

    on May 4, 2021

    Member

    More actions

    Yes, it is the same issue.

    This assert says that the file watcher callback can be called even after the EventStream was stopped using FSEventStreamStop. So we have to be robust against that situation and use a different scheme to perform the cleanup.
19. jkotas

    reopened this on May 4, 2021
20. jaredpar commented on May 4, 2021

    

    jaredpar

    on May 4, 2021

    Member

    More actions

    I hope we got a dump of the process so we can figure the issue out.

    https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-52252-merge-d239ae9491a24a9cb9/System.IO.FileSystem.Watcher.Tests/core.4690?%3F%253Fsv%253D2019-07-07%2526se%253D2021-05-24T16%25253A53%25253A45Z%2526sr%253Dc%2526sp%253Drl%2526sig%253DsqT6WyXqnXJByjBQGYc3E1mXKv75bsK2y6ARQR3HD8Q%25253D
21. eerhardt commented on May 4, 2021

    

    eerhardt

    on May 4, 2021

    Member

    More actions

    @jaredpar - for my education, how do you find that link?
22. jaredpar commented on May 4, 2021

    

    jaredpar

    on May 4, 2021

    Member

    More actions

    Clicked on the checks tab and went to the AzDO build

    https://dev.azure.com/dnceng/public/_build/results?buildId=1120772&view=logs&jobId=4724cd84-0a26-56bc-9b1d-ca1983f340b0

    They key part there is the build id is 1120772. From there just ask runfo to dump the data

    https://runfo.azurewebsites.net/view/build/?number=1120772

    It will list all of the failed tests and for the FileWatcherTests there was a heap dump noted and linked to

    

    The link I posted is that one.

    👍React with 👍1Reacted by Eric Erhardt
23. jaredpar commented on May 4, 2021

    

    jaredpar

    on May 4, 2021

    Member

    More actions

    Truthfully I was a bit lazier than that. I didn't click on the checks tab. Really I just went here

    https://runfo.azurewebsites.net/view/pr-builds/?Repository=runtime&Number=52252

    Basically that dumps all of the builds that happened for the PR #52252. I happened to know that test ran on the runtime definition so I click here

    

    That is the link I posted above .

    https://runfo.azurewebsites.net/view/build/?number=1120772
24. danmoseley commented on May 4, 2021

    

    danmoseley

    on May 4, 2021

    Contributor

    More actions

    Even easier than that, in the dotnet/runtime repo we generate a file containing commands that you can copy/paste to get from zero to the debugger:

    

    Try it out :)
25. jaredpar commented on May 4, 2021

    

    jaredpar

    on May 4, 2021

    Member

    More actions

    Haha, can't debug though cause Windows does not like the core dump here

    
26. jaredpar commented on May 4, 2021

    

    jaredpar

    on May 4, 2021

    Last edited by jaredpar

    Member

    More actions

    Even easier than that, in the dotnet/runtime repo we generate a file containing commands that you can copy/paste to get from zero to the debugger:

    From PR to that display is seven clicks, runfo is two. And one of those clicks is a spinning wheel click waiting for that display to render :)

    Joking aside I'm glad that display is getting better but it does take a lot of clicks to get to. It also takes time to render and is not 100% reliable. Found several times over the years where it won't display anything and errors out.
27. 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 May 4, 2021
28. jkotas commented on May 4, 2021

    

    jkotas

    on May 4, 2021

    Member

    More actions

    Another attempt to fix this #52275
29. jkotas

    closed this as completedin #52275on May 5, 2021
30. 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 May 5, 2021
31. ghost locked as resolved and limited conversation to collaborators on Jun 4, 2021