search

eclipse-ee4j / glassfish

Eclipse GlassFish
https://eclipse-ee4j.github.io/glassfish/
378 stars 144 forks source link

auto-delegated recovery failed with jdbc/jms app #17789

Closed glassfishrobot closed 12 years ago

glassfishrobot commented 12 years ago

ogs-3.1.2-b11-11_21_2011.zip auto-delegated recovery failed with jdbc/jms app The same test passed on ogs-3.1.2-b10.zip

Environment

RHL 5 and JDK 1.6.0_24

Affected Versions

[3.1.2]

glassfishrobot commented 6 years ago
glassfishrobot commented 12 years ago

@glassfishrobot Commented sherryshen said: The test source is at appserver-sqe/pe/transaction/recovery/cliapp3

Please refer TX_02L for test case description http://agni-1.us.oracle.com/asqe-logs/export1/3.1/docs/sqe/txn/GF31TXRecoveryTestSpec.html

For the same test application, the test passed with tx log at file system, but failed with tx log at database.

From server.log for failed case, "NameNotFoundException: jdbc" is shown in all 3 instances.

http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg/25/artifact/server_in1.log

[#|2011-11-21T15:24:45.483-0800|SEVERE|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions|_ThreadID=18;_ThreadName=Thread-2;|JTS5070: Exception occurred while obtaining JDBC resource [jdbc/nontx] for transaction log.|#]

[#|2011-11-21T15:24:45.484-0800|SEVERE|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions|_ThreadID=18;_ThreadName=Thread-2;|javax.naming.NamingException: Lookup failed for 'jdbc/nontx' in SerialContext[myEnv=

{java.naming.factory.initial=com.sun.enterprise.naming.impl.SerialInitContextFactory, java.naming.factory.state=com.sun.corba.ee.impl.presentation.rmi.JNDIStateFactoryImpl, java.naming.factory.url.pkgs=com.sun.enterprise.naming}

[Root exception is javax.naming.NameNotFoundException: jdbc] at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:518) at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:455) at javax.naming.InitialContext.lookup(InitialContext.java:392) at javax.naming.InitialContext.lookup(InitialContext.java:392) at com.sun.jts.CosTransactions.LogDBHelper.(LogDBHelper.java:93) at com.sun.jts.CosTransactions.LogDBHelper.(LogDBHelper.java:81) at com.sun.jts.CosTransactions.RecoveryManager.dbXARecovery(RecoveryManager.java:1188) at com.sun.jts.CosTransactions.RecoveryManager.dbXARecovery(RecoveryManager.java:1178) at com.sun.jts.CosTransactions.ResyncThread.run(RecoveryManager.java:1879) Caused by: javax.naming.NameNotFoundException: jdbc at com.sun.enterprise.naming.impl.TransientContext.resolveContext(TransientContext.java:310) at com.sun.enterprise.naming.impl.TransientContext.lookup(TransientContext.java:218) at com.sun.enterprise.naming.impl.SerialContextProviderImpl.lookup(SerialContextProviderImpl.java:77) at com.sun.enterprise.naming.impl.LocalSerialContextProviderImpl.lookup(LocalSerialContextProviderImpl.java:119) at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:505) ... 8 more

| #] |

glassfishrobot commented 12 years ago

@glassfishrobot Commented sherryshen said: Raise to P2 since all tx recovery tests with dblog failed on b12.

The failure of app with jdbc and jms is not intermittent. For example, auto-delegated recovery with dblog in appserver-sqe/pe/transaction/recovery/cliapp3 it passed on b10, but failed on b11 multiple times.

The intermittent failure is observed on app with jdbc only. For example, auto-delegated recovery with dblog in appserver-sqe/pe/transaction/recovery/cliweb5 When it fails, the similar ex is shown.

