S3 QUERY IRP completion problem

Q

QuasiCodo

This problem is NOT FOR THE FAINT OF HEART:


I've got a multi-port serial (MPS) device which is having trouble with power
management. The original driver's power management code did not have any
calls to PoRequestPowerIrp() which caused some problems. I looked at
Toaster and Oney's WDM examples and changed the code to conform.


A nut-shell architecture of the driver is as follows:

1) a FDO is created for each MPS PCI adapter.

2) the driver acts as a bus driver for a virtual bus on which we hang all
the serial port devices. The driver creates a PDO for each port and
consequently, FDOs are created corresponding to each PDO.


When the Power Manager issues a S3 Query, this is what I see with my traces:

(Indenting indicates function scoping, "exit" from a function will
un-indent)

DispatchFdoS3SetQuery, RocketPort15 (COM18), Irp = FFB99A30
SendDeviceIrp, RocketPort15 (COM18), sIrp = FFB99A30
DispatchFdoD3SetQuery, RocketPort15 (COM18), Irp = FF9C3B28
HookAndPassDownIrp, RocketPort15 (COM18), Irp = FF9C3B28
DispatchPowerPdo, RocketPortPdo0 (), Irp = FF9C3B28
DEVICE QUERY
CompletionFdoD3SetQuery, RocketPort15 (COM18), Irp =
FF9C3B28
FinalizeDevicePowerIrp, RocketPort15 (COM18), Irp =
FF9C3B28
PowManCallbackFdoS3SetQuery, RocketPort15
(COM18), sIrp = FFB99A30
HookAndPassDownIrp, RocketPort15 (COM18),
Irp = FFB99A30
DispatchPowerPdo, RocketPortPdo0 (), Irp
= FFB99A30
SYSTEM QUERY
CompletionFdoS3SetQuery,
RocketPort15 (COM18), Irp = FFB99A30
CompletionFdoS3SetQuery exit, status
= STATUS_SUCCESS (00000000)

Here we have an FDO S3 Query IRP FFB99A30 for COM18. The FDO S3 dispatch
sends a device IRP to the device stack (via PoRequestDeviceIrp).

The FDO D3 Query IRP FF9C3B28 is created by the Power Manager and is issued
to the driver. The FDO D3 dispatch "hooks" the IRP and passes it down (i.e.
IoCopyCurStkLoc, IoSetCompletionR, PoCallDriver) to the "bus" driver.

Next, the PDO D3 IRP FF9C3B28 arrives at the "bus" PDO Dispatch routine.
The PDO dispatch sees that it is a DEVICE QUERY and calls PoSetPowerState.
The PDO dispatch then calls PoStartNextPowerIrp and completes the IRP.

Then the FDO D3 Completion routine gets called which completes the Device
Power IRP FF9C3B28.

Next, the Power Manager calls PowManCallbackFdoS3SetQuery to indicate that
the device IRP FF9C3B28 has completed AND it is time to handle the
corresponding S3 Irp FFB99A30.

The PoMan callback "hooks" and passes the S3 Irp down the stack.

The "bus" PDO S3 Irp FFB99A30 arrives and the driver completes it.

Finally the FDO S3 Completion routine is called. PoStartNextPowerIrp is
called and then the S3 QUERY IRP FFB99A30 is completed.

When the FDO S3 Completion routine returns, I get the following exception:


Access violation - code c0000005 (!!! second chance !!!)
Loading symbols for 80a02000 ntoskrnl.exe -> ntoskrnl.exe
*** ERROR: Symbol file could not be found. Defaulted to export symbols for
ntoskrnl.exe -
nt!KeInitializeApc+42:
80a32d04 0fb68765010000 movzx eax,byte ptr [edi+0x165]

kd> r
eax=00000000 ebx=00000000 ecx=80aaae06 edx=00000041 esi=ffb99a70
edi=00000000
eip=80a32d04 esp=fc9e6f60 ebp=fc9e6f6c iopl=0 nv up ei ng nz ac pe
cy
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010293
nt!KeInitializeApc+42:
80a32d04 0fb68765010000 movzx eax,byte ptr [edi+0x165]
ds:0023:00000165=??

