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
