You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2010/06/28 16:15:19 UTC
DO NOT REPLY [Bug 49511] New: IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Summary: IIS 7.5 incorrect logging: pfc->pFilterContext is
per-connection not per-request
Product: Tomcat Connectors
Version: 1.2.30
Platform: PC
OS/Version: Windows Server 2008 (Longhorn)
Status: NEW
Severity: major
Priority: P2
Component: isapi
AssignedTo: dev@tomcat.apache.org
ReportedBy: kiralyattila.hu@gmail.com
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.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
--- Comment #5 from Tim Whittington <ti...@apache.org> 2010-09-21 07:08:25 EDT ---
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.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Tim Whittington <ti...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |RESOLVED
Resolution| |FIXED
--- Comment #7 from Tim Whittington <ti...@apache.org> 2010-11-29 13:46:59 EST ---
This was fixed in 1.2.31
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Tim Whittington <ti...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
--- Comment #1 from Attila Király <ki...@gmail.com> 2010-06-30 05:51:56 EDT ---
The problem could be reproduced with IIS 6.0 too (32 bit).
The workaround, disabling keep-alive, solves the logging problem on both
versions.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
--- Comment #6 from Tim Whittington <ti...@apache.org> 2010-09-21 07:09:19 EDT ---
Created an attachment (id=26060)
--> (https://issues.apache.org/bugzilla/attachment.cgi?id=26060)
Patch to prevent override of logging for unmapped requests
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
--- Comment #4 from Tim Whittington <ti...@apache.org> 2010-09-21 06:37:04 EDT ---
> 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.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Attila Király <ki...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |NEW
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Attila Király <ki...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |kiralyattila.hu@gmail.com
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
--- Comment #3 from Attila Király <ki...@gmail.com> 2010-09-13 02:17:40 EDT ---
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.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 49511] IIS 7.5 incorrect logging:
pfc->pFilterContext is per-connection not per-request
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=49511
Tim Whittington <ti...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #2 from Tim Whittington <ti...@apache.org> 2010-09-12 19:24:44 EDT ---
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).
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org