PAGE_FAULT_IN_NONPAGED_AREA running .exe

NTFSD
1

Hi all,

I am getting a PAGE_FAULT_IN_NONPAGED_AREA when trying to run an .exe from
my file system. The application I am trying to run is calc.exe which I
copied to my file system from C:\windows\system32. I am testing with the
checked build of my driver on a checked version of windows xp sp2, using ifs
3790. Driver verifier is enabled for my driver. I fixed all prefast
warnings except those about performance.

Sometimes it works just fine, other times it faults. Most of the time the
error is a PAGE_FAULT_IN_NONPAGED_AREA, but once it was a
DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL, and one other time it was
IRQL_NOT_LESS_OR_EQUAL. However, I think its all pretty much the same
thing. Yes/no?

I am using DbdPrint() to trace things in my driver (using the serial port).
Unfortunately, when I enable tracing, I cannot repro the fault. When I
disable tracing, I can repro the fault easily. So I suspect a timing/race
condition. Would you agree?

However, when I do get a crash and I use '!analyze -v' in the debugger to
get more info, I don't see anything that gives me any clues. Most of the
analyze outputs look like the ones at the bottom of this email. The memory
being referenced is not something that I recognize, the faulting IP is not
in my driver. In fact, its almost always in NtGdiXXX.

If anyone has any ideas or tips on how I could proceed to debug this, it
would be greatly appreciated. Thanks.

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

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by
try-except,
it must be protected by a Probe. Typically the address is just plain bad or
it
is pointing at freed memory.
Arguments:
Arg1: ffff0901, memory referenced.
Arg2: 00000001, value 0 = read operation, 1 = write operation.
Arg3: bf830ae7, If non-zero, the instruction address which referenced the
bad memory address.
Arg4: 00000000, (reserved)

Debugging Details:

WRITE_ADDRESS: ffff0901
FAULTING_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
MM_INTERNAL_CODE: 0
IMAGE_NAME: hardware
DEBUG_FLR_IMAGE_TIMESTAMP: 0
FAULTING_MODULE: bf800000 win32k
DEFAULT_BUCKET_ID: DRIVER_FAULT
BUGCHECK_STR: 0x50
LAST_CONTROL_TRANSFER: from ad5a48f2 to bf830ae7
MISALIGNED_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

TRAP_FRAME: f2fed608 -- (.trap fffffffff2fed608)
ErrCode = 00000002
eax=00000001 ebx=00000044 ecx=855a96fc edx=00000000 esi=0007f4aa
edi=f2fed70a
eip=bf830ae7 esp=f2fed67c ebp=f2fed79b iopl=0 nv up ei ng nz ac po
nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010296
win32k!NtGdiExtTextOutW+0x33f:
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
ds:0023:ffff0901=????????
Resetting default scope

STACK_TEXT:
f2fed79b ad5a48f2 01051d80 00001037 00000100 win32k!NtGdiExtTextOutW+0x33f
WARNING: Frame IP not in any known module. Following frames may be wrong.
f2fed7c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f2
00000000 00000000 00000000 00000000 00000000 0xad59bd00

FOLLOWUP_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

SYMBOL_STACK_INDEX: 0
FOLLOWUP_NAME: MachineOwner
SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f
STACK_COMMAND: .trap fffffffff2fed608 ; kb
MODULE_NAME: hardware
FAILURE_BUCKET_ID: IP_MISALIGNED
BUCKET_ID: IP_MISALIGNED
Followup: MachineOwner

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

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by
try-except,
it must be protected by a Probe. Typically the address is just plain bad or
it
is pointing at freed memory.
Arguments:
Arg1: 85f008f9, memory referenced.
Arg2: 00000000, value 0 = read operation, 1 = write operation.
Arg3: bf943776, If non-zero, the instruction address which referenced the
bad memory
address.
Arg4: 00000000, (reserved)

Debugging Details:

READ_ADDRESS: 85f008f9
FAULTING_IP:
win32k!EXLATEOBJ::bInitXlateObj+b0
bf943776 8b4818 mov ecx,[eax+0x18]
MM_INTERNAL_CODE: 0
IMAGE_NAME: win32k.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 41108c9f
MODULE_NAME: win32k
FAULTING_MODULE: bf800000 win32k
DEFAULT_BUCKET_ID: DRIVER_FAULT
BUGCHECK_STR: 0x50
LAST_CONTROL_TRANSFER: from bf93673d to bf943776

TRAP_FRAME: f2d714bc -- (.trap fffffffff2d714bc)
ErrCode = 00000000
eax=85f008e1 ebx=00000000 ecx=f2d71664 edx=00000024 esi=e15a4248
edi=e185f007
eip=bf943776 esp=f2d71530 ebp=f2d71540 iopl=0 nv up ei ng nz ac pe
cy
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010293
win32k!EXLATEOBJ::bInitXlateObj+0xb0:
bf943776 8b4818 mov ecx,[eax+0x18]
ds:0023:85f008f9=????????
Resetting default scope

STACK_TEXT:
f2d71540 bf93673d 00000000 00000000 e185f007
win32k!EXLATEOBJ::bInitXlateObj+0xb0
f2d7166c bf948a88 3301050f 00000000 00000000 win32k!GreDrawStream+0x474
f2d717b4 80ad5a48 3301050f 00000060 0007f670 win32k!NtGdiDrawStream+0xb2
f2d717b4 7c834684 3301050f 00000060 0007f670 nt!KiFastCallEntry+0x158
0007f4dc 77f99126 77f8659e 3301050f 00000060 ntdll!KiFastSystemCallRet
0007f5ec 56aa5439 3301050f 00000060 0007f670 GDI32!NtGdiDrawStream+0xc
0007f868 56aa5d70 00b42e68 00b423e4 00000001
UxTheme!CImageFile::DrawBackgroundDS+0x3a0
0007f8e0 56aa60b7 00b42e68 00035fd8 3301050f
UxTheme!CImageFile::DrawImageInfo+0x1eb
0007f930 56abbd0e 00035fd8 3301050f 00000001
UxTheme!CImageFile::DrawBackground+0x45
0007f990 77295252 00b42e64 3301050f 00000001
UxTheme!DrawThemeBackground+0x137
0007fa88 77295706 000ae208 3301050f 00000001
comctl32!Button_DrawThemed+0x176
0007fb04 77295c5c 00000001 3301050f 00000001 comctl32!Button_DrawPush+0x59
0007fb80 77295f82 00000001 3301050f 0007fc78 comctl32!Button_Paint+0x2f9
0007fc10 77d13df0 000201a4 0000000f 00000000 comctl32!Button_WndProc+0x270
0007fc3c 77d1efeb 77295d12 000201a4 0000000f USER32!InternalCallWinProc+0x28
0007fca4 77ce96ef 00000000 77295d12 000201a4
USER32!UserCallWinProcCheckWow+0x150
0007fcf8 77ce9920 006ca958 0000000f 00000000
USER32!DispatchClientMessage+0x126
0007fd20 7c8345e3 0007fd30 00000018 006ca958 USER32!__fnDWORD+0x24
0007fd20 80a3c6f4 0007fd30 00000018 006ca958
ntdll!KiUserCallbackDispatcher+0x13
f2d71a94 80b7529e f2d71b60 f2d71b58 7ffdf6f4 nt!KiCallUserMode+0x4
f2d71af0 bf806d03 00000002 f2d71b40 00000018 nt!KeUserModeCallback+0xc8
f2d71b8c bf8f94cf be2ba958 0000000f 00000000 win32k!SfnDWORD+0x114
f2d71be4 bf8035a7 422ba958 0000000f 00000000
win32k!xxxSendMessageToClient+0x153
f2d71c34 bf80ddcd be2ba958 0000000f 00000000
win32k!xxxSendMessageTimeout+0x1f1
f2d71c58 bf80a477 be2ba958 0000000f 00000000 win32k!xxxSendMessage+0x1b
f2d71c94 bf80a51a be2ba958 00000005 be2b9570 win32k!xxxUpdateWindow2+0x83
f2d71cc8 bf80a5d1 be2b9570 00000001 0000124b win32k!xxxUpdateWindow2+0x126
f2d71d00 bf80a54c be2b9570 00000001 f2d71d48
win32k!xxxInternalUpdateWindow+0x79
f2d71d10 bf80a6cf be2b9570 f2d71d58 0007fd58 win32k!xxxUpdateWindow+0x17
f2d71d48 80ad5a48 be2b9570 0000005e 80ad59bd win32k!NtUserCallHwndLock+0xf2
f2d71d48 7c834684 be2b9570 0000005e 80ad59bd nt!KiFastCallEntry+0x158
0007fd20 7c8345e3 0007fd30 00000018 006ca958 ntdll!KiFastSystemCallRet
0007fd44 77cea0aa 77cea00e 000500f8 0000005e
ntdll!KiUserCallbackDispatcher+0x13
0007fd58 77d1b83a 000500f8 00000000 00000130 USER32!NtUserCallHwndLock+0xc
0007fd70 010024c4 000500f8 01015018 77e6a338
USER32!UpdateWindow_wrapper+0x3e
0007fe08 010027c7 0000007a 77e78bf7 000a2ea6 calc!InitSciCalc+0x414
0007ff1c 01013152 000aab90 00000055 000aab90 calc!WinMain+0x1dd
0007ffc0 77e821ce 7cb3e3a6 00000000 7ffd4000 calc!WinMainCRTStartup+0x174
0007fff0 00000000 01012fde 00000000 78746341 kernel32!BaseProcessStart+0x23

