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...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
