Bug 1023279 - Server log full of the warnings during periodic crash recovery with TIBCO and ActiveMQ running with JTS Transactions
Summary: Server log full of the warnings during periodic crash recovery with TIBCO and...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: JCA
Version: 6.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: ---
Assignee: Jeff Mesnil
QA Contact: Vladimir Rastseluev
Russell Dickenson
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-10-25 05:51 UTC by Ondrej Chaloupka
Modified: 2014-01-13 00:22 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-10-30 12:39:26 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Ondrej Chaloupka 2013-10-25 05:51:27 UTC
This issues refers to https://bugzilla.redhat.com/show_bug.cgi?id=1023193 but I'm getting different warning for different test scenario.

I run crash recovery test with TIBCO and generic JMS resouce adapter.
Transactions are set to be run with JTS. The tests uses MDB to receive messages. The server is crashed at the start of the commit method of the JMS XA resource. Then server is killed and then restarted to check the recovery works. As prepare was already done at first start the commit is expected.

During the recovery the server log contains following warning messages 'org.omg.CORBA.OBJECT_NOT_EXIST: Server-side Exception: unknown oid' [1]. When run with other messagings the server log is clean in this scenario.

WARN  [com.arjuna.ats.jts] (Periodic Recovery) ARJUNA022223: ExtendedResourceRecord.topLevelCommit caught exception: org.omg.CORBA.OBJECT_NOT_EXIST: Server-side Exception: unknown oid
 at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_45]
 at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_45]
 at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_45]
 at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_45]
 at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2-redhat-4.jar:2.3.2-redhat-4]
 at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2-redhat-4.jar:2.3.2-redhat-4]
 at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2-redhat-4.jar:2.3.2-redhat-4]
 at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2-redhat-4.jar:2.3.2-redhat-4]
 at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2-redhat-4.jar:2.3.2-redhat-4]
 at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.commit(_ArjunaSubtranAwareResourceStub.java:179) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelCommit(ExtendedResourceRecord.java:502) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2746) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2662) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1820) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.RecoveredTransaction.replayPhase2(RecoveredTransaction.java:197) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.TransactionCache.replayPhase2(TransactionCache.java:233) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.CachedRecoveredTransaction.replayPhase2(CachedRecoveredTransaction.java:173) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.TransactionRecoveryModule.recoverTransaction(TransactionRecoveryModule.java:217) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.TransactionRecoveryModule.periodicWorkSecondPass(TransactionRecoveryModule.java:161) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.jts.recovery.transactions.TopLevelTransactionRecoveryModule.periodicWorkSecondPass(TopLevelTransactionRecoveryModule.java:81) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]

Comment 2 Ondrej Chaloupka 2013-10-25 12:16:08 UTC
I found out that this errors does not

Comment 3 Ondrej Chaloupka 2013-10-25 12:19:56 UTC
I found out that this error does not occur just for TIBCO but the warn message can be found for ActiveMQ test as well. For this reason I've changed the component to 'Transaction Manager' as it seems to occur cross messagings. I think that this could be hit on WSMQ as well.

Comment 5 tom.jenkinson 2013-10-25 16:06:47 UTC
Hi Ondra,

Does the test pass for you? For me it seems to. You would expect those messages in the log at various times of recovery as until the server recovers the recovery manager has a reference to the now dead connection details (ip/port).

What is meant to happen is that bottomUp recovery will notify the recovery manager and everything should work out OK, as the test doesn't fail I am assuming that is what is happening?

Does the test detect failure scenarios and fail surefire appropriately?

Tom

Comment 8 tom.jenkinson 2013-10-28 15:06:37 UTC
This is the (initial) issue for ActiveMQ, not sure if it is the same for Tibco as I can't access it for the purposes of testing:

15:05:22,433 ERROR [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) IJ000906: Error during crash recovery: java:/JmsXA (Could not create connection.): javax.resource.ResourceException: Could not create connection.
	at org.apache.activemq.ra.ActiveMQManagedConnectionFactory.createManagedConnection(ActiveMQManagedConnectionFactory.java:190)
	at org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl.open(XAResourceRecoveryImpl.java:343)
	at org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl.getXAResources(XAResourceRecoveryImpl.java:170)
	at com.arjuna.ats.internal.jbossatx.jta.XAResourceRecoveryHelperWrapper.getXAResources(XAResourceRecoveryHelperWrapper.java:51) [jbossjts-integration-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.resourceInitiatedRecoveryForRecoveryHelpers(XARecoveryModule.java:503) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:171) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.12.Final-redhat-1.jar:4.17.12.Final-redhat-1]
Caused by: javax.jms.JMSException: Could not create Transport. Reason: java.io.IOException: Transport scheme NOT recognized: [tcp]
	at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:36) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQConnectionFactory.java:260) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(ActiveMQConnectionFactory.java:273) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.ActiveMQConnectionFactory.createConnection(ActiveMQConnectionFactory.java:194) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.ra.ActiveMQConnectionSupport.makeConnection(ActiveMQConnectionSupport.java:79)
	at org.apache.activemq.ra.ActiveMQConnectionSupport.makeConnection(ActiveMQConnectionSupport.java:61)
	at org.apache.activemq.ra.ActiveMQManagedConnectionFactory.createManagedConnection(ActiveMQManagedConnectionFactory.java:188)
	... 7 more
Caused by: java.io.IOException: Transport scheme NOT recognized: [tcp]
	at org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport.java:27) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.transport.TransportFactory.findTransportFactory(TransportFactory.java:178) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.transport.TransportFactory.connect(TransportFactory.java:63) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	at org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQConnectionFactory.java:258) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	... 12 more
Caused by: java.lang.ClassCastException: org.apache.activemq.transport.tcp.TcpTransportFactory cannot be cast to org.apache.activemq.transport.TransportFactory
	at org.apache.activemq.transport.TransportFactory.findTransportFactory(TransportFactory.java:175) [activemq-client-5.8.0.redhat-60024.jar:5.8.0.redhat-60024]
	... 14 more


Jeff, I will assign this to you, let me know if you have a problem with that.

Comment 9 tom.jenkinson 2013-10-28 15:34:16 UTC
Jeff, if you read my notes above you will see I didn't actually get a problem running tibco initially but haven't been able to verify it as I can't connect now. It could be that there are two issues:

1. the tibco issue may not be an issue if for example there are no failures the stack traces are expected as I mention above (Ondra to raise docs issue if that is the case)

2. the AMQ issue may be real, see my ClassCastException above

It may need two different BZ to deal with this if there are two different causes.

Comment 10 Ondrej Chaloupka 2013-10-29 16:53:07 UTC
Hi Tom,

the test passes. It seems there is no problem with functionality of crash recovery. There is just those warnings in the server log.
The surefire should be set correctly. At least I think so.

I've checked the recovery process a bit deeper and I think that you are right. If I can quote you "you would expect those messages in the log at various times of recovery as until the server recovers the recovery manager has a reference to the now dead connection details (ip/port)". The server throws the warning messages after the start and when the recovery starts then the log is warning messages free.

I would have just one more question - there is interesting fact that the warning messages are not shown in case of the halting server at prepare phase. Which means that the rollback is expected. The test is absolutely the same just the server is halt in different phase of the 2PC.
Do you think that this would say something about this issue?
In case that there is no suspicion that the the fact above could mean that some issue really exists I will close this bug as "NOT A BUG".


I'm not able to reproduce your case from the comment https://bugzilla.redhat.com/show_bug.cgi?id=1023279#c8. I would rather say that there is rather some problem with starting the ActiveMQ server than a problem with recovery.

Comment 12 tom.jenkinson 2013-10-30 12:07:08 UTC
Hi Ondra, 

If you halt in prepare we won't have logged anything about the resources so it will all be bottom up recovery so you wouldn't get the exceptions. Hope that clarifies.

Its strange that you don't see c8, maybe I have the wrong version of something (I just saw activemq-client-5.8.0.redhat-60024.jar in the log, I guess that should be 5.9). Either way, I guess this issue is resolved or do you like that I look further into it?

Tom

Comment 13 Ondrej Chaloupka 2013-10-30 12:39:26 UTC
Hi Tom,

ok, thank you for clarification. I agree this issue is not a bug.

Thank you for checking it
Ondra


Note You need to log in before you can comment on or make changes to this bug.