Why the DbgPrint can not work?

I’m developing a filter based on minifilter.
Recently I encounter a problem, that is my DbgPrint does not work and will lead to BSOD in a spcial condition. I have read limits and usage about DbgPrint, but I think I just use DbgPrint in a normal way, so I can not understand why this error would happen.
The following are my !analyze -v:
UNEXPECTED_KERNEL_MODE_TRAP (7f)
This means a trap occurred in kernel mode, and it’s a trap of a kind
that the kernel isn’t allowed to have/catch (bound trap) or that
is always instant death (double fault). The first number in the
bugcheck params is the number of the trap (8 = double fault, etc)
Consult an Intel x86 family manual to learn more about what these
traps are. Here is a *portion* of those codes:
If kv shows a taskGate
use .tss on the part before the colon, then kv.
Else if kv shows a trapframe
use .trap on that value
Else
.trap on the appropriate frame will show where the trap was taken
(on x86, this will be the ebp that goes with the procedure KiTrap)
Endif
kb will then show the corrected stack.
Arguments:
Arg1: 00000008, EXCEPTION_DOUBLE_FAULT
Arg2: 80042000
Arg3: 00000000
Arg4: 00000000

Debugging Details:

BUGCHECK_STR: 0x7f_8

TSS: 00000028 – (.tss 0x28)
eax=0000bb40 ebx=bacf546c ecx=00000000 edx=00000001 esi=bacf5418 edi=0000000f
eip=804fe9d0 esp=bacf4fb0 ebp=bacf503c iopl=0 nv up di ng nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010082
nt!KeContextFromKframes+0x10:
804fe9d0 53 push ebx
Resetting default scope

DEFAULT_BUCKET_ID: DRIVER_FAULT

PROCESS_NAME: System

EXCEPTION_RECORD: bacf5418 – (.exr 0xffffffffbacf5418)
ExceptionAddress: 80531e81 (nt!DebugService+0x0000001b)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 3
Parameter[0]: 00000001
Parameter[1]: bacf5548
Parameter[2]: 0000000f

TRAP_FRAME: bacf546c – (.trap 0xffffffffbacf546c)
ErrCode = 00000000
eax=00000001 ebx=ffffffff ecx=bacf5548 edx=0000000f esi=0000000f edi=00000000
eip=80531e82 esp=bacf54e0 ebp=bacf54f4 iopl=0 nv up ei pl nz na po cy
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00000203
nt!DebugService+0x1c:
80531e82 5b pop ebx
Resetting default scope

LAST_CONTROL_TRANSFER: from 804ff1d8 to 804fe9d0

STACK_TEXT:
bacf503c 804ff1d8 bacf546c 00000000 bacf5114 nt!KeContextFromKframes+0x10
bacf53fc 80542075 bacf5418 00000000 bacf546c nt!KiDispatchException+0x82
bacf5464 805427ce bacf54f4 80531e81 badb0d00 nt!CommonDispatchException+0x4d
bacf5464 80531e82 bacf54f4 80531e81 badb0d00 nt!KiTrap03+0xae
bacf54f4 80531ecc 00000001 bacf5548 0000000f nt!DebugService+0x1c
bacf5510 8052b6e3 bacf5530 ffffffff 00000000 nt!DebugPrint+0x1c
bacf5764 8052b878 8052b858 ffffffff 00000000 nt!vDbgPrintExWithPrefix+0x101
bacf5780 b143693c b14514c0 0b8b7f32 891e97dc nt!DbgPrint+0x1a
bacf5f34 ba6d5944 8958f61c bacf5f54 bacf5f84 KSkernel!KsPreReadBuffers+0x39c [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksreadcallback.c @ 241]
bacf5f94 ba6d7352 00cf5fdc 00000000 bacf5fdc fltMgr!FltpPerformPreCallbacks+0x2d4
bacf5fa8 ba6d7c15 bacf5fdc 00000000 8917a498 fltMgr!FltpPassThroughInternal+0x32
bacf5fc4 ba6d7ffb bacf5f01 891b66e0 891bce48 fltMgr!FltpPassThrough+0x1df
bacf5ff4 804efeb1 8912b4b0 8910da28 00000000 fltMgr!FltpDispatch+0xf3
bacf6004 804f08a9 00000000 891521e0 891521f0 nt!IopfCallDriver+0x31
bacf6018 804f08d1 8912b4b0 89152209 891521f8 nt!IopPageReadInternal+0xf3
bacf6038 8051681e 891b66e0 89152218 891521f8 nt!IoPageRead+0x1b
bacf60b4 80520347 e1053800 d7fc0000 c06bfe00 nt!MiDispatchFault+0x292
bacf6120 8051b1bf 00000000 d7fc0000 00000000 nt!MmAccessFault+0x877
bacf6180 804e33fe d7fc0000 00000000 bacf62e8 nt!MmCheckCachedPageState+0x601
bacf61c8 804e4ec2 8909fed0 bacf6208 00001000 nt!CcMapAndRead+0x94
bacf625c 805692f9 89500ce8 bacf629c 00000010 nt!CcPinFileData+0x242
bacf6304 ba621311 89500ce8 bacf63b8 00000010 nt!CcCopyRead+0x2f3
bacf63e0 ba620fbf 8957b508 89125a40 00000001 Ntfs!NtfsCommonRead+0xcc2
bacf6480 804efeb1 890e8020 89125a40 891bc780 Ntfs!NtfsFsdRead+0x22d
bacf6490 ba6c2459 bacf64cc 804efeb1 895fedd0 nt!IopfCallDriver+0x31
bacf6498 804efeb1 895fedd0 89125a40 89125a40 sr!SrPassThrough+0x31
bacf64a8 ba6d7e67 00000000 895d036c 00000000 nt!IopfCallDriver+0x31
bacf64cc ba6d8af5 bacf64ec 8912b4b0 00000000 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x20b
bacf6504 ba6d8d22 891e9680 89184410 891844c4 fltMgr!FltPerformSynchronousIo+0xb9
bacf6530 b14387df 895d036c 00500ce8 00cf6590 fltMgr!FltReadFile+0xf8
bacf65a8 b1439097 89500ce8 bacf6610 00000000 KSkernel!IsCacheCorrect+0x13f [f:\newgit\kernelsec\driver\kernelsec\kernelsec\misc.c @ 325]
bacf65ec ba6d4fa1 8918446c bacf6610 00000000 KSkernel!KsPostCreateBuffers+0x157 [f:\newgit\kernelsec\driver\kernelsec\kernelsec\kscreatecallback.c @ 90]
bacf6654 ba6d73ea 00184410 00000000 89184410 fltMgr!FltpPerformPostCallbacks+0x1c5
bacf6668 ba6d7817 89184410 894ac008 bacf66a8 fltMgr!FltpProcessIoCompletion+0x10
bacf6678 ba6d7ec5 8912b4b0 894ac008 89184410 fltMgr!FltpPassThroughCompletion+0x89
bacf66a8 ba6e4153 bacf66c8 00000000 00000000 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x269
bacf66e4 804efeb1 8912b4b0 894ac198 894ac008 fltMgr!FltpCreate+0x1e3
bacf66f4 80582ec2 891528e8 895610ac bacf688c nt!IopfCallDriver+0x31
bacf67d4 805bed10 89152900 00000000 89561008 nt!IopParseDevice+0xa58
bacf684c 805bb398 00000000 bacf688c 00000240 nt!ObpLookupObjectName+0x53c
bacf68a0 80575e4d 00000000 00000000 00000000 nt!ObOpenObjectByName+0xea
bacf691c 805767c4 bacf6cbc c0000000 bacf7528 nt!IopCreateFile+0x407
bacf6978 80578e8e bacf6cbc c0000000 bacf7528 nt!IoCreateFile+0x8e
bacf69b8 8054160c bacf6cbc c0000000 bacf7528 nt!NtCreateFile+0x30
bacf69b8 80500395 bacf6cbc c0000000 bacf7528 nt!KiFastCallEntry+0xfc
bacf6a5c b1439a0f bacf6cbc c0000000 bacf7528 nt!ZwCreateFile+0x11
bacf7544 b14381ad 895a6d28 00cf7898 895a6d28 KSkernel!RemoveFileProtection+0xff [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksremoveprotection.c @ 66]
bacf7d68 805768ef 8956be00 895a6d28 8056475c KSkernel!removeFileProtectionRoutine+0xbd [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksworkitemroutine.c @ 37]
bacf7d7c 80538757 89499c60 00000000 896cfb30 nt!IopProcessWorkItem+0x13
bacf7dac 805cf794 89499c60 00000000 00000000 nt!ExpWorkerThread+0xef
bacf7ddc 805460ce 80538668 00000001 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

STACK_COMMAND: .tss 0x28 ; kb

FOLLOWUP_IP:
KSkernel!KsPreReadBuffers+39c [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksreadcallback.c @ 241]
b143693c 83c404 add esp,4

FAULTING_SOURCE_CODE:
237: p2pCtx->encryptedFile = TRUE;
238:
239: #ifdef DBG_READ
240: #ifndef DBG_LOGFILE_OUTPUT

