dokan-dev / dokany

User mode file system library for windows with FUSE Wrapper
http://dokan-dev.github.io
5.21k stars 661 forks source link

Race conditions in MirrorSample when processing is multithreaded #1072

Closed zedmilner closed 2 years ago

zedmilner commented 2 years ago

Feature request can skip this form. Bug report must complete it. Check List must be 100% match or it will be automatically closed without further discussion. Please remove this line.

Environment

Check List

Description

Repro steps:

Logs

See the last few lines of the attached log. Dokan_concurrency_bug_log1.txt

Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x8d765ec0, and result object 0x000002838DCB88A0 with size 48
###GetFileInfo file handle = 0x00000000000002CC, eventID = 0039, event Info = 0x000002838BCEB3C0
GetFileInfo : d:\\x\FBuild.exe
    GetFileInformationByHandle success, file size = 1517568
FILE ATTRIBUTE  = 8225
    result =  0
    FileBasicInformation
    DispatchQueryInformation result =  0
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x8d765ec0, and result object 0x000002838DCB88A0 with size 80
###Close file handle = 0x00000000000002B0, eventID = 0017, event Info = 0x000002838BCEB5A0
###Cleanup file handle = 0x00000000000002CC, eventID = 0039, event Info = 0x000002838BCEB3C0
CloseFile: d:\\x\FBuild.exe
Cleanup: d:\\x\FBuild.exe

    error : not cleanuped file

Exception thrown at 0x00007FFA16BE0CEA (ntdll.dll) in mirror.exe: 0xC0000008: An invalid handle was specified.

Note at Close file handle it shows eventID = 0017 which is a very old event, that was used a lot before, during my first (successful) run of fbuild.exe. Seeing that eventID again here seems wrong.

Also note I made a few changes to the logging code to actually log the correct file handle. This is not the cause of the above error, it happens with or without logging eg:

