Odd URB fail on Win7

Tom_Udale · June 10, 2011, 12:52pm

Hi all,

I am having a problem on Win7 Pro 32bit Free with
URB_FUNCTION_VENDOR_DEVICE URBs failing. The IoCallDriver function
succeeds, but the returned irp->IoStatus.Status is STATUS_UNSUCCESSFUL.

For what it is worth, this is code that has run fine on XP for years.

The very odd thing is that it only fails without a debugger active. If
you boot with a debugger you will never see the problem unless you
kdbgctrl -d. Then it starts. If you subsequently kdbgctrl -e, it goes
away again. It does not show up on the checked build either.

The main function in question, ControlVendorCommand (shown below), is
called ~10 times during device run-up. Off a fresh boot, the device
will run up fine. This is a camera that is cycling tons of ISO URBs
after the run-up and also sends a number of ControlVendorCommands to
shut down.

That all works fine on the first pass. On subsequent passes however,
the run-up sequence fails. So schematically it is:

boot

runup ControlVendorCommands
ISO URBs
shutdown ControlVendorCommands

runup ControlVendorCommands - all fail

Verifier does not seem to have anything to say. Nor does the checked
build of the OS (on which it does not fail).

Also, interestingly, power cycling the device does not fix it. I would
have thought that unloading the device would clean out whatever errors
had accumulated, however only a reboot sorts it.

I have validated on a protocol analyzer that there are no transactions
on the wire. So it is definitely failing in the USB subsystem.

Any thoughts would be most appreciated.

Best regards,

Tom Udale

static NTSTATUS
CallUsbdCompletion
(
IN PDEVICE_OBJECT DeviceObject,
IN PIRP Irp,
IN PVOID Context
)
{
PKEVENT kevent = (PKEVENT)Context;

ASSERT(KeGetCurrentIrql() <= DISPATCH_LEVEL);

KeSetEvent(kevent, IO_NO_INCREMENT,FALSE);
return STATUS_MORE_PROCESSING_REQUIRED;
}

NTSTATUS
CallUSBD
(
DEVICE_OBJECT* usbdiDevice,
URB* urb
)
{
PIRP irp;

ASSERT(KeGetCurrentIrql() < DISPATCH_LEVEL);
irp= IoAllocateIrp(usbdiDevice->StackSize, FALSE);
if(irp)
{
PIO_STACK_LOCATION nextStack= IoGetNextIrpStackLocation(irp);
KEVENT TimeoutEvent;
NTSTATUS ntStatus;

nextStack->MajorFunction = IRP_MJ_INTERNAL_DEVICE_CONTROL;
nextStack->Parameters.DeviceIoControl.IoControlCode =
IOCTL_INTERNAL_USB_SUBMIT_URB;
nextStack->Parameters.Others.Argument1 = urb;

KeInitializeEvent(&TimeoutEvent,NotificationEvent,FALSE);
IoSetCompletionRoutine(irp,CallUsbdCompletion,&TimeoutEvent,
TRUE, TRUE,TRUE);

ntStatus = IoCallDriver(usbdiDevice,irp);

if(NT_SUCCESS(ntStatus))
{
if(ntStatus == STATUS_PENDING)
{
LARGE_INTEGER timeout;

/* wait 5 seconds.*/
timeout.QuadPart = -10000 * 5000;
ntStatus = KeWaitForSingleObject(&TimeoutEvent,
Executive,KernelMode,FALSE, &timeout);
if(NT_SUCCESS(ntStatus))
{
ntStatus = irp->IoStatus.Status;
// !!!
// ntStatus is 0xC0000001 here
// !!!
}
}
}
IoFreeIrp(irp);
return ntStatus;
}
return STATUS_UNSUCCESSFUL;
}

