[jbossts-issues] [JBoss JIRA] (JBTM-1978) QA test suite failure: CrashRecovery05_1_Test01
Michael Musgrove (JIRA)
jira-events at lists.jboss.org
Tue Oct 15 15:24:35 EDT 2013
[ https://issues.jboss.org/browse/JBTM-1978?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12814354#comment-12814354 ]
Michael Musgrove commented on JBTM-1978:
----------------------------------------
The test checks recovery after a server crashes during commit (in the following server2 should handle the replay request and client1 asks server2 what it did).
The output shows:
* the recovery managers last replay attempt at 20:34:40
* server2 starting at 20:34:38 (so it just missed the last replay attempt)
* client1 starting at 20:34:39 and delays for 10 * 2 seconds and asks server2 whether it was asked to recover
So there are a number of possible fixes:
- tell client1 to wait longer before asking server2 what happened
- configure the recovery manager to run more often
- arrange for client1 to explicitly ask (and wait for) the recovery manager to run a recovery scan and only then ask server2 what happened.
I have gone for the final option since it is deterministic.
> QA test suite failure: CrashRecovery05_1_Test01
> -----------------------------------------------
>
> Key: JBTM-1978
> URL: https://issues.jboss.org/browse/JBTM-1978
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Security Level: Public(Everyone can see)
> Components: Testing
> Reporter: Gytis Trikleris
> Assignee: Michael Musgrove
> Priority: Minor
> Fix For: 5.0.0.Final
>
>
> http://172.17.131.2/view/Narayana+BlackTie/job/narayana/303/TESTS=QA_JTS_JACORB,jdk=jdk7.latest,label=linux/consoleText
> client0_output.txt:
> {code}
> starting command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/client0-coverage.ec -DportOffsetId=3 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/client -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.CrashRecovery05Clients1.Client01b value_1
> 2013-10-11 20:34:34,355 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2013-10-11 20:34:34,355 err: log4j:WARN Please initialize the log4j system properly.
> 2013-10-11 20:34:34,421 err: SLF4J: Class path contains multiple SLF4J bindings.
> 2013-10-11 20:34:34,421 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/slf4j-simple.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:34,421 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/slf4j-jdk14-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:34,426 err: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> 2013-10-11 20:34:34,439 err: 10 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:34,440 err: 11 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:34,449 err: 20 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:34,466 err: 37 [main] INFO jacorb.orb.print_version -
> 2013-10-11 20:34:34,466 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:34,466 err: JacORB V 2.3.1 (JBoss patch01), www.jacorb.org
> 2013-10-11 20:34:34,466 err: (C) The JacORB project 29-Jul-2009
> 2013-10-11 20:34:34,466 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:34,538 err: 109 [main] INFO jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2013-10-11 20:34:34,585 err: 156 [main] INFO jacorb.orb.interceptors - InterceptorManager started with 1 Server Interceptors, 1 Client Interceptors and 1 IOR Interceptors
> 2013-10-11 20:34:34,784 err: 355 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:34,784 err: 355 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:34,786 err: 357 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:34,786 err: 357 [main] INFO jacorb.orb.singleton - created ORBSingleton
> 2013-10-11 20:34:34,877 err: 448 [main] INFO jacorb.poa - oid:
> 2013-10-11 20:34:34,878 err: 00 18 06 33 00 42 25 11 01 0F 11 ...3.B%....
> 2013-10-11 20:34:34,878 err: object is activated
> 2013-10-11 20:34:34,880 err: 451 [main] INFO jacorb.poa - Using server ID (3870081024) for transient POA
> 2013-10-11 20:34:34,989 err: 560 [main] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:54307 (b8872d0)
> 2013-10-11 20:34:35,111 err: 682 [main] INFO jacorb.poa - oid:
> 2013-10-11 20:34:35,111 err: 01 18 06 33 00 42 25 11 01 0F 11 ...3.B%....
> 2013-10-11 20:34:35,111 err: object is activated
> 2013-10-11 20:34:35,114 err: 685 [main] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:42337 (e33ad7)
> 2013-10-11 20:34:35,153 err: 724 [main] INFO jacorb.orb.iiop - Connected to 172.17.131.34:42337 from local port 52671
> 2013-10-11 20:34:35,298 err: 869 [ServerSocketListener] INFO jacorb.orb.iiop - Opened new server-side TCP/IP transport to 172.17.131.34:54297
> 2013-10-11 20:34:35,326 err: 896 [RequestProcessor-4] INFO jacorb.poa - oid:
> 2013-10-11 20:34:35,326 err: 02 18 06 33 00 42 25 11 01 0F 11 ...3.B%....
> 2013-10-11 20:34:35,326 err: object is activated
> 2013-10-11 20:34:35,374 err: 945 [RequestProcessor-4] INFO jacorb.orb.giop - ClientConnectionManager: found ClientGIOPConnection to 172.17.131.34:42337 (e33ad7)
> 2013-10-11 20:34:35,754 err: 1325 [ClientMessageReceptor1] INFO jacorb.orb.iiop - Client-side TCP transport to 172.17.131.34:42337 closed.
> 2013-10-11 20:34:35,754 err: 1325 [ClientMessageReceptor1] WARN jacorb.giop.conn - Abnormal connection termination. Lost 1 outstanding replie(s)!
> 2013-10-11 20:34:35,757 out: 2013-10-11 20:34:35,757 [main] WARN com.arjuna.ats.arjuna - ARJUNA012084: One-phase commit of action 0:ffffac118322:9684:525852ca:3 received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD
> 2013-10-11 20:34:35,768 err: 1339 [ServerMessageReceptor0] INFO jacorb.orb.iiop - Closed server-side transport to 172.17.131.34:54297
> 2013-10-11 20:34:35,810 err: 1381 [main] INFO jacorb.orb.iiop - Retrying to connect to 172.17.131.34:42337
> 2013-10-11 20:34:36,311 err: 1882 [main] INFO jacorb.orb.iiop - Retrying to connect to 172.17.131.34:42337
> 2013-10-11 20:34:36,812 err: 2383 [main] INFO jacorb.orb.iiop - Retrying to connect to 172.17.131.34:42337
> 2013-10-11 20:34:37,313 err: 2883 [main] INFO jacorb.orb.iiop - Retrying to connect to 172.17.131.34:42337
> 2013-10-11 20:34:37,813 err: 3384 [main] INFO jacorb.orb.iiop - Retrying to connect to 172.17.131.34:42337
> 2013-10-11 20:34:38,328 out: 2013-10-11 20:34:38,316 [main] WARN com.arjuna.ats.jts - ARJUNA022230: ResourceRecord.forgetHeuristic caught exception
> 2013-10-11 20:34:38,328 out: org.omg.CORBA.TRANSIENT: Retries exceeded, couldn't reconnect to 172.17.131.34:42337 vmcid: 0x0 minor code: 0 completed: No
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.iiop.ClientIIOPConnection.connect(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.giop.GIOPConnection.sendMessage(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.giop.GIOPConnection.sendRequest(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.giop.ClientConnection.sendRequest(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.giop.ClientConnection.sendRequest(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.Delegate.invoke_internal(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.Delegate.invoke(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.Delegate.is_a(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.omg.CORBA.portable.ObjectImpl._is_a(ObjectImpl.java:130)
> 2013-10-11 20:34:38,328 out: at org.omg.CosTransactions.TransactionalObjectHelper.narrow(TransactionalObjectHelper.java:57)
> 2013-10-11 20:34:38,328 out: at com.arjuna.ats.jts.orbspecific.jacorb.interceptors.interposition.InterpositionClientRequestInterceptorImpl.send_request(InterpositionClientRequestInterceptorImpl.java:141)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.portableInterceptor.ClientInterceptorIterator.invoke(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.portableInterceptor.AbstractInterceptorIterator.iterate(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.portableInterceptor.ClientInterceptorIterator.iterate(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.ClientInterceptorHandler.invokeInterceptors(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.ClientInterceptorHandler.handle_send_request(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.Delegate.invoke_internal(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.jacorb.orb.Delegate.invoke(Unknown Source)
> 2013-10-11 20:34:38,328 out: at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> 2013-10-11 20:34:38,328 out: at org.omg.CosTransactions._ResourceStub.forget(_ResourceStub.java:205)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.internal.jts.resources.ResourceRecord.forgetHeuristic(ResourceRecord.java:569)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.arjuna.coordinator.BasicAction.doForget(BasicAction.java:3510)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.arjuna.coordinator.BasicAction.forgetHeuristics(BasicAction.java:1329)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.forgetHeuristics(ArjunaTransactionImple.java:1365)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2429)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1475)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 2013-10-11 20:34:38,329 out: at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 2013-10-11 20:34:38,329 out: at org.jboss.jbossts.qa.CrashRecovery05Clients1.Client01b.main(Client01b.java:93)
> 2013-10-11 20:34:38,371 err: 3941 [main] INFO jacorb.orb.giop - ClientConnectionManager: found ClientGIOPConnection to 172.17.131.34:54307 (b8872d0)
> 2013-10-11 20:34:38,371 err: 3942 [ServerSocketListener] INFO jacorb.orb.iiop - Opened new server-side TCP/IP transport to 172.17.131.34:54304
> 2013-10-11 20:34:38,372 err: 3943 [main] INFO jacorb.orb.iiop - Connected to 172.17.131.34:54307 from local port 54304
> 2013-10-11 20:34:38,374 err: 3945 [AOM_RemovalThread] INFO jacorb.poa - oid:
> 2013-10-11 20:34:38,374 err: 01 18 06 33 00 42 25 11 01 0F 11 ...3.B%....
> 2013-10-11 20:34:38,374 err: object is deactivated
> 2013-10-11 20:34:38,375 out: Passed
> 2013-10-11 20:34:38,375 err: 3946 [AOM_RemovalThread] INFO jacorb.poa - oid:
> 2013-10-11 20:34:38,375 err: 02 18 06 33 00 42 25 11 01 0F 11 ...3.B%....
> 2013-10-11 20:34:38,375 err: object is deactivated
> 2013-10-11 20:34:38,378 err: 3949 [POADestructor] INFO jacorb.poa - POA RootPOA destroyed
> 2013-10-11 20:34:38,378 err: 3949 [main] INFO jacorb.orb - prepare ORB for shutdown...
> 2013-10-11 20:34:38,378 err: 3949 [main] INFO jacorb.orb - ORB going down...
> 2013-10-11 20:34:38,379 err: 3950 [ServerSocketListener] INFO jacorb.orb.iiop - Listener exited
> 2013-10-11 20:34:38,382 err: 3952 [main] INFO jacorb.orb.iiop - Closed server-side transport to 172.17.131.34:54304
> 2013-10-11 20:34:38,382 err: 3952 [main] INFO jacorb.orb.iiop - Client-side TCP transport to 172.17.131.34:54307 closed.
> 2013-10-11 20:34:38,382 err: 3952 [main] INFO jacorb.orb - ORB shutdown complete
> 2013-10-11 20:34:38,382 err: 3952 [ClientMessageReceptor0] INFO jacorb.giop.conn - Received CloseConnection on ClientGIOPConnection to 172.17.131.34:54307 (b8872d0)
> 2013-10-11 20:34:38,382 err: 3952 [ClientMessageReceptor0] INFO jacorb.util.tpool - ConsumerTie exited
> 2013-10-11 20:34:38,382 err: 3953 [ServerMessageReceptor0] INFO jacorb.orb.iiop - Closed server-side transport to 172.17.131.34:54304
> 2013-10-11 20:34:38,382 err: 3953 [ServerMessageReceptor0] INFO jacorb.util.tpool - ConsumerTie exited
> 2013-10-11 20:34:38,382 err: 3953 [ClientMessageReceptor1] INFO jacorb.util.tpool - ConsumerTie exited
> {code}
> client1_output.txt
> {code}
> starting command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/client1-coverage.ec -DportOffsetId=3 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/client -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.CrashRecovery05Clients1.Client01a value_2
> 2013-10-11 20:34:39,769 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2013-10-11 20:34:39,769 err: log4j:WARN Please initialize the log4j system properly.
> 2013-10-11 20:34:39,834 err: SLF4J: Class path contains multiple SLF4J bindings.
> 2013-10-11 20:34:39,835 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/slf4j-simple.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:39,835 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/slf4j-jdk14-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:39,835 err: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> 2013-10-11 20:34:39,848 err: 10 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:39,851 err: 13 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:39,859 err: 21 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:39,874 err: 36 [main] INFO jacorb.orb.print_version -
> 2013-10-11 20:34:39,874 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:39,874 err: JacORB V 2.3.1 (JBoss patch01), www.jacorb.org
> 2013-10-11 20:34:39,875 err: (C) The JacORB project 29-Jul-2009
> 2013-10-11 20:34:39,875 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:39,947 err: 108 [main] INFO jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2013-10-11 20:34:39,993 err: 155 [main] INFO jacorb.orb.interceptors - InterceptorManager started with 1 Server Interceptors, 1 Client Interceptors and 1 IOR Interceptors
> 2013-10-11 20:34:40,192 err: 354 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:40,192 err: 354 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:40,194 err: 356 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:40,197 err: 359 [main] INFO jacorb.orb.singleton - created ORBSingleton
> 2013-10-11 20:34:40,283 err: 445 [main] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:44860 (512e3872)
> 2013-10-11 20:34:40,307 err: 469 [main] INFO jacorb.orb.iiop - Connected to 172.17.131.34:44860 from local port 55790
> 2013-10-11 20:34:40,629 out: Using timeout delay factor of 2
> 2013-10-11 20:35:00,641 out: Failed
> 2013-10-11 20:35:00,642 err: 20804 [POADestructor] INFO jacorb.poa - POA RootPOA destroyed
> 2013-10-11 20:35:00,642 err: 20804 [main] INFO jacorb.orb - prepare ORB for shutdown...
> 2013-10-11 20:35:00,642 err: 20804 [main] INFO jacorb.orb - ORB going down...
> 2013-10-11 20:35:00,645 err: 20805 [main] INFO jacorb.orb.iiop - Client-side TCP transport to 172.17.131.34:44860 closed.
> 2013-10-11 20:35:00,645 err: 20805 [main] INFO jacorb.orb - ORB shutdown complete
> 2013-10-11 20:35:00,645 err: 20806 [ServerSocketListener] INFO jacorb.orb.iiop - Listener exited
> 2013-10-11 20:35:00,647 err: 20809 [ClientMessageReceptor0] INFO jacorb.util.tpool - ConsumerTie exited
> {code}
> server0_output.txt
> {code}
> starting command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server0-coverage.ec -DportOffsetId=1 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server0 -DRecoveryEnvironmentBean.recoveryListener=true com.arjuna.ats.arjuna.recovery.RecoveryManager -test
> 2013-10-11 20:34:32,252 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2013-10-11 20:34:32,252 err: log4j:WARN Please initialize the log4j system properly.
> 2013-10-11 20:34:32,355 err: SLF4J: Class path contains multiple SLF4J bindings.
> 2013-10-11 20:34:32,355 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/slf4j-simple.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:32,355 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/slf4j-jdk14-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:32,356 err: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> 2013-10-11 20:34:32,361 err: 3 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:32,361 err: 3 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:32,363 err: 5 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:32,378 err: 20 [main] INFO jacorb.orb.print_version -
> 2013-10-11 20:34:32,378 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:32,378 err: JacORB V 2.3.1 (JBoss patch01), www.jacorb.org
> 2013-10-11 20:34:32,378 err: (C) The JacORB project 29-Jul-2009
> 2013-10-11 20:34:32,378 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:32,449 err: 91 [main] INFO jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2013-10-11 20:34:32,495 err: 137 [main] INFO jacorb.orb.interceptors - InterceptorManager started with 1 Server Interceptors, 1 Client Interceptors and 1 IOR Interceptors
> 2013-10-11 20:34:32,722 err: 364 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:32,722 err: 364 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:32,724 err: 366 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:32,727 err: 369 [main] INFO jacorb.orb.singleton - created ORBSingleton
> 2013-10-11 20:34:32,866 err: 508 [Thread-3] INFO jacorb.orb - ORB run
> 2013-10-11 20:34:32,962 out: Ready
> 2013-10-11 20:34:40,464 err: 8104 [ServerSocketListener] INFO jacorb.orb.iiop - Opened new server-side TCP/IP transport to 172.17.131.34:54289
> 2013-10-11 20:34:40,575 err: 8217 [RequestProcessor-4] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:54307 (2451c70d)
> 2013-10-11 20:34:40,587 err: 8229 [RequestProcessor-4] INFO jacorb.orb.iiop - Connected to 172.17.131.34:54307 from local port 54307
> 2013-10-11 20:34:40,589 err: 8230 [ClientMessageReceptor0] WARN jacorb.orb.giop - Received a request on a non-bidir connection
> 2013-10-11 20:34:40,605 out: 2013-10-11 20:34:40,595 [RequestProcessor-4] WARN com.arjuna.ats.jts - ARJUNA022139: CORBA exception on trying to contact original process
> 2013-10-11 20:34:40,606 out: org.omg.CORBA.INV_POLICY: Server-side Exception: null vmcid: 0x0 minor code: 0 completed: No
> 2013-10-11 20:34:40,606 out: at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> 2013-10-11 20:34:40,606 out: at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
> 2013-10-11 20:34:40,606 out: at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> 2013-10-11 20:34:40,606 out: at java.lang.reflect.Constructor.newInstance(Constructor.java:525)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.SystemExceptionHelper.read(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.ReplyReceiver.getReply(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.Delegate.invoke_internal(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.Delegate.invoke(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.Delegate.is_a(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.omg.CORBA.portable.ObjectImpl._is_a(ObjectImpl.java:130)
> 2013-10-11 20:34:40,606 out: at org.omg.CosTransactions.TransactionalObjectHelper.narrow(TransactionalObjectHelper.java:57)
> 2013-10-11 20:34:40,606 out: at com.arjuna.ats.jts.orbspecific.jacorb.interceptors.interposition.InterpositionClientRequestInterceptorImpl.send_request(InterpositionClientRequestInterceptorImpl.java:141)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.portableInterceptor.ClientInterceptorIterator.invoke(Unknown Source)
> 2013-10-11 20:34:40,606 out: at org.jacorb.orb.portableInterceptor.AbstractInterceptorIterator.iterate(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.orb.portableInterceptor.ClientInterceptorIterator.iterate(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.orb.ClientInterceptorHandler.invokeInterceptors(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.orb.ClientInterceptorHandler.handle_send_request(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.orb.Delegate.invoke_internal(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.orb.Delegate.invoke(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:475)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ArjunaOTS._ArjunaFactoryStub.getCurrentStatus(_ArjunaFactoryStub.java:31)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.getStatus(StatusChecker.java:176)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.checkOriginalStatus(StatusChecker.java:144)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.recovery.contact.StatusChecker.get_current_status(StatusChecker.java:110)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.get_status(GenericRecoveryCoordinator.java:328)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.orbspecific.recovery.recoverycoordinators.GenericRecoveryCoordinator.replay_completion(GenericRecoveryCoordinator.java:145)
> 2013-10-11 20:34:40,607 out: at com.arjuna.ats.internal.jts.orbspecific.jacorb.recoverycoordinators.JacOrbRCDefaultServant.replay_completion(JacOrbRCDefaultServant.java:90)
> 2013-10-11 20:34:40,607 out: at org.omg.CosTransactions.RecoveryCoordinatorPOA._invoke(RecoveryCoordinatorPOA.java:44)
> 2013-10-11 20:34:40,607 out: at org.jacorb.poa.RequestProcessor.invokeOperation(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.poa.RequestProcessor.process(Unknown Source)
> 2013-10-11 20:34:40,607 out: at org.jacorb.poa.RequestProcessor.run(Unknown Source)
> {code}
> server1_output.txt
> {code}
> starting command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server1-coverage.ec -DportOffsetId=2 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.CrashRecovery05Servers.Server01 value_3 value_1
> 2013-10-11 20:34:33,392 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2013-10-11 20:34:33,392 err: log4j:WARN Please initialize the log4j system properly.
> 2013-10-11 20:34:33,458 err: SLF4J: Class path contains multiple SLF4J bindings.
> 2013-10-11 20:34:33,458 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/slf4j-simple.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:33,458 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/slf4j-jdk14-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:33,458 err: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> 2013-10-11 20:34:33,470 err: 9 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:33,473 err: 12 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:33,482 err: 21 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:33,498 err: 37 [main] INFO jacorb.orb.print_version -
> 2013-10-11 20:34:33,498 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:33,498 err: JacORB V 2.3.1 (JBoss patch01), www.jacorb.org
> 2013-10-11 20:34:33,498 err: (C) The JacORB project 29-Jul-2009
> 2013-10-11 20:34:33,498 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:33,575 err: 114 [main] INFO jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2013-10-11 20:34:33,622 err: 161 [main] INFO jacorb.orb.interceptors - InterceptorManager started with 1 Server Interceptors, 1 Client Interceptors and 1 IOR Interceptors
> 2013-10-11 20:34:33,803 out: BeforeCrashServiceImpl01(231605477, 0)
> 2013-10-11 20:34:33,804 err: 343 [main] INFO jacorb.poa - oid:
> 2013-10-11 20:34:33,804 err: 00 18 06 33 00 42 14 0E 17 4D ...3.B...M
> 2013-10-11 20:34:33,804 err: object is activated
> 2013-10-11 20:34:33,810 err: 348 [main] INFO jacorb.poa - Using server ID (3589635481) for transient POA
> 2013-10-11 20:34:33,850 err: 389 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:33,850 err: 389 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:33,852 err: 391 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:33,852 err: 391 [main] INFO jacorb.orb.singleton - created ORBSingleton
> 2013-10-11 20:34:33,914 err: 453 [main] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:42337 (59966240)
> 2013-10-11 20:34:33,925 out: Ready
> 2013-10-11 20:34:33,926 err: 465 [main] INFO jacorb.orb - ORB run
> 2013-10-11 20:34:35,151 err: 1690 [ServerSocketListener] INFO jacorb.orb.iiop - Opened new server-side TCP/IP transport to 172.17.131.34:52671
> 2013-10-11 20:34:35,234 err: 1773 [RequestProcessor-5] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:54307 (d13e8c7)
> 2013-10-11 20:34:35,271 err: 1810 [RequestProcessor-5] INFO jacorb.poa - oid:
> 2013-10-11 20:34:35,271 err: 01 18 06 33 00 42 14 0E 17 4D ...3.B...M
> 2013-10-11 20:34:35,271 err: object is activated
> 2013-10-11 20:34:35,273 err: 1811 [RequestProcessor-5] INFO jacorb.orb.giop - ClientConnectionManager: found ClientGIOPConnection to 172.17.131.34:42337 (59966240)
> 2013-10-11 20:34:35,301 err: 1840 [RequestProcessor-5] INFO jacorb.orb.iiop - Connected to 172.17.131.34:54307 from local port 54297
> 2013-10-11 20:34:35,333 err: 1870 [RequestProcessor-5] INFO jacorb.orb.giop - ClientConnectionManager: found ClientGIOPConnection to 172.17.131.34:54307 (d13e8c7)
> 2013-10-11 20:34:35,389 out: BeforeCrashServiceImpl01: storing IOR "RecoveryCoordinator_231605477_0_0"
> 2013-10-11 20:34:35,428 err: BeforeCrashServiceImpl01.is_correct: true
> 2013-10-11 20:34:35,434 err: ResourceImpl01.commit_one_phase [O0.R0]: Crash
> {code}
> server2_output.txt
> {code}
> starting command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server2-coverage.ec -DportOffsetId=2 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/server -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.CrashRecovery05Servers.Server02 value_3 value_2
> 2013-10-11 20:34:38,819 err: log4j:WARN No appenders could be found for logger (org.jboss.logging).
> 2013-10-11 20:34:38,820 err: log4j:WARN Please initialize the log4j system properly.
> 2013-10-11 20:34:38,885 err: SLF4J: Class path contains multiple SLF4J bindings.
> 2013-10-11 20:34:38,885 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/slf4j-simple.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:38,885 err: SLF4J: Found binding in [jar:file:/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/slf4j-jdk14-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> 2013-10-11 20:34:38,885 err: SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> 2013-10-11 20:34:38,898 err: 10 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:38,901 err: 13 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:38,909 err: 21 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:38,925 err: 37 [main] INFO jacorb.orb.print_version -
> 2013-10-11 20:34:38,926 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:38,926 err: JacORB V 2.3.1 (JBoss patch01), www.jacorb.org
> 2013-10-11 20:34:38,926 err: (C) The JacORB project 29-Jul-2009
> 2013-10-11 20:34:38,926 err: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2013-10-11 20:34:39,001 err: 112 [main] INFO jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2013-10-11 20:34:39,045 err: 157 [main] INFO jacorb.orb.interceptors - InterceptorManager started with 1 Server Interceptors, 1 Client Interceptors and 1 IOR Interceptors
> 2013-10-11 20:34:39,228 out: AfterCrashServiceImpl01(231605477, 0)
> 2013-10-11 20:34:39,232 err: 344 [main] INFO jacorb.poa - oid:
> 2013-10-11 20:34:39,233 err: 00 18 06 33 00 43 2C 4B 21 2D ...3.C,K!-
> 2013-10-11 20:34:39,233 err: object is activated
> 2013-10-11 20:34:39,235 err: 347 [main] INFO jacorb.poa - Using server ID (1830494895) for transient POA
> 2013-10-11 20:34:39,275 err: 387 [main] INFO jacorb.config - base configuration loaded from classpath orb.properties
> 2013-10-11 20:34:39,275 err: 387 [main] WARN jacorb.config - File e:/JacORB_CONFIG_FEATURE/etc/jacorb.properties for configuration jacorb not found
> 2013-10-11 20:34:39,277 err: 389 [main] INFO jacorb.config - configuration jacorb loaded from classpath
> 2013-10-11 20:34:39,279 err: 391 [main] INFO jacorb.orb.singleton - created ORBSingleton
> 2013-10-11 20:34:39,337 err: 449 [main] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:44860 (5c2f4f8b)
> 2013-10-11 20:34:39,356 out: Ready
> 2013-10-11 20:34:39,357 err: 469 [main] INFO jacorb.orb - ORB run
> 2013-10-11 20:34:40,306 err: 1418 [ServerSocketListener] INFO jacorb.orb.iiop - Opened new server-side TCP/IP transport to 172.17.131.34:55790
> 2013-10-11 20:34:40,401 err: 1513 [RequestProcessor-5] INFO jacorb.poa - oid:
> 2013-10-11 20:34:40,401 err: 01 18 06 33 00 43 2C 4B 21 2D ...3.C,K!-
> 2013-10-11 20:34:40,401 err: object is activated
> 2013-10-11 20:34:40,404 err: 1516 [RequestProcessor-5] INFO jacorb.orb.giop - ClientConnectionManager: found ClientGIOPConnection to 172.17.131.34:44860 (5c2f4f8b)
> 2013-10-11 20:34:40,409 out: AfterCrashServiceImpl01: loading IOR "RecoveryCoordinator_231605477_0_0"
> 2013-10-11 20:34:40,425 err: 1536 [RequestProcessor-5] INFO jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to 172.17.131.34:4711 (25a226eb)
> 2013-10-11 20:34:40,435 err: 1547 [RequestProcessor-5] ERROR jacorb.orb - no adapter activator exists for RcvCo-RecCoService_cersei.buildnet.ncl.jboss.comrecovery_coordinator
> 2013-10-11 20:34:40,461 err: 1573 [RequestProcessor-5] INFO jacorb.orb.iiop - Connected to 172.17.131.34:4711 from local port 54289
> 2013-10-11 20:34:40,612 err: AfterCrashServiceImpl01.check_oper [O0.R0]: replay_completion returned: org.omg.CosTransactions.Status at b93c476
> 2013-10-11 20:35:00,640 err: AfterCrashServiceImpl01.get_resource_trace [O0.R0]: ResourceTraceNone
> 2013-10-11 20:35:00,646 err: 21758 [ServerMessageReceptor0] INFO jacorb.orb.iiop - Closed server-side transport to 172.17.131.34:55790
> {code}
> task0_output.txt
> {code}
> performing command: /usr/local/jdk1.7.0_17/bin/java -classpath dist/narayana-full-5.0.0.Final-SNAPSHOT/etc/:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/lib/ext/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/lib/*:dist/narayana-full-5.0.0.Final-SNAPSHOT/jacorb/etc/: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/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=2 -DCoordinatorEnvironmentBean.defaultTimeout=240 -DCoordinatorEnvironmentBean.dynamic1PC=false -Demma.coverage.out.file=./testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/task0-coverage.ec -DportOffsetId=6 -DObjectStoreBaseDir=/home/hudson/workspace/narayana/TESTS/QA_JTS_JACORB/jdk/jdk7.latest/label/linux/qa/testoutput/crashrecovery05_1/CrashRecovery05_1_Test01/task0 -DRecoveryEnvironmentBean.recoveryListener=true org.jboss.jbossts.qa.Utils.RemoveServerIORStore value_1 value_2 value_3
> 2013-10-11 20:35:00,832 err: java.io.FileNotFoundException: ServerIORs (No such file or directory)
> 2013-10-11 20:35:00,832 err: at java.io.FileInputStream.open(Native Method)
> 2013-10-11 20:35:00,833 err: at java.io.FileInputStream.<init>(FileInputStream.java:138)
> 2013-10-11 20:35:00,833 err: at java.io.FileInputStream.<init>(FileInputStream.java:97)
> 2013-10-11 20:35:00,833 err: at org.jboss.jbossts.qa.Utils.FileServerIORStore.removeIOR(FileServerIORStore.java:69)
> 2013-10-11 20:35:00,833 err: at org.jboss.jbossts.qa.Utils.ServerIORStore.removeIOR(ServerIORStore.java:47)
> 2013-10-11 20:35:00,833 err: at org.jboss.jbossts.qa.Utils.RemoveServerIORStore.main(RemoveServerIORStore.java:42)
> 2013-10-11 20:35:00,834 err: java.io.FileNotFoundException: ServerIORs (No such file or directory)
> 2013-10-11 20:35:00,834 err: at java.io.FileInputStream.open(Native Method)
> 2013-10-11 20:35:00,834 err: at java.io.FileInputStream.<init>(FileInputStream.java:138)
> 2013-10-11 20:35:00,834 err: at java.io.FileInputStream.<init>(FileInputStream.java:97)
> 2013-10-11 20:35:00,834 err: at org.jboss.jbossts.qa.Utils.FileServerIORStore.removeIOR(FileServerIORStore.java:69)
> 2013-10-11 20:35:00,834 err: at org.jboss.jbossts.qa.Utils.ServerIORStore.removeIOR(ServerIORStore.java:47)
> 2013-10-11 20:35:00,835 err: at org.jboss.jbossts.qa.Utils.RemoveServerIORStore.main(RemoveServerIORStore.java:42)
> 2013-10-11 20:35:00,835 err: java.io.FileNotFoundException: ServerIORs (No such file or directory)
> 2013-10-11 20:35:00,835 err: at java.io.FileInputStream.open(Native Method)
> 2013-10-11 20:35:00,835 err: at java.io.FileInputStream.<init>(FileInputStream.java:138)
> 2013-10-11 20:35:00,835 err: at java.io.FileInputStream.<init>(FileInputStream.java:97)
> 2013-10-11 20:35:00,836 err: at org.jboss.jbossts.qa.Utils.FileServerIORStore.removeIOR(FileServerIORStore.java:69)
> 2013-10-11 20:35:00,836 err: at org.jboss.jbossts.qa.Utils.ServerIORStore.removeIOR(ServerIORStore.java:47)
> 2013-10-11 20:35:00,836 err: at org.jboss.jbossts.qa.Utils.RemoveServerIORStore.main(RemoveServerIORStore.java:42)
> 2013-10-11 20:35:00,836 out: Passed
> {code}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the jbossts-issues
mailing list