Cannot find session during shutdown

[philipdodds]

During the shutdown of a system with several MDB's we appear to be getting:

2009-05-20 12:30:52,499 ERROR [org.jboss.messaging.util.ExceptionUtil] (WorkManager(2)-44) ConnectionEndpoint[fe-oz919yuf-1-mj809yuf-bruz48-x21o4c5] sendTransaction [ur4-b6b39yuf-1-mj809yuf-bruz48-x21o4c5]
javax.jms.IllegalStateException: Cannot find session with id ie-qz919yuf-1-mj809yuf-bruz48-x21o4c5
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.processTransaction(ServerConnectionEndpoint.java:835)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:497)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeTarget(ConnectionAdvised$sendTransaction_N3268650789275322226.java)

This seems to lead to

2009-05-20 12:36:34,251 WARN [com.arjuna.ats.jta.logging.loggerI18N] (Thread-13) [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 30, 28, 4945455110253551021015755589956555058529749525010299575855555753455110253551021015755589956555058529749525010299575855555754 >

When the server restarts, what causes problems with the session not being found in a XA environment?

Thanks in advance

Philip

[clebert.suconic]

Regarding the non-serializable error, look at this thread:

http://www.jboss.org/index.html?module=bb&op=viewtopic&t=152893


I'm not sure why you're getting this error though. Maybe some missing dependency between JCA and JBossMessaging and the shutdown order is not being respected?

[clebert.suconic]

I'm not sure why you're getting this error though.

I was referring to this error:

2009-05-20 12:30:52,499 ERROR [org.jboss.messaging.util.ExceptionUtil] (WorkManager(2)-44) Connectio
nEndpoint[fe-oz919yuf-1-mj809yuf-bruz48-x21o4c5] sendTransaction [ur4-b6b39yuf-1-mj809yuf-bruz48-x21
o4c5]
javax.jms.IllegalStateException: Cannot find session with id ie-qz919yuf-1-mj809yuf-bruz48-x21o4c5
...

[philipdodds]

Hi Clebert

We have put in the recovery settings into the jbossjta-properties.xml and also moved it to the top during testing.

It worries me a little that the session isn't found - I could only find references to that problem occurring in a clustered environment (see https://jira.jboss.org/jira/browse/JBESB-2218) though we are seeing this:

2009-05-20 12:30:52,499 ERROR [org.jboss.messaging.util.ExceptionUtil] (WorkManager(2)-44) ConnectionEndpoint[fe-oz919yuf-1-mj809yuf-bruz48-x21o4c5] sendTransaction [ur4-b6b39yuf-1-mj809yuf-bruz48-x21o4c5]
javax.jms.IllegalStateException: Cannot find session with id ie-qz919yuf-1-mj809yuf-bruz48-x21o4c5
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.processTransaction(ServerConnectionEndpoint.java:835)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:497)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeTarget(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
 at org.jboss.jms.server.container.SecurityAspect.handleSendTransaction(SecurityAspect.java:195)
 at sun.reflect.GeneratedMethodAccessor345.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:122)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
 at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
 at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.sendTransaction(ConnectionAdvised.java)
 at org.jboss.jms.wireformat.ConnectionSendTransactionRequest.serverInvoke(ConnectionSendTransactionRequest.java:82)
 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:908)
 at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:106)
 at org.jboss.remoting.Client.invoke(Client.java:1708)
 at org.jboss.remoting.Client.invoke(Client.java:612)
 at org.jboss.remoting.Client.invoke(Client.java:600)
 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.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$sendTransaction$aop(ClientConnectionDelegate.java:221)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeTarget(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86)
 at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
 at org.jboss.jms.client.delegate.ClientConnectionDelegate.sendTransaction(ClientConnectionDelegate.java)
 at org.jboss.jms.tx.ResourceManager.sendTransactionXA(ResourceManager.java:662)
 at org.jboss.jms.tx.ResourceManager.prepare(ResourceManager.java:337)
 at org.jboss.jms.tx.MessagingXAResource.prepare(MessagingXAResource.java:240)
 at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:271)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2893)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2850)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2402)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1790)
 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
 at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1414)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:657)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:243)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:213)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
 at java.lang.Thread.run(Thread.java:613)
2009-05-20 12:30:52,502 WARN [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-44) [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception XAException.XA_RETRY
2009-05-20 12:30:52,503 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-44) [com.arjuna.ats.arjuna.coordinator.BasicAction_50] - Prepare phase of action -3f57fe97:c872:4a142fc9:7795 received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD
2009-05-20 12:30:52,503 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-44) [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id -3f57fe97:c872:4a142fc9:7795 failed.
2009-05-20 12:30:52,503 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-44) [com.arjuna.ats.arjuna.coordinator.BasicAction_37] - Received heuristic: TwoPhaseOutcome.HEURISTIC_HAZARD .
2009-05-20 12:30:52,503 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-44) [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting
2009-05-20 12:30:52,504 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] (WorkManager(2)-44) org.jboss.resource.adapter.jms.inflow.JmsServerSession@8e4361 failed to commit/rollback
javax.transaction.HeuristicMixedException
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1422)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:657)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:243)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:213)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
 at java.lang.Thread.run(Thread.java:613)

The HeuristicMixedException worries me - and noticed that this ticket - https://cloud.prod.atl2.jboss.com:8443/jira/browse/JBESB-2483 seemed to indicate a possible problem in JBM? I wondered if you have seen it or had any advice on what to look at? I'm not saying there might not be a problem in the code - it is an MDB that communicates to an Oracle database and XA is in place across all sides of the transaction - also JBM is running on the same Oracle database (if that helps)

Thanks again for the quick response

P

[gaohoward]

Hi Phillip, please give some details of your application server deployment and the version of JBM.

The possible reason of the "Cannot find session with id" is that the session has been closed before the 'commit' request arrives.

How did you shutdown your application servers? and in what order? I'm asking these question because this might provide a clue to what has actually happened.

[philipdodds]

We are running on a JBoss 5.0.1GA base, though we needed the startDelivery and stopDelivery methods to exist on the MDB container therefore we upgraded the EJB 3.0 container to 1.1.4(?).

Judging from the log its a JBoss 1.4.1.GA server, this is just what came with the server.

2009-05-20 12:29:01,038 INFO [org.jboss.jms.server.ServerPeer] (main) JBoss Messaging 1.4.1.GA server [0] started

The shutdown we are seeing just being initiated by a control+C on the terminal. If we don't have messages processing the shutdown is clean.

Thanks again

P

[gaohoward]

Hi Phillp,

How many JBoss AS server instances are you running? Is the JBM running in one instance, and the MDB is running in another? Are they on the same machine or separate machines? If there are multiple instances, which one do you shut down first, which one second?

Thanks.

[philipdodds]

This is just a single JBoss instance, and the only one on the network while we are testing. The persistence if using Oracle 11g to a database on a second server.

Thanks again

P

[gaohoward]

ok, this is probably a service shutdown sequence issue between MDB and Transaction Service. You can ask AS guy for how to make sure the Transaction Service is shutdown before MDB services.

Or you may not kill the process while there is live transactions.

[philipdodds]

We have continued to work on this one - and have upgraded to the latest JBoss 5.1.0GA release.

This appears to have resolved the problem with the XA transaction - however we are using the stopDelivery method on the EJB3 MDB MBean and are getting a "session cannot be found" during the stopDelivery processing.

I'm not certain if it is a problem in the MDB container or the JBoss Messaging configuration, I have opened a discussion over on the EJB3 forum, see:

http://www.jboss.org/index.html?module=bb&op=viewtopic&t=155887

I really didn't want to cross post stuff but I was wondering if any JBM guys could spot something in the trace, it looks like it rolls back ok - and we are trying to work out whether this is a problem that we need to look into or just the way things are when you stop delivery.

Thanks again for all the help

[gaohoward]

Hi,

I think 'session cannot be found' can happen as I explained. To further verify my reasoning, you can try to find in the server's server.log if there is something like:

"A problem has been detected with the connection to remote client xxxxxxxxx, jmsClientID=xxxxxxxx. It is possible the client has exited without closing its connection(s) or the network has failed. All associated connection resources will be cleaned up."

If not, then I think the connection is probably shared by two or more threads, and one of the thread closed the connection without waiting for other threads finish their work with it. That should be viewed as an application level issue from JBM angle.

[gaohoward]

Sorry, actually the second case I supposed (shared connection) is unlikely to happen. As if it happened, there wouldn't be error messages like you have got. It should be detected by other clients before reaching that point.

[timfox]

I'm not familiar with this stopDelivery method - I guess this is something added by the EJB team.

Like Howard says, perhaps it is doing something illegal, but without seeing the code for it, it would be hard to tell.

[philipdodds]

Thanks for all the help and insight - I'll jump back over to EJB3 and see if maybe it is a configuration issue in the deployment or a problem in the EJB3 container (since stopDelivery was only recently added).

Thanks again

P

[philipdodds]

We are still looking into this - I had a quick question around the way in which a JBMActivation stops, it looks like you stop delivery and then start a teardown. As I'm following it when I choose stopDelivery on the MDB it then requested deactiveEndpoint in the reosource adapter which finally gets to call stop on the JBMActivation which sets deliveryActive to false then calls teardown on the JBMMessageHandler which releases the endpoint and closes the session.

If the message is currently being consumed shouldn't this be waiting for that transaction? I'm wondering if this is causing the session can not be found when the in-flight transaction completes?

All help is greatly appreciated :)