Generating trace information in native modules

IIS7 has really nice tracing capabilities which are available to all module developers. If you want to make it easy for you and your customers to debug problems in your modules, you should definitely be using them. You can use IHttpTraceContext::RaiseTraceEvent or IHttpTraceContext::QuickTrace in your IIS7 native modules to generate trace information. Once you have your module generating trace information, you or your customers can set trace rules to collect trace data for particular requests.

Simplest way to generate trace events is by using IHttpTraceContext::QuickTrace API. You can get trace context for a particular request using IHttpContext::GetTraceContext and then dump two strings and a HRESULT with a particular verbosity (or trace level) using QuickTrace. Trace level for QuickTrace API can be from 1-7 but you will probably never use values 6, 7 which are for MODULE_START and MODULE_END events. Below is sample code calling QuickTrace.

#include <httptrace.h>

#define TRACE_CRITICAL_ERROR  1
#define TRACE_ERROR           2
#define TRACE_WARNING         3
#define TRACE_INFO            4
#define TRACE_VERBOSE         5

IHttpContext *     pContext…
IHttpTraceContext* pTraceContext = pContext->GetTraceContext();

pTraceContext->QuickTrace(
    L"Invalid data"      // Data1
    L"More Data",          // Data2
    0x8000000D,            // HRESULT
    (UCHAR)TRACE_WARNING); // Trace level

Each trace event requires a trace provider and trace area with which it is associated. When you use QuickTrace, trace provider “WWW Server” and trace area “Module” is used. So for trace events generated by IHttpTraceContext::QuickTrace to appear in trace logs, tracing for provider “WWW Server” and area “Module” must be enabled. If you want to dump information in a more custom format, you can use IHttpTraceContext::RaiseTraceEvent API instead which gives you the maximum flexibility. Types of data which you can dump in a trace event using RaiseTraceEvent are defined by HTTP_TRACE_TYPE enum in httptrace.h. Here is a sample code which generate trace events as generated by QuickTrace using RaiseTraceEvent instead.

HRESULT                  hr            = S_OK;
DWORD                    dwVerbosity   = 3; // Warning
DWORD                    dwArea        = 512;
BOOL                     fTraceEnabled = FALSE;

//
// TraceProviderGuid for WWW Server picked from applicationHost.config
//
static const GUID TraceProviderGuid =
        {0x3a2a4e84,0x4c21,0x4981,{0xae,0x10,0x3f,0xda,0x0d,0x9b,0x0f,0x83}};
static const GUID TraceAreaGuid =
        {0x528dbd54,0x1b68,0x4f58,{0xa8,0xc0,0xb3,0x92,0xdf,0x6d,0xf0,0xc9}};

// IHttpContext*   pContext;
IHttpTraceContext* pTraceContext = pContext->GetTraceContext();

//
// Check if tracing for provider + area is enabled before generating the event
//
HTTP_TRACE_CONFIGURATION TraceConfig;
TraceConfig.pProviderGuid = &TraceProviderGuid;

hr = pTraceContext->GetTraceConfiguration( &TraceConfig );

if( !FAILED(hr) && TraceConfig.fProviderEnabled == TRUE )
{
    if( ( TraceConfig.dwVerbosity >= dwVerbosity ) &&
        ( ( TraceConfig.dwAreas & dwArea ) == dwArea ) )
    {
        fTraceEnabled = TRUE;
    }
}

if( fTraceEnabled == TRUE )
{
    PCWSTR pData1      = L"Invalid data";
    PCWSTR pData2      = L"More data";
    DWORD  dwHresult   = 0x8000000D;

    HTTP_TRACE_EVENT Event;

    Event.dwEvent        = 150;    // Change this number for different events
    Event.pszEventName   = L"SampleModuleTraceEvent";
    Event.cEventItems    = 3;      // count of trace event items
    Event.dwArea         = dwArea;
    Event.dwEventVersion = 1;
    Event.dwVerbosity    = dwVerbosity;
    Event.pAreaGuid      = &TraceAreaGuid;
    Event.pProviderGuid  = &TraceProviderGuid;
    Event.dwFlags        = HTTP_TRACE_EVENT_FLAG_STATIC_DESCRIPTIVE_FIELDS;
    // IIS will set pActivityGuid, pRelatedActivityGuid, Timestamp
    Event.pActivityGuid = NULL;
    Event.pRelatedActivityGuid = NULL;
    Event.dwTimeStamp = 0;

    HTTP_TRACE_EVENT_ITEM TraceItems[ 3 ];
    TraceItems [ 0 ].pszName = L"Data1";
    TraceItems [ 0 ].dwDataType = HTTP_TRACE_TYPE_LPCWSTR;
    TraceItems [ 0 ].pbData = (PBYTE) pData1;
    TraceItems [ 0 ].cbData  = (pData1 == NULL ) ? 0 : (sizeof(WCHAR) * (1 + wcslen(pData1)));
    TraceItems [ 0 ].pszDataDescription = NULL;

    TraceItems [ 1 ].pszName = L"Data2";
    TraceItems [ 1 ].dwDataType = HTTP_TRACE_TYPE_LPCWSTR;
    TraceItems [ 1 ].pbData = (PBYTE) pData2;
    TraceItems [ 1 ].cbData = (pData2 == NULL ) ? 0 : (sizeof(WCHAR) * (1 + wcslen(pData2)));
    TraceItems [ 1 ].pszDataDescription = NULL;

    TraceItems [ 2 ].pszName = L"ErrorCode";
    TraceItems [ 2 ].dwDataType = HTTP_TRACE_TYPE_ULONG;
    TraceItems [ 2 ].pbData = (PBYTE) &dwHresult;
    TraceItems [ 2 ].cbData = 4;
    TraceItems [ 2 ].pszDataDescription = NULL;

    Event.pEventItems = TraceItems;
    pTraceContext->RaiseTraceEvent( &Event );
}