NTSTATUS
ControlVendorCommand
(
DEVICE_OBJECT* usbdiDevice,
UCHAR Request,
USHORT Value,
USHORT Index,
PVOID Buffer,
PULONG BufferLength,
BOOLEAN GetData
)
{
NTSTATUS ntStatus;
PUCHAR localBuffer;
PUCHAR buffer;
ULONG length = BufferLength ? *BufferLength : 0;

ASSERT(KeGetCurrentIrql() < DISPATCH_LEVEL);

buffer = (PUCHAR)ExAllocatePool
(
NonPagedPool,
sizeof(struct _URB_CONTROL_VENDOR_OR_CLASS_REQUEST) + length
);
ntStatus = STATUS_INSUFFICIENT_RESOURCES;

if(buffer)
{
PURB urb= (PURB) (buffer + length);

if(BufferLength && *BufferLength != 0)
{
localBuffer = buffer;
if(!GetData)
{
RtlCopyMemory(localBuffer, Buffer, *BufferLength);
}
}
else
{
localBuffer = NULL;
}

UsbBuildVendorRequest
(
urb,
URB_FUNCTION_VENDOR_DEVICE,
sizeof(struct _URB_CONTROL_VENDOR_OR_CLASS_REQUEST),
GetData ? USBD_TRANSFER_DIRECTION_IN :0,
0,
Request,
Value,
Index,
localBuffer,
NULL,
length,
NULL
);
ntStatus = CallUSBD(usbdiDevice, urb);
if(NT_SUCCESS(ntStatus))
{
if(BufferLength)
{
*BufferLength =
urb->UrbControlVendorClassRequest.TransferBufferLength;

if(localBuffer && GetData)
{
RtlCopyMemory(Buffer, localBuffer, *BufferLength);
}
}
}
ExFreePool(buffer);
}
return ntStatus;
}

Tim_Roberts · June 10, 2011, 1:20pm

Tom Udale wrote:

I am having a problem on Win7 Pro 32bit Free with
URB_FUNCTION_VENDOR_DEVICE URBs failing. The IoCallDriver function
succeeds, but the returned irp->IoStatus.Status is STATUS_UNSUCCESSFUL.

For what it is worth, this is code that has run fine on XP for years.

Don’t you ever have any easy questions, Tom?

/* wait 5 seconds.*/
timeout.QuadPart = -10000 * 5000;
ntStatus = KeWaitForSingleObject(&TimeoutEvent,
Executive,KernelMode,FALSE, &timeout);
if(NT_SUCCESS(ntStatus))

It’s worth pointing out that KeWaitForSingleObject can return several
things that pass NT_SUCCESS but do not necessarily mean that your wait
completed. STATUS_ABANDONED and STATUS_TIMEOUT will both read as
success here. You should probably print the exact status you got back,
and check ntStatus == STATUS_WAIT_0. I don’t really think that’s what’s
going on, but it’s worth a shot.

You haven’t had errors from any previous URBs, have you? You haven’t
sent a SetConfiguration request to go back to configuration #0?

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

Glen_Slick-1 · June 10, 2011, 2:27pm

[quote]
That all works fine on the first pass. On subsequent passes however,
the run-up sequence fails. So schematically it is:

boot

runup ControlVendorCommands
ISO URBs
shutdown ControlVendorCommands

runup ControlVendorCommands - all fail

Go through the first part of the sequence when things work, then before starting the second part of the sequence when things fail start a USB ETW trace capture. Then repro the failures, then stop the USB ETW trace capture.

http://msdn.microsoft.com/en-us/windows/hardware/gg463163.aspx

They maybe there will be some clues about the source of the URB failures in the USB ETW trace.

-Glen

Tom_Udale · June 10, 2011, 3:21pm

Hi Tim,

Tom Udale wrote:
> I am having a problem on Win7 Pro 32bit Free with
> URB_FUNCTION_VENDOR_DEVICE URBs failing. The IoCallDriver function
> succeeds, but the returned irp->IoStatus.Status is STATUS_UNSUCCESSFUL.
>
> For what it is worth, this is code that has run fine on XP for years.

Don’t you ever have any easy questions, Tom?

Well, where is the fun in that? Actually I usually endeavor (not always
successfully) to filter out the stupid easy ones before bothering people

> /* wait 5 seconds.*/
> timeout.QuadPart = -10000 * 5000;
> ntStatus = KeWaitForSingleObject(&TimeoutEvent,
> Executive,KernelMode,FALSE,&timeout);
> if(NT_SUCCESS(ntStatus))

It’s worth pointing out that KeWaitForSingleObject can return several
things that pass NT_SUCCESS but do not necessarily mean that your wait
completed. STATUS_ABANDONED and STATUS_TIMEOUT will both read as
success here. You should probably print the exact status you got back,
and check ntStatus == STATUS_WAIT_0. I don’t really think that’s what’s
going on, but it’s worth a shot.

I clipped out that code for the sake of brevity. The actual code is:

LARGE_INTEGER timeout;

timeout.QuadPart = -10000 * 5000;

ntStatus = KeWaitForSingleObject(&TimeoutEvent, Executive,KernelMode,FALSE,
&timeout);
if(NT_SUCCESS(ntStatus))
{
if(ntStatus == STATUS_TIMEOUT)
{
ntStatus = STATUS_IO_TIMEOUT;

// Cancel the Irp we just sent.
//
IoCancelIrp(irp);

// And wait until the cancel completes
//
KeWaitForSingleObject(&TimeoutEvent,Executive,
KernelMode, FALSE,NULL);
}
else
{
ntStatus = irp->IoStatus.Status;
#if DBG
if(!NT_SUCCESS(ntStatus))
{
DebugErrorf((“CallUSBD: IoCallDriver succeeded but
IRP failed 0x%X\n”,ntStatus));
}
#endif
}
}
else
{
DebugErrorf((“CallUSBD: KeWaitForSingleObject
failed 0x%X\n”,ntStatus));
}

So should I replace my

if(ntStatus == STATUS_TIMEOUT)

test with

if(ntStatus != STATUS_WAIT_0)

?

Indeed, that timeout error path has not been tested to my knowledge. Does it
even make sense?

You haven’t had errors from any previous URBs, have you?

I don’t think so. I will have to check to see if every URB is printing
unconditional DebugErrorf messages and all returns are checked.

You haven’t
sent a SetConfiguration request to go back to configuration #0?

Pretty sure that has not happened. But I will have to check.

Although, does not configuration 0 always have the default command pipe?

Thanks,

Tom

Tom_Udale · June 10, 2011, 3:26pm

Dear Glen,

Thanks for the info. Looking into it now.

That is quite a command line on ol’ logman

Tom

[quote]
That all works fine on the first pass. On subsequent passes however,
the run-up sequence fails. So schematically it is:

boot

runup ControlVendorCommands
ISO URBs
shutdown ControlVendorCommands

runup ControlVendorCommands - all fail

>
> Go through the first part of the sequence when things work, then before starting the second part of the sequence when things fail start a USB ETW trace capture. Then repro the failures, then stop the USB ETW trace capture.
>
> http://msdn.microsoft.com/en-us/windows/hardware/gg463163.aspx
>
> They maybe there will be some clues about the source of the URB failures in the USB ETW trace.
>
> -Glen
>
>

Tom_Udale · June 10, 2011, 5:10pm

Glen,

Go through the first part of the sequence when things work, then
before starting the second part of the sequence when things fail
start a USB ETW trace capture.

Ok, I think we are onto something. I did a cold reboot, ran the USB
capture and did a full run and rerun cycle.

I opened the log up in network monitor and applied the USB error filter.

What I have is the following:

a) USBPort traces for cancels for each of my ISO URBs when I shut down
the “working” run, one for each of the 40 URBs (they are small, 8
packets, so I have a lot). [Times 9.219-9.254]

b) a USBPort trace for a canceled URB for a device of class 9 (Hub)
[Time 13.6328]

c) two USBPub exception traces with debug text SsErr_FailedResumeOnPort
[Time 16.203 and 16.306]

d) all the failed URBs I am seeing in my driver (100% correlation
between ETW and DebugView output). All fail with
USBD_STATUS_XACT_ERROR. [Time 16.358-16.367]

On a second test all was the same except b) was missing and there was
only one SsErr_FailedResumeOnPort event in c).

So it looks (to me) like the hub (internal to the ICH I guess) is
choking for some reason and then killing all my calls subsequently.

The SsErr_FailedResumeOnPort does indeed come after a bunch of activity
on that hub device.

Lastly, I looked again on my HW bus analyzer and I definitely do not see
any activity on the second run.

Any idea what all this means?

Best regards,

Tom

Glen_Slick-1 · June 10, 2011, 5:36pm

Tom,

Is your driver doing something to enable selective suspend of the device, or requesting that the device be put into PowerDeviceD2, after it shuts down the isoch stream the first time? And then doing something to resume the device again before starting up the isoch stream the next time?

I believe the SsErr_FailedResumeOnPort indicates that after attempting to resume the port to which a device is attached the port status indicates that the port is still in the suspend state. If that is true (which would match zero activity seen on the bus analyzer, not even SOF packets) then that would explain why all subsequent transfer requests to the device fail.

Is the host controller one of these?
PCI\VEN_8086&DEV_1C26
PCI\VEN_8086&DEV_1C2D
PCI\VEN_8086&DEV_3B34
PCI\VEN_8086&DEV_3B3C

If so then even if the device is plugged directly into the system it is most likely routed through the PCH chipset Integrated Rate Matching Hub (USB\VID_8087&PID_0020 or USB\VID_8087&PID_0024).

Without further details I can’t think of any known issues that sound exactly the same as what you describe off the top of my head.

-Glen

Tom_Udale · June 10, 2011, 6:34pm

Glen,

I am not at work right now, but I am 99% sure I remember seeing suspend
events in the HW bus analyzer log, so what you are saying is quite possible.

I will look on Monday at that to be sure.

I am wondering, though, how exactly would I programmaticly generate a
suspend event? I do not recall such a thing.

At any rate, I will look into it all on Monday.

Thank you for your help.

Have a good weekend,

Tom

Is your driver doing something to enable selective suspend of the
device, or requesting that the device be put into PowerDeviceD2,
after it shuts down the isoch stream the first time? And then doing
something to resume the device again before starting up the isoch
stream the next time?

I believe the SsErr_FailedResumeOnPort indicates that after
attempting to resume the port to which a device is attached the port
status indicates that the port is still in the suspend state. If
that is true (which would match zero activity seen on the bus
analyzer, not even SOF packets) then that would explain why all
subsequent transfer requests to the device fail.

Is the host controller one of these? PCI\VEN_8086&DEV_1C26
PCI\VEN_8086&DEV_1C2D PCI\VEN_8086&DEV_3B34 PCI\VEN_8086&DEV_3B3C

If so then even if the device is plugged directly into the system it
is most likely routed through the PCH chipset Integrated Rate
Matching Hub (USB\VID_8087&PID_0020 or USB\VID_8087&PID_0024).

Without further details I can’t think of any known issues that sound
exactly the same as what you describe off the top of my head.

-Glen

Tom_Udale · June 13, 2011, 11:51am

Glen,

Is your driver doing something to enable selective suspend of the
device, or requesting that the device be put into PowerDeviceD2,
after it shuts down the isoch stream the first time? And then doing
something to resume the device again before starting up the isoch
stream the next time?

I do not explicitly set power state (PoRequestPowerIrp) or request selective
suspend (IOCTL_INTERNAL_USB_SUBMIT_IDLE_NOTIFICATION) anywhere in my driver.

The device is question is a STREAM class camera however and I cannot vouch
for STREAM. I posted the ETL log, with comments, below. There definately
are

USBPort USBPort:Device Idle State Set
USBHub USBHub:USB Device Set Dx Device Power IRP Completed

etc in the log.

Also, on the HW bus monitor side, it sees several resets and idles points on
the bus.

I believe the SsErr_FailedResumeOnPort indicates that after
attempting to resume the port to which a device is attached the port
status indicates that the port is still in the suspend state. If
that is true (which would match zero activity seen on the bus
analyzer, not even SOF packets) then that would explain why all
subsequent transfer requests to the device fail.

It also explains why powering the camera on and off does not fix it: it is
in the hub.

Is the host controller one of these? PCI\VEN_8086&DEV_1C26
PCI\VEN_8086&DEV_1C2D PCI\VEN_8086&DEV_3B34 PCI\VEN_8086&DEV_3B3C

If so then even if the device is plugged directly into the system it
is most likely routed through the PCH chipset Integrated Rate
Matching Hub (USB\VID_8087&PID_0020 or USB\VID_8087&PID_0024).

I don’t think so. I am running this on two separate machines. One is an
ICH9 box, and the other an ICH10.

The host controllers are actually a series of part numbers. The ICH9 is:

PCI\VEN_8086&DEV_2934 ;UHCs
PCI\VEN_8086&DEV_2934
PCI\VEN_8086&DEV_2936
PCI\VEN_8086&DEV_2937
PCI\VEN_8086&DEV_2938
PCI\VEN_8086&DEV_293A ;EHCs
PCI\VEN_8086&DEV_293C

The ICH10s span DEV_3A64 to DEV_3A6C

Does any of this help?

Best,

Tom

// event log follows

Device class 255 is the camera.
Device class 9 is a hub.

