Windows System Software -- Consulting, Training, Development -- Unique Expertise, Guaranteed Results

Home NTDEV
Before Posting...
Please check out the Community Guidelines in the Announcements and Administration Category.

More Info on Driver Writing and Debugging


The free OSR Learning Library has more than 50 articles on a wide variety of topics about writing and debugging device drivers and Minifilters. From introductory level to advanced. All the articles have been recently reviewed and updated, and are written using the clear and definitive style you've come to expect from OSR over the years.


Check out The OSR Learning Library at: https://www.osr.com/osr-learning-library/


WdfUsbTargetDeviceSendControlTransferSynchronously waiting indefinitely even though timeout is set

davs_shrusdavs_shrus Member - All Emails Posts: 18

Dear All,
I am try to enable and disable one particular USB interface on USB composite device from device manager. The interface has function driver(driver1) and lower filter driver(driver2). Issue is device manager getting hanged indefinitely, using notmyfault crashed system to get dump, corresponding to drivers two threads are in blocked state. Thread-1 from driver1, synchronously sending vendor request to device which goes through lower filter driver, lower filter driver2 receives on EvtIoWrite this request is again framed and sent to lower level, lower level is waiting on "KeWaitForSingleObject" indefinitely , even though timeout value is set.

I am trying to see arguments passed to KeWaitForSingleObject function, since timeout value is 5th argument, I want to make sure timeout is set. I am assuming 5th argument is pushed to stack.
when checked value it is showing "zero", this issue I am checking on windows 10 x64, quite difficult to get assured value. kindly please let me know how to debug this issue.

1) why request is not completed even though timeout value is set?
2) how to view 5th argument in case of x64( value stored on stack is assured?).

ffffdd0773496000 fffff8026f1c908d : ffff88019f744180 00000004fffffffe ffff8801ffffffff 0000000000000001 : nt!KiSwapContext+0x76
ffffdd0773496140 fffff8026f1c7f14 : ffffc704bb549040 0000000000000000 ffffde8000000000 ffffde8000000000 : nt!KiSwapThread+0xbfd
ffffdd07734961e0 fffff8026f1c76b5 : 0000000000000000 fffff80200000000 ffffdd0773498000 0000000000000000 : nt!KiCommitThreadWait+0x144
ffffdd0773496280 fffff8026fa2f9f4 : ffffdd0773496430 0000000000000000 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x255
ffffdd0773496360 fffff8026fa2ee6e : ffffdd0773496430 0000000000000102 ffffdd0773496470 000000000000001d : nt!ViKeWaitForSingleObjectCommon+0x98

