Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-5465

Occasional session loss after 500/503 status

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Major Major
    • None
    • None
    • Clustering
    • None

      Hi,

      we're occasionally seeing session being lost after an HTTP error status code (500/503). In other words, our test output looks like this:

      ...
      2015/08/29 00:06:26:966 EDT [WARN ][Runner - 1549] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>>
      2015/08/29 00:06:26:966 EDT [WARN ][Runner - 1549] SFCORE_LOG - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>>
      ...
      ... ~4 seconds later (meanwhile, other runners send their requests) ...
      ...
      2015/08/29 00:06:31:050 EDT [WARN ][Runner - 1549] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Stale session data received. Expected 78, received 0, Runner: 1549>
      2015/08/29 00:06:31:050 EDT [WARN ][Runner - 1549] SFCORE_LOG - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Stale session data received. Expected 78, received 0, Runner: 1549>
      ...
      

      The session loss is not consistent - the runner from the example has caught a 500 about ~10 times before and has had many successful requests between those error status codes.
      How it usually works (good scenario):

      • GET --> 55, GET --> 56, GET --> 57, GET --> ERROR 500, GET --> 58, ...
        How it occasionally works (bad scenario):
      • GET --> 55, GET --> 56, GET --> 57, GET --> ERROR 500, GET --> 0, ...

      When runner 1549 received a new session, the following output occurs on server side (perf19 - the server to which runner 1549 is then being directed):

      [JBossINF] �[0m�[31m00:06:26,962 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-55) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,962 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-86) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,963 ERROR [io.undertow.request] (default task-55) UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,963 ERROR [io.undertow.request] (default task-86) UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,964 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-39) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,965 ERROR [io.undertow.request] (default task-39) UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf18
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,965 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-27) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf21
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[31m00:06:26,965 ERROR [io.undertow.request] (default task-27) UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: Replication timeout for perf21
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:755)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$80(JGroupsTransport.java:602)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$34/1387701636.apply(Unknown Source)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
      [JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
      [JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1954)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:47)
      [JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      [JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      [JBossINF] 
      [JBossINF] �[0m�[0m00:06:31,045 INFO  [org.jboss.test.clusterbench.common.session.CommonHttpSessionServlet] (default task-90) New session created: iBowQB5GzE3tckL7V-5kzxBW4uvB6L9Ht0izC0PK
      

      This is similar to https://bugzilla.redhat.com/show_bug.cgi?id=901164 except we're seeing it with more scenarios (see the names of jobs below).

      Some jobs where this problem can be seen:
      https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-ejb-ejbservlet-shutdown-repl-async/8/
      https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-ejb-ejbservlet-undeploy-dist-sync/6/
      https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-ejb-ejbservlet-undeploy-repl-async-haproxy/6/
      https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-http-session-jvmkill-repl-async/6/ <-- examples are taken from here
      https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-http-session-undeploy-dist-sync/6/

              pferraro@redhat.com Paul Ferraro
              rjanik@redhat.com Richard Janik
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: