Prev: Virtual Printer
Next: troubles with Inf file
From: valouflo on 10 Sep 2009 05:12
Hi,
I work on a USB device developed with KMDF. This device was certified
with WLK 1.2.
A new functionality should be added but I encounter a problem with
pnpdtest delivered with WLK 1.4 (with QFE 002).
During surprise removal test, when device is restarting, PNPFILT
receives an error C000009C. There is no error in the driver, so I
think that it is the framework WDF that returns this error.
I tried to know if something in my driver was not freed but I found
nothing.

I would like to know what I should do to find where is the problem.

Following, you will find logs of WDF and PNPFILTR during the test. You
will also find the state of the driver when falling into surprise
removal call back and context cleanup call back.

Thanks in advance for your help

==================================================================================

LOGS in DBGVIEW:

==================================================================================
[1460] Start: Surprise Remove, TUID=
Wdf01000:
LibraryUnregisterClient: enter
Wdf01000:
LibraryUnregisterClient: exit: status 0
WdfLdr: ClientCleanupAndFree -
WdfLdr: LibraryReleaseClientReference -
WdfLdr: LibraryReleaseClientReference: Dereference module \Registry
\Machine\System\CurrentControlSet\Services\Wdf01000
Wdf01000:
LibraryDecommission: enter
Wdf01000:
LibraryDecommission: exit
WdfLdr: LibraryUnload -
WdfLdr: LibraryUnload: Unload module \Registry\Machine\System
\CurrentControlSet\Services\Wdf01000
Wdf01000:
DriverUnload
WdfLdr: WdfVersionUnbind -
WdfLdr: WdfVersionUnbind: exit: 0
WdfLdr: DllUnload -
WdfLdr: DllUnload: enter
WdfLdr: DllUnload -
WdfLdr: DllUnload: exit
WdfLdr: FxDllInitialize -
OsVersion(5.1)
WdfLdr: WdfVersionBind -
WdfLdr: WdfVersionBind: enter
WdfLdr: GetVersionRegistryHandle -
Component path \Registry\Machine\System\CurrentControlSet\Control\Wdf
\Kmdf\KmdfLibrary\Versions
WdfLdr: GetVersionServicePath -
GetVersionServicePath (\Registry\Machine\System\CurrentControlSet
\Services\Wdf01000)
WdfLdr: GetImageName -
Version Image Name "wdf01000.sys"
WdfLdr: WdfLdrDiagnosticsValueByNameAsULONG -
Value 0x1
WdfLdr: WdfLdrDiagnosticsValueByNameAsULONG -
Status 0x0
Wdf01000:
DriverEntry
WdfLdr: WdfRegisterLibrary -
Module(85C8ACE0)
Wdf01000:
LibraryCommission
Wdf01000:
OsVersion(5.1)
WdfLdr: GetImageName -
WdfLdr: LibraryLinkInClient -
Wdf01000:
LibraryRegisterClient: enter
Wdf01000:
LibraryRegisterClient: enter
Wdf01000:
LibraryRegisterClient: Enhanced Verification is ON
Wdf01000:
LibraryRegisterClient: WdfFunctions B94E22A8
Wdf01000:
LibraryRegisterClient: exit: status 0
WdfLdr: WdfVersionBind -
Returning with Status 0x0
PNPFILTR: Events being initialized
PNPFILTR: Received IRP_MN_QUERY_LEGACY_BUS_INFORMATION which I am
simply passing down
PNPFILTR: Received IRP_MN_QUERY_RESOURCE_REQUIREMENTS which I am
simply passing down
PNPFILTR: Received IRP_MN_FILTER_RESOURCE_REQUIREMENT for stack with
PDO 0x858BDDE8
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: FilterFilterResourceRequirement returning 0x00000000 for
stack with PDO 0x858BDDE8
PNPFILTR: Received IRP_MN_START_DEVICE for stack with PDO 0x858BDDE8
PNPFILTR: Received IRP_MN_QUERY_CAPABILITIES which I am simply
passing down
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: Time taken for IRP_MN_START_DEVICE to get processed for the
PDO 858BDDE8 is 968 miliseconds
PNPFILTR: Completing Start request with status == 0x00000000 PDO =
0x858BDDE8
PNPFILTR: Received IRP_MN_QUERY_CAPABILITIES which I am simply
passing down
PNPFILTR: Received IRP_MN_QUERY_PNP_DEVICE_STATE for stack with PDO
0x858BDDE8
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: Completing IRP_MN_QUERY_PNP_DEVICE_STATE for PDO 0x858BDDE8
with status 0x00000000 and information 0x00000000
PNPFILTR: Received IRP_MN_QUERY_DEVICE_RELATIONS which I am simply
passing down
PNPFILTR: Received IRP_MN_QUERY_DEVICE_RELATIONS which I am simply
passing down
[1460] Running Surprise Removal Test on node with hwid:
PNPFILTR: Received IOCTL_QUERY_DEVICE_COUNT
PNPFILTR: Received IOCTL_QUERY_HARDWARE_ID_SIZE for PDO 0x858BDDE8
PNPFILTR: Received IOCTL_QUERY_HARDWARE_ID for PDO 0x858BDDE8
PNPFILTR: Received IOCTL_SURPRISE_REMOVE_DEVICE for PDO 0x858BDDE8
PNPFILTR: Calling IoInvalidateDeviceState to start rebalance on PDO
858BDDE8
PNPFILTR: Received IRP_MN_QUERY_PNP_DEVICE_STATE for stack with PDO
0x858BDDE8
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: Completing IRP_MN_QUERY_PNP_DEVICE_STATE for PDO 0x858BDDE8
with status 0x00000000 and information 0x00000004
PNPFILTR: Received IRP_MN_QUERY_DEVICE_RELATIONS which I am simply
passing down
PNPFILTR: Received IRP_MN_SURPRISE_REMOVAL for stack with PDO
0x858BDDE8
PNPFILTR: FilterSurpriseRemove returning 0x00000103 for stack with PDO
0x858BDDE8
[1460] USB\Vid_1a44&Pid_0114&Rev_0101
PNPFILTR: Recieved Query Result
PNPFILTR: Waiting for test to be completed - will wait for 50 seconds
PNPFILTR: Received IRP_MN_REMOVE_DEVICE for stack with PDO 0x858BDDE8
PNPFILTR: Setting the test completed event
PNPFILTR: Waiting for result to be stored
PNPFILTR: Query Result Wait Satisfied... 4
PNPFILTR: Number of IRPs Stored... 4
PNPFILTR: Query Result - Releasing the remove
PNPFILTR: Remove Wait completed... now deleting
PNPFILTR: List has 0 entries
PNPFILTR: Processed 0 IRPs
PNPFILTR: Query Result -Result Stored Event set
PNPFILTR: Deleting the global control object
PNPFILTR: FilterRemove returning 0x00000000 for stack with PDO
0x858BDDE8
Wdf01000:
LibraryUnregisterClient: enter
Wdf01000:
LibraryUnregisterClient: exit: status 0
WdfLdr: ClientCleanupAndFree -
WdfLdr: LibraryReleaseClientReference -
WdfLdr: LibraryReleaseClientReference: Dereference module \Registry
\Machine\System\CurrentControlSet\Services\Wdf01000
Wdf01000:
LibraryDecommission: enter
Wdf01000:
LibraryDecommission: exit
WdfLdr: LibraryUnload -
WdfLdr: LibraryUnload: Unload module \Registry\Machine\System
\CurrentControlSet\Services\Wdf01000
Wdf01000:
DriverUnload
WdfLdr: WdfVersionUnbind -
WdfLdr: WdfVersionUnbind: exit: 0
WdfLdr: DllUnload -
WdfLdr: DllUnload: enter
WdfLdr: DllUnload -
WdfLdr: DllUnload: exit
[1460] Relevant Sequence of Irps:
[1460] IRP_MN_QUERY_PNP_DEVICE_STATE
[1460] IRP_MN_QUERY_DEVICE_RELATIONS
[1460] IRP_MN_SURPRISE_REMOVAL
[1460] IRP_MN_REMOVE_DEVICE
WdfLdr: FxDllInitialize -
OsVersion(5.1)
WdfLdr: WdfVersionBind -
WdfLdr: WdfVersionBind: enter
WdfLdr: GetVersionRegistryHandle -
Component path \Registry\Machine\System\CurrentControlSet\Control\Wdf
\Kmdf\KmdfLibrary\Versions
WdfLdr: GetVersionServicePath -
GetVersionServicePath (\Registry\Machine\System\CurrentControlSet
\Services\Wdf01000)
WdfLdr: GetImageName -
Version Image Name "wdf01000.sys"
WdfLdr: WdfLdrDiagnosticsValueByNameAsULONG -
Value 0x1
WdfLdr: WdfLdrDiagnosticsValueByNameAsULONG -
Status 0x0
Wdf01000:
DriverEntry
WdfLdr: WdfRegisterLibrary -
Module(85C8ACE0)
Wdf01000:
LibraryCommission
Wdf01000:
OsVersion(5.1)
WdfLdr: GetImageName -
WdfLdr: LibraryLinkInClient -
Wdf01000:
LibraryRegisterClient: enter
Wdf01000:
LibraryRegisterClient: enter
Wdf01000:
LibraryRegisterClient: Enhanced Verification is ON
Wdf01000:
LibraryRegisterClient: WdfFunctions F40D62A8
Wdf01000:
LibraryRegisterClient: exit: status 0
WdfLdr: WdfVersionBind -
Returning with Status 0x0
PNPFILTR: Events being initialized
PNPFILTR: Received IRP_MN_QUERY_LEGACY_BUS_INFORMATION which I am
simply passing down
PNPFILTR: Received IRP_MN_QUERY_RESOURCE_REQUIREMENTS which I am
simply passing down
PNPFILTR: Received IRP_MN_FILTER_RESOURCE_REQUIREMENT for stack with
PDO 0x858BDDE8
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: FilterFilterResourceRequirement returning 0x00000000 for
stack with PDO 0x858BDDE8
PNPFILTR: Received IRP_MN_START_DEVICE for stack with PDO 0x858BDDE8
PNPFILTR: FilterCompletionRoutine Completed, event set.
PNPFILTR: Time taken for IRP_MN_START_DEVICE to get processed for the
PDO 858BDDE8 is 3296 miliseconds
PNPFILTR: Completing Start request with status == 0xC000009C PDO =
0x858BDDE8
PNPFILTR: Received IRP_MN_REMOVE_DEVICE for stack with PDO 0x858BDDE8
PNPFILTR: List has 0 entries
PNPFILTR: Processed 0 IRPs
PNPFILTR: Deleting the global control object
PNPFILTR: FilterRemove returning 0x00000000 for stack with PDO
0x858BDDE8
Wdf01000:
LibraryUnregisterClient: enter
Wdf01000:
LibraryUnregisterClient: exit: status 0
WdfLdr: ClientCleanupAndFree -
WdfLdr: LibraryReleaseClientReference -
WdfLdr: LibraryReleaseClientReference: Dereference module \Registry
\Machine\System\CurrentControlSet\Services\Wdf01000
Wdf01000:
LibraryDecommission: enter
Wdf01000:
LibraryDecommission: exit
WdfLdr: LibraryUnload -
WdfLdr: LibraryUnload: Unload module \Registry\Machine\System
\CurrentControlSet\Services\Wdf01000
Wdf01000:
DriverUnload
WdfLdr: WdfVersionUnbind -
WdfLdr: WdfVersionUnbind: exit: 0
WdfLdr: DllUnload -
WdfLdr: DllUnload: enter
WdfLdr: DllUnload -
WdfLdr: DllUnload: exit
[1460] Assert: Device node status not ok: problem code 10
[1460] File=e:\wlk14qfe\se_enlistment\base\pnp\tools\pnpd2\user
\pnpdtest.cpp, Line=288
[748] CDisplayGatherer::XmlData: Calling Get XML Data
[748] DisplayGetData: Wrote XML
[748] CDisplayGatherer::XmlData: DisplayGetData(ex) succeeded
[1460] Filter driver removed - Test finished
[1460]
[1460]
[1460] End: Fail, Surprise Remove, TUID=, Repro=Surprise Remove the
device
[1460]
[748] CDisplayGatherer::XmlData: Calling Get XML Data
[748] DisplayGetData: Wrote XML
[748] CDisplayGatherer::XmlData: DisplayGetData(ex) succeeded
[748] CDisplayGatherer::XmlData: Calling Get XML Data
[748] DisplayGetData: Wrote XML
[748] CDisplayGatherer::XmlData: DisplayGetData(ex) succeeded


