9:14 a.m.
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
View the original post :
http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4269814#...
Reply to the post :
http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&a...