kd> kv 30
ChildEBP RetAddr Args to Child
WARNING: Stack unwind information not available. Following frames may be
wrong.
fc9e6f6c 80a23720 ffb99a70 00000000 00000000 nt!KeInitializeApc+0x42
fc9e6fb0 f644358f 02000000 ffbab7e8 ffb99ae8 nt!IoCancelIrp+0x4a5
fc9e6fc4 f64432aa ffbab730 00000000 ffbab730 rocket!DispatchPowerPdo+0x172
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 608]
fc9e6fe0 80a20812 ffbab730 ffb99a30 ffb99a30 rocket!SerialPowerDispatch+0x82
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 453]
fc9e7014 80aa3acc 01b99ae8 ffb99a30 ffb99a30 nt!IoBuildPartialMdl+0x14e
fc9e7038 f6443b0a ffbab730 f64449f8 8118a800 nt!PoCallDriver+0x318
fc9e7050 f64449f8 8118a800 ffb99a30 f6444aea rocket!HookAndPassDownIrp+0x99
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 895]
fc9e7070 80aa2af9 8118a748 00000003 00000004
rocket!PowManCallbackFdoS3SetQuery+0x88 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1472]
fc9e70a0 80a23560 ffbc1a40 ff9c3b28 f6444970 nt!ObDereferenceObject+0x2bf
fc9e70d0 f6445842 ff9c3b28 00000000 02000000 nt!IoCancelIrp+0x2e5
fc9e70e4 f644550e 8118a748 ff9c3b28 00000002
rocket!FinalizeDevicePowerIrp+0x69 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 2045]
fc9e7108 80a23560 8118a748 00000000 00000000
rocket!CompletionFdoD3SetQuery+0x84 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1915]
fc9e7138 f644358f 02000000 ffbab7e8 ff9c3be0 nt!IoCancelIrp+0x2e5
fc9e714c f64432aa ffbab730 00000001 ffbab730 rocket!DispatchPowerPdo+0x172
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 608]
fc9e7168 80a20812 ffbab730 ff9c3b28 ff9c3b28 rocket!SerialPowerDispatch+0x82
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 453]
fc9e719c 80aa3acc 019c3be0 ff9c3b28 02000000 nt!IoBuildPartialMdl+0x14e
fc9e71c0 f6443b0a ffbab730 f6445388 8118a800 nt!PoCallDriver+0x318
fc9e71d8 f6445388 8118a800 ff9c3b28 f644548a rocket!HookAndPassDownIrp+0x99
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 895]
fc9e71fc f6444c70 8118a748 ff9c3b28 ff9c3b28
rocket!DispatchFdoD3SetQuery+0xa2 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1822]
fc9e7218 f6443d2c 8118a748 00000004 8118a800
rocket!DispatchFdoDeviceSetQueryPower+0x55 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1581]
fc9e7234 f644374a 8118a748 ff9c3b28 02000000
rocket!DispatchFdoQueryPowerState+0x6b (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 978]
fc9e7254 f64432f8 8118a748 00000004 8118a748 rocket!DispatchPowerFdo+0xc7
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 732]
fc9e7270 80a20812 8118a748 ff9c3b28 ff9c3b28 rocket!SerialPowerDispatch+0xd0
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 460]
fc9e72a4 80aa3acc 019c3c04 ff9c3b28 ff9c3c20 nt!IoBuildPartialMdl+0x14e
fc9e72c8 fcb5155e 8118a748 fcb5167b ffbc1a40 nt!PoCallDriver+0x318
fc9e72f0 fcb5167b ffbc1af8 00000004 ff9c3b28 serenum+0x155e
fc9e7304 80a20812 ffbc1a40 ff9c3b28 ff9c3b28 serenum+0x167b
fc9e7338 80aa3acc 019c3c28 ff9c3b28 80aa2aa6 nt!IoBuildPartialMdl+0x14e
fc9e735c 80aa3cee ffbc1a40 f644570d 8118a800 nt!PoCallDriver+0x318
fc9e7378 f644570d 8118a748 ffb99b03 00000004 nt!PoRequestPowerIrp+0x143
fc9e73a8 f644486f 00000004 8118a748 f6444970 rocket!SendDeviceIrp+0xc5 (FPO:
[Non-Fpo]) (CONV: stdcall) [c:\projects\rocketport\nt_w2k_xp\driver\power.c
@ 1987]
fc9e73c8 f64443a4 8118a748 ffb99a30 ffb99a30
rocket!DispatchFdoS3SetQuery+0x49 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1432]
fc9e73e4 f6443d25 8118a748 ffb99a30 8118a800
rocket!DispatchFdoSystemQueryPower+0x60 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 1247]
fc9e7400 f644374a 8118a748 ffb99a30 02000000
rocket!DispatchFdoQueryPowerState+0x64 (FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 975]
fc9e7420 f64432f8 8118a748 00000002 8118a748 rocket!DispatchPowerFdo+0xc7
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 732]
fc9e743c 80a20812 8118a748 ffb99a30 ffb99a30 rocket!SerialPowerDispatch+0xd0
(FPO: [Non-Fpo]) (CONV: stdcall)
[c:\projects\rocketport\nt_w2k_xp\driver\power.c @ 460]
fc9e7470 80aa3acc 01b99b0c ffb99a30 ffb99b28 nt!IoBuildPartialMdl+0x14e
fc9e7494 fcb5155e 8118a748 fcb5167b ffbc1a40 nt!PoCallDriver+0x318
fc9e74bc fcb5167b ffbc1af8 00000002 ffb99a30 serenum+0x155e
fc9e74d0 80a20812 ffbc1a40 ffb99a30 ffb99a30 serenum+0x167b
fc9e7504 80aa3acc 01b99b30 ffb99a30 8117d938 nt!IoBuildPartialMdl+0x14e
fc9e7528 80ca9995 ffbc1a40 80ca9d62 8117dacc nt!PoCallDriver+0x318
fc9e7548 80ca9d62 80ae023c 811d8900 00000005 nt!PoSetHiberRange+0x314e
fc9e7564 80caa3ce 8117d938 0017dacc 001f0003 nt!PoSetHiberRange+0x351b
fc9e758c 80ca8556 00000000 fc9e7678 fc9e7708 nt!PoSetHiberRange+0x3b87
fc9e7664 80ac2efc 00000002 00000002 20000003 nt!PoSetHiberRange+0x1d0f
fc9e7684 80a391a1 badb0d00 fc9e76fc 00000001
nt!KeReleaseInStackQueuedSpinLockFromDpcLevel+0xc10
fc9e77d4 80ac2efc 00000002 00000002 20000003 nt!ZwSetSystemInformation+0x25