VOID DispatchClose(PDOKAN_IO_EVENT IoEvent) {
  CheckFileName(IoEvent->EventContext->Operation.Close.FileName);

  DbgPrint("###Close file handle = 0x%p, eventID = %04d, event Info = 0x%p\n",
           IoEvent->DokanOpenInfo != NULL ? IoEvent->DokanOpenInfo->UserContext : 0,
           IoEvent->DokanOpenInfo != NULL ? IoEvent->DokanOpenInfo->EventId
                                          : -1,
           IoEvent);

Please let me know what else I can help.

Thanks,

Zed

Liryna commented 2 years ago

Also note I made a few changes to the logging code to actually log the correct file handle.

By File handle we mean DokanOpenInfo which is alive for the time of the open context. It is the "dokan file handle" since UserContext can be whatever the user want it to be.

Regarding this bug, we are seeing 0017 being cleanup with CloseHandle but then we have the close event with an unexpected DokanFileInfo->Context set while it was reset in during cleanup.

Could you try to change and rebuild those lines https://github.com/dokan-dev/dokany/blob/master/dokan/dokan.c#L883-L884 by

VOID EventCompletion(PDOKAN_IO_EVENT IoEvent) {
  assert(IoEvent->EventResult);
  if (IoEvent->DokanOpenInfo) {
    ULONG64 context = IoEvent->DokanFileInfo.Context;
    InterlockedExchange64(&IoEvent->DokanOpenInfo->UserContext, context);
    ReleaseDokanOpenInfo(IoEvent);
  }
}

My guess is Close is called by ReleaseDokanOpenInfo and the InterlockedExchange64 is actually setting back the Context (that was reset) of DokanFileInfo that will be used for this event.

zedmilner commented 2 years ago

I tried that, it doesn't fix it unfortunately.

Liryna commented 2 years ago

Can you add a print of the value being exchanged in the code I provided and share new logs to see if it is called before ?

zedmilner commented 2 years ago

Dokan_concurrency_bug_log2.txt

Uploaded a new log file. I added these logs:

VOID EventCompletion(PDOKAN_IO_EVENT IoEvent) {
    assert(IoEvent->EventResult);
    if (IoEvent->DokanOpenInfo) {
        ULONG64 context = IoEvent->DokanFileInfo.Context;
        InterlockedExchange64(&IoEvent->DokanOpenInfo->UserContext, context);

        DbgPrint(" EventCompletion after exchange. DokanFileInfo = 0x%p (Context: 0x%p), DokanOpenInfo = 0x%p (UserContext: 0x%p), event Info = 0x%p\n",
            IoEvent->DokanFileInfo,
            IoEvent->DokanFileInfo.Context,
            IoEvent->DokanOpenInfo,
            IoEvent->DokanOpenInfo != NULL ? IoEvent->DokanOpenInfo->UserContext : 0,
            IoEvent);

        ReleaseDokanOpenInfo(IoEvent);
    }
}

and

VOID DispatchEvent(PDOKAN_IO_EVENT ioEvent) {

  SetupIOEventForProcessing(ioEvent);

  DbgPrint("!!DispatchEvent: MajorFunction: %d, DokanFileInfo: 0x%p (UserContext: 0x%p), DokanOpenInfo: 0x%p (UserContext: 0x%p) \n",
      ioEvent->EventContext->MajorFunction,
      ioEvent->DokanFileInfo,
      ioEvent->DokanFileInfo.Context,
      ioEvent->DokanOpenInfo,
      ioEvent->DokanOpenInfo != NULL ? ioEvent->DokanOpenInfo->UserContext : 0
  );

Hope that helps!

zedmilner commented 2 years ago

Dokan_concurrency_bug_log2_driver.txt

Added another log with driver logs enabled.

Liryna commented 2 years ago

Thanks for the logs @zedmilner this is very helpful. Can you retry with https://github.com/dokan-dev/dokany/commit/1ffacd40d6ca402c2b49aec2b6fdddfa1a668fa6 ? I am not able to repro the issue but I am guessing what is happening from your logs. If it still does not improve, please share new logs with the message you added.

zedmilner commented 2 years ago

Thanks for the quick reply! I still get the same crash with your latest CL. I tried it with your changes only, and after confirming I still get the same crash, I applied the same log changes I did before, and here is a new log:

Dokan_concurrency_bug_log3.txt

I couldn't get the crash with driver logs enabled this time, although I didn't try for too long.

These are the last few events. My limited understanding is: we first call Create, with eventID = 0088. The Close file handle with eventID = 0067 already looks incorrect, because the same eventID had been closed 500 lines earlier. But it didn't crash there. Then it goes on, calls GetFileInfo with eventID = 0088 (the file we just opened), then calls Close with eventID = 0012 which again looks incorrect, something we closed a long time ago.


!!DispatchEvent: MajorFunction: 0, DokanFileInfo: 0x00000068DB2FF730 (UserContext: 0x0000000000000000), DokanOpenInfo: 0x0000000000000000 (UserContext: 0x0000000000000000) 
###Create file handle = 0x0000025383257750, eventID = 0088, event Info = 0x00000253812B8CD0
CreateFile : d:\\x\FBuild.exe
...
Dokan Information: DokanEndDispatchCreate() status = 0, file handle = 0x0000025383257750, eventID = 0088, result = 0x1
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x83257750, and result object 0x000002538325ABD0 with size 48
!!DispatchEvent: MajorFunction: 2, DokanFileInfo: 0x00000068DB4FF700 (UserContext: 0x0000000000000000), DokanOpenInfo: 0x0000025382DDEA60 (UserContext: 0x0000000000000000) 
!!DispatchEvent: MajorFunction: 5, DokanFileInfo: 0x00000068DB2FF730 (UserContext: 0x00000000000001D0), DokanOpenInfo: 0x0000025383257750 (UserContext: 0x00000000000001D0) 
###Close file handle = 0x0000025382DDEA60, eventID = 0067, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
###GetFileInfo file handle = 0x0000025383257750, eventID = 0088, event Info = 0x00000253812B8CD0
ReleaseDokanOpenInfo: DokanOpenInfo: 0x0000025382DDEA60 (UserContext: 0x0000000000000000), DokanFileInfo: 0x00000068DB4FF620 (UserContext: 0x0000000000000000)
Close: d:\\x\FBuild.exe

GetFileInfo : d:\\x\FBuild.exe
    GetFileInformationByHandle success, file size = 1517568
FILE ATTRIBUTE  = 8225
    result =  0
    FileNetworkOpenInformation
    DispatchQueryInformation result =  0
EventCompletion. DokanFileInfo = 0x00000068DB2FF5A0 (Context: 0x00000000000001D0), DokanOpenInfo = 0x0000025383257750 (UserContext: 0x00000000000001D0), event Info = 0x00000253812B8CD0
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x83257750, and result object 0x000002538325ABD0 with size 96
!!DispatchEvent: MajorFunction: 2, DokanFileInfo: 0x00000068DB2FF730 (UserContext: 0x00000000000002CC), DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 
!!DispatchEvent: MajorFunction: 18, DokanFileInfo: 0x00000068DB4FF700 (UserContext: 0x00000000000001D0), DokanOpenInfo: 0x0000025383257750 (UserContext: 0x00000000000001D0) 
###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0
ReleaseDokanOpenInfo: DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC), DokanFileInfo: 0x00000068DB2FF650 (UserContext: 0x00000000000002CC)
###Cleanup file handle = 0x0000025383257750, eventID = 0088, UserContext = 0x00000000000001D0, event Info = 0x00000253812B8D70
Cleanup: d:\\x\FBuild.exe

CloseFile: d:\\x\FBuild.exe
    error : not cleanuped file

Exception thrown at 0x00007FF960600CEA (ntdll.dll) in mirror.exe: 0xC0000008: An invalid handle was specified.

Also, not sure if this is relevant but we execute the Close and Cleanup commands at the same time on different threads. This sounds like a problem to me - I assume they should be executed in sequence. In the Mirror sample, MirrorCloseFile and MirrorCleanup does the same thing: calls CloseHandle on the same file handle without any synchronization. I don't understand why this is guaranteed to be correct, maybe I'm missing something. To me it looks like even without the bug we are trying to find now, that is causing an old FileHandle to be passed, there may be another potential race condition when MirrorCloseFile and MirrorCleanup is called at the same time with the same FileHandle from multiple threads, and both trying to call CloseHandle. Maybe the driver should wait for the result of one of these calls before calling the other?

Thanks very much!

Liryna commented 2 years ago

All eventID have their own UserContext that is set during CreateFile. There is no Close / Cleanup at the same time for the same context here. The context that we are interested in is 0x000002538135EE60

!!DispatchEvent: MajorFunction: 5, DokanFileInfo: 0x00000068DB3FF5B0 (UserContext: 0x00000000000002CC), DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 
###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
GetFileInfo : d:\\x\FBuild.exe
 GetFileInformationByHandle success, file size = 1517568
FILE ATTRIBUTE  = 8225
 result =  0
 FileIdInformation
 DispatchQueryInformation result =  0
EventCompletion. DokanFileInfo = 0x00000068DB3FF420 (Context: 0x00000000000002CC), DokanOpenInfo = 0x000002538135EE60 (UserContext: 0x00000000000002CC), event Info = 0x00000253812B9270
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x8135ee60, and result object 0x00000253832140C0 with size 64
!!DispatchEvent: MajorFunction: 18, DokanFileInfo: 0x00000068DB3FF5B0 (UserContext: 0x00000000000002CC), DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 
!!DispatchEvent: MajorFunction: 5, DokanFileInfo: 0x00000068DB4FF700 (UserContext: 0x00000000000002CC), DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 
###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B8D70
###Cleanup file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
FileStreamInformation
Cleanup: d:\\x\FBuild.exe

FindStreams :d:\\x\FBuild.exe
==> UserContext IS GOING TO BE RESET AFTER CLEANUP <==
EventCompletion. DokanFileInfo = 0x00000068DB3FF4C0 (Context: 0x0000000000000000), DokanOpenInfo = 0x000002538135EE60 (UserContext: 0x00000000000002CC), event Info = 0x00000253812B9270
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x8135ee60, and result object 0x00000253832140C0 with size 48
 FindStreams return 1 entries in d:\\x\FBuild.exe

 result =  0
 DokanEndDispatchFindStreams result =  0x0

==> UserContext IS CLEANUP BUT WILL BE SET TO THE CLOSED HANDLE BY GetFileInfo <==
EventCompletion. DokanFileInfo = 0x00000068DB4FF580 (Context: 0x00000000000002CC), DokanOpenInfo = 0x000002538135EE60 (UserContext: 0x0000000000000000), event Info = 0x00000253812B8D70
Dokan Information: SendAndPullEventInformation() with NTSTATUS 0x0, context 0x8135ee60, and result object 0x0000025383253310 with size 88

...

==> UserContext HAS THE CLOSE HANDLE SET BY GetFileInfo <==
###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0
ReleaseDokanOpenInfo: DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC), DokanFileInfo: 0x00000068DB2FF650 (UserContext: 0x00000000000002CC)

