Serious idle problem with Bridges on AS 5.1.0.Beta
rnicholson10 Jun 7, 2009 9:13 AMI had previously reported a problem with idle timeouts on bridges:
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=154559
In my previous post I had stated that this problem only occurred with QOS_ONCE_AND_ONLY_ONCE bridges. However it would appear that this is not the case. After extensive testing it also occurs with QOS_DUPLICATES_OK. This issue is a show stopper for us as we cannot move our application to production if this issue still exists.
I have 3 questions related to this:
1) Has anyone else encountered this problem
2) Are there any planned fixes for this issue
3) When possibly could we expect to see this issue fixed in an AS5 release (as we cannot build messaging ourseleves to work with AS5, we've tried but it just doesn't work!).
Using QOS_DUPLICATES_OK in our test scenario we have a box (box1) that sends messages and another that hosts the bridge file and receives them (box2).
The bridge file on box2 looks like this:
<mbean code="org.jboss.jms.server.bridge.BridgeService" name="jboss.messaging:service=Bridge,name=InputToEngineBridge" xmbean-dd="xmdesc/Bridge-xmbean.xml"> <depends optional-attribute-name="SourceProviderLoader">jboss.messaging:service=JMSProviderLoader,name=RemoteJMSProvider</depends> <depends optional-attribute-name="TargetProviderLoader">jboss.messaging:service=JMSProviderLoader,name=JMSProvider</depends> <attribute name="SourceDestinationLookup">/queue/phaseQueueToEngine</attribute> <attribute name="TargetDestinationLookup">/queue/phaseQueueFromInput</attribute> <!-- Optional: The Quality Of Service mode to use, one of: QOS_AT_MOST_ONCE = 0; QOS_DUPLICATES_OK = 1; QOS_ONCE_AND_ONLY_ONCE = 2;--> <attribute name="QualityOfServiceMode">1</attribute> <attribute name="MaxBatchSize">1</attribute> <attribute name="MaxBatchTime">-1</attribute> <attribute name="FailureRetryInterval">5000</attribute> <attribute name="MaxRetries">-1</attribute> <attribute name="AddMessageIDInHeader">false</attribute> </mbean>
After an idle period of 16 hours (jboss running but no messages are sent), box1 attempts to send 100 messages. The following error occurs on box1:
2009-06-07 13:23:58,655 ERROR [org.jboss.messaging.util.ExceptionUtil] (http-0.0.0.0-8080-6) ConnectionFactoryEndpoint[jboss.messaging.connectionfactory:service=ConnectionFactory] createFailoverConnectionDelegate [8f41-nq47qnvf-1-yyggvmuf-g3h4ce-b53gs4] javax.jms.JMSSecurityException: User null is NOT authenticated at org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore.authenticate(JBossASSecurityMetadataStore.java:223) at sun.reflect.GeneratedMethodAccessor926.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source) at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source) at javax.management.StandardMBean.invoke(Unknown Source) at org.jboss.mx.server.RawDynamicInvoker.invoke(RawDynamicInvoker.java:164) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668) at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210) at $Proxy108.authenticate(Unknown Source) at org.jboss.jms.server.endpoint.ServerConnectionFactoryEndpoint.createConnectionDelegateInternal(ServerConnectionFactoryEndpoint.java:233) at org.jboss.jms.server.endpoint.ServerConnectionFactoryEndpoint.createConnectionDelegate(ServerConnectionFactoryEndpoint.java:171) at org.jboss.jms.server.endpoint.advised.ConnectionFactoryAdvised.org$jboss$jms$server$endpoint$advised$ConnectionFactoryAdvised$createConnectionDelegate$aop(ConnectionFactoryAdvised.java:108) at org.jboss.jms.server.endpoint.advised.ConnectionFactoryAdvised.createConnectionDelegate(ConnectionFactoryAdvised.java) at org.jboss.jms.wireformat.ConnectionFactoryCreateConnectionDelegateRequest.serverInvoke(ConnectionFactoryCreateConnectionDelegateRequest.java:91) at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143) at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:908) at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:106) at org.jboss.remoting.Client.invoke(Client.java:1708) at org.jboss.remoting.Client.invoke(Client.java:612) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.org$jboss$jms$client$delegate$ClientConnectionFactoryDelegate$createConnectionDelegate$aop(ClientConnectionFactoryDelegate.java:171) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.invokeTarget(ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.java) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111) at org.jboss.jms.client.container.StateCreationAspect.handleCreateConnectionDelegate(StateCreationAspect.java:81) at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect_z_handleCreateConnectionDelegate_12191562.invoke(StateCreationAspect_z_handleCreateConnectionDelegate_12191562.java) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.createConnectionDelegate(ClientConnectionFactoryDelegate.java) at org.jboss.jms.client.JBossConnectionFactory.createConnectionInternal(JBossConnectionFactory.java:205) at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:87) at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:82) at com.paddypower.phase.test.servlet.TestMessageOneServlet.doGet(TestMessageOneServlet.java:92) at javax.servlet.http.HttpServlet.service(HttpServlet.java:617) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190) at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:601) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Unknown Source) 2009-06-07 13:23:58,657 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (http-0.0.0.0-8080-6) removing callback handler ServerInvokerCallbackHandler[4sg35b-ec4h3g-fumvggyy-1-fvnq74q0-14f2+4sg35b-ec4h3g-fumvggyy-1-fvnq74qf-14f5] 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.InvokerRegistry] (http-0.0.0.0-8080-6) removed org.jboss.remoting.transport.local.LocalClientInvoker@1f5facb from registry 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.ServerInvoker] (http-0.0.0.0-8080-6) ServerInvoker (SocketServerInvoker[172.16.113.11:1227169616]) removing client callback handler with session id of 4sg35b-ec4h3g-fumvggyy-1-fvnq74q0-14f2+4sg35b-ec4h3g-fumvggyy-1-fvnq74qf-14f5. 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] (http-0.0.0.0-8080-6) unrecognized listener ID: 4sg35b-ec4h3g-fumvggyy-1-fvnq74qf-14f5 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.InvokerRegistry] (http-0.0.0.0-8080-6) removed org.jboss.remoting.transport.local.LocalClientInvoker@2460e7 from registry 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (http-0.0.0.0-8080-6) SocketServerInvoker[172.16.113.11:1227169616] stopped threads in clientpool 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (http-0.0.0.0-8080-6) SocketServerInvoker[172.16.113.11:1227169616] stopped threads in threadpool 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (http-0.0.0.0-8080-6) SocketServerInvoker[172.16.113.11:1227169616] exiting 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.ServerInvoker] (http-0.0.0.0-8080-6) SocketServerInvoker[172.16.113.11:1227169616] stopped 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.InvokerRegistry] (http-0.0.0.0-8080-6) decremented org.jboss.remoting.transport.local.LocalClientInvoker@1da6374's count, current count 2 2009-06-07 13:23:58,657 DEBUG [org.jboss.remoting.InvokerRegistry] (http-0.0.0.0-8080-6) decremented org.jboss.remoting.transport.local.LocalClientInvoker@b76609's count, current count 2
At this point I restart jboss on box1, but box2 now gives the following errors:
2009-06-07 13:20:00,372 WARN [org.jboss.jms.server.bridge.Bridge] (Thread-98) jboss.messaging:name=InputToEngineBridge,service=Bridge Failed to set up connections javax.jms.JMSSecurityException: User null is NOT authenticated at org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore.authenticate(JBossASSecurityMetadataStore.java:223) at sun.reflect.GeneratedMethodAccessor301.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source) at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source) at javax.management.StandardMBean.invoke(Unknown Source) at org.jboss.mx.server.RawDynamicInvoker.invoke(RawDynamicInvoker.java:164) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668) at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210) at $Proxy98.authenticate(Unknown Source) at org.jboss.jms.server.endpoint.ServerConnectionFactoryEndpoint.createConnectionDelegateInternal(ServerConnectionFactoryEndpoint.java:233) at org.jboss.jms.server.endpoint.ServerConnectionFactoryEndpoint.createConnectionDelegate(ServerConnectionFactoryEndpoint.java:171) at org.jboss.jms.server.endpoint.advised.ConnectionFactoryAdvised.org$jboss$jms$server$endpoint$advised$ConnectionFactoryAdvised$createConnectionDelegate$aop(ConnectionFactoryAdvised.java:108) at org.jboss.jms.server.endpoint.advised.ConnectionFactoryAdvised.createConnectionDelegate(ConnectionFactoryAdvised.java) at org.jboss.jms.wireformat.ConnectionFactoryCreateConnectionDelegateRequest.serverInvoke(ConnectionFactoryCreateConnectionDelegateRequest.java:91) at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143) at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:908) at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:106) at org.jboss.remoting.Client.invoke(Client.java:1708) at org.jboss.remoting.Client.invoke(Client.java:612) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.org$jboss$jms$client$delegate$ClientConnectionFactoryDelegate$createConnectionDelegate$aop(ClientConnectionFactoryDelegate.java:171) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.invokeTarget(ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.java) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111) at org.jboss.jms.client.container.StateCreationAspect.handleCreateConnectionDelegate(StateCreationAspect.java:81) at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect_z_handleCreateConnectionDelegate_7578460.invoke(StateCreationAspect_z_handleCreateConnectionDelegate_7578460.java) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.createConnectionDelegate(ClientConnectionFactoryDelegate.java) at org.jboss.jms.client.JBossConnectionFactory.createConnectionInternal(JBossConnectionFactory.java:205) at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:87) at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:82) at org.jboss.jms.server.bridge.Bridge.createConnection(Bridge.java:893) at org.jboss.jms.server.bridge.Bridge.setupJMSObjects(Bridge.java:1015) at org.jboss.jms.server.bridge.Bridge.setupJMSObjectsWithRetry(Bridge.java:1223) at org.jboss.jms.server.bridge.Bridge.access$1600(Bridge.java:68) at org.jboss.jms.server.bridge.Bridge$FailureHandler.run(Bridge.java:1569) at java.lang.Thread.run(Unknown Source) 2009-06-07 13:20:00,375 DEBUG [org.jboss.remoting.InvokerRegistry] (Thread-98) removed SocketClientInvoker[138cef1, bisocket://jbdevapp1.inhouse.paddypower.com:4457] from registry 2009-06-07 13:20:00,375 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Thread-98) SocketClientInvoker[138cef1, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:00,375 DEBUG [org.jboss.remoting.ConnectionValidator] (Thread-98) ConnectionValidator[SocketClientInvoker[138cef1, bisocket://jbdevapp1.inhouse.paddypower.com:4457], pingPeriod=10000 ms] stopped, returning true 2009-06-07 13:20:00,477 DEBUG [org.jboss.remoting.ServerInvoker] (Thread-98) ServerInvoker (SocketServerInvoker[172.16.113.22:1145771147]) removing client callback handler with session id of 4sg35m-gh2wpi-fvmo2mas-1-fvnq20td-356+4sg35m-gh2wpi-fvmo2mas-1-fvnq20u7-35a. 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] (Thread-98) SocketServerInvoker[172.16.113.22:1145771147] shutting down control connection: 4sg35m-gh2wpi-fvmo2mas-1-fvnq20u7-35a 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.InvokerRegistry] (Thread-98) removed org.jboss.remoting.transport.local.LocalClientInvoker@3abbcd from registry 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (Thread-98) SocketServerInvoker[172.16.113.22:1145771147] stopped threads in clientpool 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (Thread-98) SocketServerInvoker[172.16.113.22:1145771147] stopped threads in threadpool 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.transport.socket.SocketServerInvoker] (Thread-98) SocketServerInvoker[172.16.113.22:1145771147] exiting 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.ServerInvoker] (Thread-98) SocketServerInvoker[172.16.113.22:1145771147] stopped 2009-06-07 13:20:00,478 DEBUG [org.jboss.remoting.LeasePinger] (Thread-98) LeasePinger[SocketClientInvoker[1058a14, bisocket://jbdevapp1.inhouse.paddypower.com:4457](4sg35m-gh2wpi-fvmo2mas-1-fvnq20mq-34s)] setting disconnect timeout to: -1 2009-06-07 13:20:00,490 DEBUG [org.jboss.remoting.InvokerRegistry] (Thread-98) removed SocketClientInvoker[1058a14, bisocket://jbdevapp1.inhouse.paddypower.com:4457] from registry 2009-06-07 13:20:00,490 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Thread-98) SocketClientInvoker[1058a14, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (Thread-98) ClientSocketWrapper[Socket[addr=/172.16.113.11,port=4457,localport=36016].7f5d75] closing socket 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (Thread-98) ClientSocketWrapper[Socket[addr=/172.16.113.11,port=4457,localport=36016].7f5d75] closed socket 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (Thread-98) ClientSocketWrapper[Socket[addr=/172.16.113.11,port=4457,localport=36017].1d0ca53] closing socket 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (Thread-98) ClientSocketWrapper[Socket[addr=/172.16.113.11,port=4457,localport=36017].1d0ca53] closed socket 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.InvokerRegistry] (Thread-98) removed SocketClientInvoker[1b4f110, bisocket://jbdevapp1.inhouse.paddypower.com:4457] from registry 2009-06-07 13:20:00,491 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Thread-98) SocketClientInvoker[1b4f110, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:00,491 WARN [org.jboss.jms.server.bridge.Bridge] (Thread-98) jboss.messaging:name=InputToEngineBridge,service=Bridge Failed to set up connections, will retry after a pause of 5000 ms 2009-06-07 13:20:01,526 FINE [sun.rmi.transport.tcp] (RMI Scheduler(0)) RMI Scheduler(0): close connection 2009-06-07 13:20:02,171 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Finalizer) SocketClientInvoker[1058a14, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:02,171 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Finalizer) SocketClientInvoker[1058a14, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:02,171 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Finalizer) SocketClientInvoker[1b4f110, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:02,171 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Finalizer) SocketClientInvoker[1b4f110, bisocket://jbdevapp1.inhouse.paddypower.com:4457] disconnecting ... 2009-06-07 13:20:02,172 DEBUG [org.jboss.remoting.ServerInvoker] (Finalizer) SocketServerInvoker[172.16.113.22:1304616729] stopped 2009-06-07 13:20:02,172 DEBUG [org.jboss.remoting.ServerInvoker] (Finalizer) SocketServerInvoker[172.16.113.22:1104212656] stopped 2009-06-07 13:20:02,173 DEBUG [org.jboss.remoting.ServerInvoker] (Finalizer) SocketServerInvoker[172.16.113.22:1145771147] stopped 2009-06-07 13:20:02,173 DEBUG [org.jboss.remoting.ServerInvoker] (Finalizer) SocketServerInvoker[172.16.113.22:1304616767] stopped
If I now restart box2, the bridges behave correctly once again.