Advanced Logging for IIS - Real-Time Logging

by Vishal Sood

IIS Advanced Logging can extend the web platform to support real-time analytics, helping you to provide real-time reports to customers or work with partners to do the same. The Advanced Logging feature contains an option that enables consumption of log entries in real-time. It aggregates all of the events sent to it during each request and the log definition property publishLogEvent controls whether real-time events are raised for consumption by other applications.

Requirements

  • This article is intended for developers and assumes basic native code writing skills.
  • An understanding of the IIS pipeline isn't required; however, it might help to review the articles listed in the References section to learn more about the methods and data structures that are used.
  • The IS Advanced Logging is an extension for Internet Information Services (IIS) 7 is no longer available. We recommend Enhanced Logging for IIS 8.5.

Enabling Real-time Logging

Real-time logging is a per-log-definition setting in IIS Advanced Logging. To enable real-time logging for a log definition, do the following:

  1. In IIS Manager, open the Advanced Logging feature. Click the server in the Connections pane, and then double-click the Advanced Logging icon on the Home page.
    Screenshot of the I I S Manager features pane. The Advanced Logging icon is selected.

  2. Enable the Advanced Logging feature. In the Actions pane, click Enable Advanced Logging.
    Screenshot of the Actions pane showing Enable Advanced Logging highlighted.

  3. Select the log definition for which you want to enable real-time logging.

    1. In IIS Manager, open the Advanced Logging feature at the server, website, directory, or application level.
    2. In the Advanced Logging feature page, click the log definition, and then in the Actions pane, click Edit Log Definition.
      Screenshot showing Advanced Logging in the main pane. Edit Log Definition is selected in the Actions pane.
  4. Enable real-time logging of events for the selected log definition by selecting the Publish real-time events check box.
    Screenshot of the Log Definition pane. Publish real-time events is checked.

  5. Write an IIS module that consumes the events in real time, as described in the following section.

Writing an IIS Module to Consume Real-Time Events

To log the real-time events raised by the Advanced Logging feature, you must create an IIS module. This section reviews the IIS tracing infrastructure and provides sample code in a compressed (zipped) folder for creating a simple module that you can use as a reference.

Note

The sample code hasn't been tested for memory leaks and other issues and is intended to be used as a reference only.

IIS Tracing Infrastructure

This section describes some IIS tracing concepts that are used for logging real-time events.

IGlobalTraceEventProvider::GetTraceEvent Method

To consume the real-time events raised by Advanced Logging, the IIS module that you create must register for global events. The OnGlobalTraceEvent method should be called for every event that is raised by the system. Registering for it gives you access to the real-time logging events. For more information, see CGlobalModule::OnGlobalTraceEvent Method.

Data Structures

HTTP_TRACE_EVENT Structure

The HTTP_TRACE_EVENT structure forms the backbone of the real-time logging infrastructure. The real-time logging information is passed in the form of this structure.

struct HTTP_TRACE_EVENT{
   LPCGUID pProviderGuid;
   DWORD dwArea;
   LPCGUID pAreaGuid;
   DWORD dwEvent;
   LPCWSTR pszEventName;
   DWORD dwEventVersion;
   DWORD dwVerbosity;
   LPCGUID pActivityGuid;
   LPCGUID pRelatedActivityGuid;
   DWORD dwTimeStamp;
   DWORD dwFlags;
   DWORD cEventItems;
   __field_ecount(cEventItems) HTTP_TRACE_EVENT_ITEM * pEventItems;
};

For more information about this structure, see HTTP_TRACE_EVENT Structure.

HTTP_TRACE_EVENT_ITEM Structure

The HTTP_TRACE_EVENT structure contains one or more HTTP_TRACE_EVENT_ITEM structures, depending on the number of logging fields included in the log definition for which a log was generated.

struct HTTP_TRACE_EVENT_ITEM{
   LPCWSTR pszName;
   HTTP_TRACE_TYPE dwDataType;
   PBYTE pbData;
   DWORD cbData;
   LPCWSTR pszDataDescription;
};