CloseFile: d:\\x\FBuild.exe
 error : not cleanuped file

Exception thrown at 0x00007FF960600CEA (ntdll.dll) in mirror.exe: 0xC0000008: An invalid handle was specified.

The problem is Windows is canceling / not waiting for GetFileInfo in this case and force the resources to be released by calling Cleanup and Close. GetFileInfo User context is set to the current context value after Cleanup so Close event get the GetFileInfo value (closed handle) instead of taking the reset value of cleanup after it was closed.

I don't think the library can really do much here but here is some solutions:

Please let me know what you think and if anyone is reading this and has some push back to implement point 2, please speak up!

zedmilner commented 2 years ago

Dokan_concurrency_bug_log3b.txt

Thanks again for the very quick iteration on this.

I uploaded a version of the previous log where I inserted a line number for each line, to make it easier to see what is where.

The last instance of the first line in your extract

!!DispatchEvent: MajorFunction: 5, DokanFileInfo: 0x00000068DB3FF5B0 (UserContext: 0x00000000000002CC), DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 

is at line 2041.

2041  !!DispatchEvent: MajorFunction: 5, DokanFileInfo: 0x00000068DB3FF5B0 (UserContext: 0x00000000000002CC), 
DokanOpenInfo: 0x000002538135EE60 (UserContext: 0x00000000000002CC) 

