In my USB modem driver I have a manual queue where I store serial IOCTLs (such as IOCTL_SERIAL_WAIT_ON_MASK) for later completion (for example, inside my bulk continuous reader completion routine).
I’ve encountered an extremely strange (at least to me) problem. Under certain circumstances, the act of writing to this IOCTL’s output buffer freezes the machine.
The pattern looks like this:
-
WdfIoQueueRetrieveNextRequest(manualQueue, &request) – this is OK.
-
WdfRequestOutputBuffer(request, sizeof(ULONG), &pBuffer, &size) – this is okay, size is sizeof(ULONG) and pBuffer seems to be a valid address (sample: 0x86F7BAC8).
-
RtlCopyMemory(pBuffer, &myData, sizeof(ULONG)) – doing this freezes the machine.
I don’t have any clue why this would happen. Any ideas?
Sorry, I guess that analysis wasn’t very good. Let me add some details. I broke into the debugger when the machine was hung and issued !thread.
Note in the output below that I’m completing my pended request and then KMDF is issuing me another (and then I try to complete it synchronously) in the same call stack.
I seem to remember reading somewhere that this is, or can be, bad. Is that right? Something about recursion or a deadlock?
Hopefully this more general problem will ring a bell for someone.
805487c4 8054026d 00000001 00000002 000000d1 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
805487c4 ee92ad3f 00000001 00000002 000000d1 nt!KeUpdateSystemTime+0x165 (FPO: [0,2] TrapFrame @ 805487d8)
8054885c ee92be67 00000000 85565afc 86c99b10 Wdf01000!FxIoQueue::QueueRequest+0x24a (FPO: [Non-Fpo])
80548880 ee91ad9a 855659e0 805488b8 804eddf9 Wdf01000!FxPkgIo::Dispatch+0x377 (FPO: [Non-Fpo])
8054888c 804eddf9 85521450 855659e0 85565b20 Wdf01000!FxDevice::Dispatch+0x7f (FPO: [Non-Fpo])
8054889c f797f023 85565ae3 855659e0 00000000 nt!IopfCallDriver+0x31 (FPO: [0,0,0])
805488b8 804f0362 85774c68 85565902 85774da0 Modem!UniGeneralWaitComplete+0x147 (FPO: [Non-Fpo])
805488e8 ee9496b4 86c87c10 80548920 ee914994 nt!IopfCompleteRequest+0xa2 (FPO: [Non-Fpo])
805488f4 ee914994 00000002 ee94f118 86c87c10 Wdf01000!FxIrp::CompleteRequest+0x13 (FPO: [Non-Fpo])
80548920 ee916938 00000000 00000002 86dced48 Wdf01000!FxRequest::CompleteInternal+0x4e9 (FPO: [Non-Fpo])
8054893c ee91695c 00000000 00000002 80548968 Wdf01000!FxRequest::Complete+0xb3 (FPO: [Non-Fpo])
8054894c ee8fffd4 00000000 00000004 86c08010 Wdf01000!FxRequest::CompleteWithInformation+0x18 (FPO: [Non-Fpo])
80548968 f791cecd 86c87c10 793783e8 00000000 Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f (FPO: [Non-Fpo])
80548980 f791d8b0 793783e8 00000000 00000004 xxxmodem!WdfRequestCompleteWithInformation+0x1d (FPO: [Non-Fpo]) (CONV: stdcall) [c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
(I’m issued a second IOCTL in the same calling context and I try to complete it synchronously on the following line).
805489e8 ee925ba4 793f7fe8 793783e8 00000004 xxxmodem!xxxEvtIoDeviceControl+0x940 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\xxxmodem\ioctl.c @ 642]
80548a0c ee926f7c 793f7fe8 793783e8 00000004 Wdf01000!FxIoQueueIoDeviceControl::Invoke+0x30 (FPO: [Non-Fpo])
80548a3c ee929598 793783e8 86c87c10 86c08010 Wdf01000!FxIoQueue::DispatchRequestToDriver+0x445 (FPO: [Non-Fpo])
80548a58 ee92ad2c 86c08002 ee950188 86c08010 Wdf01000!FxIoQueue::DispatchEvents+0x485 (FPO: [Non-Fpo])
80548a74 ee92be67 00000000 85565afc 86c99b10 Wdf01000!FxIoQueue::QueueRequest+0x237 (FPO: [Non-Fpo])
80548a98 ee91ad9a 855659e0 80548ad0 804eddf9 Wdf01000!FxPkgIo::Dispatch+0x377 (FPO: [Non-Fpo])
80548aa4 804eddf9 85521450 855659e0 85565b20 Wdf01000!FxDevice::Dispatch+0x7f (FPO: [Non-Fpo])
80548ab4 f797f023 85565ae3 855659e0 00000000 nt!IopfCallDriver+0x31 (FPO: [0,0,0])
80548ad0 804f0362 85774c68 85565902 85774da0 Modem!UniGeneralWaitComplete+0x147 (FPO: [Non-Fpo])
80548b00 ee9496b4 86c9a100 80548b38 ee914994 nt!IopfCompleteRequest+0xa2 (FPO: [Non-Fpo])
80548b0c ee914994 00000002 ee94f118 86c9a100 Wdf01000!FxIrp::CompleteRequest+0x13 (FPO: [Non-Fpo])
80548b38 ee916938 00000000 00000002 86dced48 Wdf01000!FxRequest::CompleteInternal+0x4e9 (FPO: [Non-Fpo])
80548b54 ee91695c 00000000 00000002 80548b80 Wdf01000!FxRequest::Complete+0xb3 (FPO: [Non-Fpo])
80548b64 ee8fffd4 00000000 00000004 86900c80 Wdf01000!FxRequest::CompleteWithInformation+0x18 (FPO: [Non-Fpo])
80548b80 f791cecd 86c9a100 79365ef8 00000000 Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f (FPO: [Non-Fpo])
80548b98 f791f0b5 79365ef8 00000000 00000004 xxxmodem!
WdfRequestCompleteWithInformation+0x1d (FPO: [Non-Fpo]) (CONV: stdcall) [c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
(I complete the pended IOCTL on the following line.)
80548c08 ee8fb426 79358c60 7aaa8ff0 00000008 xxxmodem!xxxEvtBulkInCompletion+0x375 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\xxxmodem\readwrit.c @ 843]
80548c38 ee91c245 7aa66fe8 79358c60 86d736c4 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3e (FPO: [Non-Fpo])
80548c60 ee8f35d3 855bbc1f 86ca7398 00000000 Wdf01000!FxRequestBase::CompleteSubmitted+0x89 (FPO: [Non-Fpo])
80548c7c ee8f368d 01599010 8560acd0 80548ca8 Wdf01000!FxIoTarget::RequestCompletionRoutine+0x195 (FPO: [Non-Fpo])
80548c8c 804ef403 00000000 855bbb40 85599010 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35 (FPO: [Non-Fpo])
80548ca8 804f0362 00000000 855bbb40 8560acd0 nt!IopUnloadSafeCompletion+0x1d (FPO: [Non-Fpo])
80548cd8 f6536ee5 855bbb40 8603f8e0 86c1d028 nt!IopfCompleteRequest+0xa2 (FPO: [Non-Fpo])
80548d40 f6537b57 86d7370c 00000000 86c1d7d8 USBPORT!USBPORT_CompleteTransfer+0x373 (FPO: [Non-Fpo])
80548d70 f6538754 026e6f44 86c1d0e0 86c1d0e0 USBPORT!USBPORT_DoneTransfer+0x137 (FPO: [Non-Fpo])
80548da8 f6539f6a 86c1d028 805418a8 86c1d230 USBPORT!USBPORT_FlushDoneTransferList+0x16c (FPO: [Non-Fpo])
Also, one more thing. From a pure debug trace perspective, if I catch this freeze happening, it looks like KMDF keeps feeding me the two same WDFREQUESTs over and over, alternating between them:
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x793536A8.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x7AA08C90.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x793536A8.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x7AA08C90.
[ad infinitum…]
xxxxx@gmail.com wrote:
Also, one more thing. From a pure debug trace perspective, if I catch this freeze happening, it looks like KMDF keeps feeding me the two same WDFREQUESTs over and over, alternating between them:
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x793536A8.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x7AA08C90.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x793536A8.
[Xxxmodem COM4] XxxEvtIoDeviceControl: entry – IOCTL code is IOCTL_SERIAL_WAIT_ON_MASK (18 / 0x001B0048), request is 0x7AA08C90.
[ad infinitum…]
These are probably coming from a lookaside list. As long as it never
needs more than two at the same time, you’ll just see the same two
WDFREQUESTs again and again. Note that this doesn’t mean these are the
same two requests – it just means the request structures happen to live
at the same address.
–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.
Well, I think you’re right – I saw that 0x7AA08C90 much earlier in the log as well, so it’s probably just something that’s being recycled.
I didn’t mean to imply anything, just sharing an observation – the main point is that I get into an infinite loop of dispatch/complete/dispatch/complete/etc.
Ok, so I figured this out – I was completing IOCTL_SERIAL_WAIT_ON_MASK (if the mask was RXCHAR) synchronously if I had any characters in my buffer.
But (based on observing usbser.sys) you apparently only complete that IOCTL when *another* character is received, regardless of what has already come in.
Apparently this led to modem.sys issuing the same IOCTL over and over at DISPATCH_LEVEL, or something.