For more information about this structure, see HTTP_TRACE_EVENT_ITEM Structure.

pProviderGuid

The HTTP_TRACE_EVENT structure contains the pProviderGuid property, an LPCGUID that contains the provider identifier. It's important to understand its significance.

As described in CAnalyticsGlobalModule::OnGlobalTraceEvent, OnGlobalTraceEvent is called for every event that is raised by the system. This means that you must filter unwanted events from the incoming events so that only the events of interest (real-time logging events) are available for consumption. You can do this by using the pProviderGuid property value 3C729B22-F9A9-4096-92A4-07E0DDF403EB.

//
// {3C729B22-F9A9-4096-92A4-07E0DDF403EB}
//
static const GUID _LOGGING_PUBLISHING_GUID = 
{ 0x3c729b22, 0xf9a9, 0x4096, { 0x92, 0xa4, 0x7, 0xe0, 0xdd, 0xf4, 0x3, 0xeb } };
………………
………………
    
if ((pTraceEvent->pProviderGuid != &_LOGGING_PUBLISHING_GUID) &&
        (!IsEqualGUID(*(pTraceEvent->pProviderGuid), _LOGGING_PUBLISHING_GUID)))
{
    goto Finished;
}

The Sample Code uses this value to filter out the unwanted events.

Sample Code

This section displays sample code that illustrates the real-time logging concepts described previously in this article. Download CAnalyticsGlobalModule.zip, a copy of the sample code in a compressed (zipped) folder.

Note

The sample code hasn't been tested for memory leaks and other issues and is intended to be used as a reference only.

CAnalyticsGlobalModule::OnGlobalTraceEvent

