[ros-diffs] [reactos] 05/05: [NTOS:KD64] Implement KdLogDbgPrint() for the WinDbg !dbgprint command.

[Hermès Bélusca-Maïto]

https://git.reactos.org/?p=reactos.git;a=commitdiff;h=ffb05406e6f4a408df857…

commit ffb05406e6f4a408df8577c4b3472f0a0972d77e
Author:     Hermès Bélusca-Maïto <hermes.belusca-maito(a)reactos.org>
AuthorDate: Wed Nov 23 23:24:59 2022 +0100
Commit:     Hermès Bélusca-Maïto <hermes.belusca-maito(a)reactos.org>
CommitDate: Thu Nov 24 01:18:18 2022 +0100

    [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-…
    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 .)
---
 ntoskrnl/include/internal/kd64.h | 13 ++++++
 ntoskrnl/kd64/kddata.c           |  1 +
 ntoskrnl/kd64/kdprint.c          | 91 +++++++++++++++++++++++++++++++++++++++-
 3 files changed, 103 insertions(+), 2 deletions(-)

diff --git a/ntoskrnl/include/internal/kd64.h b/ntoskrnl/include/internal/kd64.h
index d12d10fde1e..9c8670ab557 100644
--- a/ntoskrnl/include/internal/kd64.h
+++ b/ntoskrnl/include/internal/kd64.h
@@ -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;
diff --git a/ntoskrnl/kd64/kddata.c b/ntoskrnl/kd64/kddata.c
index 6e99c18d374..7111d287d0a 100644
--- a/ntoskrnl/kd64/kddata.c
+++ b/ntoskrnl/kd64/kddata.c
@@ -136,6 +136,7 @@ ULONG KdPrintRolloverCount;
 PCHAR KdPrintCircularBuffer = KdPrintDefaultCircularBuffer;
 ULONG KdPrintBufferSize = sizeof(KdPrintDefaultCircularBuffer);
 ULONG KdPrintBufferChanges = 0;
+KSPIN_LOCK KdpPrintSpinLock;
 
 //
 // Debug Filter Masks
diff --git a/ntoskrnl/kd64/kdprint.c b/ntoskrnl/kd64/kdprint.c
index 83e2e2f3840..c6089b534b4 100644
--- a/ntoskrnl/kd64/kdprint.c
+++ b/ntoskrnl/kd64/kdprint.c
@@ -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)