NFSERR_ACCESS on reparse file

NTFSD
1

Hi I have created a reparse file in windows storage server 2008 and shared the folder for NFS. When I mount the NFS share on linux and issue “ls” command, I am able to see regular files but for reparse file the linux is showing “Permission denied”.

I captured the IRP calls on storage server using procmon and found it is returning “REPARSE” for the IRP request and it is normal. But when I captured the NFS packets using ethreal, I found the reply to NFS “LOOKUP” has status “NFSERR_ACCES”.

I have mounted the NFS share on linux and provided “ANONYMUS LOGON” access in storage server. I want to know why the NFS share has permission denied and how to resolve the issue.

2

You need to provide some more detail. What kind of reparse point did you create? Is it a symbolic link, a mount point, a custom reparse point? Can you access the file via a Windows client?

3

Hi thanks for reply. I am working on archive project where the file will be archived and file is replaced with a stub file marking it as reparse file. When the user later on access the file, the file will be recalled. Here a minifilter driver will listen for open of this stub file for recall.

Basically the file is archived and called DeviceIoControl with “FSCTL_SET_REPARSE_POINT” by passing a custom reparse buffer which stores some reference information of the path. After setting the reparse information, DeviceIoControl is called with “FSCTL_SET_SPARSE” setting the file as sparse.

If the file is opened by windows, the recall is success. Even if the file is opened over CIFS, the file is opened successfully but when the folder is shared over NFS, the linux is showing permission denied.
Please let me know if the information is not sufficient.

4

The thing to do at this stage would be to run filespy on the NFS server and
look for the failing IO

5

Thanks. When I execute “ls” on linux for nfs folder, there is a IRP_MJ_CREATE on the reparse file with the following properties.
Desired Access: Read Attributes, Synchronize
Disposition: Open
Options: Synchronous IO Non-Alert
Attributes: n/a
ShareMode: Read, Write, Delete
AllocationSize: n/a
Impersonating: NT AUTHORITY\ANONYMOUS LOGON

The IO_STATUS_BLOCK is having “Status” set “STATUS_REPARSE” and “Information” set to non zero value. This is a correct condition as the file is set as reparse file. But when I look at the NFS packets using network packet analyzer, there is a NFSERROR_ACCESS status sent over the NFS packet.

6

