Link to home
Start Free TrialLog in
Avatar of Smith Davis
Smith Davis

asked on

Lost sessions and / or lost session data in a site with Spring MVC/Security and Tomcat

The website I am supporting was developed with Spring MVC (4.2.9.RELEASE), Spring Security (3.2.5.RELEASE), JSP, and Hibernate (4.3.8.Final). The frontend is a load balancer (Kemp LoadMaster 3000) and the site runs on Tomcat (8.5.54). In order to find the cause of this issue, I am running only one Tomcat instance behind the load balancer in order to have a simpler system. Each page on the site (public pages and the pages seen after authentication) runs under HTTPS (The SSL certificate is installed on the load balancer, which sends HTTP requests to Tomcat). The server is Windows Server 2012 R2 Standard. There is no use of session.invalidate() in code.

The site has a multi-page form for the public (no authentication is needed). The following simplified code shows the issue (the multi-form uses the same JSP and controller methods)

----get----

@RequestMapping(value="/form", method = RequestMethod.GET)
public String pageGet(HttpServletRequest request, 
    HttpServletResponse response,
    Model model, Map<String, Object> map) throws IOException {

    request.getSession().setAttribute("token", "token-value");
    request.getSession().setAttribute("sessionId", request.getSession().getId());

    return "myform";
}

Open in new window


----jsp----

<form method="post" action="....">

<input type="hidden" name="sessionId" value="the value of session id from the get method"> 

...other fields

</form>

Open in new window


----post----

@RequestMapping(value="/form", method = RequestMethod.POST)
public String pageGet(HttpServletRequest request, 
    HttpServletResponse response,
    Model model, Map<String, Object> map) throws IOException {

    System.out.println(request.getSession().getAttribute("token"));
    System.out.println(request.getParameter("sessionId")); //session ID stored in form
    System.out.println(request.getSession().getId()); //current session ID

    return "redirect:/success";
}

Open in new window


The controller class has no class variables that store the token value or store session id shown in the code.

The session timeout on the load balancer is 60 minutes and its persistent mode is

Super HTTP and Source IP

Note that cache on the load balancer is disabled. The session timeout on Tomcat is also 60 minutes specified in web.xml

<session-config>
    <session-timeout>60</session-timeout>
    <tracking-mode>COOKIE</tracking-mode>
</session-config>

Open in new window


Here are my observations about the issue of lost sessions and/or session data. For a big percentage of the times, the POST method prints the same session IDs and token value if the submission takes place within 60 minutes after the form is displayed, and the multi-page form work just fine. This is understandable. What I don't understand is that for a small percentage of cases in which the form submission happens before the 60 minute limit, the session ID changes AND the token value is null or the session IDs remain the same BUT the token value is null. This issue could happen at any step of the form (that is, page 1, page 2, etc.)

I added a listener to get some info about when lost sessions are destroyed in the sessionDestroyed method.

long inactivePeriod =  (new Date().getTime() -  session.getLastAccessedTime())/1000;

The value is always a few seconds after 3600 sessions (an hour) such as 3602, 3604, etc. No exceptions.

The following is the related setup in Spring Security.

<security:http auto-config="false" use-expressions="true" request-matcher="regex" entry-point-ref="authenticationEntryPoint" >
    <security:intercept-url pattern="^\/secure\/.*$" access="hasRole('ROLE_USER')"  />
    <security:access-denied-handler ref="accessDeniedHandler" />
    <security:logout invalidate-session="true" logout-url="/secure/logout" logout-success-url="/" delete-cookies="JSESSIONID" />
    <security:custom-filter ref="authenticationFilter" position="FORM_LOGIN_FILTER" />  
    <security:anonymous username="guest" granted-authority="ROLE_GUEST" />
</security:http>

Open in new window


This is the server.xml in Tomcat.

<Server port="dddd" shutdown="kkkkk">
  <Listener className="org.apache.catalina.startup.VersionLoggerListener" />
  <Listener className="org.apache.catalina.core.AprLifecycleListener" SSLEngine="on" />
  <Listener className="org.apache.catalina.core.JreMemoryLeakPreventionListener" />
  <Listener className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener" />
  <Listener className="org.apache.catalina.core.ThreadLocalLeakPreventionListener" />

  <Service name="Catalina">

    <Connector URIEncoding="UTF-8" 
        compressableMimeType="text/html,text/xml,text/plain,text/css,text/javascript,application/javascript,application/json" 
        compression="on" 
        compressionMinSize="2048" 
        connectionTimeout="20000" 
        maxThreads="500" 
        maxConnections="30000" 
        noCompressionUserAgents="gozilla, traviata" 
        port="80" 
          maxHttpHeaderSize="10240" 
        protocol="org.apache.coyote.http11.Http11NioProtocol" 
        redirectPort="443"
        useSendfile="false"/> 

    <Engine name="Catalina" defaultHost="localhost">

        <Cluster className="org.apache.catalina.ha.tcp.SimpleTcpCluster"
                 channelSendOptions="8">

          <Manager className="org.apache.catalina.ha.session.DeltaManager"
                   expireSessionsOnShutdown="false"
                   notifyListenersOnReplication="true"/>

          <Channel className="org.apache.catalina.tribes.group.GroupChannel">
            <Membership className="org.apache.catalina.tribes.membership.McastService"
                        address="224.0.0.252"
                        port="4001"
                        frequency="500"
                        dropTime="3000"/>
            <Receiver className="org.apache.catalina.tribes.transport.nio.NioReceiver"
                      address="auto"
                      port="4000"
                      autoBind="100"
                      selectorTimeout="5000"
                      maxThreads="250"
                      minThreads="6"/>

            <Sender className="org.apache.catalina.tribes.transport.ReplicationTransmitter">
              <Transport className="org.apache.catalina.tribes.transport.nio.PooledParallelSender"/>
            </Sender>
            <Interceptor className="org.apache.catalina.tribes.group.interceptors.TcpFailureDetector"/>
            <Interceptor className="org.apache.catalina.tribes.group.interceptors.MessageDispatchInterceptor"/>
          </Channel>

          <Valve className="org.apache.catalina.ha.tcp.ReplicationValve"
                 filter=""/>
          <Valve className="org.apache.catalina.ha.session.JvmRouteBinderValve"/>

          <ClusterListener className="org.apache.catalina.ha.session.ClusterSessionListener"/>
        </Cluster>        

    </Engine>
  </Service>
</Server>

Open in new window


How can I prevent the loss of sessions and/or session data if a session does not time out? I really need this because of how the site works. I spend a lot of time online for a possible fix and did MANY and VARIOUS tests (including adding code to exclude the possibility that the issue is caused by spam or attack), but no success.

Please feel free to let me know if you need more info about the site or tests.

-----6/19/20 Update ------

I have added screenshots to show the settings of the load balancer.

-----6/20/20 Update ------

The multi-page form has extra code to make sure Javascript  and cookies are enabled. If Javascript or cookie is disabled in a browser, the form doesn't show form fields or the submit button.
Screenshot_2020-06-19-part1.png
Screenshot_2020-06-19-part2.png
RequestDumperFilter-catalina-2020070.txt
log-access-20200709.txt
Avatar of girionis
girionis
Flag of Greece image

Maybe the load balancer does not propagate the session correctly. Have you tried to remove the load balancer and stay only with tomncat?
Avatar of Smith Davis
Smith Davis

ASKER

@girionis, I am unable to remove the load balancer because this is a production system and besides I don't have resources to reconfigure the network to remove the load balancer.
Thanks for chiming in! 
You asked me to look at this question.  But I can't help you much because I don't use Spring or Kemp.  
But,  I do have a few questions.  
 System.out.println(request.getSession().getAttribute("token"));

Open in new window

 
Where do  you create your sessions?  
Your use of  request.getSession() is curious. If the request had no session associated with it, then a session would have been created and the attribute would return null.
 I would have used something like
