7 Replies Latest reply on Oct 10, 2013 4:36 AM by ataylor

    HQ119027 - client cannot commit message in 2.3.0

    nick.pomfret

      Since upgrading to Hornetq 2.3.0 I'm getting the following error during a call to HornetQSession.commit...

       

      javax.jms.IllegalStateException: HQ119027: Could not find reference on consumer ID=0, messageId = 118,135,629 queue = <blah-q>

      at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:388)

      at org.hornetq.core.client.impl.ClientSessionImpl.commit(ClientSessionImpl.java:563)

      at org.hornetq.core.client.impl.DelegatingSession.commit(DelegatingSession.java:159)

      at org.hornetq.jms.client.HornetQSession.commit(HornetQSession.java:229)

      at com.mystuff.MessageListener.onMessage(...)

      at org.hornetq.jms.client.JMSMessageListenerWrapper.onMessage(JMSMessageListenerWrapper.java:98)

       

      At this point we attempt to roll back that message, which appears to have worked. However it appears that this has caused a bunch of additional (unrelated) messages to get delivered directly to the dead letter address.  There are no additional error messages in the client logs, however the server logs do confirm this - i see lots of these messages:

       

      INFO | jvm 1 | 2013/10/09 06:29:50 | 2013-10-09T06:29:49.986+0000 WARN [Thread-11 (HornetQ-server-HornetQServerImpl::serverUUID=a6c5209b-2e68-11e3-83a3-bdb599320317-158139074)] [org.hornetq.core.server] HQ222149: Message Reference[118136536]:RELIABLE:ServerMessage[messageID=118136536,priority=4, bodySize=2821,expiration=0, durable=true, address=blah-q,properties=TypedProperties[{stuff, __HQ_CID=ecac7e1b-2e77-11e3-8bee-7139273b8e0b}]]@1334971142 has reached maximum delivery attempts, sending it to Dead Letter Address dlq from blah-q

       

      I also found the following in the broker logs:

       

      INFO | jvm 1 | 2013/10/09 06:29:47 | 2013-10-09T06:29:46.986+0000 WARN [Thread-3 (HornetQ-server-HornetQServerImpl::serverUUID=a6c5209b-2e68-11e3-83a3-bdb599320317-158139074)] [org.hornetq.core.server] HQ222015: Internal error! Delivery logic has identified a non delivery and still handled a consumer!

      INFO | jvm 1 | 2013/10/09 06:29:48 | 2013-10-09T06:29:48.190+0000 ERROR [Old I/O server worker (parentId: 2133521284, [id: 0x7f2af384, /169.52.212.41:1307])] [org.hornetq.core.server] HQ224016: Caught exception

      INFO | jvm 1 | 2013/10/09 06:29:48 | HornetQException[errorType=ILLEGAL_STATE message=HQ119027: Could not find reference on consumer ID=0, messageId = 118,135,629 queue = blah-q]

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.server.impl.ServerConsumerImpl.acknowledge(ServerConsumerImpl.java:704)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.server.impl.ServerSessionImpl.acknowledge(ServerSessionImpl.java:634)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:274)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:631)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:547)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:523)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:564)

      INFO | jvm 1 | 2013/10/09 06:29:48 | at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.messageReceived(HornetQChannelHandler.java:72)

       

      We only have one message in each transaction so a rollback of one message should cause this behavior as far as I can tell.  We have one thread per session, and multiple sessions with a consumer on each listening to this queue.  They share a single jms connection. We do have a fairly large consumer window size.  I can't see any evidence of message delivery problems in the client logs other than the one described above.

       

      We are running a cluster of brokers on a mixture of linux and windows.  This particular client is talking to a windows broker.

       

      So I guess my questions are:

       

      1) What causes HQ119027

      2) Why do so many messages end up on the DQL?

        • 1. Re: HQ119027 - client cannot commit message in 2.3.0
          ataylor

          This is typically caused by the same message being acknowledged twice, usually if the session is shared across threads.

           

          if you post some code maybe i can help more

          • 2. Re: HQ119027 - client cannot commit message in 2.3.0
            nick.pomfret

            The code is fairly straight forward, it essentially boils down to this:

             

                        for (int i = 0; i < numberOfListeners; i++) {

                            Session jmsListeningSession = connection.createTransactedSession();

                            Queue replyQueue = jmsListeningSession.createQueue(someName);

                            MessageConsumer consumer = jmsListeningSession.createConsumer(replyQueue);

                            consumer.setMessageListener(new SomeImplementationOfMessageListener(

                                ...

                            );

                        }

             

            I thought about what you said and decided to wrap the session object up in a dynamic proxy that records which threads call it's methods.  Ignoring the 'main' thread that is used to set up the queue and consumer etc, I see that the session objects are indeed accessed by multiple threads - but they are all owed by hornetq, e.g.

             

            A single session was acccess by these threads (plus the 'main' thread):

                 [

                      Thread-42 (HornetQ-client-global-threads-1299932575), Thread-30 (HornetQ-client-global-threads-1299932575),

                      Thread-38 (HornetQ-client-global-threads-1299932575), Thread-37 (HornetQ-client-global-threads-1299932575),

                      Thread-41 (HornetQ-client-global-threads-1299932575), Thread-39 (HornetQ-client-global-threads-1299932575),

                      Thread-40 (HornetQ-client-global-threads-1299932575), Thread-43 (HornetQ-client-global-threads-1299932575),

                      Thread-35 (HornetQ-client-global-threads-1299932575), Thread-31 (HornetQ-client-global-threads-1299932575),

                      Thread-44 (HornetQ-client-global-threads-1299932575), Thread-45 (HornetQ-client-global-threads-1299932575),

                      Thread-50 (HornetQ-client-global-threads-1299932575), Thread-48 (HornetQ-client-global-threads-1299932575),

                      Thread-49 (HornetQ-client-global-threads-1299932575), Thread-46 (HornetQ-client-global-threads-1299932575)

                 ]

             

            Is this expected?

             

            It's probably worth mentioning that the message listener implementation will send more messages in it's onMessage() method.  Some of these messages are sent the same session (and are part of the transaction), and some on a different session (on a different thread) and do not take part in the transaction.

            • 3. Re: HQ119027 - client cannot commit message in 2.3.0
              ataylor

              that all sounds fine, any chance you could provide something we can run?

              • 4. Re: HQ119027 - client cannot commit message in 2.3.0
                nick.pomfret

                Unfortunately not, it's incredibly difficult to reproduce - it happens like one in a million times (literally).  I can't send you the real code, it's a big system and apart from anything else I'd get fired .  I'd normally write a unit test for you if I could reproduce it, but in this case that's not going to work.

                 

                Can I just get a few things confirmed:

                 

                1) It's ok to have a single connection that has many sessions?

                2) It's ok to have a session accessed my multiple threads, so long as they're all hornetq threads?

                3) Within a single message delivery transaction, only 1 hornetq thread should access the session?

                4) Within a transaction it's ok to send messages on a separate (non-hornetq) thread, so long as a different session is used?

                5) If Session.commit() fails (because of some sort of JMSException), it's ok to try and call Session.rollback() ?

                6) When calling Session.rollback() only messages in the current transaction should get rolled back - and not other messages that are in the consumer window?

                 

                What happens in the unlikely situation where a client receives a JMSException when calling Session.commit() and then calls Session.rollback() *BUT* the broker did actually commit the transaction successfully???

                • 5. Re: HQ119027 - client cannot commit message in 2.3.0
                  ataylor

                  1) It's ok to have a single connection that has many sessions?

                  yes

                  2) It's ok to have a session accessed my multiple threads, so long as they're all hornetq threads?

                  im not sure what you mean here

                  3) Within a single message delivery transaction, only 1 hornetq thread should access the session?

                  again i dont know what you mean

                  4) Within a transaction it's ok to send messages on a separate (non-hornetq) thread, so long as a different session is used?

                  yes (as long as only 1 thread is accessing that other session)

                  5) If Session.commit() fails (because of some sort of JMSException), it's ok to try and call Session.rollback() ?

                  that depends on the failure, we do some stuff when a commit fails depending on what happens.

                  6) When calling Session.rollback() only messages in the current transaction should get rolled back - and not other messages that are in the consumer window?

                  yes, altho the consumers buffer is emptied

                   

                  re 2 and 3, hornetq threads are just there for message delivery, reading buffers etc that we control so im not sure why you are asking.

                   

                  re 5 what exception do you get?

                  • 6. Re: HQ119027 - client cannot commit message in 2.3.0
                    nick.pomfret

                    Let me try and explain quesitons 2 & 3.

                     

                    You replied to my inital post and said that I shouldn't share sessions across threads.  To make sure I wasn't doing this, I wrapped the session in a dynamic proxy that recorded the threads that were using it.  I discivered that hornetq it self accesses a single session with multiple threads, that's what this output was supposed to illustrate (it's the names of the threads that access a *single* session):

                     

                      [

                              Thread-42 (HornetQ-client-global-threads-1299932575), Thread-30 (HornetQ-client-global-threads-1299932575),

                              Thread-38 (HornetQ-client-global-threads-1299932575), Thread-37 (HornetQ-client-global-threads-1299932575),

                              Thread-41 (HornetQ-client-global-threads-1299932575), Thread-39 (HornetQ-client-global-threads-1299932575),

                              Thread-40 (HornetQ-client-global-threads-1299932575), Thread-43 (HornetQ-client-global-threads-1299932575),

                              Thread-35 (HornetQ-client-global-threads-1299932575), Thread-31 (HornetQ-client-global-threads-1299932575),

                              Thread-44 (HornetQ-client-global-threads-1299932575), Thread-45 (HornetQ-client-global-threads-1299932575),

                              Thread-50 (HornetQ-client-global-threads-1299932575), Thread-48 (HornetQ-client-global-threads-1299932575),

                              Thread-49 (HornetQ-client-global-threads-1299932575), Thread-46 (HornetQ-client-global-threads-1299932575)

                         ]

                     

                    The output shows that although multiple threads do access a session, none of them are owned by my program.  They are all owned by hornetq. Does this explain why I asked questions 2 & 3? 

                     

                    With regard to question 5, I posted the exception in my original post.  Here is is again:

                     

                    javax.jms.IllegalStateException: HQ119027: Could not find reference on consumer ID=0, messageId = 118,135,629 queue = <blah-q>

                      at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:388)

                      at org.hornetq.core.client.impl.ClientSessionImpl.commit(ClientSessionImpl.java:563)

                      at org.hornetq.core.client.impl.DelegatingSession.commit(DelegatingSession.java:159)

                      at org.hornetq.jms.client.HornetQSession.commit(HornetQSession.java:229)

                      at com.mystuff.MessageListener.onMessage(...)

                      at org.hornetq.jms.client.JMSMessageListenerWrapper.onMessage(JMSMessageListenerWrapper.java:98)

                     

                    With regard to question 6. You said that 'the consumers buffer is emptied' when I call Session.rollback().  What happens to the messages in the consumer buffer when it get's emptied?

                    • 7. Re: HQ119027 - client cannot commit message in 2.3.0
                      ataylor

                      ok, forget about 2 and 3, when i posed the question it was about how you were handling threads.

                       

                      with regard to the exception i didnt know whether you were handling some other issue and then getting this. tbh without a test or some code i can look at its impossible for me to say why this is happening.

                       

                      With regard to question 6. You said that 'the consumers buffer is emptied' when I call Session.rollback().  What happens to the messages in the consumer buffer when it get's emptied?

                      nothing happens, they are just forgot about (the server still has them)