HQ119027 - client cannot commit message in 2.3.0
nick.pomfret Oct 9, 2013 6:27 AMSince 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?