In Soak test for ActiveMQ [1]resource adapter there WARN messages like: 12:23:07 [0m[33m12:23:07,915 WARN [com.arjuna.ats.arjuna] (Periodic Recovery) Could not query objectstore: : java.io.IOException: java.lang.NullPointerException 12:23:07 at com.arjuna.ats.arjuna.StateManager.unpackHeader(StateManager.java:732) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 at com.arjuna.ats.internal.jta.recovery.arjunacore.RecoverConnectableAtomicAction.<init>(RecoverConnectableAtomicAction.java:52) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 at com.arjuna.ats.internal.jta.recovery.arjunacore.CommitMarkableResourceRecordRecoveryModule.periodicWorkFirstPass(CommitMarkableResourceRecordRecoveryModule.java:379) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 Caused by: java.lang.NullPointerException 12:23:07 at com.arjuna.ats.arjuna.StateManager.unpackHeader(StateManager.java:697) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 12:23:07 ... 4 more 12:23:07 15:16:36 [0m[33m15:16:36,247 WARN [com.arjuna.ats.arjuna] (Periodic Recovery) Could not query objectstore: : com.arjuna.ats.arjuna.exceptions.ObjectStoreException: ShadowingStore::read_state error: java.io.FileNotFoundException: /tmp/activemq-soak/ibm-mq-testsuite/src/test/config/activemq/install/target/jboss-eap/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a106418_-2b02421b_534ffd61_4c1764 (No such file or directory) 15:16:36 at com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore.read_state(ShadowingStore.java:412) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 at com.arjuna.ats.internal.arjuna.objectstore.FileSystemStore.read_committed(FileSystemStore.java:98) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 at com.arjuna.ats.internal.jta.recovery.arjunacore.RecoverConnectableAtomicAction.<init>(RecoverConnectableAtomicAction.java:48) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 at com.arjuna.ats.internal.jta.recovery.arjunacore.CommitMarkableResourceRecordRecoveryModule.periodicWorkFirstPass(CommitMarkableResourceRecordRecoveryModule.java:379) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 Caused by: java.io.FileNotFoundException: /tmp/activemq-soak/ibm-mq-testsuite/src/test/config/activemq/install/target/jboss-eap/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff0a106418_-2b02421b_534ffd61_4c1764 (No such file or directory) 15:16:36 at java.io.FileInputStream.open(Native Method) [rt.jar:1.7.0_51] 15:16:36 at java.io.FileInputStream.<init>(FileInputStream.java:146) [rt.jar:1.7.0_51] 15:16:36 at com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore.read_state(ShadowingStore.java:406) [jbossjts-jacorb-4.17.18.Final-redhat-1.jar:4.17.18.Final-redhat-1] 15:16:36 ... 5 more 15:16:36 This happens only during periodic recovery and appears to be harmless for data integrity. [1] https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EAP6/view/EAP6-ActiveMQ/job/eap6-activemq-soak-clone/10/jdk=java17_default,label_exp=messaging-10||messaging-11||messaging-12||messaging-13||messaging-14||messaging-15/consoleText
Hi, under load it is expected that these messages can occur. Basically at one time the tx exists on disk, the next it doesn't as the main thread has committed it so you get errors as you see have observed. There is an algorithm I could use to minimize the likelihood of it - e.g. we can add the uid of not running tx to a list and only recover these after its still in the list after a couple of iterations of the recovery manager. My preference is to not make a code change unless customer demand is high for it, but I have raised a community feature request over here: https://issues.jboss.org/browse/JBTM-2159 I would also recommend that this behaviour be documented so would suggest updating this BZ to a documentation bug.
Hi Tom, there is one trouble with this behavior. As I was advised some of our customers are touchy about warnings in the logs and especially from transactions. And warning with NPE is then the harder case. Wouldn't be possible, at least, somelike handle the NPE?
Handling the NPE is dealing with the after effects, in that regard we could consider just downgrading the log messages. My preference is to document it and implement the enhancement if we get enough "votes".
Ok, I see. But when I imagine myself as a customer who get the NPE in the log I don't know... If this error does not hide any other problem could you put the log severity to debug for customers won't see it in normal cases?
But if it was in the documentation they would know about it :) However, I will take another look to see if there is a less invasive option than I initially see. It's core code to the transaction manager and making major changes for a cosmetic change is not always the best approach.
OK, I managed to fix the NPE (it was a bug - sorry!), the FileNotFound I am still looking into.
OK, so the NPE is a bug, but the FileNotFound we are not happy to remove as it can happen for bad reasons too. I will downgrade the logging to INFO though, is that better?
When I say "bad reasons" - I mean user error (deleting object store etc) so I need to make sure the user hasn't done that, hence I need to put some INFO out.
Hi Tom, the change to INFO is not the solution for us. The reason why we want to change the log level to DEBUG is that customer would not see NPE in log for standard configuration. Change to INFO would not solve that. Do you think that the root cause could be fixed for 6.3.0 release? Thanks Ondra
I realize my error. The Narayana is put under warning (WARN) log level by default. So the info level could be sufficient to avoid the user to see it.
Tom Jenkinson <tom.jenkinson> updated the status of jira JBTM-2159 to Resolved
Fixed by https://bugzilla.redhat.com/show_bug.cgi?id=1097673
There was no 100% reproducer but I don't see those warnings any more in our jobs. Setting as verified.
Tom Jenkinson <tom.jenkinson> updated the status of jira JBTM-2159 to Closed