StartIo receiving bad device context

Jeff_Glass · December 9, 2011, 2:37pm

I’m seeing a problem with a StorPort Miniport where the device context I receive from StorPort has a value of 8.

The context of what’s going on is that I’m running tests with a third party test tool (DriveMaster) and the script in question is issuing a lot of commands that cause my driver to be unloaded and reloaded.

The result of all these resets is eventually I get a StartIo call (for a PnP Remove) that has this goofy device context. However, I already completed a remove, adapter control was called several times, and DriverEntry of the new instance has been called.

I’m wondering if anyone else has experienced something similar and could suggest what I might be doing wrong to cause this to happen. This has the smell of a problem from another thread in the archives although the details are a bit different. http://www.osronline.com/showThread.cfm?link=161318

Here’s a little trace
STORMINI: BuildIo: Exit. return FALSE
STORMINI: BuildIo: Enter.
STORMINI: ExecuteScsi: Enter. SRB=FFFFFA8006866490
STORMINI: ScsiWrite10: Enter.
STORMINI: ScsiWrite: Enter.
STORMINI: BuildScsiMessage: Enter.
STORMINI: BuildScsiMessage: Exit.
STORMINI: ScsiWrite: Exit.
STORMINI: ScsiWrite10: Exit.
STORMINI: ExecuteScsi: Exit. return TRUE
STORMINI: BuildIo: Exit. return FALSE
STORMINI: BuildIo: Enter.
STORMINI: BuildIo: Pass PnP request to StartIO
STORMINI: BuildIo: Exit. return TRUE
STORMINI: StartIo: Enter. SRB Function=0x00000025, SrbStatus=0, TimeoutValue=10
STORMINI: StartIo: pnp action = 2
STORMINI: StartIo: Send halt command
STORMINI: StartIo: Exit. return TRUE
STORMINI: StateChangeIsr: Complete PnP SRB.
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=1
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=0
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=3
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: DriverEntry: Enter.
STORMINI: DriverEntry: Enter
STORMINI: DriverEntry: Built at Dec 9 2011 09:30:39
STORMINI: DriverEntry: Exit. status=0x00000000

*** Fatal System Error: 0x0000007e
(0xFFFFFFFFC0000005,0xFFFFFA6000E0C5D0,0xFFFFFA6002DD23B8,0xFFFFFA6002DD1D90)

<** The exception is caused by my driver trying to dereference a device context value of 8. **>

SIDisk!StartIo+0xd0 [\startio.c @ 109]
storport!RaidAdapterPostScatterGatherExecute+0x150
storport!RaidPnPPassToMiniPort+0x22c
storport!RaidAdapterReleaseResources+0x35
storport!RaidAdapterRemoveDeviceIrp+0x5f
storport!RaidAdapterPnpIrp+0x127
storport!RaDriverPnpIrp+0x95
nt!IopSynchronousCall+0x10a
nt!IopRemoveDevice+0x101
nt!PnpRemoveLockedDeviceNode+0x1a6
nt!PnpDeleteLockedDeviceNode+0x44
nt!PnpDeleteLockedDeviceNodes+0xa0
nt!PnpProcessQueryRemoveAndEject+0xbe7
nt!PnpProcessTargetDeviceEvent+0x4c
nt! ?? ::NNGAKEGL::string'+0x4e537 nt!ExpWorkerThread+0xfb nt!PspSystemThreadStartup+0x57 nt!KiStartSystemThread+0x16 3: kd> dt _SCSI_PNP_REQUEST_BLOCK 0xfffffa800680a810 SIDisk!_SCSI_PNP_REQUEST_BLOCK +0x000 Length : 0x58 +0x002 Function : 0x25 'Unknown format characterUnknown format control character +0x003 SrbStatus : 0 '' +0x004 PnPSubFunction : 0 '' +0x005 PathId : 0 '' +0x006 TargetId : 0 '' +0x007 Lun : 0 '' +0x008 PnPAction : 2 ( StorRemoveDevice ) +0x00c SrbFlags : 0x100 +0x010 DataTransferLength : 0 +0x014 TimeOutValue : 0xa +0x018 DataBuffer : (null) +0x020 SenseInfoBuffer : (null) +0x028 NextSrb : (null) +0x030 OriginalRequest : 0xfffffa6008b84010
+0x038 SrbExtension : 0xfffffa60`08b84380
+0x040 SrbPnPFlags : 1
+0x044 Reserved : 0
+0x048 Reserved4 : [16] “”

3: kd> !devnode 0xfffffa8005f96730
DevNode 0xfffffa8005f96730 for PDO 0xfffffa8005f97060
Parent 0xfffffa8005f777b0 Sibling 0000000000 Child 0000000000
State = DeviceNodeStartCompletion (0x306)
Previous State = DeviceNodeStartCompletion (0x306)
StateHistory[18] = DeviceNodeAwaitingQueuedRemoval (0x30f)
StateHistory[17] = DeviceNodeStartCompletion (0x306)
StateHistory[16] = DeviceNodeStartPending (0x305)
StateHistory[15] = DeviceNodeResourcesAssigned (0x304)
StateHistory[14] = DeviceNodeDriversAdded (0x303)
StateHistory[13] = DeviceNodeInitialized (0x302)
StateHistory[12] = DeviceNodeUninitialized (0x301)
StateHistory[11] = DeviceNodeRemoved (0x312)
StateHistory[10] = DeviceNodeQueryRemoved (0x310)
StateHistory[09] = DeviceNodeStarted (0x308)
StateHistory[08] = DeviceNodeEnumerateCompletion (0x30d)
StateHistory[07] = DeviceNodeEnumeratePending (0x30c)
StateHistory[06] = DeviceNodeStarted (0x308)
StateHistory[05] = DeviceNodeEnumerateCompletion (0x30d)
StateHistory[04] = DeviceNodeEnumeratePending (0x30c)
StateHistory[03] = DeviceNodeStarted (0x308)
StateHistory[02] = DeviceNodeStartPostWork (0x307)
StateHistory[01] = DeviceNodeStartCompletion (0x306)
StateHistory[00] = DeviceNodeStartPending (0x305)
StateHistory[19] = DeviceNodeResourcesAssigned (0x304)
Flags (0x00000030) DNF_ENUMERATED, DNF_IDS_QUERIED
CapabilityFlags (0x00000003) DeviceD1, DeviceD2

Doron_Holan · December 9, 2011, 2:53pm

Are you sure the value is 8? Usually when you see single digit pointer values like that it is a field offset of a null pointer. Are you sure it is not your own NULL pointer you are dereferencing? Output of !analyze -v?

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@gmail.com
Sent: Friday, December 09, 2011 11:37 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] StartIo receiving bad device context

I’m seeing a problem with a StorPort Miniport where the device context I receive from StorPort has a value of 8.

The context of what’s going on is that I’m running tests with a third party test tool (DriveMaster) and the script in question is issuing a lot of commands that cause my driver to be unloaded and reloaded.

The result of all these resets is eventually I get a StartIo call (for a PnP Remove) that has this goofy device context. However, I already completed a remove, adapter control was called several times, and DriverEntry of the new instance has been called.

I’m wondering if anyone else has experienced something similar and could suggest what I might be doing wrong to cause this to happen. This has the smell of a problem from another thread in the archives although the details are a bit different. http://www.osronline.com/showThread.cfm?link=161318

Here’s a little trace
STORMINI: BuildIo: Exit. return FALSE
STORMINI: BuildIo: Enter.
STORMINI: ExecuteScsi: Enter. SRB=FFFFFA8006866490
STORMINI: ScsiWrite10: Enter.
STORMINI: ScsiWrite: Enter.
STORMINI: BuildScsiMessage: Enter.
STORMINI: BuildScsiMessage: Exit.
STORMINI: ScsiWrite: Exit.
STORMINI: ScsiWrite10: Exit.
STORMINI: ExecuteScsi: Exit. return TRUE
STORMINI: BuildIo: Exit. return FALSE
STORMINI: BuildIo: Enter.
STORMINI: BuildIo: Pass PnP request to StartIO
STORMINI: BuildIo: Exit. return TRUE
STORMINI: StartIo: Enter. SRB Function=0x00000025, SrbStatus=0, TimeoutValue=10
STORMINI: StartIo: pnp action = 2
STORMINI: StartIo: Send halt command
STORMINI: StartIo: Exit. return TRUE
STORMINI: StateChangeIsr: Complete PnP SRB.
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=1
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=0
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: AdapterControl: Enter.
STORMINI: AdapterControl: ControlType=3
STORMINI: AdapterControl: Exit. status=0x00000000
STORMINI: DriverEntry: Enter.
STORMINI: DriverEntry: Enter
STORMINI: DriverEntry: Built at Dec 9 2011 09:30:39
STORMINI: DriverEntry: Exit. status=0x00000000

*** Fatal System Error: 0x0000007e
(0xFFFFFFFFC0000005,0xFFFFFA6000E0C5D0,0xFFFFFA6002DD23B8,0xFFFFFA6002DD1D90)

<** The exception is caused by my driver trying to dereference a device context value of 8. **>

SIDisk!StartIo+0xd0 [\startio.c @ 109]
storport!RaidAdapterPostScatterGatherExecute+0x150
storport!RaidPnPPassToMiniPort+0x22c
storport!RaidAdapterReleaseResources+0x35
storport!RaidAdapterRemoveDeviceIrp+0x5f
storport!RaidAdapterPnpIrp+0x127
storport!RaDriverPnpIrp+0x95
nt!IopSynchronousCall+0x10a
nt!IopRemoveDevice+0x101
nt!PnpRemoveLockedDeviceNode+0x1a6
nt!PnpDeleteLockedDeviceNode+0x44
nt!PnpDeleteLockedDeviceNodes+0xa0
nt!PnpProcessQueryRemoveAndEject+0xbe7
nt!PnpProcessTargetDeviceEvent+0x4c
nt! ?? ::NNGAKEGL::string'+0x4e537 nt!ExpWorkerThread+0xfb nt!PspSystemThreadStartup+0x57 nt!KiStartSystemThread+0x16 3: kd> dt _SCSI_PNP_REQUEST_BLOCK 0xfffffa800680a810 SIDisk!_SCSI_PNP_REQUEST_BLOCK +0x000 Length : 0x58 +0x002 Function : 0x25 'Unknown format characterUnknown format control character +0x003 SrbStatus : 0 '' +0x004 PnPSubFunction : 0 '' +0x005 PathId : 0 '' +0x006 TargetId : 0 '' +0x007 Lun : 0 '' +0x008 PnPAction : 2 ( StorRemoveDevice ) +0x00c SrbFlags : 0x100 +0x010 DataTransferLength : 0 +0x014 TimeOutValue : 0xa +0x018 DataBuffer : (null) +0x020 SenseInfoBuffer : (null) +0x028 NextSrb : (null) +0x030 OriginalRequest : 0xfffffa6008b84010
+0x038 SrbExtension : 0xfffffa60`08b84380
+0x040 SrbPnPFlags : 1
+0x044 Reserved : 0
+0x048 Reserved4 : [16] “”

