Complete system hang of AVD VM

[uhonermann]

Check List

• I checked my issue doesn't exist yet
• My issue is valid with mirror default sample and not specific to my user-mode driver implementation
• I can always reproduce the issue with the provided description below.
• I have updated Dokany to the latest version and have reboot my computer after.
• I tested one of the last snapshot from appveyor CI

Describe the bug
We've a customer that is using our Dokan2 based network drive on a pool of about 70 Azure Virtual Desktop machines.
Every day 5-6 of them hang completely (the whole system is not responding anymore), which stops about 60 people from working.
The Azure support connected to a hanging system using (virtual) serial port and created a Kernel Dump by causing a BSOD (only thing still possible).
They found a problem with an Outlook process trying to read from our drive, and blocking lots of other kernel threads.

To Reproduce
Steps to reproduce the behavior:

Unfortunately, the issue cannot be reproduced by us, it (currently) only happens in the customers environment.

Expected behavior
System should not hang.

Logs
Please attach in separate files: mirror output, library logs and kernel logs.
In case of BSOD, please attach minidump or dump analyze output.

Memory Dump is about 1 GB, I'll ask the customer to allow the upload.

Environment:

• Windows version: Microsoft Windows 11 Enterprise multi-session
• Processor architecture: x64
• Dokany version: 2.3.0.1000
• Library type (Dokany/FUSE): Dokany

Additional context
The dump has been analyzed by Microsoft already, and they'll work together with us to solve the issue.
Also their analysis can be provided.

