BSOD w/WDF_VIOLATION during WLK 1.4 Pnpd w/concurrent IO test with DevPathExer

I’m having some problems with the WLK 1.4 while running the “Pnp test with concurrent IO in parallel with DevPathExer”. I’ve seen the failure on both 32 and 64 bit versions of the latest Windows 7 RTM. I’m testing a USB Virtual COM port driver, created from the WDF serial sample (KMDF version 1.7). I’m simply running tests on it as an Unclassified Device.

During this test I am getting a BSOD which indicates a WDF_VIOLATION, specifically trying to acquire an already held spinlock. Problem is that I amy driver is not acquiring the lock, it looks like something inside the KMDF.

From the call stack I can tell that I am getting an IOCTL through DeviceIoControl which ends up goes in the default case and should return STATUS_INVALID_PARAMETER (FFFFFFFFC000000D). But during the call to WdfRequestCompleteWithInformation somehow the pnpfiltr gets involved and appears to also issue a Close in the same callstack. By doing this it appears to dispatch another call to the WDF serial driver to close the device, but some internal lock needs to be acquired for the dispatch which might already be in use from the original DeviceIOCTL call.

Does anyone have an idea on this one? At first I thought maybe I should just pend the request for the IOCTL, but I’ve checked back with some sample code and this doesn’t seem to be incorrect.

Here is the analyze -v:

*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

WDF_VIOLATION (10d)
The Kernel-Mode Driver Framework was notified that Windows detected an error
in a framework-based driver. In general, the dump file will yield additional
information about the driver that caused this bug check.
Arguments:
Arg1: 0000000000000002, An attempt is being made to acquire a lock that is currently
being held. The lock in question can be determined by examining
the caller’s stack.
Arg2: fffffa8000ea1b90, Reserved.
Arg3: 0000000000000000, Reserved.
Arg4: fffffa80025cfa30, Reserved.

Debugging Details:

BUGCHECK_STR: 0x10D_2

DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT

PROCESS_NAME: System

CURRENT_IRQL: 2

LAST_CONTROL_TRANSFER: from fffff80002769792 to fffff8000267d540

