[jbossts-issues] [JBoss JIRA] (JBTM-1867) Confusing error logged after crash recovery on prepare when hornetq object store used

Ondřej Chaloupka (JIRA) jira-events at lists.jboss.org
Fri Aug 16 08:03:26 EDT 2013


    [ https://issues.jboss.org/browse/JBTM-1867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12797292#comment-12797292 ] 

Ondřej Chaloupka commented on JBTM-1867:
----------------------------------------

Hi Mike,

I'm sorry for longer response time.
I do understand that it's hard (or impossible) to detect the second round of the rollback but it's when the circumstances occur then the log is full of nasty messages. And it's true that is not every day scenario to see such messages but still it's not much kind to user to show him error messages in case that no error occurs.

Maybe at least would be better to log that message by logger than to stderr? But of course I'm not sure whether there is some reason for such behaviour. 
Or maybe to reduce the severity to INFO? By default messages from com.arjuna are logged (shown to user) from severity WARN and higher. But probably this is not good solution either as Mark pointed.

I can live with such error messages in this log but I don't like it.

Do you mind to discuss this with Tom next week?

Thank you
Ondra
                
> Confusing error logged after crash recovery on prepare when hornetq object store used
> -------------------------------------------------------------------------------------
>
>                 Key: JBTM-1867
>                 URL: https://issues.jboss.org/browse/JBTM-1867
>             Project: JBoss Transaction Manager
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: JTS
>    Affects Versions: 4.17.7, 5.0.0.M3
>            Reporter: Ondřej Chaloupka
>            Assignee: Michael Musgrove
>
> There is logged an confusing error after crash recovery happens when server crashed in prepare phase.
> {code}
> 14:47:59,697 ERROR [stderr] (RequestProcessor-10) com.arjuna.ats.arjuna.exceptions.ObjectStoreException: java.lang.IllegalStateException: Cannot find add info 3
> 14:47:59,698 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ats.internal.arjuna.objectstore.hornetq.HornetqJournalStore.remove_committed(HornetqJournalStore.java:153)
> 14:47:59,698 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ats.internal.arjuna.objectstore.hornetq.HornetqObjectStoreAdaptor.remove_committed(HornetqObjectStoreAdaptor.java:186)
> 14:47:59,698 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.destroyState(XAResourceRecord.java:1271)
> 14:47:59,699 INFO  [org.jboss.as.test.jbossts.common.TestXAResourceCommon] (Periodic Recovery) TestXAResourceCommon.isSameRM(xaResource=TestXAResourceRecovered(TestXAResourceCommon(0, null)))
> 14:47:59,699 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.rollback(XAResourceRecord.java:411)
> 14:47:59,699 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ArjunaOTS.OTSAbstractRecordPOA._invoke(OTSAbstractRecordPOA.java:213)
> 14:47:59,699 ERROR [stderr] (RequestProcessor-10) 	at org.jacorb.poa.RequestProcessor.invokeOperation(RequestProcessor.java:306)
> 14:47:59,699 ERROR [stderr] (RequestProcessor-10) 	at org.jacorb.poa.RequestProcessor.process(RequestProcessor.java:626)
> 14:47:59,699 ERROR [stderr] (RequestProcessor-10) 	at org.jacorb.poa.RequestProcessor.run(RequestProcessor.java:769)
> 14:47:59,700 ERROR [stderr] (RequestProcessor-10) Caused by: java.lang.IllegalStateException: Cannot find add info 3
> 14:47:59,700 ERROR [stderr] (RequestProcessor-10) 	at org.hornetq.core.journal.impl.JournalImpl.appendDeleteRecord(JournalImpl.java:904)
> 14:47:59,700 ERROR [stderr] (RequestProcessor-10) 	at org.hornetq.core.journal.impl.JournalBase.appendDeleteRecord(JournalBase.java:163)
> 14:47:59,700 ERROR [stderr] (RequestProcessor-10) 	at org.hornetq.core.journal.impl.JournalImpl.appendDeleteRecord(JournalImpl.java:82)
> 14:47:59,701 ERROR [stderr] (RequestProcessor-10) 	at com.arjuna.ats.internal.arjuna.objectstore.hornetq.HornetqJournalStore.remove_committed(HornetqJournalStore.java:151)
> 14:47:59,701 ERROR [stderr] (RequestProcessor-10) 	... 7 more
> {code}
> This happens when hornetq object store is used. This is caused because of the rollback is called on resource two times. This is ok - this matches to OTS spec (https://bugzilla.redhat.com/show_bug.cgi?id=988724).
> But after the second call of rollback the TM tries to remove Xid from object store. But as the xid does not exist anymore the hornetq object store implementation throws exception that is logged directly on stderr:
> XAResourceRecord.destroyState does e.printStackTrace()
> I would propose to put this exception to debug or trace as it does not mean error in fact.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira



More information about the jbossts-issues mailing list