9 Replies Latest reply on Oct 28, 2008 2:04 AM by theoverlord

    JBM exception

    theoverlord

      I'm using JBM 1.4.0.SP3_CP03 to send messages to a remote MDB.

      I'm using a clustered queue.

      After a sending many messages, JBM basically dies and starts spewing the following messages repeatedly:

      
      2008-08-01 11:00:02,851 [ReusableThread] ERROR org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager - Failed to process notification
      org.jboss.jms.exception.MessagingJMSException: Failed to invoke
       at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
       at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
       at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
       at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$createConsumerDelegate$aop(ClientSessionDelegate.java:245)
       at org.jboss.jms.client.delegate.ClientSessionDelegate$createConsumerDelegate_8721389917985689973.invokeNext(ClientSessionDelegate$createConsumerDelegate_8721389917985689973.java)
       at org.jboss.jms.client.container.StateCreationAspect.handleCreateConsumerDelegate(StateCreationAspect.java:142)
       at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect30.invoke(StateCreationAspect30.java)
       at org.jboss.jms.client.delegate.ClientSessionDelegate$createConsumerDelegate_8721389917985689973.invokeNext(ClientSessionDelegate$createConsumerDelegate_8721389917985689973.java)
       at org.jboss.jms.client.container.ConsumerAspect.handleCreateConsumerDelegate(ConsumerAspect.java:73)
       at org.jboss.aop.advice.org.jboss.jms.client.container.ConsumerAspect29.invoke(ConsumerAspect29.java)
       at org.jboss.jms.client.delegate.ClientSessionDelegate$createConsumerDelegate_8721389917985689973.invokeNext(ClientSessionDelegate$createConsumerDelegate_8721389917985689973.java)
       at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
       at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
       at org.jboss.jms.client.delegate.ClientSessionDelegate$createConsumerDelegate_8721389917985689973.invokeNext(ClientSessionDelegate$createConsumerDelegate_8721389917985689973.java)
       at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
       at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
       at org.jboss.jms.client.delegate.ClientSessionDelegate$createConsumerDelegate_8721389917985689973.invokeNext(ClientSessionDelegate$createConsumerDelegate_8721389917985689973.java)
       at org.jboss.jms.client.delegate.ClientSessionDelegate.createConsumerDelegate(ClientSessionDelegate.java)
       at org.jboss.messaging.core.impl.clusterconnection.MessageSucker.start(MessageSucker.java:126)
       at org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager.createSucker(ClusterConnectionManager.java:478)
       at org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager.notify(ClusterConnectionManager.java:318)
       at org.jboss.messaging.core.impl.DefaultClusterNotifier.sendNotification(DefaultClusterNotifier.java:72)
       at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.addBindingInMemory(MessagingPostOffice.java:2427)
       at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.internalAddBinding(MessagingPostOffice.java:1868)
       at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.addBindingFromCluster(MessagingPostOffice.java:1035)
       at org.jboss.messaging.core.impl.postoffice.BindRequest.execute(BindRequest.java:55)
       at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:606)
       at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:610)
       at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:654)
       at org.jgroups.blocks.RequestCorrelator.access$200(RequestCorrelator.java:40)
       at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944)
       at org.jgroups.util.ReusableThread.run(ReusableThread.java:234)
       at java.lang.Thread.run(Thread.java:595)
      Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id i-nueykcjf-1-fkmxkcjf-7pmlak-t36hs4
       at org.jboss.jms.wireformat.SessionCreateConsumerDelegateRequest.serverInvoke(SessionCreateConsumerDelegateRequest.java:97)
       at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:809)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:608)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
       at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:163)
       at org.jboss.remoting.Client.invoke(Client.java:1634)
       at org.jboss.remoting.Client.invoke(Client.java:548)
       at org.jboss.remoting.Client.invoke(Client.java:536)
       at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
       ... 31 more
      


      After it enters this state, it's useless and unrecoverable. It requires a total cluster restart of the AS.

      On the MDB side (different physical machine), it's spewing this:

      INFO org.jboss.jms.client.FailoverCommandCenter - JBoss Messaging server failure detected - waiting for failover to complete...
      2008-08-01 08:46:03,919 [Thread-273] WARN org.jboss.remoting.LeasePinger - LeasePinger[SocketClientInvoker[9fa2fb, bisocket://apr-s02:8527](4sh63s-mvdw0q-fjckz12o-1-fjcl06j5-5)] tried to remove lease for client with session ID 4sh63s-mvdw0q-fjckz12o-1-fjcyu0zf-5ob7, but no such lease was found
      


      The key to this mystery is that it doesn't happen when I move the MDB into the same machines where the queue reside.

      When I move the MDB external to the queues, that's when the problem occurs.

      I've tried hundreds of different things to figure this out but it all fails after several hours of stress testing.

      Any ideas what is going on?


        • 1. Re: JBM exception
          theoverlord

          Here's another error I'm seeing:

          WARN org.jboss.jms.client.container.ClientConsumer - Timed out waiting for last delivery 9045 got -1
          


          What's going on?

          • 2. Re: JBM exception
            theoverlord

            Here's another one I just got:

            org.jboss.messaging.core.impl.postoffice.UnbindRequest - Failed to remove binding
            java.lang.IllegalStateException: Cannot remove references while deliveries are in progress, there are 43
             at org.jboss.messaging.core.impl.ChannelSupport.removeAllReferences(ChannelSupport.java:390)
             at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.internalRemoveBinding(MessagingPostOffice.java:1935)
             at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBindingFromCluster(MessagingPostOffice.java:1082)
             at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:61)
             at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:606)
             at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:610)
             at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:654)
             at org.jgroups.blocks.RequestCorrelator.access$200(RequestCorrelator.java:40)
             at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944)
             at org.jgroups.util.ReusableThread.run(ReusableThread.java:234)
             at java.lang.Thread.run(Thread.java:595)
            




            • 3. Re: JBM exception
              theoverlord

              As mentioned previously when I move the MDB into the same machines as the queues it all works and I don't see any of the errors above.

              • 4. Re: JBM exception
                theoverlord

                And more errors:

                ERROR org.jboss.messaging.util.ExceptionUtil - SessionEndpoint[r72-wf8uddjf-1-le525djf-g3buv3-s36hs4] deleteTemporaryDestination [x72-g36wddjf-1-le525djf-g3buv3-s36hs4]
                java.lang.IllegalStateException: org.jboss.messaging.core.impl.postoffice.GroupMember@1e0fe7d response not received from XXX.XXX.XXX.XXX:XXXXX - there may be others
                 at org.jboss.messaging.core.impl.postoffice.GroupMember.multicastControl(GroupMember.java:246)
                 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.internalRemoveBinding(MessagingPostOffice.java:1932)
                 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBinding(MessagingPostOffice.java:469)
                 at org.jboss.jms.server.endpoint.ServerSessionEndpoint.deleteTemporaryDestination(ServerSessionEndpoint.java:736)
                 at org.jboss.jms.server.endpoint.advised.SessionAdvised.org$jboss$jms$server$endpoint$advised$SessionAdvised$deleteTemporaryDestination$aop(SessionAdvised.java:130)
                 at org.jboss.jms.server.endpoint.advised.SessionAdvised$deleteTemporaryDestination_N5233806045047796315.invokeNext(SessionAdvised$deleteTemporaryDestination_N5233806045047796315.java)
                 at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
                 at org.jboss.jms.server.endpoint.advised.SessionAdvised$deleteTemporaryDestination_N5233806045047796315.invokeNext(SessionAdvised$deleteTemporaryDestination_N5233806045047796315.java)
                 at org.jboss.jms.server.endpoint.advised.SessionAdvised.deleteTemporaryDestination(SessionAdvised.java)
                 at org.jboss.jms.wireformat.SessionDeleteTemporaryDestinationRequest.serverInvoke(SessionDeleteTemporaryDestinationRequest.java:75)
                 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
                 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:809)
                 at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101)
                 at org.jboss.remoting.Client.invoke(Client.java:1634)
                 at org.jboss.remoting.Client.invoke(Client.java:548)
                 at org.jboss.remoting.Client.invoke(Client.java:536)
                 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
                 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
                 at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$deleteTemporaryDestination$aop(ClientSessionDelegate.java:338)
                 at org.jboss.jms.client.delegate.ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.invokeNext(ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.java)
                 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
                 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
                 at org.jboss.jms.client.delegate.ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.invokeNext(ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.java)
                 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
                 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
                 at org.jboss.jms.client.delegate.ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.invokeNext(ClientSessionDelegate$deleteTemporaryDestination_N5233806045047796315.java)
                 at org.jboss.jms.client.delegate.ClientSessionDelegate.deleteTemporaryDestination(ClientSessionDelegate.java)
                 at org.jboss.jms.destination.JBossTemporaryQueue.delete(JBossTemporaryQueue.java:71)
                 at org.jboss.resource.adapter.jms.JmsSessionFactoryImpl.close(JmsSessionFactoryImpl.java:299)
                


                Why all these errors?

                • 5. Re: JBM exception
                  theoverlord

                  Another one:

                  WARN org.jboss.jms.server.endpoint.ServerSessionEndpoint - No expiry queue has been configured so removing expired Reference[2469908131932164233]:NON-RELIABLE




                  • 6. Re: JBM exception
                    timfox

                    Overlord, with respect, can you please stop the "stream of consciousness" posts.

                    If you have a problem, please do some research into it, make sure you have set things up correctly, read all the manuals etc.

                    If that still doesn't work, then create a simple self contained test case that demonstrates the problem you are seeing, and is runnable by us, post it on this list, or create a jira and attach it, and we will be happy to investigate.

                    Even better, if you have a support account, as you say you have, please use that.

                    But please, no more spamming the list.

                    • 7. Re: JBM exception
                      xxbrandonoxx

                      I am having the exact same issue when I try to cluster the application. It is a very difficult situation to create a simple test for as it includes MDBs, datasources, databases, clusters, jboss messaging, etc.

                      I think it breaks down to a failure of the cluster. I have 2 boxes A & B. Both A & B have jboss messaging installed based upon the documentation. They both use a shared Oracle data store. I am using a shared (configured) Queue for request, and temporary queues for responses (a basic pattern I think). Things seem to work well under light load, but upon funkload'ing a sample app to trigger the mechanisms with high load the cluster seems to fail.

                      I am using the system like this.
                      * I have a simple one page, one form JSF app that will fire a JMS request on my common request queue. This app will create a temporary response queue, listen on it with a java "Future" object, put a message on the global configured queue with appropriate reply-to, a MDB echo's back a hard coded string on the reply-to, the app echo's response to screen.
                      * I have my app configured such that if the request goes to A, the we use A's 1099 port for JMS lookups, and similarly on B.
                      * I am only hitting box A in this test

                      What I see
                      The application seems to work ok for the first few seconds, but then fails between 5-20 seconds into the load test. Like I said above, I am only hitting A.
                      I see a lot of the following on A

                      2008-09-15 14:21:36,192 ERROR [org.jboss.messaging.util.ExceptionUtil] SessionEndpoint[1hn-dln9f5lf-1-b8q6e5lf-np8q9k-t1ce1a]
                       addTemporaryDestination [pko-ctaaf5lf-1-b8q6e5lf-np8q9k-t1ce1a]
                      java.lang.IllegalStateException: org.jboss.messaging.core.impl.postoffice.GroupMember@1ad11ec response not received from 10.5
                      0.12.136:56010 - there may be others
                       at org.jboss.messaging.core.impl.postoffice.GroupMember.multicastControl(GroupMember.java:253)
                       at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.internalAddBinding(MessagingPostOffice.java:1886)
                      


                      The more informative piece of information (IMHO) actually comes from B
                      2008-09-15 14:22:51,660 DEBUG [org.jboss.messaging.core.impl.postoffice.GroupMember] org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener@1aec0d1 got new view [10.50.12.136:56010|2] [10.50.12.136:56010], old view is [10.50.12.136:56010|1] [10.50.12.136:56010, 10.50.12.137:35992]
                      2008-09-15 14:22:51,660 DEBUG [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] Updated failover map:
                      
                       1->1
                      
                      2008-09-15 14:22:51,660 DEBUG [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@fbf107: 10.50.12.137:35992 left
                      2008-09-15 14:22:51,660 DEBUG [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@fbf107: node 2 has crashed
                      2008-09-15 14:22:51,661 DEBUG [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@fbf107 the failover node for the crashed node is 1
                      2008-09-15 14:22:58,558 INFO [org.jboss.cache.TreeCache] viewAccepted(): [10.50.12.136:55867|32] [10.50.12.136:55867]
                      2008-09-15 14:22:58,566 DEBUG [org.jboss.cache.buddyreplication.BuddyManager] Instance 10.50.12.136:55867 broadcasting membership in buddy pool default to recipients []
                      2008-09-15 14:22:58,566 DEBUG [org.jboss.cache.buddyreplication.BuddyManager] Data owner address 10.50.12.136:55867
                      2008-09-15 14:22:58,566 DEBUG [org.jboss.cache.buddyreplication.BuddyManager] Entering updateGroup. Current group: BuddyGroup: (dataOwner: 10.50.12.136:55867, groupName: 10.50.12.136_55867, buddies: [10.50.12.137:35817]). Current View membership: [10.50.12.136:55867]
                      2008-09-15 14:22:58,566 INFO [org.jboss.cache.buddyreplication.NextMemberBuddyLocator] Expected to look for 1 buddies but could only find 0 suitable candidates - trying with colocated buddies as well.
                      2008-09-15 14:22:58,566 INFO [org.jboss.cache.buddyreplication.NextMemberBuddyLocator] Expected to look for 1 buddies but could only find 0 suitable candidates - trying again, ignoring buddy pool hints.
                      2008-09-15 14:22:58,566 INFO [org.jboss.cache.buddyreplication.NextMemberBuddyLocator] Expected to look for 1 buddies but could only find 0 suitable candidates - trying with colocated buddies as well.
                      2008-09-15 14:22:58,566 INFO [org.jboss.cache.buddyreplication.NextMemberBuddyLocator] Expected to look for 1 buddies but could only find 0 suitable candidates!
                      2008-09-15 14:22:58,572 INFO [org.jboss.cache.buddyreplication.BuddyManager] Removing obsolete buddies from buddy group [10.50.12.136_55867]. Obsolete buddies are [10.50.12.137:35817]
                      2008-09-15 14:22:58,572 INFO [org.jboss.cache.buddyreplication.BuddyManager] New buddy group: BuddyGroup: (dataOwner: 10.50.12.136:55867, groupName: 10.50.12.136_55867, buddies: [])
                      


                      #'s
                      I am currently running a load test of 256 concurrent users consistently requesting with 0.1 second delay between requests. Note: this is the same configuration that ran fairly well on my laptop in a non-clustered situation (using hypersonic).

                      Versions
                      JBoss: 4.2.1.GA
                      JBoss Messaging
                      Implementation-Version: 1.4.0.SP3 (build: CVSTag=JBossMessaging_1_4_0_
                      SP3 date=200712131418)
                      Remoting
                      Implementation-Version: 2.2.2.SP4

                      Any help or guidance would be appreciated.

                      • 8. Re: JBM exception
                        timfox

                        Are you creating a temp queue for each request?

                        If so, this is an anti-pattern and will put a lot of strain on the cluster.

                        Better to re-use your temp queus, or better still use a distributed topic to get your requests back.

                        • 9. Re: JBM exception
                          theoverlord

                          This problem has not been resolved for me.

                          It's almost as though a node in the cluster is shunned by the rest of the nodes in the cluster for whatever reason.

                          Why would it do that?