Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

Strange BSOD during data transfers

68 views
Skip to first unread message

Sushma

unread,
Jul 30, 2009, 1:50:04 AM7/30/09
to
Hello All,

I'm seeing a strange behavior with my USB-Serial device. I get a BSOD
with huge data transfer and it occurs after 4-5 hrs of rigorous
testing.

Moreover, this BSOD occurs on particular system configuration. Core 2
Duo, 2.20 G Hz, 2.00 GB RAM, Dell Laptop.

The BSOD does not occurs in any other PCs with same configuration or
other laptops (Tested for more than 24hrs).
A polling thread is started when driver loaded. Driver gets Read
request. The polling thread starts processing the read request. The
error occurs while submitting the request to lower stack. I guess the
problem is related to synchronization but I'm not sure of it.

Can some point out if I'm missing anything. Any help is much
appreciated.

Thanks And Regards,
Sushma

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

Use !analyze -v to get detailed debugging information.

BugCheck 7E, {c0000005, b4c1fa62, b5f4cc18, b5f4c914}

Probably caused by : tusbserial.sys ( tusbserial!ReceivePoll+8d )

Followup: MachineOwner
---------

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

SYSTEM_THREAD_EXCEPTION_NOT_HANDLED (7e)
This is a very common bugcheck. Usually the exception address
pinpoints
the driver/function that caused the problem. Always note this address
as well as the link date of the driver/image that contains this
address.
Arguments:
Arg1: c0000005, The exception code that was not handled
Arg2: b4c1fa62, The address that the exception occurred at
Arg3: b5f4cc18, Exception Record Address
Arg4: b5f4c914, Context Record Address

Debugging Details:
------------------


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

FAULTING_IP:
Wdf01000!FxRequest::CompleteInternal+1a
b4c1fa62 8b7960 mov edi,dword ptr [ecx+60h]

EXCEPTION_RECORD: b5f4cc18 -- (.exr 0xffffffffb5f4cc18)
ExceptionAddress: b4c1fa62 (Wdf01000!FxRequest::CompleteInternal
+0x0000001a)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 00000060
Attempt to read from address 00000060

CONTEXT: b5f4c914 -- (.cxr 0xffffffffb5f4c914)
eax=89af5990 ebx=00000000 ecx=00000000 edx=00001008 esi=89ba0d68
edi=89ba0d68
eip=b4c1fa62 esp=b5f4cce0 ebp=b5f4cd00 iopl=0 nv up ei pl zr
na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010246
Wdf01000!FxRequest::CompleteInternal+0x1a:
b4c1fa62 8b7960 mov edi,dword ptr [ecx+60h] ds:
0023:00000060=????????
Resetting default scope

PROCESS_NAME: System

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

EXCEPTION_PARAMETER1: 00000000

EXCEPTION_PARAMETER2: 00000060

READ_ADDRESS: 00000060

FOLLOWUP_IP:
tusbserial!ReceivePoll+8d [d:\tusbserial\serial.c @ 1610]
b74d45ed 8d45f8 lea eax,[ebp-8]

BUGCHECK_STR: 0x7E

DEFAULT_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER: from b4c12812 to b4c1fa62

STACK_TEXT:
b5f4cd00 b4c12812 00000000 00000002 804eeba2 Wdf01000!
FxRequest::CompleteInternal+0x1a
b5f4cd1c b74d45ed 00000000 89ba0d68 00000000 Wdf01000!
imp_WdfRequestComplete+0x108
b5f4cd5c b74d473d 76458e68 805459e8 89ba7358 tusbserial!ReceivePoll
+0x8d [d:\tusbserial\serial.c @ 1610]
b5f4cd70 b74d6dae 76458e68 b3f59a3c 89d8b370 tusbserial!SerialPoll
+0x55 [d:\tusbserial\serial.c @ 191]
b5f4cd90 b74d74c2 76458e68 00000000 8987bda8 tusbserial!GetNextRequest
+0x6e [d:\tusbserial\usb.c @ 313]
b5f4cdac 805ce794 76458e68 00000000 00000000 tusbserial!ThreadUSBDevice
+0x2c [d:\tusbserial\usb.c @ 221]
b5f4cddc 805450ce b74d7496 76458e68 00000000 nt!PspSystemThreadStartup
+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16