The last instance of the line after your comment

==> UserContext IS GOING TO BE RESET AFTER CLEANUP <==

is at line 900

0900  EventCompletion. DokanFileInfo = 0x00000068DB3FF4C0 (Context: 0x0000000000000000), DokanOpenInfo = 0x000002538135EE60 (UserContext: 0x00000000000002CC), event Info = 0x00000253812B9270

and the line after

==> UserContext IS CLEANUP BUT WILL BE SET TO THE CLOSED HANDLE BY GetFileInfo <==

is at line 906

0906  EventCompletion. DokanFileInfo = 0x00000068DB4FF580 (Context: 0x00000000000002CC), DokanOpenInfo = 0x000002538135EE60 (UserContext: 0x0000000000000000), event Info = 0x00000253812B8D70

And the line after

==> UserContext HAS THE CLOSE HANDLE SET BY GetFileInfo <==

is at line 3574.

3574  ###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0

It is not easy to see from the log, but the full log is the result of me manually running fbuild.exe from the command line multiple times until I get the crash, eg:

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

N:\x>fbuild
Failed to open BFF 'N:\x\fbuild.bff'

If I search for eventID = 0012, These are the lines in the log:

0471  ###Create file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0486  Dokan Information: DokanEndDispatchCreate() status = 0, file handle = 0x000002538135EE60, eventID = 0012, result = 0x1
0489  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0499  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0509  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0519  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0526  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0533  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0540  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0614  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0627  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0642  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0652  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0667  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0677  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0687  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0694  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0701  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0708  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0715  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0722  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0729  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0790  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0805  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0815  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0825  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0840  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0873  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0883  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
0894  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B8D70
0895  ###Cleanup file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
2043  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
3069  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B94F0
3574  ###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0