FOLLOWUP_IP:
win32k!EXLATEOBJ::bInitXlateObj+b0
bf943776 8b4818 mov ecx,[eax+0x18]

SYMBOL_STACK_INDEX: 0
FOLLOWUP_NAME: MachineOwner
SYMBOL_NAME: win32k!EXLATEOBJ::bInitXlateObj+b0
STACK_COMMAND: .trap fffffffff2d714bc ; kb
FAILURE_BUCKET_ID: 0x50_win32k!EXLATEOBJ::bInitXlateObj+b0
BUCKET_ID: 0x50_win32k!EXLATEOBJ::bInitXlateObj+b0

Followup: MachineOwner

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you're done.]

2

> Unfortunately, when I enable tracing, I cannot repro the fault. When I

disable tracing, I can repro the fault easily. So I suspect a timing/race
condition. Would you agree?
Possible, but…
Just a suggestion: check all (all) your DbgPrint buffers.
If you write 90 bytes into an 80-byte buffer, the symptoms
may be similar to what you see.

----- Original Message -----
From: “Roger Tawa”
To: “Windows File Systems Devs Interest List”
Sent: Tuesday, February 21, 2006 8:34 PM
Subject: [ntfsd] PAGE_FAULT_IN_NONPAGED_AREA running .exe

> Hi all,
>
> I am getting a PAGE_FAULT_IN_NONPAGED_AREA when trying to run an .exe from
> my file system. The application I am trying to run is calc.exe which I
> copied to my file system from C:\windows\system32. I am testing with the
> checked build of my driver on a checked version of windows xp sp2, using
> ifs
> 3790. Driver verifier is enabled for my driver. I fixed all prefast
> warnings except those about performance.
>
> Sometimes it works just fine, other times it faults. Most of the time the
> error is a PAGE_FAULT_IN_NONPAGED_AREA, but once it was a
> DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL, and one other time it was
> IRQL_NOT_LESS_OR_EQUAL. However, I think its all pretty much the same
> thing. Yes/no?
>
> I am using DbdPrint() to trace things in my driver (using the serial
> port).
> Unfortunately, when I enable tracing, I cannot repro the fault. When I
> disable tracing, I can repro the fault easily. So I suspect a timing/race
> condition. Would you agree?
>
> However, when I do get a crash and I use ‘!analyze -v’ in the debugger to
> get more info, I don’t see anything that gives me any clues. Most of the
> analyze outputs look like the ones at the bottom of this email. The
> memory
> being referenced is not something that I recognize, the faulting IP is not
> in my driver. In fact, its almost always in NtGdiXXX.
>
> If anyone has any ideas or tips on how I could proceed to debug this, it
> would be greatly appreciated. Thanks.
>
> kd> !analyze -v
> *************************************************************************
>
> *
> *
> * Bugcheck Analysis
> *
> *
> *
> *************************************************************************
>
>
> PAGE_FAULT_IN_NONPAGED_AREA (50)
> Invalid system memory was referenced. This cannot be protected by
> try-except,
> it must be protected by a Probe. Typically the address is just plain bad
> or
> it
> is pointing at freed memory.
> Arguments:
> Arg1: ffff0901, memory referenced.
> Arg2: 00000001, value 0 = read operation, 1 = write operation.
> Arg3: bf830ae7, If non-zero, the instruction address which referenced the
> bad memory address.
> Arg4: 00000000, (reserved)
>
> Debugging Details:
> ------------------
> WRITE_ADDRESS: ffff0901
> FAULTING_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
> MM_INTERNAL_CODE: 0
> IMAGE_NAME: hardware
> DEBUG_FLR_IMAGE_TIMESTAMP: 0
> FAULTING_MODULE: bf800000 win32k
> DEFAULT_BUCKET_ID: DRIVER_FAULT
> BUGCHECK_STR: 0x50
> LAST_CONTROL_TRANSFER: from ad5a48f2 to bf830ae7
> MISALIGNED_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
>
> TRAP_FRAME: f2fed608 – (.trap fffffffff2fed608)
> ErrCode = 00000002
> eax=00000001 ebx=00000044 ecx=855a96fc edx=00000000 esi=0007f4aa
> edi=f2fed70a
> eip=bf830ae7 esp=f2fed67c ebp=f2fed79b iopl=0 nv up ei ng nz ac po
> nc
> cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
> efl=00010296
> win32k!NtGdiExtTextOutW+0x33f:
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
> ds:0023:ffff0901=???
> Resetting default scope
>
> STACK_TEXT:
> f2fed79b ad5a48f2 01051d80 00001037 00000100 win32k!NtGdiExtTextOutW+0x33f
> WARNING: Frame IP not in any known module. Following frames may be wrong.
> f2fed7c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f2
> 00000000 00000000 00000000 00000000 00000000 0xad59bd00
>
>
> FOLLOWUP_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
>
> SYMBOL_STACK_INDEX: 0
> FOLLOWUP_NAME: MachineOwner
> SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f
> STACK_COMMAND: .trap fffffffff2fed608 ; kb
> MODULE_NAME: hardware
> FAILURE_BUCKET_ID: IP_MISALIGNED
> BUCKET_ID: IP_MISALIGNED
> Followup: MachineOwner
> ---------
>
>
> kd> !analyze -v
> *************************************************************************
>
> *
> *
> * Bugcheck Analysis
> *
> *
> *
> *************************************************************************
>
>
> PAGE_FAULT_IN_NONPAGED_AREA (50)
> Invalid system memory was referenced. This cannot be protected by
> try-except,
> it must be protected by a Probe. Typically the address is just plain bad
> or
> it
> is pointing at freed memory.
> Arguments:
> Arg1: 85f008f9, memory referenced.
> Arg2: 00000000, value 0 = read operation, 1 = write operation.
> Arg3: bf943776, If non-zero, the instruction address which referenced the
> bad memory
> address.
> Arg4: 00000000, (reserved)
>
> Debugging Details:
> ------------------
> READ_ADDRESS: 85f008f9
> FAULTING_IP:
> win32k!EXLATEOBJ::bInitXlateObj+b0
> bf943776 8b4818 mov ecx,[eax+0x18]
> MM_INTERNAL_CODE: 0
> IMAGE_NAME: win32k.sys
> DEBUG_FLR_IMAGE_TIMESTAMP: 41108c9f
> MODULE_NAME: win32k
> FAULTING_MODULE: bf800000 win32k
> DEFAULT_BUCKET_ID: DRIVER_FAULT
> BUGCHECK_STR: 0x50
> LAST_CONTROL_TRANSFER: from bf93673d to bf943776
>
> TRAP_FRAME: f2d714bc – (.trap fffffffff2d714bc)
> ErrCode = 00000000
> eax=85f008e1 ebx=00000000 ecx=f2d71664 edx=00000024 esi=e15a4248
> edi=e185f007
> eip=bf943776 esp=f2d71530 ebp=f2d71540 iopl=0 nv up ei ng nz ac pe
> cy
> cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
> efl=00010293
> win32k!EXLATEOBJ::bInitXlateObj+0xb0:
> bf943776 8b4818 mov ecx,[eax+0x18]
> ds:0023:85f008f9=???
> Resetting default scope
>
> STACK_TEXT:
> f2d71540 bf93673d 00000000 00000000 e185f007
> win32k!EXLATEOBJ::bInitXlateObj+0xb0
> f2d7166c bf948a88 3301050f 00000000 00000000 win32k!GreDrawStream+0x474
> f2d717b4 80ad5a48 3301050f 00000060 0007f670 win32k!NtGdiDrawStream+0xb2
> f2d717b4 7c834684 3301050f 00000060 0007f670 nt!KiFastCallEntry+0x158
> 0007f4dc 77f99126 77f8659e 3301050f 00000060 ntdll!KiFastSystemCallRet
> 0007f5ec 56aa5439 3301050f 00000060 0007f670 GDI32!NtGdiDrawStream+0xc
> 0007f868 56aa5d70 00b42e68 00b423e4 00000001
> UxTheme!CImageFile::DrawBackgroundDS+0x3a0
> 0007f8e0 56aa60b7 00b42e68 00035fd8 3301050f
> UxTheme!CImageFile::DrawImageInfo+0x1eb
> 0007f930 56abbd0e 00035fd8 3301050f 00000001
> UxTheme!CImageFile::DrawBackground+0x45
> 0007f990 77295252 00b42e64 3301050f 00000001
> UxTheme!DrawThemeBackground+0x137
> 0007fa88 77295706 000ae208 3301050f 00000001
> comctl32!Button_DrawThemed+0x176
> 0007fb04 77295c5c 00000001 3301050f 00000001 comctl32!Button_DrawPush+0x59
> 0007fb80 77295f82 00000001 3301050f 0007fc78 comctl32!Button_Paint+0x2f9
> 0007fc10 77d13df0 000201a4 0000000f 00000000 comctl32!Button_WndProc+0x270
> 0007fc3c 77d1efeb 77295d12 000201a4 0000000f
> USER32!InternalCallWinProc+0x28
> 0007fca4 77ce96ef 00000000 77295d12 000201a4
> USER32!UserCallWinProcCheckWow+0x150
> 0007fcf8 77ce9920 006ca958 0000000f 00000000
> USER32!DispatchClientMessage+0x126
> 0007fd20 7c8345e3 0007fd30 00000018 006ca958 USER32!__fnDWORD+0x24
> 0007fd20 80a3c6f4 0007fd30 00000018 006ca958
> ntdll!KiUserCallbackDispatcher+0x13
> f2d71a94 80b7529e f2d71b60 f2d71b58 7ffdf6f4 nt!KiCallUserMode+0x4
> f2d71af0 bf806d03 00000002 f2d71b40 00000018 nt!KeUserModeCallback+0xc8
> f2d71b8c bf8f94cf be2ba958 0000000f 00000000 win32k!SfnDWORD+0x114
> f2d71be4 bf8035a7 422ba958 0000000f 00000000
> win32k!xxxSendMessageToClient+0x153
> f2d71c34 bf80ddcd be2ba958 0000000f 00000000
> win32k!xxxSendMessageTimeout+0x1f1
> f2d71c58 bf80a477 be2ba958 0000000f 00000000 win32k!xxxSendMessage+0x1b
> f2d71c94 bf80a51a be2ba958 00000005 be2b9570 win32k!xxxUpdateWindow2+0x83
> f2d71cc8 bf80a5d1 be2b9570 00000001 0000124b win32k!xxxUpdateWindow2+0x126
> f2d71d00 bf80a54c be2b9570 00000001 f2d71d48
> win32k!xxxInternalUpdateWindow+0x79
> f2d71d10 bf80a6cf be2b9570 f2d71d58 0007fd58 win32k!xxxUpdateWindow+0x17
> f2d71d48 80ad5a48 be2b9570 0000005e 80ad59bd
> win32k!NtUserCallHwndLock+0xf2
> f2d71d48 7c834684 be2b9570 0000005e 80ad59bd nt!KiFastCallEntry+0x158
> 0007fd20 7c8345e3 0007fd30 00000018 006ca958 ntdll!KiFastSystemCallRet
> 0007fd44 77cea0aa 77cea00e 000500f8 0000005e
> ntdll!KiUserCallbackDispatcher+0x13
> 0007fd58 77d1b83a 000500f8 00000000 00000130 USER32!NtUserCallHwndLock+0xc
> 0007fd70 010024c4 000500f8 01015018 77e6a338
> USER32!UpdateWindow_wrapper+0x3e
> 0007fe08 010027c7 0000007a 77e78bf7 000a2ea6 calc!InitSciCalc+0x414
> 0007ff1c 01013152 000aab90 00000055 000aab90 calc!WinMain+0x1dd
> 0007ffc0 77e821ce 7cb3e3a6 00000000 7ffd4000 calc!WinMainCRTStartup+0x174
> 0007fff0 00000000 01012fde 00000000 78746341
> kernel32!BaseProcessStart+0x23
>
>
> FOLLOWUP_IP:
> win32k!EXLATEOBJ::bInitXlateObj+b0
> bf943776 8b4818 mov ecx,[eax+0x18]
>
> SYMBOL_STACK_INDEX: 0
> FOLLOWUP_NAME: MachineOwner
> SYMBOL_NAME: win32k!EXLATEOBJ::bInitXlateObj+b0
> STACK_COMMAND: .trap fffffffff2d714bc ; kb
> FAILURE_BUCKET_ID: 0x50_win32k!EXLATEOBJ::bInitXlateObj+b0
> BUCKET_ID: 0x50_win32k!EXLATEOBJ::bInitXlateObj+b0
>
> Followup: MachineOwner
> ---------
>
>
> =================================================
> Roger Tawa
> http://tawacentral.net/
> [One thing about paradigms: shift happens.]
> [When you stop, you’re done.]
>
>
>
>
>
> —
> Questions? First check the IFS FAQ at
> https://www.osronline.com/article.cfm?id=17
>
> You are currently subscribed to ntfsd as: xxxxx@bellsouth.net
> To unsubscribe send a blank email to xxxxx@lists.osr.com
>