// Normal ISO stream processing:
255 (0xFF) 0x82 6365 5:02:48 PM 6/10/2011 9.9180402 (0) USBPort
USBPort:Complete COMPLETE_URB_FUNCTION_ISOCH_TRANSFER
255 (0xFF) 0x82 6366 5:02:48 PM 6/10/2011 9.9180737 (0) USBPort
USBPort:Dispatch URB_FUNCTION_ISOCH_TRANSFER

// This is the STOP stream command sent to the camera in StopStream()
255 (0xFF) 0x0 6367 5:02:48 PM 6/10/2011 9.9180811 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Now I abort the pipe, which cancels all outstanding IRPs.
255 (0xFF) 0x82 6368 5:02:48 PM 6/10/2011 9.9188634 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_ABORT_PIPE
// First cancel.
255 (0xFF) 0x82 6369 5:02:48 PM 6/10/2011 9.9188669 (0) USBPort
USBPort:Complete COMPLETE_URB_FUNCTION_ISOCH_TRANSFER
// Followed by lots of other cancels…

// Now this random guy.
6396 5:02:48 PM 6/10/2011 9.9708344 (0) USBPort USBPort:Host Controller
Periodic Schedule Disable
// Lots more cancels…
// Last cancel:
255 (0xFF) 0x82 6409 5:02:48 PM 6/10/2011 9.9709066 (0) USBPort
USBPort:Complete COMPLETE_URB_FUNCTION_ISOCH_TRANSFER

// End of abort.
255 (0xFF) 0x82 6410 5:02:48 PM 6/10/2011 9.9709114 (0) USBPort
USBPort:Complete URB_FUNCTION_ABORT_PIPE

// This is a Get Port Status
9 (0x9) 0x0 6411 5:02:48 PM 6/10/2011 9.9709339 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6412 5:02:48 PM 6/10/2011 9.9709383 (2508) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data

// Now I reset the pipe:
255 (0xFF) 0x82 6413 5:02:48 PM 6/10/2011 9.9709453 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SYNC_RESET_PIPE_AND_CLEAR_STALL

// Camera stop command sent a second time in CloseStream() (oops)
255 (0xFF) 0x0 6414 5:02:48 PM 6/10/2011 9.9937125 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6415 5:02:48 PM 6/10/2011 9.9937249 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6416 5:02:48 PM 6/10/2011 9.9939070 (0) USBPort USBPort:Host Controller
Async Schedule Disable
255 (0xFF) 0x0 6417 5:02:48 PM 6/10/2011 9.9939145 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Not sure what this is, but it is not related to the previous URB
(different pointer)
6418 5:02:48 PM 6/10/2011 9.9939316 (2508) USBPort USBPort:Dispatch URB
INVALID_HEADER_LENGTH_WARNING

// Select alternate setting 3 which kills the ISO endpoint, this is a
little confusing as there
// are multiple URBs that are generated from the one I created.
255 (0xFF) 6419 5:02:48 PM 6/10/2011 9.9939338 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SELECT_INTERFACE
255 (0xFF) 0x82 6420 5:02:48 PM 6/10/2011 9.9939378 (2508) USBPort
USBPort:Endpoint Close
255 (0xFF) 0x0 6421 5:02:48 PM 6/10/2011 10.0277281 (2508) USBPort
USBPort:Internal URB_FUNCTION_CONTROL_TRANSFER
6422 5:02:48 PM 6/10/2011 10.0277334 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6423 5:02:48 PM 6/10/2011 10.0279002 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6424 5:02:48 PM 6/10/2011 10.0279054 (0) USBPort
USBPort:Complete Internal URB_FUNCTION_CONTROL_TRANSFER

// From here until the ********** below, we are not in my code.

6425 5:02:48 PM 6/10/2011 10.0408203 (4) USBHub USBHub:USB Device Set
Dx Device Power IRP Dispatched
9 (0x9) 0x0 6426 5:02:48 PM 6/10/2011 10.0408485 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6427 5:02:48 PM 6/10/2011 10.0408551 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6428 5:02:48 PM 6/10/2011 10.0408806 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6429 5:02:48 PM 6/10/2011 10.0408837 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6430 5:02:48 PM 6/10/2011 10.0408969 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6431 5:02:48 PM 6/10/2011 10.0410262 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX
255 (0xFF) 6432 5:02:48 PM 6/10/2011 10.0410372 (4) USBPort
USBPort:Device Idle State Set
6433 5:02:48 PM 6/10/2011 10.0410416 (4) USBHub USBHub:USB Device Set
Dx Device Power IRP Completed