All Cleanup events: eventID = 12 is at line 895

    Line 188: 0188  ###Cleanup file handle = 0x0000025382D00810, eventID = 0005, UserContext = 0x00000000000001C8, event Info = 0x00000253812B8D70
    Line 226: 0226  ###Cleanup file handle = 0x000002538135EE60, eventID = 0006, UserContext = 0x00000000000001C8, event Info = 0x00000253812B9270
    Line 264: 0264  ###Cleanup file handle = 0x000002538135EE60, eventID = 0007, UserContext = 0x00000000000002B8, event Info = 0x00000253812B8D70
    Line 324: 0324  ###Cleanup file handle = 0x000002538135EE60, eventID = 0008, UserContext = 0x00000000000002BC, event Info = 0x00000253812B8D70
    Line 373: 0373  ###Cleanup file handle = 0x0000025382D00810, eventID = 0009, UserContext = 0x00000000000002C0, event Info = 0x00000253812B9270
    Line 423: 0423  ###Cleanup file handle = 0x000002538135EE60, eventID = 0010, UserContext = 0x00000000000001DC, event Info = 0x00000253812B8D70
    Line 460: 0460  ###Cleanup file handle = 0x000002538135EE60, eventID = 0011, UserContext = 0x00000000000002BC, event Info = 0x00000253812B8D70
    Line 571: 0571  ###Cleanup file handle = 0x0000025382D00810, eventID = 0013, UserContext = 0x00000000000001DC, event Info = 0x00000253812B9270
    Line 606: 0606  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0014, UserContext = 0x00000000000002C0, event Info = 0x00000253812B8D70
    Line 752: 0752  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0015, UserContext = 0x00000000000002B8, event Info = 0x00000253812B9270
    Line 779: 0779  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0016, UserContext = 0x00000000000002C0, event Info = 0x00000253812B9270
    Line 895: 0895  ###Cleanup file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 950: 0950  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0018, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 997: 0997  ###Cleanup file handle = 0x0000025382D00810, eventID = 0019, UserContext = 0x00000000000002B8, event Info = 0x00000253812B9270
    Line 1122: 1122  ###Cleanup file handle = 0x0000025382D00810, eventID = 0020, UserContext = 0x00000000000002B8, event Info = 0x00000253812B9270
    Line 1177: 1177  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0026, UserContext = 0x00000000000001D0, event Info = 0x00000253812B8D70
    Line 1244: 1244  ###Cleanup file handle = 0x0000025382D00810, eventID = 0028, UserContext = 0x00000000000002C0, event Info = 0x00000253812B9270
    Line 1309: 1309  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0030, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 1317: 1317  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0027, UserContext = 0x00000000000002D8, event Info = 0x00000253812B8CD0
    Line 1382: 1382  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0032, UserContext = 0x00000000000002D8, event Info = 0x00000253812B8D70
    Line 1393: 1393  ###Cleanup file handle = 0x0000025383257750, eventID = 0033, UserContext = 0x00000000000002B8, event Info = 0x00000253812B8D70
    Line 1443: 1443  ###Cleanup file handle = 0x0000025383257750, eventID = 0034, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 1481: 1481  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0035, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 1519: 1519  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0036, UserContext = 0x00000000000002E4, event Info = 0x00000253812B8D70
    Line 1569: 1569  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0037, UserContext = 0x00000000000002E4, event Info = 0x00000253812B8D70
    Line 1618: 1618  ###Cleanup file handle = 0x0000025383257750, eventID = 0038, UserContext = 0x00000000000002C0, event Info = 0x00000253812B9270
    Line 1668: 1668  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0039, UserContext = 0x00000000000002B8, event Info = 0x00000253812B8D70
    Line 1705: 1705  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0040, UserContext = 0x00000000000002C0, event Info = 0x00000253812B9270
    Line 1768: 1768  ###Cleanup file handle = 0x0000025383257750, eventID = 0042, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 1803: 1803  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0043, UserContext = 0x00000000000002E8, event Info = 0x00000253812B9270
    Line 1900: 1900  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0044, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 1927: 1927  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0045, UserContext = 0x00000000000002EC, event Info = 0x00000253812B8D70
    Line 2042: 2042  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0041, UserContext = 0x00000000000002E4, event Info = 0x00000253812B8D70
    Line 2098: 2098  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0047, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 2145: 2145  ###Cleanup file handle = 0x0000025383257750, eventID = 0048, UserContext = 0x00000000000002C8, event Info = 0x00000253812B8D70
    Line 2270: 2270  ###Cleanup file handle = 0x0000025383257750, eventID = 0049, UserContext = 0x00000000000002B8, event Info = 0x00000253812B8D70
    Line 2370: 2370  ###Cleanup file handle = 0x0000025382D00810, eventID = 0057, UserContext = 0x00000000000002F4, event Info = 0x00000253812B8D70
    Line 2415: 2415  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0055, UserContext = 0x00000000000002F0, event Info = 0x00000253812B8D70
    Line 2419: 2419  ###Cleanup file handle = 0x0000025383257750, eventID = 0059, UserContext = 0x00000000000002F4, event Info = 0x00000253812B8CD0
    Line 2493: 2493  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0061, UserContext = 0x00000000000002F4, event Info = 0x00000253812B94F0
    Line 2519: 2519  ###Cleanup file handle = 0x0000025382D00810, eventID = 0060, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 2541: 2541  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0062, UserContext = 0x00000000000002F4, event Info = 0x00000253812B94F0
    Line 2596: 2596  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0063, UserContext = 0x00000000000002F4, event Info = 0x00000253812B94F0
    Line 2645: 2645  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0064, UserContext = 0x00000000000002E8, event Info = 0x00000253812B9270
    Line 2695: 2695  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0065, UserContext = 0x00000000000002E8, event Info = 0x00000253812B94F0
    Line 2732: 2732  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0066, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 2795: 2795  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0068, UserContext = 0x00000000000002F0, event Info = 0x00000253812B94F0
    Line 2830: 2830  ###Cleanup file handle = 0x0000025382D00810, eventID = 0069, UserContext = 0x00000000000002FC, event Info = 0x00000253812B9270
    Line 2927: 2927  ###Cleanup file handle = 0x0000025382D00810, eventID = 0070, UserContext = 0x00000000000002E8, event Info = 0x00000253812B94F0
    Line 2954: 2954  ###Cleanup file handle = 0x0000025382D00810, eventID = 0071, UserContext = 0x00000000000002E8, event Info = 0x00000253812B94F0
    Line 3070: 3070  ###Cleanup file handle = 0x0000025382DDEA60, eventID = 0067, UserContext = 0x00000000000002B8, event Info = 0x00000253812B9270
    Line 3125: 3125  ###Cleanup file handle = 0x0000025382D00810, eventID = 0073, UserContext = 0x00000000000002CC, event Info = 0x00000253812B94F0
    Line 3172: 3172  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0074, UserContext = 0x0000000000000300, event Info = 0x00000253812B9270
    Line 3297: 3297  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0075, UserContext = 0x00000000000002B8, event Info = 0x00000253812B94F0
    Line 3405: 3405  ###Cleanup file handle = 0x0000025382D00810, eventID = 0084, UserContext = 0x00000000000002B8, event Info = 0x00000253812B94F0
    Line 3409: 3409  ###Cleanup file handle = 0x0000025383257750, eventID = 0081, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 3478: 3478  ###Cleanup file handle = 0x0000025382DDE970, eventID = 0085, UserContext = 0x00000000000002E8, event Info = 0x00000253812B8D70
    Line 3520: 3520  ###Cleanup file handle = 0x0000025382DDEF10, eventID = 0086, UserContext = 0x00000000000001D0, event Info = 0x00000253812B8D70
    Line 3524: 3524  ###Cleanup file handle = 0x0000025383257750, eventID = 0087, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0
    Line 3576: 3576  ###Cleanup file handle = 0x0000025383257750, eventID = 0088, UserContext = 0x00000000000001D0, event Info = 0x00000253812B8D70

