Multiple IRP Completion Bug Check because of usbccgp.sys on Windows XP

Hi Everyone,

My USB virtual bus driver is hitting a blue screen (MULTIPLE_IRP_COMPLETE_REQUESTS)
and I need you guys, the driver experts to help me.

Some info:

The bus driver enumerates the usb devices and communicates to the real usb device over the network. For every URB my driver receives, it marks it as pending and forwards the request over the network and completes it on receiving response.

I investigated this issue and found that the blue screen is caused by usbccgp cancelling the URB that is marked as pending by my virtual bus driver. So my drivers cancellation Routine that was set via IoSetCancelRoutine() is called which does WdfCompleteRequest() resulting into calling of the usbccgp’s completion routine. After the IoCancelIrp call return, usbccgp does IoCompleteRequest() [please see CallDriverSync function below].Now the call returns back to sumbiturb() where IoFreeIrp is done resulting into completion of the same IRP twice.

*NOTE THAT THIS OCCURS ONLY ON XP*

Here is crash dump analysis:

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

MULTIPLE_IRP_COMPLETE_REQUESTS (44)
A driver has requested that an IRP be completed (IoCompleteRequest()), but
the packet has already been completed. This is a tough bug to find because
the easiest case, a driver actually attempted to complete its own packet
twice, is generally not what happened. Rather, two separate drivers each
believe that they own the packet, and each attempts to complete it. The
first actually works, and the second fails. Tracking down which drivers
in the system actually did this is difficult, generally because the trails
of the first driver have been covered by the second. However, the driver
stack for the current request can be found by examining the DeviceObject
fields in each of the stack locations.
Arguments:
Arg1: 85962528, Address of the IRP
Arg2: 00001bc0
Arg3: 00000000
Arg4: 00000000

Debugging Details:

*** No owner thread found for resource 80559260
*** No owner thread found for resource 80559260
*** No owner thread found for resource 80559260
*** No owner thread found for resource 80559260

IRP_ADDRESS: 85962528

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x44

PROCESS_NAME: System

LOCK_ADDRESS: 805592e0 – (!locks 805592e0)

Resource @ nt!IopDeviceTreeLock (0x805592e0) Shared 1 owning threads
Threads: 863c48b8-01<*>
1 total locks, 1 locks currently held

PNP_TRIAGE:
Lock address : 0x805592e0
Thread Count : 1
Thread address: 0x863c48b8
Thread wait : 0x26f5c

LAST_CONTROL_TRANSFER: from 8051be4f to 80533846

STACK_TEXT:
f79527c0 8051be4f 00000044 85962528 00001bc0 nt!KeBugCheckEx+0x1b
f79527e8 f78bb80e 85962528 00000001 859625bc nt!IopFreeIrp+0xe9
f7952804 f78bda76 8624cda0 85ebfbb0 00000001 usbccgp!SubmitUrb+0x6e
f795285c f78bd2bd 85ba4c60 85ff13e0 804ec8b1 usbccgp!UrbFunctionSelectConfiguration+0x206
f7952894 f78bb786 85ba4c60 85958348 85ba4c60 usbccgp!FunctionInternalDeviceControl+0xed
f79528b8 f78bb5d3 85ba4c58 85958348 0000000f usbccgp!USBC_InternalDeviceControl+0x56
f79528f4 804e3807 85ba4ba0 85958348 85940cd8 usbccgp!USBC_Dispatch+0x183
f7952904 f450f3b0 00000000 859acf38 85a3a728 nt!IopfCallDriver+0x31
WARNING: Stack unwind information not available. Following frames may be wrong.
f795291c 804e3807 85ff13e0 85958348 85958348 nx6000+0x13b0
f795292c f3be43d8 85a3a728 85ff13e0 00000002 nt!IopfCallDriver+0x31
f7952960 f3be4470 85940cd8 85ff13e0 00000000 usbvideo!USBVideoCallUSBD+0x82
f7952978 f3be47a7 85940cd8 85ff13e0 85a66110 usbvideo!SubmitUrbToUsbdSynch+0x14
f79529a8 f3be4b8b 85a66110 86039cc0 00000000 usbvideo!SelectDeviceConfiguration+0x271
f79529d0 f3be40e9 00000000 85a66110 85a660a8 usbvideo!StartUSBVideoDevice+0x22b
f79529e8 f6171804 85a66110 861f6a70 00000000 usbvideo!USBVideoPnpStart+0x47
f7952a10 f616dd87 861f6a70 861f6bb8 85c134d8 ks!CKsDevice::PnpStart+0x3d
f7952a28 804e3807 859848d8 861f6a70 f7952aa4 ks!CKsDevice::DispatchPnp+0x1b3
f7952a38 8058a9f9 f7952aa4 85ba4ba0 00000000 nt!IopfCallDriver+0x31
f7952a64 805b6595 859848d8 f7952a80 00000000 nt!IopSynchronousCall+0xb7
f7952aa8 80509678 85ba4ba0 85a0dee8 00000001 nt!IopStartDevice+0x4d
f7952ac4 805b6431 85ba4ba0 85ba4b01 85a0dee8 nt!PipProcessStartPhase1+0x4e
f7952d1c 8061c247 85f7c458 00000001 00000000 nt!PipProcessDevNodeTree+0x1db
f7952d4c 8050634f 00000003 80559340 8056237c nt!PiRestartDevice+0x80
f7952d74 804e427b 00000000 00000000 863c48b8 nt!PipDeviceActionWorker+0x15e
f7952dac 80579453 00000000 00000000 00000000 nt!ExpWorkerThread+0x100
f7952ddc 804f88fa 804e41a6 00000001 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
nx6000+13b0
f450f3b0 6a18 push 18h

