Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-1225

Occasional session loss after 500/503 status

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 7.0.0.ER2 (Beta)
    • 7.0.0.DR9
    • Clustering
    • None

    Description

      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/

      Attachments

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. WFLY-5465 Occasional session loss after 500/503 status

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Bug - A problem that impairs or prevents the functions of the product. WFLY-5158 WARN ISPN000197: Error updating cluster member list at the boot up

          • Minor - To be worked after urgent, high, and medium priorities are resolved. This term is chosen when the severity of the issue is low, or the complexity or effort to correct it may be higher, relatively speaking. For low priority issues, known workarounds exist or are not needed due to the trivial effort needed to address the issue.
          • Closed

          Activity

            People

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

              Dates

                Created:
                Updated:
                Resolved: