Cookie Header Not Being Parsed

[Durand, Dustin]

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="<URL> " authType="null" characterEncoding="UTF-8" contentLength="81" contentType=application/json; charset=UTF-8

CookieHeader="JSESSIONID=ABC; ... <rest of headers>"
cookie_JSESSIONID="ABC"
cookie__lang="en"
cookie_... <and so on>

header_host="<host>" header_connection="Keep-Alive" header_content-length="81" header_origin="<host>" header_adrum="isAjax:true" header_accept="*/*" header_test="LoadTest" header_user-agent="<agent>" header_accept-encoding="gzip, deflate, br" header_accept-language="en-US,en;q=0.9"

header_cookie="JSESSIONID=ABC; ... <rest of headers>"
header_content-type="application/json; charset=UTF-8" header_x-forwarded-for="<ip>" locale=en_US method="POST" pathInfo="null" protocol="HTTP/1.0" queryString"null" remoteAddr="<IP>" remoteHost="<IP>" remoteUser="null" requestedSessionId="ABC" scheme="http" serverName="<host>" serverPort="80" servletPath="<URL> " 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="<url> " authType="null" characterEncoding="UTF-8" contentLength="81" contentType=application/json; charset=UTF-8

CookieHeader="JSESSIONID=ABC; <rest of headers>"
cookies=null

header_host="<host>" header_connection="Keep-Alive" header_content-length="81" header_origin="<origin>" header_adrum="isAjax:true"
header_accept="*/*" header_test="LoadTest" header_user-agent="<agent>" header_accept-encoding="gzip, deflate, br" header_accept-language="en-US,en;q=0.9"

header_cookie="JSESSIONID=ABC; ... <rest of headers>"

header_content-type="application/json; charset=UTF-8" header_x-forwarded-for="<IP>" locale=en_US method="POST" pathInfo="null" protocol="HTTP/1.0" queryString="null" remoteAddr="<IP>" remoteHost="<IP>" remoteUser="null" requestedSessionId="null" scheme="http" serverName="<host> " serverPort="80" servletPath="<URL> " 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_<name>== iterating over values from httpServletRequest.getHeaderNames();
- cookie_<name> == 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[]: <HEADER_VALUE>

But the requests that have null for getCookies() don't have this log entry, despite having the same header value for the cookie as the previous requests.



Has anyone else seen this behavior or have any recommendations on how to troubleshoot this further.

Thanks!
Dustin

[Caldarale, Charles R]

Subject: Cookie Header Not Being Parsed
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)

Thanks for supplying the version info; many people forget.

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.

The last sentence is the key point, indicating the probable source of the
problem: 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).

- Chuck


THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
MATERIAL and is thus for use only by the intended recipient. If you received
this in error, please contact the sender and delete the e-mail and its
attachments from all computers.

[Durand, Dustin]

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



B�KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKCB��[��X��ܚX�KK[XZ[�\�\��][��X��ܚX�P�X�]�\X�K�ܙ�B��܈Y][ۘ[��[X[��K[

[Mark Thomas]

Post by Durand, Dustin

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.

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

Post by Durand, Dustin
-------
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());
}
...
------
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-***@tomcat.apache.org
For additional commands, e-mail: users-***@tomcat.apache.org

[Durand, Dustin]

Tomcat recycles HttpServletRequest objects. If an application retains a reference to a request then you can see the behaviour you describe.
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());
}
...
------
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-***@tomcat.apache.org
For additional commands, e-mail: users-***@tomcat.apache.org



B�KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKCB��[��X��ܚX�KK[XZ[�\�\��][��X��ܚX�P�X�]�\X�K�ܙ�B��܈Y][ۘ[��[X[��K[