support/um/tracingum.cpp

/*++

Copyright (c) Microsoft Corporation

Module Name:

    Tracing.cpp

Abstract:

    This module implements tracing for the driver frameworks

Author:


Revision History:


--*/

#include "FxSupportPch.hpp"
#include "fxldrum.h"

extern "C" {
#if defined(EVENT_TRACING)
#include "TracingUM.tmh"
#endif
}

#include <strsafe.h>
#include <initguid.h>
#include "fxIFR.h"       // shared struct between IFR and debug ext.
#include "fxIFRKm.h"     // kernel mode only IFR definitions


_Must_inspect_result_
NTSTATUS
FxTraceInitialize(
    VOID
    )

/*++

Routine Description:

    This routine initializes the frameworks tracing.

    It must be called early on in the frameworks DriverEntry
    initialization.

Arguments:

    None

Returns:

    NTSTATUS code

--*/
{
    //
    // Initialize the tracing package.
    //
    WPP_INIT_TRACING(NULL, NULL);

    return STATUS_SUCCESS;
}

VOID
TraceUninitialize(
    VOID
    )
/*++

Routine Description:
    This routine uninitializes the frameworks tracing.  It must be called just
    before DriverUnload

Arguments:
    None

Returns:
    None

--*/
{
    WPP_CLEANUP(NULL);
}

_Must_inspect_result_
NTSTATUS
FxWmiQueryTraceInformation(
    __in TRACE_INFORMATION_CLASS /* TraceInformationClass */,
    __out_bcount(TraceInformationLength) PVOID /* TraceInformation */,
    __in ULONG /* TraceInformationLength */,
    __out_opt PULONG /* RequiredLength */,
    __in_opt PVOID /* Buffer */
    )
{
    return STATUS_UNSUCCESSFUL;
}

_Must_inspect_result_
NTSTATUS
FxWmiTraceMessage(
    __in TRACEHANDLE  LoggerHandle,
    __in ULONG        MessageFlags,
    __in LPGUID       MessageGuid,
    __in USHORT       MessageNumber,
         ...
    )
{
    NTSTATUS status = STATUS_SUCCESS;

    va_list va;
    va_start(va, MessageNumber);
    //
    // UMDF is supported only on XP and newer OS so no need to support w2k
    // tracing (which requires using a different tracing api, see kmdf impl)
    //
#pragma prefast(suppress:__WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
    status = TraceMessageVa(LoggerHandle,
                            MessageFlags,
                            MessageGuid,
                            MessageNumber,
                            va);

    va_end(va);

    return status;
}


//-----------------------------------------------------------------------------
// Subcomponents for the In-Flight Recorder follow.
//-----------------------------------------------------------------------------

ULONG
FxIFRGetSize(
    __in PFX_DRIVER_GLOBALS FxDriverGlobals,
    __in PCUNICODE_STRING RegistryPath
    )
/*++

Routine Description:
    Checks to see if the service has overriden the default number of pages that
    are in the IFR.

Arguments:
    RegistryPath - path to the service

Return Value:
    The size of the IFR to create in bytes (not pages!)

  --*/
{
    FxAutoRegKey service, parameters;
    NTSTATUS status;
    ULONG numPages;

    //
    // This is the value used in case of any error while retrieving 'LogPages'
    // from the registry.
    //
    numPages  = FxIFRMinLogPages;

    //
    // External representation of the IFR is the "log", so use tha term when
    // overriding the size via the registry.
    //
    DECLARE_CONST_UNICODE_STRING(parametersPath, L"Parameters\\Wdf");
    DECLARE_CONST_UNICODE_STRING(valueName, L"LogPages");

    //
    // UMDF may not provide this registry path
    //
    if (NULL == RegistryPath) {
        goto defaultValues;
    }

    status = FxRegKey::_OpenKey(NULL,
                                (PCUNICODE_STRING)RegistryPath,
                                &service.m_Key,
                                KEY_READ);
    if (!NT_SUCCESS(status)) {
        goto defaultValues;
    }

    status = FxRegKey::_OpenKey(service.m_Key,
                                (PCUNICODE_STRING)&parametersPath,
                                &parameters.m_Key,
                                KEY_READ);
    if (!NT_SUCCESS(status)) {
        goto defaultValues;
    }

    status = FxRegKey::_QueryULong(parameters.m_Key, &valueName, &numPages);
    if (!NT_SUCCESS(status)) {
        goto defaultValues;
    }

    if (numPages == 0) {
        numPages = FxIFRMinLogPages;
    }

defaultValues:
    //
    // This behavior is different from KMDF. KMDF would allocate Average page count (5)
    // if Verifier is on otherwise 1 page if the request is large.
    // Since for UMDF the memory is coming from WudfRd, which does not know about verifier
    // we will give it max pages here.
    //
    if (numPages > FxIFRMaxLogPages) {
        numPages = FxIFRMaxLogPages;
    }

    return numPages * PAGE_SIZE;
}