All Close file handle events. Notice that eventID = 0012 is at line 3574, a lot later than its Cleanup call.

Line 195: 0195  ###Close file handle = 0x0000025382D00810, eventID = 0005, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 232: 0232  ###Close file handle = 0x000002538135EE60, eventID = 0006, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 270: 0270  ###Close file handle = 0x000002538135EE60, eventID = 0007, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 330: 0330  ###Close file handle = 0x000002538135EE60, eventID = 0008, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 379: 0379  ###Close file handle = 0x0000025382D00810, eventID = 0009, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 429: 0429  ###Close file handle = 0x000002538135EE60, eventID = 0010, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 466: 0466  ###Close file handle = 0x000002538135EE60, eventID = 0011, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 577: 0577  ###Close file handle = 0x0000025382D00810, eventID = 0013, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 613: 0613  ###Close file handle = 0x0000025382DDEA60, eventID = 0014, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 758: 0758  ###Close file handle = 0x0000025382DDEA60, eventID = 0015, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 785: 0785  ###Close file handle = 0x0000025382DDEA60, eventID = 0016, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 956: 0956  ###Close file handle = 0x0000025382DDEA60, eventID = 0018, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1003: 1003  ###Close file handle = 0x0000025382D00810, eventID = 0019, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1133: 1133  ###Close file handle = 0x0000025382D00810, eventID = 0020, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1190: 1190  ###Close file handle = 0x0000025382DDEA60, eventID = 0026, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1250: 1250  ###Close file handle = 0x0000025382D00810, eventID = 0028, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1316: 1316  ###Close file handle = 0x0000025382DDEA60, eventID = 0030, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1330: 1330  ###Close file handle = 0x0000025382DDE970, eventID = 0027, UserContext = 0x0000000000000000, event Info = 0x00000253812B8CD0
    Line 1388: 1388  ###Close file handle = 0x0000025382DDEA60, eventID = 0032, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1399: 1399  ###Close file handle = 0x0000025383257750, eventID = 0033, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1449: 1449  ###Close file handle = 0x0000025383257750, eventID = 0034, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1487: 1487  ###Close file handle = 0x0000025382DDEA60, eventID = 0035, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1525: 1525  ###Close file handle = 0x0000025382DDEA60, eventID = 0036, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1575: 1575  ###Close file handle = 0x0000025382DDEA60, eventID = 0037, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1624: 1624  ###Close file handle = 0x0000025383257750, eventID = 0038, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1674: 1674  ###Close file handle = 0x0000025382DDEA60, eventID = 0039, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1711: 1711  ###Close file handle = 0x0000025382DDEA60, eventID = 0040, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1775: 1775  ###Close file handle = 0x0000025383257750, eventID = 0042, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1810: 1810  ###Close file handle = 0x0000025382DDE970, eventID = 0043, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 1906: 1906  ###Close file handle = 0x0000025382DDE970, eventID = 0044, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 1933: 1933  ###Close file handle = 0x0000025382DDE970, eventID = 0045, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 2104: 2104  ###Close file handle = 0x0000025382DDE970, eventID = 0047, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 2151: 2151  ###Close file handle = 0x0000025383257750, eventID = 0048, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 2277: 2277  ###Close file handle = 0x0000025383257750, eventID = 0049, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 2384: 2384  ###Close file handle = 0x0000025382D00810, eventID = 0057, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 2427: 2427  ###Close file handle = 0x0000025382DDE970, eventID = 0055, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 2432: 2432  ###Close file handle = 0x0000025383257750, eventID = 0059, UserContext = 0x0000000000000000, event Info = 0x00000253812B8CD0
    Line 2499: 2499  ###Close file handle = 0x0000025382DDE970, eventID = 0061, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2533: 2533  ###Close file handle = 0x0000025382D00810, eventID = 0060, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 2547: 2547  ###Close file handle = 0x0000025382DDE970, eventID = 0062, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2552: 2552  ###Close file handle = 0x0000025382DDEA60, eventID = 0041, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2603: 2603  ###Close file handle = 0x0000025382DDEA60, eventID = 0063, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2651: 2651  ###Close file handle = 0x0000025382DDE970, eventID = 0064, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 2701: 2701  ###Close file handle = 0x0000025382DDEA60, eventID = 0065, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2738: 2738  ###Close file handle = 0x0000025382DDEA60, eventID = 0066, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 2801: 2801  ###Close file handle = 0x0000025382DDE970, eventID = 0068, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2837: 2837  ###Close file handle = 0x0000025382D00810, eventID = 0069, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 2933: 2933  ###Close file handle = 0x0000025382D00810, eventID = 0070, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 2960: 2960  ###Close file handle = 0x0000025382D00810, eventID = 0071, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 3132: 3132  ###Close file handle = 0x0000025382D00810, eventID = 0073, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 3178: 3178  ###Close file handle = 0x0000025382DDE970, eventID = 0074, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 3303: 3303  ###Close file handle = 0x0000025382DDE970, eventID = 0075, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 3421: 3421  ###Close file handle = 0x0000025382D00810, eventID = 0084, UserContext = 0x0000000000000000, event Info = 0x00000253812B94F0
    Line 3423: 3423  ###Close file handle = 0x0000025383257750, eventID = 0081, UserContext = 0x0000000000000000, event Info = 0x00000253812B9270
    Line 3484: 3484  ###Close file handle = 0x0000025382DDE970, eventID = 0085, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 3532: 3532  ###Close file handle = 0x0000025382DDEF10, eventID = 0086, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 3537: 3537  ###Close file handle = 0x0000025383257750, eventID = 0087, UserContext = 0x0000000000000000, event Info = 0x00000253812B8CD0
    Line 3559: 3559  ###Close file handle = 0x0000025382DDEA60, eventID = 0067, UserContext = 0x0000000000000000, event Info = 0x00000253812B8D70
    Line 3574: 3574  ###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0

