Tuesday, October 31, 2006

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

5 comments:

Fragmentor said...

Hi David,

Great article. What about transferring to a custom 404 page via async HSE_REQ_EXEC_URL and wanting to log a 404 code even though the child 404 page will have "completed" successfully?

Thanks,
Nathan

Anonymous said...

David, is it possible to set a status code from within an ISAPI filter?

Based on your code, I successfully rewrite URLs using an ISAPI filter. Now that I want to update my URL rewrite scheme, I don't want to lose my search engine rankings and would like for the filter to do a 301 redirect to the newer URL.


Unfortunatly, I don't know how or if this is possible. Thank you.

Unknown said...

Every lv is checked before louis vuitton goes out, to make sure that on the other end of the shipment is a very happy customer who will shop with us again and again. We don't strive to just sell you a Louis vuitton bags ; we strive to make you giddy with the louis vuitton handbags designer handbag you have ordered from us.

Unknown said...

There is no limit to the amazing styles of christian audigier . Their own products are designed for the young and fashionable. You will have difficulties choosing among the wide selection of hardy shirt , shirts and hardy shirts . Manufactured using the most durable and comfortable material, you are guaranteed of excellent quality hardy shirt at affordable prices.

You will find that today the rage is very popular in skate shoes are now going out of style, and Hogan skate shoes are adjusting easily to this. Because Hogan scarpe uomo already has some Hogan skate shoes that are in the punk-rock style that many skateboarders today are looking for. Hogan scarpe donna transition to their new Hogan uomo skate shoe look is occurring so easily today because in the late 1990s when the fashion trend started they were able to experiment by re-issuing some of the earlier skate shoe models that they had.


You can use the corresponding jack to connect the PPERFECT STRANGERS player to your home TV or entertainment system. Although the Durabrand PPERFECT STRANGERS DVD doesn't include earphones, PERFECT STRANGERS DVD COLLECTION does come with several accessories - including a battery that appears to be of much higher quality than those in more expensive units.

Unknown said...

However, ugg boots which owns a array of acclaimed designers, not abandoned delights women by contemporary styles, but aswell by absolute abundance and practicality.Sheepskin ugg is absolutely crafted from wool. Many times, uggs are befuddled abroad because they get adulterated or channelled afterwards getting beat for one season, instead of acceptable out of date. There are lots of styles in the accumulating of affidavit ugg sundance , accoutrement tall, abbreviate and abate versions. Due to adaptable sheepskin, these ugg sundance boots do not get channelled or torn even admitting you bend and extend them times.