QA - ISAPI Extension and Logged Status Code

Question:

Hi,

My ISAPI extension returns "404 xxx" status using

(*ecb->ServerSupportFunction) (ecb->ConnID,
   HSE_REQ_SEND_RESPONSE_HEADER_EX,
   &vBuffer,
   (LPDWORD) NULL,
   (LPDWORD) NULL);

but the log file in C:\WINDOWS\SYSTEM32\logfiles\W3SVC1\ex061030.log always shows a status code of 200:

23:00:55 10.10.36.235 GET /bvcgi-bin/michen.dll 200

How to force the log entry to reflect the true status code set by the ISAPI extension?

Thanks for your help!

Answer:

Each ISAPI Extension DLL is responsible for setting the logged HTTP status code for the request it handled. This is done via the dwHttpStatusCode member of the EXTENSION_CONTROL_BLOCK associated with the request. If the ISAPI Extension DLL does not set the HTTP status code, the default value is 200.

Where's the Magic Fairy Dust?

Now, one may be wondering WHY IIS cannot magically set the logged HTTP status code for the ISAPI Extension. After all, it knows the sequence of ServerSupportFunction calls made by ISAPI; why doesn't IIS just "figure out" what gets sent as the response status line and automagically log it?

Well, that behavior assumes that IIS buffers the response data sent by ISAPIs, which then allows IIS to parse the buffered response to determine the actual response status line... and IIS simply does not buffer the response, so it cannot correctly determine the response status line.

For example, suppose you have this sequence of ISAPI function calls:

1. WriteClient() of "HTTP/1.0 401 Access Denied\r\nContent-Length: 100\r\n\r\n"
2. HSE_REQ_SEND_RESPONSE_HEADER with a "404 xxx" status

Now, since IIS does not buffer nor parse the response, the WriteClient() data just goes straight to the client. Thus, the client sees a 401 response header with the subsequent 100 bytes (consisting of some part of the "404 xxx" response header) as response entity. Meanwhile, IIS can detect a 404 status line sent by HSE_REQ_SEND_RESPONSE_HEADER. So what should be logged? 401? 404? 200?

If IIS buffered and parsed the response, it would notice that the 401 is the status line preceeding the double \r\n, so it can log the same HTTP status code that the client perceives.

IIS makes no attempt to sort through the above ambiguous situations, so it leaves the choice to the ISAPI making the function calls. After all, the ISAPI should know its effective response status since it must generate the response...

Other Considerations

Now, the ISAPI is responsible for correctly setting the logged HTTP status code for both synchronous and asynchronous IO calls. For synchronous IO calls, the logic is straight forward - make sure to set dwHttpStatusCode on the ECB before returning from HttpExtensionProc.

DWORD WINAPI HttpExtensionProc(
    LPEXTENSION_CONTROL_BLOCK pecb
)
{
    ...
    //
    // Send 404 response header
    //
    pecb->ServerSupportFunction(
        pecb->ConnID,
        HSE_REQ_SEND_RESPONSE_HEADER,
        "404 Not Found",
        (LPDWORD)NULL,
        (LPDWORD)NULL);
    //
    // log 404 HTTP status code
    //
    pecb->dwHttpStatusCode = 404;

    return HSE_STATUS_SUCCESS;
}

For asynchronous IO calls, the logic is slightly different - make sure to set the dwHttpStatusCode on the ECB in the asynchronous callback function prior to calling HSE_REQ_DONE_WITH_SESSION.

VOID WINAPI * PFN_HSE_IO_COMPLETION AsyncIOCompletionFunction(
    LPEXTENSION_CONTROL_BLOCK pecb,
    PVOID pContext,
    DWORD cbIO,
    DWORD dwError
);

DWORD WINAPI HttpExtensionProc(
    LPEXTENSION_CONTROL_BLOCK pecb
)
{
    HSE_CUSTOM_ERROR_INFO* pErrorInfo = NULL;

    ...

    //
    // Setup for asynchronous IO
    //
    // Create IO objects on heap and make sure its memory
    // remains valid throughout the lifetime of the
    // asynchronous IO call.
    //
    pErrorInfo = new HSE_CUSTOM_ERROR_INFO;
    if ( NULL == pErrorInfo )
    {
        goto Finished;
    }

    ZeroMemory( pErrorInfo, sizeof( HSE_CUSTOM_ERROR_INFO ) );
    pErrorInfo->pszStatus = "403 Forbidden";
    pErrorInfo->uHttpSubError = 2;
    pErrorInfo->fAsync = TRUE;

    //
    // Keep track of memory used on asynchronous IO call
    // with the "context" of the IO Completion function.
    //
    pecb->ServerSupportFunction(
        pecb->ConnID,
        HSE_REQ_IO_COMPLETION,
        AsyncIOCompletionFunction,
        (LPDWORD)NULL,
        (LPDWORD)pErrorInfo );

    //
    // Make the asynchronous IO call.
    // - On success, do not touch pErrorInfo and
    //   immediately return HSE_STATUS_PENDING
    // - On failure, immediately cleanup and
    //   return HSE_STATUS_ERROR
    //
    if ( pecb->ServerSupportFunction(
            pecb->ConnID,
            HSE_REQ_SEND_CUSTOM_ERROR,
            pErrorInfo,
            (LPDWORD)NULL,
            (LPDWORD)NULL) )
    {
        return HSE_STATUS_PENDING;
    }

Finished:

    if ( NULL != pErrorInfo )
    {
        delete pErrorInfo;
        pErrorInfo = NULL;
    }

    return HSE_STATUS_ERROR;
}

VOID WINAPI * PFN_HSE_IO_COMPLETION AsyncIOCompletionFunction(
    LPEXTENSION_CONTROL_BLOCK pecb,
    PVOID pContext,
    DWORD cbIO,
    DWORD dwError
)
{
    HSE_CUSTOM_ERROR_INFO* pErrorInfo = (HSE_CUSTOM_ERROR_INFO*)pContext;
    DWORD dwIOStatus = dwError == NO_ERROR ?
                       HSE_STATUS_SUCCESS :
                       HSE_STATUS_ERROR;

    if ( NULL != pErrorInfo )
    {
        //
        // log HTTP status code
        //
        pecb->dwHttpStatusCode = atoi( pErrorInfo->pszStatus );

        delete pErrorInfo;
        pErrorInfo = NULL;
    }

    pecb->ServerSupportFunction(
        pecb->ConnID,
        HSE_REQ_DONE_WITH_SESSION,
        &dwIOStatus,
        (LPDWORD)NULL,
        (LPDWORD)NULL );
}

And the tricky one - the asynchronous callback function of HSE_REQ_EXEC_URL. The parent wildcard application mapping which called HSE_REQ_EXEC_URL controls the logged HTTP status code, but that value should come from the execution of the child - you want to log the fact that the child got a 401 during execution and not the fact that the parent reports 200 for being able to transfer execution to the child. Thus, the parent must remember to retrieve the HTTP status code from the child via HSE_REQ_GET_EXEC_URL_STATUS and record that in the dwHttpStatusCode of the parent's ECB in the asynchronous callback.

VOID WINAPI * PFN_HSE_IO_COMPLETION AsyncIOCompletionFunction(
    LPEXTENSION_CONTROL_BLOCK pecb,
    PVOID pContext,
    DWORD cbIO,
    DWORD dwError
);

DWORD WINAPI HttpExtensionProc(
    LPEXTENSION_CONTROL_BLOCK pecb
)
{
    HSE_EXEC_URL_INFO* pExecInfo = NULL;

    ...

    //
    // Setup for asynchronous IO
    //
    // Create IO objects on heap and make sure its memory
    // remains valid throughout the lifetime of the
    // asynchronous IO call.
    //
    pExecInfo = new HSE_EXEC_URL_INFO;
    if ( NULL == pErrorInfo )
    {
        goto Finished;
    }

    ZeroMemory( pExecInfo, sizeof( HSE_EXEC_URL_INFO ) );

    //
    // Keep track of memory used on asynchronous IO call
    // with the "context" of the IO Completion function.
    //
    pecb->ServerSupportFunction(
        pecb->ConnID,
        HSE_REQ_IO_COMPLETION,
        AsyncIOCompletionFunction,
        (LPDWORD)NULL,
        (LPDWORD)pErrorInfo );

    //
    // Make the asynchronous IO call.
    // - On success, do not touch pErrorInfo and
    //   immediately return HSE_STATUS_PENDING
    // - On failure, immediately cleanup and
    //   return HSE_STATUS_ERROR
    //
    if ( pecb->ServerSupportFunction(
            pecb->ConnID,
            HSE_REQ_EXEC_URL,
            pExecInfo,
            (LPDWORD)NULL,
            (LPDWORD)NULL) )
    {
        return HSE_STATUS_PENDING;
    }

Finished:

    if ( NULL != pExecInfo )
    {
        delete pExecInfo;
        pExecInfo = NULL;
    }

    return HSE_STATUS_ERROR;
}

VOID WINAPI * PFN_HSE_IO_COMPLETION AsyncIOCompletionFunction(
    LPEXTENSION_CONTROL_BLOCK pecb,
    PVOID pContext,
    DWORD cbIO,
    DWORD dwError
)
{
    HSE_EXEC_URL_INFO* pExecInfo = (HSE_EXEC_URL_INFO*)pContext;
    HSE_EXEC_URL_STATUS ExecStatus;

    DWORD dwIOStatus = dwError == NO_ERROR ?
                       HSE_STATUS_SUCCESS :
                       HSE_STATUS_ERROR;

    if ( pecb->ServerSupportFunction(
            pecb->ConnID,
            HSE_REQ_GET_EXEC_URL_STATUS,
            &ExecStatus,
            (LPDWORD)NULL,
            (LPDWORD)NULL ) )
    {
        //
        // log HTTP status code
        //
        pecb->dwHttpStatusCode = ExecStatus.uHttpStatusCode;
    }

    if ( NULL != pExecInfo )
    {
        delete pExecInfo;
        pExecInfo = NULL;
    }

    pecb->ServerSupportFunction(
        pecb->ConnID,
        HSE_REQ_DONE_WITH_SESSION,
        &dwIOStatus,
        (LPDWORD)NULL,
        (LPDWORD)NULL );
}

Conclusion

IIS provides ISAPI a lot of control when it comes to the HTTP status code logged for requests it handles. And with such power comes responsibility...

One final thought... the astute reader should realize that this entire HTTP status code logging scheme has one little flaw since IIS6 - ISAPI is NOT able to manipulate the HTTP SubStatus Code introduced in IIS6. Thus, ISAPI can only log 401.0 but not 401.3, even if it called HSE_REQ_SEND_CUSTOM_ERROR to send the 401.3 custom error. Alas, this flaw will likely remain... unless someone really complains about it. :-)

//David