FAULTING_SOURCE_CODE:
1608: IoReleaseCancelSpinLock(oldIrql);
1609: WdfRequestComplete(pRequest, Status);
> 1610: IoAcquireCancelSpinLock(&oldIrql);
1611:

SYMBOL_STACK_INDEX: 2

SYMBOL_NAME: tusbserial!ReceivePoll+8d

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: tusbserial

IMAGE_NAME: tusbserial.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4a702100

STACK_COMMAND: .cxr 0xffffffffb5f4c914 ; kb

FAILURE_BUCKET_ID: 0x7E_tusbserial!ReceivePoll+8d

BUCKET_ID: 0x7E_tusbserial!ReceivePoll+8d

Followup: MachineOwner
---------

Maxim S. Shatskih

unread,
Jul 30, 2009, 3:51:06 AM7/30/09
to
> 1608: IoReleaseCancelSpinLock(oldIrql);
> 1609: WdfRequestComplete(pRequest, Status);
>> 1610: IoAcquireCancelSpinLock(&oldIrql);

Why are you ever using cancel spinlock in KMDF code? KMDF provides you the queues which liberate you from such a burden.

--
Maxim S. Shatskih
Windows DDK MVP
ma...@storagecraft.com
http://www.storagecraft.com

Volodymyr Shcherbyna

unread,
Jul 30, 2009, 4:36:48 AM7/30/09
to
IMO: it is related to syncronization, so the solution is look at code in
more details and find out the problem, or post it here, maybe someone will
have ideas.

--
Volodymyr M. Shcherbyna, blog: http://www.shcherbyna.com/
(This posting is provided "AS IS" with no warranties, and confers no
rights)

"Sushma" <sushma...@gmail.com> wrote in message
news:fd5fb55d-3317-493c...@z4g2000prh.googlegroups.com...

Sushma

unread,
Jul 30, 2009, 4:50:44 AM7/30/09
to
Due to some reasons i had to use wdm code, so i used cancel spin
locks. Also, i have polling thread.

I cannot post the code due to some legal issues. I was able to further
debug using !wdflogdump. Before completing the request i disable the
cacellation of I/O request using WdfRequestUnmarkCancelable(). The
logdump says the request does not belong to any queue. I'm not able to
understand the problem.

Here are last few lines of wdflogdump. May be this can provide some
ideas what is going wrong.

3156027: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156028: FxIoQueue::CanThreadDispatchEventsLocked - Current thread
0x8055AE40 is not at the passive-level 0x00000002(DPC), posting to
worker thread for WDFQUEUE 0x7670A1F8
3156029: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156030: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156031: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156032: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156033: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156034: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156035: FxIoQueue::CanThreadDispatchEventsLocked - Current thread
0xB833AE20 is not at the passive-level 0x00000002(DPC), posting to
worker thread for WDFQUEUE 0x7670A1F8
3156036: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156037: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156038: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156039: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156040: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156041: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156042: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156043: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156044: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156045: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156046: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156047: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156048: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156049: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156050: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156051: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156052: FxIoQueue::CanThreadDispatchEventsLocked - Current thread
0xB833AE20 is not at the passive-level 0x00000002(DPC), posting to
worker thread for WDFQUEUE 0x76412FE8
3156053: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156054: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76280FE8 !devobj 0x89C98CB0 entering power idle state FxIdleBusy
from FxIdleDecrementIo
3156055: imp_WdfRequestUnmarkCancelable - WDFREQUEST 7645F290 doesn't
belong to any queue 0xc0000010(STATUS_INVALID_DEVICE_REQUEST)
3156056: FxIoQueue::CanThreadDispatchEventsLocked - Current thread
0xB833AE20 is not at the passive-level 0x00000002(DPC), posting to
worker thread for WDFQUEUE 0x7670A1F8
3156057: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state
FxIdleDecrementIo from FxIdleBusy
3156058: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE
0x76458E68 !devobj 0x8994EAA8 entering power idle state FxIdleBusy
from FxIdleDecrementIo
---- end of log ----

Regards,
Sushma

Maxim S. Shatskih

