Illegal state of the rollinglogged PM just after server star
Our application has 2 JMS queues (as a single entry point for the 200+ types of the application requests) with the rollinglogged persistence.
Persistence manager configuration relies on defaults.
<mbean code="org.jboss.mq.pm.rollinglogged.PersistenceManager" name="jboss.mq:service=PersistenceManager"> <attribute name="DataDirectory">data/jbossmq/file</attribute> <depends optional-attribute-name="MessageCache">jboss.mq:service=MessageCache</depends> </mbean>
The queue #1 stores pending application requests. The messages posted to this queue have type ObjectMessage and sent with the following options: Not transacted, Persistent, Aknowledged by client, Never expired. This queue is used for the load control and must be unchanged after server restart. Receiver for this queue is manually managed by our application.
The queue #2 is used for the activate application requests. The messages posted to this queue have type ObjectMessage and sent with the following options: Not transacted, Not persistent, Aknowledged by client, Never expired. MDB is receiver for this queue.
Application request processing flow is the following:
1. The message is sent to the queue #1.
2a. Application thread listens for all messages by the listening QueueReceiver of the queue #1 and receives the message. It pplication does not aknowledge the message.
2c. Application sends a message with the same object to the queue #2.
3a. MDB receives the message from queue #2.
3b. MDB processes application request encoded in the message object.
3c. MDB closes listening QueueReceiver of the queue #1 and opens aknowledging QueueReceiver of the queue #1 to aknowledge the single message.
3d. MDB receives the single message (the same message was received before at step 2a) and aknowledges it.
3e. MDB closes aknowledging QueueReceiver of the queue #1 and opens listening QueueReceiver.
Operations 2a and 3c-3e are synchronized. Only 1 instance of the QueueReceiver of the queue #1 (either for all message listen or for the single message aknowledgement) is possible at any time.
This scheme works fine (with a multiple thousands of application requests processing) with one exclusion: sometimes just after daily server restart following exception occurs at step 3c.
2008-04-24 04:11:23,231 ERROR [org.jboss.mq.server.BasicQueue] Caught unusual exception in nackMessage for 247 msg=806 hard NOT_STORED PERSISTENT persistData=org.jboss.mq.pm.rollinglogged.PersistenceManager$LogInfo@f96752 queue=QUEUE.kyriba.jms.tasks.request_queue priority=4 lateClone=false hashCode=25798515
javax.jms.JMSException: no logs for this txLog: org.jboss.mq.pm.rollinglogged.SpyTxLog@cef6f1
at org.jboss.mq.pm.rollinglogged.PersistenceManager.update(PersistenceManager.java:429)
at org.jboss.mq.server.BasicQueue.nackMessage(BasicQueue.java:402)
at org.jboss.mq.server.BasicQueue$RestoreMessageTask.run(BasicQueue.java:1183)
at org.jboss.mq.pm.TxManager.addPostCommitTask(TxManager.java:119)
at org.jboss.mq.server.BasicQueue.acknowledge(BasicQueue.java:569)
at org.jboss.mq.server.JMSQueue.acknowledge(JMSQueue.java:171)
at org.jboss.mq.server.ClientConsumer.acknowledge(ClientConsumer.java:334)
at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:486)
at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:479)
at org.jboss.mq.server.JMSServerInterceptorSupport.acknowledge(JMSServerInterceptorSupport.java:213)
at org.jboss.mq.server.TracingInterceptor.acknowledge(TracingInterceptor.java:467)
at org.jboss.mq.server.JMSServerInvoker.acknowledge(JMSServerInvoker.java:213)
at org.jboss.mq.il.jvm.JVMServerIL.acknowledge(JVMServerIL.java:229)
at org.jboss.mq.Connection.send(Connection.java:1089)
at org.jboss.mq.SpySession.close(SpySession.java:426)
at
(((application code here:
//stopListening();
receiver.close();
//session.recover();
session.close(); !! PROCESSING THIS INSTRUCTION !!
session = connection.createQueueSession(false, QueueSession.CLIENT_ACKNOWLEDGE);
ackReceiver = session.createReceiver(queue, "JMSMessageID='" + request.getJMSMessageID() + "'");
ObjectMessage message = (ObjectMessage)ackReceiver.receiveNoWait();
if (message == null) {
// attempt to ack message wich does not exist
throw new TaskException("no message with JMSMessageID=" +
request.getJMSMessageID());
}
message.acknowledge();
)))
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.jboss.ejb.MessageDrivenContainer$ContainerInterceptor.invoke(MessageDrivenContainer.java:472)
at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:198)
at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:101)
at org.jboss.ejb.plugins.AbstractTxInterceptorBMT.invokeNext(AbstractTxInterceptorBMT.java:161)
at org.jboss.ejb.plugins.MessageDrivenTxInterceptorBMT.invoke(MessageDrivenTxInterceptorBMT.java:47)
at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:77)
at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:206)
at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:136)
at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:386)
at org.jboss.ejb.Container.invoke(Container.java:723)
at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:962)
at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1257)
at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:266)
at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:902)
at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
at org.jboss.mq.SpySession.run(SpySession.java:323)
at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
at java.lang.Thread.run(Thread.java:595)
Moreover this exception occurs only for the messages sent to the queue #1 before server stop and processed after server start. And this exception never repeats after the following restart.
Server shutdown is performed correctly by "kill -15 $PID".
No operating system level troubles observed.
