HOWTO: Get Field Data for Custom Logging with ISAPI Filter

  • Article

Question:

I'm trying to write a Filter that handles writing a W3C-compliant log file based on a special set of criteria. I have found most of the needed information in GetServerVariables(), but I still need the following things:

sc-status: The status code returned by the server on the request (i.e. 200 if the HTTP request was OK)

sc-substatus: Substatus code, it's an entry in the current IIS log files and I'd like to keep it

sc-win32-status: Appears to always be 0, but I'll keep it if I can.

sc-bytes: The number of bytes sent back to the client as the response.

time-taken: The amount of time it took IIS internally to process and complete the request.

If anyone can help me with the necessary calls to get these values, that would be wonderful. They are values in the normal IIS log files when W3C is selected, so I feel like they must be available.

Thanks,

Answer:

You can do it the EASY way or the HARD way. :-) I'll provide you the info; you pick.

Easy Way

The info you want can be found in the HTTP_FILTER_LOG structure available in the SF_NOTIFY_LOG ISAPI Filter event.

 typedef struct _HTTP_FILTER_LOG
{
    const CHAR * pszClientHostName;
    const CHAR * pszClientUserName;
    const CHAR * pszServerName;
    const CHAR * pszOperation;
    const CHAR * pszTarget;
    const CHAR * pszParameters;

    DWORD  dwHttpStatus;
    DWORD  dwWin32Status;

    DWORD  dwBytesSent;             
    DWORD  dwBytesRecvd;            
    DWORD  msTimeForProcessing;     

} HTTP_FILTER_LOG, *PHTTP_FILTER_LOG;

The SF_NOTIFY_LOG event happens right before IIS is about to write the log entry for that request. The members of HTTP_FILTER_LOG are read/write, so it should be trivial for you to use it for custom logging purposes.

What are the benefits of using HTTP_FILTER_LOG?

  1. You do not need to call GetServerVariable() and [re]-allocate a buffer (see this blog entry for an example)
  2. You can even alter what IIS will log by changing the fields of this structure (see this blog entry for an example) - so you can modify pszParameters, have IIS keep the merged log files of all your subdomains (for analysis purposes), and still know which request went to which subdomain

The only thing that is missing is sc-substatus, and it cannot be retrieved in ISAPI Filter.

Hard Way

If you insist on doing it the hard way:

  • sc-status can be obtained from SF_NOTIFY_SEND_RESPONSE, in the HTTP_FILTER_SEND_RESPONSE.HttpStatus member. This only works for structured responses... for raw responses, you have to buffer and parse SF_NOTIFY_SEND_RAW_DATA.

  • sc-substatus and sc-win32-status:

    The only way on IIS6 to get sc-substatus and sc-win32-status for the response is in the async completion function of an HSE_REQ_EXEC_URL ServerSupportFunction call by calling HSE_REQ_GET_EXEC_URL_STATUS.

    Nowhere else in ISAPI Filter/Extension API do you have access to that value, even though we added sc-substatus in IIS6, because we would break binary compatibility by changing existing structures where it logically belongs:

    • You can't read/set it in ISAPI Filter
    • You can't set it in ISAPI Extension
    • You can read it in ISAPI Extension in async completion function HSE_REQ_EXEC_URL

  • sc-bytes - listen on SF_NOTIFY_SEND_RAW_DATA and track HTTP_FILTER_RAW_DATA.cbInData to count number of bytes transferred. Hard part is figuring out how to do this on a per-request basis because pFilterContext is per-connection.

  • time-taken - Set timer between SF_NOTIFY_READ_RAW_DATA and SF_NOTIFY_END_OF_NET_SESSION. This is not compatible with IIS6 Worker Process Isolation Mode.

//David