//
// {3C729B22-F9A9-4096-92A4-07E0DDF403EB}
//
static const GUID _LOGGING_PUBLISHING_GUID = 
{ 0x3c729b22, 0xf9a9, 0x4096, { 0x92, 0xa4, 0x7, 0xe0, 0xdd, 0xf4, 0x3, 0xeb } }; 
//
//  This call is happening on the same thread (synchronous/blocking call) as
//  the call to RaiseTraceEvent, so bail a.s.a.p. if this isn't something
//  we want to handle, and minimize the work we do here
//
//    
GLOBAL_NOTIFICATION_STATUS
CAnalyticsGlobalModule::OnGlobalTraceEvent(
    __in IGlobalTraceEventProvider  *  pProvider)
{
    HRESULT                 hr              = S_OK;
    IHttpContext *          pHttpContext    = NULL;
    HTTP_TRACE_EVENT *      pTraceEvent     = NULL;
    DBG_ASSERT(pProvider != NULL
    //
    //  We only want to handle trace events that are raised for 
    //  logging purposes, so bail a.s.a.p. if this event isn't
    //  for us
    //
    hr = pProvider->GetTraceEvent(&pTraceEvent
    if (FAILED(hr))
    {
        TRACEHR(hr
        goto Finished;
    }
    if (pTraceEvent->pProviderGuid == NULL)
    {
        TRACEMSG(SS_DEFAULT, 
                 TRACE_LEVEL_INFORMATION, 
                 L"Not handling trace event - NULL value for provider GUID"
        goto Finished;
    }
    if ((pTraceEvent->pProviderGuid != &_LOGGING_PUBLISHING_GUID) &&
        (!IsEqualGUID(*(pTraceEvent->pProviderGuid), _LOGGING_PUBLISHING_GUID)))
    {
        goto Finished;
    }
    //
    //  We now need the HTTP context which is used to get the site info later
    //
    hr = pProvider->GetCurrentHttpRequestContext(&pHttpContext
    if (FAILED(hr))
    {
        TRACEHR(hr
        goto Finished;
    }
    ProcessLogEvent(pTraceEvent, pHttpContext

Finished:
    
    return GL_NOTIFICATION_CONTINUE;    
}

ProcessLogEvent

The ProcessLogEvent method copies the logging data into a local data structure so that it can be used later to push data to a web service or database.

Note

The data in the request itself shouldn't be processed as that might cause the request to slow responses to clients.

Note

The code for ProcessLogEvent should be aware that memory used by events might be temporary memory allocated by AllocateRequestMemory. To unblock the thread, the data should be copied.

void ProcessLogEvent(
        __in    HTTP_TRACE_EVENT *  pHttpTraceEvent,
        __in    IHttpContext     *  pHttpContext)
    {
        HRESULT                     hr = S_OK;
        DWORD                       cchName = 0;
        HTTP_TRACE_EVENT *          pNewHttpTraceEvent  = NULL;
        LPCSTR                      pszHostName     = NULL;
        pNewHttpTraceEvent = new HTTP_TRACE_EVENT;
        if (pNewHttpTraceEvent == NULL)
        {
            goto Finished;
        }
        pNewHttpTraceEvent->pEventItems = new HTTP_TRACE_EVENT_ITEM[pHttpTraceEvent->cEventItems];
        if (pNewHttpTraceEvent->pEventItems == NULL)
        {
            goto Finished;
        }
        ZeroMemory(pNewHttpTraceEvent->pEventItems, sizeof(HTTP_TRACE_EVENT_ITEM) * pHttpTraceEvent->cEventItems);
        
        for (DWORD ix = 0; ix < pHttpTraceEvent->cEventItems; ix++)
        {
            if (pHttpTraceEvent->pEventItems[ix].pszName == NULL)
            {
                pNewHttpTraceEvent->pEventItems[ix].pszName = NULL;
                pNewHttpTraceEvent->pEventItems[ix].cbData = 0;
                pNewHttpTraceEvent->pEventItems[ix].pbData = NULL;
                continue;
            }
            //
            //  Copy the name of this event item
            //
            cchName = wcslen(pHttpTraceEvent->pEventItems[ix].pszName);
            pNewHttpTraceEvent->pEventItems[ix].pszName = new WCHAR[cchName + 1];
            if (pNewHttpTraceEvent->pEventItems[ix].pszName == NULL)
            {
                goto Finished;
            }
            memcpy((VOID *)pNewHttpTraceEvent->pEventItems[ix].pszName, pHttpTraceEvent->pEventItems[ix].pszName, (cchName+1) * sizeof(WCHAR));
            //
            //  If there's no data to copy, mark it empty
            //           
            if ((pHttpTraceEvent->pEventItems[ix].cbData == 0) ||
                (pHttpTraceEvent->pEventItems[ix].pbData == NULL))
            {
                pNewHttpTraceEvent->pEventItems[ix].cbData = 0;
                pNewHttpTraceEvent->pEventItems[ix].pbData = NULL;
                continue;
            }
            pNewHttpTraceEvent->pEventItems[ix].pbData = new BYTE[pHttpTraceEvent->pEventItems[ix].cbData];
            if (pNewHttpTraceEvent->pEventItems[ix].pbData  == NULL)
            {
                goto Finished;
            }
            memcpy(pNewHttpTraceEvent->pEventItems[ix].pbData, pHttpTraceEvent->pEventItems[ix].pbData, pHttpTraceEvent->pEventItems[ix].cbData);
            pNewHttpTraceEvent->pEventItems[ix].cbData = pHttpTraceEvent->pEventItems[ix].cbData;
            pNewHttpTraceEvent->pEventItems[ix].dwDataType = pHttpTraceEvent->pEventItems[ix].dwDataType;
        }
        //
        //  At this point, you've copied the event into your memory and can now process your copy, queue it, etc.
        //
//        WriteEventViewerLog(pHttpTraceEvent->pszEventName);   // Can write to eventViewer log to verify that event is processed...
    Finished:
        return;
    }

Summary

In this walkthrough, we reviewed how real-time logging works in the IIS Advanced Logging feature and how to consume logging data in real-time by creating a simple IIS module.

References