Re: [ros-dev] [ros-diffs] [dgorbachev] 43331: Fix logging to a file. In spite of limitations, it remains the only way to obtain desired logs for some people.

[Alex Ionescu]

This code has multiple synchronization issues, such as spinning on a
test-for-spin-lock, which is non-atomic... might as well get rid of
the spinlock.

Also, you should probably be using a worker thread instead of
consuming system resources for a dedicated thread and mucking with
priorities.

Best regards,
Alex Ionescu



On Wed, Oct 7, 2009 at 3:57 PM,  <dgorbachev(a)svn.reactos.org> wrote:
>   Author: dgorbachev
>  Date: Wed Oct  7 21:57:40 2009
>  New Revision: 43331
>
>  URL: http://svn.reactos.org/svn/reactos?rev=43331&view=rev
>  Log:
>  Fix logging to a file.
>
>  In spite of limitations, it remains the only way to obtain desired logs for some people.
>
>  Modified:
>     trunk/reactos/ntoskrnl/kd/kdio.c
>
>  Modified: trunk/reactos/ntoskrnl/kd/kdio.c
>  URL:
> http://svn.reactos.org/svn/reactos/trunk/reactos/ntoskrnl/kd/kdio.c?rev=433…
>  ==============================================================================
>  --- trunk/reactos/ntoskrnl/kd/kdio.c [iso-8859-1] (original)
>  +++ trunk/reactos/ntoskrnl/kd/kdio.c [iso-8859-1] Wed Oct  7 21:57:40 2009
>  @@ -14,16 +14,17 @@
>
>   /* GLOBALS *******************************************************************/
>
>  -#define BufferSize 32*1024
>  -
>  -HANDLE KdbLogFileHandle;
>  -BOOLEAN KdpLogInitialized;
>  -CHAR DebugBuffer[BufferSize];
>  -ULONG CurrentPosition;
>  -WORK_QUEUE_ITEM KdpDebugLogQueue;
>  +#define KdpBufferSize  (1024 * 512)
>  +BOOLEAN KdpLoggingEnabled = FALSE;
>  +PCHAR KdpDebugBuffer = NULL;
>  +volatile ULONG KdpCurrentPosition = 0;
>  +volatile ULONG KdpFreeBytes = 0;
>  +KSPIN_LOCK KdpDebugLogSpinLock;
>  +KEVENT KdpLoggerThreadEvent;
>  +HANDLE KdpLogFileHandle;
>  +
>   KSPIN_LOCK KdpSerialSpinLock;
>  -BOOLEAN ItemQueued;
>  -KD_PORT_INFORMATION SerialPortInfo = {DEFAULT_DEBUG_PORT, DEFAULT_DEBUG_BAUD_RATE, 0};
>  +KD_PORT_INFORMATION SerialPortInfo = { DEFAULT_DEBUG_PORT, DEFAULT_DEBUG_BAUD_RATE, 0
> };
>
>   /* Current Port in use. FIXME: Do we support more then one? */
>   ULONG KdpPort;
>  @@ -32,56 +33,103 @@
>
>   VOID
>   NTAPI
>  -KdpPrintToLogInternal(PVOID Context)
>  -{
>  +KdpLoggerThread(PVOID Context)
>  +{
>  +    ULONG beg, end, num;
>      IO_STATUS_BLOCK Iosb;
>
>  -    /* Write to the Debug Log */
>  -    NtWriteFile(KdbLogFileHandle,
>  -                NULL,
>  -                NULL,
>  -                NULL,
>  -                &Iosb,
>  -                DebugBuffer,
>  -                CurrentPosition,
>  -                NULL,
>  -                NULL);
>  -
>  -    /* Clear the Current Position */
>  -    CurrentPosition = 0;
>  -
>  -    /* A new item can be queued now */
>  -    ItemQueued = FALSE;
>  -}
>  -
>  -VOID
>  -NTAPI
>  -KdpPrintToLog(PCH String,
>  -              ULONG StringLength)
>  -{
>  -    /* Don't overflow */
>  -    if ((CurrentPosition + StringLength) > BufferSize) return;
>  -
>  -    /* Add the string to the buffer */
>  -    RtlCopyMemory(&DebugBuffer[CurrentPosition], String, StringLength);
>  -
>  -    /* Update the Current Position */
>  -    CurrentPosition += StringLength;
>  -
>  -    /* Make sure we are initialized and can queue */
>  -    if (!KdpLogInitialized || (ItemQueued)) return;
>  -
>  -    /*
>  -     * Queue the work item
>  -     * Note that we don't want to queue if we are > DISPATCH_LEVEL...
>  -     * The message is in the buffer and will simply be taken care of at
>  -     * the next time we are at <= DISPATCH, so it won't be lost.
>  -     */
>  -    if (KeGetCurrentIrql() <= DISPATCH_LEVEL)
>  -    {
>  -        ExQueueWorkItem(&KdpDebugLogQueue, HyperCriticalWorkQueue);
>  -        ItemQueued = TRUE;
>  -    }
>  +    KdpLoggingEnabled = TRUE;
>  +
>  +    while (TRUE)
>  +    {
>  +        KeWaitForSingleObject(&KdpLoggerThreadEvent, 0, KernelMode, FALSE, NULL);
>  +
>  +        /* Bug */
>  +        end = KdpCurrentPosition;
>  +        num = KdpFreeBytes;
>  +        beg = (end + num) % KdpBufferSize;
>  +        num = KdpBufferSize - num;
>  +
>  +        /* Nothing to do? */
>  +        if (num == 0)
>  +            continue;
>  +
>  +        if (end > beg)
>  +        {
>  +            NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb,
>  +                        KdpDebugBuffer + beg, num, NULL, NULL);
>  +        }
>  +        else
>  +        {
>  +            NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb,
>  +                        KdpDebugBuffer + beg, KdpBufferSize - beg, NULL, NULL);
>  +
>  +            NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb,
>  +                        KdpDebugBuffer, end, NULL, NULL);
>  +        }
>  +
>  +        InterlockedExchangeAddUL(&KdpFreeBytes, num);
>  +    }
>  +}
>  +
>  +VOID
>  +NTAPI
>  +KdpPrintToLogFile(PCH String,
>  +                  ULONG StringLength)
>  +{
>  +    ULONG beg, end, num;
>  +    KIRQL OldIrql;
>  +
>  +    if (KdpDebugBuffer == NULL) return;
>  +
>  +    /* Acquire the printing spinlock without waiting at raised IRQL */
>  +    while (TRUE)
>  +    {
>  +        /* Wait when the spinlock becomes available */
>  +        while (!KeTestSpinLock(&KdpDebugLogSpinLock));
>  +
>  +        /* Spinlock was free, raise IRQL */
>  +        KeRaiseIrql(HIGH_LEVEL, &OldIrql);
>  +
>  +        /* Try to get the spinlock */
>  +        if (KeTryToAcquireSpinLockAtDpcLevel(&KdpDebugLogSpinLock))
>  +            break;
>  +
>  +        /* Someone else got the spinlock, lower IRQL back */
>  +        KeLowerIrql(OldIrql);
>  +    }
>  +
>  +    beg = KdpCurrentPosition;
>  +    num = KdpFreeBytes;
>  +    if (StringLength < num)
>  +        num = StringLength;
>  +
>  +    if (num != 0)
>  +    {
>  +        end = (beg + num) % KdpBufferSize;
>  +        KdpCurrentPosition = end;
>  +        KdpFreeBytes -= num;
>  +
>  +        if (end > beg)
>  +        {
>  +            RtlCopyMemory(KdpDebugBuffer + beg, String, num);
>  +        }
>  +        else
>  +        {
>  +            RtlCopyMemory(KdpDebugBuffer + beg, String, KdpBufferSize - beg);
>  +            RtlCopyMemory(KdpDebugBuffer, String + KdpBufferSize - beg, end);
>  +        }
>  +    }
>  +
>  +    /* Release spinlock */
>  +    KiReleaseSpinLock(&KdpDebugLogSpinLock);
>  +
>  +    /* Lower IRQL */
>  +    KeLowerIrql(OldIrql);
>  +
>  +    /* Signal the logger thread */
>  +    if (OldIrql <= DISPATCH_LEVEL && KdpLoggingEnabled)
>  +        KeSetEvent(&KdpLoggerThreadEvent, 0, FALSE);
>   }
>
>   VOID
>  @@ -90,9 +138,11 @@
>                  ULONG BootPhase)
>   {
>      NTSTATUS Status;
>  +    UNICODE_STRING FileName;
>      OBJECT_ATTRIBUTES ObjectAttributes;
>  -    UNICODE_STRING FileName;
>      IO_STATUS_BLOCK Iosb;
>  +    HANDLE ThreadHandle;
>  +    KPRIORITY Priority;
>
>      if (!KdpDebugMode.File) return;
>
>  @@ -102,10 +152,20 @@
>
>          /* Write out the functions that we support for now */
>          DispatchTable->KdpInitRoutine = KdpInitDebugLog;
>  -        DispatchTable->KdpPrintRoutine = KdpPrintToLog;
>  +        DispatchTable->KdpPrintRoutine = KdpPrintToLogFile;
>
>          /* Register as a Provider */
>          InsertTailList(&KdProviders, &DispatchTable->KdProvidersList);
>  +
>  +    }
>  +    else if (BootPhase == 1)
>  +    {
>  +        /* Allocate a buffer for debug log */
>  +        KdpDebugBuffer = ExAllocatePool(NonPagedPool, KdpBufferSize);
>  +        KdpFreeBytes = KdpBufferSize;
>  +
>  +        /* Initialize spinlock */
>  +        KeInitializeSpinLock(&KdpDebugLogSpinLock);
>
>          /* Display separator + ReactOS version at start of the debug log */
>         
> DPRINT1("---------------------------------------------------------------\n");
>  @@ -117,7 +177,7 @@
>      }
>      else if (BootPhase == 3)
>      {
>  -        /* Setup the Log Name */
>  +        /* Setup the log name */
>          RtlInitUnicodeString(&FileName, L"\\SystemRoot\\debug.log");
>          InitializeObjectAttributes(&ObjectAttributes,
>                                     &FileName,
>  @@ -125,9 +185,9 @@
>                                     NULL,
>                                     NULL);
>
>  -        /* Create the Log File */
>  -        Status = NtCreateFile(&KdbLogFileHandle,
>  -                              FILE_ALL_ACCESS,
>  +        /* Create the log file */
>  +        Status = NtCreateFile(&KdpLogFileHandle,
>  +                              FILE_APPEND_DATA | SYNCHRONIZE,
>                                &ObjectAttributes,
>                                &Iosb,
>                                NULL,
>  @@ -138,9 +198,26 @@
>                                NULL,
>                                0);
>
>  -        /* Allow it to be used */
>  -        ExInitializeWorkItem(&KdpDebugLogQueue, &KdpPrintToLogInternal, NULL);
>  -        KdpLogInitialized = TRUE;
>  +        if (!NT_SUCCESS(Status)) return;
>  +
>  +        KeInitializeEvent(&KdpLoggerThreadEvent, SynchronizationEvent, TRUE);
>  +
>  +        /* Create the logger thread */
>  +        Status = PsCreateSystemThread(&ThreadHandle,
>  +                                      THREAD_ALL_ACCESS,
>  +                                      NULL,
>  +                                      NULL,
>  +                                      NULL,
>  +                                      KdpLoggerThread,
>  +                                      NULL);
>  +
>  +        if (!NT_SUCCESS(Status)) return;
>  +
>  +        Priority = 7;
>  +        NtSetInformationThread(ThreadHandle,
>  +                               ThreadPriority,
>  +                               &Priority,
>  +                               sizeof(Priority));
>      }
>   }
>
>  @@ -160,7 +237,7 @@
>          /* Wait when the spinlock becomes available */
>          while (!KeTestSpinLock(&KdpSerialSpinLock));
>
>  -        /* Spinlock was free, raise irql */
>  +        /* Spinlock was free, raise IRQL */
>          KeRaiseIrql(HIGH_LEVEL, &OldIrql);
>
>          /* Try to get the spinlock */
>
>
>