HttpSession session = request.getSession(false);
if(session != null){
    System.out.println(session id is " + session.getId());
	System.out.println(session.getAttribute("token"));	
} else{
    System.out.println("no session");
}

Open in new window

The value is always a few seconds after 3600 sessions (an hour) such as 3602, 3604, etc. No exceptions.

Isn't that what should happen?  Tomcat invalidated the session after the 3600 inactive interval.
Did you notice any pattern for those small percentage of cases that fail?

Also, can you enable debug logs to see all headers coming from/going to the load balancer? It will probably show that in the problematic requests the "cookie" header is missing.
@rrz

>>Where do  you create your sessions?  
>>Your use of  request.getSession() is curious. If the request had no session associated with it, then a session would have been created and the attribute would return null.

The app doesn't have explicit code to create a session. It is my understanding that Tomcat/Java creates the session for you if it doesn't exist and keeps the session for you until it is explicitly invalidated and time out. I need to know why some requests return the session Id changed and/or null for the value stored in session.

 >>Isn't that what should happen?  Tomcat invalidated the session after the 3600 inactive interval.

The reason that I used a listener to find out the longevity of a session is to prove that no session is invalidated prematurely through code or something.

It is my understanding that Tomcat/Java creates the session for you if it doesn't exist
This is true. The session will be implicitly created (if there isn't one already).
@girionis

>>Did you notice any pattern for those small percentage of cases that fail?

I added many logging statements in code to get out related info. The only pattern is that missing sessions are just very few and that in even fewer cases the session IDs don't change (which means the session is not lost) but the token value is null.

>>Also, can you enable debug logs to see all headers coming from/going to the load balancer? It will probably show that in the problematic requests the "cookie" header is missing.

Technically, the issue could happen between the load balancer and Tomat. I will see if I can output all headers. If the "cookie" is missing, then it explains why the session ID changes. What about the missing token values stored in the session when the session ID doesn't change?

For your info: the multi-page form already has extra code to prevent issues. If Javascript or cookie is disabled in a browser, the form doesn't show form fields or the submit button. Does this piece of info help?


I can't explain the missing token. Is it possible that somewhere in your code you set it to null/remove it?

For your info: the multi-page form already has extra code to prevent issues. If Javascript or cookie is disabled in a browser, the form doesn't show form fields or the submit button. Does this piece of info help?
It could be possible for the user, while in the multi-page form, to remove the cookies from the browser and start over. This would create a new session though. This could explain why the session is lost, but it is highly unlikable.
@girionis,

>>>>Also, can you enable debug logs to see all headers coming from/going to the load balancer? It will probably show that in the problematic requests the "cookie" header is missing.

I cannot think of a quick way of capturing both "from" and "to" the load balancer. Do you know of any pointers or samples? Thanks!
The app doesn't have explicit code to create a session
 If Spring Security, is controlling the Authentication process, then maybe it is creating the session.
 
 
It is my understanding that Tomcat/Java creates the session for you

The only place a session is automatically created in Tomcat is in a JSP. But, since you are using Spring I doubt that is happening.

I cannot think of a quick way of capturing both "from" and "to" the load balancer

If that is the same as what is going in and out of your web app in Tomcat, then you could use a Servlet filter.
@rrz

>> If Spring Security, is controlling the Authentication process, then maybe it is creating the session.

I already looked at this possibility. From what I know, spring security MAY create a new session at authentication to have session fixation protection. The page I have that has the issue of lost sessions/data is a public page that doesn't involve authentication. Even so, I already tried the following configuration:

<security:session-management session-fixation-protection="none">
   <security:concurrency-control max-sessions="2" />
</security:session-management>  

The issue still exists. If you know something else, please feel free to let me know.

>>The only place a session is automatically created in Tomcat is in a JSP. But, since you are using Spring I doubt that is happening.

I am not sure about what you meant by this. Are you saying that in my case spring security manages sessions?







Are you saying that in my case spring security manages sessions?
I don't  use Spring. So, I  don't really know.  But, I guess that  is the case.  
Hopefully, a Spring expert will comment here.
have session fixation protection.
Even if this is happening, the default behaviour is migrateSession, which means all attributes in session will be copied over to the new session. This does not explain the lost token.
By the way, @Smith Davis, you can implement the HttpSessionListener interface and you can know when a session is created/destroyed. I think this will be useful.
@girionis

>>you can implement the HttpSessionListener interface and you can know when a session is created/destroyed. I think this will be useful.

I already implemented it when I tested out this configuration

security:session-management session-fixation-protection="none">
   <security:concurrency-control max-sessions="2" />
</security:session-management>

>>the default behaviour is migrateSession, which means all attributes in session will be copied over to the new session.  

I was aware of this behavior. But it is supposed to applicable at authentication. The issue I have is about public pages.

@ girionis,

>>>>Also, can you enable debug logs to see all headers coming from/going to the load balancer? It will probably show that in the problematic requests the "cookie" header is missing.
>>https://stackoverflow.com/questions/34094030/log-all-http-requests-of-tomcat-server 

I have been using the referred logging in Tomcat. I adjusted the logging pattern to get more info. Here is the setup in server.xml

        <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%t %a %u %S &quot;%r&quot; %s %b %D %F" />

The existing logging in the site is able to identify the cases of changed session IDs at POST. Here are three example cases that were logged in "localhost_access_log"  this morning (US Eastern Summer time). The multi-page form is a questionnaire form, and the number of pages may vary depending on a particular questionnaire.

Case 1
[22/Jun/2020:00:21:23 -0400] 42.76.135.136 - - "GET /s?did=wla5a6yi25u11&lang=zh_TW HTTP/1.1" 200 10237
[22/Jun/2020:00:21:23 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /css/v1_default.css?v=20200505 HTTP/1.1" 200 6917
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /lib/bootstrap-datepicker-1.3.0/js/locales/bootstrap-datepicker.zh-TW.js HTTP/1.1" 200 891
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - - "GET /js/namespaces.js HTTP/1.1" 200 609
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965
[22/Jun/2020:00:21:24 -0400] 42.76.135.136 - - "GET /js/site.min.js?v=20200617 HTTP/1.1" 200 86789
[22/Jun/2020:00:21:25 -0400] 42.76.135.136 - 48C08735889B5AD96E643D15A10717C6 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403
[22/Jun/2020:00:21:38 -0400] 42.76.135.136 - - "POST /s?did=wla5a6yi25u11 HTTP/1.1" 302 223
[22/Jun/2020:00:21:39 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=1 HTTP/1.1" 200 9760
[22/Jun/2020:00:21:42 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=1 HTTP/1.1" 302 223
[22/Jun/2020:00:21:42 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=3 HTTP/1.1" 200 9803
[22/Jun/2020:00:21:45 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=3 HTTP/1.1" 302 223
[22/Jun/2020:00:21:46 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=5 HTTP/1.1" 200 9773
[22/Jun/2020:00:21:49 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=5 HTTP/1.1" 302 223
[22/Jun/2020:00:21:50 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=7 HTTP/1.1" 200 9801
[22/Jun/2020:00:21:55 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=7 HTTP/1.1" 302 223
[22/Jun/2020:00:21:55 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=9 HTTP/1.1" 200 9908
[22/Jun/2020:00:22:01 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=9 HTTP/1.1" 302 223
[22/Jun/2020:00:22:01 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=10 HTTP/1.1" 200 10413
[22/Jun/2020:00:22:15 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=10 HTTP/1.1" 302 223
[22/Jun/2020:00:22:15 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s?did=wla5a6yi25u11&page=13 HTTP/1.1" 200 9981
[22/Jun/2020:00:22:40 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "POST /s?did=wla5a6yi25u11&page=13 HTTP/1.1" 302 223
[22/Jun/2020:00:22:41 -0400] 42.76.135.136 - 27986A72D695DBCF1784F69812C7A200 "GET /s/thankyou?rs=c&did=wla5a6yi25u11 HTTP/1.1" 200 6420

Case 2
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /s?did=s14bp6ijzbuzx&lang=en_US HTTP/1.1" 200 9017
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - 934A7AF9037EA03E62FE51CD46230143 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - 934A7AF9037EA03E62FE51CD46230143 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - 934A7AF9037EA03E62FE51CD46230143 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - 934A7AF9037EA03E62FE51CD46230143 "GET /css/v1_cake_batter.css?v=20200505 HTTP/1.1" 200 7021
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /js/namespaces.js HTTP/1.1" 200 609
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /js/site.min.js?v=20200617 HTTP/1.1" 200 86789
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403
[22/Jun/2020:03:50:57 -0400] 109.246.32.114 - - "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160
[22/Jun/2020:03:50:58 -0400] 109.246.32.114 - - "GET /img/ico/favicon.png HTTP/1.1" 200 3100
[22/Jun/2020:03:51:14 -0400] 109.246.32.114 - - "POST /s?did=s14bp6ijzbuzx HTTP/1.1" 302 223
[22/Jun/2020:03:51:14 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "GET /s?did=s14bp6ijzbuzx&page=1 HTTP/1.1" 200 9026
[22/Jun/2020:03:51:29 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "POST /s?did=s14bp6ijzbuzx&page=1 HTTP/1.1" 302 223
[22/Jun/2020:03:51:30 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "GET /s?did=s14bp6ijzbuzx&page=2 HTTP/1.1" 200 9030
[22/Jun/2020:03:51:34 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "POST /s?did=s14bp6ijzbuzx&page=2 HTTP/1.1" 302 223
[22/Jun/2020:03:51:34 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "GET /s?did=s14bp6ijzbuzx&page=3 HTTP/1.1" 200 9206
[22/Jun/2020:03:51:56 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "POST /s?did=s14bp6ijzbuzx&page=3 HTTP/1.1" 302 223
[22/Jun/2020:03:51:57 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "GET /s?did=s14bp6ijzbuzx&page=4 HTTP/1.1" 200 8926
[22/Jun/2020:03:52:02 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "POST /s?did=s14bp6ijzbuzx&page=4 HTTP/1.1" 302 223
[22/Jun/2020:03:52:03 -0400] 109.246.32.114 - 6BAE9F57FCA600643F6A9E63B3C1F5B9 "GET /s/thankyou?rs=c&did=s14bp6ijzbuzx HTTP/1.1" 200 6522

Case 3
[22/Jun/2020:03:50:44 -0400] 210.195.5.82 - - "GET /s?did=goob70i07b491&lang=en_US HTTP/1.1" 200 13023
[22/Jun/2020:03:50:45 -0400] 210.195.5.82 - - "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169
[22/Jun/2020:03:50:45 -0400] 210.195.5.82 - 51467F89DAC4C14C5CDAF60AFB32531F "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870
[22/Jun/2020:03:50:46 -0400] 210.195.5.82 - - "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513
[22/Jun/2020:03:50:46 -0400] 210.195.5.82 - - "GET /css/v1_printing_press.css?v=20200505 HTTP/1.1" 200 7069
[22/Jun/2020:03:50:46 -0400] 210.195.5.82 - - "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173
[22/Jun/2020:03:50:47 -0400] 210.195.5.82 - - "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965
[22/Jun/2020:03:50:47 -0400] 210.195.5.82 - - "GET /js/namespaces.js HTTP/1.1" 200 609
[22/Jun/2020:03:50:48 -0400] 210.195.5.82 - - "GET /js/site.min.js?v=20200617 HTTP/1.1" 200 86789
[22/Jun/2020:03:50:49 -0400] 210.195.5.82 - - "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403
[22/Jun/2020:03:51:03 -0400] 210.195.5.82 - - "GET /img/ico/favicon.png HTTP/1.1" 200 3100
[22/Jun/2020:04:04:03 -0400] 210.195.5.82 - - "POST /s?did=goob70i07b491 HTTP/1.1" 302 223
[22/Jun/2020:04:04:03 -0400] 210.195.5.82 - 65836A3108CBE5EA0B1727AB5FC63DD3 "GET /s/thankyou?rs=c&did=goob70i07b491 HTTP/1.1" 200 5758

Case 4
[22/Jun/2020:06:18:21 -0400] 85.255.234.175 - - "GET /s?did=s14bp6ijzbuzx&lang=en_US HTTP/1.1" 200 9015
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /css/v1_cake_batter.css?v=20200505 HTTP/1.1" 200 7021
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /js/namespaces.js HTTP/1.1" 200 609
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /js/site.min.js?v=20200617 HTTP/1.1" 200 86789
[22/Jun/2020:06:18:22 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160
[22/Jun/2020:06:18:24 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /img/ico/favicon.png HTTP/1.1" 200 3100
[22/Jun/2020:06:20:46 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "POST /s?did=s14bp6ijzbuzx HTTP/1.1" 302 223
[22/Jun/2020:06:48:41 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "POST /s?did=s14bp6ijzbuzx HTTP/1.1" 302 223
[22/Jun/2020:06:48:41 -0400] 85.255.234.175 - 9D29CB2D408B82C39EEBBA9E8A13861E "GET /s?did=s14bp6ijzbuzx&page=1 HTTP/1.1" 200 9026

More info:
1) The above logs show complete traces of four visitors on the site. The first three cases show that a visitor completes the multi-page questionnaire. Case 4 shows that session ID didn't change, but the site code was unable to find the token stored in the session. Also in Case 4, the visitor abandoned in the middle of filling a questionnaire. The form has validation code and it is unable to move to the next page if validation fails or a visitor abandons.
2)  I have verified that the old session IDs were never used in any other site visits.
3) The lost of sessions and/or session data happen 99.999999% on the first page (which is true in all above cases). The form's page number starts at zero or null (equivalent to zero). I recall I saw the issue on other pages, but very rarely.










I can see the change in the sesison id. Do you have the headers though? We need to see if the session is lost because the lb does not propagate it or for some other reason.
@girionis

>>Do you have the headers though?

The logging pattern in my earlier post does not record any headers. As you know, there are a lot of request and response headers. Do you know what headers to track that can help? I can add them easily. Could you please share you thoughts about why headers affect sessions?

>>the lb does not propagate it or for some other reason.

What do you mean by "lb"? "propagate" ?

We need to see when the session is lost. So we are interested mainly in these two headers:

Set-Cookie (when tomcat responds)
Cookie (when the client sends the request)

What do you mean by "lb"? "propagate" ?
lb = load balancer. It might be possible that the cookie is lost in the load balancer.
This is the list of request and response headers. Could you please select the ones you think are helpful?
https://developer.mozilla.org/en-US/docs/Glossary/Request_header
https://developer.mozilla.org/en-US/docs/Glossary/Response_header

Regarding cookies, which cookie do you think we should track? JESSIONID via pattern "%{JSESSIONID}c"?
In the first three cases, I notice that the session ID changes after a redirect.
Is that always the case?  
Why is that redirect sent?
@rrz
>>Is that always the case?  
The session ID changes at POST and this applies to only a very few cases, which is the issue of this post about (lost sessions).
>>Why is that redirect sent?
After a submission is successful, the form redirects a visitor to the next page or show the thank you page if the form is completed.


the form redirects a visitor to the next page

If you  forward the request instead of redirecting, then does the  problem remain?
Could you please select the ones you think are helpful?

Set-Cookie (when tomcat responds)
Cookie (when the client sends the request)

Regarding cookies, which cookie do you think we should track? JESSIONID via pattern "%{JSESSIONID}c"?
It depends how many you set. Just to be on the safe side, track all.
@rrz

>>If you  forward the request instead of redirecting, then does the  problem remain?
Cannot do this test without re-coding. It is a production system. post-redirect is a proven pattern. 
@girionis, here is what I have for logging in server.xml:

        <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%t %a %u %S %{JSESSIONID}c &quot;%r&quot; %s %b %{Set-Cookie}o" />    

Here are three example cases of lost sessions:

Case 1
[22/Jun/2020:19:58:48 -0400] 183.171.97.209 - - - "GET /s?did=s14bp6iyvbuzx&lang=en_US HTTP/1.1" 200 9610 JSESSIONID=68063B1924E10E2F316F80B0BF84D5E1; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:58:48 GMT; Path=/,app_distribution_last_visit_s14bp6iyvbuzx=last-visit; Max-Age=3600; Expires=Tue, 23-Jun-2020 00:58:48 GMT
[22/Jun/2020:19:58:48 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[22/Jun/2020:19:58:48 -0400] 183.171.97.209 - 68063B1924E10E2F316F80B0BF84D5E1 68063B1924E10E2F316F80B0BF84D5E1 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[22/Jun/2020:19:58:49 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:19:58:49 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /cssv1_default.css?v=20200505 HTTP/1.1" 200 6917 -
[22/Jun/2020:19:58:49 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[22/Jun/2020:19:58:50 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[22/Jun/2020:19:58:50 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[22/Jun/2020:19:58:50 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[22/Jun/2020:19:58:50 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /js/app.min.js?v=20200617 HTTP/1.1" 200 86789 -
[22/Jun/2020:19:58:51 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[22/Jun/2020:19:58:53 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[22/Jun/2020:19:59:32 -0400] 183.171.97.209 - - 68063B1924E10E2F316F80B0BF84D5E1 "POST /s?did=s14bp6iyvbuzx HTTP/1.1" 302 223 JSESSIONID=994E4EB09CF37E83403B5E13F42985AF; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:59:32 GMT; Path=/,app_participated_campaigns2=etf5firdo54ja/80EEFBBDC69B12A8A0F26D5BCA37D644_etf5firdo54ja-etf5firv254ja/DF11B6030754D0AAB4CDE15786ABC899_etf5firv254ja-st7b0i1tfbrir/FFAB039BD250D763AC9635193993451C_st7b0i1tfbrir-etfbfirjdb4ja/E7D2804D2DC5334BB364909B1201AD73_etfbfirjdb4ja-kt4m7i1ihmpv0/EB120123BE9093038C5830FB469EE5C1_kt4m7i1ihmpv0-etfmfirz8m4ja/3CBB6FA233DF37A52A4B9437CBA3F219_etfmfirz8m4ja-37lb2i1drbv9o/470FA5F2D530AE73C6DB31432C38DAFB_37lb2i1drbv9o-cfp5our6z51ip/317FAA715E1F042CDB7C1609C3614D5B_cfp5our6z51ip-krpmzi10jmi7x/9C522FDB2D1923432E8ECE9E3CE18FDF_krpmzi10jmi7x-cfpmourlnm1ip/39611FE584B39CAB37845CB873D95404_cfpmourlnm1ip-kt457i1yn5pv0/5AE6CB2DBD3AADCDFE4B48996A7A7DEA_kt457i1yn5pv0-kt451idly5pd0/5D19CFEBDA0B8CFF59D0E4D36BB01D46_kt451idly5pd0-s9nmtudnimvuv/A4E00F81376F2779FF991F8A0C31F27C_s9nmtudnimvuv-cfpmou7p7m1ip/45B97CB5DE973E0CECBB72DAF9A51BED_cfpmou7p7m1ip-s9n5pudy15vuv/EA96628D573D48196F2B5709F095AE77_s9n5pudy15vuv-37lb2iviubv9o/1BB0A1907A678979AF93AC0C4DB718C6_37lb2iviubv9o-ctfbnu7rzb0f0/7597C1559048983A1AED2D89B7948BC6_ctfbnu7rzb0f0-s9nmpudv7mvuv/78C72C0DD65B6EFDEC693EE5660F01C6_s9nmpudv7mvuv-s9n5tud0f5vuv/13653B5DF1DFAEC5F11A96A5293CE7D8_s9n5tud0f5vuv-s84baunf0b1pp/44FF0F930513C343D88209EDA7468AF8_s84baunf0b1pp-s9n56uvfd5vuv/0F010CC18079EFED5072328008F1356E_s9n56uvfd5vuv-etfbfizp8b4ja/8BC25070B47252DF32D1948E84D8F22B_etfbfizp8b4ja-st750irzp5rir/AEE988B42BDE575F5E50CD87BC98375B_st750irzp5rir-ctfmjuzoom0f0/1C18D89FE7762453B69EC918E5AE893B_ctfmjuzoom0f0-st750irid5rir/1360A09C19D7CC96F4F007809FA25D60_st750irid5rir-kt4m7irvfmpv0/629ADA3E9FE93FB00339DACC27D3809D_kt4m7irvfmpv0-37lb2irr8bv9o/566D2DF73E3796935012160A12144AAF_37lb2irr8bv9o-krp5zirju5i7x/F9D23E0276E3D49AE28AE6EB3C1C4811_krp5zirju5i7x-kt4muiv61mpd0/793D111444D1D55DF096FF076F88937A_kt4muiv61mpd0-s9nmtuvt4mvuv/994E4EB09CF37E83403B5E13F42985AF_s9nmtuvt4mvuv; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:59:32 GMT,app_completed_distributions=cfl546pdu58d7-qldbu0pf0btjz-kxn5h681v5xnf-s6tm96810myxa-kxnbh68n8bxnf-c6tb268aubyf6-sfyby6hprb8rj-cfl5v6hyp58d7-wlama6hvdmu11-kxnbj68j0bxnf-s14mp69o9muzx-goom109lxm49a-w215o69yl5djv-goo510902549a-c6tm26996myf6-goo5709vj5491-sjtbl6f7lbdzj-w215o69hf5djv-wfobn6yv2bj9a-wpv5f64py5auv-s14mr6y9umuzp-cflmv6yu4m8d7-s145p6y0i5uzx-wfobn6yd4bj9a-kxn5h69105xnf-qld5u0ita5tjz-sfy5y6ith58rj-goob70i82b491-s14mr6ip7muzp-s14bp6iyvbuzx; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:59:32 GMT
[22/Jun/2020:19:59:33 -0400] 183.171.97.209 - 994E4EB09CF37E83403B5E13F42985AF 994E4EB09CF37E83403B5E13F42985AF "GET /s/thankyou?rs=c&did=s14bp6iyvbuzx HTTP/1.1" 200 6502 _app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:59:33 GMT; Path=/

Case 2
[22/Jun/2020:20:03:58 -0400] 180.217.158.211 - 9601063838F2FF398D9556126A227CA9 9601063838F2FF398D9556126A227CA9 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - 9601063838F2FF398D9556126A227CA9 9601063838F2FF398D9556126A227CA9 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - 9601063838F2FF398D9556126A227CA9 9601063838F2FF398D9556126A227CA9 "GET /cssv1_default.css?v=20200505 HTTP/1.1" 200 6917 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - 9601063838F2FF398D9556126A227CA9 9601063838F2FF398D9556126A227CA9 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /lib/bootstrap-datepicker-1.3.0/js/locales/bootstrap-datepicker.zh-TW.js HTTP/1.1" 200 891 -
[22/Jun/2020:20:03:59 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[22/Jun/2020:20:04:00 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /js/app.min.js?v=20200617 HTTP/1.1" 200 86789 -
[22/Jun/2020:20:04:01 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[22/Jun/2020:20:04:20 -0400] 180.217.158.211 - - 9601063838F2FF398D9556126A227CA9 "POST /s?did=wla5a6yi25u11 HTTP/1.1" 302 223 JSESSIONID=6F44FC2AA61531905216884A2E186888; Path=/; HttpOnly,_app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:20 GMT; Path=/,app_participated_campaigns2=kt4b7ir2abpv0/6F44FC2AA61531905216884A2E186888_kt4b7ir2abpv0; Max-Age=31536000; Expires=Wed, 23-Jun-2021 00:04:20 GMT
[22/Jun/2020:20:04:21 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=1 HTTP/1.1" 200 9756 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:21 GMT; Path=/
[22/Jun/2020:20:04:26 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=1 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:26 GMT; Path=/
[22/Jun/2020:20:04:26 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=3 HTTP/1.1" 200 9809 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:26 GMT; Path=/
[22/Jun/2020:20:04:32 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=3 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:32 GMT; Path=/
[22/Jun/2020:20:04:32 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=5 HTTP/1.1" 200 9776 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:32 GMT; Path=/
[22/Jun/2020:20:04:35 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=5 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:35 GMT; Path=/
[22/Jun/2020:20:04:36 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=7 HTTP/1.1" 200 9804 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:36 GMT; Path=/
[22/Jun/2020:20:04:40 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=7 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:40 GMT; Path=/
[22/Jun/2020:20:04:40 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=9 HTTP/1.1" 200 9907 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:40 GMT; Path=/
[22/Jun/2020:20:04:46 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=9 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:46 GMT; Path=/
[22/Jun/2020:20:04:46 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=12 HTTP/1.1" 200 9936 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:46 GMT; Path=/
[22/Jun/2020:20:04:56 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=12 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:55 GMT; Path=/
[22/Jun/2020:20:04:56 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s?did=wla5a6yi25u11&page=13 HTTP/1.1" 200 9945 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:04:56 GMT; Path=/
[22/Jun/2020:20:05:04 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "POST /s?did=wla5a6yi25u11&page=13 HTTP/1.1" 302 223 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:05:03 GMT; Path=/,app_completed_distributions=wla5a6yi25u11; Max-Age=31536000; Expires=Wed, 23-Jun-2021 00:05:04 GMT
[22/Jun/2020:20:05:04 -0400] 180.217.158.211 - 6F44FC2AA61531905216884A2E186888 6F44FC2AA61531905216884A2E186888 "GET /s/thankyou?rs=c&did=wla5a6yi25u11 HTTP/1.1" 200 6420 _app_site_lang=zh_TW; Max-Age=2592000; Expires=Thu, 23-Jul-2020 00:05:04 GMT; Path=/

Case 3
[22/Jun/2020:19:53:03 -0400] 175.140.22.123 - - - "GET /s?did=s6t506jno5yoa&lang=en_US HTTP/1.1" 200 9779 JSESSIONID=D9EA35B504ECF9C98504C8A5B8B6C6E4; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:53:03 GMT; Path=/,app_distribution_last_visit_s6t506jno5yoa=last-visit; Max-Age=3600; Expires=Tue, 23-Jun-2020 00:53:03 GMT
[22/Jun/2020:19:53:04 -0400] 175.140.22.123 - D9EA35B504ECF9C98504C8A5B8B6C6E4 D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[22/Jun/2020:19:53:04 -0400] 175.140.22.123 - D9EA35B504ECF9C98504C8A5B8B6C6E4 D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - D9EA35B504ECF9C98504C8A5B8B6C6E4 D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /cssv1_default.css?v=20200505 HTTP/1.1" 200 6917 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - D9EA35B504ECF9C98504C8A5B8B6C6E4 D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /js/app.min.js?v=20200617 HTTP/1.1" 200 86789 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /s/logo?did=s6t506jno5yoa&sid=&v=275 HTTP/1.1" 200 37224 JSESSIONID=CFBF156D09254C0B6F1BF2C93DA97BE9; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:53:05 GMT; Path=/
[22/Jun/2020:19:53:08 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[22/Jun/2020:19:53:14 -0400] 175.140.22.123 - CFBF156D09254C0B6F1BF2C93DA97BE9 CFBF156D09254C0B6F1BF2C93DA97BE9 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[22/Jun/2020:19:53:40 -0400] 175.140.22.123 - CFBF156D09254C0B6F1BF2C93DA97BE9 CFBF156D09254C0B6F1BF2C93DA97BE9 "POST /s?did=s6t506jno5yoa HTTP/1.1" 302 223 _app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:53:39 GMT; Path=/,app_participated_campaigns2=cfp5ouzz851ip/CFBF156D09254C0B6F1BF2C93DA97BE9_cfp5ouzz851ip; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:53:40 GMT,app_completed_distributions=s6t506jno5yoa; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:53:40 GMT
[22/Jun/2020:19:53:40 -0400] 175.140.22.123 - CFBF156D09254C0B6F1BF2C93DA97BE9 CFBF156D09254C0B6F1BF2C93DA97BE9 "GET /s/thankyou?rs=c&did=s6t506jno5yoa HTTP/1.1" 200 6713 _app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:53:40 GMT; Path=/

A few things:
1) In all three cases, the visitor completed all pages of a questionnaire
2) Case 3 is interesting because the session ID changed when  the site was serving a logo (some questionnaires may have a logo). This means that the session id changed before POST, which may applies to all the cases of lost sessions, but I am not sure. Spring MVC allows direct access to js, css, images, etc. without going thorough a controller. Here is the set up in the site:

   <mvc:resources mapping="/js/**" location="/js/" />      
   <mvc:resources mapping="/css/**" location="/css/" />      
   <mvc:resources mapping="/img/**" location="/img/" />      
   <mvc:resources mapping="/lib/**" location="/lib/" />

If there is a way to force all requests of js, css, and image to show JSESSIONID (sent to the client) in each log entry, it would be great. Can I force Tomcat to do this?

3) I have a question: why Tomcat shows two session (same) IDs when retrieving a CSS file, but one session ID for another one. See this in Case 3:

[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - D9EA35B504ECF9C98504C8A5B8B6C6E4 D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -






Case three hints us that the browser might not be sending the cookie. Have you noticed this behaviour on all browsers? It is possible that the browser randomly ignores the cookie on 302 and 200.

Can you also make sure that when you redirect, you redirect to the same host, protocol and context? If you're using "localhost" anywhere, can yo replace it with 127.0.0.1?

I know that you said this is a production system, but can you try some code changes and if possible try to redirect to some relative paths and see if it helps?
@girionis

>>Case three hints us that the browser might not be sending the cookie. Have you noticed this behaviour on all browsers?

Regarding the browser, requests come from the internet. the site doesn't record this browser info at this moment. I doubt that the browser is causing the issue, but I am not sure.

>>It is possible that the browser randomly ignores the cookie on 302 and 200.

Not sure whether this is true. Take this as example:

[22/Jun/2020:19:53:05 -0400] 175.140.22.123 - - D9EA35B504ECF9C98504C8A5B8B6C6E4 "GET /s/logo?did=s6t506jno5yoa&sid=&v=275 HTTP/1.1" 200 37224 JSESSIONID=CFBF156D09254C0B6F1BF2C93DA97BE9; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:53:05 GMT; Path=/

Even though, "%s" in "%S %{JSESSIONID}c" doesn't show the session ID, but "%{JSESSIONID}c" does hold the same session ID.

>>Can you also make sure that when you redirect, you redirect to the same host, protocol and context? If you're using "localhost" anywhere, can yo replace it with 127.0.0.1?
>>I know that you said this is a production system, but can you try some code changes and if possible try to redirect to some relative paths and see if it helps?

All cases came from internet users, not from my test environment. None of them was from my test environment. Besides, in my local non-clustering setup, I always use 127.0.0.1 and am not able to see this issue (possibly because it happens seldom). Redirect is always relative without host or protocol in urls (I coded the site). The context is blank because the site is placed in ROOT under webapps in Tomcat.








@girionis

I looked at a few normal cases in which no session was lost. It seems that their access logs show consistent logging of both values in "%S %{JSESSIONID}c" regarding access to js, css, png, and other library files. Here are two example cases. I looked at a few more normal cases, and it seems they show the same pattern (note that I can't examine each one). Thought?

Case 1
[22/Jun/2020:19:40:02 -0400] 67.247.35.41 - - - "GET /s?did=s0t560jd85yoa&lang=en_US HTTP/1.1" 200 11160 JSESSIONID=1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5; Path=/; HttpOnly,_app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:40:02 GMT; Path=/,app_distribution_last_visit_s0t560jd85yoa=last-visit; Max-Age=3600; Expires=Tue, 23-Jun-2020 00:40:02 GMT
[22/Jun/2020:19:40:02 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /css/v1_default.css?v=20200505 HTTP/1.1" 200 6917 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /js/app.min.js?v=20200617 HTTP/1.1" 200 86789 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[22/Jun/2020:19:40:03 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[22/Jun/2020:19:40:04 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[22/Jun/2020:19:42:15 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "POST /s?did=s0t560jd85yoa HTTP/1.1" 302 223 _app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:42:15 GMT; Path=/,app_participated_campaigns2=cfpbouzt6b1ip/1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5_cfpbouzt6b1ip; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:42:15 GMT,app_completed_distributions=s0t560jd85yoa; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:42:15 GMT
[22/Jun/2020:19:42:15 -0400] 67.247.35.41 - 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 1B29EAFFF9E9ACA7D6FC1B8DCFECDBA5 "GET /s/thankyou?rs=c&did=s0t560jd85yoa HTTP/1.1" 200 6504 _app_site_lang=en_US; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:42:15 GMT; Path=/

Case 2
[22/Jun/2020:19:14:57 -0400] 181.117.15.200 - - - "GET /s?did=w215o6j425djv&lang=es_MX HTTP/1.1" 200 9169 JSESSIONID=9ED21ABCB5DB8AB5F07C0115CB2C9427; Path=/; HttpOnly,_app_site_lang=es_MX; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:14:57 GMT; Path=/,app_distribution_last_visit_w215o6j425djv=last-visit; Max-Age=3600; Expires=Tue, 23-Jun-2020 00:14:57 GMT
[22/Jun/2020:19:14:58 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[22/Jun/2020:19:14:58 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[22/Jun/2020:19:14:58 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /css/tools.css?v=20190511 HTTP/1.1" 200 8513 -
[22/Jun/2020:19:14:58 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /css/v1_default.css?v=20200505 HTTP/1.1" 200 6917 -
[22/Jun/2020:19:14:58 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[22/Jun/2020:19:14:59 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[22/Jun/2020:19:14:59 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[22/Jun/2020:19:14:59 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /js/app.min.js?v=20200617 HTTP/1.1" 200 86789 -
[22/Jun/2020:19:15:00 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[22/Jun/2020:19:15:00 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[22/Jun/2020:19:15:27 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[22/Jun/2020:19:18:46 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "POST /s?did=w215o6j425djv HTTP/1.1" 302 223 _app_site_lang=es_MX; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:18:46 GMT; Path=/,app_participated_campaigns2=erpbiy7ltbxod/9ED21ABCB5DB8AB5F07C0115CB2C9427_erpbiy7ltbxod; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:18:46 GMT,app_completed_distributions=w215o6j425djv; Max-Age=31536000; Expires=Tue, 22-Jun-2021 23:18:46 GMT
[22/Jun/2020:19:18:46 -0400] 181.117.15.200 - 9ED21ABCB5DB8AB5F07C0115CB2C9427 9ED21ABCB5DB8AB5F07C0115CB2C9427 "GET /s/thankyou?rs=c&did=w215o6j425djv HTTP/1.1" 200 6831 _app_site_lang=es_MX; Max-Age=2592000; Expires=Wed, 22-Jul-2020 23:18:46 GMT; Path=/



>>It is possible that the browser randomly ignores the cookie on 302 and 200.

Not sure whether this is true.
Well, if you get a new session this means that the old session is indeed lost (i.e. the cookie is not sent either from browser or from the load balancer).

The logs you have do not show all headers properly. When I said you must log all incoming/outgoing headers I meant something like the following (taken from out system):

---> POST https://<omitted> HTTP/1.1
Accept: application/json
Authorization: Basic <omitted>
Content-Length: 82
Content-Type: application/x-www-form-urlencoded
<body of the POST request omitted>
---> END HTTP (82-byte body)
<--- HTTP/1.1 200  (10ms)
cache-control: no-store
content-length: 1061
content-type: application/json
date: <omitted>
pragma: no-cache
server: <omitted>
x-content-type-options: nosniff
x-frame-options: DENY
x-xss-protection: 1; mode=block
<body of the response omitted>
<--- END HTTP (1061-byte body)

Open in new window

You can see all request/response headers above (no cookie in this example since our app is stateless).

Maybe you can use a RequestDumperValve (or RequestDumperFilter, depending on the version of your Tomcat) to achieve this.
Hello girionis,

Sorry for not posting anything in the past two weeks.My site uses Tomcat 8.4.54 and so I used RequestDumperFilter. It is interesting to notice that after adding RequestDumperFilter, the log files often do not show complete traces. I did many tests in an attempt to capture a case with complete traces. Here is the one. Here is how the process happened:

1. A brand-new visitor came to the site to take a survey. A session was created with ID: 17E214C2578A49DF47FAC8971131FF61
2. The site displayed the page (and stored the above session ID in a survey form of questions) and then a few Javascript or CSS files were retrieved
3. The visitor submitted the survey form and the controller took user input and printed the session ID stored in the form and the current session ID: EE017B40A784407AC504C973DDA93846 (this value was used in a site-created cookie named participated_campaigns2) . Then the controller invalidated the page and redirected the visitor to the thank you page. Thus there is a new session ID: 4C24B4D2D6A1D96987B4FFD29AABB195

Here is the localhost_access_log.txt to show the process:
[08/Jul/2020:15:38:14 -0400] 181.189.177.45 - - - "GET /s?did=goom10if0m49a&lang=es_MX HTTP/1.1" 200 12274 JSESSIONID=17E214C2578A49DF47FAC8971131FF61; Path=/; HttpOnly,site_lang=es_MX; Max-Age=2592000; Expires=Fri, 07-Aug-2020 19:38:13 GMT; Path=/,distribution_last_visit_goom10if0m49a=last-visit; Max-Age=3600; Expires=Wed, 08-Jul-2020 20:38:13 GMT
[08/Jul/2020:15:38:22 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /css/survey-tools.css?v=20190511 HTTP/1.1" 200 8513 -
[08/Jul/2020:15:38:22 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /css/survey/v1_default.css?v=20200505 HTTP/1.1" 200 6975 -
[08/Jul/2020:15:38:24 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /js/site.min.js?v=202006707 HTTP/1.1" 200 86811 -
[08/Jul/2020:15:38:25 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[08/Jul/2020:15:38:36 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[08/Jul/2020:15:38:44 -0400] 181.189.177.45 - 17E214C2578A49DF47FAC8971131FF61 17E214C2578A49DF47FAC8971131FF61 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[08/Jul/2020:15:48:10 -0400] 181.189.177.45 - - - "POST /s?did=goom10if0m49a HTTP/1.1" 302 223 JSESSIONID=4C24B4D2D6A1D96987B4FFD29AABB195; Path=/; HttpOnly,site_lang=es_MX; Max-Age=2592000; Expires=Fri, 07-Aug-2020 19:48:09 GMT; Path=/,participated_campaigns2=s9nbpujllbvuv/EE017B40A784407AC504C973DDA93846_s9nbpujllbvuv; Max-Age=31536000; Expires=Thu, 08-Jul-2021 19:48:10 GMT,completed_distributions=goom10if0m49a; Max-Age=31536000; Expires=Thu, 08-Jul-2021 19:48:10 GMT
[08/Jul/2020:15:48:10 -0400] 181.189.177.45 - 4C24B4D2D6A1D96987B4FFD29AABB195 4C24B4D2D6A1D96987B4FFD29AABB195 "GET /s/thankyou?rs=c&did=goom10if0m49a HTTP/1.1" 200 6823 site_lang=es_MX; Max-Age=2592000; Expires=Fri, 07-Aug-2020 19:48:10 GMT; Path=/

The logs generated by RequestDumperFilter is a long and is attached to the original post. The file name is RequestDumperFilter-catalina-20200709.txt. I also attached the above trace logs in a file called log-access-20200709.txt.

Please feel free to ask any questions.


I know you addressed your last post to girionis. But, since it has been three days with no comment, I will add my comment.    
The following is my summary of the process in    
https://filedb.experts-exchange.com/incoming/2020/07_w28/1476098/RequestDumperFilter-catalina-2020070.txt   
the client's request is received      
08-Jul-2020 15:38:13.667  http-nio-80-exec-10  requestURI=/s    
the web app sends a session cookie in the response    
08-Jul-2020 15:38:14.263  http-nio-80-exec-10 header=Set-Cookie=JSESSIONID=17E214C2578A49DF47FAC8971131FF61; Path=/; HttpOnly    
the client send requests for css, js, font, favicon and files. In each of those requests it send the session cookie    
cookie=JSESSIONID=17E214C2578A49DF47FAC8971131FF61  
and the web app recognizes the session Id in each one of those requests    
requestedSessionId=17E214C2578A49DF47FAC8971131FF61  
after filling out the form, the client sends a request
08-Jul-2020 15:48:09.425  http-nio-80-exec-17 requestURI=/s  
08-Jul-2020 15:48:09.425  http-nio-80-exec-17 contentType=application/x-www-form-urlencoded  
no session cookie sent at 08-Jul-2020 15:48:09.425
that omission is confirmed with
08-Jul-2020 15:48:09.487  http-nio-80-exec-17 requestedSessionId=null
the web app sends a response that includes  
08-Jul-2020 15:48:10.081  http-nio-80-exec-17 header=Set-Cookie=JSESSIONID=4C24B4D2D6A1D96987B4FFD29AABB195; Path=/; HttpOnly  
and redirects
08-Jul-2020 15:48:10.097  http-nio-80-exec-17 status=302
the client sends request following the redirection
08-Jul-2020 15:48:10.425  http-nio-80-exec-12  requestURI=/s/thankyou  
that includes session cookie  
08-Jul-2020 15:48:10.440  http-nio-80-exec-12 cookie=JSESSIONID=4C24B4D2D6A1D96987B4FFD29AABB195  
the web app sends a response without a session cookie.  

Last month, I was wrong at  my post.  
The session was lost when the client made his request(that submitted the form) and did not send the session cookie.
This was before the redirection.  
It  seems that  girionis' initial  suspicion was correct.
You posted
3. The visitor submitted the survey form and the controller took user input and printed the session ID stored in the form and the current session ID: EE017B40A784407AC504C973DDA93846 (this value was used in a site-created cookie named participated_campaigns2) . Then the controller invalidated the page and redirected the visitor to the thank you page. Thus there is a new session ID: 4C24B4D2D6A1D96987B4FFD29AABB195
My questions for you.
Why did you put the session Id in a form field?  
Why do you think that ID: EE017B40A784407AC504C973DDA93846 is the current session Id?
As rrz already pointed out, you can see that at 08-Jul-2020 15:48:09, when the user requested the url /s, the previous cookie 17E214C2578A49DF47FAC8971131FF61 is not sent to the server, therefore the server does not know that this is an existing session and responds with a new cookie (a new session) 4C24B4D2D6A1D96987B4FFD29AABB195.

Now that we established that the cookie is not sent to your server, we need to see where exactly this happens. There are two possible paths here:

1) The browser does not send the cookie at all (it can happen)
2) The browser does send the cookie, but the load balancer (lb) ignores it.

What you can do:

1) This is not hard, but it requires time. You already have the logs, so you need to monitor them for similar cases and see if you can spot a pattern. In this example I can see that the user is using Mozilla/5.0 (the user-agent header). You have to see if this happens with other browsers as well. If not, then it is a problem related to a specific browser/version.
2) You have to add similar logs to your lb. Your lb needs to log all incoming headers (all headers that come to it from the browser) and all outgoing headers (all headers it sends to your server). Then you compare them and see if the cookie header is in the incoming but not in the outgoing headers.
Thanks to you two for your response.

Answer to @rrz's question:
>>Why did you put the session Id in a form field?  
I would like to know whether the session form changes at form posts. This is the only way from a Java controller if not using Tomcat logs.

>>Why do you think that ID: EE017B40A784407AC504C973DDA93846 is the current session Id?
Because at post, the controller prints the stored session ID sent from the form as well as the current session ID. See the following code example:

String hsid = request.getParameter("hsid");
String currentSessionID = request.getSession().getId() ;  (the value is: EE017B40A784407AC504C973DDA93846)

Note that 4C24B4D2D6A1D96987B4FFD29AABB195  is the session ID that the post controller generated through request.getSession().getId() AFTER performing request.getSession().invalidate(). A successful post redirects the visitor to the /s/thankyou page. The /s/thankyou continues it (4C24B4D2D6A1D96987B4FFD29AABB195), which you can see in the logs.

To @girionis,

>>As rrz already pointed out, you can see that at 08-Jul-2020 15:48:09, when the user requested the url /s, the previous cookie 17E214C2578A49DF47FAC8971131FF61 is not sent to the server, therefore the server does not know that this is an existing session and responds with a new cookie (a new session) 4C24B4D2D6A1D96987B4FFD29AABB195.
This is not correct. The current session ID at the form's post request is EE017B40A784407AC504C973DDA93846. See my explanation of this value in my earlier post.

Your thoughts about the browser and lb logs seem to be the direction. I will see what I can do.

 
This is not correct. The current session ID at the form's post request is EE017B40A784407AC504C973DDA93846
I  don't  agree.  We never see  that ID set as  JSESSIONID in a cookie that is sent or returned to the server .  
You are saying that there were three session IDs.  But, in the cookies in the dump we only see two.  
I  can't explain that discrepancy.
This is not correct. The current session ID at the form's post request is EE017B40A784407AC504C973DDA93846. See my explanation of this value in my earlier post.

You set several cookies. The one that corresponds to the JSESSIONID is the 4C24B4D2D6A1D96987B4FFD29AABB195.
>>I  don't  agree.  We never see  that ID set as  JSESSIONID in a cookie that is sent or returned to the server .  
You are saying that there were three session IDs.  But, in the cookies in the dump we only see two.  
I  can't explain that discrepancy.
>>You set several cookies. The one that corresponds to the JSESSIONID is the 4C24B4D2D6A1D96987B4FFD29AABB195.

The post controller saw a new session id when doing request.getSession().getId() (EE017B40A784407AC504C973DDA93846 which is used for the cookie participated_campaigns2 by my program). For a successful post, the post controller invalidates the current session (which destroys EE017B40A784407AC504C973DDA93846 and generates a new session with the session ID being 4C24B4D2D6A1D96987B4FFD29AABB195 )  and redirect the visitor to the /s/thankyou page, which is why "The one that corresponds to the JSESSIONID is the 4C24B4D2D6A1D96987B4FFD29AABB195 "
Ok that explains the three  Session IDs.
To make it less confusing, I have removed the request.getSession().invalidate() when a form post is successful. You can only see only TWO session IDs. Here I also provided a good case that had no issue (one session ID). You may be able to see how they are different.

Bad case (two session IDs)

[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - - "GET /s?did=s6t506f2r5yoa&lang=en_US&fbclid=IwAR3WgX0VlwhiJUDlAGmz4IaKZsxf3afvNZSidIftoexRFzOjjd3mvuCbxSM HTTP/1.1" 200 8763 JSESSIONID=2041725920DA9C4BCA594B9FF414E365; Path=/; HttpOnly,site_lang=en_US; Max-Age=2592000; Expires=Fri, 14-Aug-2020 19:57:36 GMT; Path=/,distribution_last_visit_s6t506f2r5yoa=last-visit; Max-Age=3600; Expires=Wed, 15-Jul-2020 20:57:36 GMT
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - 2041725920DA9C4BCA594B9FF414E365 2041725920DA9C4BCA594B9FF414E365 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /css/survey-tools.css?v=20190511 HTTP/1.1" 200 8513 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /css/survey/v1_default.css?v=20200505 HTTP/1.1" 200 6975 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /js/site.min.js?v=202006707 HTTP/1.1" 200 86811 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[15/Jul/2020:15:57:36 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "GET /img/ico/favicon.png HTTP/1.1" 200 3100 -
[15/Jul/2020:15:57:43 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "POST /s?did=s6t506f2r5yoa HTTP/1.1" 302 223 JSESSIONID=CCAA0BEF6A726070256E39791A6146A8; Path=/; HttpOnly,site_lang=en_US; Max-Age=2592000; Expires=Fri, 14-Aug-2020 19:57:43 GMT; Path=/,participated_campaigns2=stnbviz2vbrir/CCAA0BEF6A726070256E39791A6146A8_stnbviz2vbrir; Max-Age=31536000; Expires=Thu, 15-Jul-2021 19:57:43 GMT,completed_distributions=s6t506f2r5yoa; Max-Age=31536000; Expires=Thu, 15-Jul-2021 19:57:43 GMT
[15/Jul/2020:15:57:43 -0400] 99.152.33.7 - CCAA0BEF6A726070256E39791A6146A8 CCAA0BEF6A726070256E39791A6146A8 "GET /s/thankyou?rs=c&did=s6t506f2r5yoa HTTP/1.1" 200 6488 site_lang=en_US; Max-Age=2592000; Expires=Fri, 14-Aug-2020 19:57:43 GMT; Path=/

Good case (one session ID)

[15/Jul/2020:23:55:08 -0400] 112.134.239.185 - - - "GET /s?did=s145p64u15uzx&lang=en_US HTTP/1.1" 200 14361 JSESSIONID=2B4853A8D16EBD75E0852631CB3D5EF1; Path=/; HttpOnly,site_lang=en_US; Max-Age=2592000; Expires=Sat, 15-Aug-2020 03:55:08 GMT; Path=/,distribution_last_visit_s145p64u15uzx=last-visit; Max-Age=3600; Expires=Thu, 16-Jul-2020 04:55:08 GMT
[15/Jul/2020:23:55:09 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /css/survey/v1_default.css?v=20200505 HTTP/1.1" 200 6975 -
[15/Jul/2020:23:55:09 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /lib/modernizr-2.6.2/modernizr-2.6.2-respond-1.1.0.min.js HTTP/1.1" 200 8173 -
[15/Jul/2020:23:55:09 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /lib/bootstrap-3.2.0/dist/css/bootstrap.min.css HTTP/1.1" 200 18870 -
[15/Jul/2020:23:55:09 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /css/survey-tools.css?v=20190511 HTTP/1.1" 200 8513 -
[15/Jul/2020:23:55:09 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /lib/font-awesome-4.7.0/css/font-awesome.min.css HTTP/1.1" 200 7169 -
[15/Jul/2020:23:55:10 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /lib/bootstrap-3.2.0/dist/js/bootstrap.min.js HTTP/1.1" 200 8965 -
[15/Jul/2020:23:55:10 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /js/namespaces.js HTTP/1.1" 200 609 -
[15/Jul/2020:23:55:10 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /js/site.min.js?v=202006706 HTTP/1.1" 200 86778 -
[15/Jul/2020:23:55:10 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /lib/font-awesome-4.7.0/fonts/fontawesome-webfont.woff2?v=4.7.0 HTTP/1.1" 200 77160 -
[15/Jul/2020:23:55:10 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /js/site-tools.js?v=20190716 HTTP/1.1" 200 419403 -
[15/Jul/2020:23:56:17 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "POST /s?did=s145p64u15uzx HTTP/1.1" 302 223 site_lang=en_US; Max-Age=2592000; Expires=Sat, 15-Aug-2020 03:56:16 GMT; Path=/,participated_campaigns2=etfmfiol0m4ja/2B4853A8D16EBD75E0852631CB3D5EF1_etfmfiol0m4ja; Max-Age=31536000; Expires=Fri, 16-Jul-2021 03:56:17 GMT,completed_distributions=s145p64u15uzx; Max-Age=31536000; Expires=Fri, 16-Jul-2021 03:56:17 GMT
[15/Jul/2020:23:56:17 -0400] 112.134.239.185 - 2B4853A8D16EBD75E0852631CB3D5EF1 2B4853A8D16EBD75E0852631CB3D5EF1 "GET /s/thankyou?rs=c&did=s145p64u15uzx HTTP/1.1" 200 6487 site_lang=en_US; Max-Age=2592000; Expires=Sat, 15-Aug-2020 03:56:17 GMT; Path=/




I assume that your last post showed us excerpts from your Tomcat's  log-access file.
Could you please post the pattern attribute in your  AccessLogValve in your Tomcat's server.xml file?  
I don't see it  in the server.xml file that you posted at the top of this question.
For example, my entry in my Tomcat's server.xml file is
        <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%h %l %u %t %S &quot;%r&quot; %s %b" />

Open in new window

 
If we knew the pattern attribute, then we could interpret the log better.
The reason I ask is  due to the following  that I copied from  your last post under  the "Bad case (two session IDs)" heading.
[15/Jul/2020:15:57:43 -0400] 99.152.33.7 - - 2041725920DA9C4BCA594B9FF414E365 "POST /s?did=s6t506f2r5yoa
If I am reading that correctly, then it looks like the session cookie(JSESSIONID) was returned with that POST request.
If I am reading that correctly. then please tell us what is bad in that case?
Here is what I have for logging in server.xml (posted in one of the earlier resposnes):

        <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%t %a %u %S %{JSESSIONID}c &quot;%r&quot; %s %b %{Set-Cookie}o" />    

In the good case, session ID (2B4853A8D16EBD75E0852631CB3D5EF1) is present in each request and post request for "%S %{JSESSIONID}c", which is not true in the bad case.  In the bad case, "%{JSESSIONID}c" is there for all requests, but "%S" is missing for most requests, including the POST request (you can see two dashes "- - " after date/time and IP address in each line).

This observation conflicts with the suggestion from @girionis that the load balancer doesn't send session info (which is JSESSIONID) to the site because %{JSESSIONID}c existed for each request (page, js, css, etc.). So, the load balancer does did the JSESSIONID to the site for each request, but the site somehow wanted to start a new session. Is this right?
In the bad case, "%{JSESSIONID}c" is there for all requests, but "%S" is missing for most requests
I can't explain that.   It would seem that the session cookie is returned but the  user doesn't have a valid  session.  It is a mystery to me.  
Also, it is  strange that  the session cookie has  Expires set to a month. A session cookie  normally is deleted when the browser closes. That is  accomplished  by not setting  a Expires value.      
I suspect Spring, but I don't use Spring, so I can't help you there.
but the site somehow wanted to start a new session. Is this right?

It would seem so.  
This observation conflicts with the suggestion from @girionis that the load balancer doesn't send session info
 
We  said that  about the case you had in the  requestdumpfilter log
Hi All,

I am facing similar issue, in my application tomcat 8.5.51 is dropping/changing jsessionid intermittently, I do see the jsessionid passed in request header in fiddler log but still new jsessionid is introduced in the response header. Any idea why would that be? Is tomcat is not able to read the original jsessionid from request header and adding new jsessionid in response or something else? Any help in this matter will be appreciated.
This question needs an answer!
Become an EE member today
7 DAY FREE TRIAL
Members can start a 7-Day Free trial then enjoy unlimited access to the platform.
View membership options
or
Learn why we charge membership fees
We get it - no one likes a content blocker. Take one extra minute and find out why we block content.