==================================================================================

WINDBG in EvtDeviceSurpriseRemoval

==================================================================================

kd> !wdfdriverinfo usbocs3 0xfff
----------------------------------
warning: symbols for usbocs3 not found
Default driver image name: usbocs3
WDF library image name:
FxDriverGlobals 0x861f6af8
WdfBindInfo 0xb94e2130
Version v1.9 build(7600)
----------------------------------
Driver Handles:
dt FxDriver 0x860FEAC8 : !WDFDRIVER 0x79f01530
dt FxDevice 0x858CD3C0 : !WDFDEVICE 0x7a732c38 Context
858cd588 Cleanup b94dfd70, Context 858d1768
dt FxDefaultIrpHandler 0x8607BFC8: WDF INTERNAL
dt FxPkgGeneral 0x85C9E4A0 : WDF INTERNAL
dt FxWmiIrpHandler 0x85D51218 : WDF INTERNAL
dt FxPkgIo 0x85FE9010 : WDF INTERNAL
dt FxPkgFdo 0x858F7338 : WDF INTERNAL
dt FxCmResList 0x858E10C0 : !WDFCMRESLIST 0x7a71ef38
dt FxCmResList 0x86022690 : !WDFCMRESLIST 0x79fdd968
dt FxChildList 0x861157D0 : !WDFCHILDLIST 0x79eea828
dt FxIoTarget 0x85C77D80 : !WDFIOTARGET 0x7a388278
dt FxUsbDevice 0x858F0D58 : !WDFUSBDEVICE 0x7a70f2a0
dt FxUsbInterface 0x85F161B0 : !WDFUSBINTERFACE
0x7a0e9e48
dt FxObject 0x85CD2C30 : !WDFMEMORY 0x7a32d3c8
----------------------------------
Dump leaked handles: the driver is not tracking handles
----------------------------------