// Cannot figure out who this is (maybe keyboard or mouse?)
0 (0x0) 0x82 6434 5:02:49 PM 6/10/2011 10.4259414 (0) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
// …bunches…

6616 5:02:52 PM 6/10/2011 14.1766521 (4) USBHub USBHub:USB Device Set
D0 Device Power IRP Dispatched
9 (0x9) 0x0 6617 5:02:52 PM 6/10/2011 14.1766953 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6618 5:02:52 PM 6/10/2011 14.1767010 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6619 5:02:52 PM 6/10/2011 14.1767137 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
6620 5:02:52 PM 6/10/2011 14.1767199 (4) USBPort USBPort:Host
Controller Async Schedule Enable
9 (0x9) 0x0 6621 5:02:52 PM 6/10/2011 14.1767234 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX
6622 5:02:53 PM 6/10/2011 14.2427088 (0) USBPort USBPort:Host
Controller Async Schedule Disable
9 (0x9) 0x81 6623 5:02:53 PM 6/10/2011 14.2427281 (0) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
9 (0x9) 0x0 6624 5:02:53 PM 6/10/2011 14.2427479 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6625 5:02:53 PM 6/10/2011 14.2427510 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
6626 5:02:53 PM 6/10/2011 14.2427563 (4) USBHub USBHub:USB Hub Port
Status Change
9 (0x9) 0x0 6627 5:02:53 PM 6/10/2011 14.2427620 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6628 5:02:53 PM 6/10/2011 14.2427642 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x81 6629 5:02:53 PM 6/10/2011 14.2427801 (4) USBPort
USBPort:Dispatch URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER
9 (0x9) 0x0 6630 5:02:53 PM 6/10/2011 14.2427875 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6631 5:02:53 PM 6/10/2011 14.2427955 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
255 (0xFF) 6632 5:02:53 PM 6/10/2011 14.2947155 (4) USBPort
USBPort:Device Idle State Clear
6633 5:02:53 PM 6/10/2011 14.2947181 (4) USBHub USBHub:USB Device Set
D0 Device Power IRP Completed
6634 5:02:53 PM 6/10/2011 14.3024054 (4) USBHub USBHub:USB Device Set
Dx Device Power IRP Dispatched
9 (0x9) 0x0 6635 5:02:53 PM 6/10/2011 14.3024261 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6636 5:02:53 PM 6/10/2011 14.3024318 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6637 5:02:53 PM 6/10/2011 14.3024613 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6638 5:02:53 PM 6/10/2011 14.3024644 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6639 5:02:53 PM 6/10/2011 14.3024767 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6640 5:02:53 PM 6/10/2011 14.3026056 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX
255 (0xFF) 6641 5:02:53 PM 6/10/2011 14.3026162 (4) USBPort
USBPort:Device Idle State Set
6642 5:02:53 PM 6/10/2011 14.3026206 (4) USBHub USBHub:USB Device Set
Dx Device Power IRP Completed
6643 5:02:53 PM 6/10/2011 14.3062696 (4) USBHub USBHub:USB Device Set
D0 Device Power IRP Dispatched
9 (0x9) 0x0 6644 5:02:53 PM 6/10/2011 14.3063096 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6645 5:02:53 PM 6/10/2011 14.3063153 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
9 (0x9) 0x0 6646 5:02:53 PM 6/10/2011 14.3063290 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
6647 5:02:53 PM 6/10/2011 14.3063347 (4) USBPort USBPort:Host
Controller Async Schedule Enable
9 (0x9) 0x0 6648 5:02:53 PM 6/10/2011 14.3063387 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX

// This guy again…
0 (0x0) 0x82 6649 5:02:53 PM 6/10/2011 14.3299022 (0) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data