SYMBOL_STACK_INDEX: 8

SYMBOL_NAME: nx6000+13b0

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: nx6000

IMAGE_NAME: nx6000.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4cf81c67

FAILURE_BUCKET_ID: 0x44_nx6000+13b0

BUCKET_ID: 0x44_nx6000+13b0

Followup: MachineOwner

Below is the assembly of Usbccgp!CallDriverSync in
Windows XP:

usbccgp!CallDriverSync:
00016600 8bff mov edi,edi
00016602 55 push ebp
00016603 8bec mov ebp,esp
00016605 83ec34 sub esp,34h
00016608 8b450c mov eax,dword ptr [ebp+0Ch]
0001660b 8b4860 mov ecx,dword ptr [eax+60h]
0001660e 83e924 sub ecx,24h
00016611 894dec mov dword ptr [ebp-14h],ecx
00016614 8b55ec mov edx,dword ptr [ebp-14h]
00016617 0fb602 movzx eax,byte ptr [edx]
0001661a 8945d0 mov dword ptr [ebp-30h],eax
0001661d 8b4dec mov ecx,dword ptr [ebp-14h]
00016620 0fb65101 movzx edx,byte ptr [ecx+1]
00016624 8955e8 mov dword ptr [ebp-18h],edx
00016627 6a00 push 0
00016629 6a00 push 0
0001662b 8d45d4 lea eax,[ebp-2Ch]
0001662e 50 push eax
0001662f ff15943d0100 call dword ptr [usbccgp!_imp__KeInitializeEvent (00013d94)]
00016635 c745f400000000 mov dword ptr [ebp-0Ch],0
0001663c 6855736243 push 43627355h
00016641 6a08 push 8
00016643 6a00 push 0
00016645 ff15a03d0100 call dword ptr [usbccgp!_imp__ExAllocatePoolWithTag (00013da0)]
0001664b 8945f0 mov dword ptr [ebp-10h],eax
0001664e 837df000 cmp dword ptr [ebp-10h],0
00016652 0f8446010000 je usbccgp!CallDriverSync+0x19e (0001679e)

usbccgp!CallDriverSync+0x58:
00016658 8b4df0 mov ecx,dword ptr [ebp-10h]
0001665b 8d55d4 lea edx,[ebp-2Ch]
0001665e 8911 mov dword ptr [ecx],edx
00016660 8b45f0 mov eax,dword ptr [ebp-10h]
00016663 8d4df4 lea ecx,[ebp-0Ch]
00016666 894804 mov dword ptr [eax+4],ecx
00016669 8b550c mov edx,dword ptr [ebp+0Ch]
0001666c 8b4260 mov eax,dword ptr [edx+60h]
0001666f 83e824 sub eax,24h
00016672 8945cc mov dword ptr [ebp-34h],eax
00016675 8b4dcc mov ecx,dword ptr [ebp-34h]
00016678 c7411c302f0100 mov dword ptr [ecx+1Ch],offset usbccgp!CallDriverSyncCompletion (00012f30)
0001667f 8b55cc mov edx,dword ptr [ebp-34h]
00016682 8b45f0 mov eax,dword ptr [ebp-10h]
00016685 894220 mov dword ptr [edx+20h],eax
00016688 8b4dcc mov ecx,dword ptr [ebp-34h]
0001668b c6410300 mov byte ptr [ecx+3],0
0001668f ba01000000 mov edx,1
00016694 85d2 test edx,edx
00016696 7407 je usbccgp!CallDriverSync+0x9f (0001669f)

usbccgp!CallDriverSync+0x98:
00016698 8b45cc mov eax,dword ptr [ebp-34h]
0001669b c6400340 mov byte ptr [eax+3],40h