3

Thanks for the tip Alex.

I took a look at all DbgPrint() calls, as well as calls to
RtlStringXXX functions I use to format info for debugging. One bug I
found was that I was using %Z instead of %wZ to format
UNICODE_STRINGs. I fixed this, but it did not make the crash go away.

I have now compiled out all calls to DbgPrint() and any RtlStringXXX
functions. The only place where this is still one call to
RtlStringCbCatNW() is in the rename path, but my crash scenario does
not go through there.

I am still getting a crash, so I suspect the logging code is not the
cause. I have place the output of another run of windbg below. I
think I will enable driver verifier for win32k.sys to see if I get any
more insight.

In some cases, I see this when I type analyze -v after the crash:

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

what does this mean (pifsk is my FSD)

The partial output of the Modules… menu item is this:

Name Start End Timestamp Checksum Symbols Symbol file
kmixer f298a000 f29ba400 Wed Aug 04 03:09:44 2004 (41108bb8) 00038921 PDB …
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
pifsk f29bb000 f29dd580 Thu Feb 23 21:47:51 2006 (43fe73d7) 0002a099 PDB …

Output of windbg:



 This is the string you add to your checkin description
 Driver Verifier: Enabled for pifsk.sys on Build 2600 JQsxF3onQhyGsyMxpGz5oD

****
(s: 0 0x264.27c csrss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x180.1cc cmd.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3f4.3f0 net.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3e8.3e4 net1.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x18c.1e0 pifss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
NOTICE: PiStore startup - version 1.20
INFO: Master record found in PiStore.dat
NOTICE: PiStore hasn’t been properly shut down
automatic recovery in progress…
NOTICE: Recovery finished
NOTICE: PiStore running
WARNING: Full scan query!!!
WARNING: Full scan query!!!
GDI: NtGdiDrawStreamInternal: destination clip is empty

(s: 0 0x634.68c Explorer.EXE) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x634.68c explorer.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid
hwnd (00000000)
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Manifest) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Config) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateStreams(MessageFlags=1) exiting 0xc000000f
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x168.240 calc.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd (00000000)

Fatal System Error: 0x00000050
(0xFFFF0901,0x00000001,0xBF830AE7,0x00000000)

Driver at fault:
 win32k.sys - Address BF830AE7 base at BF800000, DateStamp 41108c9f
.
Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols
…
Loading unloaded module list
…
Loading User Symbols
…
Bugcheck Analysis



Use !analyze -v to get detailed debugging information.

BugCheck 50, {ffff0901, 1, bf830ae7, 0}

Probably caused by : hardware ( win32k!NtGdiExtTextOutW+33f )

Followup: MachineOwner
---------

nt!RtlpBreakWithStatusInstruction:
80aba26c cc int 3
kd> !analyze -v
Bugcheck Analysis



PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except,
it must be protected by a Probe. Typically the address is just plain bad or it
is pointing at freed memory.
Arguments:
Arg1: ffff0901, memory referenced.
Arg2: 00000001, value 0 = read operation, 1 = write operation.
Arg3: bf830ae7, If non-zero, the instruction address which referenced
the bad memory
address.
Arg4: 00000000, (reserved)

Debugging Details:
------------------

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

WRITE_ADDRESS: ffff0901

FAULTING_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

MM_INTERNAL_CODE: 0

IMAGE_NAME: hardware

DEBUG_FLR_IMAGE_TIMESTAMP: 0

FAULTING_MODULE: bf800000 win32k

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x50

LAST_CONTROL_TRANSFER: from ad5a48f3 to bf830ae7

MISALIGNED_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

TRAP_FRAME: f3a07608 – (.trap fffffffff3a07608)
ErrCode = 00000002
eax=00000001 ebx=00000044 ecx=85b396cc edx=00000000 esi=0007f4aa edi=f3a0770a
eip=bf830ae7 esp=f3a0767c ebp=f3a0779b iopl=0 nv up ei ng nz ac po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010296
win32k!NtGdiExtTextOutW+0x33f:
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743] ds:0023:ffff0901=???
Resetting default scope

STACK_TEXT:
f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3
00000000 00000000 00000000 00000000 00000000 0xad59bd00

FOLLOWUP_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

SYMBOL_STACK_INDEX: 0

FOLLOWUP_NAME: MachineOwner

SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f

STACK_COMMAND: .trap fffffffff3a07608 ; kb

MODULE_NAME: hardware

FAILURE_BUCKET_ID: IP_MISALIGNED

BUCKET_ID: IP_MISALIGNED

Followup: MachineOwner
---------