3: kd> !devnode 0xfffffa8005f96730
DevNode 0xfffffa8005f96730 for PDO 0xfffffa8005f97060
Parent 0xfffffa8005f777b0 Sibling 0000000000 Child 0000000000
State = DeviceNodeStartCompletion (0x306)
Previous State = DeviceNodeStartCompletion (0x306)
StateHistory[18] = DeviceNodeAwaitingQueuedRemoval (0x30f)
StateHistory[17] = DeviceNodeStartCompletion (0x306)
StateHistory[16] = DeviceNodeStartPending (0x305)
StateHistory[15] = DeviceNodeResourcesAssigned (0x304)
StateHistory[14] = DeviceNodeDriversAdded (0x303)
StateHistory[13] = DeviceNodeInitialized (0x302)
StateHistory[12] = DeviceNodeUninitialized (0x301)
StateHistory[11] = DeviceNodeRemoved (0x312)
StateHistory[10] = DeviceNodeQueryRemoved (0x310)
StateHistory[09] = DeviceNodeStarted (0x308)
StateHistory[08] = DeviceNodeEnumerateCompletion (0x30d)
StateHistory[07] = DeviceNodeEnumeratePending (0x30c)
StateHistory[06] = DeviceNodeStarted (0x308)
StateHistory[05] = DeviceNodeEnumerateCompletion (0x30d)
StateHistory[04] = DeviceNodeEnumeratePending (0x30c)
StateHistory[03] = DeviceNodeStarted (0x308)
StateHistory[02] = DeviceNodeStartPostWork (0x307)
StateHistory[01] = DeviceNodeStartCompletion (0x306)
StateHistory[00] = DeviceNodeStartPending (0x305)
StateHistory[19] = DeviceNodeResourcesAssigned (0x304)
Flags (0x00000030) DNF_ENUMERATED, DNF_IDS_QUERIED
CapabilityFlags (0x00000003) DeviceD1, DeviceD2

—
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

Jeff_Glass · December 9, 2011, 3:06pm

Thanks for the reply Doron. I’m pretty sure that I’m being passed that value because the fault is happening at the beginning of the function in a debug print that announces function entry.

BOOLEAN
StartIo(
IN PVOID devExt,
IN PSCSI_REQUEST_BLOCK srb
)
{
BOOLEAN retval = FALSE;
skd_device_t * device_context = (skd_device_t*)devExt;

DBGPRINT( (device_context->instanceNumber, SD_COMP_IO, SD_SUBCOMP_FUNCTIONS, FUNC “: Enter. SRB Function=0x%08X, SrbStatus=%X, TimeoutValue=%u\n”, srb->Function, srb->SrbStatus, srb->TimeOutValue) );

Probably caused by : SIDisk.sys ( SIDisk!StartIo+d0 )

Followup: MachineOwner

nt!RtlpBreakWithStatusInstruction:
fffff800`0185f720 cc int 3
3: kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

SYSTEM_THREAD_EXCEPTION_NOT_HANDLED (7e)
This is a very common bugcheck. Usually the exception address pinpoints
the driver/function that caused the problem. Always note this address
as well as the link date of the driver/image that contains this address.
Arguments:
Arg1: ffffffffc0000005, The exception code that was not handled
Arg2: fffffa6000e0c5d0, The address that the exception occurred at
Arg3: fffffa6002dd23b8, Exception Record Address
Arg4: fffffa6002dd1d90, Context Record Address

Debugging Details:

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

FAULTING_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

EXCEPTION_RECORD: fffffa6002dd23b8 – (.exr 0xfffffa6002dd23b8)
ExceptionAddress: fffffa6000e0c5d0 (SIDisk!StartIo+0x00000000000000d0)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000000
Parameter[1]: 0000000000000010
Attempt to read from address 0000000000000010

CONTEXT: fffffa6002dd1d90 – (.cxr 0xfffffa6002dd1d90)
rax=0000000000000008 rbx=fffffa81496291b0 rcx=0000000000000025
rdx=0000000000000005 rsi=fffffa800680a810 rdi=fffffa6008b84010
rip=fffffa6000e0c5d0 rsp=fffffa6002dd25f0 rbp=0000000000000000
r8=0000000000000040 r9=fffffa6000e195f0 r10=0000000000000000
r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
r14=fffffa8149629060 r15=fffffa6001e46110
iopl=0 nv up ei pl nz na pe nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b efl=00010202
SIDisk!StartIo+0xd0:
fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8] ds:002b:0000000000000010=???
Resetting default scope

PROCESS_NAME: System

CURRENT_IRQL: 2

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1: 0000000000000000

EXCEPTION_PARAMETER2: 0000000000000010

READ_ADDRESS: 0000000000000010

FOLLOWUP_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

BUGCHECK_STR: 0x7E

DEFAULT_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER: from fffffa6001e3a930 to fffffa6000e0c5d0

STACK_TEXT:
fffffa6002dd25f0 fffffa6001e3a930 : 0000000000000008 fffffa800680a810 fffffa80069988e0 fffffa6001e2d256 : SIDisk!StartIo+0xd0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa6002dd2720 fffffa6001e3e9bc : fffffa6008b84000 fffffa800680a810 0000000000000000 fffffa81496291b0 : storport!RaidAdapterPostScatterGatherExecute+0x150
fffffa6002dd2780 fffffa6001e7f655 : fffffffffffffc18 fffffa6000000002 fffffa81496291b0 fffffa81496291b0 : storport!RaidPnPPassToMiniPort+0x22c
fffffa6002dd27f0 fffffa6001e7f6ef : fffffa81496291b0 fffffa8005f97060 0000000000000000 00000000c00000bb : storport!RaidAdapterReleaseResources+0x35
fffffa6002dd2830 fffffa6001e80387 : fffffa814de294b0 0000000000000002 fffffa81496291b0 0000000000000000 : storport!RaidAdapterRemoveDeviceIrp+0x5f
fffffa6002dd2860 fffffa6001e805d5 : fffffa814de294b0 00000000c00000bb fffff880096f56b0 fffffa814de294b0 : storport!RaidAdapterPnpIrp+0x127
fffffa6002dd28c0 fffff80001a60632 : fffffa814de294b0 0000000000000000 fffffa6002dd29b8 fffff80001b869f9 : storport!RaDriverPnpIrp+0x95
fffffa6002dd2900 fffff80001c3f481 : fffffa8005f97060 0000000000000000 fffffa8005f96730 0000000000000002 : nt!IopSynchronousCall+0x10a
fffffa6002dd2970 fffff80001938476 : fffff880095b21d0 fffff880095b21d0 fffff880095b21d8 0000000000000000 : nt!IopRemoveDevice+0x101
fffffa6002dd2a30 fffff80001c3efc4 : fffffa8005f96730 0000000000000000 0000000000000002 fffffa8007f2eb20 : nt!PnpRemoveLockedDeviceNode+0x1a6
fffffa6002dd2a80 fffff80001c3f0e0 : 0000000000000000 fffffa8005f96700 fffff880097af2d0 fffff8003f051397 : nt!PnpDeleteLockedDeviceNode+0x44
fffffa6002dd2ab0 fffff80001c43797 : 0000000000000002 0000000000000000 0000000000000006 fffffa8005f96730 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffffa6002dd2b20 fffff80001c43dcc : fffffa6002dd2cf8 fffffa800670e700 fffffa8005add700 fffffa8000000000 : nt!PnpProcessQueryRemoveAndEject+0xbe7
fffffa6002dd2c70 fffff80001b42dca : 0000000000000001 fffffa800670e7d0 fffff880097b7ae0 0000000000000000 : nt!PnpProcessTargetDeviceEvent+0x4c
fffffa6002dd2ca0 fffff8000186c8cb : fffff80001a62870 fffff880097b7ae0 fffff8000199c8f8 fffffa8005add720 : nt! ?? ::NNGAKEGL::string'+0x4e537 fffffa6002dd2cf0 fffff80001a6ff97 : fffffa800670e7d0 34383438d078d078 fffffa8005add720 0000000000000080 : nt!ExpWorkerThread+0xfb fffffa6002dd2d50 fffff800018a25c6 : fffffa60029d8180 fffffa8005add720 fffffa60029e1d40 fffffa8005adf138 : nt!PspSystemThreadStartup+0x57 fffffa6002dd2d80 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 00000000`00000000 : nt!KiStartSystemThread+0x16

SYMBOL_STACK_INDEX: 0

SYMBOL_NAME: SIDisk!StartIo+d0

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: SIDisk

IMAGE_NAME: SIDisk.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4ee245c0

STACK_COMMAND: .cxr 0xfffffa6002dd1d90 ; kb

FAILURE_BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

Followup: MachineOwner

3: kd> !irp 0xfffffa814de294b0
Irp is active with 2 stacks 2 is current (= 0xfffffa814de295c8)
No Mdl: No System Buffer: Thread fffffa8005add720: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[1b, 2] 0 0 fffffa8149629060 00000000 00000000-00000000
\Driver\SIDisk
Args: 00000000 00000000 00000000 00000000

The fault is actually being caused by the DBGPRINT message at the start of the function.

OSR_Community_User · December 9, 2011, 3:47pm

Take a look at the spec for StartIo: you are passed a pointer to the
device object, not the device extension.

For example,

http://www.osronline.com/ddkx/kmarch/drvrrtns_6isy.htm

Would be a good start. RTFM helps; note that StartIo is documented as
returning NTSTATUS, not BOOLEAN, and the first parameter is specified as a
PDEVICE_OBJECT, not a PVOID. And the second parameter is a PIRP. If you
are not using StartIo queuing, it is a Bad Idea to re-use a
semantically-loaded name for a different purpose.
Joe

Thanks for the reply Doron. I’m pretty sure that I’m being passed that
value because the fault is happening at the beginning of the function in a
debug print that announces function entry.

BOOLEAN
StartIo(
IN PVOID devExt,
IN PSCSI_REQUEST_BLOCK srb
)
{
BOOLEAN retval = FALSE;
skd_device_t * device_context =
(skd_device_t*)devExt;

DBGPRINT( (device_context->instanceNumber, SD_COMP_IO,
SD_SUBCOMP_FUNCTIONS, FUNC “: Enter. SRB Function=0x%08X,
SrbStatus=%X, TimeoutValue=%u\n”, srb->Function, srb->SrbStatus,
srb->TimeOutValue) );

Probably caused by : SIDisk.sys ( SIDisk!StartIo+d0 )

Followup: MachineOwner

nt!RtlpBreakWithStatusInstruction:
fffff800`0185f720 cc int 3
3: kd> !analyze -v
*******************************************************************************
*
*
* Bugcheck Analysis
*
*
*
*******************************************************************************

SYSTEM_THREAD_EXCEPTION_NOT_HANDLED (7e)
This is a very common bugcheck. Usually the exception address pinpoints
the driver/function that caused the problem. Always note this address
as well as the link date of the driver/image that contains this address.
Arguments:
Arg1: ffffffffc0000005, The exception code that was not handled
Arg2: fffffa6000e0c5d0, The address that the exception occurred at
Arg3: fffffa6002dd23b8, Exception Record Address
Arg4: fffffa6002dd1d90, Context Record Address

Debugging Details:

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx
referenced memory at 0x%08lx. The memory could not be %s.

FAULTING_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

EXCEPTION_RECORD: fffffa6002dd23b8 – (.exr 0xfffffa6002dd23b8)
ExceptionAddress: fffffa6000e0c5d0 (SIDisk!StartIo+0x00000000000000d0)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000000
Parameter[1]: 0000000000000010
Attempt to read from address 0000000000000010

CONTEXT: fffffa6002dd1d90 – (.cxr 0xfffffa6002dd1d90)
rax=0000000000000008 rbx=fffffa81496291b0 rcx=0000000000000025
rdx=0000000000000005 rsi=fffffa800680a810 rdi=fffffa6008b84010
rip=fffffa6000e0c5d0 rsp=fffffa6002dd25f0 rbp=0000000000000000
r8=0000000000000040 r9=fffffa6000e195f0 r10=0000000000000000
r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
r14=fffffa8149629060 r15=fffffa6001e46110
iopl=0 nv up ei pl nz na pe nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b
efl=00010202
SIDisk!StartIo+0xd0:
fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8] ds:002b:0000000000000010=???
Resetting default scope

PROCESS_NAME: System

CURRENT_IRQL: 2

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced
memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1: 0000000000000000

EXCEPTION_PARAMETER2: 0000000000000010

READ_ADDRESS: 0000000000000010

FOLLOWUP_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

BUGCHECK_STR: 0x7E

DEFAULT_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER: from fffffa6001e3a930 to fffffa6000e0c5d0

STACK_TEXT:
fffffa6002dd25f0 fffffa6001e3a930 : 0000000000000008 fffffa800680a810
fffffa80069988e0 fffffa6001e2d256 : SIDisk!StartIo+0xd0
[s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa6002dd2720 fffffa6001e3e9bc : fffffa6008b84000 fffffa800680a810
0000000000000000 fffffa81496291b0 :
storport!RaidAdapterPostScatterGatherExecute+0x150
fffffa6002dd2780 fffffa6001e7f655 : fffffffffffffc18 fffffa6000000002
fffffa81496291b0 fffffa81496291b0 : storport!RaidPnPPassToMiniPort+0x22c
fffffa6002dd27f0 fffffa6001e7f6ef : fffffa81496291b0 fffffa8005f97060
0000000000000000 00000000c00000bb :
storport!RaidAdapterReleaseResources+0x35
fffffa6002dd2830 fffffa6001e80387 : fffffa814de294b0 0000000000000002
fffffa81496291b0 0000000000000000 :
storport!RaidAdapterRemoveDeviceIrp+0x5f
fffffa6002dd2860 fffffa6001e805d5 : fffffa814de294b0 00000000c00000bb
fffff880096f56b0 fffffa814de294b0 : storport!RaidAdapterPnpIrp+0x127
fffffa6002dd28c0 fffff80001a60632 : fffffa814de294b0 0000000000000000
fffffa6002dd29b8 fffff80001b869f9 : storport!RaDriverPnpIrp+0x95
fffffa6002dd2900 fffff80001c3f481 : fffffa8005f97060 0000000000000000
fffffa8005f96730 0000000000000002 : nt!IopSynchronousCall+0x10a
fffffa6002dd2970 fffff80001938476 : fffff880095b21d0 fffff880095b21d0
fffff880095b21d8 0000000000000000 : nt!IopRemoveDevice+0x101
fffffa6002dd2a30 fffff80001c3efc4 : fffffa8005f96730 0000000000000000
0000000000000002 fffffa8007f2eb20 : nt!PnpRemoveLockedDeviceNode+0x1a6
fffffa6002dd2a80 fffff80001c3f0e0 : 0000000000000000 fffffa8005f96700
fffff880097af2d0 fffff8003f051397 : nt!PnpDeleteLockedDeviceNode+0x44
fffffa6002dd2ab0 fffff80001c43797 : 0000000000000002 0000000000000000
0000000000000006 fffffa8005f96730 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffffa6002dd2b20 fffff80001c43dcc : fffffa6002dd2cf8 fffffa800670e700
fffffa8005add700 fffffa8000000000 :
nt!PnpProcessQueryRemoveAndEject+0xbe7
fffffa6002dd2c70 fffff80001b42dca : 0000000000000001 fffffa800670e7d0
fffff880097b7ae0 0000000000000000 : nt!PnpProcessTargetDeviceEvent+0x4c
fffffa6002dd2ca0 fffff8000186c8cb : fffff80001a62870 fffff880097b7ae0
fffff8000199c8f8 fffffa8005add720 : nt! ?? ::NNGAKEGL::string'+0x4e537 fffffa6002dd2cf0 fffff80001a6ff97 : fffffa800670e7d0 34383438d078d078 fffffa8005add720 0000000000000080 : nt!ExpWorkerThread+0xfb fffffa6002dd2d50 fffff800018a25c6 : fffffa60029d8180 fffffa8005add720 fffffa60029e1d40 fffffa8005adf138 : nt!PspSystemThreadStartup+0x57 fffffa6002dd2d80 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 00000000`00000000 : nt!KiStartSystemThread+0x16

SYMBOL_STACK_INDEX: 0

SYMBOL_NAME: SIDisk!StartIo+d0

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: SIDisk

IMAGE_NAME: SIDisk.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4ee245c0

STACK_COMMAND: .cxr 0xfffffa6002dd1d90 ; kb

FAILURE_BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

Followup: MachineOwner

3: kd> !irp 0xfffffa814de294b0
Irp is active with 2 stacks 2 is current (= 0xfffffa814de295c8)
No Mdl: No System Buffer: Thread fffffa8005add720: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
>[1b, 2] 0 0 fffffa8149629060 00000000 00000000-00000000
\Driver\SIDisk
Args: 00000000 00000000 00000000 00000000

The fault is actually being caused by the DBGPRINT message at the start of
the function.

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

Doron_Holan · December 9, 2011, 3:52pm

Joe, you are quoting the wrong FM in this case.

HwScsiStartIo
http://msdn.microsoft.com/en-us/library/windows/hardware/ff557323(v=vs.85).aspx

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@flounder.com
Sent: Friday, December 09, 2011 12:47 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] StartIo receiving bad device context

Take a look at the spec for StartIo: you are passed a pointer to the device object, not the device extension.

For example,

http://www.osronline.com/ddkx/kmarch/drvrrtns_6isy.htm

Would be a good start. RTFM helps; note that StartIo is documented as returning NTSTATUS, not BOOLEAN, and the first parameter is specified as a PDEVICE_OBJECT, not a PVOID. And the second parameter is a PIRP. If you are not using StartIo queuing, it is a Bad Idea to re-use a semantically-loaded name for a different purpose.
Joe

Thanks for the reply Doron. I’m pretty sure that I’m being passed
that value because the fault is happening at the beginning of the
function in a debug print that announces function entry.

BOOLEAN
StartIo(
IN PVOID devExt,
IN PSCSI_REQUEST_BLOCK srb
)
{
BOOLEAN retval = FALSE;
skd_device_t * device_context =
(skd_device_t*)devExt;

DBGPRINT( (device_context->instanceNumber, SD_COMP_IO,
SD_SUBCOMP_FUNCTIONS, FUNC “: Enter. SRB Function=0x%08X,
SrbStatus=%X, TimeoutValue=%u\n”, srb->Function, srb->SrbStatus,
srb->TimeOutValue) );

Probably caused by : SIDisk.sys ( SIDisk!StartIo+d0 )

Followup: MachineOwner

nt!RtlpBreakWithStatusInstruction:
fffff800`0185f720 cc int 3
3: kd> !analyze -v
**********************************************************************
*********
*
*
* Bugcheck Analysis
*
*
*
**********************************************************************
*********

SYSTEM_THREAD_EXCEPTION_NOT_HANDLED (7e) This is a very common
bugcheck. Usually the exception address pinpoints the driver/function
that caused the problem. Always note this address as well as the link
date of the driver/image that contains this address.
Arguments:
Arg1: ffffffffc0000005, The exception code that was not handled
Arg2: fffffa6000e0c5d0, The address that the exception occurred at
Arg3: fffffa6002dd23b8, Exception Record Address
Arg4: fffffa6002dd1d90, Context Record Address

Debugging Details:

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx
referenced memory at 0x%08lx. The memory could not be %s.

FAULTING_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

EXCEPTION_RECORD: fffffa6002dd23b8 – (.exr 0xfffffa6002dd23b8)
ExceptionAddress: fffffa6000e0c5d0 (SIDisk!StartIo+0x00000000000000d0)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000000
Parameter[1]: 0000000000000010
Attempt to read from address 0000000000000010

CONTEXT: fffffa6002dd1d90 – (.cxr 0xfffffa6002dd1d90)
rax=0000000000000008 rbx=fffffa81496291b0 rcx=0000000000000025
rdx=0000000000000005 rsi=fffffa800680a810 rdi=fffffa6008b84010
rip=fffffa6000e0c5d0 rsp=fffffa6002dd25f0 rbp=0000000000000000
r8=0000000000000040 r9=fffffa6000e195f0 r10=0000000000000000
r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
r14=fffffa8149629060 r15=fffffa6001e46110
iopl=0 nv up ei pl nz na pe nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b
efl=00010202
SIDisk!StartIo+0xd0:
fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8] ds:002b:0000000000000010=???
Resetting default scope

PROCESS_NAME: System

CURRENT_IRQL: 2

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx
referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1: 0000000000000000

EXCEPTION_PARAMETER2: 0000000000000010

READ_ADDRESS: 0000000000000010

FOLLOWUP_IP:
SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa60`00e0c5d0 8b4808 mov ecx,dword ptr [rax+8]

BUGCHECK_STR: 0x7E

DEFAULT_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER: from fffffa6001e3a930 to fffffa6000e0c5d0

STACK_TEXT:
fffffa6002dd25f0 fffffa6001e3a930 : 0000000000000008 fffffa800680a810
fffffa80069988e0 fffffa6001e2d256 : SIDisk!StartIo+0xd0
[s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
fffffa6002dd2720 fffffa6001e3e9bc : fffffa6008b84000 fffffa800680a810
0000000000000000 fffffa81496291b0 :
storport!RaidAdapterPostScatterGatherExecute+0x150
fffffa6002dd2780 fffffa6001e7f655 : fffffffffffffc18 fffffa6000000002
fffffa81496291b0 fffffa81496291b0 :
storport!RaidPnPPassToMiniPort+0x22c
fffffa6002dd27f0 fffffa6001e7f6ef : fffffa81496291b0 fffffa8005f97060
0000000000000000 00000000c00000bb :
storport!RaidAdapterReleaseResources+0x35
fffffa6002dd2830 fffffa6001e80387 : fffffa814de294b0 0000000000000002
fffffa81496291b0 0000000000000000 :
storport!RaidAdapterRemoveDeviceIrp+0x5f
fffffa6002dd2860 fffffa6001e805d5 : fffffa814de294b0 00000000c00000bb
fffff880096f56b0 fffffa814de294b0 : storport!RaidAdapterPnpIrp+0x127
fffffa6002dd28c0 fffff80001a60632 : fffffa814de294b0 0000000000000000
fffffa6002dd29b8 fffff80001b869f9 : storport!RaDriverPnpIrp+0x95
fffffa6002dd2900 fffff80001c3f481 : fffffa8005f97060 0000000000000000
fffffa8005f96730 0000000000000002 : nt!IopSynchronousCall+0x10a
fffffa6002dd2970 fffff80001938476 : fffff880095b21d0 fffff880095b21d0
fffff880095b21d8 0000000000000000 : nt!IopRemoveDevice+0x101
fffffa6002dd2a30 fffff80001c3efc4 : fffffa8005f96730 0000000000000000
0000000000000002 fffffa8007f2eb20 :
nt!PnpRemoveLockedDeviceNode+0x1a6
fffffa6002dd2a80 fffff80001c3f0e0 : 0000000000000000 fffffa8005f96700
fffff880097af2d0 fffff8003f051397 :
nt!PnpDeleteLockedDeviceNode+0x44
fffffa6002dd2ab0 fffff80001c43797 : 0000000000000002 0000000000000000
0000000000000006 fffffa8005f96730 :
nt!PnpDeleteLockedDeviceNodes+0xa0
fffffa6002dd2b20 fffff80001c43dcc : fffffa6002dd2cf8 fffffa800670e700
fffffa8005add700 fffffa8000000000 :
nt!PnpProcessQueryRemoveAndEject+0xbe7
fffffa6002dd2c70 fffff80001b42dca : 0000000000000001 fffffa800670e7d0
fffff880097b7ae0 0000000000000000 :
nt!PnpProcessTargetDeviceEvent+0x4c
fffffa6002dd2ca0 fffff8000186c8cb : fffff80001a62870 fffff880097b7ae0
fffff8000199c8f8 fffffa8005add720 : nt! ??
::NNGAKEGL::string'+0x4e537 fffffa6002dd2cf0 fffff80001a6ff97 : fffffa800670e7d0
34383438d078d078 fffffa8005add720 0000000000000080 : nt!ExpWorkerThread+0xfb fffffa6002dd2d50 fffff800018a25c6 : fffffa60029d8180
fffffa8005add720 fffffa60029e1d40 fffffa8005adf138 : nt!PspSystemThreadStartup+0x57 fffffa6002dd2d80 0000000000000000 : 0000000000000000
0000000000000000 0000000000000000 00000000`00000000 : nt!KiStartSystemThread+0x16

SYMBOL_STACK_INDEX: 0

SYMBOL_NAME: SIDisk!StartIo+d0

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: SIDisk

IMAGE_NAME: SIDisk.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4ee245c0

STACK_COMMAND: .cxr 0xfffffa6002dd1d90 ; kb

FAILURE_BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0

Followup: MachineOwner

3: kd> !irp 0xfffffa814de294b0
Irp is active with 2 stacks 2 is current (= 0xfffffa814de295c8) No
Mdl: No System Buffer: Thread fffffa8005add720: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
>[1b, 2] 0 0 fffffa8149629060 00000000 00000000-00000000
\Driver\SIDisk
Args: 00000000 00000000 00000000 00000000

The fault is actually being caused by the DBGPRINT message at the
start of the function.

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

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

James_Antognini-3 · December 9, 2011, 4:44pm

Just for the record, this is the correct URL for this callback: http://msdn.microsoft.com/en-us/library/windows/hardware/ff557423(v=vs.85).aspx.

The first parameter is the address of the per-HBA area for the miniport (despite the MSDN name of ‘DeviceExtension’), so this is effectively a context area.

Doron’s point, I believe, is that DeviceExtension=0x8 probably resulted from StorPort starting with an address of NULL and pointing with that to a member at offset of 0x8 in the structure addressed by NULL. That is, the context would be a member/imbedded structure in something like:

typedef struct _Stuff {
ULONG something 1;
ULONG something 2;
UCHAR HBAContext[256];
…
} Stuff, * pStuff;

Note that I made this structure up; it is not the actual structure StorPort uses, as far as I can imagine. So my working hypothesis is that somehow StorPort has a NULL pointer to whatever structure contains your miniport’s per-HBA area/context. I don’t know why that might be. I can only guess that it is connected with the fact that StorPort was sending an SRB, probably a PnP SRB (I hope you were using the correct mapping for such an SRB, if you got that far), as part of device removal.

James

OSR_Community_User · December 9, 2011, 5:03pm

So if the name had been given as HwScsiStartIo the it would have been more
apparent. I go back to my comment about using semantically loaded names.
Unfortunately, I see this all the time, like the guy who rewrote strcmp to
return 0 if not equal and 1 if equal, or the guy who was convinced that
two different drivers could not both have a routine called “DriverEntry”
and figured out how to change it for each of the six drivers he wrote. A
nontrivial effort. The result was unintelligible and in maintainable code.
Joe

Joe, you are quoting the wrong FM in this case.

HwScsiStartIo
http://msdn.microsoft.com/en-us/library/windows/hardware/ff557323(v=vs.85).aspx

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@flounder.com
Sent: Friday, December 09, 2011 12:47 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] StartIo receiving bad device context

Take a look at the spec for StartIo: you are passed a pointer to the
device object, not the device extension.

For example,

http://www.osronline.com/ddkx/kmarch/drvrrtns_6isy.htm

Would be a good start. RTFM helps; note that StartIo is documented as
returning NTSTATUS, not BOOLEAN, and the first parameter is specified as a
PDEVICE_OBJECT, not a PVOID. And the second parameter is a PIRP. If you
are not using StartIo queuing, it is a Bad Idea to re-use a
semantically-loaded name for a different purpose.
Joe

> Thanks for the reply Doron. I’m pretty sure that I’m being passed
> that value because the fault is happening at the beginning of the
> function in a debug print that announces function entry.
>
> BOOLEAN
> StartIo(
> IN PVOID devExt,
> IN PSCSI_REQUEST_BLOCK srb
> )
> {
> BOOLEAN retval = FALSE;
> skd_device_t * device_context =
> (skd_device_t*)devExt;
>
> DBGPRINT( (device_context->instanceNumber, SD_COMP_IO,
> SD_SUBCOMP_FUNCTIONS, FUNC “: Enter. SRB Function=0x%08X,
> SrbStatus=%X, TimeoutValue=%u\n”, srb->Function, srb->SrbStatus,
> srb->TimeOutValue) );
>
>
>
> Probably caused by : SIDisk.sys ( SIDisk!StartIo+d0 )
>
> Followup: MachineOwner
> ---------
>
> nt!RtlpBreakWithStatusInstruction:
> fffff8000185f720 cc int 3 \> 3: kd\> !analyze -v \> \*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\* \> \*\*\*\*\*\*\*\*\* \> \* \> \* \> \* Bugcheck Analysis \> \* \> \* \> \* \> \*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\* \> \*\*\*\*\*\*\*\*\* \> \> SYSTEM_THREAD_EXCEPTION_NOT_HANDLED (7e) This is a very common \> bugcheck. Usually the exception address pinpoints the driver/function \> that caused the problem. Always note this address as well as the link \> date of the driver/image that contains this address. \> Arguments: \> Arg1: ffffffffc0000005, The exception code that was not handled \> Arg2: fffffa6000e0c5d0, The address that the exception occurred at \> Arg3: fffffa6002dd23b8, Exception Record Address \> Arg4: fffffa6002dd1d90, Context Record Address \> \> Debugging Details: \> ------------------ \> \> \> EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx \> referenced memory at 0x%08lx. The memory could not be %s. \> \> FAULTING_IP: \> SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109] \> fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8]
>
> EXCEPTION_RECORD: fffffa6002dd23b8 – (.exr 0xfffffa6002dd23b8)
> ExceptionAddress: fffffa6000e0c5d0 (SIDisk!StartIo+0x00000000000000d0)
> ExceptionCode: c0000005 (Access violation)
> ExceptionFlags: 00000000
> NumberParameters: 2
> Parameter[0]: 0000000000000000
> Parameter[1]: 0000000000000010
> Attempt to read from address 0000000000000010
>
> CONTEXT: fffffa6002dd1d90 – (.cxr 0xfffffa6002dd1d90)
> rax=0000000000000008 rbx=fffffa81496291b0 rcx=0000000000000025
> rdx=0000000000000005 rsi=fffffa800680a810 rdi=fffffa6008b84010
> rip=fffffa6000e0c5d0 rsp=fffffa6002dd25f0 rbp=0000000000000000
> r8=0000000000000040 r9=fffffa6000e195f0 r10=0000000000000000
> r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
> r14=fffffa8149629060 r15=fffffa6001e46110
> iopl=0 nv up ei pl nz na pe nc
> cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b
> efl=00010202
> SIDisk!StartIo+0xd0:
> fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8] \> ds:002b:0000000000000010=???
> Resetting default scope
>
> PROCESS_NAME: System
>
> CURRENT_IRQL: 2
>
> ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx
> referenced memory at 0x%08lx. The memory could not be %s.
>
> EXCEPTION_PARAMETER1: 0000000000000000
>
> EXCEPTION_PARAMETER2: 0000000000000010
>
> READ_ADDRESS: 0000000000000010
>
> FOLLOWUP_IP:
> SIDisk!StartIo+d0 [s:\sandbox\windows\drivers\sidisk\startio.c @ 109]
> fffffa6000e0c5d0 8b4808 mov ecx,dword ptr [rax+8] \> \> BUGCHECK_STR: 0x7E \> \> DEFAULT_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE \> \> LAST_CONTROL_TRANSFER: from fffffa6001e3a930 to fffffa6000e0c5d0 \> \> STACK_TEXT: \> fffffa6002dd25f0 fffffa6001e3a930 : 0000000000000008
> fffffa800680a810 \> fffffa80069988e0 fffffa6001e2d256 : SIDisk!StartIo+0xd0 \> [s:\sandbox\windows\drivers\sidisk\startio.c @ 109] \> fffffa6002dd2720 fffffa6001e3e9bc : fffffa6008b84000
> fffffa800680a810 \> 0000000000000000 fffffa81496291b0 : \> storport!RaidAdapterPostScatterGatherExecute+0x150 \> fffffa6002dd2780 fffffa6001e7f655 : fffffffffffffc18
> fffffa6000000002 \> fffffa81496291b0 fffffa81496291b0 : \> storport!RaidPnPPassToMiniPort+0x22c \> fffffa6002dd27f0 fffffa6001e7f6ef : fffffa81496291b0
> fffffa8005f97060 \> 0000000000000000 00000000c00000bb : \> storport!RaidAdapterReleaseResources+0x35 \> fffffa6002dd2830 fffffa6001e80387 : fffffa814de294b0
> 0000000000000002 \> fffffa81496291b0 0000000000000000 : \> storport!RaidAdapterRemoveDeviceIrp+0x5f \> fffffa6002dd2860 fffffa6001e805d5 : fffffa814de294b0
> 00000000c00000bb \> fffff880096f56b0 fffffa814de294b0 : storport!RaidAdapterPnpIrp+0x127 \> fffffa6002dd28c0 fffff80001a60632 : fffffa814de294b0
> 0000000000000000 \> fffffa6002dd29b8 fffff80001b869f9 : storport!RaDriverPnpIrp+0x95 \> fffffa6002dd2900 fffff80001c3f481 : fffffa8005f97060
> 0000000000000000 \> fffffa8005f96730 0000000000000002 : nt!IopSynchronousCall+0x10a \> fffffa6002dd2970 fffff80001938476 : fffff880095b21d0
> fffff880095b21d0 \> fffff880095b21d8 0000000000000000 : nt!IopRemoveDevice+0x101 \> fffffa6002dd2a30 fffff80001c3efc4 : fffffa8005f96730
> 0000000000000000 \> 0000000000000002 fffffa8007f2eb20 : \> nt!PnpRemoveLockedDeviceNode+0x1a6 \> fffffa6002dd2a80 fffff80001c3f0e0 : 0000000000000000
> fffffa8005f96700 \> fffff880097af2d0 fffff8003f051397 : \> nt!PnpDeleteLockedDeviceNode+0x44 \> fffffa6002dd2ab0 fffff80001c43797 : 0000000000000002
> 0000000000000000 \> 0000000000000006 fffffa8005f96730 : \> nt!PnpDeleteLockedDeviceNodes+0xa0 \> fffffa6002dd2b20 fffff80001c43dcc : fffffa6002dd2cf8
> fffffa800670e700 \> fffffa8005add700 fffffa8000000000 : \> nt!PnpProcessQueryRemoveAndEject+0xbe7 \> fffffa6002dd2c70 fffff80001b42dca : 0000000000000001
> fffffa800670e7d0 \> fffff880097b7ae0 0000000000000000 : \> nt!PnpProcessTargetDeviceEvent+0x4c \> fffffa6002dd2ca0 fffff8000186c8cb : fffff80001a62870
> fffff880097b7ae0 \> fffff8000199c8f8 fffffa8005add720 : nt! ?? \> ::NNGAKEGL::string’+0x4e537
> fffffa6002dd2cf0 fffff80001a6ff97 : fffffa800670e7d0 \> 34383438d078d078
> fffffa8005add720 0000000000000080 : nt!ExpWorkerThread+0xfb
> fffffa6002dd2d50 fffff800018a25c6 : fffffa60029d8180 \> fffffa8005add720
> fffffa60029e1d40 fffffa8005adf138 : nt!PspSystemThreadStartup+0x57
> fffffa6002dd2d80 0000000000000000 : 0000000000000000 \> 0000000000000000
> 0000000000000000 0000000000000000 : nt!KiStartSystemThread+0x16
>
>
> SYMBOL_STACK_INDEX: 0
>
> SYMBOL_NAME: SIDisk!StartIo+d0
>
> FOLLOWUP_NAME: MachineOwner
>
> MODULE_NAME: SIDisk
>
> IMAGE_NAME: SIDisk.sys
>
> DEBUG_FLR_IMAGE_TIMESTAMP: 4ee245c0
>
> STACK_COMMAND: .cxr 0xfffffa6002dd1d90 ; kb
>
> FAILURE_BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0
>
> BUCKET_ID: X64_0x7E_SIDisk!StartIo+d0
>
> Followup: MachineOwner
> ---------
>
> 3: kd> !irp 0xfffffa814de294b0
> Irp is active with 2 stacks 2 is current (= 0xfffffa814de295c8) No
> Mdl: No System Buffer: Thread fffffa8005add720: Irp stack trace.
> cmd flg cl Device File Completion-Context
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
>>[1b, 2] 0 0 fffffa8149629060 00000000 00000000-00000000
> \Driver\SIDisk
> Args: 00000000 00000000 00000000 00000000
>
>
> The fault is actually being caused by the DBGPRINT message at the
> start of the function.
>
>
>
>
> —
> 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
>

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

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

Jeff_Glass · December 9, 2011, 5:10pm

Its definitely a PnP removal SRB. I dumped it in that wall of text above. Here it is again (below).

What I don’t know if this is the same Removal I processed and completed just before the DriverEntry got called, or if this is a new removal that’s associated with the new driver instance. Since I’m getting this StartIo call before even FindAdapter, it’s plausible to me that the null device context is associated with the new driver instance. Conversely, it could be a nulled out device context from the old instance. If no one posts with insight into this within the next couple days, I’ll open a support case and post the results here. I just can’t think of anything I could be doing that would cause this, but I thought someone else might have experienced and been able to post “don’t do X stupid”. I guess I did get a “don’t do X stupid”, but it was off base. Be careful what you wish for apparently.

There is no outstanding I/O.
The first removal SRB has been processed and completed (interrupts turned off & device quiesced)
AdapterControl has been called three times as part of the typical removal sequence.
DriverEntry is called for the reload.
Out of the blue this oddball StartIo call.

3: kd> dt _SCSI_PNP_REQUEST_BLOCK 0xfffffa800680a810
SIDisk!_SCSI_PNP_REQUEST_BLOCK
+0x000 Length : 0x58
+0x002 Function : 0x25 'Unknown format characterUnknown format
control character
+0x003 SrbStatus : 0 ‘’
+0x004 PnPSubFunction : 0 ‘’
+0x005 PathId : 0 ‘’
+0x006 TargetId : 0 ‘’
+0x007 Lun : 0 ‘’
+0x008 PnPAction : 2 ( StorRemoveDevice )
+0x00c SrbFlags : 0x100
+0x010 DataTransferLength : 0
+0x014 TimeOutValue : 0xa
+0x018 DataBuffer : (null)
+0x020 SenseInfoBuffer : (null)
+0x028 NextSrb : (null)
+0x030 OriginalRequest : 0xfffffa6008b84010 +0x038 SrbExtension : 0xfffffa6008b84380
+0x040 SrbPnPFlags : 1
+0x044 Reserved : 0
+0x048 Reserved4 : [16] “”

OSR_Community_User · December 9, 2011, 5:15pm

It’s more like

typedef struct _Stuff {
PDEVICE_EXTENSION pStorPortDevExt;
UCHAR HwDeviceExtension [Miniport driver’s extension size];
…
} Stuff, * pStuff;

If you disassemble just about any of the StorPortXxx function calls you
can see that this is true; for example

StorPortGetDeviceBase:
00015776: 55 push ebp
00015777: 8B EC mov ebp,esp
00015779: 51 push ecx
0001577A: 51 push ecx
0001577B: 8B 45 08 mov eax,dword ptr [ebp+8] ;
pHwDeviceExtension
0001577E: 8B 40 FC mov eax,dword ptr [eax-4] ;
pStorPortDevExt
…

Now, this is a disassembly of a very old x86 StorPort.sys so an x64
StorProt would use an offset of -8.

Looks like somebody has NULLed out a pStuff and used that to generate the
pHwDeviceExtension to pass to the miniport.

Same idea but …

xxxxx@mindspring.com
Sent by: xxxxx@lists.osr.com
12/09/2011 04:44 PM
Please respond to
“Windows System Software Devs Interest List”

To
“Windows System Software Devs Interest List”
cc

Subject
RE:[ntdev] StartIo receiving bad device context

Just for the record, this is the correct URL for this callback:
http://msdn.microsoft.com/en-us/library/windows/hardware/ff557423(v=vs.85).aspx
.

The first parameter is the address of the per-HBA area for the miniport
(despite the MSDN name of ‘DeviceExtension’), so this is effectively a
context area.

Doron’s point, I believe, is that DeviceExtension=0x8 probably resulted
from StorPort starting with an address of NULL and pointing with that to a
member at offset of 0x8 in the structure addressed by NULL. That is, the
context would be a member/imbedded structure in something like:

typedef struct _Stuff {
ULONG something 1;
ULONG something 2;
UCHAR HBAContext[256];
…
} Stuff, * pStuff;

Note that I made this structure up; it is not the actual structure
StorPort uses, as far as I can imagine. So my working hypothesis is that
somehow StorPort has a NULL pointer to whatever structure contains your
miniport’s per-HBA area/context. I don’t know why that might be. I can
only guess that it is connected with the fact that StorPort was sending an
SRB, probably a PnP SRB (I hope you were using the correct mapping for
such an SRB, if you got that far), as part of device removal.

James

—
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

Alex_Grig · December 9, 2011, 6:15pm

Try to run it with the DriverVerifier, standard settings + special pool.

James_Antognini-3 · December 10, 2011, 6:11am

Jeff,

The flag in SrbPnPFlags indicates the SRB applies to the HBA, and the SRB indicates it’s a removal because of PnPAction=StorRemoveDevice. It looks like a bug that StorPort gave you a bad HBA extension pointer, but Microsoft support would make that determination.

That said, are you sure that FindAdapter wasn’t called for a new HBA and that if it was called, that it reported success? I ask because the second-to-last comment at https://www.osronline.com/showThread.CFM?link=152676 suggests that non-success from FindAdapter would result in HBA removal and hence the kind of SRB you are seeing. Maybe that’s the circumstance that led to this putative bug appearing.

James

Alex_Grig · December 10, 2011, 6:13pm

Jeff,

What is the test tool doing? does it install a filter above your port? Set a breakpoint in your RemoveDevice handler, and issue !devstack for your stack PDO (you can find it using !devnode command). If you’ll see another DevfObj above your port, then I suspect the filter mishandles the remove IRP, or is sending a spurious one.

James_Antognini-3 · December 11, 2011, 12:35am

Jeff,

If your driver’s FindAdapter is not getting control, there is a possibility that your test tool is stopping the HBA whilst it is in the middle of being started. In that case, it’s conceivable that StorPort is handling a Stop Device IRP before it has fully initialized the miniport’s structures.

James

Jeff_Glass · December 12, 2011, 11:40am

James: 100% sure FindAdapter isn’t being called.

Alex: Thanks for the suggestions. Its been a while since I ran verifier against this driver, and I didn’t think to look for a filter. It doesn’t look like DriveMaster uses a filter. I think it’s just using SetupDI*/CM* to disable and enable the device because if I keep devmgmt.msc open while the test is running I see my device come up with a disabled marker occassionally. The SetupDI*/CM* calls are imports for the executable too. Particularly suspicious is CM_Reenumerate_DevNode.

I’m trying to reproduce a failure now with Verifier enabled on both my driver and on storport itself. It usually takes a few hours of hammering on the device with I/O and resets for the problem to pop up.

Alex_Grig · December 12, 2011, 4:27pm

Jeff,

How do you complete StorRemoveDevice SRB? What status do you set to SrbStatus? How do you handle StorSurpriseRemoval?