[NTOS:KD64] Implement KdLogDbgPrint() for the WinDbg !dbgprint command.

See this command's documentation:
https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/-dbgprint
and the section "DbgPrint buffer and the debugger"
https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/reading-and-filtering-debugging-messages#dbgprint-buffer-and-the-debugger
for more details.

- Loosely implement the function, based on our existing circular printout
  buffers in kdio.c.
- Enable its usage in the KdpPrint() and KdpPrompt() functions.

Notice that this function will *only* capture the strings being sent **to**
the debugger, and not the strings the debugger itself produce. (This means
that we cannot use the KdPrintCircularBuffer as a replacement for our
KDBG dmesg one, for example...)

How to test:
Run ReactOS under WinDbg, and use the !dbgprint command to view the
buffer. You can also use the Memory Window, place yourself at the
address pointed by KdPrintCircularBuffer and KdPrintWritePointer, and
read its contents.

What you should observe:
Prior notice: The circular buffer in debug builds of ReactOS and Windows
is 0x8000 bytes large. In release builds, its size is down to 0x1000.
1- When you start e.g. the 2nd-stage GUI installation of ReactOS, going
   past the initial "devices installation" and letting it stabilize on
   the Welcome page, break into WinDbg and run the !dbgprint command. You
   should notice that the end of its output is weirdly truncated, compared
   to what has been actually emitted to the debug output. Comparing this
   with the actual contents of the circular buffer (via Memory Window),
   shows that the buffer contents is actually correct.
2- Copy all the text that has been output by the !dbgprint command and
   paste it in an editor; count the number of all characters appearing +
   newlines (only CR or LF), and observe that this number is "mysteriously"
   equal to 16384 == 0x4000.
3- Continue running ReactOS installation for a little while, breaking back
   back into WinDbg and looking at !dbgprint again. Its output seems to be
   still stopping at the same place as before (but the actual buffer memory
   contents shows otherwise). Continue running ROS installation, and break
   into the debugger when ROS is about to restart. You should now observe
   that the dbgprint buffer rolled over:
     dd nt!KdPrintRolloverCount shows 1.
   Carefully analysing the output of !dbgprint, however, you will notice
   that it looks a bit garbage-y: the first part of the output is actually
   truncated after 16384 characters, then you get a second part of the
   buffer showing what ReactOS was printing while shutting down. Then
   you get again what was shown at the top of the !dbgprint output.
   (Of course, comparing with the actual contents of the circular buffer
   in memory shows that its contents are fine...)

The reason of these strange observations, is because there is an intrinsic
bug in the !dbgprint command implementation (in kdexts.dll). Essentially,
it displays the contents of the circular buffer in two single dprintf()
calls: one for the "older" (bottom) part of the buffer:
  [WritePointer, EndOfBuffer]
