Random invocation failure and errors if EJB session beans are invoked or UserTransaction is used with an EAP6 standalone client

Issue

• If the EJB is called direct or after a short period the invocation will work, if there is a longer time between lookup and invocation it fails
• One of our clients running in its own JVM outside JBoss is calling EJB to and after several succesful calls, we occasionally get the exception below. We are using remote: protocol to lookup the EJB

java.lang.IllegalStateException: EJBCLIENT000025: No EJB receiver available for handling [appName:test, moduleName:example, distinctName:] combination for invocation context org.jboss.ejb.client.EJBClientInvocationContext@77cab87f
      at org.jboss.ejb.client.EJBClientContext.requireEJBReceiver(EJBClientContext.java:588)
      at org.jboss.ejb.client.ReceiverInterceptor.handleInvocation(ReceiverInterceptor.java:116)
      at org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:183)
      at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:136)
      at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:121)
      at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:104)
      at $Proxy0.makeRequest(Unknown Source)
      ...

• Sporadic a standalone client fail if a session bean is invoked via the proxy class

ERROR: Channel end notification received, closing channel Channel ID efda086e (outbound) of Remoting connection 61970ced to localhost/127.0.0.1:4447
Exception in thread "main" javax.ejb.EJBException: java.io.IOException: Channel Channel ID d979ebfa (outbound) of Remoting connection 61970ced to localhost/127.0.0.1:4447 has been closed
    at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:216)
    at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:161)
    at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:124)
    at sun.proxy.$Proxy0.logAndWait(Unknown Source)
    at org.jboss.wfink.simple.RemoteNamingGCTest.invoke(RemoteNamingGCTest.java:40)
    at org.jboss.wfink.simple.RemoteNamingGCTest.main(RemoteNamingGCTest.java:55)
Caused by: java.io.IOException: Channel Channel ID d979ebfa (outbound) of Remoting connection 61970ced to localhost/127.0.0.1:4447 has been closed
    at org.jboss.ejb.client.remoting.ChannelAssociation$1.handleClose(ChannelAssociation.java:115)
    at org.jboss.ejb.client.remoting.ChannelAssociation$1.handleClose(ChannelAssociation.java:107)
    at org.jboss.remoting3.spi.SpiUtils.safeHandleClose(SpiUtils.java:54)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable$CloseHandlerTask.run(AbstractHandleableCloseable.java:501)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.runCloseTask(AbstractHandleableCloseable.java:406)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeComplete(AbstractHandleableCloseable.java:277)
    at org.jboss.remoting3.remote.RemoteConnectionChannel.closeAction(RemoteConnectionChannel.java:515)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:359)
    at org.jboss.remoting3.remote.RemoteConnectionHandler.closeAllChannels(RemoteConnectionHandler.java:390)
    at org.jboss.remoting3.remote.RemoteConnectionHandler.sendCloseRequest(RemoteConnectionHandler.java:231)
    at org.jboss.remoting3.remote.RemoteConnectionHandler.closeAction(RemoteConnectionHandler.java:376)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:359)
    at org.jboss.remoting3.ConnectionImpl.closeAction(ConnectionImpl.java:52)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:359)
    at org.jboss.remoting3.EndpointImpl.closeAction(EndpointImpl.java:201)
    at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:359)
    at org.jboss.naming.remote.client.EndpointCache.release(EndpointCache.java:58)
    at org.jboss.naming.remote.client.EndpointCache$EndpointWrapper.closeAsync(EndpointCache.java:189)
    at org.jboss.naming.remote.client.InitialContextFactory$1.close(InitialContextFactory.java:228)
    at org.jboss.naming.remote.client.RemoteContext.finalize(RemoteContext.java:199)
    at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
    at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:101)
    at java.lang.ref.Finalizer.access$100(Finalizer.java:32)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:178)
Mar 21, 2013 5:51:03 PM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleEnd
EJBCLIENT000016: Channel Channel ID d979ebfa (outbound) of Remoting connection 61970ced to null can no longer process messages

or this