6655 5:02:53 PM 6/10/2011 14.3722233 (0) USBPort USBPort:Host
Controller Async Schedule Disable
9 (0x9) 0x81 6656 5:02:53 PM 6/10/2011 14.3722365 (0) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
9 (0x9) 0x0 6657 5:02:53 PM 6/10/2011 14.3722567 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6658 5:02:53 PM 6/10/2011 14.3722602 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
6659 5:02:53 PM 6/10/2011 14.3722651 (4) USBHub USBHub:USB Hub Port
Status Change
9 (0x9) 0x0 6660 5:02:53 PM 6/10/2011 14.3722717 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6661 5:02:53 PM 6/10/2011 14.3722743 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x81 6662 5:02:53 PM 6/10/2011 14.3722893 (4) USBPort
USBPort:Dispatch URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER
9 (0x9) 0x0 6663 5:02:53 PM 6/10/2011 14.3722959 (4) USBPort
USBPort:Dispatch URB_FUNCTION_CONTROL_TRANSFER_EX
9 (0x9) 0x0 6664 5:02:53 PM 6/10/2011 14.3723086 (4) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER_EX with Data
6665 5:02:53 PM 6/10/2011 14.3723174 (4) USBHub USBHub:USB Hub
Exception Logged
0 (0x0) 0x82 6666 5:02:53 PM 6/10/2011 14.3858896 (0) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
0 (0x0) 0x82 6667 5:02:53 PM 6/10/2011 14.3859077 (0) USBPort
USBPort:Dispatch URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER
255 (0xFF) 6668 5:02:53 PM 6/10/2011 14.3982277 (4) USBPort
USBPort:Device Idle State Clear
6669 5:02:53 PM 6/10/2011 14.3982299 (4) USBHub USBHub:USB Device Set
D0 Device Power IRP Completed
0 (0x0) 0x82 6670 5:02:53 PM 6/10/2011 14.4179065 (2508) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
0 (0x0) 0x82 6671 5:02:53 PM 6/10/2011 14.4179496 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER

//******************* Now start second run, set image width.

255 (0xFF) 0x0 6672 5:02:53 PM 6/10/2011 14.4238111 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6673 5:02:53 PM 6/10/2011 14.4238190 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6674 5:02:53 PM 6/10/2011 14.4239862 (0) USBPort USBPort:Host
Controller Async Schedule Disable
// Set width fails XACT_ERROR
255 (0xFF) 0x0 6675 5:02:53 PM 6/10/2011 14.4239933 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set height, fails XACT_ERROR
255 (0xFF) 0x0 6676 5:02:53 PM 6/10/2011 14.4240267 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6677 5:02:53 PM 6/10/2011 14.4240315 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6678 5:02:53 PM 6/10/2011 14.4241072 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6679 5:02:53 PM 6/10/2011 14.4241129 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set x offset, fails XACT_ERROR
255 (0xFF) 0x0 6680 5:02:53 PM 6/10/2011 14.4241415 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6681 5:02:53 PM 6/10/2011 14.4241464 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6682 5:02:53 PM 6/10/2011 14.4242308 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6683 5:02:53 PM 6/10/2011 14.4242361 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6684 5:02:53 PM 6/10/2011 14.4242792 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6685 5:02:53 PM 6/10/2011 14.4242841 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6686 5:02:53 PM 6/10/2011 14.4243549 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6687 5:02:53 PM 6/10/2011 14.4243606 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6688 5:02:53 PM 6/10/2011 14.4243866 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6689 5:02:53 PM 6/10/2011 14.4243910 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6690 5:02:53 PM 6/10/2011 14.4244807 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6691 5:02:53 PM 6/10/2011 14.4244865 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6692 5:02:53 PM 6/10/2011 14.4245102 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6693 5:02:53 PM 6/10/2011 14.4245146 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6694 5:02:53 PM 6/10/2011 14.4246057 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6695 5:02:53 PM 6/10/2011 14.4246110 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6696 5:02:53 PM 6/10/2011 14.4246391 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6697 5:02:53 PM 6/10/2011 14.4246435 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6698 5:02:53 PM 6/10/2011 14.4247306 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6699 5:02:53 PM 6/10/2011 14.4247359 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6700 5:02:53 PM 6/10/2011 14.4247588 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6701 5:02:53 PM 6/10/2011 14.4247632 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6702 5:02:53 PM 6/10/2011 14.4248551 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6703 5:02:53 PM 6/10/2011 14.4248600 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6704 5:02:53 PM 6/10/2011 14.4248859 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6705 5:02:53 PM 6/10/2011 14.4248903 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6706 5:02:53 PM 6/10/2011 14.4249792 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6707 5:02:53 PM 6/10/2011 14.4249845 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Set param, fails XACT_ERROR
255 (0xFF) 0x0 6708 5:02:53 PM 6/10/2011 14.4250162 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_VENDOR_DEVICE
6709 5:02:53 PM 6/10/2011 14.4250206 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6710 5:02:53 PM 6/10/2011 14.4251055 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6711 5:02:53 PM 6/10/2011 14.4251108 (0) USBPort
USBPort:Complete URB_FUNCTION_CONTROL_TRANSFER