So what exactly is your driver doing when it sees the irp returned with STATUS_REPARSE? The correct thing is to reissue the request with FILE_FLAG_OPEN_REPARSE_POINT and the file will be opened sucessfully (STATUS_REPARSE means the file was not opened, even though it is considered a “Success” code (NT_SUCCESS will consider it as such). When you get the IRP with STATUS_SUCCESS then you can ad some context tot he file object so you can know to fetch the data when you see a read or write. It sounds like you are not doing this part (reissuing the request). If you are doing this then what is the Status of the IRP after being reissued?

7

Thanks Rick. You are correct. I am not reissuing the IRP by setting the flag. After reissuing the IRP by setting the flag will not result in the permission denied issue. But is this reissuing the IRP is mandatory as it works without any issues on windows.

I have one more observation where if I open the file using VI editor in linux, I am not receiving an IRP with FILE_READ_DATA but still VI is able to read the contents of the file. But this is not the case in windows where if the file is opned, it reads the attribute and then issue IRP with read data attribute.

8

There must be something else going on. If you are not reissuing the irp then the file is not being opened (regardless if the client is windows or anything else). Unless the reparse tag is a Microsoft defined tag the file will not really be opened unless some driver catches the STATUS_REPARSE and reissues the irp. Note that STATUS_REPARSE is considered a success code so it might appear to some applications that the file was opened but it was not. If you are actually getting a handle and are able to read or write the file then something strange is happening.

Do you have a driver doing anything at all in this code path? If so what exactly is it doing?

9

Hi Rick. Thanks for the help. The driver intercepts the IRP_MJ_CREATE and looks for the right permission in the desired access to recall the file. If the desired access is just read attributes, it will set FILE_OPEN_REPARSE_POINT bit and reissue the IRP. Hence there will be no permission denied problem.

After mounting the folder on NFS, if I directly open the file using “vi” command without doing “ls” command on linux, I observe an IRP_MJ_CREATE with READ and WRITE attributes and hence I will recall the file and completes the IRP. Hence the file is opened and read.

But after mounting the folder on NFS, if I issue “ls” command, it send IRM_MJ_CREATE with read attributes and the driver will reissue the irp by setting FILE_OPEN_REPARSE_POINT and the IRP is completed with success. After which if I issue “vi” the IRP_MJ_CREATE will not have right attributes to recall and IRP_MJ_READ is returning junk data.

I want to know why NFS is not sending right permission in IRP_MJ_CREATE?

May I know any links in MSDN which says IRP should be reissued if it is a REPARSE file.

10

I don’t know that this is documented well in msdn. I learned it from writing HSM drivers for years. I do not know much about Linux or NFS either but the general rules I followed were as follows:

  1. If they are not asking for read or write data permission they are not going to access the file data so I passed the open request through without recalling the data.

  2. If they do ask for read or write data then I need to recall the data and this was always done when the first read (or write) Irp was received (not at the create). If no read or write Irp was seen then the data was not recalled.

In all cases the create request must be reissued with FILE_OPEN_REPARSE_POINT.

When you issue the ls command it does not need the data so you do not see it asking for data access and you do not need to recall the file in this case (why would you want to?).

11

Hi Thanks for the help. I continued my experiments with the HSM driver to recall the file in read operation. Following is the steps that driver performs.

  1. When driver gets Create function reissue the IRP by setting the “FILE_OPEN_REPARSE_POINT” flag and it creates a stream context . This will resolve the issue of permission denied problem of linux on create.

  2. When the read is executed on the stream context, the driver will inform to the service by sending the file information and will start waiting for the reply from service.

  3. Service will do actual recall of the file and send the status to driver.

  4. Driver will complete the read request and reissue the IRP.

I have installed this driver and service over Storage server and created a reparse file and shared the folder for NFS. When the file is opened in a linux machine, I received a create request with just read attributes for which the driver appends “FILE_OPEN_REPARSE_POINT” flag and completes the IRP. Also stream context is created after reissue of the IRP.

The “vi” command from linux will now issue read operation. On read the driver will inform service with file information to recall and waits for the reply.

The service will try to open the stub file with flags “FILE_FLAG_OPEN_REPARSE_POINT | FILE_FLAG_OPEN_NO_RECALL | FILE_FLAG_BACKUP_SEMANTICS” and issue IOCTL “FSCTL_GET_REPARSE_POINT” to get the reparse point information. When it calls CloseHandle on the file handle which is opened, I am finding a indefinite hang with the system call. Below is the call stack of the CloseHandle.

THREAD fffffa8002d80780 Cid 0540.05b8 Teb: 000007fffffae000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa800302e200 SynchronizationEvent
fffffa8002d80838 NotificationTimer
IRP List:
fffff980022a4c60: (0006,03a0) Flags: 40000404 Mdl: 00000000
Not impersonating
DeviceMap fffff88000005150
Owning Process fffffa8002d46760 Image: hsmd.exe
Attached Process N/A Image: N/A
Wait Start TickCount 192389 Ticks: 100 (0:00:00:01.560)
Context Switch Count 1126
UserTime 00:00:00.000
KernelTime 00:00:00.062
Win32 Start Address MSVCR80!_threadstartex (0x00000000759c3810)
Stack Init fffffa60046badb0 Current fffffa60046ba630
Base fffffa60046bb000 Limit fffffa60046b5000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
*** WARNING: Unable to verify checksum for adahsm.dll
Child-SP RetAddr Call Site
fffffa60046ba670 fffff80001860f8a nt!KiSwapContext+0x7f
fffffa60046ba7b0 fffff8000186276a nt!KiSwapThread+0x2fa
fffffa60046ba820 fffff80001872e0c nt!KeWaitForSingleObject+0x2da
fffffa60046ba8b0 fffffa60010d56cd nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa60046ba920 fffffa6001023999 Ntfs!NtfsCommonCleanup+0x27d
fffffa60046bad30 fffff80001855637 Ntfs!NtfsCommonCleanupCallout+0x19
fffffa60046bad60 fffff800018555ee nt!KxSwitchKernelStackCallout+0x27 (TrapFrame @ fffffa60046bac20) fffffa6003361430 fffff8000187c224 nt!KiSwitchKernelStackContinue fffffa6003361450 fffffa6001023162 nt!KeExpandKernelStackAndCalloutEx+0x134 fffffa60033614e0 fffffa60010d9fa8 Ntfs!NtfsCommonCleanupOnNewStack+0x42 fffffa6003361550 fffff80001c6b59a Ntfs!NtfsFsdCleanup+0x138 fffffa60033617b0 fffffa6000cbfe17 nt!IovCallDriver+0x34a fffffa60033617f0 fffffa6000cbf0dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa6003361860 fffff80001c6b59a fltmgr!FltpDispatch+0xcd fffffa60033618c0 fffffa6000cbfe17 nt!IovCallDriver+0x34a fffffa6003361900 fffffa6000cbf0dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa6003361970 fffff80001c6b59a fltmgr!FltpDispatch+0xcd fffffa60033619d0 fffff80001ada2e4 nt!IovCallDriver+0x34a fffffa6003361a10 fffff80001ad7950 nt!IopCloseFile+0x184 fffffa6003361aa0 fffff80001ad7d07 nt!ObpDecrementHandleCount+0xc0 fffffa6003361b30 fffff80001ad7ec4 nt!ObpCloseHandleTableEntry+0xb7 fffffa6003361bd0 fffff8000185adf3 nt!ObpCloseHandle+0x94 fffffa6003361c20 00000000778d5b6a nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa6003361c20)
00000000020ff7a8 00000000776bcf2d ntdll!ZwClose+0xa
00000000020ff7b0 0000000180005743 kernel32!CloseHandle+0x29
00000000020ff7e0 0000000075a79f40 adahsm!HsmGetUserAttr+0x743 [e:\binary\windows\2003\64bits\flthsm\src\win\lib\hslhsm.cpp @ 2343]
00000000020ff7e8 0000000075a79f40 MSVCR80!_iob+0x90
00000000020ff7f0 0000000000000007 MSVCR80!_iob+0x90
00000000020ff7f8 0000000000000000 0x7

Any help on why the CloseHandle is hanging?

12

I am not sure what is causing the hang but opening the file from the service can be problematic (especially when an anti-virus program is running). What we did was pass the reparse info up to the service along with an ID we created specific to that file. When the service had data to write back to the file it was passed back to the driver (along with the id) via FSCTL_HSM_DATA (a MS defined FSCTL that was used for the Remote Storage component in Windows 2000 but is now decomissioned) and the driver wrote the data to the file. This way the service does not have to open the file and drivers above you do not see the IO.

13

Thanks Rick for the information. Even if windows decommissioned ?FSCTL_HSM_DATA?, still driver can make use of other communication method like FltSendMessage(). Am I right?
I tried to recall the file from read path by opening the file using ?FltCreateFileEx? so that the driver sends request to its lower drivers. After create the driver will issue ?FltWriteFile? to write the recalled data to the offline file and close the file and reissue the IRP. Below is the code sample for it.

Status = FltCreateFileEx(GlobalData.Filter, //Filter
FltObjects->Instance, //Instance
&FileHandle, //FileHandle
&pFileObject, //FileObject
GENERIC_WRITE | SYNCHRONIZE, //DesiredAccess
&objectAttributes, //ObjectAttributes
&IoStatus, //IoStatusBlock
NULL, //AllocationSize
FILE_ATTRIBUTE_NORMAL, //FileAttributes
FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE, //ShareAccess
FILE_OPEN, //CreateDisposition
FILE_OPEN_REPARSE_POINT | FILE_SYNCHRONOUS_IO_ALERT | FILE_RANDOM_ACCESS | FILE_OPEN_FOR_BACKUP_INTENT, //CreateOptions
NULL, //EaBuffer
0, //EaLength
IO_NO_PARAMETER_CHECKING //Flags
);

if(!NT_SUCCESS(Status))
{
DEBUG(DBG_INFO, “Failed to create with status 0x%x”, Status);
return Status;
}

Status = FltQueryInformationFile(FltObjects->Instance, pFileObject, &BasicInformation, sizeof(BasicInformation), FileBasicInformation, &ulBytesWritten);
if(!NT_SUCCESS(Status))
{
DEBUG(DBG_INFO, “Failed to FltQueryInformationFile with status 0x%x”, Status);
return Status;
}

Status = FltWriteFile(FltObjects->Instance, pFileObject, NULL, length, pBuff, FLTFL_IO_OPERATION_NON_CACHED, &ulBytesWritten, NULL, NULL);
if(!NT_SUCCESS(Status))
{
DEBUG(DBG_INFO, “Failed to write with status 0x%x”, Status);
return Status;
}

BasicInformation.FileAttributes &= ~(FILE_ATTRIBUTE_OFFLINE);

Status = FltSetInformationFile(FltObjects->Instance, pFileObject, &BasicInformation, sizeof(BasicInformation), FileBasicInformation);
if(!NT_SUCCESS(Status))
{
DEBUG(DBG_INFO, “Failed to FltSetInformationFile with status 0x%x”, Status);
return Status;
}

Status = FltClose(FileHandle);
if(!NT_SUCCESS(Status))
{
DEBUG(DBG_INFO, “Failed to close with status 0x%x”, Status);
return Status;
}

//Data->Iopb->Parameters.Create.Options |= FILE_OPEN_REPARSE_POINT;
FltSetCallbackDataDirty(Data);
FltReissueSynchronousIo(FltObjects->Instance, Data);

When I tried this code from local machine by opening the reparse file, the recall is successful but when I open the reparse file over CIFS, the ?FltWriteFile? will not return as it is a synchronous operation. Why the FltWriteFile does not return when opened over network?

14

You are correct about using FltSendMessage or any other method to get the driver to write the data back. Regarding the question about why FltWriteFile does not return I am not sure of the reason. Just to be clear the client opening the file is going through CIFS but the FltCreateFile is local correct - in other words the driver is running on the same machine that the file lives on?

It may be helpful to post a stack of the hung call. The output of !locks may be useful too.

Are you issuing the FltCreateFile and FltWriteFile from the pre or post create callback? We ended up not starting the recall until we saw the first read or write for the file. There were multiple reasons for this. For one, an application may open the file for read/write access but then never read or write it. This causes unnecessary recalls of the file, or in some cases many files. We also noted that we would get into deadlock situations when there were too many recalls started from remote clients. This was because the lanman server held some lock or resource and there could only be a limited number of creates blocked before all clients were locked out until one of the recalls completed. We tried to work through the problems of recalling at create time but in the end moved it to the first read or write.

15

You are correct. Client is opening the file over CIFS and the server which has the stub file runs the driver and the driver needs to recall the file.

Rick I have tried calling FltCreateFile from both PostCreate and PostRead operations. But I am going to call FltWriteFile from PostRead operation since I need to recall the file on first read operation. Earlier i had the same implementation of recalling in PostCreate but since for the issue of linux i am changing the recall path to first read operation.