VOID
FxIFRStart(
    __in PFX_DRIVER_GLOBALS FxDriverGlobals,
    __in PCUNICODE_STRING RegistryPath,
    __in MdDriverObject DriverObject
    )
/*++

Routine Description:

    This routine initialize the In-Flight Recorder (IFR).

    The default log size is set by WDF_IFR_LOG_SIZE and currently
    is 4096 (one x86 page).
    This routine should be called very early in driver initialization
    to allow the capture of all significant events.

Arguments:

Returns:

--*/
{
    PWDF_IFR_HEADER pHeader;
    ULONG pageCount;
    ULONG sizeCb;
    HRESULT hr;
    IWudfDeviceStack2 *pDeviceStack2;
    PDRIVER_OBJECT_UM umDriverObject;
    PWCHAR serviceName;
    size_t bufferLengthCch;
    ULONG allocatedBufferLengthCb;
    LONG i;

    //
    // Return early if IFR is disabled.
    //
    if (FxLibraryGlobals.IfrDisabled) {
        ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
        return;
    }

    WDFCASSERT(FxIFRRecordSignature == WDF_IFR_RECORD_SIGNATURE);

    if (FxDriverGlobals == NULL || FxDriverGlobals->WdfLogHeader != NULL) {
        return;
    }

    //
    // It is safe to use StringCchLength here as WudfHost makes sure that this
    // RegistryPath is null terminated
    //
    hr = StringCchLength(RegistryPath->Buffer,
                         RegistryPath->MaximumLength/sizeof(WCHAR),
                         &bufferLengthCch);

    if (FAILED(hr)) {
        return;
    }

    //
    // Lets find the last '\' that will mark the begining of the service name
    //
    for (i = (ULONG)bufferLengthCch - 1;
        i >= 0 && RegistryPath->Buffer[i] != '\\';
        i--);

    //
    // We did not find the service name
    //
    if (i < 0) {
        return;
    }

    serviceName = &RegistryPath->Buffer[i+1];

    sizeCb = FxIFRGetSize(FxDriverGlobals, RegistryPath);
    pageCount = sizeCb / PAGE_SIZE;

    //
    // Get the IWudfDeviceStack interface
    //
    umDriverObject = (PDRIVER_OBJECT_UM)DriverObject;

    pDeviceStack2 = (IWudfDeviceStack2 *)umDriverObject->WudfDevStack;

    if(pDeviceStack2 == NULL) {
        return;
    }

    allocatedBufferLengthCb = 0;
    hr = pDeviceStack2->AllocateIfrMemory(serviceName,
                                          pageCount,
                                          FALSE,
                                          TRUE,
                                          (PVOID *)&pHeader,
                                          &allocatedBufferLengthCb);

    if (pHeader == NULL || allocatedBufferLengthCb <= sizeof(WDF_IFR_HEADER)) {
        return;
    }

    //
    // Initialize the header.
    // Base will be where the IFR records are placed.
    // WPP_ThisDir_CTLGUID_FrameworksTraceGuid
    //
    RtlCopyMemory(&pHeader->Guid, (PVOID) &WdfTraceGuid, sizeof(GUID));

    pHeader->Base = (PUCHAR) &pHeader[1];
    pHeader->Size = allocatedBufferLengthCb - sizeof(WDF_IFR_HEADER);

    pHeader->Offset.u.s.Current  = 0;
    pHeader->Offset.u.s.Previous = 0;
    pHeader->SequenceNumberPointer = &(DriverObject->IfrSequenceNumber);

    StringCchCopyA(pHeader->DriverName, WDF_IFR_HEADER_NAME_LEN, FxDriverGlobals->Public.DriverName);

    FxDriverGlobals->WdfLogHeader = pHeader;

    DoTraceLevelMessage(FxDriverGlobals, TRACE_LEVEL_VERBOSE, TRACINGDRIVER,
                        "FxIFR logging started" );

    if (sizeCb > FxIFRMinLogSize) {
        DoTraceLevelMessage(
            FxDriverGlobals, TRACE_LEVEL_INFORMATION, TRACINGDRIVER,
            "FxIFR has been started with a size override:  size 0x%x bytes, "
            "# Pages %d.  An extended IFR size may not be written to a minidump!",
            sizeCb, sizeCb/PAGE_SIZE);
    }

    if (sizeCb != allocatedBufferLengthCb) {
        ASSERTMSG("FxIFR requested buffer size could not be allocated",FALSE);
        DoTraceLevelMessage(
            FxDriverGlobals, TRACE_LEVEL_WARNING, TRACINGDRIVER,
            "FxIFR requested an allocation of size 0x%x bytes, "
            "Allocated memory was of size 0x%x bytes",
            sizeCb, allocatedBufferLengthCb);
    }
}

VOID
FxIFRStop(
    __in PFX_DRIVER_GLOBALS FxDriverGlobals
    )
/*++

Routine Description:

    This routine stops the In-Flight Recorder (IFR).

    For UMDF FxIFRStop is no longer required as WudfRd manages the buffer's lifetime
    The buffer is kept alive till WudfRd unloads to aid in debugging in cases of
    WudfHost crash or in dumps with WudfHost paged out or not captured

Arguments:

Returns:

--*/
{
    UNREFERENCED_PARAMETER(FxDriverGlobals);

    //
    // Uncomment the code below if you add any logic to this function.
    //
    // if (FxLibraryGlobals.IfrDisabled) {
    //     ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
    //     return;
    // }
    //
}

_Must_inspect_result_
NTSTATUS
FxIFR(
    __in PFX_DRIVER_GLOBALS FxDriverGlobals,
    __in UCHAR              MessageLevel,
    __in ULONG              MessageFlags,
    __in LPGUID             MessageGuid,
    __in USHORT             MessageNumber,
         ...
    )
/*++

Routine Description:

    This routine is the main In-Flight Recorder (IFR) routine.

    It captures a WPP message to the IFR log.
    The IFR is always running, e.g. not WPP logger is necessary
    to start logging.

Arguments:

    MessageLevel  - The WPP message level for this event
    MessageFlags  - The WPP message flags for this event (see trace GUID)
    MessageGuid   - The tracewpp generated guid for module emitting this event.
    MessageNumber - The tracewpp generated message number within
                    the emitting module.
    ...           - Variable arguments associates with the emitted message.

Returns:

    NTSTATUS

--*/
{
    size_t            size;
    PWDF_IFR_RECORD   record;

    UNREFERENCED_PARAMETER( MessageLevel );

    //
    // Return early if IFR is disabled.
    //
    if (FxLibraryGlobals.IfrDisabled) {
        ASSERT(FxDriverGlobals->WdfLogHeader == NULL);
        return STATUS_SUCCESS;
    }

    if ( FxDriverGlobals->WdfLogHeader == NULL) {
        return STATUS_UNSUCCESSFUL;
    }


    UNREFERENCED_PARAMETER( MessageFlags );


    //
    // Determine the number bytes to follow header
    //
    size = 0;   // For Count of Bytes

    //
    // Determine how much log space is needed for this
    // trace record's data.
    //
    {
        va_list   ap;
        size_t    argLen;

        va_start(ap, MessageNumber);
#pragma prefast(suppress: __WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
        while ((va_arg(ap, PVOID)) != NULL) {

            argLen = va_arg(ap, size_t);

            if (argLen > 0) {

                if (argLen > FxIFRMaxMessageSize) {
                    goto drop_message;
                }
                size += (USHORT) argLen;
            }
        }

        va_end(ap);

        //
        // NOTE: The final size must be 32-bit (ULONG) aligned.
        //       This is necessary for IA64 to prevent Alignment Faults.
        //
        size += (size % sizeof(ULONG)) ? sizeof(ULONG) - (size % sizeof(ULONG)) : 0;

        if (size > FxIFRMaxMessageSize) {
            goto drop_message;
        }
    }

    size += sizeof(WDF_IFR_RECORD);

    //
    // Allocate log space of the calculated size
    //
    {
        PWDF_IFR_HEADER  header;
        WDF_IFR_OFFSET   offsetRet;
        WDF_IFR_OFFSET   offsetCur;
        WDF_IFR_OFFSET   offsetNew;
        USHORT           usSize = (USHORT) size;  // for a prefast artifact.

        header = (PWDF_IFR_HEADER) FxDriverGlobals->WdfLogHeader;
        ASSERT(header->Size < FxIFRMaxLogSize); // size doesn't include header.
        ASSERT(header->Size >= header->Offset.u.s.Current);
        ASSERT(header->Size >= header->Offset.u.s.Previous);

        offsetRet.u.AsLONG = header->Offset.u.AsLONG;
        offsetNew.u.AsLONG = offsetRet.u.s.Current;

        do {
            offsetCur.u.AsLONG = offsetRet.u.AsLONG;

            if (&header->Base[header->Size] < &header->Base[offsetCur.u.s.Current+size]) {

                offsetNew.u.s.Current  = 0;
                offsetNew.u.s.Previous = offsetRet.u.s.Previous;

                offsetRet.u.AsLONG =
                    InterlockedCompareExchange( &header->Offset.u.AsLONG,
                                                offsetNew.u.AsLONG,
                                                offsetCur.u.AsLONG );

                if (offsetCur.u.AsLONG != offsetRet.u.AsLONG) {
                    continue;
                } else {
                    offsetNew.u.s.Current  = offsetCur.u.s.Current + usSize;
                    offsetNew.u.s.Previous = offsetRet.u.s.Current;
                }
            } else {

                offsetNew.u.s.Current  = offsetCur.u.s.Current + usSize;
                offsetNew.u.s.Previous = offsetCur.u.s.Current;
            }

            offsetRet.u.AsLONG =
                InterlockedCompareExchange( &header->Offset.u.AsLONG,
                                            offsetNew.u.AsLONG,
                                            offsetCur.u.AsLONG );

        } while (offsetCur.u.AsLONG != offsetRet.u.AsLONG);

        record = (PWDF_IFR_RECORD) &header->Base[offsetRet.u.s.Current];

        // RtlZeroMemory( record, sizeof(WDF_IFR_RECORD) );

        //
        // Build record (fill all fields!)
        //
        record->Signature     = FxIFRRecordSignature;
        record->Length        = (USHORT) size;
        record->PrevOffset    = (USHORT) offsetRet.u.s.Previous;
        record->MessageNumber = MessageNumber;
        record->Sequence      = InterlockedIncrement(header->SequenceNumberPointer);
        record->MessageGuid   = *MessageGuid;
    }

    //
    // Move variable part of data into log.
    //
    {
        va_list  ap;
        size_t   argLen;
        PVOID    source;
        PUCHAR   argsData;

        argsData = (UCHAR*) &record[1];

        va_start(ap, MessageNumber);
#pragma prefast(suppress: __WARNING_BUFFER_OVERFLOW, "Recommneded by EndClean");
        while ((source = va_arg(ap, PVOID)) != NULL) {

            argLen = va_arg(ap, size_t);

            if (argLen > 0) {

                RtlCopyMemory( argsData, source, argLen );
                argsData += argLen;
            }
        }

        va_end(ap);
    }

    return STATUS_SUCCESS;

    {
        //
        // Increment sequence number to indicate dropped message
        //
drop_message:
        PWDF_IFR_HEADER  header;
        header = (PWDF_IFR_HEADER) FxDriverGlobals->WdfLogHeader;
        InterlockedIncrement(header->SequenceNumberPointer);
        return STATUS_UNSUCCESSFUL;
    }
}