[jboss-user] [Remoting] - Unexplained ConnectionValidator Timeout

[wigdavbar2]

hi

We are using JBoss EAP 4.3.0 CP03 from Red Hat for the first time. 

We are currently in QA and are having serious problems with a plain JVM acting as a JMS client to a non clustered JBoss app server running on the same box. The client keeps getting its remoting connection invalidated, the exception listener is called, our software reconnects and carries on and messages get through slowly, with a lot of disruption.

I thought maybe the validatorPingTimeout was set too low at 2 seconds and that once bug JBMESSAGING-1482 was fixed we could increase it but looking at the TRACE level messages i'm not sure that is the problem.

Even when the JVM starts up and sits there idle it gets the ConnectionValidator detecting an invalid connection after 90 seconds or so. Once messages start getting produced the invalid connections come frequently.

The tracing shows that when the JVM starts the ConnectionValidator kicks off every 2 seconds and reports connection ok. The LeasePinger also kicks off every 10 seconds and reports everything ok. Then whilst the ConnectionValidator is running another ConnectionValidator on a different thread kicks in and reports the connection is invalid.

See an extract of the trace below. Looks like the ConnectionValidator sends request for version, after a second the second ConnectionValidator kicks in an detects an invalid connection, after another second the first ConnectionValidator gets the version ok. Is there another timeout of 1 second on receiving responses from the server?

thanks
dave barton
lead developer
interactive data
london

09:35:27,966 [Timer-2] ConnectionValidator  - ConnectionValidator[SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457], pingPeriod=2000 ms] sending PING tied to lease
  | 09:35:27,966 [Timer-2] ConnectionValidator  - pinging, sending InvocationRequest[4532be10, self, $PING$] over SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457]
  | 09:35:27,966 [Timer-2] MicroRemoteClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457](1) invoking InvocationRequest[4532be10, self, $PING$]
  | 09:35:27,966 [Timer-2] transport.socket.MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] obtained semaphore: 49
  | 09:35:27,967 [Timer-2] transport.socket.MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/172.22.186.24,port=4457,localport=42634].390e4fd7]
  | 09:35:27,967 [Timer-2] transport.socket.MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] writing version 22 on output stream
  | 09:35:27,967 [Timer-2] transport.socket.MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] writing invocation to marshaller
  | 09:35:27,967 [Timer-2] JMSWireFormat  - Writing InvocationRequest[4532be10, self, $PING$]
  | 09:35:27,967 [Timer-2] JMSWireFormat  - Stream is a DataOutputStream
  | 09:35:27,967 [Timer-2] JMSWireFormat  - Writing packet: SerializedPacket[InvocationRequest[4532be10, self, $PING$]]
  | 09:35:27,978 [Timer-2] JMSWireFormat  - Wrote packet
  | 09:35:27,978 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] done writing invocation to marshaller
  | 09:35:27,978 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] reading version from input stream
  | 
  | 09:35:28,982 [Timer-3] ConnectionValidator  - ConnectionValidator[SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457], pingPeriod=2000 ms]'s connections is invalid
  | 
  | 09:35:29,092 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] read version 22 from input stream
  | 09:35:29,092 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] reading response from unmarshaller
  | 09:35:29,092 [Timer-2] JMSWireFormat  - Reading
  | 09:35:29,092 [Timer-2] JMSWireFormat  - Stream is already DataInputStream :)
  | 09:35:29,092 [Timer-2] JMSWireFormat  - Created packet SerializedPacket[null]
  | 09:35:29,092 [Timer-2] JMSWireFormat  - Reading packet
  | 09:35:29,094 [Timer-2] JMSWireFormat  - Read packet
  | 09:35:29,094 [Timer-2] JMSWireFormat  - Returning payload: InvocationResponse[21ce9f9d, true]
  | 09:35:29,094 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] returned ClientSocketWrapper[Socket[addr=/172.22.186.24,port=4457,localport=42634].390e4fd7] to pool
  | 09:35:29,094 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] released semaphore: 50
  | 09:35:29,094 [Timer-2] MicroSocketClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] received response InvocationResponse[21ce9f9d, true]
  | 09:35:29,094 [Timer-2] MicroRemoteClientInvoker  - SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457] received InvocationResponse so going to return response's return value of true
  | 09:35:29,094 [Timer-2] ConnectionValidator  - ConnectionValidator got successful ping using SocketClientInvoker[215b011c, bisocket://lnvmbdidev01.eu.intdata.com:4457]
  | 

View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4212845#4212845

Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4212845