[#|2011-11-29T19:00:19.045-0800|SEVERE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.recovery| _ThreadID=18;_ThreadName=Thread-2;|RAR7109: Error while loading jdbc resources during recovery : jdbc/nontx|#]

[#|2011-11-29T19:00:19.049-0800|INFO|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions| _ThreadID=18;_ThreadName=Thread-2;|JTS5014: Recoverable JTS instance, serverId = [100]|#]

[#|2011-11-29T19:00:19.059-0800|SEVERE|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions| _ThreadID=19;_ThreadName=Thread-2;|JTS5070: Exception occurred while obtaining JDBC resource [jdbc/nontx] for transaction log.|#]

[#|2011-11-29T19:00:19.060-0800|SEVERE|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions| _ThreadID=19;_ThreadName=Thread-2;|javax.naming.NamingException: Lookup failed for 'jdbc/nontx' in SerialContext[myEnv=

{java.naming.factory.initial=com.sun.enterprise.naming.impl.SerialInitContextFactory, java.naming.factory.state=com.sun.corba.ee.impl.presentation.rmi.JNDIStateFactoryImpl, java.naming.factory.url.pkgs=com.sun.enterprise.naming}

[Root exception is javax.naming.NameNotFoundException: jdbc] at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:518) at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:455) at javax.naming.InitialContext.lookup(InitialContext.java:392) at javax.naming.InitialContext.lookup(InitialContext.java:392) at com.sun.jts.CosTransactions.LogDBHelper.(LogDBHelper.java:93) at com.sun.jts.CosTransactions.LogDBHelper.(LogDBHelper.java:81) at com.sun.jts.CosTransactions.RecoveryManager.dbXARecovery(RecoveryManager.java:1188) at com.sun.jts.CosTransactions.RecoveryManager.dbXARecovery(RecoveryManager.java:1178) at com.sun.jts.CosTransactions.ResyncThread.run(RecoveryManager.java:1879) Caused by: javax.naming.NameNotFoundException: jdbc at com.sun.enterprise.naming.impl.TransientContext.resolveContext(TransientContext.java:310) at com.sun.enterprise.naming.impl.TransientContext.lookup(TransientContext.java:218) at com.sun.enterprise.naming.impl.SerialContextProviderImpl.lookup(SerialContextProviderImpl.java:77) at com.sun.enterprise.naming.impl.LocalSerialContextProviderImpl.lookup(LocalSerialContextProviderImpl.java:119) at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:505) ... 8 more

| #] |

glassfishrobot commented 12 years ago

@glassfishrobot Commented sherryshen said: From RE build log for #111 (Dec 1, 2011 1:01:10 AM) 51214. Fix for #17789 - Start ResourceManager if it hadn't started yet at the time of autorecovery on startup — mvatkina / detail

I ran tx recovery tests with using tx db log to verify the fix on above nightly build. The second part of the problem (intermittent failure with jdbc app) was resolved. The original part of the problem (non-intermittent failure with jdbc/jms app) was not resolved.

http://sqe-hudson.us.oracle.com:8080/hudson/view/Sherry_core/job/sherry-tx/

21 b13-12_02_2011

glassfishrobot commented 12 years ago

@glassfishrobot Commented mvatkina said: Which hudson job failed for jdbc/jms after the above change? The latest job in http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg was Nov 29.

glassfishrobot commented 12 years ago

@glassfishrobot Commented mvatkina said: This is a completely different failure. Can you rerun cliweb3 separately on the latest build?

glassfishrobot commented 12 years ago

@glassfishrobot Commented sherryshen said: b13-12_04_2011 1) 1 test with dblog and debug message http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg/ run 34 auto-delegated recovery failed in cliapp3

Debug in client out shows the content of TXN_LOG_TABLE http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg/34/console

[sql] LOCALTID,SERVERNAME,INSTANCENAME,GTRID [sql] 0,apg-sqe2,clustered_instance_2,P100,clustered_instance_2,null [sql] 0,apg-sqe2,clustered_instance_1,P100,clustered_instance_1,null [sql] 0,apg-sqe2,clustered_instance_3,P100,clustered_instance_3,null [sql] 2,apg-sqe2,clustered_instance_2,P43700,clustered_instance_2,020000002ca87b106170672d737165322c636c757374657265645f696e7374616e63655f322c503433373030 [sql]

server.log has info message about transaction logging http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg/34/artifact/server_in1.log [#|2011-12-05T15:07:05.142-0800|INFO|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions| _ThreadID=18;_ThreadName=Thread-2;|JTS5078: Did not create table for transaction logging on this instance. If the table did not exist and was expected to be created by this instance, use FINE log level to see the details of the error.|#]

2) more tests with creating dblog once at top level. http://sqe-hudson.us.oracle.com:8080/hudson/job/sherry-tx-lc-dbg/ run 33 auto-delegated recovery with jdbc passed in cliweb3 auto-delegated recovery with jdbc/jms failed in cliapp3 cli-self recovery with jdbc/jms passed in cliapp2 auto-self recovery with jdbc/jms passed in cliapp2

glassfishrobot commented 12 years ago

@glassfishrobot Commented mvatkina said: Fixed with revs 51214 (Start ResourceManager if it hadn't started yet at the time of autorecovery on startup), 51321 (logging), 51326 (Create a marker record only when XA transaction accesses LogDBHelper), 51339 (Add marker record to the table from CurrentImpl.begin(timeout))

glassfishrobot commented 12 years ago

@glassfishrobot Commented Was assigned to mvatkina

glassfishrobot commented 7 years ago

@glassfishrobot Commented This issue was imported from java.net JIRA GLASSFISH-17789

glassfishrobot commented 12 years ago

@glassfishrobot Commented Reported by sherryshen

glassfishrobot commented 12 years ago

@glassfishrobot Commented Marked as fixed on Friday, December 9th 2011, 1:22:05 pm