java.lang.IllegalStateException: EJBCLIENT000025: No EJB receiver available for handling [appName:simpleEJB3, moduleName:ejb, distinctName:] combination for invocation context org.jboss.ejb.client.EJBClientInvocationContext@2352fd52
        at org.jboss.ejb.client.EJBClientContext.requireEJBReceiver(EJBClientContext.java:693)
        at org.jboss.ejb.client.ReceiverInterceptor.handleInvocation(ReceiverInterceptor.java:116)
        at org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:183)
        at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:177)
        at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:161)
        at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:124)

• Sporadic the UserTransaction can not be used

java.lang.IllegalStateException: EJBCLIENT000027: No EJBReceiver available for node name node1
        at org.jboss.ejb.client.EJBClientContext.requireNodeEJBReceiver(EJBClientContext.java:616)
        at org.jboss.ejb.client.EJBClientContext.requireNodeEJBReceiverContext(EJBClientContext.java:651)
        at org.jboss.ejb.client.ReceiverInterceptor.handleInvocation(ReceiverInterceptor.java:47)
        at org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:183)
        at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:136)
        at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:121)
        at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:104)

The client code look like this:

public class RemoteNamingGCTest {
  final Simple myRemoteProxy;

  RemoteNamingGCTest() throws NamingException {
    Properties p = new Properties();
    p.put(javax.naming.Context.INITIAL_CONTEXT_FACTORY, "org.jboss.naming.remote.client.InitialContextFactory");
    p.put(javax.naming.Context.PROVIDER_URL, "remote://localhost:4447");
    p.put("jboss.naming.client.ejb.context", true);
    p.put("java.naming.factory.url.pkgs", "org.jboss.ejb.client.naming");

    InitialContext c = new InitialContext(p);
    myRemoteProxy = (Simple) c.lookup("simpleEJB30/ejb/SimpleBean!" + Simple.class.getName());
  }

  private void invoke() {
    ...
    myRemoteProxy.doSomething();
    ...
  }
  ....
}

• I see the folowing messages in the client's logfile and the EJB invocation fails

[Remoting "config-based-naming-client-endpoint" task-3 - ]  INFO remoting:442 - EJBCLIENT000016: Channel Channel ID ee4c071d (outbound) of Remoting connection 00643901 to host/192.168.1.2:4447 can no longer process messages

[Remoting "config-based-naming-client-endpoint" task-2 - ] ERROR RemoteNamingStoreV1:262 - Channel end notification received, closing channel Channel ID b6501301 (outbound) of Remoting connection 00643901 to host/192.168.1.2:4447

[Thread-1 - ] ERROR handler-errors:56 - Close handler threw an exception
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1dc06c1 rejected from java.util.concurrent.ThreadPoolExecutor@3f9b18[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 1]
    at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048)
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
    at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:110)
    at org.jboss.ejb.client.EJBClientContext.unregisterEJBReceiver(EJBClientContext.java:432)
    at org.jboss.ejb.client.EJBReceiverContext.close(EJBReceiverContext.java:59)
    at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver$1$1.handleClose(RemotingConnectionEJBReceiver.java:152)

[Thread-1 - ] TRACE connection:359 - Connection error detail
java.io.EOFException: Writes have been shut down

public class RemoteNamingGCTest {
  final MyEJBRemote myEJB;

  RemoteNamingGCTest() throws NamingException {
     myEJB = MyEJBUtil.getEJBRemote();
  }

  public void invoke() {
    ...
    for(int i=0; i<100; i++) {
      myEJB.doSomething();
    }
    ...
  }
  ....
}

public class MyEJBUtil {
  public static MyEJBRemote getEJBRemote() {
    Properties p = new Properties();
    p.put(javax.naming.Context.INITIAL_CONTEXT_FACTORY, "org.jboss.naming.remote.client.InitialContextFactory");
    p.put(javax.naming.Context.PROVIDER_URL, "remote://localhost:4447");
    p.put("jboss.naming.client.ejb.context", true);
    p.put("java.naming.factory.url.pkgs", "org.jboss.ejb.client.naming");

    InitialContext c = new InitialContext(p);
    return (MyEJBRemote) c.lookup("MyEJBBean!MyEJBRemote);
  }
}