STACK_TEXT:
fffff88002fa94a8 fffff80002769792 : 0000000000000002 fffffa8000cd7040 0000000000000065 fffff800026ab620 : nt!RtlpBreakWithStatusInstruction
fffff88002fa94b0 fffff8000276a57e : 0000000000000003 0000000000000000 fffff800026abe80 000000000000010d : nt!KiBugCheckDebugBreak+0x12
fffff88002fa9510 fffff80002686084 : fffffa8000dc000a fffff88002fa9c48 0000000000000008 0000000000000000 : nt!KeBugCheck2+0x71e
fffff88002fa9be0 fffff88000c38e0d : 000000000000010d 0000000000000002 fffffa8000ea1b90 0000000000000000 : nt!KeBugCheckEx+0x104
fffff88002fa9c20 fffff88000c43a05 : fffffa80025ce530 fffff88002fa9c00 fffffa80025cfa30 fffff88002fa9cf8 : Wdf01000!FxCallbackMutexLock::Lock+0x69
fffff88002fa9c60 fffff88000c43267 : 0000000000000000 fffffa8001d7df40 0000000000000000 fffffa8002a06390 : Wdf01000!FxPkgGeneral::OnClose+0xa1
fffff88002fa9cc0 fffff88000c37215 : fffffa8002a06390 0000000000000001 fffffa8002a06390 0000000000000000 : Wdf01000!FxPkgGeneral::Dispatch+0x14f
fffff88002fa9d20 fffff880015db1d0 : 0000000000000002 fffffa8002c137b0 ffffffffc000000d fffffa80025c3000 : Wdf01000!FxDevice::Dispatch+0xa9
fffff88002fa9d50 fffff880015e0587 : 0000000000000002 fffffa8002c137b0 ffffffffc000000d fffffa80025c3000 : pnpfiltr+0x11d0
fffff88002fa9d80 fffff8000295b6ae : fffffa8000dcf070 0000000000000001 fffffa8002a06390 0000000000000000 : pnpfiltr+0x6587
fffff88002fa9db0 fffff8000267b5b4 : 0000000000000004 0000000000000000 fffffa8000cd9b40 fffff88000c624e0 : nt!IopDeleteFile+0x11e
fffff88002fa9e40 fffff880015db817 : 0000000000000000 fffffa8002d4e760 0000000000000000 0000000000000003 : nt!ObfDereferenceObject+0xd4
fffff88002fa9ea0 fffff8000268e6b7 : fffffa80025c3080 0000000000000000 0000000000000001 fffff88000c3129a : pnpfiltr+0x1817
fffff88002fa9ed0 fffff88000c319ca : 0000000000000000 fffffa8000dcc002 0000000000000001 0000000000000000 : nt!IopfCompleteRequest+0x397
fffff88002fa9fa0 fffff88000c2205e : fffffa8002d4e760 fffffa8000000001 fffffa80025cfa02 fffffa8002d4e760 : Wdf01000!FxRequest::CompleteInternal+0x646
fffff88002faa050 fffff880048ca27e : fffff880048d3700 fffffa80025c3080 fffffa80025c3080 0000057fff233f78 : Wdf01000!imp_WdfRequestCompleteWithInformation+0x1aa
fffff88002faa0c0 fffff880048cf31f : 0000057ffda3cf78 fffff880c000000d 0000000000000000 0000057ffda3cf78 : virtcom!WdfRequestCompleteWithInformation+0x2e [c:\winddk\6001.18002\inc\wdf\kmdf\1.7\wdfrequest.h @ 949]
fffff88002faa0f0 fffff880048da320 : 0000057ffda3cf78 0000057fc000000d 0000000000000000 fffff880048d2ad0 : virtcom!SerialCompleteRequest+0x5f [c:\dev\vcp\utils.c @ 987]
fffff88002faa140 fffff880048d843d : 0000057fff233f78 0000057ffda3cf78 0000000000000000 0000000000000000 : virtcom!SerialEvtIoDeviceControl+0x1ec0 [c:\dev\vcp\ioctl_serial.c @ 1497]
fffff88002fab5d0 fffff88000c48f28 : 0000057fff233f78 0000057ffda3cf78 0000000000000000 0000000000000000 : virtcom!VirtComEvtIoDeviceControl+0x7d [c:\dev\vcp\device.c @ 2310]
fffff88002fab620 fffff88000c48937 : fffffa80025c3000 fffffa80025c3080 fffffa8000dcc080 fffffa8000dcc080 : Wdf01000!FxIoQueue::DispatchRequestToDriver+0x4b8
fffff88002fab6a0 fffff88000c47f30 : 0000000000000000 0000000000000000 0000000000000000 fffffa80025c31d2 : Wdf01000!FxIoQueue::DispatchEvents+0x4df
fffff88002fab710 fffff88000c4d4f0 : fffffa8002d4e900 fffffa80025c3080 fffffa8002d4e760 fffffa80025c3080 : Wdf01000!FxIoQueue::QueueRequest+0x2bc
fffff88002fab780 fffff88000c37215 : fffffa80025c3080 fffffa8002c13900 fffffa8002933c60 0000000000000000 : Wdf01000!FxPkgIo::Dispatch+0x37c
fffff88002fab800 fffff880015db5f3 : fffffa80028323d0 fffff880015dc660 0000000000000001 fffff88002fab880 : Wdf01000!FxDevice::Dispatch+0xa9
fffff88002fab830 fffff880015e1cba : fffffa8000efa1b0 fffffa8002933c60 fffffa8000005a0c fffffa8002c137b0 : pnpfiltr+0x15f3
fffff88002fab870 fffff880015e0fd4 : fffffa8002933c60 fffff880015da000 fffffa8002c137b0 fffffa8001d4b060 : pnpfiltr+0x7cba
fffff88002fab8a0 fffff800028d46b5 : fffffa8002c137b0 00000000c00000bb fffff88002fab988 fffffa8002933c60 : pnpfiltr+0x6fd4
fffff88002fab8d0 fffff80002a568d1 : fffffa8001d4b060 0000000000000000 fffffa80020219a0 0000000000000000 : nt!IopSynchronousCall+0xc5
fffff88002fab940 fffff80002a555c8 : fffff88002fabb00 fffffa8001d4b060 000000000000030a 0000000000000308 : nt!IopRemoveDevice+0x101
fffff88002faba00 fffff80002a56417 : fffffa80020219a0 0000000000000000 0000000000000003 00000000000007ff : nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff88002faba40 fffff80002a56530 : 0000000000000000 fffff8a002612500 fffff8a002858e80 000000004e706e50 : nt!PnpDeleteLockedDeviceNode+0x37
fffff88002faba70 fffff80002aee57f : 0000000000000002 0000000000000000 fffffa80020219a0 fffff8a0026125a0 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffff88002fabae0 fffff80002aef13c : fffff88002fabcb8 fffff800028d4e00 fffffa8000cd7000 fffffa8000000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff88002fabc20 fffff800029dca2a : 0000000000000000 fffffa8002b24220 fffff8a0026125a0 0000000000000000 : nt!PnpProcessTargetDeviceEvent+0x4c
fffff88002fabc50 fffff8000268b744 : fffffa8002b24220 fffff8a0026125a0 fffff80002818638 0000000000000001 : nt! ?? ::NNGAKEGL::string'+0x5a5bb fffff88002fabcb0 fffff8000290be66 : 000005aa00000000 0000000000000001 fffffa8000cd7040 000005aa00000000 : nt!ExpWorkerThread+0x11a fffff88002fabd40 fffff80002638a86 : fffff800027ede80 fffffa8000cd7040 fffffa8000cd6680 000005aa00000000 : nt!PspSystemThreadStartup+0x5a fffff88002fabd80 0000000000000000 : fffff88002fac000 fffff88002fa6000 fffff88002fab330 00000000`00000000 : nt!KxStartSystemThread+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
pnpfiltr+11d0
fffff880`015db1d0 8bd8 mov ebx,eax

SYMBOL_STACK_INDEX: 8

SYMBOL_NAME: pnpfiltr+11d0

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: pnpfiltr

IMAGE_NAME: pnpfiltr.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 49f1593a

FAILURE_BUCKET_ID: X64_0x10D_2_pnpfiltr+11d0

BUCKET_ID: X64_0x10D_2_pnpfiltr+11d0

xxxxx@silabs.com wrote:

I’m having some problems with the WLK 1.4 while running the “Pnp test with concurrent IO in parallel with DevPathExer”. I’ve seen the failure on both 32 and 64 bit versions of the latest Windows 7 RTM. I’m testing a USB Virtual COM port driver, created from the WDF serial sample (KMDF version 1.7). I’m simply running tests on it as an Unclassified Device.

During this test I am getting a BSOD which indicates a WDF_VIOLATION, specifically trying to acquire an already held spinlock. Problem is that I amy driver is not acquiring the lock, it looks like something inside the KMDF.

>From the call stack I can tell that I am getting an IOCTL through DeviceIoControl which ends up goes in the default case and should return STATUS_INVALID_PARAMETER (FFFFFFFFC000000D). But during the call to WdfRequestCompleteWithInformation somehow the pnpfiltr gets involved and appears to also issue a Close in the same callstack.

I’m confused by the stack dump. You’re being called from
IopRemoveDevice. That means the IRP you got should have been
IRP_MN_REMOVE_DEVICE, in which case it should not have been dispatched
to your IoControlDevice handler at all. Are you intercepting or
preprocessing the IRPs in some way?


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

Thanks for the reply Tim.

I am doing some preprocessing for IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION, IRP_MJ_SET_INFORMATION and IRP_MJ_READ. I am not however preprocessing IRP_MJ_DEVICE_CONTROL or IRP_MJ_PNP/IRP_MN_REMOVE_DEVICE.

I too am also a bit confused on this. I don’t fully understand how the pnpfiltr driver works, but it seems like the completion of the first WDFREQUEST should have finished before anything else attempted to call into the WDF driver. And as you are saying, I don’t know how my DeviceIoControl handler is getting called if I am indeed getting and IRP_MN_REMOVE_DEVICE.

Perhaps I need to add some preprocessing for this - currently I’m simply using WDF for power and PNP.

xxxxx@silabs.com wrote:

Thanks for the reply Tim.

I am doing some preprocessing for IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION, IRP_MJ_SET_INFORMATION and IRP_MJ_READ. I am not however preprocessing IRP_MJ_DEVICE_CONTROL or IRP_MJ_PNP/IRP_MN_REMOVE_DEVICE.

What kind of a device is this where you are getting this IRPs? How are
you doing that preprocessing? Are you overriding WDF’s dispatch table
with your own routines, then forwarding the IRPs on to WDF after you’ve
looked at them? Is this “miniport” mode?


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

These are std preprocessing items for a serial port implementation. Kmdf does not handle flush buffers and query and set information. You need to preprocess read to turn it into sync io for mscomm32.ocx. I forwarded the stack and description to the rest of the wdf team, maybe one of them has an idea of what is going on

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Tim Roberts
Sent: Monday, June 15, 2009 10:23 AM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] BSOD w/WDF_VIOLATION during WLK 1.4 Pnpd w/concurrent IO test with DevPathExer

xxxxx@silabs.com wrote:

Thanks for the reply Tim.

I am doing some preprocessing for IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION, IRP_MJ_SET_INFORMATION and IRP_MJ_READ. I am not however preprocessing IRP_MJ_DEVICE_CONTROL or IRP_MJ_PNP/IRP_MN_REMOVE_DEVICE.

What kind of a device is this where you are getting this IRPs? How are
you doing that preprocessing? Are you overriding WDF’s dispatch table
with your own routines, then forwarding the IRPs on to WDF after you’ve
looked at them? Is this “miniport” mode?


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


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

Thanks Doron - that would be great. We are actually attempting to do the same thing through another contact we have at Microsoft, so hopefully both of these angles will help to get this solved. I also have full memory dumps available if needed.

Fortunately all my other DTM tests for Windows 7 have passed, and this is the last one to debug.

Tim - I’m not running in minport mode. Everything that Doron mentioned is correct. IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION, IRP_MJ_SET_INFORMATION aren’t handled by WDF so I must handle them myself (this is in the KMDF serial sample as well). And the IRP_MJ_READ interception was indeed the workaround for the MSCOMM control.

The way to do this is to call this during device initialization:

status = WdfDeviceInitAssignWdmIrpPreprocessCallback(pwdfDeviceInit,
PreprocessFunction,
IRP_MJ_READ, // major IRP to preprocess
NULL, // pointer minor function table
0);

I am not intercepting the power IRPs though.

Thanks again to both of you for the replies, and help.

Email me offline with a web or ftp link that i can get a full or kernel memory dump and i can fwd to the right folks

d

Sent from my phone with no t9, all spilling mistakes are not intentional.

-----Original Message-----
From: xxxxx@silabs.com
Sent: Monday, June 15, 2009 6:58 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] BSOD w/WDF_VIOLATION during WLK 1.4 Pnpd w/concurrent IO test with DevPathExer

Thanks Doron - that would be great. We are actually attempting to do the same thing through another contact we have at Microsoft, so hopefully both of these angles will help to get this solved. I also have full memory dumps available if needed.

Fortunately all my other DTM tests for Windows 7 have passed, and this is the last one to debug.

Tim - I’m not running in minport mode. Everything that Doron mentioned is correct. IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION, IRP_MJ_SET_INFORMATION aren’t handled by WDF so I must handle them myself (this is in the KMDF serial sample as well). And the IRP_MJ_READ interception was indeed the workaround for the MSCOMM control.

The way to do this is to call this during device initialization:

status = WdfDeviceInitAssignWdmIrpPreprocessCallback(pwdfDeviceInit,
PreprocessFunction,
IRP_MJ_READ, // major IRP to preprocess
NULL, // pointer minor function table
0);

I am not intercepting the power IRPs though.

Thanks again to both of you for the replies, and help.


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

Hi,

I have a similar issue though my driver is not a Serial driver but it is a
wdf driver. What was the issue? Was it in Prestons driver or is it something
somewhere else? Not exactly sure which tests were run but it was with WLK
1.4.

Thanks
/Faik

On Tue, Jun 16, 2009 at 4:32 AM, Doron Holan wrote:

> Email me offline with a web or ftp link that i can get a full or kernel
> memory dump and i can fwd to the right folks
>
> d
>
> Sent from my phone with no t9, all spilling mistakes are not intentional.
>
> -----Original Message-----
> From: xxxxx@silabs.com
> Sent: Monday, June 15, 2009 6:58 PM
> To: Windows System Software Devs Interest List
> Subject: RE:[ntdev] BSOD w/WDF_VIOLATION during WLK 1.4 Pnpd w/concurrent
> IO test with DevPathExer
>
>
> Thanks Doron - that would be great. We are actually attempting to do the
> same thing through another contact we have at Microsoft, so hopefully both
> of these angles will help to get this solved. I also have full memory dumps
> available if needed.
>
> Fortunately all my other DTM tests for Windows 7 have passed, and this is
> the last one to debug.
>
> Tim - I’m not running in minport mode. Everything that Doron mentioned is
> correct. IRP_MJ_FLUSH_BUFFERS, IRP_MJ_QUERY_INFORMATION,
> IRP_MJ_SET_INFORMATION aren’t handled by WDF so I must handle them myself
> (this is in the KMDF serial sample as well). And the IRP_MJ_READ
> interception was indeed the workaround for the MSCOMM control.
>
> The way to do this is to call this during device initialization:
>
> status = WdfDeviceInitAssignWdmIrpPreprocessCallback(pwdfDeviceInit,
> PreprocessFunction,
> IRP_MJ_READ, // major IRP to
> preprocess
> NULL, // pointer minor function
> table
> 0);
>
> I am not intercepting the power IRPs though.
>
> Thanks again to both of you for the replies, and help.
>
> —
> 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
>
>
> —
> 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
>

Velio - I ended up opening a support case with Microsoft CSS, and Doron I believe forwarded the dump to someone who could help as well. I’m just waiting for responses at this point. I haven’t heard anything yet, however I will complete this post with the solution once I get one.

Hi Preston,

Thanks for the input. Thought that the issue might had been resolved.

Regards
/Faik

On Tue, Jun 30, 2009 at 9:58 PM, wrote:

> Velio - I ended up opening a support case with Microsoft CSS, and Doron I
> believe forwarded the dump to someone who could help as well. I’m just
> waiting for responses at this point. I haven’t heard anything yet, however I
> will complete this post with the solution once I get one.
>
> —
> 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
>

This issue has been resolved, here is the scenario and workaroud - thanks to those that provided support on this issue:

Limitations of the current KMDF implementation requires, for a device created with a synchronization scope of WdfSynchronizationScopeDevice (auto locking), that any Wdf Requests (IRPs) sent to a device on a specific thread be completed before another request may be submitted to the device on the same thread. The current version of pnpfiltr.sys does not conform to this requirement and instead sends a device control IRP followed by a close IRP on the same thread, resulting in a WDF_VIOLATION (0x10d) bugcheck.

The work around for this problem is to use a different synchronization scope for your device (WdfSynchronizationScopeQueue or WdfSynchronizationScopeNone), along with the accompanying design changes in your driver to handle the resulting different synchronization behaviors.