There is logged an confusing error after crash recovery happens when server crashed in prepare phase. 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 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.
Michael Musgrove <mmusgrov> made a comment on jira JBTM-1867 The hornetq store is the only one which throws an exception if we try to remove an entry which isn't in the log so, as Mark suggests, we should change the hornetq store to do likewise (with a warning message). Note, the different store implementations behave as follows: * VolatileStore, TwoPhaseVolatileStore, CacheStore and ShadowingStore all return false if the entry isn't in the log * JDBCStore logs a warning (message id 12255) and then returns false * LogStore always returns true
Mark Little <mark.little> made a comment on jira JBTM-1867 Yes, LogStore doesn't check whether the state is available in the log at the point where remove_committed is called since all we do is write a "remove state" entry to the log for later processing. If that later processing fails then a warning message should be output as with the other stores.
Michael Musgrove <mmusgrov> made a comment on jira JBTM-1867 The bug report is asking for the exception to be logged at debug or trace but it is not possible to infer whether the transaction log entry has been removed because of a previous rollback attempt or for some other reason (perhaps the tooling has inadvertently removed it). Therefore I don't think it is a good idea to reduce the severity of log statement. Onrej, would you mind if I close the jira as will not fix or can you suggest an alternate way of resolving this issue.
Ondřej Chaloupka <ochaloup> made a comment on jira 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
Michael Musgrove <mmusgrov> made a comment on jira JBTM-1867 The error we get from the hornetq journal is IllegalState which if we look at the hornetq source is only thrown if the entry does not exists so I can easily add a warning message. So what I propose is: - log a warning if hornetq throws an IllegalState exception - otherwise I will log a warning and include the full stacktrace Feel free to discus with Tom and let me know what you decide (I am on leave until Wed)
Hi Mike, this solution seems to me nice. If you can do it I'll fully agree. Thank you Ondra
Michael Musgrove <mmusgrov> updated the status of jira JBTM-1867 to Closed
Went into 4.17.9
Verified on revision EAP 6.4.0.DR12. Now it is logged as WARN.