usbccgp!CallDriverSync+0x9f:
0001669f b901000000 mov ecx,1
000166a4 85c9 test ecx,ecx
000166a6 7412 je usbccgp!CallDriverSync+0xba (000166ba)

usbccgp!CallDriverSync+0xa8:
000166a8 8b55cc mov edx,dword ptr [ebp-34h]
000166ab 0fb64203 movzx eax,byte ptr [edx+3]
000166af 0d80000000 or eax,80h
000166b4 8b4dcc mov ecx,dword ptr [ebp-34h]
000166b7 884103 mov byte ptr [ecx+3],al

usbccgp!CallDriverSync+0xba:
000166ba ba01000000 mov edx,1
000166bf 85d2 test edx,edx
000166c1 7410 je usbccgp!CallDriverSync+0xd3 (000166d3)

usbccgp!CallDriverSync+0xc3:
000166c3 8b45cc mov eax,dword ptr [ebp-34h]
000166c6 0fb64803 movzx ecx,byte ptr [eax+3]
000166ca 83c920 or ecx,20h
000166cd 8b55cc mov edx,dword ptr [ebp-34h]
000166d0 884a03 mov byte ptr [edx+3],cl

usbccgp!CallDriverSync+0xd3:
000166d3 8b550c mov edx,dword ptr [ebp+0Ch]
000166d6 8b4d08 mov ecx,dword ptr [ebp+8]
000166d9 ff15a43d0100 call dword ptr [usbccgp!_imp_IofCallDriver (00013da4)]
000166df 8945e4 mov dword ptr [ebp-1Ch],eax
000166e2 817de403010000 cmp dword ptr [ebp-1Ch],103h
000166e9 0f859a000000 jne usbccgp!CallDriverSync+0x189 (00016789)

usbccgp!CallDriverSync+0xef:
000166ef c745f8800f05fd mov dword ptr [ebp-8],0FD050F80h
000166f6 c745fcffffffff mov dword ptr [ebp-4],0FFFFFFFFh
000166fd 8d45f8 lea eax,[ebp-8]
00016700 50 push eax
00016701 6a00 push 0
00016703 6a00 push 0
00016705 6a00 push 0
00016707 8d4dd4 lea ecx,[ebp-2Ch]
0001670a 51 push ecx
0001670b ff15b83d0100 call dword ptr [usbccgp!_imp__KeWaitForSingleObject (00013db8)]
00016711 8945e4 mov dword ptr [ebp-1Ch],eax
00016714 817de402010000 cmp dword ptr [ebp-1Ch],102h
0001671b 756c jne usbccgp!CallDriverSync+0x189 (00016789)

usbccgp!CallDriverSync+0x11d:
0001671d ba01000000 mov edx,1
00016722 8d4df4 lea ecx,[ebp-0Ch]
00016725 ff15e83d0100 call dword ptr [usbccgp!_imp_InterlockedExchange (00013de8)]
0001672b 85c0 test eax,eax
0001672d 753e jne usbccgp!CallDriverSync+0x16d (0001676d)

usbccgp!CallDriverSync+0x12f:
0001672f 8b550c mov edx,dword ptr [ebp+0Ch]
00016732 52 push edx
00016733 ff15d83d0100 call dword ptr [usbccgp!_imp__IoCancelIrp (00013dd8)]
00016739 ba02000000 mov edx,2
0001673e 8d4df4 lea ecx,[ebp-0Ch]
00016741 ff15e83d0100 call dword ptr [usbccgp!_imp_InterlockedExchange (00013de8)]
00016747 83f803 cmp eax,3
0001674a 7521 jne usbccgp!CallDriverSync+0x16d (0001676d)

usbccgp!CallDriverSync+0x14c:
0001674c 8b450c mov eax,dword ptr [ebp+0Ch]
0001674f 8b4860 mov ecx,dword ptr [eax+60h]
00016752 0fb65103 movzx edx,byte ptr [ecx+3]
00016756 83ca01 or edx,1
00016759 8b450c mov eax,dword ptr [ebp+0Ch]
0001675c 8b4860 mov ecx,dword ptr [eax+60h]
0001675f 885103 mov byte ptr [ecx+3],dl
00016762 32d2 xor dl,dl
00016764 8b4d0c mov ecx,dword ptr [ebp+0Ch]
00016767 ff15a83d0100 call dword ptr [usbccgp!_imp_IofCompleteRequest (00013da8)] <------------ We are using IoAllocateIRP to create an IRP. Is this valid?

usbccgp!CallDriverSync+0x16d:
0001676d 6a00 push 0
0001676f 6a00 push 0
00016771 6a00 push 0
00016773 6a00 push 0
00016775 8d55d4 lea edx,[ebp-2Ch]
00016778 52 push edx
00016779 ff15b83d0100 call dword ptr [usbccgp!_imp__KeWaitForSingleObject (00013db8)]
0001677f 8b450c mov eax,dword ptr [ebp+0Ch]
00016782 c740189c0000c0 mov dword ptr [eax+18h],0C000009Ch

