[JBoss JIRA] (JBTM-2273) Admin CLI build failed
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-2273?page=com.atlassian.jira.plugin.... ]
Amos Feng resolved JBTM-2273.
-----------------------------
Resolution: Done
> Admin CLI build failed
> ----------------------
>
> Key: JBTM-2273
> URL: https://issues.jboss.org/browse/JBTM-2273
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: BlackTie
> Reporter: Gytis Trikleris
> Assignee: Amos Feng
> Fix For: 5.0.4
>
>
> http://172.17.131.2/view/Status/job/narayana-quickstarts/112/
> {code}
> [INFO] ------------------------------------------------------------------------
> [INFO] Building BlackTie Admin CLI Tool 5.0.4.Final-SNAPSHOT
> [INFO] ------------------------------------------------------------------------
> [INFO]
> [INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ btadmin ---
> [INFO]
> [INFO] --- maven-enforcer-plugin:1.3.1:enforce (enforce-java-version) @ btadmin ---
> [INFO]
> [INFO] --- maven-enforcer-plugin:1.3.1:enforce (enforce-maven-version) @ btadmin ---
> [INFO]
> [INFO] --- buildnumber-maven-plugin:1.2:create-timestamp (get-build-timestamp) @ btadmin ---
> [INFO]
> [INFO] --- buildnumber-maven-plugin:1.2:create (get-scm-revision) @ btadmin ---
> [INFO]
> [INFO] --- maven-dependency-plugin:2.8:unpack-dependencies (unpack-test-dependencies) @ btadmin ---
> [INFO] Unpacking /home/hudson/.m2/repository/apache-log4cxx/contrib/log4cxx/902683/log4cxx-902683-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/.m2/repository/junit/junit/4.11/junit-4.11.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/.m2/repository/apr-1/contrib/apr-1/1.3.3/apr-1-1.3.3-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/codec/target/blacktie-codec-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/core/target/blacktie-core-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/tx/target/blacktie-tx-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/transport/target/blacktie-transport-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/.m2/repository/xml-apis/xml-apis/1.3.04/xml-apis-1.3.04.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/.m2/repository/xerces/xercesImpl/2.9.1/xercesImpl-2.9.1.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/xatmi/target/blacktie-xatmi-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/xsd/target/blacktie-xsd-5.0.4.Final-SNAPSHOT.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO] Unpacking /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/hybrid/target/blacktie-hybrid-5.0.4.Final-SNAPSHOT-centos54x64.jar to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cxx/test with includes "**/*" and excludes ""
> [INFO]
> [INFO] --- maven-dependency-plugin:2.8:copy-dependencies (copy-dependencies) @ btadmin ---
> [INFO] Copying protoc-2.4.1.3-centos54x64.zip to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/dependencies/protoc-2.4.1.3-centos54x64.zip
> [INFO] Copying xercesc-3.0.1-centos54x64.zip to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/dependencies/xercesc-3.0.1-centos54x64.zip
> [INFO]
> [INFO] --- maven-antrun-plugin:1.7:run (unzip) @ btadmin ---
> [WARNING] Parameter tasks is deprecated, use target instead
> [INFO] Executing tasks
> main:
> [echo] unzip dependencies to test
> [INFO] Executed tasks
> [INFO]
> [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ btadmin ---
> [INFO] Using 'UTF-8' encoding to copy filtered resources.
> [INFO] Copying 1 resource
> [INFO]
> [INFO] --- maven-compiler-plugin:3.1:compile (default-compile) @ btadmin ---
> [INFO] Changes detected - recompiling the module!
> [INFO] Compiling 18 source files to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/classes
> [WARNING] /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/src/main/java/org/jboss/narayana/blacktie/btadmin/commands/Help.java:[129,50] decode(java.lang.String) in java.net.URLDecoder has been deprecated
> [WARNING] /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/src/main/java/org/jboss/narayana/blacktie/btadmin/commands/Shutdown.java: Some input files use unchecked or unsafe operations.
> [WARNING] /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/src/main/java/org/jboss/narayana/blacktie/btadmin/commands/Shutdown.java: Recompile with -Xlint:unchecked for details.
> [INFO]
> [INFO] --- blacktie-cpp-plugin:5.0.4.Final-SNAPSHOT:process-classes (process-classes) @ btadmin ---
> copy-check:
> init:
> package:
> [mkdir] Created dir: /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/classes/lib
> [mkdir] Created dir: /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/classes/include
> copy-idl:
> copy-includes:
> copy-libs:
> process-classes:
> [INFO]
> [INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ btadmin ---
> [INFO] Using 'UTF-8' encoding to copy filtered resources.
> [INFO] Copying 3 resources
> [INFO]
> [INFO] --- maven-compiler-plugin:3.1:testCompile (default-testCompile) @ btadmin ---
> [INFO] Changes detected - recompiling the module!
> [INFO] Compiling 12 source files to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/test-classes
> [INFO]
> [INFO] --- blacktie-cpp-plugin:5.0.4.Final-SNAPSHOT:test-compile (test-compile) @ btadmin ---
> init:
> fileset.test.check:
> [echo] src/test/cpp **/*.c*
> gen-test-runner1:
> gen-test-runner2:
> gen-test-runner:
> package:
> test-compile:
> [INFO]
> [INFO] --- blacktie-cpp-plugin:5.0.4.Final-SNAPSHOT:generate-exe (generate-exe) @ btadmin ---
> init:
> init-cpp-test:
> [mkdir] Created dir: /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cpp-test-classes
> [copy] Copying 3 files to /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/target/cpp-test-classes
> generate-exe:
> libnames not specified or empty.
> libnames not specified or empty.
> [cc] 1 total files to be compiled.
> [cc] /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/src/test/cpp/cs.cxx: In function ‘int main(int, char**)’:
> [cc] /home/hudson/workspace/narayana-quickstarts/narayana/blacktie/btadmin/src/test/cpp/cs.cxx:31:39: warning: deprecated conversion from string constant to ‘char*’ [-Wwrite-strings]
> [cc] putenv("BLACKTIE_CONFIGURATION=linux");
> [cc] ^
> [cc] Starting link
> [cc] /lib64/libaprutil-1.so.0: undefined reference to `apr_pool_pre_cleanup_register'
> [cc] collect2: error: ld returned 1 exit status
> [INFO] ------------------------------------------------------------------------
> [INFO] Reactor Summary:
> [INFO]
> [INFO] Blacktie C++ Plugin ............................... SUCCESS [8.183s]
> [INFO] BlackTie all files ................................ SUCCESS [0.626s]
> [INFO] Blacktie Defaults and Dependencies ................ SUCCESS [0.032s]
> [INFO] Blacktie C Defaults and Dependencies .............. SUCCESS [21.098s]
> [INFO] Blacktie Java JNI Tests ........................... SUCCESS [1.017s]
> [INFO] Blacktie Schemas .................................. SUCCESS [0.252s]
> [INFO] Blacktie CORBA Transport .......................... SUCCESS [0.018s]
> [INFO] Blacktie CORBA Transport Java Bindings ............ SUCCESS [1.057s]
> [INFO] BlackTie Messaging (via JMS) ...................... SUCCESS [10.750s]
> [INFO] Blacktie Java XATMI Implementation ................ SUCCESS [5.635s]
> [INFO] Blacktie Java NBF Implementation .................. SUCCESS [0.228s]
> [INFO] Blacktie Administration Services .................. SUCCESS [1:22.245s]
> [INFO] Blacktie Administration Services EAR .............. SUCCESS [2.325s]
> [INFO] Blacktie Core C++ Implementation .................. SUCCESS [13.134s]
> [INFO] Blacktie Codec C++ Implementation ................. SUCCESS [16.424s]
> [INFO] Blacktie C++ REST Transport ....................... SUCCESS [5.257s]
> [INFO] Blacktie Utilities ................................ SUCCESS [3.695s]
> [INFO] Blacktie C++ TX Client Library .................... SUCCESS [8.486s]
> [INFO] Blacktie C++ Hybrid Transport ..................... SUCCESS [6.268s]
> [INFO] Blacktie C++ XATMI Implementation ................. SUCCESS [7.711s]
> [INFO] Blacktie C++ Queue Client ......................... SUCCESS [4.280s]
> [INFO] Blacktie NBF ...................................... SUCCESS [5.005s]
> [INFO] BlackTie Admin CLI Tool ........................... FAILURE [1.831s]
> [INFO] Blacktie Server Code Generation ................... SKIPPED
> [INFO] Blacktie Java/C C/Java XATMI Tests ................ SKIPPED
> [INFO] Blacktie Distribution ............................. SKIPPED
> [INFO] ------------------------------------------------------------------------
> [INFO] BUILD FAILURE
> [INFO] ------------------------------------------------------------------------
> [INFO] Total time: 3:26.487s
> [INFO] Finished at: Sat Oct 18 01:28:34 BST 2014
> [INFO] Final Memory: 65M/431M
> [INFO] ------------------------------------------------------------------------
> [ERROR] Failed to execute goal org.jboss.narayana.blacktie.plugins:blacktie-cpp-plugin:5.0.4.Final-SNAPSHOT:generate-exe (generate-exe) on project btadmin: Failed to execute: Executing Ant script: /btcpp.build.xml [generate-exe]: Failed to execute. gcc failed with return code 1 -> [Help 1]
> [ERROR]
> [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
> [ERROR] Re-run Maven using the -X switch to enable full debug logging.
> [ERROR]
> [ERROR] For more information about the errors and possible solutions, please read the following articles:
> [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
> [ERROR]
> [ERROR] After correcting the problems, you can resume the build with the command
> [ERROR] mvn <goals> -rf :btadmin
> UID PID PPID C STIME TTY TIME CMD
> hudson 2525 2522 0 Oct10 ? 00:08:00 sshd: hudson@notty
> hudson 2568 2525 0 Oct10 ? 00:00:00 bash -c cd '/home/hudson' && java -jar slave.jar
> hudson 2575 2568 0 Oct10 ? 01:36:55 java -jar slave.jar
> hudson 3261 32389 0 01:28 ? 00:00:00 ps -f
> hudson 32369 2575 0 01:07 ? 00:00:00 /bin/bash -xe /tmp/hudson884782302161251351.sh
> hudson 32389 32369 0 01:07 ? 00:00:00 /bin/bash -xe /tmp/hudson884782302161251351.sh
> pkill: killing pid 2468 failed: Operation not permitted
> pkill: killing pid 298 failed: Operation not permitted
> pkill: killing pid 299 failed: Operation not permitted
> pkill: killing pid 300 failed: Operation not permitted
> pkill: killing pid 301 failed: Operation not permitted
> pkill: killing pid 302 failed: Operation not permitted
> pkill: killing pid 303 failed: Operation not permitted
> pkill: killing pid 304 failed: Operation not permitted
> pkill: killing pid 305 failed: Operation not permitted
> pkill: killing pid 306 failed: Operation not permitted
> pkill: killing pid 307 failed: Operation not permitted
> pkill: killing pid 308 failed: Operation not permitted
> pkill: killing pid 309 failed: Operation not permitted
> pkill: killing pid 310 failed: Operation not permitted
> pkill: killing pid 311 failed: Operation not permitted
> pkill: killing pid 312 failed: Operation not permitted
> pkill: killing pid 313 failed: Operation not permitted
> pkill: killing pid 314 failed: Operation not permitted
> pkill: killing pid 323 failed: Operation not permitted
> pkill: killing pid 324 failed: Operation not permitted
> pkill: killing pid 327 failed: Operation not permitted
> pkill: killing pid 328 failed: Operation not permitted
> pkill: killing pid 331 failed: Operation not permitted
> pkill: killing pid 332 failed: Operation not permitted
> pkill: killing pid 333 failed: Operation not permitted
> UID PID PPID C STIME TTY TIME CMD
> hudson 2525 2522 0 Oct10 ? 00:08:00 sshd: hudson@notty
> hudson 2568 2525 0 Oct10 ? 00:00:00 bash -c cd '/home/hudson' && java -jar slave.jar
> hudson 2575 2568 0 Oct10 ? 01:36:55 java -jar slave.jar
> hudson 3272 32389 0 01:28 ? 00:00:00 ps -f
> hudson 32369 2575 0 01:07 ? 00:00:00 /bin/bash -xe /tmp/hudson884782302161251351.sh
> hudson 32389 32369 0 01:07 ? 00:00:00 /bin/bash -xe /tmp/hudson884782302161251351.sh
> Some tests failed: http://172.17.131.2/job/narayana-quickstarts/112/
> Build step 'Execute shell' marked build as failure
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Christian von Kutzleben (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Christian von Kutzleben commented on JBTM-2287:
-----------------------------------------------
Tom, the XAResource itself remains functional, but all(*) subsequent calls will fail until the database has restarted and a connection can be reestablished,
after that all calls should succeed again.
(*) our provoked database crash/shutdown is not really atomic and with JTA we see that a rollback succeeds right after the failed prepare, and then
the database is really shutdown
I'm using 4.17.15 and I don't see a rollback invocation with JTS on our XAResource; even if rollback were called -- like in the JTA case --;
rollback might report success, but the database might shut down right after that and upon restart, the transaction was revived by the
database recovery system and waits for a decision by the TM.
So what we expect from the fix is, that our recovery XAResource is advised to rollback this transaction.
Specifically, even if you change something, so that now information is kept about this transactions outcome, it's hard
for you to know, when you can drop this information, because a rollback might have been successfully issued to all XAResources,
but because rollbacks are not f-synced in the database log and immediate crashing afterwards might revive these transactions
as dead to-be-recovered transactions.
Which means, if you don't keep information for this transaction for forever, then you should -- as Mike suggested -- presume abort.
What we don't expect - but it would not harm either - is that rollback is called by the regular commit code.
What we also don't expect - but it would be nice to have - is preventing the double end invocation.
Btw. we have seen double-ends before, even with JTA, e.g. if the first end(tmsuccess) raises an XAException, then
a second end(tmfail) is issued. Since we've found that out, we have a workaround in place to ignore double end invocations.
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson commented on JBTM-2287:
-------------------------------------
I have written a test that even without Marks fix seems to work for a DummyXAResource: https://github.com/tomjenkinson/narayana/compare/jbosstm:master...tomjenk...
Can you give a few more details of what you are expecting? Do all calls on this XAResource after the prepare failure fail until periodic recovery kicks in and uses a new XAResource instance which does have a connection to the database or is it really just the one call to prepare that is meant to be failing?
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Mark Little (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Mark Little edited comment on JBTM-2287 at 11/14/14 7:04 AM:
-------------------------------------------------------------
Mike, we fail in prepare to there's no log. However, you're right in so much that recovery should eventually check the db and get the xid for the prepared resource. Since we don't have a log entry we should fall to presumed abort and roll it back. So you are correct in wondering why it doesn't kick in.
I'd like to know why JTA works and JTS doesn't.
was (Author: marklittle):
Mike, we fail in prepare to there's no log. However, you're right in so much that recovery should eventually check the db and get the xid for the prepared resource. Since we don't have a log entry we should fall to presumed abort and roll it back.
I'd like to know why JTA works and JTS doesn't.
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Mark Little (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Mark Little commented on JBTM-2287:
-----------------------------------
Mike, we fail in prepare to there's no log. However, you're right in so much that recovery should eventually check the db and get the xid for the prepared resource. Since we don't have a log entry we should fall to presumed abort and roll it back.
I'd like to know why JTA works and JTS doesn't.
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2121) Add a jdbc object store implementation for later revisions of MySQL driver
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/JBTM-2121?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration commented on JBTM-2121:
-----------------------------------------------
Martin Simka <msimka(a)redhat.com> changed the Status of [bug 1097166|https://bugzilla.redhat.com/show_bug.cgi?id=1097166] from CLOSED to NEW
> Add a jdbc object store implementation for later revisions of MySQL driver
> --------------------------------------------------------------------------
>
> Key: JBTM-2121
> URL: https://issues.jboss.org/browse/JBTM-2121
> Project: JBoss Transaction Manager
> Issue Type: Task
> Affects Versions: 4.17.17, 5.0.1
> Reporter: Tom Jenkinson
> Assignee: Tom Jenkinson
> Fix For: 4.17.20, 5.0.2
>
>
> commit 44553931 updated the MySQl driver to 5.1.28.
> In this revision of the driver, it is reporting as mysql, not mysql_ab. It should be possible to duplicate our mysql_ab_driver to mysql_driver in order to catch both cases.
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Christian von Kutzleben (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Christian von Kutzleben commented on JBTM-2287:
-----------------------------------------------
@Michael: here is the entire log file output (it's not that long), from the bean invocation which (artificially) kills the database, after prepare, before returning
the result; up to a successful bean invocation after the database has been restarted automatically after the crash and after that the recovery attempts.
Let me know, if you need more information. Note, that Xids logged by us in this output use a different toString() because of JBTM-2284
09:59:45,005 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 4) start flags=TMNOFLAGS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:45,006 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 4) start created Versant TxnId 5641.0.4109 for Xid 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:45,012 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 4) start flags=TMNOFLAGS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.76.0.0.0.0.0.0.0.0
09:59:45,012 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 4) start created Versant TxnId 5642.0.4106 for Xid 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.76.0.0.0.0.0.0.0.0
09:59:45,044 INFO [stdout] (EJB default - 4) About to terminate db server 0
09:59:45,047 INFO [stdout] (EJB default - 4) Crashhook set.
09:59:45,054 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) end flags=TMSUCCESS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:45,055 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) prepare xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:46,890 WARN [com.arjuna.ats.jtax] (RequestProcessor-5) ARJUNA024015: XAResource prepare failed on resource com.versant.odbms.XAResourceImpl@2eed27ad for transaction < 131072, 29, 36, 0000000000-1-1101065041-50-615010084100114-110007049, 292929292929292929292828391357970-21-327912911312914318292929997829292929292929 > with: XAException.XAER_RMFAIL: com.versant.odbms.VersantXAException: Prepare error: Network error on database [jpadb1@localhost].
at com.versant.odbms.XAResourceImpl.getResult(XAResourceImpl.java:650)
at com.versant.odbms.XAResourceImpl.prepare(XAResourceImpl.java:409)
at com.arjuna.ats.internal.jta.resources.jts.orbspecific.XAResourceRecord.prepare(XAResourceRecord.java:234) [jbossjts-jacorb-4.17.15.Final-redhat-5.jar:4.17.15.Final-redhat-5]
at com.arjuna.ArjunaOTS.OTSAbstractRecordPOA._invoke(OTSAbstractRecordPOA.java:81) [jbossjts-jacorb-4.17.15.Final-redhat-5.jar:4.17.15.Final-redhat-5]
at org.jacorb.poa.RequestProcessor.invokeOperation(RequestProcessor.java:306) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.jacorb.poa.RequestProcessor.process(RequestProcessor.java:626) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.jacorb.poa.RequestProcessor.run(RequestProcessor.java:769) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
Caused by: com.versant.odbms.DatastoreException: Network error on database [jpadb1@localhost].
at com.versant.odbms.Connection$30.getOrThrow(Connection.java:597)
at com.versant.odbms.XAResourceImpl.getResult(XAResourceImpl.java:623)
... 6 more
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.read0(Native Method) [rt.jar:1.7.0_25]
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43) [rt.jar:1.7.0_25]
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:225) [rt.jar:1.7.0_25]
at sun.nio.ch.IOUtil.read(IOUtil.java:193) [rt.jar:1.7.0_25]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375) [rt.jar:1.7.0_25]
at com.versant.odbms.net.RPC.readAll(RPC.java:759)
at com.versant.odbms.net.StreamedRPC.read(StreamedRPC.java:125)
at com.versant.odbms.net.StreamedRPC.receive(StreamedRPC.java:114)
at com.versant.odbms.SimpleConnection.doReceive(SimpleConnection.java:704)
at com.versant.odbms.Connection$30.getOrThrow(Connection.java:593)
... 7 more
09:59:46,900 WARN [com.arjuna.ats.arjuna] (EJB default - 4) ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffff0a6a3229:-313ccd9c:546472f5:46 failed.
09:59:46,900 WARN [com.arjuna.ats.arjuna] (EJB default - 4) ARJUNA012075: Action Aborting
09:59:46,901 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) end flags=TMFAIL xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:276) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:339) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:238) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:329) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:70) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:203) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_25]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_25]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]
at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
09:59:46,910 WARN [jacorb.poa.controller] (RequestController-1) rid: 200 opname: _get_type_id cannot process request, because object doesn't exist
09:59:46,911 WARN [jacorb.poa.controller] (RequestController-1) rid: 200 opname: _get_type_id request rejected with exception: null
09:59:46,911 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022228: ExtendedResourceRecord.typeIs failed. Returning default value: 151
09:59:46,912 WARN [com.arjuna.ats.arjuna] (EJB default - 4) ARJUNA012091: Top-level abort of action 0:ffff0a6a3229:-313ccd9c:546472f5:46 received TwoPhaseOutcome.FINISH_ERROR from com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord
09:59:46,914 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) end flags=TMFAIL xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.76.0.0.0.0.0.0.0.0
09:59:46,914 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) rollback xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.76.0.0.0.0.0.0.0.0
09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:276)
09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:339)
09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:238)
09:59:46,965 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,965 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79)
09:59:46,965 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,965 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
09:59:46,966 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,966 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
09:59:46,966 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,966 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
09:59:46,967 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,967 ERROR [stderr] (EJB default - 4) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
09:59:46,967 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,968 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55)
09:59:46,968 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,968 ERROR [stderr] (EJB default - 4) at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
09:59:46,968 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
09:59:46,969 ERROR [stderr] (EJB default - 4) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
09:59:46,969 ERROR [stderr] (EJB default - 4) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
09:59:46,969 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:329)
09:59:46,969 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:70)
09:59:46,969 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:203)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.util.concurrent.FutureTask.run(FutureTask.java:166)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
09:59:46,970 ERROR [stderr] (EJB default - 4) at java.lang.Thread.run(Thread.java:724)
09:59:46,971 ERROR [stderr] (EJB default - 4) at org.jboss.threads.JBossThread.run(JBossThread.java:122)
09:59:46,971 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 4) JBAS014134: EJB Invocation failed on component ReconnectTestBean for method public abstract long[] com.versant.jpa.j2ee.jboss.beans.ReconnectTestBeanRemote.modifyAndStopDbBeforeCommit(com.versant.jpa.j2ee.jboss.entities.J2EEBook[],com.versant.jpa.foundation.Option,int): javax.ejb.EJBTransactionRolledbackException: Transaction rolled back
at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleEndTransactionException(CMTTxInterceptor.java:138) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:118) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:276) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:339) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:238) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:329) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:70) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:203) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_25]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_25]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]
at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: javax.transaction.RollbackException: org.omg.CORBA.TRANSACTION_ROLLEDBACK
at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1324)
at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
... 30 more
09:59:48,516 INFO [stdout] (EJB default - 5) * ADD: begin J2EEBook[0 / Programming In Scala]
09:59:48,593 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 5) start flags=TMNOFLAGS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.84.0.0.0.0.0.0.0.0
09:59:48,593 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 5) start created Versant TxnId 5641.0.19463 for Xid 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.84.0.0.0.0.0.0.0.0
09:59:48,601 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 5) start flags=TMNOFLAGS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.88.0.0.0.0.0.0.0.0
09:59:48,601 FINER [com.versant.odbms.XAResourceImpl] (EJB default - 5) start created Versant TxnId 5642.0.4108 for Xid 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.88.0.0.0.0.0.0.0.0
09:59:48,619 INFO [stdout] (EJB default - 5) * ADD: finish J2EEBook[1587800343624829960 / Programming In Scala]
09:59:48,624 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) end flags=TMSUCCESS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.84.0.0.0.0.0.0.0.0
09:59:48,625 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) prepare xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.84.0.0.0.0.0.0.0.0
09:59:48,744 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) end flags=TMSUCCESS xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.88.0.0.0.0.0.0.0.0
09:59:48,745 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) prepare xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.88.0.0.0.0.0.0.0.0
09:59:48,998 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) commit onePhase=false xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.84.0.0.0.0.0.0.0.0
09:59:49,097 FINER [com.versant.odbms.XAResourceImpl] (RequestProcessor-5) commit onePhase=false xid=131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.82.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.88.0.0.0.0.0.0.0.0
09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Michael Musgrove (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Michael Musgrove commented on JBTM-2287:
----------------------------------------
Marks fix should trigger the rollback but I would still like to understand why xid1 isn't being picked up by our "orphan detection" filters: the standard XA recovery module has asked com.versant.odbms.XARecoveryResource for the pending xid and when we find it's one of ours and that we don't have a log for then we run it through registered "orphan filters" which should result in a roll back. Would it be possible for you to provide more information about what's happening in the logs (at trace level) around about one of our calls to your recovery resource:
{quote}
09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
{quote}
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
by Mark Little (JIRA)
[ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.... ]
Mark Little commented on JBTM-2287:
-----------------------------------
Yes, we should set the _prepared to true in jts.XAResourceRecord.prepare - we skip it because it happens in createState and we don't create any state (log) in this case, but we still need to remember we've been through this method. That will also stop the second call to end and then the subsequent call to rollback should work.
> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
> Key: JBTM-2287
> URL: https://issues.jboss.org/browse/JBTM-2287
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 4.17.15
> Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
> Reporter: Christian von Kutzleben
> Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1 //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
>
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0
[JBoss JIRA] (JBTM-2286) Create a zip with all javadocs included
by Mark Little (JIRA)
[ https://issues.jboss.org/browse/JBTM-2286?page=com.atlassian.jira.plugin.... ]
Mark Little commented on JBTM-2286:
-----------------------------------
ok
> Create a zip with all javadocs included
> ---------------------------------------
>
> Key: JBTM-2286
> URL: https://issues.jboss.org/browse/JBTM-2286
> Project: JBoss Transaction Manager
> Issue Type: Task
> Components: Documentation
> Reporter: Gytis Trikleris
> Assignee: Gytis Trikleris
> Fix For: 5.0.4
>
>
> Currently javadocs are split by component. It would be convenient to produce a single bundle of javadocs of all project as well for ease of publishing on the site.
> What we are proposing is to produce a single Javadoc artifact for the Narayana project which has all the public API stuff (ignoring **/internal/**). Same as what you get with the JSE or JEE javadocs. A single link for users to see all public Narayana javadoc.
> Each component will create its own JavaDocs as normal but a single uber zip would also be produced and this is what would be published on the site.
--
This message was sent by Atlassian JIRA
(v6.3.8#6338)
10 years
- 1
- 0