none
Synchronization in EvtDevicePrepareHardware ? RRS feed

  • Question

  • <p>Hi:</p><p></p><p>I got the below crash when running the "Wdf Fault Injection Logo Test" on Windows 7. Looks like the crash occur because some code in the kernel get paged out as the result of WDF fails the call WdfChileListRetrieveNextDevice(), when my driver held a spinlock</p><span style="font-size:small;"> </span><p></p>

    KAL

    Monday, September 24, 2012 4:33 PM

Answers

  • looks like an issue in wdftester. if this is blocking certification, please ask for an errata.

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

    Monday, September 24, 2012 9:53 PM
  • I have already opened a support case for this.


    KAL

    • Marked as answer by Kiet Ly Friday, September 28, 2012 9:36 PM
    Wednesday, September 26, 2012 1:39 AM

All replies

  • Here is the crash:

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

    IRQL_NOT_LESS_OR_EQUAL (a)
    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 a kernel debugger is available get the stack backtrace.
    Arguments:
    Arg1: 82c849cd, memory referenced
    Arg2: 00000002, IRQL
    Arg3: 00000008, bitfield :
     bit 0 : value 0 = read operation, 1 = write operation
     bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)
    Arg4: 82c849cd, address which referenced memory

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

    *** ERROR: Symbol file could not be found.  Defaulted to export symbols for wdftester.sys -

    READ_ADDRESS:  82c849cd

    CURRENT_IRQL:  2

    FAULTING_IP:
    nt!RtlUnicodeToMultiByteN+0
    82c849cd 8bff            mov     edi,edi

    DEFAULT_BUCKET_ID:  VISTA_DRIVER_FAULT

    BUGCHECK_STR:  0xA

    PROCESS_NAME:  System

    TRAP_FRAME:  87b1ef6c -- (.trap 0xffffffff87b1ef6c)
    ErrCode = 00000010
    eax=87b1f00c ebx=8aa60e6a ecx=00000000 edx=8aa60e68 esi=87b1f04c edi=00000000
    eip=82c849cd esp=87b1efe0 ebp=87b1f000 iopl=0         nv up ei ng nz na pe nc
    cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00010286
    nt!RtlUnicodeToMultiByteN:
    82c849cd 8bff            mov     edi,edi
    Resetting default scope

    LOCK_ADDRESS:  82b84be0 -- (!locks 82b84be0)

    Resource @ nt!PiEngineLock (0x82b84be0)    Exclusively owned
        Contention Count = 14
        NumberOfExclusiveWaiters = 1
         Threads: 85b23a70-01<*>
         Threads Waiting On Exclusive Access:
                  85b23020      

    1 total locks, 1 locks currently held

    PNP_TRIAGE:
     Lock address  : 0x82b84be0
     Thread Count  : 1
     Thread address: 0x85b23a70
     Thread wait   : 0x1b67

    LAST_CONTROL_TRANSFER:  from 82c849cd to 82a5f65b

    FAILED_INSTRUCTION_ADDRESS:
    nt!RtlUnicodeToMultiByteN+0
    82c849cd 8bff            mov     edi,edi

    STACK_TEXT: 
    87b1ef6c 82c849cd badb0d00 8aa60e68 00000008 nt!KiTrap0E+0x2cf
    87b1efdc 82a254ae 87b1f284 00000006 87b1f00c nt!RtlUnicodeToMultiByteN
    87b1f000 82a2543a 87b1f04c 87b1f284 00000006 nt!_wctomb_s_l+0x6a
    87b1f01c 82ae26ef 87b1f04c 87b1f284 00000006 nt!wctomb_s+0x18
    87b1f290 82ae2a3c 87b1f2b4 850e9038 00000000 nt!_output_l+0x833
    87b1f2d4 82ae2afd 87b1f354 000001ff 850e901c nt!_vsnprintf_l+0x72
    87b1f2f0 82ae3078 87b1f354 000001ff 850e901c nt!_vsnprintf+0x18
    87b1f310 82ae2da2 850e901c 87b1f5a0 aebca2fb nt!RtlStringCbVPrintfA+0x30
    87b1f574 82a2d46c 00000065 00000003 850e901c nt!vDbgPrintExWithPrefixInternal+0x88
    87b1f594 850dae36 850e901c 00000007 8aa60e68 nt!DbgPrint+0x1d
    WARNING: Stack unwind information not available. Following frames may be wrong.
    87b1f5b8 850db3dd 00000000 00000007 94d94fd0 wdftester!CvRegisterHookProvider+0x26cc4
    87b1f5d4 850b4c71 87b1f600 94d94fd0 6b2210c8 wdftester!CvRegisterHookProvider+0x2726b
    87b1f624 946124a6 820e1220 6b2210c8 87b1f760 wdftester!CvRegisterHookProvider+0xaff
    87b1f728 94612590 6b2210c8 87b1f760 00000000 honeywell_enum!usb_child_retrieve_or_remove_next+0x182 [c:\work-dir\svn-source\usb-serial-driver\trunk\honeywell_standard-old-09182012\dc_cdc_acm.src\cdc\bus\kernel\winnt\usb_enum_cdc.c @ 239]
    87b1f73c 946156db 87b1f780 6b2210c8 87b1f760 honeywell_enum!usb_child_retrieve_next+0x18 [c:\work-dir\svn-source\usb-serial-driver\trunk\honeywell_standard-old-09182012\dc_cdc_acm.src\cdc\bus\kernel\winnt\usb_enum_cdc.c @ 287]
    87b1f788 9461178e 00000000 89b22fa0 82e356ee honeywell_enum!ctrl_add_usb_device+0x13d [c:\work-dir\svn-source\usb-serial-driver\trunk\honeywell_standard-old-09182012\dc_cdc_acm.src\cdc\bus\kernel\winnt\ctrl_device.c @ 299]
    87b1f804 85097335 765093d0 7650d058 4d891058 honeywell_enum!usb_evt_device_prepare_hardware+0x4e6 [c:\work-dir\svn-source\usb-serial-driver\trunk\honeywell_standard-old-09182012\dc_cdc_acm.src\cdc\bus\kernel\winnt\usb_device.c @ 754]
    87b1f830 85081301 765093d0 7650d058 4d891058 Wdf01000!VfEvtDevicePrepareHardware+0x5e
    87b1f84c 85081543 4d891058 89bccd30 01af6c28 Wdf01000!FxPkgPnp::PnpPrepareHardware+0x77
    87b1f860 85080484 89bccd30 89bccdd8 89bccd30 Wdf01000!FxPkgPnp::PnpEventHardwareAvailable+0x2b
    87b1f888 85080db2 00000108 89bccdd8 89bccd30 Wdf01000!FxPkgPnp::PnpEnterNewState+0x104
    87b1f8ac 8508147a 87b1f8c4 94d94f08 89bccd30 Wdf01000!FxPkgPnp::PnpProcessEventInner+0x149
    87b1f8d0 8507a40b 00000002 00000000 87b1f900 Wdf01000!FxPkgPnp::PnpProcessEvent+0x13e
    87b1f8e0 85079e02 89bccd30 87b1f908 aab20e28 Wdf01000!FxPkgPnp::_PnpStartDevice+0x1e
    87b1f900 85056a3f aab20e28 87b1f928 85056c63 Wdf01000!FxPkgPnp::Dispatch+0x207
    87b1f90c 85056c63 9103c4f0 aab20e28 b3368a98 Wdf01000!FxDevice::Dispatch+0x7f
    87b1f928 82d4f6c3 9103c4f0 aab20e28 aab20fd4 Wdf01000!FxDevice::DispatchWithLock+0x7b
    87b1f94c 82a55575 00000000 aab20ff8 9103c4f0 nt!IovCallDriver+0x258
    87b1f960 82d61235 8b4a7008 aab20e28 ad10cee0 nt!IofCallDriver+0x1b
    87b1f978 82d4f6c3 ad10cee0 9103c4f0 aab21000 nt!ViFilterDispatchPnp+0x120
    87b1f99c 82a55575 00000000 87b1fa20 ad10cee0 nt!IovCallDriver+0x258
    87b1f9b0 82bdc77c 00000000 875d63b0 910cf7d0 nt!IofCallDriver+0x1b
    87b1f9cc 82a302bb 87b1f9fc 82a3309f 910cf7d0 nt!PnpAsynchronousCall+0x92
    87b1fa30 82bd35e5 82a3309f 910cf7d0 91021518 nt!PnpStartDevice+0xe1
    87b1fa8c 82bd34ae 910cf7d0 00000020 00000000 nt!PnpStartDeviceNode+0x12c
    87b1faa8 82bdaec1 00000000 00000000 ad0d66d8 nt!PipProcessStartPhase1+0x62
    87b1fca4 82caaca6 91021518 ad0d66d8 87b1fcd0 nt!PipProcessDevNodeTree+0x188
    87b1fcd8 82a32ce7 82b82b00 85b23a70 82b593bc nt!PiRestartDevice+0x8a
    87b1fd00 82a9ba6b 00000000 00000000 85b23a70 nt!PnpDeviceActionWorker+0x1fb
    87b1fd50 82c27056 00000001 aebcaa1f 00000000 nt!ExpWorkerThread+0x10d
    87b1fd90 82acf1a9 82a9b95e 00000001 00000000 nt!PspSystemThreadStartup+0x9e
    00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x19


    STACK_COMMAND:  kb

    FOLLOWUP_IP:
    wdftester!CvRegisterHookProvider+26cc4
    850dae36 83c410          add     esp,10h

    SYMBOL_STACK_INDEX:  a

    SYMBOL_NAME:  wdftester!CvRegisterHookProvider+26cc4

    FOLLOWUP_NAME:  MachineOwner

    MODULE_NAME: wdftester

    IMAGE_NAME:  wdftester.sys

    DEBUG_FLR_IMAGE_TIMESTAMP:  5010ad02

    FAILURE_BUCKET_ID:  0xA_VRF_CODE_AV_BAD_IP_wdftester!CvRegisterHookProvider+26cc4

    BUCKET_ID:  0xA_VRF_CODE_AV_BAD_IP_wdftester!CvRegisterHookProvider+26cc4

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

    1: kd> lmv
    start    end        module name
    80bb3000 80bbb000   kdcom      (deferred)            
        Image path: kdcom.dll
        Image name: kdcom.dll
        Timestamp:        Mon Jul 13 21:08:58 2009 (4A5BDAAA)
        CheckSum:         000138B1
        ImageSize:        00008000
        Translations:     0000.04b0 0000.04e4 0409.04b0 0409.04e4
    82a1e000 82e30000   nt         (pdb symbols)          c:\symbols-fre\ntkrpamp.pdb\C1FE0CF3B52C4C9A89B7D35DBAFC6CF72\ntkrpamp.pdb
        Loaded symbol image file: ntkrpamp.exe
        Image path: ntkrpamp.exe
        Image name: ntkrpamp.exe
        Timestamp:        Fri Mar 30 22:24:37 2012 (4F766AE5)
        CheckSum:         003CDCDC
        ImageSize:        00412000
        File version:     6.1.7601.17803
        Product version:  6.1.7601.17803
        File flags:       0 (Mask 3F)
        File OS:          40004 NT Win32
        File type:        1.0 App
        File date:        00000000.00000000
        Translations:     0409.04b0
        CompanyName:      Microsoft Corporation
        ProductName:      Microsoft® Windows® Operating System
        InternalName:     ntkrpamp.exe
        OriginalFilename: ntkrpamp.exe
        ProductVersion:   6.1.7601.17803
        FileVersion:      6.1.7601.17803 (win7sp1_gdr.120330-1504)
        FileDescription:  NT Kernel & System
        LegalCopyright:   © Microsoft Corporation. All rights reserved.


    KAL

    Monday, September 24, 2012 4:34 PM
  • You would have to show us the code to help you more.  The actual failure is a DbgPrint with a UNICODE string which cannot be done at DISPATCH_LEVEL (which is what holding a spinlock raises IRQL to).


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com Blog: http://msmvps.com/blogs/WinDrvr

    Monday, September 24, 2012 5:08 PM
  • Here is the code:

    ctrl_add_usb_device() is called as part of VfEvtDevicePrepareHardware. It is holding a spinlock. The call WdfChildListRetrieveNextDevice() is failed by WDFtester. I am not calling DbgPrint with UNICODE string in my code.

    thanks,

    void usb_child_list_begin_iterator(WDFDEVICE usb_device,

        WDFCHILDLIST *list, WDF_CHILD_LIST_ITERATOR *iterator)

    {

        if (!drv_ctx.control_device_used)

            *list = WdfFdoGetDefaultChildList(usb_device);

        else

            *list = WdfFdoGetDefaultChildList(drv_ctx.control_device);

        WDF_CHILD_LIST_ITERATOR_INIT(iterator, WdfRetrievePresentChildren);

        WdfChildListBeginIteration(*list, iterator);

    }

    static NTSTATUS usb_child_retrieve_or_remove_next(WDFDEVICE *child,

        WDFCHILDLIST list, WDF_CHILD_LIST_ITERATOR *iterator,

        const usb_ident_desc_t *usb_ident_desc, BOOLEAN remove_ctrl_child)

    {

        NTSTATUS status;

        WDF_CHILD_RETRIEVE_INFO child_info;

        CDC_PDO_IDENTIFICATION_DESCRIPTION cdc_dev_desc;

        if (!drv_ctx.control_device_used)

        {

            status = WdfChildListRetrieveNextDevice(list, iterator, child, NULL);

            goto Exit;

        }

        WDF_CHILD_RETRIEVE_INFO_INIT(&child_info, &cdc_dev_desc.header);

        child_info.EvtChildListIdentificationDescriptionCompare =

            cdc_evt_id_compare;

        WDF_CHILD_IDENTIFICATION_DESCRIPTION_HEADER_INIT(&cdc_dev_desc.header,

            sizeof(cdc_dev_desc));

        RtlCopyMemory(&cdc_dev_desc.usb_ident_desc, usb_ident_desc,

            sizeof(usb_ident_desc_t));

        status = WdfChildListRetrieveNextDevice(list, iterator, child,

            &child_info);

        if (!NT_SUCCESS(status))

          {

            goto Exit;

          }

        ASSERT(child_info.Status == WdfChildListRetrieveDeviceSuccess);

        if (remove_ctrl_child)

        {

            status = WdfChildListUpdateChildDescriptionAsMissing(list,

                &cdc_dev_desc.header);

        }

    Exit:

        if (!NT_SUCCESS(status))

          {

            *child = NULL;

          }

        status = status == STATUS_NO_MORE_ENTRIES ? STATUS_SUCCESS : status;

        return status;

    }

    /**

     * Function name:  ctrl_add_usb_device

     * Description: Handle the newly plugged in USB device.

     *     Called by usb_evt_dev_prepare_hardware.

     * Parameters:

     *     @usb_device:

     *

     * Return value: NT status

     * Scope: global

     **/

    NTSTATUS ctrl_add_usb_device(WDFDEVICE usb_device)

    {

        NTSTATUS status;

        PDEVICE_CONTEXT usb_fdx;

        WDFDEVICE cdc_dev;

        CDC_DEVICE_CONTEXT *cdc_pdx;

        WDF_CHILD_LIST_ITERATOR iterator;

        WDFCHILDLIST list;

        ULONG count;

        DBG_V(("%s: entered, device %p\n", __FUNCTION__, usb_device));

        /* Add to the list of USB FDOs */

        WdfSpinLockAcquire(drv_ctx.usb_dev_spinlock);

        /* Sanity check: the new USB FDO should not be in the list */

        if (ctrl_find_usb_device(usb_device))

        {

            WdfSpinLockRelease(drv_ctx.usb_dev_spinlock);

            DBG_E(("%s: The USB FDO is already listed\n", __FUNCTION__));

            return STATUS_DEVICE_IS_LISTED;

        }

        /* Adding to collection also increments object's reference count */

        status = WdfCollectionAdd(drv_ctx.usb_dev_list, usb_device);

        if (!NT_SUCCESS(status))

        {

            WdfSpinLockRelease(drv_ctx.usb_dev_spinlock);

            DBG_E(("%s: Failed adding to collection\n", __FUNCTION__));

            return status;

        }

        if (!drv_ctx.control_device)

        {

            WdfSpinLockRelease(drv_ctx.usb_dev_spinlock);

            return STATUS_SUCCESS;

        }

        /* Check if a matching child exists */

        usb_fdx = usb_get_fdx(usb_device);

        usb_child_list_begin_iterator(usb_device, &list, &iterator);

        for (count = 0; ; count++)

        {

            status = usb_child_retrieve_next(&cdc_dev, list, &iterator,

                &usb_fdx->usb_ident_desc);

            if (!cdc_dev)

                {

              break;

                }

            /* Revive the matching child */

            cdc_pdx = cdc_get_pdx(cdc_dev);

            cdc_pdx->usb_device = usb_device;

        }

        usb_child_list_end_iterator(list, iterator);

        WdfSpinLockRelease(drv_ctx.usb_dev_spinlock);

        if (!count && NT_SUCCESS(status))

        {

            status = usb_children_enum(drv_ctx.control_device,

                &usb_fdx->usb_ident_desc, usb_fdx->num_of_multiplexed_comm,

                usb_fdx->ext_ctrl_enabled);

        }

        return status;

    }


    KAL

    Monday, September 24, 2012 5:50 PM
  • I'd check that your DBG_V or DBG_E macros are not doing anything clever like using UNICODE, and if not bring this to the attention of Microsoft.  As the dump warns the frames showing the DbgPrint as comming from wdftester!CvRegisterHookProvider could be wrong, but if not people like Doron from Microsoft should be able to check if this is a bug.


    Don Burn Windows Filesystem and Driver Consulting Website: http://www.windrvr.com Blog: http://msmvps.com/blogs/WinDrvr

    Monday, September 24, 2012 8:55 PM
  • looks like an issue in wdftester. if this is blocking certification, please ask for an errata.

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

    Monday, September 24, 2012 9:53 PM
  • Hi Kiet,

    This bug is fixed with the HCK 2.0 release. Can you please try running the same test with the latest kit release?

    Best,

    Neslihan

    Monday, September 24, 2012 10:38 PM
  • Hi Neslihan:

    This is the latest HCK which releases on 8/15/2012, at the below link:

    http://msdn.microsoft.com/en-US/windows/hardware/hh852359

    Is this 2.0 ? If not, where is it?

    thanks,

    Kiet


    KAL

    Monday, September 24, 2012 10:51 PM
  • Yes, this is HCK 2.0. Can you please run WDF FI test again and see if it reproes?

    Best,

    Neslihan

    Tuesday, September 25, 2012 8:09 PM
  • Neslihan:

    I did run with HCK 2.0 and the issue posted here is the result.

    Kiet


    KAL

    Tuesday, September 25, 2012 8:20 PM
  • Kiet, can you please share out the "!lmi wdftester" output? WdfChildListRetriveNextDevice doesn't call DbgPrint with UNICODE in HCK 2.0.

    Best,

    Neslihan

    Tuesday, September 25, 2012 9:20 PM

  • 1: kd> !lmi wdftester
    Loaded Module Info: [wdftester]
             Module: wdftester
       Base Address: 850b1000
         Image Name: wdftester.sys
       Machine Type: 332 (I386)
         Time Stamp: 5010ad02 Wed Jul 25 22:35:46 2012
               Size: 50000
           CheckSum: 570c0
    Characteristics: 102 
    Debug Data Dirs: Type  Size     VA  Pointer
                 CODEVIEW    26, 43880,   42880 RSDS - GUID: {89761A65-4BA9-4E83-81C7-124B36256213}
                   Age: 1, Pdb: wdftester.pdb
         Image Type: MEMORY   - Image read successfully from loaded memory.
        Symbol Type: EXPORT   - PDB not found
        Load Report: export symbols

    KAL

    Tuesday, September 25, 2012 10:01 PM
  • Wdftester version looks right.

    usb_child_retrieve_or_remove_next only calls 2 WDF DDIs; WdfChildListRetrieveNextDevice and

    WdfChildListUpdateChildDescriptionAsMissing, both of which are callable from DISPATCH_LEVEL and above, so wdftester doesn't call DbgPrint with UNICODE for these DDIs.

    Since WdfChildListRetrieveNextDevice is failed then usb_child_retrieve_or_remove_next should execute starting from the Exit label which doesn't actually call into WDF;

    usb_child_retrieve_or_remove_next:

    ...

        status = WdfChildListRetrieveNextDevice(list, iterator, child,

                                            &child_info);

        if (!NT_SUCCESS(status))

        {

            goto Exit;

        }

    ..

    Exit:

        if (!NT_SUCCESS(status))

        {

            *child = NULL;

        }

        status = status == STATUS_NO_MORE_ENTRIES ? STATUS_SUCCESS : status;

        return status;

    If a DDI is already failed then !analyze stack frame doesn't belong to that same DDI call. So I'm not sure via which DDI wdftester happens to call into DbgPrint. But the debug print call is coming from wdftester, I need to analyze the dump file with symbols to understand which DDI call is leading to this code path. It's also likely that a DDI which isn't callable from DISPATCH_LEVEL is called so with the spinlock held, for these DDIs wdftester actually calls DbgPrint with a UNICODE. In case it's a test bug you'll receive an errata. Could you please open a support case for this problem? I appreciate your collaboration and patience.

    HTH,

    Neslihan

    Tuesday, September 25, 2012 11:27 PM
  • I have already opened a support case for this.


    KAL

    • Marked as answer by Kiet Ly Friday, September 28, 2012 9:36 PM
    Wednesday, September 26, 2012 1:39 AM
  • One more thing:

    I run the same HCK test job, "Wdf Fault Injection", on Windows 8 and I do not have this issue. I only run the test once, I will try a few more to see

    if the result is consistent or not. It does look like the same wdftester.sys is used for both Windows 7 and Windows 8 run. Wdf01000.sys is newer on

    Windows 8 as compared to that on Windows 7

    Again, this is HCK RTM.

    Neslihan/Doron, can you comment?

    thanks,

    Kiet


    KAL

    Wednesday, October 3, 2012 6:01 PM