[jbossts-issues] [JBoss JIRA] (JBTM-3128) Rollback in QA JDBCResources01 Test003 is not performed on Oracle DB
Ondrej Chaloupka (Jira)
issues at jboss.org
Tue Apr 16 01:42:00 EDT 2019
[ https://issues.jboss.org/browse/JBTM-3128?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13722768#comment-13722768 ]
Ondrej Chaloupka edited comment on JBTM-3128 at 4/16/19 1:41 AM:
-----------------------------------------------------------------
[~tomjenkinson] I did the review but I don't understand if and where the race condition is.
I tried matrix of combinations of different Oracle DBs instances (local, from lab, narayana ci one) and in different configuration (using jdbc store, using standard object store) and still the test passes without issue.
I talked with [~istraka] asking him to rerun his testing to confirm how to reproduce. One of my suspicion is if previous test could influence the later one. The race condition would be then in ordering of the tests. But despite this assumption I'm not successful to reproduce it.
[~tomjenkinson] if you have some idea how to reproduce the issue I would be grateful if you take a look.
was (Author: ochaloup):
[~tomjenkinson] I did the review but I don't understand if and where the race condition is.
I tried matrix of combinations of different Oracle DBs instances (local, from lab, narayana ci one) and in different configuration (using jdbc store, using standard object store) and still the test passes without issue.
I talked with [~istraka] asking him to rerun his testing to confirm how to reproduce. One of my suspicion is if previous test could influence the later one. The race condition would be then in ordering of the tests. But even here I still was not successful to reproduce it.
[~tomjenkinson] if you have some idea how to reproduce the issue I would be grateful if you take a look.
> Rollback in QA JDBCResources01 Test003 is not performed on Oracle DB
> --------------------------------------------------------------------
>
> Key: JBTM-3128
> URL: https://issues.jboss.org/browse/JBTM-3128
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Affects Versions: 5.9.0.Final, 5.9.5.Final
> Reporter: Ivan Straka
> Assignee: Ondrej Chaloupka
> Priority: Major
> Attachments: java_xa.xa_start_new_mustbedeclared-server1_output.txt
>
>
> Running JDBCResources Test003 against Oracle DB: rollback is not performed:
> *client0_output.txt*
> {code:java}
> 2019-04-01 11:10:07,245: Task [client0 102]: starting command: /qa/tools/opt/x86_64/jdk1.8.0_last/bin/java -classpath /home/hudson/hudson_workspace/workspace/eap-7.x-jbossts-qa-tests-full/0187c9fc/jboss-as/build/target/jboss-eap-7.3/modules/system/layers/base/io/netty/main/netty-all-4.1.25.Final-redhat-00003.jar:dist/narayana-full-5.9.6.Final-SNAPSHOT/etc/:dbdrivers/jconn4.jar:dbdrivers/db2jcc4.jar:dbdrivers/ojdbc8.jar:dbdrivers/mssql-jdbc-6.4.0.jre8.jar:dbdrivers/mysql-connector-java-8.0.12.jar:dbdrivers/postgresql-42.2.2.jar:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/*:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/ext/*:ext/fscontext.jar:ext/providerutil.jar:ext/jboss-profiler-jvmti.jar:ext/jboss-logging-spi.jar:tests/build/classes/:dbdrivers/selected_dbdriver/*:dbdrivers/DB2_v9.7/db2jcc.jar:dbdrivers/jConnect-6_0/classes/jconn3.jar:dbdrivers/mssql2005_sqljdbc_2.0/enu/sqljdbc4.jar:dbdrivers/mysql-connector-java-5.1.8-bin.jar:dbdrivers/oracle_10_2_0_4/ojdbc14.jar:dbdrivers/postgresql-8.3-605.jdbc4.jar:ext/log4j.jar:ext/netty.jar -Dqa.debug=true -Djava.naming.provider.url=file:///tmp -Djava.naming.factory.initial=com.sun.jndi.fscontext.RefFSContextFactory -Dperformanceprofilestore.dir=config/perf_profiles/ -Djdbcprofilestore.dir=config/jdbc_profiles -Dmemorytestprofilestore.dir=config/memory_profiles/ -Dots.server.bindname=value_1 -DCoordinatorEnvironmentBean.maintainHeuristics=NO -DRecoveryEnvironmentBean.recoveryBackoffPeriod=5 -DCoreEnvironmentBean.timeoutFactor=1 -DCoordinatorEnvironmentBean.defaultTimeout=120 -DCoordinatorEnvironmentBean.dynamic1PC=false -Dio.narayana.perf.failonregression=false -Xbootclasspath/p:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/ext/openjdk-orb.jar -Xms1024m -Xmx1024m -XX:ParallelGCThreads=2 -Demma.coverage.out.file=./testoutput/jdbcresources01_oracle_thin_jndi/JDBCResources01_abstract_Test003/client0-coverage.ec -DportOffsetId=5 -DObjectStoreBaseDir=/home/hudson/hudson_workspace/workspace/eap-7.x-jbossts-qa-tests-full/0187c9fc/qa/testoutput/jdbcresources01_oracle_thin_jndi/JDBCResources01_abstract_Test003/client0 -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.JDBCResources01Clients.Client03 value_1
> 2019-04-01 11:10:07,466 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2019-04-01 11:10:07,469 err: log4j:WARN Please initialize the log4j system properly.
> 2019-04-01 11:10:07,469 err: log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
> 2019-04-01 11:10:07,725 err: com.arjuna.ats.arjuna [main] ARJUNA012170: TransactionStatusManager started on port 39358 and host 127.0.0.1 with service com.arjuna.ats.arjuna.recovery.ActionStatusService
> 2019-04-01 11:10:08,211 out: Failed
> {code}
> *Server1.output*
> {code:java}
> 2019-04-01 11:10:06,094: Task [server1 101]: starting command: /qa/tools/opt/x86_64/jdk1.8.0_last/bin/java -classpath /home/hudson/hudson_workspace/workspace/eap-7.x-jbossts-qa-tests-full/0187c9fc/jboss-as/build/target/jboss-eap-7.3/modules/system/layers/base/io/netty/main/netty-all-4.1.25.Final-redhat-00003.jar:dist/narayana-full-5.9.6.Final-SNAPSHOT/etc/:dbdrivers/jconn4.jar:dbdrivers/db2jcc4.jar:dbdrivers/ojdbc8.jar:dbdrivers/mssql-jdbc-6.4.0.jre8.jar:dbdrivers/mysql-connector-java-8.0.12.jar:dbdrivers/postgresql-42.2.2.jar:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/*:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/ext/*:ext/fscontext.jar:ext/providerutil.jar:ext/jboss-profiler-jvmti.jar:ext/jboss-logging-spi.jar:tests/build/classes/:dbdrivers/selected_dbdriver/*:dbdrivers/DB2_v9.7/db2jcc.jar:dbdrivers/jConnect-6_0/classes/jconn3.jar:dbdrivers/mssql2005_sqljdbc_2.0/enu/sqljdbc4.jar:dbdrivers/mysql-connector-java-5.1.8-bin.jar:dbdrivers/oracle_10_2_0_4/ojdbc14.jar:dbdrivers/postgresql-8.3-605.jdbc4.jar:ext/log4j.jar:ext/netty.jar -Dqa.debug=true -Djava.naming.provider.url=file:///tmp -Djava.naming.factory.initial=com.sun.jndi.fscontext.RefFSContextFactory -Dperformanceprofilestore.dir=config/perf_profiles/ -Djdbcprofilestore.dir=config/jdbc_profiles -Dmemorytestprofilestore.dir=config/memory_profiles/ -Dots.server.bindname=value_1 -DCoordinatorEnvironmentBean.maintainHeuristics=NO -DRecoveryEnvironmentBean.recoveryBackoffPeriod=5 -DCoreEnvironmentBean.timeoutFactor=1 -DCoordinatorEnvironmentBean.defaultTimeout=120 -DCoordinatorEnvironmentBean.dynamic1PC=false -Dio.narayana.perf.failonregression=false -Xbootclasspath/p:dist/narayana-full-5.9.6.Final-SNAPSHOT/lib/ext/openjdk-orb.jar -Xms1024m -Xmx1024m -XX:ParallelGCThreads=2 -Demma.coverage.out.file=./testoutput/jdbcresources01_oracle_thin_jndi/JDBCResources01_abstract_Test003/server1-coverage.ec -DportOffsetId=4 -DObjectStoreBaseDir=/home/hudson/hudson_workspace/workspace/eap-7.x-jbossts-qa-tests-full/0187c9fc/qa/testoutput/jdbcresources01_oracle_thin_jndi/JDBCResources01_abstract_Test003/server1 -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.JDBCResources01Servers.Server01 DB1_THIN_JNDI value_1
> 2019-04-01 11:10:06,339 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2019-04-01 11:10:06,339 err: log4j:WARN Please initialize the log4j system properly.
> 2019-04-01 11:10:06,339 err: log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
> 2019-04-01 11:10:06,687 err: Setting up connection
> 2019-04-01 11:10:07,162 err: connection = oracle.jdbc.driver.T4CConnection at 646be2c3
> 2019-04-01 11:10:07,162 err: Database URL = jdbc:oracle:thin:@oracle-12cr1.rhev-ci-vms.eng.rdu2.redhat.com:1521:dballo
> 2019-04-01 11:10:07,244 out: Ready
> 2019-04-01 11:10:07,795 err: 01------------------ doing insert (Name_0,Value_0) -----------------------------
> 2019-04-01 11:10:07,846 err: com.arjuna.ats.arjuna [p: default-threadpool; w: Idle] ARJUNA012170: TransactionStatusManager started on port 33107 and host 127.0.0.1 with service com.arjuna.ats.arjuna.recovery.ActionStatusService
> 2019-04-01 11:10:07,876 err: Current Status = 0
> 2019-04-01 11:10:07,931 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_0', 'Value_0')
> 2019-04-01 11:10:07,971 err: 01------------------ doing insert (Name_1,Value_1) -----------------------------
> 2019-04-01 11:10:07,971 err: Current Status = 0
> 2019-04-01 11:10:07,971 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_1', 'Value_1')
> 2019-04-01 11:10:07,982 err: 01------------------ doing insert (Name_2,Value_2) -----------------------------
> 2019-04-01 11:10:07,982 err: Current Status = 0
> 2019-04-01 11:10:07,982 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_2', 'Value_2')
> 2019-04-01 11:10:07,994 err: 01------------------ doing insert (Name_3,Value_3) -----------------------------
> 2019-04-01 11:10:07,994 err: Current Status = 0
> 2019-04-01 11:10:07,994 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_3', 'Value_3')
> 2019-04-01 11:10:08,013 err: 01------------------ doing insert (Name_4,Value_4) -----------------------------
> 2019-04-01 11:10:08,013 err: Current Status = 0
> 2019-04-01 11:10:08,013 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_4', 'Value_4')
> 2019-04-01 11:10:08,024 err: 01------------------ doing insert (Name_5,Value_5) -----------------------------
> 2019-04-01 11:10:08,024 err: Current Status = 0
> 2019-04-01 11:10:08,024 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_5', 'Value_5')
> 2019-04-01 11:10:08,034 err: 01------------------ doing insert (Name_6,Value_6) -----------------------------
> 2019-04-01 11:10:08,034 err: Current Status = 0
> 2019-04-01 11:10:08,034 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_6', 'Value_6')
> 2019-04-01 11:10:08,045 err: 01------------------ doing insert (Name_7,Value_7) -----------------------------
> 2019-04-01 11:10:08,045 err: Current Status = 0
> 2019-04-01 11:10:08,045 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_7', 'Value_7')
> 2019-04-01 11:10:08,056 err: 01------------------ doing insert (Name_8,Value_8) -----------------------------
> 2019-04-01 11:10:08,056 err: Current Status = 0
> 2019-04-01 11:10:08,056 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_8', 'Value_8')
> 2019-04-01 11:10:08,070 err: 01------------------ doing insert (Name_9,Value_9) -----------------------------
> 2019-04-01 11:10:08,070 err: Current Status = 0
> 2019-04-01 11:10:08,070 err: INSERT INTO crash2_rhel7_medium_33452_ VALUES('Name_9', 'Value_9')
> 2019-04-01 11:10:08,092 err: 01------------------ doing update (Name_3,Value_8) -----------------------------
> 2019-04-01 11:10:08,097 err: Current Status = 0
> 2019-04-01 11:10:08,097 err: UPDATE crash2_rhel7_medium_33452_ SET Value = 'Value_8' WHERE Name = 'Name_3'
> 2019-04-01 11:10:08,117 err: 01------------------ doing select (Name_0) -----------------------------
> 2019-04-01 11:10:08,124 err: Current Status = 0
> 2019-04-01 11:10:08,124 err: SELECT Value FROM crash2_rhel7_medium_33452_ WHERE Name = 'Name_0'
> 2019-04-01 11:10:08,183 err: 01------------------ doing select (Name_1) -----------------------------
> 2019-04-01 11:10:08,183 err: Current Status = 0
> 2019-04-01 11:10:08,183 err: SELECT Value FROM crash2_rhel7_medium_33452_ WHERE Name = 'Name_1'
> 2019-04-01 11:10:08,191 err: 01------------------ doing select (Name_2) -----------------------------
> 2019-04-01 11:10:08,191 err: Current Status = 0
> 2019-04-01 11:10:08,191 err: SELECT Value FROM crash2_rhel7_medium_33452_ WHERE Name = 'Name_2'
> 2019-04-01 11:10:08,202 err: 01------------------ doing select (Name_3) -----------------------------
> 2019-04-01 11:10:08,202 err: Current Status = 0
> 2019-04-01 11:10:08,202 err: SELECT Value FROM crash2_rhel7_medium_33452_ WHERE Name = 'Name_3'
> {code}
> After adding some prints to JDBCResources01Clients/Client03.java I can see that value for "Name_3" is "Value_8", therefore rollback was not performed.
> This happens only on Oracle DB. Test passes with 5.2.16.Final
> bash command:
> {code:bash}
> ant -f run-tests.xml -Dtest.name=jdbcresources01_oracle_thin_jndi -Dtest.methods="JDBCResources01_abstract_Test003" -Dprofile=oracle -Djdbc.db.url="oracle-12cr1.rhev-ci-vms.eng.rdu2.redhat.com" -Djdbc.db.name=dballo -Djdbc.db.user=crashrec -Djdbc.db.password=crashrec -Djdbc.db.port=1521 onetest
> {code}
> Moreover there are another failures that happens only on Oracle DB:
> jdbcresources01_oracle_thin_jndi JDBCResources01_abstract_Test003 Fail (0m13.560s)
> jdbcresources01_oracle_thin_jndi JDBCResources01_abstract_Test004 Fail (0m12.856s)
> jdbcresources01_oracle_thin_jndi JDBCResources01_abstract_Test009 Fail (0m13.824s)
> jdbcresources01_oracle_thin_jndi JDBCResources01_abstract_Test010 Fail (0m13.889s)
> jdbcresources02_oracle_thin_jndi JDBCResources02_abstract_Test003 Fail (0m13.253s)
> jdbcresources02_oracle_thin_jndi JDBCResources02_abstract_Test004 Fail (0m13.101s)
> jdbcresources02_oracle_thin_jndi JDBCResources02_abstract_Test009 Fail (0m13.755s)
> jdbcresources02_oracle_thin_jndi JDBCResources02_abstract_Test010 Fail (0m14.125s)
> I can provide outputs if you need.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
More information about the jbossts-issues
mailing list