and one for the "newer" (upper) part of the buffer:
  [CircularBuffer, WritePointer[ .
The first aspect of the bug (causing observation 3), is that those two
parts are not necessarily NULL-terminated strings (especially after
rollover), so for example, displaying the upper part of the buffer, will
potentially also display part of the buffer's bottom part.
The second aspect of the bug (explaining observations 1 and 2), is due
to the implementation of the dprintf() function (callback in dbgenv.dll).
There, it uses a fixed-sized buffer of size 0x4000 == 16384 characters.
Since the output of the circular buffer is not done by little chunks,
but by the two large parts, if any of those are larger than 0x4000 they
get truncated on display.
(This last observation is confirmed in a completely different context by
https://community.osr.com/discussion/112439/dprintf-s-max-string-length .)
This commit is contained in:
Hermès Bélusca-Maïto 2022-11-23 23:24:59 +01:00
parent 36335d9cee
commit ffb05406e6
No known key found for this signature in database
GPG key ID: 3B2539C65E7B93D0
3 changed files with 103 additions and 2 deletions

View file

@ -523,6 +523,11 @@ NTAPI
KdpPrintString(
_In_ PSTRING Output);
VOID
NTAPI
KdLogDbgPrint(
_In_ PSTRING String);
//
// Global KD Data
//
@ -558,7 +563,15 @@ extern LARGE_INTEGER KdTimerStop, KdTimerStart, KdTimerDifference;
extern CHAR KdpMessageBuffer[KDP_MSG_BUFFER_SIZE];
extern CHAR KdpPathBuffer[KDP_MSG_BUFFER_SIZE];
extern CHAR KdPrintDefaultCircularBuffer[KD_DEFAULT_LOG_BUFFER_SIZE];
extern PCHAR KdPrintWritePointer;
extern ULONG KdPrintRolloverCount;
extern PCHAR KdPrintCircularBuffer;
extern ULONG KdPrintBufferSize;
extern ULONG KdPrintBufferChanges;
extern KSPIN_LOCK KdpPrintSpinLock;
extern BREAKPOINT_ENTRY KdpBreakpointTable[KD_BREAKPOINT_MAX];
extern KD_BREAKPOINT_TYPE KdpBreakpointInstruction;
extern BOOLEAN KdpOweBreakpoint;

View file

@ -136,6 +136,7 @@ ULONG KdPrintRolloverCount;
PCHAR KdPrintCircularBuffer = KdPrintDefaultCircularBuffer;
ULONG KdPrintBufferSize = sizeof(KdPrintDefaultCircularBuffer);
ULONG KdPrintBufferChanges = 0;
KSPIN_LOCK KdpPrintSpinLock;
//
// Debug Filter Masks

View file

@ -17,6 +17,93 @@
/* FUNCTIONS *****************************************************************/
KIRQL
NTAPI
KdpAcquireLock(
_In_ PKSPIN_LOCK SpinLock)
{
KIRQL OldIrql;
/* Acquire the spinlock without waiting at raised IRQL */
while (TRUE)
{
/* Loop until the spinlock becomes available */
while (!KeTestSpinLock(SpinLock));
/* Spinlock is free, raise IRQL to high level */
KeRaiseIrql(HIGH_LEVEL, &OldIrql);
/* Try to get the spinlock */
if (KeTryToAcquireSpinLockAtDpcLevel(SpinLock))
break;
/* Someone else got the spinlock, lower IRQL back */
KeLowerIrql(OldIrql);
}
return OldIrql;
}
VOID
NTAPI
KdpReleaseLock(
_In_ PKSPIN_LOCK SpinLock,
_In_ KIRQL OldIrql)
{
/* Release the spinlock */
KiReleaseSpinLock(SpinLock);
// KeReleaseSpinLockFromDpcLevel(SpinLock);
/* Restore the old IRQL */
KeLowerIrql(OldIrql);
}
VOID
NTAPI
KdLogDbgPrint(
_In_ PSTRING String)
{
SIZE_T Length, Remaining;
KIRQL OldIrql;
/* If the string is empty, bail out */
if (!String->Buffer || (String->Length == 0))
return;
/* If no log buffer available, bail out */
if (!KdPrintCircularBuffer /*|| (KdPrintBufferSize == 0)*/)
return;
/* Acquire the log spinlock without waiting at raised IRQL */
OldIrql = KdpAcquireLock(&KdpPrintSpinLock);
Length = min(String->Length, KdPrintBufferSize);
Remaining = KdPrintCircularBuffer + KdPrintBufferSize - KdPrintWritePointer;
if (Length < Remaining)
{
KdpMoveMemory(KdPrintWritePointer, String->Buffer, Length);
KdPrintWritePointer += Length;
}
else
{
KdpMoveMemory(KdPrintWritePointer, String->Buffer, Remaining);
Length -= Remaining;
if (Length > 0)
KdpMoveMemory(KdPrintCircularBuffer, String->Buffer + Remaining, Length);
KdPrintWritePointer = KdPrintCircularBuffer + Length;
/* Got a rollover, update count (handle wrapping, must always be >= 1) */
++KdPrintRolloverCount;
if (KdPrintRolloverCount == 0)
++KdPrintRolloverCount;
}
/* Release the spinlock */
KdpReleaseLock(&KdpPrintSpinLock, OldIrql);
}
BOOLEAN
NTAPI
KdpPrintString(
@ -270,7 +357,7 @@ KdpPrompt(
ResponseBuffer.MaximumLength = MaximumResponseLength;
/* Log the print */
//KdLogDbgPrint(&PromptBuffer);
KdLogDbgPrint(&PromptBuffer);
/* Enter the debugger */
Enable = KdEnterDebugger(TrapFrame, ExceptionFrame);
@ -405,7 +492,7 @@ KdpPrint(
OutputString.Length = OutputString.MaximumLength = Length;
/* Log the print */
//KdLogDbgPrint(&OutputString);
KdLogDbgPrint(&OutputString);
/* Check for a debugger */
if (KdDebuggerNotPresent)