Following is the call stack and !locks output. From the log it seems that when the driver is calling FltWriteFile, it is trying to acquire the same lock in Exclusive mode and running in self deadlock condition. The read file object has owned the resource in shared mode and the same thread is trying to acquire the resource in exclusive mode and getting hung. Am i right? Even i tried completing the Create request of application by appending DesiredAccess with STANDARD_RIGHTS_WRITE | FILE_WRITE_DATA | FILE_WRITE_ATTRIBUTES | FILE_WRITE_EA | STANDARD_RIGHTS_READ. But still the FltWrite is not returning.

1: kd> !locks -d
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks.....

Resource @ 0xfffffa800259b790 Shared 1 owning threads
Contention Count = 1
Threads: fffffa8001936040-01<*>
KD: Scanning for held locks..............................................................................................................................................

Resource @ 0xfffffa8003995700 Shared 1 owning threads
Contention Count = 2
NumberOfExclusiveWaiters = 2
Threads: fffffa80038a5040-01<*>
Threads Waiting On Exclusive Access:
fffffa80038a5040 fffffa8001936040

KD: Scanning for held locks.....................................................................................

Resource @ 0xfffffa8003824dc0 Exclusively owned
Threads: fffffa8001936040-01<*>
KD: Scanning for held locks.
7380 total locks, 3 locks currently held

