BSOD in ndis.sys after resume from StandBy or Hibernate

OSR_Community_User · September 17, 2009, 12:07pm

Dear Gentlemen`s,

I have implemented NDIS IM pass-through driver, and all its
functionality works fine except one.
The system failed to resume after StandBy or Hibernate with BSOD in
ndis.sys.
When my driver uninstalled, the system resume fine.

I will appreciate for any help to start research with.

The crashdump analysis is bellow:

Loading Dump File [D:.crash\MEMORY.DMP]
Kernel Summary Dump File: Only kernel address space is available

WARNING: Inaccessible path: ‘C:.crash’
Symbol search path is:
D:.crash;C:.crash;srv*D:.symbols*http://msdl.microsoft.com/download/symbols;srv\*D:\.symbols\*https://codepremium.msdn.microsoft.com/Symbols
Executable search path is:
Windows XP Kernel Version 2600 (Service Pack 3) MP (2 procs) Free x86
compatible
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 2600.xpsp_sp3_gdr.090206-1234
Machine Name:
Kernel base = 0x804d7000 PsLoadedModuleList = 0x8055d720
Debug session time: Thu Sep 17 18:36:51.453 2009 (GMT+3)
System Uptime: 0 days 0:02:10.994
Loading Kernel Symbols
…
…
Loading User Symbols

Loading unloaded module list
…
*******************************************************************************
*
*
* Bugcheck
Analysis *
*
*
*******************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck D1, {0, 2, 0, b9cfc0b8}

Probably caused by : NDIS.sys ( NDIS!ndisMSyncQueryInformationComplete+32 )

Followup: MachineOwner

1: kd> !analyze -v
*******************************************************************************
*
*
* Bugcheck
Analysis *
*
*
*******************************************************************************

DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
An attempt was made to access a pageable (or completely invalid) address
at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If kernel debugger is available get stack backtrace.
Arguments:
Arg1: 00000000, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4: b9cfc0b8, address which referenced memory

Debugging Details:

READ_ADDRESS: 00000000

CURRENT_IRQL: 2

FAULTING_IP:
NDIS!ndisMSyncQueryInformationComplete+32
b9cfc0b8 8b0f mov ecx,dword ptr [edi]

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0xD1

PROCESS_NAME: System

TRAP_FRAME: b8c6cca8 – (.trap 0xffffffffb8c6cca8)
ErrCode = 00000000
eax=8a5ad884 ebx=00000000 ecx=00000000 edx=c0010011 esi=8a5ad748
edi=00000000
eip=b9cfc0b8 esp=b8c6cd1c ebp=b8c6cd30 iopl=0 nv up ei pl zr na
pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010246
NDIS!ndisMSyncQueryInformationComplete+0x32:
b9cfc0b8 8b0f mov ecx,dword ptr [edi]
ds:0023:00000000=???
Resetting default scope

LAST_CONTROL_TRANSFER: from b9cfc0b8 to 805446f0

STACK_TEXT:
b8c6cca8 b9cfc0b8 badb0d00 c0010011 8a21c76c nt!KiTrap0E+0x238
b8c6cd30 b9cfc362 00000000 8a7728b0 8a5ad748
NDIS!ndisMSyncQueryInformationComplete+0x32
b8c6cd58 b9cf8a11 8a7728b0 8a5ad748 8a45f290 NDIS!ndisMDoRequests+0x30c
b8c6cd74 b9cfc3a6 8a7728b0 8a45f290 8a4642d8 NDIS!ndisMRequest+0xfc
b8c6cd98 b9ce9baa 8a4642c0 00000000 8a2ff2a8 NDIS!ndisMRundownRequests+0x32
b8c6cdac 805cff70 8a4642c8 00000000 00000000 NDIS!ndisWorkerThread+0x75
b8c6cddc 805460ee b9ce9b85 8a4642c8 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
NDIS!ndisMSyncQueryInformationComplete+32
b9cfc0b8 8b0f mov ecx,dword ptr [edi]

SYMBOL_STACK_INDEX: 1

SYMBOL_NAME: NDIS!ndisMSyncQueryInformationComplete+32

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: NDIS

IMAGE_NAME: NDIS.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 48025d03

FAILURE_BUCKET_ID: 0xD1_NDIS!ndisMSyncQueryInformationComplete+32

BUCKET_ID: 0xD1_NDIS!ndisMSyncQueryInformationComplete+32

Followup: MachineOwner

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

Maxim_S_Shatskih · September 17, 2009, 7:38pm

> The system failed to resume after StandBy or Hibernate with BSOD in

ndis.sys.

Try checked build of NDIS.SYS

–
Maxim S. Shatskih
Windows DDK MVP
xxxxx@storagecraft.com
http://www.storagecraft.com

Calvin_Guan-2 · September 17, 2009, 9:51pm

This is a null ptr dereferencing in the sync oid query completion path which is easy to identify. Typical causes are you clobbered something accidentally, or retturn something that ndis doesn’t like.

If you can read assembly, you could find the OID that’s choking in stack or in registers or in ndis internal structure.

If you’re sick of reading assembly (like I did recently), you just printk all query request from the driver, the last one appears in the debugger is the OID you’re looking for. Once it’s identified, take a closer look at how the OID is being handled in your driver.

Calvin Guan
Broadcom Corp.
Connecting Everything(r)

OSR_Community_User · September 18, 2009, 5:23am

Maxim S. Shatskih Ð¿Ð¸ÑˆÐµÑ‚:

> The system failed to resume after StandBy or Hibernate with BSOD in
> ndis.sys.
>
Try checked build of NDIS.SY

Thank you, hope it will help.

Best regards,

Andrew Rukavishnikov
Sunbay Innovations Ltd.

OSR_Community_User · September 18, 2009, 5:27am

xxxxx@yahoo.ca Ð¿Ð¸ÑˆÐµÑ‚:

This is a null ptr dereferencing in the sync oid query completion path which is easy to identify. Typical causes are you clobbered something accidentally, or retturn something that ndis doesn’t like.

If you can read assembly, you could find the OID that’s choking in stack or in registers or in ndis internal structure.

If you’re sick of reading assembly (like I did recently), you just printk all query request from the driver, the last one appears in the debugger is the OID you’re looking for. Once it’s identified, take a closer look at how the OID is being handled in your driver.
The problem is that I was not able to start debugging when system goes from StandBy or Hibernate,
The start session is ok, then system goes down, and after resuming, just a 2 seconds latter I have
a BSOD, and no debug session restoration. May be I need to read about how to debug Hibernate or
Sleep modes…

Anyway will try to look into stack for faulting OID…

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

OSR_Community_User · September 18, 2009, 7:00am

Maxim S. Shatskih wrote:

> The system failed to resume after StandBy or Hibernate with BSOD in
> ndis.sys.
>

Try checked build of NDIS.SYS

Bellow is a crash dump analysis of checked version of NDIS.SYS
Any conclusion about which invalid request caused this BSOD?

Loading Dump File [D:.crash\MEMORY.DMP]
Kernel Summary Dump File: Only kernel address space is available

WARNING: Inaccessible path: ‘C:.crash’
Symbol search path is:
D:.crash;C:.crash;srv*D:.symbols*http://msdl.microsoft.com/download/symbols;srv\*D:\.symbols\*https://codepremium.msdn.microsoft.com/Symbols
Executable search path is:
Windows XP Kernel Version 2600 (Service Pack 3) MP (2 procs) Free x86
compatible
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 2600.xpsp_sp3_gdr.090206-1234
Machine Name:
Kernel base = 0x804d7000 PsLoadedModuleList = 0x8055d720
Debug session time: Fri Sep 18 13:35:20.203 2009 (GMT+3)
System Uptime: 0 days 0:02:49.859
Loading Kernel Symbols
…
…
Loading User Symbols

Loading unloaded module list
…
*******************************************************************************
*
*
* Bugcheck
Analysis *
*
*
*******************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck 7E, {80000003, 80531e9d, a79868c8, a79865c4}

Probably caused by : NDIS.sys ( NDIS!ndisMSyncQueryInformationComplete+74 )

Followup: MachineOwner

1: 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: 80000003, The exception code that was not handled
Arg2: 80531e9d, The address that the exception occurred at
Arg3: a79868c8, Exception Record Address
Arg4: a79865c4, Context Record Address

Debugging Details:

EXCEPTION_CODE: (HRESULT) 0x80000003 (2147483651) - One or more
arguments are invalid

FAULTING_IP:
nt!DebugService+1b
80531e9d cc int 3

EXCEPTION_RECORD: a79868c8 – (.exr 0xffffffffa79868c8)
ExceptionAddress: 80531e9d (nt!DebugService+0x0000001b)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 3
Parameter[0]: 00000002
Parameter[1]: 8052cc7a
Parameter[2]: 00000056

CONTEXT: a79865c4 – (.cxr 0xffffffffa79865c4)
eax=00000002 ebx=a7986a0c ecx=8052cc7a edx=00000056 esi=8052cc7b
edi=00000002
eip=80531e9d esp=a7986990 ebp=a79869a4 iopl=0 nv up ei pl nz ac
pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00000216
nt!DebugService+0x1b:
80531e9d cc int 3
Resetting default scope

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x7E

PROCESS_NAME: System

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION} Breakpoint A
breakpoint has been reached.

EXCEPTION_PARAMETER1: 00000002

EXCEPTION_PARAMETER2: 8052cc7a

EXCEPTION_PARAMETER3: 00000056

LAST_CONTROL_TRANSFER: from 80531f13 to 80531e9d

ASSERT_DATA: Request != NULL

ASSERT_FILE_LOCATION: d:\xpsp\net\ndis\sys\requestm.c at Line 2492

STACK_TEXT:
a79869a4 80531f13 00000002 8052cc7a 00000056 nt!DebugService+0x1b
a79869c0 8052b7c6 a79869d4 a79869dc 8052cc1d nt!DebugPrompt+0x21
a79869e4 8052cd92 8052cc7a a7986a0c 00000002 nt!DbgPrompt+0x3c
a7986ce0 8052ce40 b9ce887a b9ce885a 000009bc nt!RtlAssert2+0x98
a7986cfc b9ce8f2e b9ce887a b9ce885a 000009bc nt!RtlAssert+0x18
a7986d20 b9ce7649 8a3aeac8 c0010011 00000000
NDIS!ndisMSyncQueryInformationComplete+0x74
a7986d50 b9cd9b9a 8a3aeac8 8a4694e0 8a3aeac8 NDIS!ndisMDoRequests+0x3ff
a7986d6c b9cec30e 004694e0 8a19a6d0 8a3831c0 NDIS!ndisMRequest+0x156
a7986d94 b9cbab92 8a3831a8 00000000 8a38ca60 NDIS!ndisMRundownRequests+0x50
a7986dac 805cff70 8a3831b0 00000000 00000000 NDIS!ndisWorkerThread+0xde
a7986ddc 805460ee b9cbaab4 8a3831b0 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

FOLLOWUP_IP:
NDIS!ndisMSyncQueryInformationComplete+74
b9ce8f2e 8b0f mov ecx,dword ptr [edi]

SYMBOL_STACK_INDEX: 5

SYMBOL_NAME: NDIS!ndisMSyncQueryInformationComplete+74

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: NDIS

IMAGE_NAME: NDIS.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4802ae44

STACK_COMMAND: .cxr 0xffffffffa79865c4 ; kb

FAILURE_BUCKET_ID: 0x7E_NDIS!ndisMSyncQueryInformationComplete+74

BUCKET_ID: 0x7E_NDIS!ndisMSyncQueryInformationComplete+74

Followup: MachineOwner

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

David_R_Cattley · September 18, 2009, 7:57am

Now that you have got the checked build of NDIS installed (the hard part)
you ought to also enable the verbose debug output too. This can be done by
setting values in the registry or with the !ndiskd debug extension.

http://support.microsoft.com/kb/248413

Followup: MachineOwner

1: 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: 80000003, The exception code that was not handled
Arg2: 80531e9d, The address that the exception occurred at
Arg3: a79868c8, Exception Record Address
Arg4: a79865c4, Context Record Address

Debugging Details:

EXCEPTION_CODE: (HRESULT) 0x80000003 (2147483651) - One or more
arguments are invalid

FAULTING_IP:
nt!DebugService+1b
80531e9d cc int 3

EXCEPTION_RECORD: a79868c8 – (.exr 0xffffffffa79868c8)
ExceptionAddress: 80531e9d (nt!DebugService+0x0000001b)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 3
Parameter[0]: 00000002
Parameter[1]: 8052cc7a
Parameter[2]: 00000056

CONTEXT: a79865c4 – (.cxr 0xffffffffa79865c4)
eax=00000002 ebx=a7986a0c ecx=8052cc7a edx=00000056 esi=8052cc7b
edi=00000002
eip=80531e9d esp=a7986990 ebp=a79869a4 iopl=0 nv up ei pl nz ac
pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00000216
nt!DebugService+0x1b:
80531e9d cc int 3
Resetting default scope

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x7E

PROCESS_NAME: System

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION} Breakpoint A
breakpoint has been reached.

EXCEPTION_PARAMETER1: 00000002

EXCEPTION_PARAMETER2: 8052cc7a

EXCEPTION_PARAMETER3: 00000056

LAST_CONTROL_TRANSFER: from 80531f13 to 80531e9d

ASSERT_DATA: Request != NULL

ASSERT_FILE_LOCATION: d:\xpsp\net\ndis\sys\requestm.c at Line 2492

STACK_TEXT:
a79869a4 80531f13 00000002 8052cc7a 00000056 nt!DebugService+0x1b
a79869c0 8052b7c6 a79869d4 a79869dc 8052cc1d nt!DebugPrompt+0x21
a79869e4 8052cd92 8052cc7a a7986a0c 00000002 nt!DbgPrompt+0x3c
a7986ce0 8052ce40 b9ce887a b9ce885a 000009bc nt!RtlAssert2+0x98
a7986cfc b9ce8f2e b9ce887a b9ce885a 000009bc nt!RtlAssert+0x18
a7986d20 b9ce7649 8a3aeac8 c0010011 00000000
NDIS!ndisMSyncQueryInformationComplete+0x74
a7986d50 b9cd9b9a 8a3aeac8 8a4694e0 8a3aeac8 NDIS!ndisMDoRequests+0x3ff
a7986d6c b9cec30e 004694e0 8a19a6d0 8a3831c0 NDIS!ndisMRequest+0x156
a7986d94 b9cbab92 8a3831a8 00000000 8a38ca60 NDIS!ndisMRundownRequests+0x50
a7986dac 805cff70 8a3831b0 00000000 00000000 NDIS!ndisWorkerThread+0xde
a7986ddc 805460ee b9cbaab4 8a3831b0 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

FOLLOWUP_IP:
NDIS!ndisMSyncQueryInformationComplete+74
b9ce8f2e 8b0f mov ecx,dword ptr [edi]

SYMBOL_STACK_INDEX: 5

SYMBOL_NAME: NDIS!ndisMSyncQueryInformationComplete+74

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: NDIS

IMAGE_NAME: NDIS.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4802ae44

STACK_COMMAND: .cxr 0xffffffffa79865c4 ; kb

FAILURE_BUCKET_ID: 0x7E_NDIS!ndisMSyncQueryInformationComplete+74

BUCKET_ID: 0x7E_NDIS!ndisMSyncQueryInformationComplete+74

Followup: MachineOwner

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

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

OSR_Community_User · September 18, 2009, 8:16am

Thank you Dave, for such detailed description.

And yes you are completely right about NDIS_STATUS_ADAPTER_NOT_READY
(0xc0010011)
code which was returned by underlying driver.

I have enabled debug output of OID path in my driver and captured it
using dbgview at hibernate bootup time.
So when I experience BSOD in ndis this is always logged by my driver
(see the last line, after which crash occurred).

Also you can see that all previous request about OID_GEN_LINK_SPEED was
successful, this requests simple
redirected to underlying miniport and I always passthrough it and it
status, so it is a reply of underlying miniport about
adapter not ready status. How I can deal in such cases?

00006313 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006314 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006315 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006316 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006317 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006318 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006319 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006320 14:52:02 >>> [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006321 14:52:02 *** [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006322 14:52:02 <<< [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006323 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006324 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006325 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006326 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006327 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006337 14:52:02 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000001):
00006338 14:52:02 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006339 14:52:02 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000001):
00006340 14:52:02 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006341 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006342 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status
00000000
00006343 14:52:02 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006344 14:52:02 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status
00000000
00006345 14:52:02 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001):
00006346 14:52:02 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006347 14:52:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006348 14:52:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000004
00006349 14:52:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006350 14:52:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006351 14:52:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000004
00006352 14:52:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006353 14:52:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006354 14:52:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006355 14:52:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006368 14:52:03 [MUP]: DfscFsctrlStateTransition invoked.
00006369 14:52:03 [MUP]: Flushing pkt cache…[MUP]: done.
00006370 14:52:03 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000000):
00006371 14:52:03 *** [89E84674]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006372 14:52:03 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006381 14:52:03 <<< [89D27254] CProtocol::DelayedRemoval():
exited
00006382 14:52:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006383 14:52:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006384 14:52:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006459 14:53:03 watchdog!WdUpdateRecoveryState: Recovery
enabled.
00006513 14:53:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006514 14:53:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006515 14:53:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006529 14:53:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006530 14:53:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000001
00006531 14:53:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006532 14:53:03 >>> [89FA12EC] CMiniport::PnPEventNotify():
00006533 14:53:03 *** [89FA12EC] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006534 14:53:03 <<< [89FA12EC] CMiniport::PnPEventNotify():
exited
00006535 14:53:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006536 14:53:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000001
00006537 14:53:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006538 14:53:03 >>> [89FF1684] CMiniport::PnPEventNotify():
00006539 14:53:03 *** [89FF1684] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006540 14:53:03 <<< [89FF1684] CMiniport::PnPEventNotify():
exited
00006541 14:53:03 >>> [8A062E54] CMiniport::PnPEventNotify():
00006542 14:53:03 *** [8A062E54] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006543 14:53:03 <<< [8A062E54] CMiniport::PnPEventNotify():
exited
00006544 14:53:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006545 14:53:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006546 14:53:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006559 14:53:03 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006560 14:53:03 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006561 14:53:03 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006562 14:53:03 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006563 14:53:03 –> [89988544]
INetworkAdapter::IncomingThread():
00006564 14:53:03 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006565 14:53:03 >>> [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006566 14:53:03 *** [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
C0010011
00006567 14:53:03 <<< [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006568 14:53:03 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
C0010011

David R. Cattley wrote:

Now that you have got the checked build of NDIS installed (the hard part)
you ought to also enable the verbose debug output too. This can be done by
setting values in the registry or with the !ndiskd debug extension.

http://support.microsoft.com/kb/248413

see also

http://msdn.microsoft.com/en-us/library/aa504995.aspx

http://support.microsoft.com/kb/266403

for information about the NDIS ‘verifier’.

Now keep in mind that the NDISKD debug extension is experiencing a bit of a
mid-life crisis at present having got all cool & stuff with NDIS6 support
only to have the correct symbols not available to make it work. You can
always jack-up the debug output with registry settings or just hitting the
appropriate values in the debugger. For inspiration, try the following
commands in Windbg:

> x ndis!*Dbg*
> x ndis!*Debug*

I cannot be sure this matters but your stack-dump happens to have
NDIS_STATUS_ADAPTER_NOT_READY (0xc0010011) on it.

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

OSR_Community_User · September 18, 2009, 8:29am

Andrew Rukavishnikov wrote:

Thank you Dave, for such detailed description.

And yes you are completely right about NDIS_STATUS_ADAPTER_NOT_READY
(0xc0010011)
code which was returned by underlying driver.

I have enabled debug output of OID path in my driver and captured it
using dbgview at hibernate bootup time.
So when I experience BSOD in ndis this is always logged by my driver
(see the last line, after which crash occurred).

Also you can see that all previous request about OID_GEN_LINK_SPEED
was successful, this requests simple
redirected to underlying miniport and I always passthrough it and it
status, so it is a reply of underlying miniport about
adapter not ready status. How I can deal in such cases?
Sorry for messed log, here new one:

00006313 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006314 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status 00000103
00006315 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006316 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status 00000000
00006317 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006318 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006319 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status 00000103
00006320 14:52:02 >>> [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006321 14:52:02 *** [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status 00000000
00006322 14:52:02 <<< [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006323 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006324 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status 00000103
00006325 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006326 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status 00000000
00006327 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006337 14:52:02 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000001):
00006338 14:52:02 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006339 14:52:02 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000001):
00006340 14:52:02 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006341 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006342 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status 00000000
00006343 14:52:02 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006344 14:52:02 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status 00000000
00006345 14:52:02 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001):
00006346 14:52:02 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006347 14:52:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006348 14:52:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state 00000004
00006349 14:52:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006350 14:52:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006351 14:52:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state 00000004
00006352 14:52:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006353 14:52:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006354 14:52:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006355 14:52:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006368 14:52:03 [MUP]: DfscFsctrlStateTransition invoked.
00006369 14:52:03 [MUP]: Flushing pkt cache…[MUP]: done.
00006370 14:52:03 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000000):
00006371 14:52:03 *** [89E84674]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006372 14:52:03 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006381 14:52:03 <<< [89D27254] CProtocol::DelayedRemoval(): exited
00006382 14:52:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006383 14:52:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006384 14:52:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006459 14:53:03 watchdog!WdUpdateRecoveryState: Recovery enabled.
00006513 14:53:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006514 14:53:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006515 14:53:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006529 14:53:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006530 14:53:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state 00000001
00006531 14:53:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006532 14:53:03 >>> [89FA12EC] CMiniport::PnPEventNotify():
00006533 14:53:03 *** [89FA12EC] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006534 14:53:03 <<< [89FA12EC] CMiniport::PnPEventNotify(): exited
00006535 14:53:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006536 14:53:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state 00000001
00006537 14:53:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006538 14:53:03 >>> [89FF1684] CMiniport::PnPEventNotify():
00006539 14:53:03 *** [89FF1684] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006540 14:53:03 <<< [89FF1684] CMiniport::PnPEventNotify(): exited
00006541 14:53:03 >>> [8A062E54] CMiniport::PnPEventNotify():
00006542 14:53:03 *** [8A062E54] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006543 14:53:03 <<< [8A062E54] CMiniport::PnPEventNotify(): exited
00006544 14:53:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006545 14:53:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006546 14:53:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006559 14:53:03 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006560 14:53:03 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status 00000103
00006561 14:53:03 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006562 14:53:03 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status 00000103
00006564 14:53:03 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006565 14:53:03 >>> [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006566 14:53:03 *** [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status C0010011
00006567 14:53:03 <<< [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006568 14:53:03 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status C0010011

Best regards,

–
Andrew Rukavishnikov
Sunbay Innovations Ltd.

David_R_Cattley · September 18, 2009, 8:45am

Andrew,

It’s a crash. The system is trying to access some address. The address is
either some bit of information that was returned by your driver, stomped on
by your driver, or incorrectly freed by your driver.

The NDIS Request mechanism should not be blowing up because an OID request
returns an error. More than likely, it is because your IM driver is not
handling the error correctly (or not handling requests correctly in
general).

Connect a live debugger with a serial port (because resuming from
hibernation is rather a PITA to debug over firewire) and get a live crash.
Go pick through the trace output from your IM driver and correlate the
address that causes the exception to some value or side-effect of your
driver processing the request.

It sucks. It might be hard. You might need to set a couple of break-points
so that you can step through the most interesting of the requests. You
might want to look at how your IM driver handles request completion (since I
can see from your debug output that sometimes the requests come back
NDIS_STATUS_PENDING and sometimes they do not).

But really, nobody but you can figure this out from that debug output. I
have no idea what your code looks like and at what point that debug output
is being generated in the nominal request processing flow. That is the
thing about instrumentation, without sharing with us lots of details about
where it is ‘plugged in’, well, it frankly is not all that useful to the
outside observer.

Based on the output, however, it looks as if your IM driver ‘filters’ both
the request presentation and completion. Since this request appears to be
failing ‘synchronously’ I am going to guess that your code calls the
completion ‘filtering’ synchronously from the ‘presentation’ filtering in
that case. Look carefully at what you do here. Make sure you don’t both
complete the request and return a non NDIS_STATUS_PENDING result from
MiniportQueryInformation(). That tends to result in the caller’s request
structure being freed by the completion routine and then referenced by the
calling activity. Sort-of what might be happening with your situation.

Also, I see some evidence that you might have a ‘thread’ involved. Make
sure you are properly synchronizing its interaction. NDIS5 Miniports are
‘synchronized’ by internal NDIS locking and have specific rules for
NdisRequest() processing and completion. Don’t break the rules. Bad stuff
happens.

Lastly, IM drivers in particular have some rough edges with respect to power
state management. Since I can see from the debug output that your driver
appears to be written as C++ classes, I am guessing that it’s lineage from
PASSTHRU is, well, rather stretched. Making sure that you handle the
Protocol edge PnP notifications correctly is pretty important.

Good Luck,
Dave Cattley

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Andrew Rukavishnikov
Sent: Friday, September 18, 2009 8:16 AM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] BSOD in ndis.sys after resume from StandBy or Hibernate

Thank you Dave, for such detailed description.

And yes you are completely right about NDIS_STATUS_ADAPTER_NOT_READY
(0xc0010011)
code which was returned by underlying driver.

I have enabled debug output of OID path in my driver and captured it
using dbgview at hibernate bootup time.
So when I experience BSOD in ndis this is always logged by my driver
(see the last line, after which crash occurred).

Also you can see that all previous request about OID_GEN_LINK_SPEED was
successful, this requests simple
redirected to underlying miniport and I always passthrough it and it
status, so it is a reply of underlying miniport about
adapter not ready status. How I can deal in such cases?

00006313 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006314 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006315 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006316 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006317 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006318 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006319 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006320 14:52:02 >>> [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006321 14:52:02 *** [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006322 14:52:02 <<< [8A04C764]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006323 14:52:02 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006324 14:52:02 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006325 14:52:02 >>> [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006326 14:52:02 *** [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
00000000
00006327 14:52:02 <<< [89D27254]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006337 14:52:02 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000001):
00006338 14:52:02 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006339 14:52:02 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000001):
00006340 14:52:02 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006341 14:52:02 >>> [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006342 14:52:02 <<< [8A062E54]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status
00000000
00006343 14:52:02 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER):
00006344 14:52:02 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_PNP_QUERY_POWER): exited, status
00000000
00006345 14:52:02 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001):
00006346 14:52:02 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000001): exited, status 00000000
00006347 14:52:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006348 14:52:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000004
00006349 14:52:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006350 14:52:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006351 14:52:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000004
00006352 14:52:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006353 14:52:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006354 14:52:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006355 14:52:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006368 14:52:03 [MUP]: DfscFsctrlStateTransition invoked.
00006369 14:52:03 [MUP]: Flushing pkt cache…[MUP]: done.
00006370 14:52:03 >>> [89E84674]
CProtocol::PnPEvent(NetEvent=00000000):
00006371 14:52:03 *** [89E84674]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006372 14:52:03 <<< [89E84674]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006381 14:52:03 <<< [89D27254] CProtocol::DelayedRemoval():
exited
00006382 14:52:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006383 14:52:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 4
00006384 14:52:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006459 14:53:03 watchdog!WdUpdateRecoveryState: Recovery
enabled.
00006513 14:53:03 >>> [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000):
00006514 14:53:03 *** [8A04C764]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006515 14:53:03 <<< [8A04C764]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006529 14:53:03 >>> [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006530 14:53:03 *** [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000001
00006531 14:53:03 <<< [89FA12EC]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006532 14:53:03 >>> [89FA12EC] CMiniport::PnPEventNotify():
00006533 14:53:03 *** [89FA12EC] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006534 14:53:03 <<< [89FA12EC] CMiniport::PnPEventNotify():
exited
00006535 14:53:03 >>> [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER):
00006536 14:53:03 *** [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): new power state
00000001
00006537 14:53:03 <<< [8A062E54]
CMiniport::SetInformation___(OID_PNP_SET_POWER): exited, status 00000000
00006538 14:53:03 >>> [89FF1684] CMiniport::PnPEventNotify():
00006539 14:53:03 *** [89FF1684] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006540 14:53:03 <<< [89FF1684] CMiniport::PnPEventNotify():
exited
00006541 14:53:03 >>> [8A062E54] CMiniport::PnPEventNotify():
00006542 14:53:03 *** [8A062E54] CMiniport::PnPEventNotify():
NdisPowerProfileAcOnLine
00006543 14:53:03 <<< [8A062E54] CMiniport::PnPEventNotify():
exited
00006544 14:53:03 >>> [89D27254]
CProtocol::PnPEvent(NetEvent=00000000):
00006545 14:53:03 *** [89D27254]
CProtocol::PnPEvent(NetEventSetPower): new 1
00006546 14:53:03 <<< [89D27254]
CProtocol::PnPEvent(NetEvent=00000000): exited, status 00000000
00006559 14:53:03 >>> [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006560 14:53:03 <<< [89FF1684]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006561 14:53:03 >>> [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006562 14:53:03 <<< [8A062E54]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
00000103
00006563 14:53:03 –> [89988544]
INetworkAdapter::IncomingThread():
00006564 14:53:03 >>> [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED):
00006565 14:53:03 >>> [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED):
00006566 14:53:03 *** [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): parsed, status
C0010011
00006567 14:53:03 <<< [89E84674]
CProtocol::RequestComplete__(OID_GEN_LINK_SPEED): exited
00006568 14:53:03 <<< [89FA12EC]
CMiniport::QueryInformation_(OID_GEN_LINK_SPEED): exited, status
C0010011

OSR_Community_User · September 18, 2009, 3:42pm

David,

Thank you for pointing my mind in right direction, I have found the
issues with code in
MiniportQueryInformation, the IM passed down incoming request by
performing NdisRequest,
than NdisRequest return NDIS_STATUS_ADAPTER_NOT_FOUND or other
unsuccessful status,
then I have called NdisMQueryInformationComplete and return indicated
invalid status from
MiniportQueryInformation. But I must return NDIS_STATUS_PENDING when
performing
asynchronous request completion.

I have found that this subject is not so clear in DDK documentation.

And another amazing things that this code worked w/o any fault in other
situation, when missed some
OID or request failed. But crash cured only on resuming from hibernate
or standby mode.

Anyway thank you for pointing me to right direction.

PS: It’s was hard for us to find some computers with com port to debug
such issue. Hope 1394 will
work on vista and later system w/o such problem.

Best regards,

Andrew Rukavishnikov
Sunbay Innovations Ltd.

David R. Cattley Ð¿Ð¸ÑˆÐµÑ‚:

Andrew,

It’s a crash. The system is trying to access some address. The address is
either some bit of information that was returned by your driver, stomped on
by your driver, or incorrectly freed by your driver.

The NDIS Request mechanism should not be blowing up because an OID request
returns an error. More than likely, it is because your IM driver is not
handling the error correctly (or not handling requests correctly in
general).

Connect a live debugger with a serial port (because resuming from
hibernation is rather a PITA to debug over firewire) and get a live crash.
Go pick through the trace output from your IM driver and correlate the
address that causes the exception to some value or side-effect of your
driver processing the request.

It sucks. It might be hard. You might need to set a couple of break-points
so that you can step through the most interesting of the requests. You
might want to look at how your IM driver handles request completion (since I
can see from your debug output that sometimes the requests come back
NDIS_STATUS_PENDING and sometimes they do not).

But really, nobody but you can figure this out from that debug output. I
have no idea what your code looks like and at what point that debug output
is being generated in the nominal request processing flow. That is the
thing about instrumentation, without sharing with us lots of details about
where it is ‘plugged in’, well, it frankly is not all that useful to the
outside observer.

Based on the output, however, it looks as if your IM driver ‘filters’ both
the request presentation and completion. Since this request appears to be
failing ‘synchronously’ I am going to guess that your code calls the
completion ‘filtering’ synchronously from the ‘presentation’ filtering in
that case. Look carefully at what you do here. Make sure you don’t both
complete the request and return a non NDIS_STATUS_PENDING result from
MiniportQueryInformation(). That tends to result in the caller’s request
structure being freed by the completion routine and then referenced by the
calling activity. Sort-of what might be happening with your situation.

Also, I see some evidence that you might have a ‘thread’ involved. Make
sure you are properly synchronizing its interaction. NDIS5 Miniports are
‘synchronized’ by internal NDIS locking and have specific rules for
NdisRequest() processing and completion. Don’t break the rules. Bad stuff
happens.

Lastly, IM drivers in particular have some rough edges with respect to power
state management. Since I can see from the debug output that your driver
appears to be written as C++ classes, I am guessing that it’s lineage from
PASSTHRU is, well, rather stretched. Making sure that you handle the
Protocol edge PnP notifications correctly is pretty important.

David_R_Cattley · September 18, 2009, 4:39pm

Before you assume that you can always return NDIS_STATUS_PENDING from MiniportQueryInformation() please read the WDK documentation about MiniportQueryInformation() *very* carefully.

Take particular note of:

If possible, MiniportQueryInformation should not return NDIS_STATUS_PENDING for initialization-time requests. Until NDIS has sufficient information to set up bindings to the miniport driver, such requests should be handled synchronously.

In an IM driver, it is ‘best’ to return a synchronous completion status (in other words, not NDIS_STATUS_PENDING) for any request that was passed to the lower binding *and* itself returned synchronously. This is not really hard to do with both pre-filtering and post-filtering.

MiniportQueryInformation(…)
{

status = MyPreFilter(…)
if (NT_SUCCESS(status))
{
status = NdisRequest_ToLowerBinding(…);

if (NDIS_STATUS_PENDING != status)
{
status = MyPostFilter(…);
}
}

return status;
}

ProtocolRequestComplete(…)
{
status = MyPostFilter(…);
NdisM{Query|Set}InformationComplete(…);
}

The point is to separate out the post-filtering from the request completion so that you can call the post filtering ‘syncronously’ without having to return NDIS_STATUS_PENDING from every request.

And I guess you are right about the WDK documentation if it left you confused. It does say pretty clearly what you have to do if you return NDIS_STATUS_PENDING. It does not say that you *must* return NDIS_STATUS_PENDING if you intend to (or did) call NdisM*InformationComplete() in such plain language. Or if it does say it, it does not say it on the Miniport*Information() pages.

Good Luck,
Dave Cattley

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Andrew Rukavishnikov
Sent: Friday, September 18, 2009 3:42 PM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] BSOD in ndis.sys after resume from StandBy or Hibernate

David,

Thank you for pointing my mind in right direction, I have found the
issues with code in
MiniportQueryInformation, the IM passed down incoming request by
performing NdisRequest,
than NdisRequest return NDIS_STATUS_ADAPTER_NOT_FOUND or other
unsuccessful status,
then I have called NdisMQueryInformationComplete and return indicated
invalid status from
MiniportQueryInformation. But I must return NDIS_STATUS_PENDING when
performing
asynchronous request completion.

I have found that this subject is not so clear in DDK documentation.

And another amazing things that this code worked w/o any fault in other
situation, when missed some
OID or request failed. But crash cured only on resuming from hibernate
or standby mode.

Anyway thank you for pointing me to right direction.

PS: It’s was hard for us to find some computers with com port to debug
such issue. Hope 1394 will
work on vista and later system w/o such problem.

Best regards,

Andrew Rukavishnikov
Sunbay Innovations Ltd.

David R. Cattley пишет:

Andrew,

It’s a crash. The system is trying to access some address. The address is
either some bit of information that was returned by your driver, stomped on
by your driver, or incorrectly freed by your driver.

The NDIS Request mechanism should not be blowing up because an OID request
returns an error. More than likely, it is because your IM driver is not
handling the error correctly (or not handling requests correctly in
general).

Connect a live debugger with a serial port (because resuming from
hibernation is rather a PITA to debug over firewire) and get a live crash.
Go pick through the trace output from your IM driver and correlate the
address that causes the exception to some value or side-effect of your
driver processing the request.

It sucks. It might be hard. You might need to set a couple of break-points
so that you can step through the most interesting of the requests. You
might want to look at how your IM driver handles request completion (since I
can see from your debug output that sometimes the requests come back
NDIS_STATUS_PENDING and sometimes they do not).

But really, nobody but you can figure this out from that debug output. I
have no idea what your code looks like and at what point that debug output
is being generated in the nominal request processing flow. That is the
thing about instrumentation, without sharing with us lots of details about
where it is ‘plugged in’, well, it frankly is not all that useful to the
outside observer.

Based on the output, however, it looks as if your IM driver ‘filters’ both
the request presentation and completion. Since this request appears to be
failing ‘synchronously’ I am going to guess that your code calls the
completion ‘filtering’ synchronously from the ‘presentation’ filtering in
that case. Look carefully at what you do here. Make sure you don’t both
complete the request and return a non NDIS_STATUS_PENDING result from
MiniportQueryInformation(). That tends to result in the caller’s request
structure being freed by the completion routine and then referenced by the
calling activity. Sort-of what might be happening with your situation.

Also, I see some evidence that you might have a ‘thread’ involved. Make
sure you are properly synchronizing its interaction. NDIS5 Miniports are
‘synchronized’ by internal NDIS locking and have specific rules for
NdisRequest() processing and completion. Don’t break the rules. Bad stuff
happens.

Lastly, IM drivers in particular have some rough edges with respect to power
state management. Since I can see from the debug output that your driver
appears to be written as C++ classes, I am guessing that it’s lineage from
PASSTHRU is, well, rather stretched. Making sure that you handle the
Protocol edge PnP notifications correctly is pretty important.

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

Maxim_S_Shatskih · September 21, 2009, 2:43am

> The start session is ok, then system goes down, and after resuming, just a 2 seconds latter I have

a BSOD, and no debug session restoration.

Debug the crash dump then.

–
Maxim S. Shatskih
Windows DDK MVP
xxxxx@storagecraft.com
http://www.storagecraft.com