All references to eventID = 0012

    Line 471: 0471  ###Create file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 486: 0486  Dokan Information: DokanEndDispatchCreate() status = 0, file handle = 0x000002538135EE60, eventID = 0012, result = 0x1
    Line 489: 0489  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 499: 0499  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 509: 0509  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 519: 0519  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 526: 0526  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 533: 0533  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 540: 0540  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 614: 0614  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 627: 0627  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 642: 0642  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 652: 0652  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 667: 0667  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 677: 0677  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 687: 0687  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 694: 0694  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 701: 0701  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 708: 0708  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 715: 0715  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 722: 0722  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 729: 0729  ###Read file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 790: 0790  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 805: 0805  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 815: 0815  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 825: 0825  ###GetFileSecurity file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 840: 0840  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 873: 0873  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 883: 0883  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 894: 0894  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B8D70
    Line 895: 0895  ###Cleanup file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B9270
    Line 2043: 2043  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B9270
    Line 3069: 3069  ###GetFileInfo file handle = 0x000002538135EE60, eventID = 0012, event Info = 0x00000253812B94F0
    Line 3574: 3574  ###Close file handle = 0x000002538135EE60, eventID = 0012, UserContext = 0x00000000000002CC, event Info = 0x00000253812B8CD0

It looks unintuitive why GetFileInfo are called twice (ln 2043 and 3069) way after Cleanup (ln 895).

