Bug 1089251 - WARN [com.arjuna.ats.arjuna] (Periodic Recovery) Could not query objectstore: : java.io.IOException: java.lang.NullPointerException
Summary: WARN [com.arjuna.ats.arjuna] (Periodic Recovery) Could not query objectstore...
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: Transaction Manager
Version: 6.3.0
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ER5
: EAP 6.3.0
Assignee: tom.jenkinson
QA Contact: Ondrej Chaloupka
URL:
Whiteboard:
Keywords:
Depends On:
Blocks: 1097673
TreeView+ depends on / blocked
 
Reported: 2014-04-18 11:01 UTC by Miroslav Novak
Modified: 2017-10-10 00:15 UTC (History)
5 users (show)

(edit)
Clone Of:
(edit)
Last Closed: 2014-06-28 15:30:19 UTC


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
JBoss Issue Tracker JBTM-2159 Major Closed It is possible for the CommitMarkableResource recovery manager to attempt to activate an AtomicAction while it is being ... 2016-11-08 15:00 UTC

Description Miroslav Novak 2014-04-18 11:01:52 UTC
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

Comment 1 tom.jenkinson 2014-04-24 19:16:45 UTC
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.

Comment 2 Ondrej Chaloupka 2014-04-25 12:14:11 UTC
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?

Comment 3 tom.jenkinson 2014-04-25 12:35:02 UTC
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".

Comment 4 Ondrej Chaloupka 2014-04-25 12:56:27 UTC
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?

Comment 5 tom.jenkinson 2014-04-25 13:08:40 UTC
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.

Comment 6 tom.jenkinson 2014-04-28 07:22:42 UTC
OK, I managed to fix the NPE (it was a bug - sorry!), the FileNotFound I am still looking into.

Comment 7 tom.jenkinson 2014-05-01 11:09:25 UTC
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?

Comment 8 tom.jenkinson 2014-05-01 11:10:07 UTC
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.

Comment 9 Ondrej Chaloupka 2014-05-05 09:27:57 UTC
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

Comment 10 Ondrej Chaloupka 2014-05-06 12:10:17 UTC
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.

Comment 11 JBoss JIRA Server 2014-05-08 14:41:11 UTC
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2159 to Resolved

Comment 12 Kabir Khan 2014-05-15 08:06:47 UTC
Fixed by https://bugzilla.redhat.com/show_bug.cgi?id=1097673

Comment 13 Miroslav Novak 2014-05-30 13:01:29 UTC
There was no 100% reproducer but I don't see those warnings any more in our jobs. Setting as verified.

Comment 14 JBoss JIRA Server 2014-09-15 12:49:31 UTC
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2159 to Closed


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