// Remainder of setup, surely I check an error code somewhere? Naa, this
stuff “cannot fail”.
// (all fail with XACT_ERROR)
0 (0x0) 0x82 6712 5:02:53 PM 6/10/2011 14.4258978 (704) USBPort
USBPort:Complete URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER with Data
0 (0x0) 0x82 6713 5:02:53 PM 6/10/2011 14.4259299 (704) USBPort
USBPort:Dispatch URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER
6714 5:02:53 PM 6/10/2011 14.4307114 (2508) USBPort USBPort:Dispatch
URB INVALID_HEADER_LENGTH_WARNING
255 (0xFF) 6715 5:02:53 PM 6/10/2011 14.4307153 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SELECT_INTERFACE
255 (0xFF) 0x0 6716 5:02:53 PM 6/10/2011 14.4307224 (2508) USBPort
USBPort:Internal URB_FUNCTION_CONTROL_TRANSFER
6717 5:02:53 PM 6/10/2011 14.4307281 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6718 5:02:53 PM 6/10/2011 14.4308605 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6719 5:02:53 PM 6/10/2011 14.4308667 (0) USBPort
USBPort:Complete Internal URB_FUNCTION_CONTROL_TRANSFER
6720 5:02:53 PM 6/10/2011 14.4308900 (2508) USBPort USBPort:Dispatch
URB INVALID_HEADER_LENGTH_WARNING
255 (0xFF) 6721 5:02:53 PM 6/10/2011 14.4308918 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SELECT_INTERFACE
255 (0xFF) 0x0 6722 5:02:53 PM 6/10/2011 14.4308962 (2508) USBPort
USBPort:Internal URB_FUNCTION_CONTROL_TRANSFER
6723 5:02:53 PM 6/10/2011 14.4309006 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6724 5:02:53 PM 6/10/2011 14.4309820 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6725 5:02:53 PM 6/10/2011 14.4309872 (0) USBPort
USBPort:Complete Internal URB_FUNCTION_CONTROL_TRANSFER
6726 5:02:53 PM 6/10/2011 14.4336952 (2508) USBPort USBPort:Dispatch
URB INVALID_HEADER_LENGTH_WARNING
255 (0xFF) 6727 5:02:53 PM 6/10/2011 14.4336974 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SELECT_INTERFACE
255 (0xFF) 0x0 6728 5:02:53 PM 6/10/2011 14.4337013 (2508) USBPort
USBPort:Internal URB_FUNCTION_CONTROL_TRANSFER
6729 5:02:53 PM 6/10/2011 14.4337062 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6730 5:02:53 PM 6/10/2011 14.4338553 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6731 5:02:53 PM 6/10/2011 14.4338601 (0) USBPort
USBPort:Complete Internal URB_FUNCTION_CONTROL_TRANSFER
6732 5:02:53 PM 6/10/2011 14.4338755 (2508) USBPort USBPort:Dispatch
URB INVALID_HEADER_LENGTH_WARNING
255 (0xFF) 6733 5:02:53 PM 6/10/2011 14.4338773 (2508) USBPort
USBPort:Dispatch URB_FUNCTION_SELECT_INTERFACE
255 (0xFF) 0x0 6734 5:02:53 PM 6/10/2011 14.4338804 (2508) USBPort
USBPort:Internal URB_FUNCTION_CONTROL_TRANSFER
6735 5:02:53 PM 6/10/2011 14.4338848 (2508) USBPort USBPort:Host
Controller Async Schedule Enable
6736 5:02:53 PM 6/10/2011 14.4339811 (0) USBPort USBPort:Host
Controller Async Schedule Disable
255 (0xFF) 0x0 6737 5:02:53 PM 6/10/2011 14.4339860 (0) USBPort
USBPort:Complete Internal URB_FUNCTION_CONTROL_TRANSFER