eventID = 0041 looks simliar to eventID = 0012. It has the same series of calls to GetFileInfo and GetFileSecurity. Note that we only have Read file handle calls for eventID = 0012, my theory is the windows cache only reads the contents of fbuild.exe once, and the subsequent runs it only checks the file info but serves the contents from the cache.

Sorry if I'm clearly on a completely wrong path here, I don't really have any experience with Dokan or file system drivers at all. Just trying to understand what the log shows :)

Thanks

Liryna commented 2 years ago

What you are describing is out of Dokan control. They are external (Kernel/Apps) requests and we cannot reorder them. We could return an error but that might have another impact. Yes, the GetFileInfo looks odd to happen after Cleanup but I am not very surprised. By using procmon you might probably be able to see who is requested those after cleanup but I have some doubt. I would expect where are in a similar situation as https://github.com/dokan-dev/dokany/issues/1016

That said, my comment last points https://github.com/dokan-dev/dokany/issues/1072#issuecomment-1060025500 are still valid.

mjvh80 commented 2 years ago

I have a multiprocess/multithreaded application running on code adapted from the mirror sample (remote FS with local cache), and I think there's a race condition in for example ReadFile, particularly around the pair of operations SetFilePointerEx followed by ::ReadFile, that is during two concurrent reads one thread might call ::ReadFile after another got to SetFilePointerEx. In my case putting a mutex around these two fixed my issues, though I suspect there might be more such places. It was difficult to debug as any logging or debugging affected timing such that the issue would not show up.

Liryna commented 2 years ago

Closing this as the original question was answered here https://github.com/dokan-dev/dokany/issues/1072#issuecomment-1060713483