usbccgp!CallDriverSync+0x189:
00016789 8b4df0 mov ecx,dword ptr [ebp-10h]
0001678c 51 push ecx
0001678d ff15c03d0100 call dword ptr [usbccgp!_imp__ExFreePool (00013dc0)]
00016793 8b550c mov edx,dword ptr [ebp+0Ch]
00016796 8b4218 mov eax,dword ptr [edx+18h]
00016799 8945e4 mov dword ptr [ebp-1Ch],eax
0001679c eb07 jmp usbccgp!CallDriverSync+0x1a5 (000167a5)

usbccgp!CallDriverSync+0x19e:
0001679e c745e49a0000c0 mov dword ptr [ebp-1Ch],0C000009Ah

usbccgp!CallDriverSync+0x1a5:
000167a5 8b45e4 mov eax,dword ptr [ebp-1Ch]
000167a8 8be5 mov esp,ebp
000167aa 5d pop ebp
000167ab c20800 ret 8


Below is the assembly of SubmitUrb of usbccgp in Windows XP
usbccgp!SubmitUrb:
000107a0 8bff mov edi,edi
000107a2 55 push ebp
000107a3 8bec mov ebp,esp
000107a5 83ec10 sub esp,10h
000107a8 6a00 push 0
000107aa 8b4508 mov eax,dword ptr [ebp+8]
000107ad 8b4810 mov ecx,dword ptr [eax+10h]
000107b0 8a5130 mov dl,byte ptr [ecx+30h]
000107b3 52 push edx
000107b4 ff15b43d0100 call dword ptr [usbccgp!_imp__IoAllocateIrp (00013db4)]
000107ba 8945fc mov dword ptr [ebp-4],eax
000107bd 837dfc00 cmp dword ptr [ebp-4],0
000107c1 0f84d2000000 je usbccgp!SubmitUrb+0xf9 (00010899)

usbccgp!SubmitUrb+0x27:
000107c7 8b45fc mov eax,dword ptr [ebp-4]
000107ca 8b4860 mov ecx,dword ptr [eax+60h]
000107cd 83e924 sub ecx,24h
000107d0 894df4 mov dword ptr [ebp-0Ch],ecx
000107d3 8b55f4 mov edx,dword ptr [ebp-0Ch]
000107d6 c6020f mov byte ptr [edx],0Fh
000107d9 8b45f4 mov eax,dword ptr [ebp-0Ch]
000107dc c7400c03002200 mov dword ptr [eax+0Ch],220003h
000107e3 8b4df4 mov ecx,dword ptr [ebp-0Ch]
000107e6 8b550c mov edx,dword ptr [ebp+0Ch]
000107e9 895104 mov dword ptr [ecx+4],edx
000107ec 0fb64510 movzx eax,byte ptr [ebp+10h]
000107f0 85c0 test eax,eax
000107f2 741f je usbccgp!SubmitUrb+0x73 (00010813)

usbccgp!SubmitUrb+0x54:
000107f4 8b4dfc mov ecx,dword ptr [ebp-4]
000107f7 51 push ecx
000107f8 8b5508 mov edx,dword ptr [ebp+8]
000107fb 52 push edx
000107fc e8bf5d0000 call usbccgp!CallNextDriverSync (000165c0)
00010801 8945f8 mov dword ptr [ebp-8],eax
00010804 8b45fc mov eax,dword ptr [ebp-4]
00010807 50 push eax
00010808 ff15b03d0100 call dword ptr [usbccgp!_imp__IoFreeIrp (00013db0)] <-------------------- 2nd IRP Free Happening here. Resulting in Blue Screen
0001080e e984000000 jmp usbccgp!SubmitUrb+0xf7 (00010897)

usbccgp!SubmitUrb+0x73:
00010813 8b4dfc mov ecx,dword ptr [ebp-4]
00010816 8b5160 mov edx,dword ptr [ecx+60h]
00010819 83ea24 sub edx,24h
0001081c 8955f0 mov dword ptr [ebp-10h],edx
0001081f 8b45f0 mov eax,dword ptr [ebp-10h]
00010822 8b4d14 mov ecx,dword ptr [ebp+14h]
00010825 89481c mov dword ptr [eax+1Ch],ecx
00010828 8b55f0 mov edx,dword ptr [ebp-10h]
0001082b 8b4518 mov eax,dword ptr [ebp+18h]
0001082e 894220 mov dword ptr [edx+20h],eax
00010831 8b4df0 mov ecx,dword ptr [ebp-10h]
00010834 c6410300 mov byte ptr [ecx+3],0
00010838 ba01000000 mov edx,1
0001083d 85d2 test edx,edx
0001083f 7407 je usbccgp!SubmitUrb+0xa8 (00010848)

