EJB (SLSB) invocation ignores read timeout, blocks indefinit

[sumitsu]

I have an application which is exposed as an EJB 3 stateless session bean, and which is running on a clustered environment of JBoss 4.2.3 instances under Java 6. In some cases, the service exposed by the SLSB never returns after invocation, and in that event, it is imperative that the client time out (and fail out with an Exception) after a relatively short interval.

Clients of the SLSB invoke it via JNDI, and the behavior observed is that even though the properties used to build the JNDI context specify both jnp.timeout and jnp.sotimeout (as prescribed by the NamingContextFactory documentation: http://www.jboss.org/community/wiki/NamingContextFactory), invocations of the SLSB block, and never time out.

I have verified this behavior by deploying a test version of the application which deliberately enters an infinite loop upon invocation, and therefore the clients should encounter the read timeout every time.

Server-Side Code:

 public void postData() {
 log.info("\n" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n" +
 " TIMEOUT TEST -- STALLING NOW" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n" +
 "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n");
 Object nullRef = null;
 while (nullRef == null) {
 try {
 Thread.sleep(3600000);
 } catch (InterruptedException iEx) {
 // Do nothing.
 }
 }
 log.error("\n" +
 "??????????????????????????????????????????????????\n" +
 "??????????????????????????????????????????????????\n" +
 "??????????????????????????????????????????????????\n" +
 " TIMEOUT TEST -- OUT OF STALL ??" +
 " THIS SHOULD NEVER HAPPEN... TEST MUST NOT BE WORKING..." +
 "??????????????????????????????????????????????????\n" +
 "??????????????????????????????????????????????????\n" +
 "??????????????????????????????????????????????????\n");
 }

Client-Side Code:

 Properties jndiProps;
 jndiProps = new Properties();
 jndiProps.setProperty(Context.PROVIDER_URL, "jnp://node1:31501,jnp://node2:31601");
 jndiProps.setProperty(Context.INITIAL_CONTEXT_FACTORY, "org.jnp.interfaces.NamingContextFactory");
 jndiProps.setProperty(Context.URL_PKG_PREFIXES, "org.jboss.naming:org.jnp.interfaces");
 jndiProps.setProperty("jnp.socketFactory", "org.jnp.interfaces.TimedSocketFactory");
 jndiProps.setProperty("jnp.timeout", "1000");
 jndiProps.setProperty("jnp.sotimeout", "1000");
 jndiProps.setProperty("jnp.maxRetries", "1");
 jndiProps.setProperty("jnp.disableDiscovery", "true");

 String relayJndiName = RELAY_JNDI_NAME;

 log.info("ESBT@GSC: JNDI Connection Properties: " + jndiProps);

 Context jndiContext = new InitialContext(jndiProps);

 ServiceRelay relay =
 (ServiceRelay)
 PortableRemoteObject.narrow(jndiContext.lookup(relayJndiName),
 ServiceRelay.class);
 relay.postData();

Server-Side Logs:

07:35:10.317 INFO [relay.ServiceRelayBean]
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
 TIMEOUT TEST -- STALLING NOW!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

Client-Side Logs:

(actual IP addresses replaced by "(node1)"; 31516 is the EJB3 Server Bind Port specified in deploy/ejb3.deployer/META-INF/jboss-service.xml)

2009-12-08 21:22:43,408 INFO [(client)] ESBT@GSC: JNDI Connection Properties: {java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.provider.url=jnp://(node1):31500, jnp.disableDiscovery=true, jnp.timeout=1000, jnp.maxRetries=1, jnp.socketFactory=org.jnp.interfaces.TimedSocketFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces, jnp.sotimeout=1000}

2009-12-08 21:22:43,580 DEBUG [org.jboss.security.SecurityAssociation] Using ThreadLocal: false

2009-12-08 21:22:43,595 TRACE [org.jboss.security.SecurityAssociation] getPrincipal, principal=null

2009-12-08 21:22:43,626 TRACE [org.jboss.util.propertyeditor.PropertyEditors] Mapping properties for bean: SocketClientInvoker[485fcf29, socket://(node1):31516]

2009-12-08 21:22:43,626 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] constructed

2009-12-08 21:22:43,626 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] connecting

2009-12-08 21:22:43,626 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] Creating semaphore with size 50

2009-12-08 21:22:43,626 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] added new pool ([]) as ServerAddress[(node1):31516, NO enableTcpNoDelay timeout 0 ms, maxPoolSize=50]

2009-12-08 21:22:43,626 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] connected