WDF Verifier settings for usbocs3.sys is OFF
----------------------------------
kd> !wdfdevice 0x7a732c38 0xf

Dumping WDFDEVICE 0x7a732c38
=================================

WDM PDEVICE_OBJECTs:self 85cf28e0, attached 858bdde8, pdo 858bdde8

Pnp state: 127 ( WdfDevStatePnpSurpriseRemoveIoStarted )
Power state: 307 ( WdfDevStatePowerD0 )
Power Pol state: 565 ( WdfDevStatePwrPolStarted )

Default WDFIOTARGET: 7a388278

Pended pnp(IRP_MN_SURPRISE_REMOVAL) irp 0x85bf3008
Device is the power policy owner for the stack

owning thread: 861ed640
Pnp state history:
[0] WdfDevStatePnpObjectCreated (0x100)
[1] WdfDevStatePnpInit (0x105)
[2] WdfDevStatePnpInitStarting (0x106)
[3] WdfDevStatePnpHardwareAvailable (0x108)
[4] WdfDevStatePnpEnableInterfaces (0x109)
[5] WdfDevStatePnpStarted (0x119)
[6] WdfDevStatePnpSurpriseRemoveIoStarted (0x127)

Power state history:
[0] WdfDevStatePowerObjectCreated (0x300)
[1] WdfDevStatePowerStartingCheckDeviceType (0x316)
[2] WdfDevStatePowerD0Starting (0x30f)
[3] WdfDevStatePowerD0StartingConnectInterrupt (0x310)
[4] WdfDevStatePowerD0StartingDmaEnable (0x311)
[5] WdfDevStatePowerD0StartingStartSelfManagedIo (0x312)
[6] WdfDevStatePowerDecideD0State (0x313)
[7] WdfDevStatePowerD0 (0x307)

Power policy state history:
[0] WdfDevStatePwrPolObjectCreated (0x500)
[1] WdfDevStatePwrPolStarting (0x501)
[2] WdfDevStatePwrPolStartingSucceeded (0x502)
[3] WdfDevStatePwrPolStartingDecideS0Wake (0x504)
[4] WdfDevStatePwrPolStarted (0x565)

WDFCHILDLIST Handles:
!WDFCHILDLIST 0x79eea828 (static PDO list)

Properties:
SynchronizationScope: WdfSynchronizationScopeDevice
ExecutionLevel: WdfExecutionLevelPassive
IoType: WdfDeviceIoBuffered
FileObjectClass: 1 ( WdfFileObjectNotRequired )
Exclusive: Yes
AutoForwardCleanupClose: No
DefaultPriorityBoost: 0


==================================================================================

WINDBG in EvtCleanupCallback

==================================================================================
kd> !wdfdriverinfo usbocs3 0xfff
----------------------------------
warning: symbols for usbocs3 not found
Default driver image name: usbocs3
WDF library image name:
FxDriverGlobals 0x861f6af8
WdfBindInfo 0xb94e2130
Version v1.9 build(7600)
----------------------------------
Driver Handles:
dt FxDriver 0x860FEAC8 : !WDFDRIVER 0x79f01530
----------------------------------
Dump leaked handles: the driver is not tracking handles
----------------------------------

WDF Verifier settings for usbocs3.sys is OFF
----------------------------------
kd> !wdfdevice 0x7a732c38 0xf

Dumping WDFDEVICE 0x7a732c38
=================================

WDM PDEVICE_OBJECTs:self 85cf28e0, attached 858bdde8, pdo 858bdde8

Pnp state: 124 ( WdfDevStatePnpFdoRemoved )
Power state: 315 ( WdfDevStatePowerStopped )
Power Pol state: 563 ( WdfDevStatePwrPolStopped )

Default WDFIOTARGET: 7a388278

No pended pnp or power irps
Device is the power policy owner for the stack

owning thread: 861ed640
Pnp state history:
[0] WdfDevStatePnpSurpriseRemoveIoStarted (0x127)
[1] WdfDevStatePnpFailedIoStarting (0x129)
[2] WdfDevStatePnpFailedOwnHardware (0x12a)
[3] WdfDevStatePnpFailed (0x12b)
[4] WdfDevStatePnpFailedWaitForRemove (0x12e)
[5] WdfDevStatePnpRemoved (0x113)
[6] WdfDevStatePnpRemovedChildrenRemoved (0x136)
[7] WdfDevStatePnpFdoRemoved (0x124)

Power state history:
[0] WdfDevStatePowerD0Starting (0x30f)
[1] WdfDevStatePowerD0StartingConnectInterrupt (0x310)
[2] WdfDevStatePowerD0StartingDmaEnable (0x311)
[3] WdfDevStatePowerD0StartingStartSelfManagedIo (0x312)
[4] WdfDevStatePowerDecideD0State (0x313)
[5] WdfDevStatePowerD0 (0x307)
[6] WdfDevStatePowerGotoD3Stopped (0x314)
[7] WdfDevStatePowerStopped (0x315)

Power policy state history:
[0] WdfDevStatePwrPolObjectCreated (0x500)
[1] WdfDevStatePwrPolStarting (0x501)
[2] WdfDevStatePwrPolStartingSucceeded (0x502)
[3] WdfDevStatePwrPolStartingDecideS0Wake (0x504)
[4] WdfDevStatePwrPolStarted (0x565)
[5] WdfDevStatePwrPolStopping (0x55b)
[6] WdfDevStatePwrPolStoppingSendStatus (0x55d)
[7] WdfDevStatePwrPolStopped (0x563)

WDFCHILDLIST Handles:
No handles.

Properties:
SynchronizationScope: WdfSynchronizationScopeDevice
ExecutionLevel: WdfExecutionLevelPassive
IoType: WdfDeviceIoBuffered
FileObjectClass: 1 ( WdfFileObjectNotRequired )
Exclusive: Yes
AutoForwardCleanupClose: No
DefaultPriorityBoost: 0
From: valouflo on 17 Sep 2009 04:32
I found where is the problem.
I thought that the problem was in the driver but in fact the problem
was in the device.
The device didn't respond to get descriptor request if it wasn't
powered off. I think in this test, the surprise removal is only
simulated. So when the get descriptor request is sent after the
surprise removal, the device blocks it. this explained why the
framework KMDF returned an error.
That I don't know, it is if there are modifications in the surprise
removal test between WLK 1.2 (that i used until now) and WLK 1.4.
 | 
Pages: 1
Prev: Virtual Printer
Next: troubles with Inf file