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

(7.2.z) EJB-314/EJB-317 - Legacy EJB Client: High communication fail rate during failover

    XMLWordPrintable

Details

    Description

      This bug is being filed as Blocker because we are observing and elevated fail rate: roughly a thousand each run for (about 0.3%).
      It is observed when hitting a 4 nodes cluster using a client legacy EJB Client (version 3); fail-over is introduced by means of clean shut down.

      7.2.0.GA.CR1

      With version 7.2.0.GA.CR1 (server jboss-eap-7.2.0.GA.CR1.zip, client org.jboss:jboss-ejb-client-legacy:3.0.2.Final-redhat-1) in a scenario with 4 clustered nodes where nodes are failed via jboss shut-down / restart: after node 3 of 4 is shut-down, a a series of errors start on the client side the yield to 1282 errors on a total of 341408 samples;

      find here the complete logs;

      the start of client errors is here:

      2018/11/06 11:12:27:263 EST [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Failing node 2 (perf20)
11:12:29,078 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-1) EJBCLIENT000016: Channel Channel ID fb008f94 (outbound) of Remoting connection 2a00ed12 to /10.16.90.58:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61> can no longer process messages
11:12:29,114 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-4) EJBCLIENT000016: Channel Channel ID 8f12f2ec (outbound) of Remoting connection 13f3f7a6 to /10.16.90.72:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61> can no longer process messages
11:12:29,132 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-4) EJBCLIENT000017: Received server version 3 and marshalling strategies [river]
11:12:29,132 INFO  [org.jboss.ejb.client.remoting] (ejb-client-context-tasks-1-thread-22) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@79a74a25, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@17bd8cb2,channel=jboss.ejb,nodename=perf21]} on channel Channel ID f6f6b0ba (outbound) of Remoting connection 13f3f7a6 to /10.16.90.72:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61>
11:12:29,164 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-3) EJBCLIENT000016: Channel Channel ID f6f6b0ba (outbound) of Remoting connection 13f3f7a6 to /10.16.90.72:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61> can no longer process messages
2018/11/06 11:12:29:180 EST [ERROR][Runner - 1922] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <java.lang.IllegalStateException: EJBCLIENT000032: Cannot retry a request which hasn't previously been completed>
        
2018/11/06 11:12:29:180 EST [ERROR][Runner - 494] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <java.lang.IllegalStateException: EJBCLIENT000032: Cannot retry a request which hasn't previously been completed>
        
2018/11/06 11:12:29:180 EST [ERROR][Runner - 969] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <java.lang.IllegalStateException: EJBCLIENT000032: Cannot retry a request which hasn't previously been completed>
        
2018/11/06 11:12:29:181 EST [INFO ][Runner - 494] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Reached treshold of 1 errors, resetting session.
2018/11/06 11:12:29:180 EST [ERROR][Runner - 1287] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <java.lang.IllegalStateException: EJBCLIENT000032: Cannot retry a request which hasn't previously been completed>
        
2018/11/06 11:12:29:180 EST [ERROR][Runner - 1761] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <javax.ejb.EJBException: java.io.IOException: Channel Channel ID f6f6b0ba (outbound) of Remoting connection 13f3f7a6 to /10.16.90.72:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61> has been closed>
        
2018/11/06 11:12:29:181 EST [INFO ][Runner - 1287] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Reached treshold of 1 errors, resetting session.
2018/11/06 11:12:29:181 EST [INFO ][Runner - 969] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Reached treshold of 1 errors, resetting session.
2018/11/06 11:12:29:180 EST [INFO ][Runner - 1922] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Reached treshold of 1 errors, resetting session.
2018/11/06 11:12:29:181 EST [WARN ][Runner - 494] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 494.>
        