kd> !thread
THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread: e1e52008
RUNNING on processor 0
Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit f3a03000 Call f3a07a7c
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
f3a0714c 80a30be1 00000003 ffff0901 00000000
nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 00000003 c03fffc0 00000001
nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 00000050 ffff0901 00000001 nt!KeBugCheck2+0x574
(FPO: [Non-Fpo])
f3a07598 80a9e9c3 00000050 ffff0901 00000001 nt!KeBugCheckEx+0x1b
(FPO: [Non-Fpo])
f3a075f0 80ad8d18 00000001 ffff0901 00000000 nt!MmAccessFault+0xd33
(FPO: [Non-Fpo])
f3a075f0 bf830ae7 00000001 ffff0901 00000000 nt!KiTrap0E+0xdc (FPO:
[0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 01044880 0000101d 00000100
win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3
00000000 00000000 00000000 00000000 00000000 0xad59bd00

kd> !process
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe
VadRoot 85c2fc60 Vads 56 Clone 0 Private 176. Modified 2994. Locked 0.
DeviceMap e1a93b60
Token e10e2940
ElapsedTime 00:00:00.578
UserTime 00:00:00.031
KernelTime 00:00:00.250
QuotaPoolUsage[PagedPool] 34100
QuotaPoolUsage[NonPagedPool] 2240
Working Set Sizes (now,min,max) (1107, 50, 345) (4428KB, 200KB, 1380KB)
PeakWorkingSetSize 1107
VirtualSize 33 Mb
PeakVirtualSize 39 Mb
PageFaultCount 1168
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 519

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0

kd> !process 0 e calc.exe
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0
Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit
f3a03000 Call f3a07a7c
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr
f3a0714c 80a30be1 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 nt!KeBugCheck2+0x574 (FPO: [Non-Fpo])
f3a07598 80a9e9c3 nt!KeBugCheckEx+0x1b (FPO: [Non-Fpo])
f3a075f0 80ad8d18 nt!MmAccessFault+0xd33 (FPO: [Non-Fpo])
f3a075f0 bf830ae7 nt!KiTrap0E+0xdc (FPO: [0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 0xad5a48f3
00000000 00000000 0xad59bd00

On 2/21/06, xxxxx@Home wrote:
> > Unfortunately, when I enable tracing, I cannot repro the fault. When I
> > disable tracing, I can repro the fault easily. So I suspect a timing/race
> > condition. Would you agree?
> Possible, but…
> Just a suggestion: check all (all) your DbgPrint buffers.
> If you write 90 bytes into an 80-byte buffer, the symptoms
> may be similar to what you see.
>

[snip]

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you’re done.]

4

I don’t see where you use the recommended stack analysis command(s):
STACK_COMMAND: .trap fffffffff3a07608 ; kb

Follow the stack back up into your driver to find the error.

“Roger Tawa” wrote in message news:xxxxx@ntfsd…
Thanks for the tip Alex.

I took a look at all DbgPrint() calls, as well as calls to
RtlStringXXX functions I use to format info for debugging. One bug I
found was that I was using %Z instead of %wZ to format
UNICODE_STRINGs. I fixed this, but it did not make the crash go away.

I have now compiled out all calls to DbgPrint() and any RtlStringXXX
functions. The only place where this is still one call to
RtlStringCbCatNW() is in the rename path, but my crash scenario does
not go through there.

I am still getting a crash, so I suspect the logging code is not the
cause. I have place the output of another run of windbg below. I
think I will enable driver verifier for win32k.sys to see if I get any
more insight.

In some cases, I see this when I type analyze -v after the crash:

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

what does this mean (pifsk is my FSD)

The partial output of the Modules… menu item is this:

Name Start End Timestamp Checksum Symbols Symbol file
kmixer f298a000 f29ba400 Wed Aug 04 03:09:44 2004 (41108bb8) 00038921 PDB
…
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000)
00000000 None kmixer.sys
pifsk f29bb000 f29dd580 Thu Feb 23 21:47:51 2006 (43fe73d7) 0002a099 PDB …

Output of windbg:



 This is the string you add to your checkin description
 Driver Verifier: Enabled for pifsk.sys on Build 2600
JQsxF3onQhyGsyMxpGz5oD

****
(s: 0 0x264.27c csrss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x180.1cc cmd.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3f4.3f0 net.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3e8.3e4 net1.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x18c.1e0 pifss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
NOTICE: PiStore startup - version 1.20
INFO: Master record found in PiStore.dat
NOTICE: PiStore hasn’t been properly shut down
automatic recovery in progress…
NOTICE: Recovery finished
NOTICE: PiStore running
WARNING: Full scan query!!!
WARNING: Full scan query!!!
GDI: NtGdiDrawStreamInternal: destination clip is empty

(s: 0 0x634.68c Explorer.EXE) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x634.68c explorer.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid
hwnd (00000000)
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Manifest) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Config) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateStreams(MessageFlags=1) exiting 0xc000000f
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x168.240 calc.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd
(00000000)

Fatal System Error: 0x00000050
(0xFFFF0901,0x00000001,0xBF830AE7,0x00000000)

Driver at fault:
 win32k.sys - Address BF830AE7 base at BF800000, DateStamp 41108c9f
.
Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols
…
Loading unloaded module list
…
Loading User Symbols
…

Bugcheck Analysis



******

Use !analyze -v to get detailed debugging information.

BugCheck 50, {ffff0901, 1, bf830ae7, 0}

Probably caused by : hardware ( win32k!NtGdiExtTextOutW+33f )

Followup: MachineOwner
---------

nt!RtlpBreakWithStatusInstruction:
80aba26c cc int 3
kd> !analyze -v

Bugcheck Analysis



******

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by
try-except,
it must be protected by a Probe. Typically the address is just plain bad or
it
is pointing at freed memory.
Arguments:
Arg1: ffff0901, memory referenced.
Arg2: 00000001, value 0 = read operation, 1 = write operation.
Arg3: bf830ae7, If non-zero, the instruction address which referenced
the bad memory
address.
Arg4: 00000000, (reserved)

Debugging Details:
------------------

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

WRITE_ADDRESS: ffff0901

FAULTING_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

MM_INTERNAL_CODE: 0

IMAGE_NAME: hardware

DEBUG_FLR_IMAGE_TIMESTAMP: 0

FAULTING_MODULE: bf800000 win32k

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x50

LAST_CONTROL_TRANSFER: from ad5a48f3 to bf830ae7

MISALIGNED_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

TRAP_FRAME: f3a07608 – (.trap fffffffff3a07608)
ErrCode = 00000002
eax=00000001 ebx=00000044 ecx=85b396cc edx=00000000 esi=0007f4aa
edi=f3a0770a
eip=bf830ae7 esp=f3a0767c ebp=f3a0779b iopl=0 nv up ei ng nz ac po
nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010296
win32k!NtGdiExtTextOutW+0x33f:
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
ds:0023:ffff0901=???
Resetting default scope

STACK_TEXT:
f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3
00000000 00000000 00000000 00000000 00000000 0xad59bd00

FOLLOWUP_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

SYMBOL_STACK_INDEX: 0

FOLLOWUP_NAME: MachineOwner

SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f

STACK_COMMAND: .trap fffffffff3a07608 ; kb

MODULE_NAME: hardware

FAILURE_BUCKET_ID: IP_MISALIGNED

BUCKET_ID: IP_MISALIGNED

Followup: MachineOwner
---------

kd> !thread
THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread: e1e52008
RUNNING on processor 0
Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit f3a03000 Call
f3a07a7c
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
f3a0714c 80a30be1 00000003 ffff0901 00000000
nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 00000003 c03fffc0 00000001
nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 00000050 ffff0901 00000001 nt!KeBugCheck2+0x574
(FPO: [Non-Fpo])
f3a07598 80a9e9c3 00000050 ffff0901 00000001 nt!KeBugCheckEx+0x1b
(FPO: [Non-Fpo])
f3a075f0 80ad8d18 00000001 ffff0901 00000000 nt!MmAccessFault+0xd33
(FPO: [Non-Fpo])
f3a075f0 bf830ae7 00000001 ffff0901 00000000 nt!KiTrap0E+0xdc (FPO:
[0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 01044880 0000101d 00000100
win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3
00000000 00000000 00000000 00000000 00000000 0xad59bd00

kd> !process
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe
VadRoot 85c2fc60 Vads 56 Clone 0 Private 176. Modified 2994. Locked 0.
DeviceMap e1a93b60
Token e10e2940
ElapsedTime 00:00:00.578
UserTime 00:00:00.031
KernelTime 00:00:00.250
QuotaPoolUsage[PagedPool] 34100
QuotaPoolUsage[NonPagedPool] 2240
Working Set Sizes (now,min,max) (1107, 50, 345) (4428KB, 200KB, 1380KB)
PeakWorkingSetSize 1107
VirtualSize 33 Mb
PeakVirtualSize 39 Mb
PageFaultCount 1168
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 519

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0

kd> !process 0 e calc.exe
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0
Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit
f3a03000 Call f3a07a7c
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr
f3a0714c 80a30be1 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 nt!KeBugCheck2+0x574 (FPO: [Non-Fpo])
f3a07598 80a9e9c3 nt!KeBugCheckEx+0x1b (FPO: [Non-Fpo])
f3a075f0 80ad8d18 nt!MmAccessFault+0xd33 (FPO: [Non-Fpo])
f3a075f0 bf830ae7 nt!KiTrap0E+0xdc (FPO: [0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 0xad5a48f3
00000000 00000000 0xad59bd00

On 2/21/06, xxxxx@Home wrote:
> > Unfortunately, when I enable tracing, I cannot repro the fault. When I
> > disable tracing, I can repro the fault easily. So I suspect a
> > timing/race
> > condition. Would you agree?
> Possible, but…
> Just a suggestion: check all (all) your DbgPrint buffers.
> If you write 90 bytes into an 80-byte buffer, the symptoms
> may be similar to what you see.
>

[snip]

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you’re done.]

5

Hi David,

On 2/24/06, David J. Craig wrote:
> I don’t see where you use the recommended stack analysis command(s):
> STACK_COMMAND: .trap fffffffff3a07608 ; kb

The result of both commands can be seen already in the analyze output;
see the output under TRAP_FRAME: and STACK_TEXT:.

Having enabled driver verifier on win32k.sys, I am breaking earlier in
the debugger. I now get an access violation, the stack trace is at
the end of this email. The address at the top of the stack (be272ee0)
does not correspond to any modules loaded on my system.

On my screen, I see that the calc program’s window is partially drawn.
Could it be that the calc.exe image is being unloaded while win32k
tries to draw the window based on resources in calc.exe?

Access violation - code c0000005 (!!! second chance !!!)
be272ee0 c60004 mov byte ptr [eax],0x4
kd> !thread
THREAD 85b76a80 Cid 0780.0774 Teb: 7ffdf000 Win32Thread: 87b84eb0
RUNNING on processor 0
Not impersonating
DeviceMap e15369d0
Owning Process 850d7b38 Image: calc.exe
Wait Start TickCount 16197 Ticks: 2 (0:00:00:00.031)
Context Switch Count 192 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0265
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f46e8ae0 Current f46e8474 Base f46e9000 Limit f46e4000 Call f46e8ae8
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
f46e8664 bf81ab96 be272ee0 86170eec 00000001 0xbe272ee0
f46e8690 bf81ac4a be272ee0 00000004 bfa69820
win32k!xxxInternalDoSyncPaint+0x18 (FPO: [Non-Fpo])
f46e86c8 bf81befe 87b84eb0 00000004 00000000
win32k!xxxInternalDoSyncPaint+0xcc (FPO: [Non-Fpo])
f46e86dc bf81b2f4 be270dd0 00000004 00000000
win32k!xxxDoSyncPaint+0x31 (FPO: [Non-Fpo])
f46e8780 bf81b474 00000001 00000000 bf9df938
win32k!xxxEndDeferWindowPosEx+0x3f7 (FPO: [Non-Fpo])
f46e87a0 bf81dbd0 be272ee0 00000000 00000000
win32k!xxxSetWindowPos+0x127 (FPO: [Non-Fpo])
f46e8814 80ad5a48 00000000 00000000 00000000
win32k!NtUserSetWindowPos+0x212 (FPO: [Non-Fpo])
f46e8814 7c834684 00000000 00000000 00000000 nt!KiFastCallEntry+0x158
(FPO: [0,3] TrapFrame @ f46e8844)
0007fbf0 77cebd30 01006a12 000400c6 00000000 ntdll!KiFastSystemCallRet
(FPO: [0,0,0])
0007fc34 77d13df0 000400c6 00000005 00000000 user32!NtUserSetWindowPos+0xc
0007fc60 77d1efeb 010067f9 000400c6 00000005 user32!InternalCallWinProc+0x28
0007fcc8 77ce96ef 00000000 010067f9 000400c6
user32!UserCallWinProcCheckWow+0x150 (FPO: [Non-Fpo])
0007fd1c 77ce9920 00682ee0 00000005 00000000
user32!DispatchClientMessage+0x126 (FPO: [Non-Fpo])
0007fd44 7c8345e3 0007fd54 00000018 00682ee0 user32!__fnDWORD+0x24
(FPO: [Non-Fpo])
0007fd44 80a3c6f4 0007fd54 00000018 00682ee0
ntdll!KiUserCallbackDispatcher+0x13 (FPO: [0,0,0])
f46e8b00 80b7529e f46e8bcc f46e8bc4 7ffdf6f4 nt!KiCallUserMode+0x4
(FPO: [2,3,4])
f46e8b5c bf806d03 00000002 f46e8bac 00000018
nt!KeUserModeCallback+0xc8 (FPO: [Non-Fpo])
f46e8bf8 bf8f94cf be272ee0 00000005 00000000 win32k!SfnDWORD+0x114
(FPO: [Non-Fpo])
f46e8c50 bf8035a7 03272ee0 00000005 00000000
win32k!xxxSendMessageToClient+0x153 (FPO: [Non-Fpo])
f46e8ca0 bf80ddcd be272ee0 00000005 00000000
win32k!xxxSendMessageTimeout+0x1f1 (FPO: [Non-Fpo])
f46e8cc4 bf822e79 be272ee0 00000005 00000000
win32k!xxxSendMessage+0x1b (FPO: [Non-Fpo])
f46e8cec bf822971 be272ee0 00000000 be272ee0
win32k!xxxSendSizeMessage+0x41 (FPO: [Non-Fpo])
f46e8d0c bf82c3d2 00000000 00000043 0007fd7c
win32k!xxxShowWindow+0x28f (FPO: [Non-Fpo])
f46e8d48 80ad5a48 000400c6 00000005 80ad59bd
win32k!NtUserShowWindow+0x131 (FPO: [Non-Fpo])
f46e8d48 7c834684 000400c6 00000005 80ad59bd nt!KiFastCallEntry+0x158
(FPO: [0,3] TrapFrame @ f46e8d64)
0007fd44 7c8345e3 0007fd54 00000018 00682ee0 ntdll!KiFastSystemCallRet
(FPO: [0,0,0])
0007fd68 77cf2096 010024b8 000400c6 00000005
ntdll!KiUserCallbackDispatcher+0x13 (FPO: [0,0,0])
0007fe08 010027c7 0000007a 77e78bf7 000a2ea6 user32!NtUserShowWindow+0xc
0007ff1c 01013152 000aab90 00000055 000aab90 calc!WinMain+0x1dd (FPO: [Non-Fpo])
0007ffc0 77e821ce 7cb3e3a6 00000000 7ffd8000
calc!WinMainCRTStartup+0x174 (FPO: [Non-Fpo])
0007fff0 00000000 01012fde 00000000 78746341
kernel32!BaseProcessStart+0x23 (FPO: [Non-Fpo])

kd> lm m calc
start end module name
01000000 01027000 calc (pdb symbols)
C:\Symbols\calc.pdb\3B7D7F9A1\calc.pdb

kd> u win32k!xxxInternalDoSyncPaint L20
win32k!xxxInternalDoSyncPaint:
bf81ab7e 8bff mov edi,edi
bf81ab80 55 push ebp
bf81ab81 8bec mov ebp,esp
bf81ab83 83ec1c sub esp,0x1c
bf81ab86 56 push esi
bf81ab87 8b7508 mov esi,[ebp+0x8]
bf81ab8a 56 push esi
bf81ab8b e8ee760800 call win32k!CheckLock (bf8a227e)
bf81ab90 56 push esi
bf81ab91 e8f139ffff call win32k!xxxSimpleDoSyncPaint (bf80e587)
bf81ab96 f6450c20 test byte ptr [ebp+0xc],0x20 <-----
win32k!xxxInternalDoSyncPaint+0x18 here
bf81ab9a 7514 jnz win32k!xxxInternalDoSyncPaint+0x32 (bf81abb0)
bf81ab9c f6450c04 test byte ptr [ebp+0xc],0x4
bf81aba0 0f84bf000000 je win32k!xxxInternalDoSyncPaint+0xe7 (bf81ac65)
bf81aba6 f6462302 test byte ptr [esi+0x23],0x2
bf81abaa 0f84b5000000 je win32k!xxxInternalDoSyncPaint+0xe7 (bf81ac65)

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you’re done.]

6

> On my screen, I see that the calc program’s window is partially drawn.

Could it be that the calc.exe image is being unloaded while win32k
tries to draw the window based on resources in calc.exe?

Although I cannot give you any reasonable advice,
I am 100% sure that this is not the problem

L.

7

The docs for KdPrint / DbgPrint explicitly say that you cannot use format
strings that operate on Unicode strings at elevated IRQL (DISPATCH_LEVEL or
above):

Specifies a pointer to the format string to print.
The Format string supports all the printf-style
formatting codes. However, the Unicode format codes
(%C, %S, %lc, %ls, %wc, %ws, and %wZ) can only be
used with IRQL = PASSIVE_LEVEL.

Presumably this is because the code that handles converting Unicode to 8-bit
is pageable.

– arlie

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Roger Tawa
Sent: Friday, February 24, 2006 10:11 AM
To: Windows File Systems Devs Interest List
Subject: Re: [ntfsd] PAGE_FAULT_IN_NONPAGED_AREA running .exe

Thanks for the tip Alex.

I took a look at all DbgPrint() calls, as well as calls to RtlStringXXX
functions I use to format info for debugging. One bug I found was that I
was using %Z instead of %wZ to format UNICODE_STRINGs. I fixed this, but it
did not make the crash go away.

I have now compiled out all calls to DbgPrint() and any RtlStringXXX
functions. The only place where this is still one call to
RtlStringCbCatNW() is in the rename path, but my crash scenario does not go
through there.

I am still getting a crash, so I suspect the logging code is not the cause.
I have place the output of another run of windbg below. I think I will
enable driver verifier for win32k.sys to see if I get any more insight.

In some cases, I see this when I type analyze -v after the crash:

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

what does this mean (pifsk is my FSD)

The partial output of the Modules… menu item is this:

Name Start End Timestamp Checksum Symbols Symbol file kmixer f298a000
f29ba400 Wed Aug 04 03:09:44 2004 (41108bb8) 00038921 PDB …
f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000) 00000000
None kmixer.sys f29ad000 f29de000 Wed Dec 31 19:00:00 1969
(00000000) 00000000 None kmixer.sys f29ad000 f29de000 Wed Dec 31
19:00:00 1969 (00000000) 00000000 None kmixer.sys pifsk f29bb000 f29dd580
Thu Feb 23 21:47:51 2006 (43fe73d7) 0002a099 PDB …

Output of windbg:

*********************************************************************

This is the string you add to your checkin description
 Driver Verifier: Enabled for pifsk.sys on Build 2600
JQsxF3onQhyGsyMxpGz5oD

*************************************************************************
(s: 0 0x264.27c csrss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x180.1cc cmd.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3f4.3f0 net.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
ShimLib - [Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x3e8.3e4 net1.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x18c.1e0 pifss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
NOTICE: PiStore startup - version 1.20
INFO: Master record found in PiStore.dat
NOTICE: PiStore hasn’t been properly shut down
automatic recovery in progress…
NOTICE: Recovery finished
NOTICE: PiStore running
WARNING: Full scan query!!!
WARNING: Full scan query!!!
GDI: NtGdiDrawStreamInternal: destination clip is empty

(s: 0 0x634.68c Explorer.EXE) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x634.68c explorer.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd
(00000000)
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Manifest) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Config) failed
SXS: BasepSxsCreateFileStream() exiting 0xc000000f
SXS: BasepSxsCreateStreams(MessageFlags=1) exiting 0xc000000f ShimLib -
[Shim] AddProcessParametersFlags(“20000”)
(s: 0 0x168.240 calc.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
Invalid:00000000 Type:0x1
(s: 0 0x168.240 calc.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd
(00000000)

Fatal System Error: 0x00000050
(0xFFFF0901,0x00000001,0xBF830AE7,0x00000000)

Driver at fault:
 win32k.sys - Address BF830AE7 base at BF800000, DateStamp 41108c9f
.
Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE Loading
Kernel Symbols
…
…
Loading unloaded module list
…
Loading User Symbols
…
*******************************************************************


Bugcheck Analysis



*************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck 50, {ffff0901, 1, bf830ae7, 0}

Probably caused by : hardware ( win32k!NtGdiExtTextOutW+33f )

Followup: MachineOwner
---------

nt!RtlpBreakWithStatusInstruction:
80aba26c cc int 3
kd> !analyze -v
*******************************************************************


Bugcheck Analysis



*************************************************************************

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by
try-except, it must be protected by a Probe. Typically the address is just
plain bad or it is pointing at freed memory.
Arguments:
Arg1: ffff0901, memory referenced.
Arg2: 00000001, value 0 = read operation, 1 = write operation.
Arg3: bf830ae7, If non-zero, the instruction address which referenced the
bad memory address.
Arg4: 00000000, (reserved)

Debugging Details:
------------------

OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap

WRITE_ADDRESS: ffff0901

FAULTING_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

MM_INTERNAL_CODE: 0

IMAGE_NAME: hardware

DEBUG_FLR_IMAGE_TIMESTAMP: 0

FAULTING_MODULE: bf800000 win32k

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x50

LAST_CONTROL_TRANSFER: from ad5a48f3 to bf830ae7

MISALIGNED_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

TRAP_FRAME: f3a07608 – (.trap fffffffff3a07608) ErrCode = 00000002
eax=00000001 ebx=00000044 ecx=85b396cc edx=00000000 esi=0007f4aa
edi=f3a0770a
eip=bf830ae7 esp=f3a0767c ebp=f3a0779b iopl=0 nv up ei ng nz ac po
nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010296
win32k!NtGdiExtTextOutW+0x33f:
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
ds:0023:ffff0901=???
Resetting default scope

STACK_TEXT:
f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3 00000000 00000000
00000000 00000000 00000000 0xad59bd00

FOLLOWUP_IP:
win32k!NtGdiExtTextOutW+33f
bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]

SYMBOL_STACK_INDEX: 0

FOLLOWUP_NAME: MachineOwner

SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f

STACK_COMMAND: .trap fffffffff3a07608 ; kb

MODULE_NAME: hardware

FAILURE_BUCKET_ID: IP_MISALIGNED

BUCKET_ID: IP_MISALIGNED

Followup: MachineOwner
---------

kd> !thread
THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread: e1e52008 RUNNING
on processor 0 Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde) Stack Init f3a07a70
Current f3a06e40 Base f3a08000 Limit f3a03000 Call f3a07a7c Priority 8
BasePriority 8 PriorityDecrement 0 DecrementCount 0 ChildEBP RetAddr Args
to Child f3a0714c 80a30be1 00000003 ffff0901 00000000
nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 00000003 c03fffc0 00000001
nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 00000050 ffff0901 00000001 nt!KeBugCheck2+0x574
(FPO: [Non-Fpo])
f3a07598 80a9e9c3 00000050 ffff0901 00000001 nt!KeBugCheckEx+0x1b
(FPO: [Non-Fpo])
f3a075f0 80ad8d18 00000001 ffff0901 00000000 nt!MmAccessFault+0xd33
(FPO: [Non-Fpo])
f3a075f0 bf830ae7 00000001 ffff0901 00000000 nt!KiTrap0E+0xdc (FPO:
[0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
(FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3 00000000 00000000
00000000 00000000 00000000 0xad59bd00

kd> !process
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe
VadRoot 85c2fc60 Vads 56 Clone 0 Private 176. Modified 2994. Locked 0.
DeviceMap e1a93b60
Token e10e2940
ElapsedTime 00:00:00.578
UserTime 00:00:00.031
KernelTime 00:00:00.250
QuotaPoolUsage[PagedPool] 34100
QuotaPoolUsage[NonPagedPool] 2240
Working Set Sizes (now,min,max) (1107, 50, 345) (4428KB, 200KB, 1380KB)
PeakWorkingSetSize 1107
VirtualSize 33 Mb
PeakVirtualSize 39 Mb
PageFaultCount 1168
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 519

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0

kd> !process 0 e calc.exe
PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid: 0634
DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
Image: calc.exe

THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
e1e52008 RUNNING on processor 0
Not impersonating
DeviceMap e1a93b60
Owning Process 858d42e0 Image: calc.exe
Wait Start TickCount 16250 Ticks: 0
Context Switch Count 199 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0234
Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit f3a03000
Call f3a07a7c
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr
f3a0714c 80a30be1 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
f3a07198 80a31854 nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
f3a07578 80a31de5 nt!KeBugCheck2+0x574 (FPO: [Non-Fpo])
f3a07598 80a9e9c3 nt!KeBugCheckEx+0x1b (FPO: [Non-Fpo])
f3a075f0 80ad8d18 nt!MmAccessFault+0xd33 (FPO: [Non-Fpo])
f3a075f0 bf830ae7 nt!KiTrap0E+0xdc (FPO: [0,0] TrapFrame @ f3a07608)
f3a0779b ad5a48f3 win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f3a077c3 ad59bd00 0xad5a48f3
00000000 00000000 0xad59bd00

On 2/21/06, xxxxx@Home wrote:
> > Unfortunately, when I enable tracing, I cannot repro the fault.
> > When I disable tracing, I can repro the fault easily. So I suspect
> > a timing/race condition. Would you agree?
> Possible, but…
> Just a suggestion: check all (all) your DbgPrint buffers.
> If you write 90 bytes into an 80-byte buffer, the symptoms may be
> similar to what you see.
>

[snip]

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.] [When you stop, you’re done.]

—
Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as: unknown lmsubst tag argument: ‘’
To unsubscribe send a blank email to xxxxx@lists.osr.com

8

> you cannot use format

strings that operate on Unicode strings at elevated IRQL (DISPATCH_LEVEL
or
above)
True, but Roger says that his chk build works.

I still suspect that Roger overwrites a buffer somewhere.

Roger, is the crash reproducible, in the first place? If it is, the
analysis should not be difficult.

Remote debugging through smtp is not especially welcome
in this list, just several (trivial) suggestions:

  1. OVERLAPPED_MODULE can be ignored.

  2. Have you tried to bp at “win32k!NtGdiExtTextOutW+0x33f”?
    Do you hit this spot successfully before crashing?

  3. Is the code (yes, I mean “code inside win32k”) intact?
    Are the params of the pre-mortal call reasonable?

  4. Ok, chk works, fre does not; where is that border between
    good and evil?
    What if you (temporarily) disable optinmizations in release build
    (so that DBG-related things are out, but all the rest is as it is in
    chk) - does it explode?
    The other way round: make a special build with DBG=1 but
    optimizations turned ON - does it explode now?

----- Original Message -----
From: “Arlie Davis”
To: “Windows File Systems Devs Interest List”
Sent: Monday, February 27, 2006 6:27 PM
Subject: RE: [ntfsd] PAGE_FAULT_IN_NONPAGED_AREA running .exe

> The docs for KdPrint / DbgPrint explicitly say that you cannot use format
> strings that operate on Unicode strings at elevated IRQL (DISPATCH_LEVEL
> or
> above):
>
> Specifies a pointer to the format string to print.
> The Format string supports all the printf-style
> formatting codes. However, the Unicode format codes
> (%C, %S, %lc, %ls, %wc, %ws, and %wZ) can only be
> used with IRQL = PASSIVE_LEVEL.
>
> Presumably this is because the code that handles converting Unicode to
> 8-bit
> is pageable.
>
> – arlie
>
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Roger Tawa
> Sent: Friday, February 24, 2006 10:11 AM
> To: Windows File Systems Devs Interest List
> Subject: Re: [ntfsd] PAGE_FAULT_IN_NONPAGED_AREA running .exe
>
> Thanks for the tip Alex.
>
> I took a look at all DbgPrint() calls, as well as calls to RtlStringXXX
> functions I use to format info for debugging. One bug I found was that I
> was using %Z instead of %wZ to format UNICODE_STRINGs. I fixed this, but
> it
> did not make the crash go away.
>
> I have now compiled out all calls to DbgPrint() and any RtlStringXXX
> functions. The only place where this is still one call to
> RtlStringCbCatNW() is in the rename path, but my crash scenario does not
> go
> through there.
>
> I am still getting a crash, so I suspect the logging code is not the
> cause.
> I have place the output of another run of windbg below. I think I will
> enable driver verifier for win32k.sys to see if I get any more insight.
>
> In some cases, I see this when I type analyze -v after the crash:
>
> OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap
>
> what does this mean (pifsk is my FSD)
>
> The partial output of the Modules… menu item is this:
>
> Name Start End Timestamp Checksum Symbols Symbol file kmixer f298a000
> f29ba400 Wed Aug 04 03:09:44 2004 (41108bb8) 00038921 PDB …
> f29ad000 f29de000 Wed Dec 31 19:00:00 1969 (00000000) 00000000
> None kmixer.sys f29ad000 f29de000 Wed Dec 31 19:00:00 1969
> (00000000) 00000000 None kmixer.sys f29ad000 f29de000 Wed Dec
> 31
> 19:00:00 1969 (00000000) 00000000 None kmixer.sys pifsk f29bb000 f29dd580
> Thu Feb 23 21:47:51 2006 (43fe73d7) 0002a099 PDB …
>
>
> Output of windbg:
>
> *************************************************************************
>
> *
> * This is the string you add to your checkin description
> * Driver Verifier: Enabled for pifsk.sys on Build 2600
> JQsxF3onQhyGsyMxpGz5oD
> *
> *************************************************************************
>
> (s: 0 0x264.27c csrss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> (s: 0 0x180.1cc cmd.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> ShimLib - [Shim] AddProcessParametersFlags(“20000”)
> (s: 0 0x3f4.3f0 net.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> ShimLib - [Shim] AddProcessParametersFlags(“20000”)
> (s: 0 0x3e8.3e4 net1.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> (s: 0 0x18c.1e0 pifss.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> NOTICE: PiStore startup - version 1.20
> INFO: Master record found in PiStore.dat
> NOTICE: PiStore hasn’t been properly shut down
> automatic recovery in progress…
> NOTICE: Recovery finished
> NOTICE: PiStore running
> WARNING: Full scan query!!!
> WARNING: Full scan query!!!
> GDI: NtGdiDrawStreamInternal: destination clip is empty
>
> (s: 0 0x634.68c Explorer.EXE) USER-[Wrn=1400] HMValidateHandle:
> Invalid:00000000 Type:0x1
> (s: 0 0x634.68c explorer.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd
> (00000000)
> SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Manifest)
> failed
> SXS: BasepSxsCreateFileStream() exiting 0xc000000f
> SXS: BasepSxsCreateFileStream() NtOpenFile(??\P:\calc.exe.Config) failed
> SXS: BasepSxsCreateFileStream() exiting 0xc000000f
> SXS: BasepSxsCreateStreams(MessageFlags=1) exiting 0xc000000f ShimLib -
> [Shim] AddProcessParametersFlags(“20000”)
> (s: 0 0x168.240 calc.exe) USRK-[Wrn] xxxCreateDesktop: Object name exists
> (s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
> Invalid:00000000 Type:0x1
> (s: 0 0x168.240 calc.exe) USER-[Wrn=1400] HMValidateHandle:
> Invalid:00000000 Type:0x1
> (s: 0 0x168.240 calc.exe) USRK-[Wrn=1400] ValidateHwnd: Invalid hwnd
> (00000000)
>
> Fatal System Error: 0x00000050
> (0xFFFF0901,0x00000001,0xBF830AE7,0x00000000)
>
> Driver at fault:
> win32k.sys - Address BF830AE7 base at BF800000, DateStamp 41108c9f
> .
> Break instruction exception - code 80000003 (first chance)
>
> A fatal system error has occurred.
> Debugger entered on first try; Bugcheck callbacks have not been invoked.
>
> A fatal system error has occurred.
>
> Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE Loading
> Kernel Symbols
> …
> …
> Loading unloaded module list
> …
> Loading User Symbols
> …
> *************************************************************************
>
> *
> *
> * Bugcheck Analysis
> *
> *
> *
> *************************************************************************
>
>
> Use !analyze -v to get detailed debugging information.
>
> BugCheck 50, {ffff0901, 1, bf830ae7, 0}
>
> Probably caused by : hardware ( win32k!NtGdiExtTextOutW+33f )
>
> Followup: MachineOwner
> ---------
>
> nt!RtlpBreakWithStatusInstruction:
> 80aba26c cc int 3
> kd> !analyze -v
> *************************************************************************
>
> *
> *
> * Bugcheck Analysis
> *
> *
> *
> *************************************************************************
>
>
> PAGE_FAULT_IN_NONPAGED_AREA (50)
> Invalid system memory was referenced. This cannot be protected by
> try-except, it must be protected by a Probe. Typically the address is
> just
> plain bad or it is pointing at freed memory.
> Arguments:
> Arg1: ffff0901, memory referenced.
> Arg2: 00000001, value 0 = read operation, 1 = write operation.
> Arg3: bf830ae7, If non-zero, the instruction address which referenced the
> bad memory address.
> Arg4: 00000000, (reserved)
>
> Debugging Details:
> ------------------
>
>
> OVERLAPPED_MODULE: Address regions for ‘pifsk’ and ‘kmixer.sys’ overlap
>
> WRITE_ADDRESS: ffff0901
>
> FAULTING_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
>
> MM_INTERNAL_CODE: 0
>
> IMAGE_NAME: hardware
>
> DEBUG_FLR_IMAGE_TIMESTAMP: 0
>
> FAULTING_MODULE: bf800000 win32k
>
> DEFAULT_BUCKET_ID: DRIVER_FAULT
>
> BUGCHECK_STR: 0x50
>
> LAST_CONTROL_TRANSFER: from ad5a48f3 to bf830ae7
>
> MISALIGNED_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
>
> TRAP_FRAME: f3a07608 – (.trap fffffffff3a07608) ErrCode = 00000002
> eax=00000001 ebx=00000044 ecx=85b396cc edx=00000000 esi=0007f4aa
> edi=f3a0770a
> eip=bf830ae7 esp=f3a0767c ebp=f3a0779b iopl=0 nv up ei ng nz ac po
> nc
> cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
> efl=00010296
> win32k!NtGdiExtTextOutW+0x33f:
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
> ds:0023:ffff0901=???
> Resetting default scope
>
> STACK_TEXT:
> f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
> WARNING: Frame IP not in any known module. Following frames may be wrong.
> f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3 00000000 00000000
> 00000000 00000000 00000000 0xad59bd00
>
>
> FOLLOWUP_IP:
> win32k!NtGdiExtTextOutW+33f
> bf830ae7 ff83bd08ffff inc dword ptr [ebx-0xf743]
>
> SYMBOL_STACK_INDEX: 0
>
> FOLLOWUP_NAME: MachineOwner
>
> SYMBOL_NAME: win32k!NtGdiExtTextOutW+33f
>
> STACK_COMMAND: .trap fffffffff3a07608 ; kb
>
> MODULE_NAME: hardware
>
> FAILURE_BUCKET_ID: IP_MISALIGNED
>
> BUCKET_ID: IP_MISALIGNED
>
> Followup: MachineOwner
> ---------
>
> kd> !thread
> THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread: e1e52008
> RUNNING
> on processor 0 Not impersonating
> DeviceMap e1a93b60
> Owning Process 858d42e0 Image: calc.exe
> Wait Start TickCount 16250 Ticks: 0
> Context Switch Count 199 LargeStack
> UserTime 00:00:00.0015
> KernelTime 00:00:00.0234
> Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
> Win32 Start Address calc!WinMainCRTStartup (0x01012fde) Stack Init
> f3a07a70
> Current f3a06e40 Base f3a08000 Limit f3a03000 Call f3a07a7c Priority 8
> BasePriority 8 PriorityDecrement 0 DecrementCount 0 ChildEBP RetAddr Args
> to Child f3a0714c 80a30be1 00000003 ffff0901 00000000
> nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
> f3a07198 80a31854 00000003 c03fffc0 00000001
> nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
> f3a07578 80a31de5 00000050 ffff0901 00000001 nt!KeBugCheck2+0x574
> (FPO: [Non-Fpo])
> f3a07598 80a9e9c3 00000050 ffff0901 00000001 nt!KeBugCheckEx+0x1b
> (FPO: [Non-Fpo])
> f3a075f0 80ad8d18 00000001 ffff0901 00000000 nt!MmAccessFault+0xd33
> (FPO: [Non-Fpo])
> f3a075f0 bf830ae7 00000001 ffff0901 00000000 nt!KiTrap0E+0xdc (FPO:
> [0,0] TrapFrame @ f3a07608)
> f3a0779b ad5a48f3 01044880 0000101d 00000100 win32k!NtGdiExtTextOutW+0x33f
> (FPO: [Non-Fpo])
> WARNING: Frame IP not in any known module. Following frames may be wrong.
> f3a077c3 ad59bd00 00000080 00010000 07f42000 0xad5a48f3 00000000 00000000
> 00000000 00000000 00000000 0xad59bd00
>
> kd> !process
> PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid:
> 0634
> DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
> Image: calc.exe
> VadRoot 85c2fc60 Vads 56 Clone 0 Private 176. Modified 2994. Locked 0.
> DeviceMap e1a93b60
> Token e10e2940
> ElapsedTime 00:00:00.578
> UserTime 00:00:00.031
> KernelTime 00:00:00.250
> QuotaPoolUsage[PagedPool] 34100
> QuotaPoolUsage[NonPagedPool] 2240
> Working Set Sizes (now,min,max) (1107, 50, 345) (4428KB, 200KB,
> 1380KB)
> PeakWorkingSetSize 1107
> VirtualSize 33 Mb
> PeakVirtualSize 39 Mb
> PageFaultCount 1168
> MemoryPriority BACKGROUND
> BasePriority 8
> CommitCharge 519
>
> THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
> e1e52008 RUNNING on processor 0
>
> kd> !process 0 e calc.exe
> PROCESS 858d42e0 SessionId: 0 Cid: 0168 Peb: 7ffdb000 ParentCid:
> 0634
> DirBase: 001f1000 ObjectTable: e18d3d88 HandleCount: 27.
> Image: calc.exe
>
> THREAD 85b39698 Cid 0168.0240 Teb: 7ffdf000 Win32Thread:
> e1e52008 RUNNING on processor 0
> Not impersonating
> DeviceMap e1a93b60
> Owning Process 858d42e0 Image: calc.exe
> Wait Start TickCount 16250 Ticks: 0
> Context Switch Count 199 LargeStack
> UserTime 00:00:00.0015
> KernelTime 00:00:00.0234
> Start Address kernel32!BaseProcessStartThunk (0x77e5e3a4)
> Win32 Start Address calc!WinMainCRTStartup (0x01012fde)
> Stack Init f3a07a70 Current f3a06e40 Base f3a08000 Limit f3a03000
> Call f3a07a7c
> Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
> ChildEBP RetAddr
> f3a0714c 80a30be1 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
> f3a07198 80a31854 nt!KiBugCheckDebugBreak+0x19 (FPO: [Non-Fpo])
> f3a07578 80a31de5 nt!KeBugCheck2+0x574 (FPO: [Non-Fpo])
> f3a07598 80a9e9c3 nt!KeBugCheckEx+0x1b (FPO: [Non-Fpo])
> f3a075f0 80ad8d18 nt!MmAccessFault+0xd33 (FPO: [Non-Fpo])
> f3a075f0 bf830ae7 nt!KiTrap0E+0xdc (FPO: [0,0] TrapFrame @
> f3a07608)
> f3a0779b ad5a48f3 win32k!NtGdiExtTextOutW+0x33f (FPO: [Non-Fpo])
> WARNING: Frame IP not in any known module. Following frames may be wrong.
> f3a077c3 ad59bd00 0xad5a48f3
> 00000000 00000000 0xad59bd00
>
>
> On 2/21/06, xxxxx@Home wrote:
>> > Unfortunately, when I enable tracing, I cannot repro the fault.
>> > When I disable tracing, I can repro the fault easily. So I suspect
>> > a timing/race condition. Would you agree?
>> Possible, but…
>> Just a suggestion: check all (all) your DbgPrint buffers.
>> If you write 90 bytes into an 80-byte buffer, the symptoms may be
>> similar to what you see.
>>
>
> [snip]
>
> =================================================
> Roger Tawa
> http://tawacentral.net/
> [One thing about paradigms: shift happens.] [When you stop, you’re done.]
>
>
> —
> Questions? First check the IFS FAQ at
> https://www.osronline.com/article.cfm?id=17
>
> You are currently subscribed to ntfsd as: unknown lmsubst tag argument: ‘’
> To unsubscribe send a blank email to xxxxx@lists.osr.com
>
>
>
>
> —
> Questions? First check the IFS FAQ at
> https://www.osronline.com/article.cfm?id=17
>
> You are currently subscribed to ntfsd as: xxxxx@bellsouth.net
> To unsubscribe send a blank email to xxxxx@lists.osr.com

9

Hi Arlie,

As Alex says, I compiled out all calls to RtlStringXXX and DbgPrintXXX
and I was still able to repro my problem. Thanks for the tip though.

On 2/27/06, xxxxx@Home wrote:
> > you cannot use format
> > strings that operate on Unicode strings at elevated IRQL (DISPATCH_LEVEL
> > or
> > above)
> True, but Roger says that his chk build works.
>

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you’re done.]

10

Hi all,

To bring some closure to this issue, I’d just like to tell everyone
that I think its fixed, and what I did (or did not do) to fix it. I
say “think” because the very easy repro steps I used to cause the
crash no longer cause it, and my QA buddy is also no longer able to
repro the crash. Time will tell?

I decided to put this problem on the backburner since I was not able
to crack it. So I moved to Microsoft Word 2003 SP2: I kept getting a
sharing violation during save. I noticed two things:

My file system did not delay CcInitializeCacheMap(), I figured that
was just an optimization. Because of this, my file system was getting
a particular CLEANUP IRP much later than NTFS was for the same save
scenario. It turns out that during Word’s save dance of multiple
temporary files, multiple renames, multiple opens and multiple closes,
delaying this CLEANUP IRP causes an incompatibility between the
desired access/sharing flags of the various opens. By delaying
CcInitializeCacheMap(), the CLEANUP IRP came sooner, and avoided this
violation.

So the lesson I learn from this is that delaying
CcInitializeCacheMap() is not just an optimization for file systems,
some apps out there depend on this functionality, with or without
knowing it.

The second thing was a bug in my code. While processing the CLEANUP
IRP, I was releasing the lock on the FCB before calling
CcUninitializeCacheMap(). This is one of the last things I do in
CLEANUP, and I don’t touch the FCB after that, so there were not cases
where I would be touching an unlocked FCB, or even worse, memory that
had been freed. In any case, the reason I had done this is because a
while back I saw call a to CcUninitializeCacheMap() that caused a
recursive dispatch of a CLOSE IRP for the file object being cleaned
up, and this caused problems because in my CLOSE dispatch I check to
make sure the FCB is not locked by anyone.

However, this is a bad solution. To fix this, I decided to maintain
the FCB locked for the entire CLEANUP IRP, and post the CLOSE IRP to a
background thread if it notices that its not the top level IRP. This
seems to work just fine; don’t know if anyone has comments about this
implementation.

After making these two changes, the .exe crash problem went away. But
I can’t say I understand why these two changes fix the .exe crash.

Thanks to everyone who took the time to respond to my original post.
For every question I do post, I find enough information in the
archives to prevent me from post a dozen other questions. This is a
great list.

=================================================
Roger Tawa
http://tawacentral.net/
[One thing about paradigms: shift happens.]
[When you stop, you’re done.]