241: DbgPrint( “READ Operation\n” );
242: #else
243: KsWriteLogFile( L"READ " );
244: KsWriteLogFileWithUnicodeString(&fileFullName);
245: KsWriteLogFile( L"\n" );
246: #endif

SYMBOL_STACK_INDEX: 8

SYMBOL_NAME: KSkernel!KsPreReadBuffers+39c

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: KSkernel

IMAGE_NAME: KSkernel.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 5408209c

FAILURE_BUCKET_ID: 0x7f_8_KSkernel!KsPreReadBuffers+39c

BUCKET_ID: 0x7f_8_KSkernel!KsPreReadBuffers+39c

Followup: MachineOwner

Besides, I found that if I delete the DbgPrint function my filter will run quite well.
I need some advice about this problem, any help will be appreciated!

> UNEXPECTED_KERNEL_MODE_TRAP (7f)

Arg1: 00000008, EXCEPTION_DOUBLE_FAULT

This is usually a kernel stack overflow.


Maxim S. Shatskih
Microsoft MVP on File System And Storage
xxxxx@storagecraft.com
http://www.storagecraft.com

Thanks for your help!
So, is there any way to fix this problem?

True. What makes this confusing is that the debugger claims it is a “pop” instruction causing the crash. What it looks like, however, is that the DbgPrint is triggering a breakpoint and it is the exception handler that runs out of stack space:

bacf503c 804ff1d8 bacf546c 00000000 bacf5114 nt!KeContextFromKframes+0x10

0xbacf503c is 60 bytes from the end of the stack.

Usually I use the “kf” command in a situation like this to look for overly large stack frames. Since that information is not provided by the OP I did quick visual check and see a couple of large stack frames:

bacf6a5c b1439a0f bacf6cbc c0000000 bacf7528 nt!ZwCreateFile+0x11
bacf7544 b14381ad 895a6d28 00cf7898 895a6d28 KSkernel!RemoveFileProtection+0xff [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksremoveprotection.c @ 66]
bacf7d68 805768ef 8956be00 895a6d28 8056475c KSkernel!removeFileProtectionRoutine+0xbd [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksworkitemroutine.c @ 37]

These two frames account for 4,876 bytes - that’s more than 1/3 of the entire kernel stack.

There’s one other rather large stack:

bacf5780 b143693c b14514c0 0b8b7f32 891e97dc nt!DbgPrint+0x1a
bacf5f34 ba6d5944 8958f61c bacf5f54 bacf5f84 KSkernel!KsPreReadBuffers+0x39c [f:\newgit\kernelsec\driver\kernelsec\kernelsec\ksreadcallback.c @ 241]

This is an additional 1,972 bytes. There’s a small frame as well for this driver, but that wouldn’t concern me generally.

So this one driver is consuming more than 6,848 bytes of the 12,288 bytes in the stack - more than 50%.

Were I trying to fix this, I’d make sure I minimized stack utilization. If using the WDK 7.1, there is a switch (“/stackhogthreshold”) that can be used with PREFAST to find such issues. See http://msdn.microsoft.com/en-us/library/aa449785.aspx - and I’d suggest using a very conservative value here: 128 is generally what I aim for.

If you are using the WDK 8.1, use the static code analysis tools (we do that as a matter of course at OSR and even go so far as to enable “all rules”). There is a switch for stack usage - “/analyzestackusage” and you should set the threshold value for that as well (again, I’d suggest 128). http://msdn.microsoft.com/en-CA/library/ms173498.aspx

For situations in which it is not possible to easily fix this (usually re-entrant cases in the file system stack after you’ve done stack minimization) the OS now provides KeExpandKernelStackAndCalloutEx (http://msdn.microsoft.com/en-us/library/windows/hardware/ff552036(v=vs.85).aspx ) for extending the current stack. Note: I *would not* use that in this case as it’s not justified based upon the information that you’ve provided.

Tony
OSR

One way to avoid reentrancy altogether (on this path at least) would be to modify KSkernel!RemoveFileProtection so that it uses FltCreateFile instead of ZwCreateFile. As this is not on the IO path there would be a small challenge in mapping the volume to an FLT_INSTANCE but FltEnumerateInstances and FltGetInstanceInformation will help here.

Thanks Maxim, it’s really a stack overflow, thanks for your help.
Besieds, thanks for Tony and Marks’s advice, my filter used too many local variables, there were even hundred-level bytes arrays.
After making local variables become pointers, my filter now works well.
Now they use heap instead of stack, aha :slight_smile: