vDbgPrintEx("%.*s",n,s) triggers a bugcheck

NTDEV
1

Hello,

I’m hitting a breakpoint in vDbgPrintEx, and I’ve no idea what is causing it.

kd> !analyze -v hang
Connected to Windows 10 10586 x64 target at (Sun Apr 10 12:09:15.046 2016 (UTC - 7:00)), ptr64 TRUE
Loading Kernel Symbols
…
…
…
Loading User Symbols
…
Loading unloaded module list
…
Loading Wow64 Symbols
…
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

Unknown bugcheck code (0)
Unknown bugcheck description
Arguments:
Arg1: 0000000000000000
Arg2: 0000000000000000
Arg3: 0000000000000000
Arg4: 0000000000000000

Debugging Details:

ignore module at 51e30000 in user-mode
ignore module at 51e30000 in user-mode
Debugger Dbgportaldb Connection::Open failed 80004005
Database Dbgportaldb not connected

DUMP_CLASS: 1

DUMP_QUALIFIER: 0

BUILD_VERSION_STRING: 10586.0.amd64fre.th2_release.151029-1700

DUMP_TYPE: 0

BUGCHECK_P1: 0

BUGCHECK_P2: 0

BUGCHECK_P3: 0

BUGCHECK_P4: 0

PROCESS_NAME: print.exe

