Bug 49511 - IIS 7.5 incorrect logging: pfc->pFilterContext is per-connection not per-request
Summary: IIS 7.5 incorrect logging: pfc->pFilterContext is per-connection not per-request
Status: RESOLVED FIXED
Alias: None
Product: Tomcat Connectors
Classification: Unclassified
Component: isapi (show other bugs)
Version: 1.2.30
Hardware: PC All
: P2 major (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-06-28 10:15 UTC by Attila Király
Modified: 2010-11-29 13:46 UTC (History)
1 user (show)



Attachments
Patch to prevent override of logging for unmapped requests (2.43 KB, patch)
2010-09-21 07:09 UTC, Tim Whittington
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Attila Király 2010-06-28 10:15:13 UTC
One of our customer is using IIS 7.5 (on top of Windows 2k8 r2 64 bit) with isapi_redirect 1.2.30. It seems IIS logging is messed up by the redirector: all requests on the same connection (keep-alive enabled) are logged with the same (probably the first) request uri (and query string). So if a jsp is requested, the images used on the jsp are logged with the jsp uri.

Microsoft said the following about the problem:
In native/iis/jk_isapi_plugin.c

-------%<-------%<-------%<-------%<-------

DWORD WINAPI HttpFilterProc(PHTTP_FILTER_CONTEXT pfc,

                            DWORD dwNotificationType, LPVOID pvNotification)

{

…

    <rewrite original URI if needed>

                …

     if (!pfc->pFilterContext) {                                                                                    <- save the rewritten URI/ Query String for logging purpose

                    isapi_log_data_t *ld = (isapi_log_data_t *)pfc->AllocMem(pfc, sizeof(isapi_log_data_t), 0);

                    memset(ld, 0, sizeof(isapi_log_data_t));

                    StringCbCopy(ld->uri, INTERNET_MAX_URL_LENGTH, forwardURI);

                    StringCbCopy(ld->query, INTERNET_MAX_URL_LENGTH, squery);

                    pfc->pFilterContext = ld;

                } else {                                                                                               <- update the rewritten URI / QS if context already exists

                    isapi_log_data_t *ld = (isapi_log_data_t *)pfc->pFilterContext;

                    memset(ld, 0, sizeof(isapi_log_data_t));

                    StringCbCopy(ld->uri, INTERNET_MAX_URL_LENGTH, forwardURI);

                    StringCbCopy(ld->query, INTERNET_MAX_URL_LENGTH, squery);

        …

    else if (dwNotificationType == SF_NOTIFY_LOG) { <- when SF_NOTIFY_LOG  occurs, use URI/QS previously saved in pFilterContext to update URI/QS logged

        if (pfc->pFilterContext) {

            isapi_log_data_t *ld = (isapi_log_data_t *)pfc->pFilterContext;

            HTTP_FILTER_LOG  *pl = (HTTP_FILTER_LOG *)pvNotification;

            pl->pszTarget = ld->uri;

            pl->pszParameters = ld->query;

        }

    }

    return SF_STATUS_REQ_NEXT_NOTIFICATION;

}

 

So, when ISAPI_REDIRECT redirects a URI, it saves/updates the target location (and query string) in a struct pointed by pFilterContext. This pointer is then subsequently used when the SF_NOTIFY_LOG  notification fires to write the redirected URL in the IIS log (instead of the original URL).

 

Now, what happened with pFilterContext  when the next request comes in on the same connection ? It is re-initialized (set to NULL) by the caller (“IIS”) ? Well, unfortunately, the pFilterContext “scope” is the HTTP connection and not the HTTP request. This is more or less documented here :

 

-          from http://blogs.msdn.com/b/david.wang/archive/2006/03/11/why-some-isapi-filter-events-trigger-multiple-times-per-request.aspx

“you need to be aware that pfc->pFilterContext is PER-CONNECTION and NOT PER-REQUEST, which has special implications when servicing keep-alive or pipelined requests”)

 

-          MSDN doc http://msdn.microsoft.com/en-us/library/ms524517(v=VS.90).aspx

 

pFilterContext

 

Points to any context information that the filter wants to associate with this request.

Any memory associated with this request can be safely freed during the SF_NOTIFY_END_OF_NET_SESSION

notification.

 

SF_NOTIFY_END_OF_NET_SESSION (http://msdn.microsoft.com/en-us/library/ms524855(VS.90).aspx)

 

 When the connection between the client and the server is closed, the SF_NOTIFY_END_OF_NET_SESSION

notification occurs. If a Keep-Alive connection has been negotiated, it is possible for many HTTP

requests to occur before this notification.

 

You can now easily understand that the pFilterContext previously used keeps his value until the HTTP connection terminates. This is what is causing the “wrong logging” problem

Fortunately, this also helps to provide a workaround or a fix :

 

1)      Workaround : disable HTTP Keep Alive (INETMGR -> HTTP Response Header icon in Feature View -> click on Set Common Headers at the Action task pane -> uncheck Keep Alive setting)

This allows to get pFilterContext cleared upon every request but, of course, this has performance implications

 

2)      Fix : set pFilterContext  to NULL once we don’t need it like this :

 

   else if (dwNotificationType == SF_NOTIFY_LOG) {

        if (pfc->pFilterContext) {

            isapi_log_data_t *ld = (isapi_log_data_t *)pfc->pFilterContext;

            HTTP_FILTER_LOG  *pl = (HTTP_FILTER_LOG *)pvNotification;

            pl->pszTarget = ld->uri;

            pl->pszParameters = ld->query;

                // fix : make sure context is set to null once we don’t need it :

                pfc->pFilterContext = NULL;

-------%<-------%<-------%<-------%<-------

Some additional info:
This is the only place where AllocMem is used to memory allocation in isapi_redirect. According to the doc http://msdn.microsoft.com/en-us/library/ms525115%28v=VS.90%29.aspx "You can call AllocMem as many times as your code requires, but you cannot flush the AllocMem buffers. IIS maintains a list of allocated memory blocks created in the filter context and frees them after a SF_NOTIFY_END_OF_NET_SESSION notification. This means that the lifespan of AllocMem memory blocks is associated with the connection to the client, not with a particular request. If you are allocating a lot of memory with a Keep-Alive connection, then none of those blocks will be freed until the client is no longer connected.

As an alternative, if blocks of memory are only needed "per request", then you can use whatever memory allocation function that you like and clean up after the SF_NOTIFY_END_OF_REQUEST notification. However, it is easy to lose track of memory blocks that you have allocated if you don't fully understand when notifications fire."

So maybe the memory should be allocated with malloc at the start of the request and freed with free at the end of the request instead of MS mentioned fix.
Comment 1 Attila Király 2010-06-30 05:51:56 UTC
The problem could be reproduced with IIS 6.0 too (32 bit).

The workaround, disabling keep-alive, solves the logging problem on both versions.
Comment 2 Tim Whittington 2010-09-12 19:24:44 UTC
What is happening here is:
 - pFilterContext is allocated per connection/session
 - the uri and query are being correctly set on each request (even if pFilterContext has been allocated)
 - the uri and query are being set correctly in the HTTP_FILTER_LOG structure
 - the uri and query are not overwritten until the next request has started

The documentation of HTTP FILTER_LOG (http://msdn.microsoft.com/en-us/library/ms525464%28v=VS.90%29.aspx) states that the memory used for the uri and query variables "must remain valid until the next filter notification", implying that logging occurs before the next HttpFilterProc notification.

https://forums.iis.net/p/1156804/1900220.aspx and other forum questions with response from Microsoft reps seems to support this theory.

It's implicit (and occasionally explicit) in all the ISAPI code and advice that I've seen (even by Microsoft ISAPI reps) that IIS serialises requests through the ISAPI filter (even for Keep-Alive and pipelined requests).
i.e. you can expect a sequence of ISAPI event notifications through HttpFilterProc to conclude before a new sequence starts.
I can find no structure, documentation, or advice on how to implement per-request data structures (aside from implementing something custom under pFilterContext), which lends weight to this theory.

However if all this were true, then there would be no issue with the logging in the redirector now - the memory in pFilterContext is allocated once per connection, and is consistent from the SF_NOTIFY_LOG event until the subsequent request is started.

The only explanation I can see for this kind of behaviour then is that the actual log writing is being done outside the ISAPI event sequence and after the next request has entered HttpFilterProc and changed the uri and query values.
i.e. we get a something like
 - SF_NOTIFY_PREPROC_HEADERS request 1
 - <normal request processing> request 1
 - SF_NOTIFY_LOG request 1
 - SF_NOTIFY_PREPROC_HEADERS request 2
 - <request 1 logged by IIS>

If this is the case, then setting pfc->pFilterContext to NULL in the SF_NOTIFY_LOG seems to be the only fix.

This will introduce a per-request memory growth of sizeof(isapi_log_data_t) (~ 4k) that will only be freed on termination of the connection though, which may be unacceptable. (We could implement a freeing of the previous log data in SF_NOTIFY_LOG, but we're still not sure that the actual logging would take place before that event. We could also trim the actual memory usage by using AllocMem individually on the uri and query parts, rather than allocating a struct with pre-allocated buffers.)

Posts like this one from David Wang (Microsoft) indicate that this is standard practice however (I've seen numerous examples and mentions of this technique from MS reps). The code explicitly NULLs pFilterContext on request start, without checking whether it was allocated previously for that session.
http://groups.google.ie/group/microsoft.public.platformsdk.internet.server.isapi-dev/msg/8d3a72b740735860


What also doesn't make sense is the assertion in the original report that:

"all requests on the same connection (keep-alive enabled) are logged with the same (probably the first) request uri (and query string)"

What I would expect to see instead is that some (or in the extreme case) all of the requests on the same connection are logged with the request uri of a subsequent request (i.e. not the first, but perhaps the last).
Comment 3 Attila Király 2010-09-13 02:17:40 UTC
I can add the following:
to fix the logging problem I recompiled the isapi redirector with the MS mentioned code modification (adding pfc->pFilterContext = NULL;). The modified dll is used in production for 2 months now. The logging problem is gone and the system is stable. So the fix is good in practice.


"What I would expect to see instead is that some (or in the extreme case) all of
the requests on the same connection are logged with the request uri of a
subsequent request (i.e. not the first, but perhaps the last)."
I see the logic behind this but what we experienced was the opposit of this. Even when we made only a single request to a jsp that contained a js file and the js pulled down a gif (so 3 requests overall) we saw 3 jsp entries in the log. That was the problem because the log is analyzed and the gif plays a special role in it. However the gif was never found. I think the reason for this is that the redirect filter was only set to serve the jsp files (dynamic content) but the js and gif (the static content) were served by the IIS itself. So the filter did not update the uri and query info when the js and gif requests were processed.
Comment 4 Tim Whittington 2010-09-21 06:37:04 UTC
> I think the reason for
this is that the redirect filter was only set to serve the jsp files (dynamic
content) but the js and gif (the static content) were served by the IIS itself.
> So the filter did not update the uri and query info when the js and gif
requests were processed.

This might actually explain what you're seeing - since the pFilterContext is allocated per session/connection we store the uri/query on the .jsp request, and if the subsequent requests for the .js and .gif are served by IIS, we won't overwrite that data.

In the SF_NOTIFY_LOG notification, we just check whether pFilterContext is allocated (which only means that any previous request on that connection was mapped) and blindly overwrite the log information even if we didn't map the current request.

I'll commit a fix to guard against this behaviour - if you could test it that'd be appreciated.
Comment 5 Tim Whittington 2010-09-21 07:08:25 UTC
I've committed a fix to prevent logging unless we actually mapped the current request into the ISAPI Redirector into trunk.

Can you please build and test this version (or alternatively apply the patch I've attached) and see if this resolves the issue.
Comment 6 Tim Whittington 2010-09-21 07:09:19 UTC
Created attachment 26060 [details]
Patch to prevent override of logging for unmapped requests
Comment 7 Tim Whittington 2010-11-29 13:46:59 UTC
This was fixed in 1.2.31