You can point your customers to this article to enable tracing and generate detailed traces. In the code above we used 'WWW Server' trace provider and 'Module' as trace area. If you want to define your own trace provider to group traces from your module, you can define your own trace provider and/or trace area. I will cover that in my next post.

Thanks.
Kanwal

3 thoughts on “Generating trace information in native modules

  1. Kanwaljeet,
    Thanks for this example. I am writing a Module and have incorporated this code into it. For some reason, I can't get the "Check if tracing for provider + area is enabled before generating the event" to work. The GetTraceConfiguration is not returning S_OK. Here is what I have:
     BOOL
    Module::ModuleTracingEnabled( IHttpTraceContext * pTraceContext, DWORD dwVerbosity )
    {
     //dwVerbosity will be set to Verbose = 5
     HTTP_TRACE_CONFIGURATION TraceConfig;
     GUID WWWTraceProviderGuid = {0x3a2a4e84,0x4c21,0x4981,{0xae,0x10,0x3f,0xda,0x0d,0x9b,0x0f,0x83}};
     DWORD m_dwArea = 512; //Module
     TraceConfig.pProviderGuid = &WWWTraceProviderGuid;
     HRESULT hr = pTraceContext->GetTraceConfiguration( &TraceConfig );
     if( !(FAILED( hr )) && TraceConfig.fProviderEnabled == TRUE )
     {
      if( ( TraceConfig.dwVerbosity >= dwVerbosity ) &&
       ( ( TraceConfig.dwAreas & m_dwArea ) == m_dwArea ) )
      {
       return TRUE;
      }
     }
     return FALSE;
    }
     I have set FREB rule correctly on the different levels (global, website, application), but none will not trigger the return value of TRUE. Can you tell me if your code still works? Do you see anything wrong in mine?
    I do not think the IHttpContext is different due to registering, but my module is registering for server events as this:
    DWORD dwRequestNotification = RQ_BEGIN_REQUEST;
    DWORD dwPostRequestNotification = 0;
    I would appreciate any thoughts that you might have.
    Thanks,
    Jamie

  2. I need to clarify something. I do get a S_OK from the GetTraceConfiguration, but TraceConfig.fProviderEnabled is always FALSE. FREB is enabled with everything selected such as WWW Server with Verbose and all Areas selected. Not sure why GetTraceConfiguration is not returning TRUE. Any thoughts regarding this?

  3. As per Jamie’s comments above, defining the GUIDs in such a way does not work (possibly depends on project configuration.)

    You should first #include <InitGuid.h> and then #include <httptrace.h> to use the const guid GUID_IIS_WWW_SERVER_TRACE_PROVIDER
    (Refer here.)

    Alternatively, you may like to define your own GUID as follows:


    // order matters! Macro defined in initguid.h
    #include <initguid.h>
    #include <httptrace.h>
    #include ...

    DEFINE_GUID(GUID_FOOBAR_TRACE_PROVIDER,
    0x12345678, 0x1111, 0x2222, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa);

    DEFINE_GUID(GUID_FOOBAR_TRACE_AREA,
    0x12345678, 0x1111, 0x2222, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa);

    Also note: While current IHttpTraceContext implementers return only S_OK from GetTraceConfiguration, you should test for success or failure by passing the returned HRESULT to the SUCCEEDED or FAILED macros, respectively, because the implementation may change.
    from here.

Leave a Reply

Your email address will not be published. Required fields are marked *