kd> u nt!KeInitializeApc
nt!KeInitializeApc:
....
80a32ce9 8b7d0c mov edi,[ebp+0xc]
....
80a32d04 0fb68765010000 movzx eax,byte ptr [edi+0x165]

kd> dd ebp+c
fc9e6f78 00000000 00000000 80a28661 80b19636


Here we see that KeInitializeApc is fetching a NULL pointer from the stack.

So the question is: how am I causing this problem?

One interesting thing to note: before KeInitializeApc, IoCanelIrp is called
to cancel IRP ffb99ae8. This is only 0xB8 away from the original S3 QUERY
IRP FFB99A30. If you notice on the stack, when the D3 QUERY IRP is
completed, there is also a call to IoCancelIrp, but the IRP is the same as
the D3 QUERY IRP. I don't know if this is a red herring or not.


((&-<
 
C

Calvin Guan

QuasiCodo said:
kd> kv 30
ChildEBP RetAddr Args to Child
WARNING: Stack unwind information not available. Following frames may be
wrong.
fc9e6f6c 80a23720 ffb99a70 00000000 00000000 nt!KeInitializeApc+0x42
fc9e6fb0 f644358f 02000000 ffbab7e8 ffb99ae8 nt!IoCancelIrp+0x4a5
fc9e6fc4 f64432aa ffbab730 00000000 ffbab730 rocket!DispatchPowerPdo+0x172
(FPO: [Non-Fpo]) (CONV: stdcall) [snip]
completed, there is also a call to IoCancelIrp, but the IRP is the same as
the D3 QUERY IRP. I don't know if this is a red herring or not.
Click to expand...

Did you actually call IoCancelIrp in rocket!DispatchPowerPdo? I'm suspecting
that the stack unwind info was wrong. You may try manually walking through
the call stack based on the current ESP value.

Good luck,
Calvin
-
Calvin Guan Software Engineer
ATI Technologies Inc. www.ati.com
 
Q

QuasiCodo

Calvin:
Did you actually call IoCancelIrp in rocket!DispatchPowerPdo? I'm suspecting
that the stack unwind info was wrong. You may try manually walking through
the call stack based on the current ESP value.
Click to expand...

No. The "bus" PDO Query handling code is as follows:

switch (irpStack->MinorFunction)
{
...

case IRP_MN_QUERY_POWER:

// Is it a SYSTEM QUERY power IRP?
if (powerType == SystemPowerState)
{
MyKdPrint (D_PnpPower,("SYSTEM QUERY\n"))
}
else if (powerType == DevicePowerState)
{
MyKdPrint (D_PnpPower,("DEVICE QUERY\n"))
}
else
{
MyKdPrint (D_PnpPower,("OTHER QUERY\n"))
}

// Complete the IRP successfully
status = STATUS_SUCCESS;
Irp->IoStatus.Status = status;
break;

...

} // end switch (irpStack->MinorFunction)

// Allow the Power Manager to send more power IRPs
PoStartNextPowerIrp (Irp);

// Complete the IRP
IoCompleteRequest (Irp, IO_NO_INCREMENT);

// Return status
MyKdPrint (D_PnpPower,("DispatchPowerPdo exit, status = %s (%p)\n",
DBGGetNtStatusString (status), status));
return status;


As you can see, there is no call to IoCancelIrp. I'm starting to think that
the "bus" portion of the driver should not complete the PDO S3 Query IRP. If
you look at my original posting, both the FDO and PDO S3 Query are the same
IRP, FFB99A30. I'm starting the believe that this IRP should only be
completed once. The CompletionFdoS3SetQuery code also completes the same
IRP:

NTSTATUS
CompletionFdoS3SetQuery (
IN PDEVICE_OBJECT DeviceObject,
IN PIRP Irp,
IN PVOID NotUsed)
{
NTSTATUS status;
PIO_STACK_LOCATION stack = IoGetCurrentIrpStackLocation
(Irp);
PSERIAL_DEVICE_EXTENSION Ext = (PSERIAL_DEVICE_EXTENSION)
DeviceObject->DeviceExtension;

ASSERT (Irp);
ASSERT (Ext);

MyKdPrint (D_PnpPower, ("CompletionFdoS3SetQuery, %s (%s), Irp = %p\n",
Ext->NtNameForPort, Ext->SymbolicLinkName, Irp));

// S Irp status = D Irp status
status = Ext->DIrpCompletionStatus;
Irp->IoStatus.Status = Ext->DIrpCompletionStatus;

// Let Power Manager send more power IRPs
PoStartNextPowerIrp (Irp);

// Complete the S Irp
IoCompleteRequest (Irp, IO_NO_INCREMENT);

// Dec driver's IO Count
SerialIRPEpilogue (Ext);

MyKdPrint (D_PnpPower, ("CompletionFdoS3SetQuery exit, status = %s
(%p)\n", DBGGetNtStatusString (status), status));
return status;
}


Of we look at a portion of the call trace again:

DispatchPowerPdo, RocketPortPdo0 (), Irp = FFB99A30
SYSTEM QUERY
(we call IoCompleteRequest here)
CompletionFdoS3SetQuery, RocketPort15 (COM18), Irp = FFB99A30
(we call IoCompleteReuqest here)
CompletionFdoS3SetQuery exit, status = STATUS_SUCCESS (00000000)
(we crash with a NULL pointer here)

I think that because we completed the IRP in the "bus" PDO code, the system
takes the IRP out of the system and frees some resources. When
CompletionFdoS3SetQuery runs, it completes the IRP a second time, which
causes the IO Subsystem to operate on something that has already been
deallocated.

((&-<
 
S

Slava M. Usov

[...]
I'm starting to think that the "bus" portion of the driver should not
complete the PDO S3 Query IRP.
[...]

I'm starting the believe that this IRP should only be completed once.
Click to expand...

The final conclusion is correct. The original one is not. A power IRP must
be completed by the bus driver, the other guys may only pass it down and
install IRP completion routines, whence they call PoStartNextPowerIrp().
Unless they fail it. I suggest that you re-read the "rules for handling
power IRPs" in DDK.

S
 
Q

QuasiCodo

Slava:

Taking the IoCompleteRequest out of the S3 & D3 Query Completion routines
seems to work! I got through all of the S3 & D3 Query IRPs.

Now I'm having trouble with the S3 & D3 Set IRPs. I think it is the same
problem.

Thanks a lot!

((&->
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Similar Threads

stop 0xC5 0

Top