unread,
Jul 30, 2009, 5:08:52 AM7/30/09
to
> Due to some reasons i had to use wdm code, so i used cancel spin
> locks.

Then why you ever call WdfXxx from WDM code?

Maxim S. Shatskih

unread,
Jul 30, 2009, 5:10:53 AM7/30/09
to
> Parameter[1]: 00000060
> Attempt to read from address 00000060

> b5f4cd00 b4c12812 00000000 00000002 804eeba2 Wdf01000!
> FxRequest::CompleteInternal+0x1a

You attempt to mix WDF and WDM code resulted in bad initialization of some WDFREQUEST, and the framework crashes trying to complete the badly initialized request.

Sushma

unread,
Jul 30, 2009, 6:32:03 AM7/30/09
to
On Jul 30, 2:10 pm, "Maxim S. Shatskih"

<ma...@storagecraft.com.no.spam> wrote:
> >   Parameter[1]: 00000060
> > Attempt to read from address 00000060
> > b5f4cd00 b4c12812 00000000 00000002 804eeba2 Wdf01000!
> > FxRequest::CompleteInternal+0x1a
>
> You attempt to mix WDF and WDM code resulted in bad initialization of some WDFREQUEST, and the framework crashes trying to complete the badly initialized request.
>

>> I guess the problem is mixing of WDF+WDM code. But error does not occurs in all other systems except one. How is this behavior possible??

Any comments??

Regards,
Sushma

Maxim S. Shatskih

unread,
Jul 30, 2009, 7:52:00 AM7/30/09
to
>> I guess the problem is mixing of WDF+WDM code. But error does not occurs in all other systems
>except one. How is this behavior possible??

Find the bug with badly initialized WDFREQUEST, fix it, retest and forget such a question. This server is just "unlucky". This occurs due to non-deterministic nature of race conditions.

Sushma

unread,
Jul 30, 2009, 9:52:11 AM7/30/09
to
On Jul 30, 4:52 pm, "Maxim S. Shatskih"

<ma...@storagecraft.com.no.spam> wrote:
> >> I guess the problem is mixing of WDF+WDM code. But error does not occurs in all other systems
> >except one. How is this behavior possible??
>
> Find the bug with badly initialized WDFREQUEST, fix it, retest and forget such a question. This server is just "unlucky". This occurs due to non-deterministic nature of race conditions.
>

Thank you for the reply.

The wdflogdump entry has "3156055: imp_WdfRequestUnmarkCancelable -


WDFREQUEST 7645F290 doesn't belong to any queue 0xc0000010
(STATUS_INVALID_DEVICE_REQUEST) "

Could you please help me understand what the statement means.

Thanks and Regards,
Sushma

Doron Holan [MSFT]

unread,
Jul 30, 2009, 1:10:32 PM7/30/09
to
is this a WDFREQUEST you created or one that was presented to you via a
WDFQUEUE Evt callback?

--

This posting is provided "AS IS" with no warranties, and confers no rights.


"Sushma" <sushma...@gmail.com> wrote in message

news:3aff7b95-9a83-4b15...@12g2000pri.googlegroups.com...

Volodymyr Shcherbyna

unread,
Jul 31, 2009, 6:37:21 AM7/31/09
to
"Sushma" <sushma...@gmail.com> wrote in message
news:3aff7b95-9a83-4b15...@12g2000pri.googlegroups.com...
On Jul 30, 4:52 pm, "Maxim S. Shatskih"

>>Thank you for the reply.

>>The wdflogdump entry has "3156055: imp_WdfRequestUnmarkCancelable -
>>WDFREQUEST 7645F290 doesn't belong to any queue 0xc0000010
>>(STATUS_INVALID_DEVICE_REQUEST) "

>>Could you please help me understand what the statement means.

>>Thanks and Regards,
>>Sushma

Well, this particular assert is called by WdfRequestUnmarkCancelable if
particular instance of WDFREQUEST object is not associated with any queue.

--
Volodymyr M. Shcherbyna, blog: http://www.shcherbyna.com/

(This posting is provided "AS IS" with no warranties, and confers no
rights)


Sushma