Mainly I need some information about internals of the driver to analyze the dump myself.
For example, in the dump I don't see any DokanProcessAndPullEvents thread running, and I'm not sure, if this is normal (because it's currently working on a request ?) or not.
And, is there a list of IRP/Requests, that have been pulled to user land ?
I know about the PendingIRP list, but I think that list contains all pending IRP, regardsless if they already have been pulled.

We see a lot of "No matching IRPs found for a reply" just before the issue occurs.
As far a I know, this means that a response for a request has been delivered from user land to the driver after the IRP has been canceled because of a timeout.
But this means, that requests are still pulled and executed by the user process, but too slow, right ?

[Liryna]

Hi @uhonermann ,

A way to reproduce or the memory dump would be indeed helpful here!

And, is there a list of IRP/Requests, that have been pulled to user land ?
I know about the PendingIRP list, but I think that list contains all pending IRP, regardsless if they already have been pulled.

The Dcb->PendingIrp has indeed all pending irps but NotifyEvent has only the event pending to be sent to userland. Not great but allows to diff which IRP has been pulled.

We see a lot of "No matching IRPs found for a reply" just before the issue occurs.
As far a I know, this means that a response for a request has been delivered from user land to the driver after the IRP has been > canceled because of a timeout.
But this means, that requests are still pulled and executed by the user process, but too slow, right ?

Correct! But that also a sign that we cancelled previous IRPs to avoid hanging the system. That's why I am curious where we could hang here.

Is that a new issue? Did the userland implementation changed (even if, the kernel should prevent system hang)?

[uhonermann]

Hi Liryna,

thank you for the information, I'll have a look into the NotifyEvent list.

Our userland implementation has been changed for some more features, but not in gemeral.
It's also the only installation, that has this problem, and the only special thing is, that they have more than 70 AVDs running.

In the meantime I found a problem with the connection to their Active Directory, that causes 90 second delays, so maybe that is somehow causing the problemds.

I also asked the customer for permission to send the dump, since it might contain sensitive data.

[uhonermann]

Okay, I can see 72 _LIST_ENTRY elements in the NotifyEvent list, all (okay, I didn't really look at all of them) seem to contain the same IRP_MJ_READ operation:

0: kd> dx -id 0,0,ffffb38818ce7040 -r1 ((dokan2!_LIST_ENTRY *)0xffffb3887a3b0610)
((dokan2!_LIST_ENTRY *)0xffffb3887a3b0610) : 0xffffb3887a3b0610 [Type: _LIST_ENTRY *]
[+0x000] Flink : 0xffffb38888c03050 [Type: _LIST_ENTRY *]
[+0x008] Blink : 0xffffb3887a3abcf0 [Type: _LIST_ENTRY *]

0: kd> dt dokan2!DRIVER_EVENT_CONTEXT 0xffffb38888c03050
+0x000 ListEntry : _LIST_ENTRY [ 0xffffb38888c0b750 - 0xffffb3887a3b0610 ]
+0x010 EventContext : _EVENT_CONTEXT
0: kd> dx -id 0,0,ffffb38818ce7040 -r1 (*((dokan2!_EVENT_CONTEXT )0xffffb38888c03060))
(((dokan2!_EVENT_CONTEXT )0xffffb38888c03060)) [Type: _EVENT_CONTEXT]
[+0x000] Length : 0x1ba [Type: unsigned long]
[+0x004] MountId : 0x1 [Type: unsigned long]
[+0x008] SerialNumber : 0x31dc7 [Type: unsigned long]
[+0x00c] ProcessId : 0x10504 [Type: unsigned long]
[+0x010] MajorFunction : 0x3 [Type: unsigned char]
[+0x011] MinorFunction : 0x0 [Type: unsigned char]
[+0x014] Flags : 0x0 [Type: unsigned long]
[+0x018] FileFlags : 0x164 [Type: unsigned long]
[+0x020] Context : 0x1ad83c60210 [Type: unsigned __int64]
[+0x028] Operation [Type: ]
0: kd> dx -id 0,0,ffffb38818ce7040 -r1 (((dokan2!_EVENT_CONTEXT )0xffffb38888c03060)).Operation
(((dokan2!_EVENT_CONTEXT )0xffffb38888c03060)).Operation [Type: ]
[+0x000] Directory [Type: _DIRECTORY_CONTEXT]
[+0x000] Read [Type: _READ_CONTEXT]
[+0x000] Write [Type: _WRITE_CONTEXT]
[+0x000] File [Type: _FILEINFO_CONTEXT]
[+0x000] Create [Type: _CREATE_CONTEXT]
[+0x000] Close [Type: _CLOSE_CONTEXT]
[+0x000] SetFile [Type: _SETFILE_CONTEXT]
[+0x000] Cleanup [Type: _CLEANUP_CONTEXT]
[+0x000] Lock [Type: _LOCK_CONTEXT]
[+0x000] Volume [Type: _VOLUME_CONTEXT]
[+0x000] Flush [Type: _FLUSH_CONTEXT]
[+0x000] Unmount [Type: _UNMOUNT_CONTEXT]
[+0x000] Security [Type: _SECURITY_CONTEXT]
[+0x000] SetSecurity [Type: _SET_SECURITY_CONTEXT]
0: kd> dx -id 0,0,ffffb38818ce7040 -r1 (((dokan2!_READ_CONTEXT )0xffffb38888c03088))
(((dokan2!_READ_CONTEXT *)0xffffb38888c03088)) [Type: _READ_CONTEXT]
[+0x000] ByteOffset : {0} [Type: _LARGE_INTEGER]
[+0x008] BufferLength : 0x1000 [Type: unsigned long]
[+0x00c] FileNameLength : 0x10a [Type: unsigned long]
[+0x010] FileName : "" [Type: wchar_t [1]]

The FileName is the one, that Outlook is trying to read.
And all of the requests I looked at use the same ByteOffset and BufferLength.

[uhonermann]

But there's only one element in the PendingIrp list:

0: kd> dx -id 0,0,ffffb38818ce7040 -r1 (*((dokan2!_IRP_LIST )0xffffb388256f0240))
(((dokan2!_IRP_LIST )0xffffb388256f0240)) [Type: _IRP_LIST]
[+0x000] ListHead [Type: _LIST_ENTRY]
[+0x010] EventEnabled : 0x0 [Type: unsigned char]
[+0x018] NotEmpty [Type: _KEVENT]
[+0x030] ListLock : 0x0 [Type: unsigned __int64]
0: kd> dx -id 0,0,ffffb38818ce7040 -r1 (((dokan2!_LIST_ENTRY )0xffffb388256f0240))
(((dokan2!_LIST_ENTRY *)0xffffb388256f0240)) [Type: _LIST_ENTRY]
[+0x000] Flink : 0xffffb3888ba22910 [Type: _LIST_ENTRY *]
[+0x008] Blink : 0xffffb3888ba22910 [Type: _LIST_ENTRY *]
0: kd> dx -id 0,0,ffffb38818ce7040 -r1 ((dokan2!_LIST_ENTRY *)0xffffb3888ba22910)
((dokan2!_LIST_ENTRY *)0xffffb3888ba22910) : 0xffffb3888ba22910 [Type: _LIST_ENTRY *]
[+0x000] Flink : 0xffffb388256f0240 [Type: _LIST_ENTRY *]
[+0x008] Blink : 0xffffb388256f0240 [Type: _LIST_ENTRY *]

Isn't that strange ?