Can filter manager APIs crash due to parallel execution

Mandar_Nanivadekar · November 22, 2016, 12:39pm

Hello,

This thread is continuation of earlier post where a mini filter crashes randomly and it crashes because a call to FltGetStreamContext function generates an access violation and IP is NULL.

A brief history

A mini filter implements a mini layered file system by creating a reparse point(s)
The mini filter intercepts read calls to a reparse point(s)
When the I/O is received, it is kept pending and the driver sends a message to a user mode program using FitSendMessage.
The user mode program processes the input and when the data is available it will reply by calling FilterSendMessage, processing I/O and calling FilterSendMessage happens in a system thread created by a driver.
After getting a notification the driver calls FltCompletePendedPostOperation to complete the I/O
So there is one thread which is calling APIs like FltGetStreamContext, FltSendMessage. At the same instant when user mode API calls FilterSendMessage, the registered notify function gets called and it is calling FltCompletePendedPostOperation on another process.

There is an intermittent driver crash which is reported by call to FltGetStreamContext being executed on the system thread and IP is shown as NULL.

However when I introduced a guarded mutex between the two function so that calls FltGetStreamContext and FltCompletePendedPostOperation are serialized the crash is not seen. The only change is introduction of a mutex in these two routines.

This seems rather strange but has something like this been observed or are there some guidelines to be followed?
I am using DDK 7600.xxx, the crash can be reproduced on Win 2012 R2 as well as 2008 R2.

2: kd> .exr -1
ExceptionAddress: 0000000000000000
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000008
Parameter[1]: 0000000000000000
Attempt to execute non-executable address 0000000000000000

2: kd> dps esp
ffffd000219b9af0 ffffe00179061010
ffffd000219b9af8 ffffe00178a1be70
ffffd000219b9b00 0000000000000000
ffffd000219b9b08 ffffe00178a1be78
ffffd000219b9b10 ffff28009974b849
ffffd000219b9b18 ffffe00178831040
ffffd000219b9b20 ffffe00178831040
ffffd000219b9b28 fffff800b8e4594f
HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+0xff
[f:\svn\storage_optimizer\storage_optimizer\trunk\filterdriverthreadpool\src\hpar
chsm.c @ 3964]
ffffd000219b9b30 ffffe00178a1be70
ffffd000219b9b38 ffffe0017b04b880
ffffd000219b9b40 ffffe0017b238070
ffffd000219b9b48 fffff80287afe4e3 nt!ExInterlockedRemoveHeadList+0x4f
ffffd000219b9b50 0000000000000001
ffffd000219b9b58 ffffe0017d401ce0
ffffd000219b9b60 ffffe0017b04a570
ffffd000219b9b68 00000000b8000000

2: kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

Unknown bugcheck code (0)
Unknown bugcheck description
Arguments:
Arg1: 0000000000000000
Arg2: 0000000000000000
Arg3: 0000000000000000
Arg4: 0000000000000000

Debugging Details:

BUGCHECK_P1: 0

BUGCHECK_P2: 0

BUGCHECK_P3: 0

BUGCHECK_P4: 0

PROCESS_NAME: System

FAULTING_IP:
+0
0010:00000000`00000000 ?? ???

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory
at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced
memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1: 0000000000000008

EXCEPTION_PARAMETER2: 0000000000000000

WRITE_ADDRESS: 0000000000000000

FOLLOWUP_IP:
HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+ff
[f:\svn\storage_optimizer\storage_optimizer\trunk\filterdriverthreadpool\src\hpar
chsm.c @ 3964]
0010:fffff800`b8e4594f 89442450 mov dword ptr [rsp+50h],eax

FAILED_INSTRUCTION_ADDRESS:
+0
0010:00000000`00000000 ?? ???

BUGCHECK_STR: ACCESS_VIOLATION

CPU_COUNT: 8

CPU_MHZ: a28

CPU_VENDOR: GenuineIntel

CPU_FAMILY: 6

CPU_MODEL: 2d

CPU_STEPPING: 7

DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT

CURRENT_IRQL: 0

ANALYSIS_VERSION: 10.0.10240.9 amd64fre

IP_IN_FREE_BLOCK: 0

LAST_CONTROL_TRANSFER: from ffffe00179061010 to 0000000000000000

SYMBOL_ON_RAW_STACK: 1

STACK_ADDR_RAW_STACK_SYMBOL: ffffd000219b9b30

STACK_COMMAND: dps ffffd000219b9b30-0x20 ; kb

STACK_TEXT:
ffffd000219b9b10 ffff28009974b849
ffffd000219b9b18 ffffe00178831040
ffffd000219b9b20 ffffe00178831040
ffffd000219b9b28 fffff800b8e4594f
HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+0xff
[f:\svn\storage_optimizer\storage_optimizer\trunk\filterdriverthreadpool\src\hpar
chsm.c @ 3964]
ffffd000219b9b30 ffffe00178a1be70
ffffd000219b9b38 ffffe0017b04b880
ffffd000219b9b40 ffffe0017b238070
ffffd000219b9b48 fffff80287afe4e3 nt!ExInterlockedRemoveHeadList+0x4f
ffffd000219b9b50 0000000000000001
ffffd000219b9b58 ffffe0017d401ce0
ffffd000219b9b60 ffffe0017b04a570
ffffd000219b9b68 00000000b8000000
ffffd000219b9b70 0000000000000000
ffffd000219b9b78 0000000000000000
ffffd000219b9b80 0000000100000000
ffffd000219b9b88 ffffe0017dffeab8

FAULTING_SOURCE_LINE:
f:\svn\storage_optimizer\storage_optimizer\trunk\filterdriverthreadpool\src\hparc
hsm.c

FAULTING_SOURCE_FILE:
f:\svn\storage_optimizer\storage_optimizer\trunk\filterdriverthreadpool\src\hparc
hsm.c

FAULTING_SOURCE_LINE_NUMBER: 3964

FAULTING_SOURCE_CODE:
3960: try
3961: {
3962:
3963: status = FltGetStreamContext(Instance, Data->Iopb->TargetFileObject,

3964: &pHpArcHsmContext);
3965: }
3966: except(BackgroundExceptionFilter1(GetExceptionCode(),
GetExceptionInformation()))
3967: {
3968: Data->IoStatus.Status =
STATUS_DISK_OPERATION_FAILED;//STATUS_ACCESS_DENIED;
3969: Data->IoStatus.Information = 0;

SYMBOL_NAME: HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+ff

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: HPEDpHsmX64

IMAGE_NAME: HPEDpHsmX64.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 5821cc5f

BUCKET_ID_FUNC_OFFSET: ff

FAILURE_BUCKET_ID:
ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion

BUCKET_ID:
ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion

PRIMARY_PROBLEM_CLASS:
ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion

ANALYSIS_SOURCE: KM

FAILURE_ID_HASH_STRING:
km:access_violation_null_ip_hpedphsmx64!hparchsmdeferredreadwritecompletion

FAILURE_ID_HASH: {e1f42df5-5598-3f4c-2aad-37cd6a1e57b6}

Followup: MachineOwner

2: kd> kb

RetAddr : Args to Child

: Call Site
00 ffffe00179061010 : ffffe00178a1be70 0000000000000000 ffffe00178a1be78
ffff28009974b849 : 0x0 01 ffffe00178a1be70 : 0000000000000000 ffffe00178a1be78 ffff28009974b849 ffffe00178831040 : 0xffffe00179061010 02 0000000000000000 : ffffe00178a1be78 ffff28009974b849 ffffe00178831040 ffffe00178831040 : 0xffffe001`78a1be70

register values
RSP ffffd000219b9af0
RBP 80
RIP 0

anatoly_mikhailov · November 22, 2016, 12:51pm

Did you try this with driver verifier?

22 нояб. 2016 г. 8:39 PM пользователь <mandar.nanivadekar> написал:

> Hello,
>
> This thread is continuation of earlier post where a mini filter crashes
> randomly and it crashes because a call to FltGetStreamContext function
> generates an access violation and IP is NULL.
>
> A brief history
>
> 1. A mini filter implements a mini layered file system by creating a
> reparse point(s)
> 2. The mini filter intercepts read calls to a reparse point(s)
> 3. When the I/O is received, it is kept pending and the driver sends a
> message to a user mode program using FitSendMessage.
> 4. The user mode program processes the input and when the data is
> available it will reply by calling FilterSendMessage, processing I/O and
> calling FilterSendMessage happens in a system thread created by a driver.
> 5. After getting a notification the driver calls
> FltCompletePendedPostOperation to complete the I/O
> 6. So there is one thread which is calling APIs like FltGetStreamContext,
> FltSendMessage. At the same instant when user mode API calls
> FilterSendMessage, the registered notify function gets called and it is
> calling FltCompletePendedPostOperation on another process.
>
> There is an intermittent driver crash which is reported by call to
> FltGetStreamContext being executed on the system thread and IP is shown as
> NULL.
>
> However when I introduced a guarded mutex between the two function so that
> calls FltGetStreamContext and FltCompletePendedPostOperation are serialized
> the crash is not seen. The only change is introduction of a mutex in these
> two routines.
>
> This seems rather strange but has something like this been observed or are
> there some guidelines to be followed?
> I am using DDK 7600.xxx, the crash can be reproduced on Win 2012 R2 as
> well as 2008 R2.
>
>
> 2: kd> .exr -1
> ExceptionAddress: 0000000000000000
> ExceptionCode: c0000005 (Access violation)
> ExceptionFlags: 00000000
> NumberParameters: 2
> Parameter[0]: 0000000000000008
> Parameter[1]: 0000000000000000
> Attempt to execute non-executable address 0000000000000000
>
> 2: kd> dps esp
> ffffd000219b9af0 ffffe00179061010
> ffffd000219b9af8 ffffe00178a1be70
> ffffd000219b9b00 0000000000000000
> ffffd000219b9b08 ffffe00178a1be78
> ffffd000219b9b10 ffff28009974b849
> ffffd000219b9b18 ffffe00178831040
> ffffd000219b9b20 ffffe00178831040
> ffffd000219b9b28 fffff800b8e4594f
> HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+0xff
> [f:\svn\storage_optimizer\storage_optimizer\trunk > filterdriverthreadpool\src\hpar
> chsm.c @ 3964]
> ffffd000219b9b30 ffffe00178a1be70
> ffffd000219b9b38 ffffe0017b04b880
> ffffd000219b9b40 ffffe0017b238070
> ffffd000219b9b48 fffff80287afe4e3 nt!ExInterlockedRemoveHeadList+0x4f
> ffffd000219b9b50 0000000000000001
> ffffd000219b9b58 ffffe0017d401ce0
> ffffd000219b9b60 ffffe0017b04a570
> ffffd000219b9b68 00000000b8000000
>
> 2: kd> !analyze -v
> *****************************************
>
> *
> *
> * Bugcheck Analysis
> *
> *
> *
> *****************************************
>
>
> Unknown bugcheck code (0)
> Unknown bugcheck description
> Arguments:
> Arg1: 0000000000000000
> Arg2: 0000000000000000
> Arg3: 0000000000000000
> Arg4: 0000000000000000
>
> Debugging Details:
> ------------------
>
>
> BUGCHECK_P1: 0
>
> BUGCHECK_P2: 0
>
> BUGCHECK_P3: 0
>
> BUGCHECK_P4: 0
>
> PROCESS_NAME: System
>
> FAULTING_IP:
> +0
> 0010:0000000000000000 ?? ??? > > ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced > memory > at 0x%08lx. The memory could not be %s. > > EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx > referenced > memory at 0x%08lx. The memory could not be %s. > > EXCEPTION_PARAMETER1: 0000000000000008 > > EXCEPTION_PARAMETER2: 0000000000000000 > > WRITE_ADDRESS: 0000000000000000 > > FOLLOWUP_IP: > HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+ff > [f:\svn\storage_optimizer\storage_optimizer\trunk\ > filterdriverthreadpool\src\hpar > chsm.c @ 3964] > 0010:fffff800b8e4594f 89442450 mov dword ptr [rsp+50h],eax
>
> FAILED_INSTRUCTION_ADDRESS:
> +0
> 0010:0000000000000000 ?? ??? > > BUGCHECK_STR: ACCESS_VIOLATION > > CPU_COUNT: 8 > > CPU_MHZ: a28 > > CPU_VENDOR: GenuineIntel > > CPU_FAMILY: 6 > > CPU_MODEL: 2d > > CPU_STEPPING: 7 > > DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT > > CURRENT_IRQL: 0 > > ANALYSIS_VERSION: 10.0.10240.9 amd64fre > > IP_IN_FREE_BLOCK: 0 > > LAST_CONTROL_TRANSFER: from ffffe00179061010 to 0000000000000000 > > SYMBOL_ON_RAW_STACK: 1 > > STACK_ADDR_RAW_STACK_SYMBOL: ffffd000219b9b30 > > STACK_COMMAND: dps ffffd000219b9b30-0x20 ; kb > > STACK_TEXT: > ffffd000219b9b10 ffff28009974b849 > ffffd000219b9b18 ffffe00178831040 > ffffd000219b9b20 ffffe00178831040 > ffffd000219b9b28 fffff800b8e4594f > HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+0xff > [f:\svn\storage_optimizer\storage_optimizer\trunk\ > filterdriverthreadpool\src\hpar > chsm.c @ 3964] > ffffd000219b9b30 ffffe00178a1be70 > ffffd000219b9b38 ffffe0017b04b880 > ffffd000219b9b40 ffffe0017b238070 > ffffd000219b9b48 fffff80287afe4e3 nt!ExInterlockedRemoveHeadList+0x4f > ffffd000219b9b50 0000000000000001 > ffffd000219b9b58 ffffe0017d401ce0 > ffffd000219b9b60 ffffe0017b04a570 > ffffd000219b9b68 00000000b8000000 > ffffd000219b9b70 0000000000000000 > ffffd000219b9b78 0000000000000000 > ffffd000219b9b80 0000000100000000 > ffffd000219b9b88 ffffe0017dffeab8 > > > FAULTING_SOURCE_LINE: > f:\svn\storage_optimizer\storage_optimizer\trunk\ > filterdriverthreadpool\src\hparc > hsm.c > > FAULTING_SOURCE_FILE: > f:\svn\storage_optimizer\storage_optimizer\trunk\ > filterdriverthreadpool\src\hparc > hsm.c > > FAULTING_SOURCE_LINE_NUMBER: 3964 > > FAULTING_SOURCE_CODE: > 3960: try > 3961: { > 3962: > 3963: status = FltGetStreamContext(Instance, > Data->Iopb->TargetFileObject, > > 3964: &pHpArcHsmContext); > 3965: } > 3966: except(BackgroundExceptionFilter1( > GetExceptionCode(), > GetExceptionInformation())) > 3967: { > 3968: Data->IoStatus.Status = > STATUS_DISK_OPERATION_FAILED;//STATUS_ACCESS_DENIED; > 3969: Data->IoStatus.Information = 0; > > > SYMBOL_NAME: HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion+ff > > FOLLOWUP_NAME: MachineOwner > > MODULE_NAME: HPEDpHsmX64 > > IMAGE_NAME: HPEDpHsmX64.sys > > DEBUG_FLR_IMAGE_TIMESTAMP: 5821cc5f > > BUCKET_ID_FUNC_OFFSET: ff > > FAILURE_BUCKET_ID: > ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion > > BUCKET_ID: > ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion > > PRIMARY_PROBLEM_CLASS: > ACCESS_VIOLATION_NULL_IP_HPEDpHsmX64!HpArcHsmDeferredReadWriteCompletion > > ANALYSIS_SOURCE: KM > > FAILURE_ID_HASH_STRING: > km:access_violation_null_ip_hpedphsmx64!hparchsmdeferredreadwritecompl > etion > > FAILURE_ID_HASH: {e1f42df5-5598-3f4c-2aad-37cd6a1e57b6} > > Followup: MachineOwner > --------- > > 2: kd> kb > # RetAddr : Args to Child > : Call Site > 00 ffffe00179061010 : ffffe00178a1be70 0000000000000000
> ffffe00178a1be78 > ffff28009974b849 : 0x0
> 01 ffffe00178a1be70 : 0000000000000000 ffffe00178a1be78 > ffff28009974b849
> ffffe00178831040 : 0xffffe00179061010
> 02 0000000000000000 : ffffe00178a1be78 ffff28009974b849 > ffffe00178831040
> ffffe00178831040 : 0xffffe00178a1be70
>
> register values
> RSP ffffd000219b9af0
> RBP 80
> RIP 0
>
> —
> NTFSD is sponsored by OSR
>
>
> MONTHLY seminars on crash dump analysis, WDF, Windows internals and
> software drivers!
> Details at http:
>
> To unsubscribe, visit the List Server section of OSR Online at <
> http://www.osronline.com/page.cfm?name=ListServer>
></http:></mandar.nanivadekar>

anatoly_mikhailov · November 22, 2016, 1:45pm

Do you keep pending I/O in postcallback?

Mandar_Nanivadekar · November 23, 2016, 5:43am

The crash is not seen when running with the driver verifier as the entire operation becomes very slow. I will try to run it again.
The post callback function creates a work item out of
PFLT_CALLBACK_DATA and PCFLT_RELATED_OBJECTS parameters.

This work item is inserted inside a list for processing and the post callback function returns FLT_POSTOP_MORE_PROCESSING_REQUIRED.

Thanks.

anatoly_mikhailov · November 23, 2016, 5:59am

It’s not enough information to help you. It’s ok to call FltGetStreamContext
and FltCompletePendedPostOperation silmultaneously. When you used guarded
mutex you forced events in your driver play in another order(like driver
verifier did). Crashes like yours resemble stack corruption. If you want
somebody would help you, this somebogy needs to debug your driver with you.

Mandar_Nanivadekar · November 23, 2016, 6:11am

Thanks for the info.

The driver has only one system thread which intercepts a callback and sends the data to the user mode and keeps the I/O pending.
The system thread just removes the work item and sends a message to the filter.
I may be wrong, but I thought that there is nothing much which would corrupt the stack.

Are there any common steps I can use to debug this stack corruption.

anatoly_mikhailov · November 23, 2016, 6:16am

It just resembles stack corruption, it’s not necessarily so.

Are there any common steps I can use to debug this stack corruption.

Try to build with all warnings treaded as errors.

Scott_Noone_OSR · November 23, 2016, 9:15am

If you can put the dump file someplace I can try to take a look, seems like
an interesting one.

-scott
OSR
@OSRDrivers

wrote in message news:xxxxx@ntfsd…

Thanks for the info.

The driver has only one system thread which intercepts a callback and sends
the data to the user mode and keeps the I/O pending.
The system thread just removes the work item and sends a message to the
filter.
I may be wrong, but I thought that there is nothing much which would corrupt
the stack.

Are there any common steps I can use to debug this stack corruption.

Mandar_Nanivadekar · November 23, 2016, 12:58pm

Please find the link to download the zip file which contains the dumps.

https://drive.google.com/file/d/0B59FSVYGDOVCV1lueElBeTNUTmM/view?usp=sharing

Thanks.

anatoly_mikhailov · November 23, 2016, 11:16pm

Microsoft server doesn’t give me pdb for your kernel and hal. Interesting
thing is last transfer control was from address which doesn’t belong to any
kernel module. And code from this address looks like usual data.

anatoly_mikhailov · November 24, 2016, 12:17am

Mandar,

I have a problem with PDB downloading for your kernel, can you do !pool
command with address from LAST_CONTROL_TRANSFER and say result here?

Most likely it’s the NonPagedPool from which was last transfer control.
Something like DEP with ROP bypassing.

anatoly_mikhailov · November 24, 2016, 1:02am

By the way, so you allocate memory from nonpaged pool with tags like ZovM
or ovMF?

anatoly_mikhailov · November 24, 2016, 2:35am

You don’t. It’s filter manager. It resemble use after free. It’s not clear
why control transfer was from there to me for now. Can enable driver
verifier for fltmgr?

24 нояб. 2016 г. 9:01 AM пользователь “Anatoly Mikhailov” <
xxxxx@gmail.com> написал:

By the way, so you allocate memory from nonpaged pool with tags like ZovM
or ovMF?

anatoly_mikhailov · November 24, 2016, 3:03am

Ok. It was branch trace. And there wasn’t transfer from this pool. It’s not
executable even. Etheir fltmgr!FltGetStreamContext do indirect jump and
there is wrong address in the filter manager structure or there is stack
corruption and some called function returns to zero address. I think it’s
stack corruption.

Mandar_Nanivadekar · November 24, 2016, 4:33am

thanks for analyzing the dump.

Memory is allocated from a non paged pool for work items which are queued to be executed by a thread.

The issue here is analyzing the crash dump usually does not give any clue of the problem.

During a LIVE kernel debugging

The crash gets captured intermittently where IP is shown as NULL and the stack trace does not show any callers
because i think NTKRNLMP catches this exception, the stack is overwritten and a bug check is raised.

BUT

When I put a try/except around FltGetStreamContext, I get my exception handler invoked which also shows that IP is NULL. and there is not stack trace available.

Please let me know if there is any other info which you may need.

anatoly_mikhailov · November 24, 2016, 5:41am

Just reversed FltGetStreamContext. It doesn’t do indirect calls. So it can
be only the stack corruption. FltGetStreamContext calls
FltpGetStreamListCtrl, GetContextFromStreamList,
IoUninitializeWorkItem, ExFreeToNPagedLookasideList
routines. One of them can return to zero address. We can check it only by
patching fltmgr binary.

Please let me know if there is any other info which you may need.

This dump isn’t enough to understand the reason. I can only help with
browsing the source and debugging.

pHpArcHsmContext
where is this variable is defined?

anatoly_mikhailov · November 24, 2016, 5:54am

I think stack corruption took place while GetContextFromStreamList is being
executed.

anatoly_mikhailov · November 24, 2016, 6:00am

I can patch your fltmgr to add breakpoint to occur if the routine is going
to return to zero address . But you must be prepare to boot your system
without driver signature verifing and you must be prepare to boot from live
cd to edit the registry.

Slava_Imameev · November 24, 2016, 6:50am

> I have a problem with PDB downloading for your kernel

Keep trying! This is a well known problem with the Microsoft symbol server for the last couple of months. Repeat .reload until you get pdb files.

anatoly_mikhailov · November 24, 2016, 7:28am

> Keep trying! This is a well known problem with the Microsoft symbol
server for the last couple of months. Repeat .reload until you get pdb
files.

I changed https for http in the URL and i was able to download them