[4.0.3SP1] NPE in BasicQueue.setupMessageAcknowledgement(Bas

[joergvf]

Hi,

after having received a couple of thousand messages, we saw this exception in our logs (using JBOSS 4.0.3SP1):

2006-10-24 18:53:24,187 ERROR [UIL2(SocketManager.MsgPool@a52a72a client=192.168.100.214:53381)#4 SocketManager] Failed to handle: org.jboss.mq.il.uil2.msgs.ReceiveMsg2084258688[msgType: m_receive, msgID: -2147361440, error: null]
java.lang.NullPointerException
at org.jboss.mq.server.BasicQueue.setupMessageAcknowledgement(BasicQueue.java:945)
at org.jboss.mq.server.BasicQueue.receive(BasicQueue.java:516)
at org.jboss.mq.server.JMSTopic.receive(JMSTopic.java:320)
at org.jboss.mq.server.ClientConsumer.receive(ClientConsumer.java:222)
at org.jboss.mq.server.JMSDestinationManager.receive(JMSDestinationManager.java:656)
at org.jboss.mq.server.JMSServerInvoker.receive(JMSServerInvoker.java:226)
at org.jboss.mq.il.uil2.ServerSocketManagerHandler.handleMsg(ServerSocketManagerHandler.java:155)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:369)
at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:377)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
at java.lang.Thread.run(Thread.java:595)
2006-10-24 18:53:24,251 WARN [Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:23/null destination=TOPIC.sgw/MOCacheInvalidationTopic messageSelector=null Local Create] id=12 SpyConnectionConsumer] Connection consumer closing due to error in listening thread SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:23/null destination=TOPIC.sgw/MOCacheInvalidationTopic messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:23/null destination=TOPIC.sgw/MOCacheInvalidationTopic messageSelector=null Local Create] id=12,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@6c6fff7a connection=Connection@753785396[token=ConnectionToken:ID:23/null rcvstate=STARTED]]
org.jboss.mq.SpyJMSException: Cannot receive ; - nested throwable: (java.lang.NullPointerException)
at org.jboss.mq.SpyJMSException.getAsJMSException(SpyJMSException.java:66)
at org.jboss.mq.SpyJMSException.rethrowAsJMSException(SpyJMSException.java:51)
at org.jboss.mq.Connection.receive(Connection.java:916)
at org.jboss.mq.SpyConnectionConsumer.run(SpyConnectionConsumer.java:238)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.NullPointerException
at org.jboss.mq.server.BasicQueue.setupMessageAcknowledgement(BasicQueue.java:945)
at org.jboss.mq.server.BasicQueue.receive(BasicQueue.java:516)
at org.jboss.mq.server.JMSTopic.receive(JMSTopic.java:320)
at org.jboss.mq.server.ClientConsumer.receive(ClientConsumer.java:222)
at org.jboss.mq.server.JMSDestinationManager.receive(JMSDestinationManager.java:656)
at org.jboss.mq.server.JMSServerInvoker.receive(JMSServerInvoker.java:226)
at org.jboss.mq.il.uil2.ServerSocketManagerHandler.handleMsg(ServerSocketManagerHandler.java:155)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:369)
at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:377)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
... 1 more

We have two durable subscriptions on that topic, and one of them (the respective MDB) does not seem to receive any onMethod() calls anymore afterwards.

It seems that MessageReference.getMessage() returns null for some reason. Do you JBOSS people have any idea how this can happen? Maybe in our code we can somehow prevent this from happening?

Regards,
Jörg

[genman]

For reference, the code that's NPEing is this:

941 protected void setupMessageAcknowledgement(Subscription sub,
 MessageReference messageRef) throws JMSException
942 {
943 SpyMessage message = messageRef.getMessage();
944 AcknowledgementRequest ack = new AcknowledgementRequest();
945 ack.destination = message.getJMSDestination();

message is null.

From what I've seen, the only way the message could be null is if it was swapped to the cache store (your database?) and was not found later on.

Unfortunately, I don't see any way you might be able to diagnose this yourself. If you could add more logging to PersistenceManager to see if this is happening, that'd be great.

I think filing a JIRA issue would be good as well.

[genman]

One thing to check is if the message cache is being used. There is an MBean with cache hits and misses. Miss would mean it's loading messages from the DB.

[joergvf]

"genman" wrote:
One thing to check is if the message cache is being used. There is an MBean with cache hits and misses. Miss would mean it's loading messages from the DB.

I looked at the MessageCache MBean and it shows 29083 cache misses. Now when exactly is a message deleted from the DB? Why can we run into PersistenceManager.loadFromStorage() after the message is already deleted from DB?

[joergvf]

"joergvf" wrote:

"genman" wrote:
One thing to check is if the message cache is being used. There is an MBean with cache hits and misses. Miss would mean it's loading messages from the DB.

I looked at the MessageCache MBean and it shows 29083 cache misses. Now when exactly is a message deleted from the DB? Why can we run into PersistenceManager.loadFromStorage() after the message is already deleted from DB?

MessageRef has synchronize blocks to prevent exactly this from happening, but that only works if we have exactly one MessageRef object per row in the database. Unfortunately, it looks like there is one MessageRef object created per message and durable subscriber id, while the durable subscriber id is not part of the primary key in the database.

If you look at the call hierarchy of the MessageRef constructor you can see that for one message being added, JMSTopic iterates the durable subscribers resulting in a call to the MessageRef constructor for each durable subscriber/message combination.

Should I raise a JIRA issue on this one?

[genman]

Go ahead with the JIRA issue. I don't know if there is a way to reproduce this problem easily. I imagine that setting the cache memory sizes low should exacerbate the problem.

[joergvf]

"Unfortunately", the problem cannot be related to multiple durable subscribers: we tried it with only one durable subscriber, and it still happened.

Now I'm really clueless. We're going to try to move some memory-intensive processing to a different node so the MessageCache has more memory and is less likely to swap out and, in consequence, load messages from DB.

Anyway, and just to stir some more reaction, doesn't JBOSS care about NPEs happening in their code? I'd think this one really shouldn't happen, as the user cannot do anything about it.

[genman]

http://wiki.jboss.org/wiki/Wiki.jsp?page=HelpBugReport

[joergvf]

"genman" wrote:
http://wiki.jboss.org/wiki/Wiki.jsp?page=HelpBugReport

Alright, created http://jira.jboss.com/jira/browse/JBAS-3791

[joergvf]

We were able to reproduce the error with tracing turned on for org.jboss.mq.pm.jdbc3, the log is attached in the JIRA issue.

The error mentions a "msgID: -2147453304", and I wonder whether that id shouldn't be mentioned somewhere else when it had been persisted? I couldn't find it anywhere else in the log.