unread,
Jul 31, 2009, 7:22:36 AM7/31/09
to
> is this a WDFREQUEST you created or one that was presented to you via a
> WDFQUEUE Evt callback?
>

The request is presented by EvtIO callback.

The sequence goes like this

EvtIoRead(,WDFREQUEST pRequest,...)
{
pDevContext->CurrentReadReq = pRequest;
}

PollThread(...)
{

WDFREQUEST pRequest = pDevContext->CurrentReadReq;
reqContext = GetRequestContext(pRequest);

//Process the current request
status = ProcessCurrRequest(pRequest);

if(status == STATUS_PENDING)
{
break;
}

ntstatus = WdfRequestUnmarkCancelable(Request);
if (NT_SUCCESS(ntstatus)) {
reqContext->CancelRoutine = NULL;
}

WdfRequestComplete(pRequest, status);

}

In ProcessCurrRequest() I'm using WDM code for getting the IRP
(WdfRequestWdmGetIrp) and process there on.

Will this be the cause of failure for any reason?

Regards,
Sushma

Maxim S. Shatskih

unread,
Jul 31, 2009, 7:42:06 AM7/31/09
to
> pDevContext->CurrentReadReq = pRequest;

Use the specially created separate KMDF queue instead of this race-prone stuff.

Chris

unread,
Jul 31, 2009, 10:10:03 AM7/31/09
to
On Jul 31, 6:42 am, "Maxim S. Shatskih"
<ma...@storagecraft.com.no.spam> wrote:

> > pDevContext->CurrentReadReq = pRequest;
>
> Use the specially created separate KMDF queue instead of this race-prone stuff.

Yep -- in particular, your driver needs to be able to handle more than
one pending read from userspace. Say I submit to you two read
requests (using overlapped IO). Judging by the code above, the first
one gets orphaned and is lost forever....

Doron Holan [MSFT]

unread,
Jul 31, 2009, 12:35:57 PM7/31/09
to
did you ever call WdfRequestMarkCancelable? you cannot call
WdfRequestUnmarkCancelable without marking it cancelable first

d

--

This posting is provided "AS IS" with no warranties, and confers no rights.


"Sushma" <sushma...@gmail.com> wrote in message

news:6c7c7d72-a87f-4ba0...@z4g2000prh.googlegroups.com...

Sushma

unread,
Jul 31, 2009, 2:36:08 PM7/31/09
to
> did you ever call WdfRequestMarkCancelable? you cannot call
> WdfRequestUnmarkCancelable without marking it cancelable first
>

In fact i called WdfRequestMarkCancelable when i get new request. ooh
i missed this in the code snippet.

Sushma

unread,
Jul 31, 2009, 2:44:25 PM7/31/09
to

> Yep -- in particular, your driver needs to be able to handle more than
> one pending read from userspace.  Say I submit to you two read
> requests (using overlapped IO).  Judging by the code above, the first
> one gets orphaned and is lost forever....

I'm using one default queue and forward to manual queues, so i get the
next request after completing the first one.

Sushma

unread,
Aug 4, 2009, 12:54:04 AM8/4/09
to
I had replaced all WDM code with WDF, but still i get the same error.

Will it be a good idea to find out if the request belongs to any
queue, and then requeue it, if it does not belongs to any queue (just
before completing the request).

queue = WdfRequestGetIoQueue(pRequest);

if(queue == NULL)
WdfRequestRequeue(pRequest);
else
WdfRequestComplete(pRequest);

I'm using manual queue and retrieving each request by calling
WdfIoQueueRetrieveNextRequest().

Any suggestions??

Thanks and Regards,
Sushma

Doron Holan [MSFT]

unread,
Aug 4, 2009, 6:13:40 PM8/4/09
to
a request presented to you in an io callback will always be associated with
a queue

d

--

This posting is provided "AS IS" with no warranties, and confers no rights.


"Sushma" <sushma...@gmail.com> wrote in message

news:3ccfc257-d830-475e...@d4g2000prc.googlegroups.com...

Sushma

unread,
Aug 5, 2009, 1:08:17 AM8/5/09
to

> a request presented to you in an io callback will always be associated with
> a queue
>

But the wdflogdump shows the request is not associated with any queue,
and when i try to complete that request i get BSOD.

0 new messages