Bug 62771 - Lost Cookie header (at least) just after request parse
Summary: Lost Cookie header (at least) just after request parse
Status: RESOLVED INVALID
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.24
Hardware: All Linux
: P2 critical (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords: RFC
Depends on:
Blocks:
 
Reported: 2018-09-28 15:17 UTC by Lino
Modified: 2018-09-28 17:26 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Lino 2018-09-28 15:17:22 UTC
Hi friends

I'm working with one tomat 8.0.24 in docker (openshift) with one liferay application. I have 3 PODS up with 12 GB each one.

I make next test: simply launch 20.000 request over the same file (one static file) in loop; i send in loop one logger JSESSIONID; when one response returns me a new JSESSIONID, stop loop and study tomcat traces.

I have actived all needed tomcat traces, and i added next traces in class CoyoteAdapter.java:


 protected void parseSessionCookiesId(Request request)
  {
    if (log.isDebugEnabled()) {
      log.debug(" (sn3) Begin  parseSessionCookiesId");
    }

    Context context = request.getMappingData().context;
    if ((context != null) && 
      (!context.getServletContext()
      .getEffectiveSessionTrackingModes().contains(
      SessionTrackingMode.COOKIE)))
    {
      if (log.isDebugEnabled()) {
        log.debug(" (sn3) Exit by sessiontracking cookie.");
      }

      return;
    }

    ServerCookies serverCookies = request.getServerCookies();
    int count = serverCookies.getCookieCount();

    if (log.isDebugEnabled()) {
      log.debug(" (sn3) this request have [" + count + "] cookies");
    }

    if (count <= 0)
    {
      if (log.isDebugEnabled()) {
        log.debug(" (sn3) exit with cookies zero");
      }
      return;
    }

Ok! Then, when i recevied one response that change my JSESSIONID, y obtain next response from tomcat:

FINE: Received [GET /combo/?browserId=firefox&minifierType=&languageId=es_ES&b=sn33672&t=1487937532000&/html/js/aui/querystring-parse/querystring-parse-min.js&/html/js/aui/aui-url/aui-url-min.js HTTP/1.1
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E; InfoPath.3)
Accept-Language: es-ES
Cookie: COOKIE_SUPPORT=true; GUEST_LANGUAGE_ID=es_ES; JSESSIONID=540BA449FBD21CFE3F91CAFE7E6E3F74; LFR_SESSION_STATE_20161=1524499633140 LFR_SESSION_STATE_21711=1524501937121; COMPANY_ID=20157; ID=68495a7a4c676f5972446677434b59425a54374341773d3d;sn3counter=3672
Referer: http://desktopccorp.aacc.gs.corp/group/espaciocorporativo/home
Cache-Control: no-cache
Pragma: no-cache
Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
Host: desktopccorp.aacc.gs.corp
X-Forwarded-Host: desktopccorp.aacc.gs.corp
X-Forwarded-Port: 80
X-Forwarded-Proto: http
Forwarded: for=180.93.30.9;host=desktopccorp.aacc.gs.corp;proto=http
X-Forwarded-For: 180.93.30.9

]

Sep 12, 2018 3:09:16 PM org.apache.catalina.connector.CoyoteAdapter parsePathParameters
FINE: The variable [uriBC] has value [/combo/]
Sep 12, 2018 3:09:16 PM org.apache.catalina.connector.CoyoteAdapter parsePathParameters
FINE: The variable [semicolon] has value [-1]
Sep 12, 2018 3:09:16 PM org.apache.catalina.connector.CoyoteAdapter parsePathParameters
FINE: The variable [enc] has value [utf-8]
Sep 12, 2018 3:09:16 PM org.apache.catalina.connector.CoyoteAdapter parseSessionCookiesId
FINE:  (sn3) Begin  parseSessionCookiesId
Sep 12, 2018 3:09:16 PM org.apache.catalina.connector.CoyoteAdapter parseSessionCookiesId
FINE:  (sn3) this request have [0] cookies


0 cookies!! All my cookies are lost, but in Received [ trace of AbstractNioInputBuffer you can see that Cookie: header is perfectly received!!!

Another important data is the absence of this trace (this is from one "good" request:

FINE: Cookies: Parsing b[]: COOKIE_SUPPORT=true; GUEST_LANGUAGE_ID=es_ES; _ga=GA1.4.1488353846.1536682028; _gid=GA1.4.887219159.1536682028; JSESSIONID=540BA449FBD21CFE3F91CAFE7E6E3F74; LFR_SESSION_STATE_20161=1536764659329; COMPANY_ID=20157; ID=767a5147686e743575702b36504e64375a3679306c673d3d; USER_UUID=6f7039446b675950595756797438326f4f724556774c3830706f4d52526f6b304a502b386c7848786955773d; LFR_SESSION_STATE_20695=1536764942296

so, reviewing tomcat code, if y have not this trace generated for cookie parser (i try with two, legacy and Rfc6265CookieProcessor), the unique explanation is that THIS REQUEST HAVE NOT COOKIE HEADER CHARGED IN REQUEST COYOTE MIMEHEADERS

OK! Another clue friends! Normally when i have this error, one thread that lost cookies, i have too this error in my tomcat log:

Caused by: java.lang.NullPointerException
	at org.apache.catalina.connector.Request.parseCookies(Request.java:2948)
	at org.apache.catalina.connector.Request.convertCookies(Request.java:2963)
	at org.apache.catalina.connector.Request.getCookies(Request.java:1992)
	at org.apache.catalina.connector.RequestFacade.getCookies(RequestFacade.java:662)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at javax.servlet.http.HttpServletRequestWrapper.getCookies(HttpServletRequestWrapper.java:69)
	at com.liferay.portal.kernel.util.CookieKeys._getCookieMap(CookieKeys.java:275)
	at com.liferay.portal.kernel.util.CookieKeys._get(CookieKeys.java:248)
	at com.liferay.portal.kernel.util.CookieKeys.getCookie(CookieKeys.java:124)
	at com.liferay.portal.util.PortalInstances._getCompanyId(PortalInstances.java:173)


Liferay (in another request) try to get all cookies return  NPE. This bug is reported yet, is  https://bz.apache.org/bugzilla/show_bug.cgi?id=58578

But I think that is not a solution for me... the context is null, ok, but, why? why at the same time one request fails becuouse mappend context is null, and another request just arraived lost Cookie Header (or all headers, I don't know exactly)???



Reviewing tomcat code I only view sense to this combination if for any reason GC "lost his mind" and begins to call recycle() methos without control. In different recycle() overrides I see that counter are moved in cookie parse, context are deleted, etc... have any sense for you??

On monday i'm going to add more traces to AbstractNioInputBuffer class, for log all parse header process and more important line:

this.headerData.headerValue = this.headers.addValue(this.buf, this.headerData.start, this.pos - this.headerData.start);

This line that add cookie to headers. In this moment I will refersh info of this ticket but, friends, meanwhile... any idea??? I am totally lost, more lost than my cookies!! I test all imaginable: numThreads, backlog size, crossContext, cookie parsers.... and no succesfull result yet

THANKS IN ADVANCE FRIENDS!

Regards,
Lino
Comment 1 Konstantin Kolinko 2018-09-28 17:26:05 UTC
Bugzilla is not a support forum.

Tomcat 8.0 has reached end of life several months ago.