FAULTING_IP:
nt!DbgBreakPointWithStatus+0 [d:\th\minkernel\ntos\rtl\amd64\debugstb.asm @ 124]
fffff802`fa3c56d0 cc int 3

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

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

EXCEPTION_CODE_STR: 80000003

EXCEPTION_PARAMETER1: 0000000000000000

CPU_COUNT: 8

CPU_MHZ: 95a

CPU_VENDOR: GenuineIntel

CPU_FAMILY: 6

CPU_MODEL: 2d

CPU_STEPPING: 7

CPU_MICROCODE: 6,2d,7,0 (F,M,S,R) SIG: 710’00000000 (cache) 710’00000000 (init)

DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT

BUGCHECK_STR: 0x0

CURRENT_IRQL: e

ANALYSIS_SESSION_HOST: GSSFH202

ANALYSIS_SESSION_TIME: 04-10-2016 12:09:17.0405

ANALYSIS_VERSION: 10.0.11063.818 amd64fre

STACK_TEXT:
ffffd00020bf8348 fffff802fa407c6c : ffffffffffffffff 0000000000000080 fffff801f54bbd2e ffffd00020bf8e1c : nt!DbgBreakPointWithStatus [d:\th\minkernel\ntos\rtl\amd64\debugstb.asm @ 124]
ffffd00020bf8350 fffff802fa354d8e : ffffd00020bf9fd1 ffffe001da7b8128 ffffd00020bf8e1c 0000000000000000 : nt!vDbgPrintExWithPrefixInternal+0xb2ed8 [d:\th\minkernel\ntos\rtl\debug.c @ 534]
ffffd00020bf8450 fffff801f4758b34 : fffff801f556b0e0 ffffd00020bf85d8 fffff801f5aa7850 ffffd00000000100 : nt!vDbgPrintEx+0x22 [d:\th\minkernel\ntos\rtl\debug.c @ 242]
ffffd00020bf8490 fffff801f4758a52 : fffff80100000004 fffff801f53e4620 0000000000000100 fffff801f5aa7850 : mydriver!myprintf_2+0x34 [c:\mydriver\myprintf_2.h @ 91]
ffffd00020bf84d0 fffff801f475894d : fffff801f556a5b0 ffffe00100000a65 fffff801f556b0c0 0000000000000004 : mydriver!myprintf+0xf2 [c:\mydriver\myprintf.c @ 313]

Apparently, " One or more arguments are invalid". But, due to legacy reasons, ALL my DbgPrint() calls look the same, like this:

// Have a custom output buffer
char out_string[512];

// Does a vsnprintf into a buffer then passes that as “%.*s” to vDbgPrintEx
void myprintf(const char *fmt, …)
{
va_list args;
va_start(args, fmt);

spinlock_acquire(); // also raises IRQL to (PASSIVE_LEVEL-1)
vsnprintf(out_string, 512, fmt, args);
myprintf_2(“%.*s”, 512, out_string);
spinlock_release(); // Restores the IRQL

va_end(args);
}
// Wrapper around vDbgPrintEx.
void myprintf_2(const char *fmt, …)
{
va_list args;
va_start(args, fmt);
vDbgPrintEx(0,0,fmt,args);
va_end(args);
}

This works as intended, except there is one print that triggers the above breakpoint:

myprintf(“%s: %s[%c] = 0x%08x”, FUNCTION, (char*)str, (char)ch, (uint32_t)status);

I’ve verified that the string passed from myprintf() to myprintf_2() is valid (properly terminated), and that the two strings are valid, narrow strings. I don’t use unicode anywhere. Total size is around 100 bytes. There doesn’t seem to be anything special about that one print. It is called from DISPATCH_LEVEL, (raised to DIRQL by spinlock), but many others are as well.

Is there any other reason for the breakpoint to be triggered? I didn’t specify any regkeys or debugger filters.

Thanks!
Milo

2

You can’t use it at DISPATCH_LEVEL. Those printf like functions may access UNICODE tables that are located at PAGED memory.

3

I thought that is only if you use the format specifiers that require those. Per MSDN:
“DbgPrint and DbgPrintEx can be called at IRQL<=DIRQL. However, Unicode format codes (%wc and %ws) can be used only at IRQL = PASSIVE_LEVEL. Also, because the debugger uses interprocess interrupts (IPIs) to communicate with other processors, calling DbgPrint at IRQL>DIRQL can cause deadlocks.”
https://msdn.microsoft.com/en-us/library/windows/hardware/ff543634(v=vs.85).aspx

I don’t deal with unicode characters anywhere. And I have other prints that use FUNCTION and such at DIRQL without any issues.

4

@ D A:

Only UNICODE format options require PASSIVE_LEVEL. Non-unicode formatting can be used on <=DIRQL.

@mtijavic:

You may be getting a debug ASSERT because the resulting string may be too long.

5

No, not because of that. Because you are calling vsnprintf() at raised IRQL. You did it before call to before DbgPrint().

6

>No, not because of that. Because you are calling vsnprintf() at raised IRQL. You

did it before call to before DbgPrint().

Make that my_vsnprintf() :). The implementation for that is completely in my driver. It doesn’t access any paged data, and doesn’t even know about unicode.

Besides, vsnprintf executes properly (since it’s not in the stack trace). All DbgPrint is seeing is this:

char str[512] = “function_name: somestring[c]=0x12341234\n”;
DbgPrintEx(0,0,“%.*s”, 512, str);

I don’t think it’s IRQL related. The bugcheck code would have been different if that was it.

@Alex Grig:

You may be getting a debug ASSERT because the resulting string may be too long.

Thought of that, but I only send ~80 bytes. Also, sending over 512 just results in the extra stuff not printed, there was no assert (I’m not running a checked Windows build).

Thanks for the suggestions, though!

7

xxxxx@gmail.com wrote:

Make that my_vsnprintf() :). The implementation for that is completely in my driver. It doesn’t access any paged data, and doesn’t even know about unicode.

Besides, vsnprintf executes properly (since it’s not in the stack trace). All DbgPrint is seeing is this:

char str[512] = “function_name: somestring[c]=0x12341234\n”;
DbgPrintEx(0,0,“%.*s”, 512, str);

Why the %.*s in the first place? In your circumstance, it serves no
purpose. Your call to vsnprintf already guarantees that the resulting
string will be no longer than 512, but even if it were, who cares?

I don’t think it’s IRQL related. The bugcheck code would have been different if that was it.

Agreed. vDbgPrintEx calls vDbgPrintExWithPrefixInternal which calls
RtlStringCbVPrintfA, and it looks like the assert you’re seeing is
because that routine returned an error.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

8

How about RtlStringCbVPrintf?
MSDN: IRQL PASSIVE_LEVEL

9

xxxxx@gmail.com wrote:

How about RtlStringCbVPrintf?
MSDN: IRQL PASSIVE_LEVEL

It matters for RtlStringCbVPrintfW. I’m not convinced it does for
RtlStringCbVPrintfA. And, as he said, that would be a different bug code.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.