Re: Cookie Header Not Being Parsed
On 10/21/18, 8:22 AM, "Mark Thomas" wrote:
> Tomcat recycles HttpServletRequest objects. If an application retains a
reference to a request then you can see the behaviour you describe.
> Setting the following system property:
> org.apache.catalina.connector.RECYCLE_FACADES=true
> will cause Tomcat to create a new wrapper for each request/response.
...
---
I checked our bin/setenv.sh, this is already set to true on our Tomcat Servers.
CATALINA_OPTS="... -Dorg.apache.catalina.connector.RECYCLE_FACADES=true ..."
Are there any other possible causes, or steps I could take to troubleshoot this?
Thanks,
Dustin
Tomcat recycles HttpServletRequest objects. If an application retains a
reference to a request then you can see the behaviour you describe.
Setting the following system property:
org.apache.catalina.connector.RECYCLE_FACADES=true
will cause Tomcat to create a new wrapper for each request/response.
This has two advantages. One it should stop one request seeing data from
another. Two it should trigger an NPE when the application tries to
access to request/response that has been retained after it should have
been discarded.
Mark
>
> ---
> public class AccessLogFilter implements Filter {
>
> private static final Logger log =
LoggerFactory.getLogger(AccessLogFilter.class);
>
> public AccessLogFilter() {}
>
> public void doFilter(ServletRequest request, ServletResponse
response, FilterChain chain) throws IOException, ServletException {
> HttpServletRequest httpServletRequest = (HttpServletRequest)
request;
>
> StringBuilder message = new StringBuilder();
> message.append("StartTime=\"" + getTimestamp()+"\"");
> message.append(" requestURI=\"" +
httpServletRequest.getRequestURI() + "\"");
> ...
> chain.doFilter(request, response);
> log.info(message.toString());
> }
> ...
> --
>
> StackTrace @ AccessLogFilter
> 1. DoFilter -> AccessLogFilter (Our new filter)
> 2. InternalDoFilter -> Application Filter Chain (org.apache.catalina.core)
> 3. Invoke -> StandardWrapperValue (org.apache.catalina.core)
> 4. Invoke -> StandardContextValue (org.apache.catalina.core)
> 5. Invoke -> AuthenicatorBase (org.apache.catalina.authenicator)
> ... (All related to org.apache.*, until we hit the java concurrency
frames for the thread)
>
> -
>
>
>
> Thanks,
> Dustin
>
>
>
>
> -
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Cookie Header Not Being Parsed
On 10/20/18, 3:34 PM, "Caldarale, Charles R" wrote:
>your application is likely hanging on to some reference to the prior request
>and inadvertently using it when a new request shows up.
> This often takes the form of instance variables in a servlet being used to
> hold request information.
> Since the servlet object is shared across all requests using it, information
> leakage can occur between concurrent requests; this is
> also true for filters used in the request handling.
> Leakage can also occur with other singletons used by the webapp, or in any
> persistent data maintained by the app (e.g., in a session object).
This makes sense, but, unless I'm misunderstanding, I'm not sure it applies in
this case.
When we started seeing getCookies() returning null, although a valid cookie
header was present, the "AccessLogFilter" class was created and added as the
first filter to be applied in the chain.
It has no instance variables and collects all its information from the provided
ServletRequest argument, before passing the HttpServletRequest down the chain.
If there was an issue where a filter, servlet, or singleton was caching (and
reusing) the old request, then this "first" filter should be unaffected, since
it's above all other application code, and references nothing but the slf4j
logger.
The data gathered by the AccessLogFilter should be coming from a brand-new
instance of HttpServletRequest that's coming from Tomcat.
If I've made a mistake in any of my assumptions above, please let me know.
---
public class AccessLogFilter implements Filter {
private static final Logger log =
LoggerFactory.getLogger(AccessLogFilter.class);
public AccessLogFilter() {}
public void doFilter(ServletRequest request, ServletResponse response,
FilterChain chain) throws IOException, ServletException {
HttpServletRequest httpServletRequest = (HttpServletRequest) request;
StringBuilder message = new StringBuilder();
message.append("StartTime=\"" + getTimestamp()+"\"");
message.append(" requestURI=\"" + httpServletRequest.getRequestURI() +
"\"");
...
chain.doFilter(request, response);
log.info(message.toString());
}
...
--
StackTrace @ AccessLogFilter
1. DoFilter -> AccessLogFilter (Our new filter)
2. InternalDoFilter -> Application Filter Chain (org.apache.catalina.core)
3. Invoke -> StandardWrapperValue (org.apache.catalina.core)
4. Invoke -> StandardContextValue (org.apache.catalina.core)
5. Invoke -> AuthenicatorBase (org.apache.catalina.authenicator)
... (All related to org.apache.*, until we hit the java concurrency frames for
the thread)
-
Thanks,
Dustin
Cookie Header Not Being Parsed
Hello Tomcat Users,
I’ve been attempting to track down an issue where the cookies aren’t being
parsed out of the cookie header in rare cases. We’re using a java service that
utilizes JSession, so this causes the users session to be lost every time one
of these failures occurs.
Version: Tomcat 8.5.31 and 8.5.34 (Attempted to upgrade)
To give additional context, we’ve been able to track this down by adding a
custom filter (derived from javax.servlet.filter) that dumps all the headers
and cookies for every request that comes to the server. This happens very
rarely, so the only way we’ve been able to reproduce this issue is by doing
load tests against our service.
During the load tests we see the rare request come into the service where the
filter dumps the cookie header which includes the expected cookies, but when
the filter attempts to pull the cookies from the HttpServletRequest they're
missing. To make it more interesting, the value cookie header usually matches
the previous request(s) cookie header value for that user, which was parsed
successfully.
httpServletRequest.getHeaderNames(); // and then iterate over the headers to
see all the headers -- the cookie header does exist and is valid even when
cookies are missing
v.s.
httpServletRequest.getHeaders("Cookie"); // and then iterate over the
enumerable to print the cookie header value. There is still only 1 header
cookie and its valid even when cookies are missing
v.s.
httpServletRequest.getCookies(); // this ends up null when the cookies are
missing
Request #1 (Cookies Present)
--
2018-10-20T12:23:21,387 | Level=INFO Class="ca.xx.web.filters.AccessLogFilter"
| StartTime="20-Oct-2018 12:23:21 GMT" requestURI=" " authType="null"
characterEncoding="UTF-8" contentLength="81" contentType=application/json;
charset=UTF-8
CookieHeader="JSESSIONID=ABC; ... "
cookie_JSESSIONID="ABC"
cookie__lang="en"
cookie_...
header_host="" header_connection="Keep-Alive" header_content-length="81"
header_origin="" header_adrum="isAjax:true" header_accept="*/*"
header_test="LoadTest" header_user-agent=""
header_accept-encoding="gzip, deflate, br"
header_accept-language="en-US,en;q=0.9"
header_cookie="JSESSIONID=ABC; ... "
header_content-type="application/json; charset=UTF-8"
header_x-forwarded-for="" locale=en_US method="POST" pathInfo="null"
protocol="HTTP/1.0" queryString"null" remoteAddr="" remoteHost=""
remoteUser="null" requestedSessionId="ABC" scheme="http" serverName=""
serverPort="80" servletPath=" " isSecure=false ResponseContentType="null"
EndTime=20-Oct-2018 12:23:21 GMT
Request #2 (Missing Cookies)
--
2018-10-20T12:23:21,472 | Level=INFO Class="ca.xx.web.filters.AccessLogFilter"
|
StartTime="20-Oct-2018 12:23:21 GMT" requestURI=" " authType="null"
characterEncoding="UTF-8" contentLength="81" contentType=application/json;
charset=UTF-8
CookieHeader="JSESSIONID=ABC; "
cookies=null
header_host="" header_connection="Keep-Alive" header_content-length="81"
header_origin="" header_adrum="isAjax:true"
header_accept="*/*" header_test="LoadTest" header_user-agent=""
header_accept-encoding="gzip, deflate, br"
header_accept-language="en-US,en;q=0.9"
header_cookie="JSESSIONID=ABC; ... "
header_content-type="application/json; charset=UTF-8"
header_x-forwarded-for="" locale=en_US method="POST" pathInfo="null"
protocol="HTTP/1.0" queryString="null" remoteAddr="" remoteHost=""
remoteUser="null" requestedSessionId="null" scheme="http" serverName=" "
serverPort="80" servletPath=" " isSecure=false ResponseContentType="null"
EndTime=20-Oct-2018 12:23:21 GMT
Notes:
- The value in the "cookie" header is the exact same between request 1 and
request 2, as are the request URL and host.
- CookieHeader == httpServletRequest.getHeaders("Cookie");
- header_== iterating over values from
httpServletRequest.getHeaderNames();
- cookie_ == iterating over httpServletRequest.getCookies();
OR cookies=null if it’s null
--
We've attempted to switching from Rfc6265CookieProcessor to
LegacyCookieProcessor, but this had no effect.
I've dug around the Tomcat Github repo, and I didn't notice anything specific.
Http11InputBuffer seems to do the main parsing of the headers into the
MimeHeaders instance that's part of the Request instance.
These MimeHeaders then end up in the cookies parsers (Rfc6265CookieProcessor or
LegacyCookieProcessor), and it's calling:
int pos = [MimeHeaders] headers.findHeader("Cookie", 0);
Based on what I'm seeing in the filter, the cookie should be available to the
parser.
We turned on the FINE level logging for the org.apache.tomcat.util classes, and
the normal requests contain something along the following:
20-Oct-2018 12:08:45.981 FINE [http-nio-8080-exec-10]
org.apache.tomcat.util.http.Rfc6265CookieProcessor.parseCookieHeader Cookies:
Parsing b[]:
But the requests that have null for getCookies() don't have this log entry,
despite having the same