4: kd> dqs ffffdd07`73496360

ffffdd0773496360 ffffdd0773496430

ffffdd0773496368 0000000000000000

ffffdd0773496370 000000000000000

ffffdd0773496378 0000000000000000

ffffdd0773496380 0000000000000000----> is it 5th argument timeout value for "KeWaitForSingleObject" ?

ffffdd0773496388 ffffdd0773496400

ffffdd0773496390 000000000000001d

Thread -1 sent synchronous request which is not getting completed, Thread-2( PNP remove) waiting on Thread-1 handle to get terminate. That's why device manager is not hanged.

Thread-1 WdfRequestSend driver1

WDF_WRITE_REQUEST_TIMEOUT 1 
WDF_REQUEST_SEND_OPTIONS_INIT(&options,WDF_REQUEST_SEND_OPTION_TIMEOUT | WDF_REQUEST_SEND_OPTION_SYNCHRONOUS);
WDF_REQUEST_SEND_OPTIONS_SET_TIMEOUT(&options,WDF_ABS_TIMEOUT_IN_SEC(WDF_WRITE_REQUEST_TIMEOUT)
WdfRequestSend(wdfRequest, deviceContext->UsbDeviceIoTargets, &options);

Thread-1 WdfUsbTargetDeviceSendControlTransferSynchronously driver2

SEND_ENCAP_REQ_TIMEOUT 1
WDF_REQUEST_SEND_OPTIONS_INIT(&requestSendOptions, WDF_REQUEST_SEND_OPTION_TIMEOUT);
WDF_REQUEST_SEND_OPTIONS_SET_TIMEOUT(&requestSendOptions, WDF_REL_TIMEOUT_IN_SEC(SEND_ENCAP_REQ_TIMEOUT));
WdfUsbTargetDeviceSendControlTransferSynchronously( pDeviceContext->UsbContext.UsbDevice,WDF_NO_HANDLE, &requestSendOptions,&usbControlSetupPacket,&memoryDescriptor,&numberOfBytesTransferred);

thread-1 and thread-2 stacks are attached.

Comments

  • Peter_Viscarola_(OSR)Peter_Viscarola_(OSR) Administrator Posts: 8,050

    (Not a WinDbg issue... Moved to NTDEV.... where the right people are likely to read it).

    Peter Viscarola
    OSR
    @OSRDrivers

  • Peter_Viscarola_(OSR)Peter_Viscarola_(OSR) Administrator Posts: 8,050

    I want to make sure timeout is set

    You have the sources for the driver? And a PDB? Can you just not look the the locals?

    Sorry... I know that sounds simple, but...

    Peter

    Peter Viscarola
    OSR
    @OSRDrivers

  • davs_shrusdavs_shrus Member - All Emails Posts: 18
    edited March 30

    @Peter_Viscarola_(OSR) thank you for reply :),
    I have PDB files related to driver1 and driver2, I saw local variables, timeout value is set.
    when I try to see KeWaitForSingleObject local variables it is saying private symbols.

    ffffdd0773496280 fffff8026fa2f9f4 : ffffdd0773496430 0000000000000000 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x255

    I am sharing local variables for requests sent by two drivers driver1 and driver2.

    Driver2:

    0b ffffdd07734967e0 fffff80ccc2b515c driver2!WdfUsbTargetDeviceSendControlTransferSynchronously+0x79
    ffffdd0773496840 struct WDFUSBDEVICE__ * UsbDevice = 0x000038fb419cb218
    ffffdd0773496848 struct WDFREQUEST__ * Request = 0x0000000000000000
    ffffdd0773496850 struct _WDF_REQUEST_SEND_OPTIONS * RequestOptions = 0xffffdd07734968f0
    ffffdd0773496858 union _WDF_USB_CONTROL_SETUP_PACKET * SetupPacket = 0xffffdd07734968e8
    ffffdd0773496860 struct _WDF_MEMORY_DESCRIPTOR * MemoryDescriptor = 0xffffdd07734968c0
    ffffdd0773496868 unsigned long * BytesTransferred = 0xffffdd0773496898
    DBGHELP: driver2is not source indexed
    4: kd> dx -r1 ((driver2!_WDF_REQUEST_SEND_OPTIONS *)0xffffdd07734968f0)
    ((driver2!_WDF_REQUEST_SEND_OPTIONS *)0xffffdd07734968f0) : 0xffffdd07734968f0 [Type: _WDF_REQUEST_SEND_OPTIONS *]
    [+0x000] Size : 0x10 [Type: unsigned long]
    [+0x004] Flags : 0x1 [Type: unsigned long]
    [+0x008] Timeout : -10000000 [Type: __int64]

    Driver1:

    1f ffffdd0773496f40 fffff80cc604ff26 driver1!WdfRequestSend+0x50
    ffffdd0773496f90 struct WDFREQUEST__ * Request = 0x000038fb411ab198
    ffffdd0773496f98 struct WDFIOTARGET__ * Target = 0x000038fb4123d188
    ffffdd0773496fa0 struct _WDF_REQUEST_SEND_OPTIONS * Options = 0xffffdd0773497050
    DBGHELP: driver1is not source indexed
    4: kd> dx -r1 ((driver1!_WDF_REQUEST_SEND_OPTIONS *)0xffffdd0773497050)
    ((driver1!_WDF_REQUEST_SEND_OPTIONS *)0xffffdd0773497050) : 0xffffdd0773497050 [Type: _WDF_REQUEST_SEND_OPTIONS *]
    [+0x000] Size : 0x10 [Type: unsigned long]
    [+0x004] Flags : 0x3 [Type: unsigned long]
    [+0x008] Timeout : 10000000 [Type: __int64]

    Source where timeout is set for driver1 and driver2.

    Thread-1 WdfRequestSend driver1

    WDF_WRITE_REQUEST_TIMEOUT 1
    WDF_REQUEST_SEND_OPTIONS_INIT(&options,WDF_REQUEST_SEND_OPTION_TIMEOUT | WDF_REQUEST_SEND_OPTION_SYNCHRONOUS);
    WDF_REQUEST_SEND_OPTIONS_SET_TIMEOUT(&options,WDF_ABS_TIMEOUT_IN_SEC(WDF_WRITE_REQUEST_TIMEOUT);
    
    WdfRequestSend(wdfRequest, deviceContext->UsbDeviceIoTargets, &options);
    

    Thread-1 WdfUsbTargetDeviceSendControlTransferSynchronously driver2

    SEND_ENCAP_REQ_TIMEOUT 1
    WDF_REQUEST_SEND_OPTIONS_INIT(&requestSendOptions, WDF_REQUEST_SEND_OPTION_TIMEOUT);
    WDF_REQUEST_SEND_OPTIONS_SET_TIMEOUT(&requestSendOptions, WDF_REL_TIMEOUT_IN_SEC(SEND_ENCAP_REQ_TIMEOUT));
    
    WdfUsbTargetDeviceSendControlTransferSynchronously( pDeviceContext->UsbContext.UsbDevice,WDF_NO_HANDLE, &requestSendOptions,&usbControlSetupPacket,&memoryDescriptor,&numberOfBytesTransferred);
    
  • Tim_RobertsTim_Roberts Member - All Emails Posts: 13,605

    The source code for KMDF is all publicly available. We have to trust that your code actually looks like you posted, but if it did, then the KMDF code would have passed a timeout to KeWaitForSingleObject, Can you cut-and-paste the exact code?

    Tim Roberts, [email protected]
    Providenza & Boekelheide, Inc.

  • davs_shrusdavs_shrus Member - All Emails Posts: 18

    @Tim_Roberts thanks for your reply I have download WDF framwork and synched with windbg.
    I am attaching source "Thread1&Thread2_functions.txt" as well. code is trimmed.
    from windbg I tried see local variables. struct _WDF_REQUEST_SEND_OPTIONS * Options = .

    4: kd> .frame 0n9;dv /t /v
    09 ffffdd07734963f0 fffff8027046e49c Wdf01000!FxIoTarget::SubmitSync+0x1191e [minkernel\wdf\framework\shared\targets\general\fxiotarget.cpp @ 1855]
    @r14 class FxIoTarget * this = 0xffffc704be634de0 @rdi class FxRequestBase * Request = 0xffffdd0773496520
    struct _WDF_REQUEST_SEND_OPTIONS * Options =
    @r15 unsigned long * Action = 0x0000000000000000 ffffdd0773496430 struct FxTargetSubmitSyncParams params = struct FxTargetSubmitSyncParams
    @esi unsigned long action = 0x1d
    ffffdd07734964b0 unsigned char irql = 0x00 '' ffffdd07734964c0 int64 timeout = 0n-10000000
    ffffdd07`734964b8 long status = 0n258

    static NTSTATUS UsbControlTransferSendToUsb
    (
        PDEVICE_CONTEXT pDeviceContext,
        PUCHAR pBuffer,
        ULONG BufferLen,
        ULONG *pBytesReturned)
    {
        NTSTATUS                        status = STATUS_UNSUCCESSFUL;
        WDF_USB_CONTROL_SETUP_PACKET    usbControlSetupPacket = { 0 };
        WDF_REQUEST_SEND_OPTIONS        requestSendOptions = { 0 };
        WDF_MEMORY_DESCRIPTOR           memoryDescriptor = { 0 };
        ULONG                           numberOfBytesTransferred = 0;
    
        //
        // USB_BM_BYTE_HOST_TO_DEVICE = 0x21 is Magic Number for 
        // (BYTE)((BYTE)(BMREQUEST_HOST_TO_DEVICE << 7) | (BYTE)(BMREQUEST_CLASS << 5) | (BYTE)BMREQUEST_TO_INTERFACE);
        //
        CONST BYTE                      USB_BM_BYTE_HOST_TO_DEVICE = 0x21;
        CONST BYTE                      SEND_ENCAPSULATED_REQUEST = 0x00;
        PAGED_CODE();
    
        if(pDeviceContext == NULL || pDeviceContext->UsbContext.UsbDevice == WDF_NO_HANDLE ||
            NULL == pBuffer || 0 == BufferLen || NULL == pBytesReturned)
        {
            return STATUS_INVALID_PARAMETER;
        }
    
        WDF_REQUEST_SEND_OPTIONS_INIT(&requestSendOptions, WDF_REQUEST_SEND_OPTION_TIMEOUT);
        WDF_REQUEST_SEND_OPTIONS_SET_TIMEOUT(&requestSendOptions, WDF_REL_TIMEOUT_IN_SEC(SEND_ENCAP_REQ_TIMEOUT));
        // Setup the control packet.
        WDF_USB_CONTROL_SETUP_PACKET_INIT_VENDOR(
            &usbControlSetupPacket,
            BmRequestHostToDevice,
            BmRequestToInterface,
            SEND_ENCAPSULATED_REQUEST,
            0,
            0);
    
        usbControlSetupPacket.Packet.bm.Byte = USB_BM_BYTE_HOST_TO_DEVICE;
        usbControlSetupPacket.Packet.wIndex.Bytes.LowByte = pDeviceContext->UsbContext.UsbInterfaceNumber;
        usbControlSetupPacket.Packet.wIndex.Bytes.HiByte = 0x00;
    
        WDF_MEMORY_DESCRIPTOR_INIT_BUFFER(&memoryDescriptor, (PVOID)pBuffer, BufferLen);
    
        status = WdfUsbTargetDeviceSendControlTransferSynchronously(
            pDeviceContext->UsbContext.UsbDevice,
            WDF_NO_HANDLE,
            &requestSendOptions,
            &usbControlSetupPacket,
            &memoryDescriptor,
            &numberOfBytesTransferred);
    
        if(!NT_SUCCESS(status))
        {
            Trace("%!FUNC!:: ERROR:: WdfUsbTargetDeviceSendControlTransferSynchronously failed %!STATUS!.", status);
        }
        else
        {
            *pBytesReturned = numberOfBytesTransferred;
    
        }
        return status;
    }
    
  • Peter_Viscarola_(OSR)Peter_Viscarola_(OSR) Administrator Posts: 8,050

    Have you dumped the log with !wdflogdump ?

    Let’s assume the timeout is working. In that case, after the timeout, your Request will be canceled. Perhaps the lower driver isn’t completing the Request... or ?

    Peter

    Peter Viscarola
    OSR
    @OSRDrivers

  • Tim_RobertsTim_Roberts Member - All Emails Posts: 13,605

    So, the timeout is set correctly, and the request does have a status value of STATUS_TIMEOUT. Now, do you understand that STATUS_TIMEOUT is a positive value, and hence will be seen as a success code by NT_SUCCESS? Is it possible that you are continuing to send more requests because you don't realize there's a problem? Sending another request after a USB request has timed out can cause issues like the one you see.

    Tim Roberts, [email protected]
    Providenza & Boekelheide, Inc.

  • davs_shrusdavs_shrus Member - All Emails Posts: 18

    @Peter_Viscarola_(OSR) , !wdflogdump. I will go through the logs, I am matching with driver flow. will update soon.

  • davs_shrusdavs_shrus Member - All Emails Posts: 18
    edited March 31

    @Peter_Viscarola_(OSR) said:
    Have you dumped the log with !wdflogdump ?

    Let’s assume the timeout is working. In that case, after the timeout, your Request will be canceled. Perhaps the lower driver isn’t completing the Request... or ?

    Peter

    how can to get notified wdf request cancelled ? in this case "WdfUsbTargetDeviceSendControlTransferSynchronously " will not return? I take your comment as reference and go through WDF source code "FxIoTarget::SubmitSync". There is issue with device whatever control request sent reponse is not coming, code is like it will try couple of times based on retry machanism, i will check lower level also if request is still pending with bus driver

  • davs_shrusdavs_shrus Member - All Emails Posts: 18

    @Tim_Roberts @Peter_Viscarola_(OSR) with help your comments, i am able to understand how wdf framework sending IRP to lower level drivers. looks like the wdf request after timeout, getting cancel, which is not getting completed(cancel) by lower level driver. In wdf framwork its waiting for cancel. currently looking into lower level drivers.

Sign In or Register to comment.

Howdy, Stranger!

It looks like you're new here. If you want to get involved, click one of these buttons!

Upcoming OSR Seminars
OSR has suspended in-person seminars due to the Covid-19 outbreak. But, don't miss your training! Attend via the internet instead!
Internals & Software Drivers 30 Nov 2020 LIVE ONLINE
Writing WDF Drivers 7 Dec 2020 LIVE ONLINE
Developing Minifilters Early 2021 LIVE ONLINE