1: kd> dt_eresource 0xfffffa8003995700
hal!_ERESOURCE
+0x000 SystemResourcesList : _LIST_ENTRY [0xfffffa8003997860 - 0xfffffa8003995960]
+0x010 OwnerTable : (null)
+0x018 ActiveCount : 1
+0x01a Flag : 0
+0x020 SharedWaiters : (null)
+0x028 ExclusiveWaiters : 0xfffffa80`02df5c70 _KEVENT
+0x030 OwnerEntry : _OWNER_ENTRY
+0x040 ActiveEntries : 1
+0x044 ContentionCount : 2
+0x048 NumberOfSharedWaiters : 0
+0x04c NumberOfExclusiveWaiters : 2
+0x050 Reserved2 : (null)
+0x058 Address : (null)
+0x058 CreatorBackTraceIndex : 0
+0x060 SpinLock : 0

1: kd> !locks -v 0xfffffa8003995700

Resource @ 0xfffffa8003995700 Shared 1 owning threads
Contention Count = 2
NumberOfExclusiveWaiters = 2
Threads: fffffa80038a5040-01<*>

THREAD fffffa80038a5040 Cid 0004.0e64 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8002df5c70 SynchronizationEvent
fffffa80038a50f8 NotificationTimer
Not impersonating
DeviceMap fffff88000005150
Owning Process fffffa80018df690 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 37417 Ticks: 224 (0:00:00:03.494)
Context Switch Count 23
UserTime 00:00:00.000
KernelTime 00:00:01.560
Win32 Start Address srv!WorkerThread (0xfffffa60040f13b0)
Stack Init fffffa60044d6db0 Current fffffa60044d4d50
Base fffffa60044d7000 Limit fffffa60044d1000 Call 0
Priority 14 BasePriority 9 PriorityDecrement 5 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa60044d4d90 fffff80001cb4f8a nt!KiSwapContext+0x7f
fffffa60044d4ed0 fffff80001cb676a nt!KiSwapThread+0x2fa
fffffa60044d4f40 fffff80001cc6e2c nt!KeWaitForSingleObject+0x2da
fffffa60044d4fd0 fffffa600102471a nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa60044d5040 fffffa6001026118 Ntfs!NtfsCommonWrite+0x1cba
fffffa60044d5240 fffff800020bf59a Ntfs!NtfsFsdWrite+0x208
fffffa60044d5300 fffffa6000cc1e17 nt!IovCallDriver+0x34a
fffffa60044d5340 fffffa6000cc5b7b fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227
fffffa60044d53b0 fffffa6000cd0422 fltmgr!FltPerformSynchronousIo+0xdb
fffffa60044d5420 fffffa6000cfccb4 fltmgr!FltWriteFile+0x342
fffffa60044d5500 fffffa60041ae6a1 fltmgr!FltvWriteFile+0x84
fffffa60044d5570 fffffa60041aec43 ada_hsm!DummyRecall+0x481 [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 1846]
fffffa60044d56e0 fffffa60041aefcb ada_hsm!Recall+0x3f3 [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 1972]
fffffa60044d57c0 fffffa6000ccebf6 ada_hsm!ReadWorker+0x28b [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 2062]
fffffa60044d58d0 fffffa6000cfc56f fltmgr!FltDoCompletionProcessingWhenSafe+0x96
fffffa60044d5900 fffffa60041af5dc fltmgr!FltvDoCompletionProcessingWhenSafe+0x8f
fffffa60044d5940 fffffa6000cfaf8b ada_hsm!ReadPostOperationCallback+0x9c [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 2296]
fffffa60044d5990 fffffa6000cc3f0c fltmgr!FltvPostOperation+0x9b
fffffa60044d5a10 fffffa6000cc63a2 fltmgr!FltpPerformPostCallbacks+0x31d
fffffa60044d5ae0 fffffa6000cc64ed fltmgr!FltpProcessIoCompletion+0x12
fffffa60044d5b10 fffff800020bc3f6 fltmgr!FltpPassThroughCompletion+0x7d
fffffa60044d5b50 fffff80001cb1785 nt!IovpLocalCompletionRoutine+0x116
fffffa60044d5b90 fffff800020b68c3 nt!IopfCompleteRequest+0x315
fffffa60044d5c50 fffffa600101d540 nt!IovCompleteRequest+0x43
fffffa60044d5d30 fffffa600101db68 Ntfs!NtfsCommonRead+0x1751
fffffa60044d5ea0 fffff800020bf59a Ntfs!NtfsFsdRead+0x1b8
fffffa60044d60a0 fffffa6000cc1e17 nt!IovCallDriver+0x34a
fffffa60044d60e0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227
fffffa60044d6150 fffff800020bf59a fltmgr!FltpDispatch+0xcd
fffffa60044d61b0 fffffa6000cc10ad nt!IovCallDriver+0x34a
fffffa60044d61f0 fffff800020bf59a fltmgr!FltpDispatch+0x9d
fffffa60044d6250 fffff80001ca6c20 nt!IovCallDriver+0x34a
fffffa60044d6290 fffff80001cd555c nt!IoPageRead+0x130
fffffa60044d62d0 fffff80001cbe4c9 nt!MiDispatchFault+0x9ec
fffffa60044d6430 fffff80001cd3280 nt!MmAccessFault+0x14c9
fffffa60044d6520 fffff80001f18917 nt!MmCheckCachedPageState+0x620
fffffa60044d65b0 fffffa600101a0d6 nt!CcCopyRead+0x1bb
fffffa60044d66d0 fffffa600101c249 Ntfs!NtfsCachedRead+0x176
fffffa60044d6720 fffffa600101db68 Ntfs!NtfsCommonRead+0x469
fffffa60044d6890 fffff800020bf59a Ntfs!NtfsFsdRead+0x1b8

Threads Waiting On Exclusive Access:
fffffa80038a5040 fffffa8001936040

1 total locks, 1 locks currently held

1: kd> !locks -v 0xfffffa800259b790

Resource @ 0xfffffa800259b790 Shared 1 owning threads
Contention Count = 1
Threads: fffffa8001936040-01<*>

THREAD fffffa8001936040 Cid 0004.0048 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8002df5c70 SynchronizationEvent
fffffa80019360f8 NotificationTimer
IRP List:
fffff98008552c60: (0006,03a0) Flags: 40000404 Mdl: 00000000
Impersonation token: fffff880068f5b10 (Level Impersonation)
Owning Process fffffa80018df690 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 37456 Ticks: 185 (0:00:00:02.886)
Context Switch Count 1420
UserTime 00:00:00.000
KernelTime 00:00:00.140
Win32 Start Address nt!ExpWorkerThread (0xfffff80001cbbf3c)
Stack Init fffffa6004b28db0 Current fffffa6004b28630
Base fffffa6004b29000 Limit fffffa6004b23000 Call 0
Priority 13 BasePriority 12 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa6004b28670 fffff80001cb4f8a nt!KiSwapContext+0x7f
fffffa6004b287b0 fffff80001cb676a nt!KiSwapThread+0x2fa
fffffa6004b28820 fffff80001cc6e2c nt!KeWaitForSingleObject+0x2da
fffffa6004b288b0 fffffa60010db6cd nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa6004b28920 fffffa6001029999 Ntfs!NtfsCommonCleanup+0x27d
fffffa6004b28d30 fffff80001ca96e7 Ntfs!NtfsCommonCleanupCallout+0x19
fffffa6004b28d60 fffff80001ca969e nt!KxSwitchKernelStackCallout+0x27 (TrapFrame @ fffffa6004b28c20) fffffa60017df0f0 fffff80001cd0244 nt!KiSwitchKernelStackContinue fffffa60017df110 fffffa6001029162 nt!KeExpandKernelStackAndCalloutEx+0x134 fffffa60017df1a0 fffffa60010dffa8 Ntfs!NtfsCommonCleanupOnNewStack+0x42 fffffa60017df210 fffff800020bf59a Ntfs!NtfsFsdCleanup+0x138 fffffa60017df470 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df4b0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df520 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df580 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df5c0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df630 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df690 fffff80001f2da54 nt!IovCallDriver+0x34a fffffa60017df6d0 fffff80001f2b0c0 nt!IopCloseFile+0x184 fffffa60017df760 fffff80001f2b477 nt!ObpDecrementHandleCount+0xc0 fffffa60017df7f0 fffff80001f2b634 nt!ObpCloseHandleTableEntry+0xb7 fffffa60017df890 fffff80001caeeb3 nt!ObpCloseHandle+0x94 fffffa60017df8e0 fffff80001caf3c0 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60017df8e0)
fffffa60017dfa78 fffffa60040a58af nt!KiServiceLinkage
fffffa60017dfa80 fffffa60040f1c50 srv!SrvDereferenceLfcbHandle+0x19f
fffffa60017dfad0 fffffa60041301d9 srv!UnlinkRfcbFromLfcb+0x40
fffffa60017dfb10 fffffa6004131f06 srv!SrvCompleteRfcbClose+0x159
fffffa60017dfb40 fffffa60040b2e71 srv!CloseRfcbInternal+0x36
fffffa60017dfb70 fffffa6004124392 srv!SrvCloseRfcbsOnSessionOrPid+0x81
fffffa60017dfba0 fffffa6004124803 srv!SrvCloseSession+0x133
fffffa60017dfbe0 fffffa60040b3bd8 srv!SrvCloseSessionsOnConnection+0x133
fffffa60017dfc40 fffffa60040b414e srv!SrvCloseConnection+0x168
fffffa60017dfc90 fffffa60040b43b1 srv!ProcessConnectionDisconnects+0x9e
fffffa60017dfcc0 fffff80001cbc056 srv!SrvResourceThread+0x21
fffffa60017dfcf0 fffff80001ed1403 nt!ExpWorkerThread+0x11a
fffffa60017dfd50 fffff80001ce9576 nt!PspSystemThreadStartup+0x57
fffffa60017dfd80 0000000000000000 nt!KxStartSystemThread+0x16

1 total locks, 1 locks currently held

1: kd> !locks -v 0xfffffa8003824dc0

Resource @ 0xfffffa8003824dc0 Exclusively owned
Threads: fffffa8001936040-01<*>

THREAD fffffa8001936040 Cid 0004.0048 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8002df5c70 SynchronizationEvent
fffffa80019360f8 NotificationTimer
IRP List:
fffff98008552c60: (0006,03a0) Flags: 40000404 Mdl: 00000000
Impersonation token: fffff880068f5b10 (Level Impersonation)
Owning Process fffffa80018df690 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 37456 Ticks: 185 (0:00:00:02.886)
Context Switch Count 1420
UserTime 00:00:00.000
KernelTime 00:00:00.140
Win32 Start Address nt!ExpWorkerThread (0xfffff80001cbbf3c)
Stack Init fffffa6004b28db0 Current fffffa6004b28630
Base fffffa6004b29000 Limit fffffa6004b23000 Call 0
Priority 13 BasePriority 12 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa6004b28670 fffff80001cb4f8a nt!KiSwapContext+0x7f
fffffa6004b287b0 fffff80001cb676a nt!KiSwapThread+0x2fa
fffffa6004b28820 fffff80001cc6e2c nt!KeWaitForSingleObject+0x2da
fffffa6004b288b0 fffffa60010db6cd nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa6004b28920 fffffa6001029999 Ntfs!NtfsCommonCleanup+0x27d
fffffa6004b28d30 fffff80001ca96e7 Ntfs!NtfsCommonCleanupCallout+0x19
fffffa6004b28d60 fffff80001ca969e nt!KxSwitchKernelStackCallout+0x27 (TrapFrame @ fffffa6004b28c20) fffffa60017df0f0 fffff80001cd0244 nt!KiSwitchKernelStackContinue fffffa60017df110 fffffa6001029162 nt!KeExpandKernelStackAndCalloutEx+0x134 fffffa60017df1a0 fffffa60010dffa8 Ntfs!NtfsCommonCleanupOnNewStack+0x42 fffffa60017df210 fffff800020bf59a Ntfs!NtfsFsdCleanup+0x138 fffffa60017df470 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df4b0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df520 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df580 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df5c0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df630 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df690 fffff80001f2da54 nt!IovCallDriver+0x34a fffffa60017df6d0 fffff80001f2b0c0 nt!IopCloseFile+0x184 fffffa60017df760 fffff80001f2b477 nt!ObpDecrementHandleCount+0xc0 fffffa60017df7f0 fffff80001f2b634 nt!ObpCloseHandleTableEntry+0xb7 fffffa60017df890 fffff80001caeeb3 nt!ObpCloseHandle+0x94 fffffa60017df8e0 fffff80001caf3c0 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60017df8e0)
fffffa60017dfa78 fffffa60040a58af nt!KiServiceLinkage
fffffa60017dfa80 fffffa60040f1c50 srv!SrvDereferenceLfcbHandle+0x19f
fffffa60017dfad0 fffffa60041301d9 srv!UnlinkRfcbFromLfcb+0x40
fffffa60017dfb10 fffffa6004131f06 srv!SrvCompleteRfcbClose+0x159
fffffa60017dfb40 fffffa60040b2e71 srv!CloseRfcbInternal+0x36
fffffa60017dfb70 fffffa6004124392 srv!SrvCloseRfcbsOnSessionOrPid+0x81
fffffa60017dfba0 fffffa6004124803 srv!SrvCloseSession+0x133
fffffa60017dfbe0 fffffa60040b3bd8 srv!SrvCloseSessionsOnConnection+0x133
fffffa60017dfc40 fffffa60040b414e srv!SrvCloseConnection+0x168
fffffa60017dfc90 fffffa60040b43b1 srv!ProcessConnectionDisconnects+0x9e
fffffa60017dfcc0 fffff80001cbc056 srv!SrvResourceThread+0x21
fffffa60017dfcf0 fffff80001ed1403 nt!ExpWorkerThread+0x11a
fffffa60017dfd50 fffff80001ce9576 nt!PspSystemThreadStartup+0x57
fffffa60017dfd80 0000000000000000 nt!KxStartSystemThread+0x16

1 total locks, 1 locks currently held

1: kd> !thread -p fffffa8001936040 f
PROCESS fffffa80018df690
SessionId: none Cid: 0004 Peb: 00000000 ParentCid: 0000
DirBase: 00124000 ObjectTable: fffff88000002f80 HandleCount: 3164.
Image: System

THREAD fffffa8001936040 Cid 0004.0048 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8002df5c70 SynchronizationEvent
fffffa80019360f8 NotificationTimer
IRP List:
fffff98008552c60: (0006,03a0) Flags: 40000404 Mdl: 00000000
Impersonation token: fffff880068f5b10 (Level Impersonation)
Owning Process fffffa80018df690 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 37456 Ticks: 185 (0:00:00:02.886)
Context Switch Count 1420
UserTime 00:00:00.000
KernelTime 00:00:00.140
Win32 Start Address nt!ExpWorkerThread (0xfffff80001cbbf3c)
Stack Init fffffa6004b28db0 Current fffffa6004b28630
Base fffffa6004b29000 Limit fffffa6004b23000 Call 0
Priority 13 BasePriority 12 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa6004b28670 fffff80001cb4f8a nt!KiSwapContext+0x7f
fffffa6004b287b0 fffff80001cb676a nt!KiSwapThread+0x2fa
fffffa6004b28820 fffff80001cc6e2c nt!KeWaitForSingleObject+0x2da
fffffa6004b288b0 fffffa60010db6cd nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa6004b28920 fffffa6001029999 Ntfs!NtfsCommonCleanup+0x27d
fffffa6004b28d30 fffff80001ca96e7 Ntfs!NtfsCommonCleanupCallout+0x19
fffffa6004b28d60 fffff80001ca969e nt!KxSwitchKernelStackCallout+0x27 (TrapFrame @ fffffa6004b28c20) fffffa60017df0f0 fffff80001cd0244 nt!KiSwitchKernelStackContinue fffffa60017df110 fffffa6001029162 nt!KeExpandKernelStackAndCalloutEx+0x134 fffffa60017df1a0 fffffa60010dffa8 Ntfs!NtfsCommonCleanupOnNewStack+0x42 fffffa60017df210 fffff800020bf59a Ntfs!NtfsFsdCleanup+0x138 fffffa60017df470 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df4b0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df520 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df580 fffffa6000cc1e17 nt!IovCallDriver+0x34a fffffa60017df5c0 fffffa6000cc10dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227 fffffa60017df630 fffff800020bf59a fltmgr!FltpDispatch+0xcd fffffa60017df690 fffff80001f2da54 nt!IovCallDriver+0x34a fffffa60017df6d0 fffff80001f2b0c0 nt!IopCloseFile+0x184 fffffa60017df760 fffff80001f2b477 nt!ObpDecrementHandleCount+0xc0 fffffa60017df7f0 fffff80001f2b634 nt!ObpCloseHandleTableEntry+0xb7 fffffa60017df890 fffff80001caeeb3 nt!ObpCloseHandle+0x94 fffffa60017df8e0 fffff80001caf3c0 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60017df8e0)
fffffa60017dfa78 fffffa60040a58af nt!KiServiceLinkage
fffffa60017dfa80 fffffa60040f1c50 srv!SrvDereferenceLfcbHandle+0x19f
fffffa60017dfad0 fffffa60041301d9 srv!UnlinkRfcbFromLfcb+0x40
fffffa60017dfb10 fffffa6004131f06 srv!SrvCompleteRfcbClose+0x159
fffffa60017dfb40 fffffa60040b2e71 srv!CloseRfcbInternal+0x36
fffffa60017dfb70 fffffa6004124392 srv!SrvCloseRfcbsOnSessionOrPid+0x81
fffffa60017dfba0 fffffa6004124803 srv!SrvCloseSession+0x133
fffffa60017dfbe0 fffffa60040b3bd8 srv!SrvCloseSessionsOnConnection+0x133
fffffa60017dfc40 fffffa60040b414e srv!SrvCloseConnection+0x168
fffffa60017dfc90 fffffa60040b43b1 srv!ProcessConnectionDisconnects+0x9e
fffffa60017dfcc0 fffff80001cbc056 srv!SrvResourceThread+0x21
fffffa60017dfcf0 fffff80001ed1403 nt!ExpWorkerThread+0x11a
fffffa60017dfd50 fffff80001ce9576 nt!PspSystemThreadStartup+0x57
fffffa60017dfd80 0000000000000000 nt!KxStartSystemThread+0x16

For an experiment i completed the Create request from application to reissue with above said write attributes and in the read operation i reused the same fileobject present in FltObjects->FileObject to write the data to file in asynch mode. But still the api is not returning. This is where the driver is not creating a new FileObject to recall the file. Below is the stack and locks log. Where here also I am finding the same issue.

1: kd> !locks -d
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks.............................................................................................................................

Resource @ 0xfffffa80037763d0 Shared 1 owning threads
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: fffffa80036abbb0-01<*>
Threads Waiting On Exclusive Access:
fffffa80036abbb0

KD: Scanning for held locks..........
4290 total locks, 1 locks currently held
1: kd> !locks -v 0xfffffa80037763d0

Resource @ 0xfffffa80037763d0 Shared 1 owning threads
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: fffffa80036abbb0-01<*>

THREAD fffffa80036abbb0 Cid 0004.0898 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8002a5d590 SynchronizationEvent
fffffa80036abc68 NotificationTimer
Not impersonating
DeviceMap fffff88000005150
Owning Process fffffa80018df690 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 10562 Ticks: 222 (0:00:00:03.463)
Context Switch Count 223
UserTime 00:00:00.000
KernelTime 00:00:01.528
Win32 Start Address srv!WorkerThread (0xfffffa60040fe3b0)
Stack Init fffffa6003f95db0 Current fffffa6003f93d80
Base fffffa6003f96000 Limit fffffa6003f90000 Call 0
Priority 10 BasePriority 9 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa6003f93dc0 fffff80001ca2f8a nt!KiSwapContext+0x7f
fffffa6003f93f00 fffff80001ca476a nt!KiSwapThread+0x2fa
fffffa6003f93f70 fffff80001cb4e2c nt!KeWaitForSingleObject+0x2da
fffffa6003f94000 fffffa600101671a nt!ExAcquireResourceExclusiveLite+0x1cc
fffffa6003f94070 fffffa6001018118 Ntfs!NtfsCommonWrite+0x1cba
fffffa6003f94270 fffff800020ad59a Ntfs!NtfsFsdWrite+0x208
fffffa6003f94330 fffffa6000cc8e17 nt!IovCallDriver+0x34a
fffffa6003f94370 fffffa6000cd6375 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227
fffffa6003f943e0 fffffa6000cd6422 fltmgr!FltPerformAsynchronousIo+0x115
fffffa6003f94450 fffffa6000cd745c fltmgr!FltpPerformAsynchronousIoWrapper+0x42
fffffa6003f94480 fffffa6000d03cb4 fltmgr!FltWriteFile+0x37c
fffffa6003f94560 fffffa60027ea635 fltmgr!FltvWriteFile+0x84
fffffa6003f945d0 fffffa60027eac53 ada_hsm!DummyRecall+0x335 [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 1871]
fffffa6003f946e0 fffffa60027eafdb ada_hsm!Recall+0x3f3 [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 2004]
fffffa6003f947c0 fffffa6000cd5bf6 ada_hsm!ReadWorker+0x28b [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 2094]
fffffa6003f948d0 fffffa6000d0356f fltmgr!FltDoCompletionProcessingWhenSafe+0x96
fffffa6003f94900 fffffa60027eb5ec fltmgr!FltvDoCompletionProcessingWhenSafe+0x8f
fffffa6003f94940 fffffa6000d01f8b ada_hsm!ReadPostOperationCallback+0x9c [e:\ada_trunk\modules\flthsm\src\win\driver\src\hsm_callbacks.c @ 2328]
fffffa6003f94990 fffffa6000ccaf0c fltmgr!FltvPostOperation+0x9b
fffffa6003f94a10 fffffa6000ccd3a2 fltmgr!FltpPerformPostCallbacks+0x31d
fffffa6003f94ae0 fffffa6000ccd4ed fltmgr!FltpProcessIoCompletion+0x12
fffffa6003f94b10 fffff800020aa3f6 fltmgr!FltpPassThroughCompletion+0x7d
fffffa6003f94b50 fffff80001c9f785 nt!IovpLocalCompletionRoutine+0x116
fffffa6003f94b90 fffff800020a48c3 nt!IopfCompleteRequest+0x315
fffffa6003f94c50 fffffa600100f540 nt!IovCompleteRequest+0x43
fffffa6003f94d30 fffffa600100fb68 Ntfs!NtfsCommonRead+0x1751
fffffa6003f94ea0 fffff800020ad59a Ntfs!NtfsFsdRead+0x1b8
fffffa6003f950a0 fffffa6000cc8e17 nt!IovCallDriver+0x34a
fffffa6003f950e0 fffffa6000cc80dd fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x227
fffffa6003f95150 fffff800020ad59a fltmgr!FltpDispatch+0xcd
fffffa6003f951b0 fffffa6000cc80ad nt!IovCallDriver+0x34a
fffffa6003f951f0 fffff800020ad59a fltmgr!FltpDispatch+0x9d
fffffa6003f95250 fffff80001c94c20 nt!IovCallDriver+0x34a
fffffa6003f95290 fffff80001cc355c nt!IoPageRead+0x130
fffffa6003f952d0 fffff80001cac4c9 nt!MiDispatchFault+0x9ec
fffffa6003f95430 fffff80001cc1280 nt!MmAccessFault+0x14c9
fffffa6003f95520 fffff80001f06917 nt!MmCheckCachedPageState+0x620
fffffa6003f955b0 fffffa600100c0d6 nt!CcCopyRead+0x1bb
fffffa6003f956d0 fffffa600100e249 Ntfs!NtfsCachedRead+0x176
fffffa6003f95720 fffffa600100fb68 Ntfs!NtfsCommonRead+0x469

Threads Waiting On Exclusive Access:
fffffa80036abbb0

1 total locks, 1 locks currently held

16

Try calling FltWriteFile from pre-read instead of post-read. Otherwise the read has already completed and it read zeros because it was a sparse, empty file. Once the recall is complete you can return from pre-read and let it read the real data. This may help with the deadlock also.