2009-12-08 21:22:43,626 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516](1) invoking InvocationRequest[409cb0f4, AOP, [advisedMethod=public abstract void com.(omitted).relay.ServiceRelay.postData(), metadata=[metaData={DISPATCHER={OID=[type=AS_ISvalue=jboss.j2ee:ear=Application.ear,jar=Application_Core.jar,name=ServiceRelay,service=EJB3]}, REMOTING={SUBSYSTEM=[type=AS_ISvalue=AOP], INVOKER_LOCATOR=[type=AS_ISvalue=InvokerLocator [socket://node1:31516/]]}, IS_LOCAL={GUID=[type=AS_ISvalue=jboss.j2ee:ear=Application.ear,jar=Application_Core.jar,name=ServiceRelay,service=EJB3,VMID=5bf119373c151ad7:621c5cda:1257036187f:-7951]}}], targetObject=null, arguments=[Ljava.lang.Object;@6f25844f]]

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] obtained semaphore: 49

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] creating socket

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] created socket: Socket[addr=/node1,port=31516,localport=4117]

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] constructing org.jboss.remoting.transport.socket.ClientSocketWrapper instance for Socket[addr=/(node1),port=31516,localport=4117], using timeout 0

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[Socket[addr=/(node1),port=31516,localport=4117].47171b26] setting timeout to 0

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.ClientSocketWrapper] ClientSocketWrapper[Socket[addr=/(node1),port=31516,localport=4117].47171b26] getting output stream from Socket[addr=/(node1),port=31516,localport=4117], org.jboss.remoting.marshal.serializable.SerializableMarshaller@3df78040

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.serialization.impl.java.JavaSerializationManager] Creating ObjectOutputStream

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.ClientSocketWrapper] ClientSocketWrapper[Socket[addr=/(node1),port=31516,localport=4117].47171b26] getting input stream from Socket[addr=/(node1),port=31516,localport=4117], org.jboss.remoting.marshal.serializable.SerializableUnMarshaller@151ca803

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.serialization.impl.java.JavaSerializationManager] Creating ObjectInputStreamWithClassLoader

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[Socket[addr=/(node1),port=31516,localport=4117].47171b26] setting timeout to 0

2009-12-08 21:22:43,642 DEBUG [org.jboss.remoting.transport.socket.ClientSocketWrapper] reset timeout: 0

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] writing version 22 on output stream

2009-12-08 21:22:43,642 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] writing invocation to marshaller

2009-12-08 21:22:43,658 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] done writing invocation to marshaller

2009-12-08 21:22:43,658 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[485fcf29, socket://(node1):31516] reading version from input stream

(I note that there are two TRACE-level logs on the client-side referencing setting or resetting the timeout to zero.)

The application server nodes are running under Solaris 10. On the client side, I have tried both Solaris and Windows XP, encountering the behavior noted above in each case. I have tried both the HA-JNDI port and the standard JNDI port, as well as specifying both a single URL and a list of all in the cluster, all to no effect.

Can anyone tell me how to enforce the read timeout? Am I missing something when I create the JNDI context? Am I misunderstanding something fundamental with regard to the read timeout / socket timeout?

Thanks in advance for any assistance anyone can offer.

Branden Smith

[sumitsu]

Thanks to another forum post by someone with a simlar issue (http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4250461), I found a way to "seed" the invoker proxy returned by JNDI lookup with a desired read timeout value, thus enforcing the timeout upon each invocation of a service within the bean.

The timeout setting, somewhat counter-intuitively, is maintained on the server side rather than specified by the client; follow these steps to add the timeout value:

(1) Edit server/CONF/deploy/ejb3.deployer/META-INF/jboss-service.xml (where CONF is the container configuration you are using)

(2) Modify the mbean

<mbean code="org.jboss.remoting.transport.Connector"
 name="jboss.remoting:type=Connector,name=DefaultEjb3Connector,handler=ejb3">

(3) Alter the socket:// URI given by the InvokerLocator attribute to add the suffix /?timeout=#####, where ##### is the desired timeout value, in milliseconds

Upon the change to the configuration, the new timeout value is reflected in the client-side TRACE logs referencing a number to which the timeout value is set (which previously indicated a blocking timeout of 0). Running the deliberate-stall test code detailed in the previous post produces a read timeout such as the following, where formerly it had stalled out:

java.lang.reflect.UndeclaredThrowableException
 ...
Caused by: java.rmi.MarshalException: Socket timed out. Waited 5000 milliseconds for response while calling on InvokerLocator [socket://(node1):31516/?timeout=5000]; nested exception is:
...
Caused by: java.net.SocketTimeoutException: Read timed out
...

It is confusing to me that this timeout is implemented as a server-side configuration rather than by obtaining it from the parameters (jnp.timeout and jnp.sotimeout) specified by the client when the JNDI context is created, since the latter option would seem to provide more flexibility to the client. As it stands, this solution would appear to apply to all remote invocations to all EJB3 services running on the app server.

If anyone in the know regarding the design logic behind this approach would like to provide an explanation, I would be interested in hearing it. (For that matter, if anyone knows of an alternative way to produce the same timeout effect, I would be interested in that as well.)

[m.miklas]

I have the same problem .... I cannot change server configuration and I need to define different timeout for one particular client. Is there already solution for that?