BSOD when calling WdfRequestForwardToIoQueue

Marshall_Cai · March 29, 2012, 3:33am

Hi,

I have a keyboard class upper filter driver. Recently, I’ve encountered several times of BSOD - DRIVER_IRQL_NOT_LESS_OR_EQUAL in calling the WdfRequestForwardToIoQueue in the EvtIoRead.

I created a control device and set EvtIoRead to default IO queue. In the EvtIoRead, I call the WdfRequestForwardToIoQueue in the pair of WdfSpinLockAcquire/WdfSpinLockRelease.

WdfSpinLockAcquire
… …
WdfRequestForwardToIoQueue
… …
WdfSpinLockRelease

Is it because the maximum IRQL in the EvtIoRead is PASSIVE_LEVEL? Should I adjust its maximum IRQL to DISPATCH_LEVEL when I create the default IO queue for the control device as below?

WDF_IO_QUEUE_CONFIG_INIT_DEFAULT_QUEUE(&ioQueueConfig, WdfIoQueueDispatchParallel);
ioQueueConfig.EvtIoDeviceControl = MyEvtIoDeviceControl;
ioQueueConfig.EvtIoRead = MyEvtIoRead;

WDF_OBJECT_ATTRIBUTES_INIT(&ioQueueAttribute)
ioQueueAttribute.ExecutionLevel = WdfExecutionLevelDispatch;

status = WdfIoQueueCreate(controlDevice, &ioQueueConfig, &ioQueueAttribute, &queue);

Marshall_Cai · March 29, 2012, 3:44am

Forget to attach the output of the command !analyze -v

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

DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If kernel debugger is available get stack backtrace.
Arguments:
Arg1: fffff880014b2166, memory referenced
Arg2: 0000000000000002, IRQL
Arg3: 0000000000000008, value 0 = read operation, 1 = write operation
Arg4: fffff880014b2166, address which referenced memory

Debugging Details:

READ_ADDRESS: GetPointerFromAddress: unable to read from fffff80002ebb0e0
fffff880014b2166

CURRENT_IRQL: 2

FAULTING_IP:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT

BUGCHECK_STR: 0xD1

PROCESS_NAME: RazerMain.exe

DEVICE_OBJECT: fffffa8003ffff20

TRAP_FRAME: fffff88005ce25e0 – (.trap 0xfffff88005ce25e0)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=0000000000000000 rbx=0000000000000000 rcx=fffffa800385c800
rdx=0000057ffc7a3802 rsi=0000000000000000 rdi=0000000000000000
rip=fffff880014b2166 rsp=fffff88005ce2770 rbp=0000057ffc79afd8
r8=0000000000000000 r9=0000000000000000 r10=fffffa80027d3990
r11=0000000000000002 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl zr na po nc
rzfilter!RzFilter_EvtIoRead+0x2e6:
fffff880014b2166 488b542450 mov rdx,qword ptr [rsp+50h] ss:0018:fffff88005ce27c0=fffffa800385c390
Resetting default scope

LAST_CONTROL_TRANSFER: from fffff80002c84469 to fffff80002c84f00

FAILED_INSTRUCTION_ADDRESS:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

STACK_TEXT:
fffff88005ce2498 fffff80002c84469 : 000000000000000a fffff880014b2166 0000000000000002 0000000000000008 : nt!KeBugCheckEx
fffff88005ce24a0 fffff80002c830e0 : fffff68000036978 fffffa800432cc80 ffffffffffffffff 0000000000000001 : nt!KiBugCheckDispatch+0x69
fffff88005ce25e0 fffff880014b2166 : 0000057ffc7a3858 fffff80002c31a8f fffff70001080000 fffffa800388c320 : nt!KiPageFault+0x260
fffff88005ce2770 fffff88000f1ed43 : 0000057ffc79afd8 0000057ffbcd3378 0000000000000010 fffffa80008a5ca0 : rzfilter!RzFilter_EvtIoRead+0x2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff88005ce2800 fffff88000f1e99f : 0000000000000000 fffffa800432cc80 fffffa8003865020 fffffa8003865020 : Wdf01000!FxIoQueue::DispatchRequestToDriver+0x26b
fffff88005ce2880 fffff88000f1df98 : 0000000000000000 0000000000000000 0000000000000000 fffffa800432cdd2 : Wdf01000!FxIoQueue::DispatchEvents+0x4df
fffff88005ce28f0 fffff88000f23558 : fffffa800413d500 fffffa800432cc80 fffffa800413d4d0 fffffa800432cc80 : Wdf01000!FxIoQueue::QueueRequest+0x2bc
fffff88005ce2960 fffff88000f0d245 : fffffa800432cc80 0000000000000000 fffffa8003ffff20 0000000000000000 : Wdf01000!FxPkgIo::Dispatch+0x37c
fffff88005ce29e0 fffff80002f98929 : 0000000000000000 fffffa8003ffff20 0000000000000000 fffffa800413d4d0 : Wdf01000!FxDevice::Dispatch+0xa9
fffff88005ce2a10 fffff80002fa0143 : fffffa8003ffff20 0000000000000000 fffffa8003ffff20 fffff80002dfde80 : nt!IopSynchronousServiceTail+0xf9
fffff88005ce2a80 fffff80002c84153 : 0000000000000000 00000000000003f4 0000000000000001 0000000005e2fea8 : nt!NtReadFile+0x631
fffff88005ce2b70 00000000744c2dd9 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiSystemServiceCopyEnd+0x13
000000000569eee8 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : 0x744c2dd9

STACK_COMMAND: kb

FOLLOWUP_IP:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

SYMBOL_STACK_INDEX: 3

SYMBOL_NAME: rzfilter!RzFilter_EvtIoRead+2e6

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: rzfilter

IMAGE_NAME: rzfilter.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4f73c4ff

FAILURE_BUCKET_ID: X64_0xD1_CODE_AV_BAD_IP_rzfilter!RzFilter_EvtIoRead+2e6

BUCKET_ID: X64_0xD1_CODE_AV_BAD_IP_rzfilter!RzFilter_EvtIoRead+2e6

Followup: MachineOwner

OSR_Community_User · March 29, 2012, 4:47am

It appears that you may be trying to touch paged memory at DISPATCH_LEVEL,
or that you are simply attempting to access an invalid address in the
kernel, period. According to the docs, WdfRequestForwardToIoQueue is
supposed to work at DISPATCH_LEVEL, so my first suspicion would be an
erroneous or damaged pointer somewhere. Certainly, acquiring a spin lock
moves you to DISPATCH_LEVEL, and it would be insane to change to
PASSIVE_LEVEL until the spin lock is released. So my first temptation
would be to guarantee the addresses are valid. There arevsome functions
that probe addresses for readability and writability, and if I were
getting intermittent failures I’d be tempted, if I couldn’t see the error
in the code, to put a test for validity under #ifdef DBG, with a call to
the DebugBreakPoint funtion (whose precise name I forget) if the
validation failed. The I’d start looking for the reason the value is
invalid.

This may not be the most expedient technique, but I’m assuming that at
this point all my “normal” debugging has not allowed me to identify the
problem.
joe

Hi,

I have a keyboard class upper filter driver. Recently, I’ve encountered
several times of BSOD - DRIVER_IRQL_NOT_LESS_OR_EQUAL in calling the
WdfRequestForwardToIoQueue in the EvtIoRead.

I created a control device and set EvtIoRead to default IO queue. In the
EvtIoRead, I call the WdfRequestForwardToIoQueue in the pair of
WdfSpinLockAcquire/WdfSpinLockRelease.

WdfSpinLockAcquire
… …
WdfRequestForwardToIoQueue
… …
WdfSpinLockRelease

Is it because the maximum IRQL in the EvtIoRead is PASSIVE_LEVEL? Should I
adjust its maximum IRQL to DISPATCH_LEVEL when I create the default IO
queue for the control device as below?

WDF_IO_QUEUE_CONFIG_INIT_DEFAULT_QUEUE(&ioQueueConfig,
WdfIoQueueDispatchParallel);
ioQueueConfig.EvtIoDeviceControl = MyEvtIoDeviceControl;
ioQueueConfig.EvtIoRead = MyEvtIoRead;

WDF_OBJECT_ATTRIBUTES_INIT(&ioQueueAttribute)
ioQueueAttribute.ExecutionLevel = WdfExecutionLevelDispatch;

status = WdfIoQueueCreate(controlDevice, &ioQueueConfig,
&ioQueueAttribute, &queue);

NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Doron_Holan · March 29, 2012, 10:27am

This is dieing jn the middle of your read function

rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

rsp=rsp=fffff88005ce2770

My guess is that fffff88005ce2770 is a piece if pagable memory, either on the stack of your struct

d

debt from my phone

From: xxxxx@hotmail.com
Sent: 3/29/2012 12:44 AM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] BSOD when calling WdfRequestForwardToIoQueue

Forget to attach the output of the command !analyze -v

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

DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If kernel debugger is available get stack backtrace.
Arguments:
Arg1: fffff880014b2166, memory referenced
Arg2: 0000000000000002, IRQL
Arg3: 0000000000000008, value 0 = read operation, 1 = write operation
Arg4: fffff880014b2166, address which referenced memory

Debugging Details:

READ_ADDRESS: GetPointerFromAddress: unable to read from fffff80002ebb0e0
fffff880014b2166

CURRENT_IRQL: 2

FAULTING_IP:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT

BUGCHECK_STR: 0xD1

PROCESS_NAME: RazerMain.exe

DEVICE_OBJECT: fffffa8003ffff20

TRAP_FRAME: fffff88005ce25e0 – (.trap 0xfffff88005ce25e0)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=0000000000000000 rbx=0000000000000000 rcx=fffffa800385c800
rdx=0000057ffc7a3802 rsi=0000000000000000 rdi=0000000000000000
rip=fffff880014b2166 rsp=fffff88005ce2770 rbp=0000057ffc79afd8
r8=0000000000000000 r9=0000000000000000 r10=fffffa80027d3990
r11=0000000000000002 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl zr na po nc
rzfilter!RzFilter_EvtIoRead+0x2e6:
fffff880014b2166 488b542450 mov rdx,qword ptr [rsp+50h] ss:0018:fffff88005ce27c0=fffffa800385c390
Resetting default scope

LAST_CONTROL_TRANSFER: from fffff80002c84469 to fffff80002c84f00

FAILED_INSTRUCTION_ADDRESS:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

STACK_TEXT:
fffff88005ce2498 fffff80002c84469 : 000000000000000a fffff880014b2166 0000000000000002 0000000000000008 : nt!KeBugCheckEx
fffff88005ce24a0 fffff80002c830e0 : fffff68000036978 fffffa800432cc80 ffffffffffffffff 0000000000000001 : nt!KiBugCheckDispatch+0x69
fffff88005ce25e0 fffff880014b2166 : 0000057ffc7a3858 fffff80002c31a8f fffff70001080000 fffffa800388c320 : nt!KiPageFault+0x260
fffff88005ce2770 fffff88000f1ed43 : 0000057ffc79afd8 0000057ffbcd3378 0000000000000010 fffffa80008a5ca0 : rzfilter!RzFilter_EvtIoRead+0x2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff88005ce2800 fffff88000f1e99f : 0000000000000000 fffffa800432cc80 fffffa8003865020 fffffa8003865020 : Wdf01000!FxIoQueue::DispatchRequestToDriver+0x26b
fffff88005ce2880 fffff88000f1df98 : 0000000000000000 0000000000000000 0000000000000000 fffffa800432cdd2 : Wdf01000!FxIoQueue::DispatchEvents+0x4df
fffff88005ce28f0 fffff88000f23558 : fffffa800413d500 fffffa800432cc80 fffffa800413d4d0 fffffa800432cc80 : Wdf01000!FxIoQueue::QueueRequest+0x2bc
fffff88005ce2960 fffff88000f0d245 : fffffa800432cc80 0000000000000000 fffffa8003ffff20 0000000000000000 : Wdf01000!FxPkgIo::Dispatch+0x37c
fffff88005ce29e0 fffff80002f98929 : 0000000000000000 fffffa8003ffff20 0000000000000000 fffffa800413d4d0 : Wdf01000!FxDevice::Dispatch+0xa9
fffff88005ce2a10 fffff80002fa0143 : fffffa8003ffff20 0000000000000000 fffffa8003ffff20 fffff80002dfde80 : nt!IopSynchronousServiceTail+0xf9
fffff88005ce2a80 fffff80002c84153 : 0000000000000000 00000000000003f4 0000000000000001 0000000005e2fea8 : nt!NtReadFile+0x631
fffff88005ce2b70 00000000744c2dd9 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiSystemServiceCopyEnd+0x13
000000000569eee8 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : 0x744c2dd9

STACK_COMMAND: kb

FOLLOWUP_IP:
rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565]
fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

SYMBOL_STACK_INDEX: 3

SYMBOL_NAME: rzfilter!RzFilter_EvtIoRead+2e6

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: rzfilter

IMAGE_NAME: rzfilter.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4f73c4ff

FAILURE_BUCKET_ID: X64_0xD1_CODE_AV_BAD_IP_rzfilter!RzFilter_EvtIoRead+2e6

BUCKET_ID: X64_0xD1_CODE_AV_BAD_IP_rzfilter!RzFilter_EvtIoRead+2e6

Followup: MachineOwner

NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Jeff_Glass · March 29, 2012, 11:35am

> DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)

An attempt was made to access a pageable (or completely invalid) address at an interrupt request
level (IRQL) that is too high. This is usually caused by drivers using improper addresses. If kernel
debugger is available get stack backtrace.
Arguments:
Arg1: fffff880014b2166, memory referenced
Arg2: 0000000000000002, IRQL
Arg3: 0000000000000008, value 0 = read operation, 1 = write operation
Arg4: fffff880014b2166, address which referenced memory

Debugging Details: ------------------
READ_ADDRESS: GetPointerFromAddress: unable to read from fffff80002ebb0e0 fffff880014b2166
CURRENT_IRQL: 2
FAULTING_IP: rzfilter!RzFilter_EvtIoRead+2e6 [e:\work\heidi\rig\overlay\rzfilter\rzioctrl.c @ 565] fffff880`014b2166 488b542450 mov rdx,qword ptr [rsp+50h]

Doesn’t this mean that the his RzFilter_EvntIoRead function is in pageable code? Arg3 is complaining that the problem was trying to execute code at Arg1. Or am I missing something?

Marshall_Cai · March 29, 2012, 9:18pm

I actually add the PAGED_CODE() to my EvtIoRead. Does it matter?

The line that causes the BSOD is to forward the request to the request queue. I have no idea whether the queue is allocted from the pageable memory or non pageable memory pool.

status = WdfRequestForwardToIoQueue(Request, pContext->hReadQueue);

But the handle of the queue is cached in the device context.

Tim_Roberts · March 29, 2012, 10:10pm

xxxxx@hotmail.com wrote:

I actually add the PAGED_CODE() to my EvtIoRead. Does it matter?

Absolutely. Depending on your synchronization and sync scope, your
handlers can be called at dispatch level, in which case they cannot be
paged.

The line that causes the BSOD is to forward the request to the request queue. I have no idea whether the queue is allocted from the pageable memory or non pageable memory pool.

status = WdfRequestForwardToIoQueue(Request, pContext->hReadQueue);

This was probably a parallel queue, which means the request never really
goes into the queue, but is immediately dispatched to the handler. The
crash occurred when it tried to call EviIoRead at a raised IRQL. The
PAGED_CODE macro will bug check the system if it is called at a raised IRQL.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Doron_Holan · March 30, 2012, 12:01am

The queue itself is not the problem. It’s your code. While PAGED_CODE() will assert on a debug build of your driver of the current irql > passive, it will not make your function pageable. Did you put the function name in a #pragma alloc_text statement?

d

debt from my phone

From: xxxxx@hotmail.com
Sent: 3/29/2012 6:19 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] BSOD when calling WdfRequestForwardToIoQueue

I actually add the PAGED_CODE() to my EvtIoRead. Does it matter?

The line that causes the BSOD is to forward the request to the request queue. I have no idea whether the queue is allocted from the pageable memory or non pageable memory pool.

status = WdfRequestForwardToIoQueue(Request, pContext->hReadQueue);

But the handle of the queue is cached in the device context.

NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Marshall_Cai · March 30, 2012, 1:44am

Hi Doron,

You’re right. I added the statement PAGED_CODE() in the function and put the function name in #pragma alloc_text. Removing them all, I don’t see any crashes so far. It looks the fix works.

Thanks all for the great help. I learnt a lot from the discussion.