usbccgp!SubmitUrb+0xa1:
00010841 8b45f0 mov eax,dword ptr [ebp-10h]
00010844 c6400340 mov byte ptr [eax+3],40h

usbccgp!SubmitUrb+0xa8:
00010848 b901000000 mov ecx,1
0001084d 85c9 test ecx,ecx
0001084f 7412 je usbccgp!SubmitUrb+0xc3 (00010863)

usbccgp!SubmitUrb+0xb1:
00010851 8b55f0 mov edx,dword ptr [ebp-10h]
00010854 0fb64203 movzx eax,byte ptr [edx+3]
00010858 0d80000000 or eax,80h
0001085d 8b4df0 mov ecx,dword ptr [ebp-10h]
00010860 884103 mov byte ptr [ecx+3],al

usbccgp!SubmitUrb+0xc3:
00010863 ba01000000 mov edx,1
00010868 85d2 test edx,edx
0001086a 7410 je usbccgp!SubmitUrb+0xdc (0001087c)

usbccgp!SubmitUrb+0xcc:
0001086c 8b45f0 mov eax,dword ptr [ebp-10h]
0001086f 0fb64803 movzx ecx,byte ptr [eax+3]
00010873 83c920 or ecx,20h
00010876 8b55f0 mov edx,dword ptr [ebp-10h]
00010879 884a03 mov byte ptr [edx+3],cl

usbccgp!SubmitUrb+0xdc:
0001087c 8b4508 mov eax,dword ptr [ebp+8]
0001087f 50 push eax
00010880 e84b260000 call usbccgp!IncrementPendingActionCount (00012ed0)
00010885 8b55fc mov edx,dword ptr [ebp-4]
00010888 8b4d08 mov ecx,dword ptr [ebp+8]
0001088b 8b4910 mov ecx,dword ptr [ecx+10h]
0001088e ff15a43d0100 call dword ptr [usbccgp!_imp_IofCallDriver (00013da4)]
00010894 8945f8 mov dword ptr [ebp-8],eax

usbccgp!SubmitUrb+0xf7:
00010897 eb07 jmp usbccgp!SubmitUrb+0x100 (000108a0)

usbccgp!SubmitUrb+0xf9:
00010899 c745f89a0000c0 mov dword ptr [ebp-8],0C000009Ah

usbccgp!SubmitUrb+0x100:
000108a0 8b45f8 mov eax,dword ptr [ebp-8]
000108a3 8be5 mov esp,ebp
000108a5 5d pop ebp
000108a6 c21400 ret 14h


This issue is not seen in Windows 7.
Below is the assembly of CallDriverSync on Windows 7:

usbccgp!CallDriverSync:
0002269a 8bff mov edi,edi
0002269c 55 push ebp
0002269d 8bec mov ebp,esp
0002269f 83ec1c sub esp,1Ch
000226a2 53 push ebx
000226a3 56 push esi
000226a4 8b750c mov esi,dword ptr [ebp+0Ch]
000226a7 8b4660 mov eax,dword ptr [esi+60h]
000226aa 83e824 sub eax,24h
000226ad 0fb608 movzx ecx,byte ptr [eax]
000226b0 0fb64001 movzx eax,byte ptr [eax+1]
000226b4 57 push edi
000226b5 33db xor ebx,ebx
000226b7 53 push ebx
000226b8 89450c mov dword ptr [ebp+0Ch],eax
000226bb 53 push ebx
000226bc 8d45e4 lea eax,[ebp-1Ch]
000226bf 50 push eax
000226c0 894dfc mov dword ptr [ebp-4],ecx
000226c3 ff1548e00100 call dword ptr [usbccgp!_imp__KeInitializeEvent (0001e048)]
000226c9 8b4660 mov eax,dword ptr [esi+60h]
000226cc 83e824 sub eax,24h
000226cf 8d4de4 lea ecx,[ebp-1Ch]
000226d2 894820 mov dword ptr [eax+20h],ecx
000226d5 8b4d08 mov ecx,dword ptr [ebp+8]
000226d8 8bd6 mov edx,esi
000226da c7401ca04d0100 mov dword ptr [eax+1Ch],offset usbccgp!CallDriverSyncCompletion (00014da0)
000226e1 c64003e0 mov byte ptr [eax+3],0E0h
000226e5 ff1510e10100 call dword ptr [usbccgp!_imp_IofCallDriver (0001e110)]
000226eb 8bf8 mov edi,eax
000226ed 81ff03010000 cmp edi,103h
000226f3 7557 jne usbccgp!CallDriverSync+0xb2 (0002274c)

usbccgp!CallDriverSync+0x5b:
000226f5 385d10 cmp byte ptr [ebp+10h],bl
000226f8 7444 je usbccgp!CallDriverSync+0xa4 (0002273e)

usbccgp!CallDriverSync+0x60:
000226fa 834df8ff or dword ptr [ebp-8],0FFFFFFFFh
000226fe 8d45f4 lea eax,[ebp-0Ch]
00022701 50 push eax
00022702 53 push ebx
00022703 53 push ebx
00022704 53 push ebx
00022705 8d45e4 lea eax,[ebp-1Ch]
00022708 50 push eax
00022709 c745f4800f05fd mov dword ptr [ebp-0Ch],0FD050F80h
00022710 ff1570e00100 call dword ptr [usbccgp!_imp__KeWaitForSingleObject (0001e070)]
00022716 8bf8 mov edi,eax
00022718 81ff02010000 cmp edi,102h
0002271e 752c jne usbccgp!CallDriverSync+0xb2 (0002274c)

usbccgp!CallDriverSync+0x86:
00022720 6820360200 push offset usbccgp! ?? ::NNGAKEGL::`string’ (00023620)
00022725 e84a3bffff call usbccgp!DebugWarn (00016274)
0002272a 59 pop ecx
0002272b 56 push esi
0002272c ff159ce00100 call dword ptr [usbccgp!_imp__IoCancelIrp (0001e09c)]
00022732 84c0 test al,al
00022734 7408 je usbccgp!CallDriverSync+0xa4 (0002273e)

usbccgp!CallDriverSync+0x9c:
00022736 bf010000c0 mov edi,0C0000001h
0002273b 897e18 mov dword ptr [esi+18h],edi

usbccgp!CallDriverSync+0xa4:
0002273e 53 push ebx
0002273f 53 push ebx
00022740 53 push ebx
00022741 53 push ebx
00022742 8d45e4 lea eax,[ebp-1Ch]
00022745 50 push eax
00022746 ff1570e00100 call dword ptr [usbccgp!_imp__KeWaitForSingleObject (0001e070)]

usbccgp!CallDriverSync+0xb2:
0002274c 3bfb cmp edi,ebx
0002274e 7d33 jge usbccgp!CallDriverSync+0xe9 (00022783)

usbccgp!CallDriverSync+0xb6:
00022750 a100f00100 mov eax,dword ptr [usbccgp!WPP_GLOBAL_Control (0001f000)]
00022755 3d00f00100 cmp eax,offset usbccgp!WPP_GLOBAL_Control (0001f000)
0002275a 742a je usbccgp!CallDriverSync+0xec (00022786)

usbccgp!CallDriverSync+0xc2:
0002275c f6402001 test byte ptr [eax+20h],1
00022760 7424 je usbccgp!CallDriverSync+0xec (00022786)

usbccgp!CallDriverSync+0xc8:
00022762 80781d04 cmp byte ptr [eax+1Dh],4
00022766 721e jb usbccgp!CallDriverSync+0xec (00022786)

usbccgp!CallDriverSync+0xce:
00022768 57 push edi
00022769 ff750c push dword ptr [ebp+0Ch]
0002276c ff75fc push dword ptr [ebp-4]
0002276f 68fce10100 push offset usbccgp!WPP_ThisDir_CTLGUID_USBCCGP+0x80 (0001e1fc)
00022774 6a0a push 0Ah
00022776 ff7014 push dword ptr [eax+14h]
00022779 ff7010 push dword ptr [eax+10h]
0002277c e815effeff call usbccgp!WPP_SF_qqD (00011696)
00022781 eb03 jmp usbccgp!CallDriverSync+0xec (00022786)

usbccgp!CallDriverSync+0xe9:
00022783 8b7e18 mov edi,dword ptr [esi+18h]

usbccgp!CallDriverSync+0xec:
00022786 8bc7 mov eax,edi
00022788 5f pop edi
00022789 5e pop esi
0002278a 5b pop ebx
0002278b c9 leave
0002278c c20c00 ret 0Ch

It can be seen that usbccgp!CallDriverSync does not call IoCompleteRequest in any code path.

Below is the submitUrb code of usbccgp in Windows 7.

usbccgp!SubmitUrb:
000116d0 8bff mov edi,edi
000116d2 55 push ebp
000116d3 8bec mov ebp,esp
000116d5 53 push ebx
000116d6 56 push esi
000116d7 8b7508 mov esi,dword ptr [ebp+8]
000116da 8b461c mov eax,dword ptr [esi+1Ch]
000116dd 0fb64030 movzx eax,byte ptr [eax+30h]
000116e1 57 push edi
000116e2 6a00 push 0
000116e4 50 push eax
000116e5 ff1560e00100 call dword ptr [usbccgp!_imp__IoAllocateIrp (0001e060)] <----------- IRP Allocation
000116eb 8bf8 mov edi,eax
000116ed 85ff test edi,edi
000116ef 7459 je usbccgp!SubmitUrb+0x7a (0001174a)

usbccgp!SubmitUrb+0x21:
000116f1 8b4760 mov eax,dword ptr [edi+60h]
000116f4 8b4d0c mov ecx,dword ptr [ebp+0Ch]
000116f7 83e824 sub eax,24h
000116fa 807d1000 cmp byte ptr [ebp+10h],0
000116fe c6000f mov byte ptr [eax],0Fh
00011701 c7400c03002200 mov dword ptr [eax+0Ch],220003h
00011708 894804 mov dword ptr [eax+4],ecx
0001170b 6a01 push 1
0001170d 7412 je usbccgp!SubmitUrb+0x51 (00011721)

usbccgp!SubmitUrb+0x3f:
0001170f 57 push edi
00011710 56 push esi
00011711 e89a150100 call usbccgp!CallNextDriverSync (00022cb0)
00011716 57 push edi
00011717 8bd8 mov ebx,eax
00011719 ff155ce00100 call dword ptr [usbccgp!_imp__IoFreeIrp (0001e05c)] <----------------- IRP being freed
0001171f eb2e jmp usbccgp!SubmitUrb+0x7f (0001174f)

usbccgp!SubmitUrb+0x51:
00011721 6a01 push 1
00011723 6a01 push 1
00011725 ff7518 push dword ptr [ebp+18h]
00011728 ff7514 push dword ptr [ebp+14h]
0001172b 57 push edi
0001172c ff7618 push dword ptr [esi+18h]
0001172f ff1558e00100 call dword ptr [usbccgp!_imp__IoSetCompletionRoutineEx (0001e058)]
00011735 8bd8 mov ebx,eax
00011737 85db test ebx,ebx
00011739 7514 jne usbccgp!SubmitUrb+0x7f (0001174f)

usbccgp!SubmitUrb+0x6b:
0001173b 8b4e1c mov ecx,dword ptr [esi+1Ch]
0001173e 8bd7 mov edx,edi
00011740 ff1510e10100 call dword ptr [usbccgp!_imp_IofCallDriver (0001e110)]
00011746 8bd8 mov ebx,eax
00011748 eb05 jmp usbccgp!SubmitUrb+0x7f (0001174f)

usbccgp!SubmitUrb+0x7a:
0001174a bb9a0000c0 mov ebx,0C000009Ah

usbccgp!SubmitUrb+0x7f:
0001174f 5f pop edi
00011750 5e pop esi
00011751 8bc3 mov eax,ebx
00011753 5b pop ebx
00011754 5d pop ebp
00011755 c21400 ret 14h


Anyone has a clue why IoCompleteRequest() is being called after usbccgp does IoCancelIrp on Windows XP?

xxxxx@gmail.com wrote:

My USB virtual bus driver is hitting a blue screen (MULTIPLE_IRP_COMPLETE_REQUESTS)
and I need you guys, the driver experts to help me.

Some info:

The bus driver enumerates the usb devices and communicates to the real usb device over the network. For every URB my driver receives, it marks it as pending and forwards the request over the network and completes it on receiving response.

I investigated this issue and found that the blue screen is caused by usbccgp cancelling the URB that is marked as pending by my virtual bus driver. So my drivers cancellation Routine that was set via IoSetCancelRoutine() is called which does WdfCompleteRequest() resulting into calling of the usbccgp’s completion routine. After the IoCancelIrp call return, usbccgp does IoCompleteRequest() [please see CallDriverSync function below].Now the call returns back to sumbiturb() where IoFreeIrp is done resulting into completion of the same IRP twice.

It is clearly a bug for usbccgp to call IoCompleteRequest on an IRP that
it created. However it can only get into this situation if the
KeWaitForSingleObject times out, and the timeout is set to 5 seconds.
Are there really situations where your processing is going to add 5
seconds to the processing? USB is going to be unusable in that case.
This is doing a “select configuration” call, which is usually the first
URB that gets sent. You may need to do some caching, or perhaps
complete the request and assume it will finish later.


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Iirc, this is a bug in usbccgp. It assumes the cancel is synchronous (which the underlying real core stack is in this scenario) and when it becomes async, things go awry .

Different issue: why are you calling IoSetCancelRoutine in a kmdf driver. The queue will do that for you in a much deeper, more integrated way

d

debt from my phone

-----Original Message-----
From: Tim Roberts
Sent: Monday, August 29, 2011 11:22 AM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] Multiple IRP Completion Bug Check because of usbccgp.sys on Windows XP

xxxxx@gmail.com wrote:

My USB virtual bus driver is hitting a blue screen (MULTIPLE_IRP_COMPLETE_REQUESTS)
and I need you guys, the driver experts to help me.

Some info:

The bus driver enumerates the usb devices and communicates to the real usb device over the network. For every URB my driver receives, it marks it as pending and forwards the request over the network and completes it on receiving response.

I investigated this issue and found that the blue screen is caused by usbccgp cancelling the URB that is marked as pending by my virtual bus driver. So my drivers cancellation Routine that was set via IoSetCancelRoutine() is called which does WdfCompleteRequest() resulting into calling of the usbccgp’s completion routine. After the IoCancelIrp call return, usbccgp does IoCompleteRequest() [please see CallDriverSync function below].Now the call returns back to sumbiturb() where IoFreeIrp is done resulting into completion of the same IRP twice.

It is clearly a bug for usbccgp to call IoCompleteRequest on an IRP that
it created. However it can only get into this situation if the
KeWaitForSingleObject times out, and the timeout is set to 5 seconds.
Are there really situations where your processing is going to add 5
seconds to the processing? USB is going to be unusable in that case.
This is doing a “select configuration” call, which is usually the first
URB that gets sent. You may need to do some caching, or perhaps
complete the request and assume it will finish later.


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.


NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Hi Tim,Doron

Thanks for your help.

Apologies. I use WdfRequestMarkCancellable to enable cancellation of the request and to register the call back that would be called when a URB is cancelled.

My bad.Really Sorry for that.

So far I havent encountered any situation that needs 5 seconds of processing, but when I see
the traces of URBs getting exchanged, I see the following:

  1. URB_FUNCTION_SELECT_INTERFACE [Interface 0,Alternate Setting 0] – SUCCESS -> The URB has the endpoint address which is say 0x83

  2. URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER – PENDING -> this is directed towards endpoint: 0x83

  3. URB_FUNCTION_SELECT_INTERFACE [Interface 0, Alternate Setting 0] – PENDING -> usbccgp times out on this and hence the code path where IRP free is called twice gets executed.

Interface Number 0 has only one Alternate Setting (ie 0). As far as I know URB_SELECT_INTERFACE is used to choose an Alternate Setting for those interfaces that have multiple Setting. Not sure why URB_FUNCTION_SELECT_INTERFACE [Interface 0, Alternate Setting 0] is exchanged here.

Regards,
Vignesh

xxxxx@gmail.com wrote:

So far I havent encountered any situation that needs 5 seconds of processing, but when I see
the traces of URBs getting exchanged, I see the following:

  1. URB_FUNCTION_SELECT_INTERFACE [Interface 0,Alternate Setting 0] – SUCCESS -> The URB has the endpoint address which is say 0x83

  2. URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER – PENDING -> this is directed towards endpoint: 0x83

  3. URB_FUNCTION_SELECT_INTERFACE [Interface 0, Alternate Setting 0] – PENDING -> usbccgp times out on this and hence the code path where IRP free is called twice gets executed.

It does seem odd that it would send a SelectInterface while a bulk
transfer was pending. You could respond to the SelectInterface call
immediately, since you already have the pipe information cached from the
previous SelectInterface call.

When you say the first SelectInterface succeeded, do you mean it got
sent over the network and was sent to a real hardware device, and you
sent the response back over to the virtual bus? Are you carefully
copying all of the response information in the pipe array?

Interface Number 0 has only one Alternate Setting (ie 0). As far as I know URB_SELECT_INTERFACE is used to choose an Alternate Setting for those interfaces that have multiple Setting. Not sure why URB_FUNCTION_SELECT_INTERFACE [Interface 0, Alternate Setting 0] is exchanged here.

SelectInterface is used to enable the use of an interface. It can also
select an alternate setting. In Windows, SelectConfiguration
automatically does a SelectInterface for the default interface, but
since usbccgp needs to address different interfaces at different times,
in might use SelectInterface more often than that.


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Yes, this is one way to approach this problem. Would Cancelling the URBs
that were
sent on the pipe and then forwarding the Select Interface to the USB device
be another
option to consider?

It does seem odd that it would send a SelectInterface while a bulk

transfer was pending. You could respond to the SelectInterface call
immediately, since you already have the pipe information cached from the
previous SelectInterface call.

Yes, the first SelectInterface succeeds. I am copying all the response
information
from pipe array carefully.

When you say the first SelectInterface succeeded, do you mean it got
sent over the network and was sent to a real hardware device, and you
sent the response back over to the virtual bus? Are you carefully
copying all of the response information in the pipe array?

Thanks and Regards,
Vignesh