2018/11/06 11:12:29:189 EST [INFO ][Runner - 1761] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Reached treshold of 1 errors, resetting session.
11:12:29,181 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-1) EJBCLIENT000017: Received server version 3 and marshalling strategies [river]
11:12:29,199 INFO  [org.jboss.ejb.client.remoting] (ejb-client-context-tasks-1-thread-22) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@79a74a25, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@17bd8cb2,channel=jboss.ejb,nodename=perf21]} on channel Channel ID beeb14c5 (outbound) of Remoting connection 13f3f7a6 to /10.16.90.72:8080 of endpoint "config-based-ejb-client-endpoint" <4b824c61>
2018/11/06 11:12:29:190 EST [WARN ][Runner - 494] SFCORE_LOG - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 494.>
        org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 494.
	at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImplLegacyClient$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImplLegacyClient.java:109)
	at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52)
	at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:103)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: EJBCLIENT000032: Cannot retry a request which hasn't previously been completed
	at org.jboss.ejb.client.EJBClientInvocationContext.retryRequest(EJBClientInvocationContext.java:203)
	at org.jboss.ejb.client.EJBInvocationHandler.sendRequestWithPossibleRetries(EJBInvocationHandler.java:260)
	at org.jboss.ejb.client.EJBInvocationHandler.sendRequestWithPossibleRetries(EJBInvocationHandler.java:279)
	at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:202)
	at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:185)
	at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:148)
	at com.sun.proxy.$Proxy2.getSerialAndIncrement(Unknown Source)
	at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImplLegacyClient$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImplLegacyClient.java:79)
	... 3 more

      7.2.0.CD14.CR2

      With version 7.2.0.CD14.CR2 (server jboss-eap-7.2.0.CD14.CR2.zip, client org.jboss:jboss-ejb-client-legacy:3.0.2.Final-redhat-1) in a scenario with 4 clustered nodes where nodes are failed via jboss shut-down / restart: after node 1 of 4 is shut-down, a a series of errors start on the client side the yield to 1307 errors on a total of 340159 samples;

      find here the complete logs;

      the start of client errors is here:

      2018/11/07 04:00:17:108 EST [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Failing node 0 (perf18)
2018/11/07 04:00:17:116 EST [INFO ][StatsRunner] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Total: Sessions: 2000, active: 2000, samples: 5120, throughput: 511.9 samples/s, bandwidth: 0.0 MB/s, response min: 1 ms, mean: 1 ms, max: 29 ms, sampling errors: 0, unhealthy samples: 0, valid samples: 5120 (100%)
2018/11/07 04:00:17:117 EST [INFO ][StatsRunner] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - unknown-node: Sessions: 2000, active: 2000, samples: 5120, throughput: 511.9 samples/s, bandwidth: 0.0 MB/s, response min: 1 ms, mean: 1 ms, max: 29 ms, sampling errors: 0, unhealthy samples: 0, valid samples: 5120 (100%)
04:00:19,053 INFO  [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-3) EJBCLIENT000016: Channel Channel ID 9687d0a2 (outbound) of Remoting connection 35bf3cbf to perf18/10.16.90.54:8080 of endpoint "config-based-ejb-client-endpoint" <e612b73> can no longer process messages
04:00:19,074 ERROR [org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver] (Remoting "config-based-ejb-client-endpoint" task-3) Failed to open channel for context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@6d037274, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection@7ac140b5,channel=jboss.ejb,nodename=perf18]}
org.jboss.remoting3.NotOpenException: Cannot open new channel because close was initiated
	at org.jboss.remoting3.remote.RemoteConnectionHandler.handleOutboundChannelOpen(RemoteConnectionHandler.java:198)
	at org.jboss.remoting3.remote.RemoteConnectionHandler.open(RemoteConnectionHandler.java:335)
	at org.jboss.remoting3.ConnectionImpl.openChannel(ConnectionImpl.java:109)
	at org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection.openChannel(ConnectionPool.java:292)
	at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.associate(RemotingConnectionEJBReceiver.java:180)
	at org.jboss.ejb.client.EJBClientContext.registerEJBReceiver(EJBClientContext.java:399)
	at org.jboss.ejb.client.EJBClientContext.registerEJBReceiver(EJBClientContext.java:349)
	at org.jboss.ejb.client.remoting.EJBClientContextConnectionReconnectHandler.reconnect(EJBClientContextConnectionReconnectHandler.java:67)
	at org.jboss.ejb.client.EJBClientContext$ReconnectAttempt.run(EJBClientContext.java:1474)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

      Attachments

        Issue Links

          clones

          Bug - A problem that impairs or prevents the functions of the product. WFLY-11292 Legacy EJB Client: High fail rate

          • Blocker - To be worked above all other priorities. This term is chosen when the severity of the issue is very high, has no workaround, or the effort for the change is comparatively low. Issues that may be very publicly visible and could generate significant media attention may also drive a higher priority.
          • Resolved
          is caused by

          Bug - A problem that impairs or prevents the functions of the product. EJBCLIENT-314 Legacy EJB Client: EJBClientInvocationContext.retryRequest fails

          • Blocker - To be worked above all other priorities. This term is chosen when the severity of the issue is very high, has no workaround, or the effort for the change is comparatively low. Issues that may be very publicly visible and could generate significant media attention may also drive a higher priority.
          • Resolved

          Enhancement - An enhancement to or refactoring of existing functionality that is not configurable by an end user (typically a change made by an internal team that affects users) EJBCLIENT-317 Legacy EJB Client: NotOpenException: Cannot open new channel because close was initiated

          • 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.
          • Resolved
          is incorporated by

          Component Upgrade - A task tracking an update to a bundled component or revision of component upstream of the project. JBEAP-16259 (7.2.z) Upgrade legacy EJB Client from 3.0.2.Final-redhat-1 to 3.0.3.Final-redhat-1

          • 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

          Activity

            People

              flaviarnn Flavia Rainone
              tborgato@redhat.com Tommaso Borgato
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: