这几天在做一些Transaction方面的研究，碰到一个诡异的问题。问题大概是这样的，之前我的测试一直在公司做，今天把工作带到家里了，结果因为如下问题，导致我没法工作了。
weblogic.transaction.RollbackException: SubCoordinator 'server_2+10.182.216.189:7021+driver_test_domain+t3+' not available
at weblogic.rjvm.ResponseImpl.unmarshalReturn(ResponseImpl.java:215)
at weblogic.rmi.internal.BasicRemoteRef.invoke(BasicRemoteRef.java:224)
at weblogic.transaction.internal.CoordinatorImpl_923_WLStub.commit(Unknown Source)
at weblogic.transaction.internal.TransactionImpl.commit(TransactionImpl.java:324)
at weblogic.transaction.internal.TransactionManagerImpl.commit(TransactionManagerImpl.java:283)
at weblogic.transaction.internal.TransactionManagerImpl.commit(TransactionManagerImpl.java:277)
at test.jdbc.DriverTest.xaTest(DriverTest.java:293)
at test.jdbc.DriverTest.main(DriverTest.java:49)
Caused by: weblogic.transaction.RollbackException: SubCoordinator 'server_2+10.182.216.189:7021+driver_test_domain+t3+' not available
at weblogic.transaction.internal.TransactionImpl.throwRollbackException(TransactionImpl.java:1809)
at weblogic.transaction.internal.ServerTransactionImpl.internalCommit(ServerTransactionImpl.java:331)
at weblogic.transaction.internal.ServerTransactionImpl.commit(ServerTransactionImpl.java:227)
at weblogic.transaction.internal.CoordinatorImpl.commit(CoordinatorImpl.java:101)
at weblogic.transaction.internal.CoordinatorImpl_WLSkel.invoke(Unknown Source)
at weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:553)
at weblogic.rmi.internal.BasicServerRef$1.run(BasicServerRef.java:443)
at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:147)
at weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:439)
at weblogic.rmi.internal.BasicServerRef.access$300(BasicServerRef.java:61)
at weblogic.rmi.internal.BasicServerRef$BasicExecuteRequest.run(BasicServerRef.java:983)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)
初看到这个异常，家里做测试，Tx的subcoordinator怎么会用到公司的IP（10.182.216.189）呐？怎么着也应该是192.168.0.51吧？第一感觉是我的datasource配置有问题，仔细检查了一下，没什么问题。再检查检查server2的listen address，也没有问题。见鬼了，怎么会这样？还有什么地方能跟IP有关系呢？tlog? 没错，的确好像跟tlog有关系，当时想直接把tlog删掉，重起一下算了。毕竟自己最近在做JTA的调查，干脆自己彻底debug一下算了。
重新启动客户端测试程序，debug一下客户端transaction信息。顺便提一下，weblogic中transaction在client、server之间是通过PropagationContext来回传递的，一次RMI调用，会导致一次传递来回。PropagationConext中一般包括如下信息：
Xid: 事务ID
CoordinatorURL: 事务主coordinator的URL(最终事务提交在对应的server上完成)
scURLs: subcoordinator url列表，每个involve到该tx中的server url都在其中。coordinator通过这个url通知每个subcoordinator完成事务的提交、回滚。
resNames: involve到该tx中所以resource的名字列表
......
从异常上来看，这个问题跟subCoordinator有关，所以在客户端，我只debug了scURLs，如下，
从debug信息来看，server2的scURL应该是没有问题的。回头再看看这个异常，因为异常是在客户端发起提交请求的时候，server端抛出的，问题是，我传递过去的是个正确的scURL(192.168.0.51)，server端怎么会解析出一个错误的url（10.182.216.189）呢？
继续debug server端，server端收到coordinatorImpl_stub的commit()时，它需要先从PropagationContext中restore transaction信息，包括根据scURLs还原scInfoList, 根据resNames还原resourceInfoList。问题出在了还原scInfoList的时候。如下：
1 if (scURLs != null) {
2 for (int i = 0; i < scURLs.length; i++) {
3 String scURL = scURLs[i];
4 if (tm.isLocalCoordinator(scURL)) continue;
5 SCInfo sci = tx.getOrCreateSCInfo(scURL);
6 sci.setState(scStates[i]);
7 if (scSyncRegs[i] == 1) sci.setSyncRegistered(true);
8 }
9 }
也就是说，PropagationContext还原事务的时候会遍历每个scURL，如果是个local的url，则忽略它，否则会要求tx检查该scURL对应的scInfo是否已经存在于tx自己的scInfoList中。再罗索一句，weblogic中，无论server端，还是client端，都会将tx保存在当前TransactionManager的txMap中，PropagationContext还原tx的时候，首先检查xid对应的tx是否存在于txMap中，没有的话，它会负责创建一个tx。再看看tx.getOrCreateSCInfo(scURL)是怎么工作的，
1 SCInfo getOrCreateSCInfo(String scURL) {
2 if (scInfoList != null) {
3 for (int i = 0; i < scInfoList.size(); i++) {
4 SCInfo sci = (SCInfo) scInfoList.get(i);
5 if (sci.getCoordinatorDescriptor().representsCoordinatorURL(scURL)) {
6 return sci;
7 }
8 }
9 }
10 SCInfo sci = createSCInfo(scURL);
11 addSC(sci);
12 return sci;
13 }
它也是遍历自己手里的scInfoList，如果发现list中某个对象和传递进来的scURL匹配，则返回这个对象，否则它创建一个新的scInfo, 把它放入scInfoList并返回。那么它是怎么判断匹配与否的呢？
1 final boolean representsCoordinatorURL(String aCoURL)
2 {
3 return getServerID().equals(getServerID(aCoURL));
4 }
匹配的依据就是ServerID相等，serveId是什么？其实就是DomainName+ServerName，例如，driver_test_domain+server_2。它并不关心IP, Port，所以问题就出现了。出问题的时候，我debug出来tx中的scInfoList如下：
因为从传递进来的scURL解析出来的ServerID也是driver_test_domain+server_2，所以tx会认为这scURL对应的scInfo已经存在，它将直接使用这个scInfo作为subcoordinator提交事务。因为这个已有的scInfo根本就不可用，所以事务是无法提交的，就像我们开始看到的异常一样。
接下来的问题是，这个错误的scInfo是什么时候被创建的呢？ SCInfo中并没有其他什么东西，核心的只有一个CoordinatorDescriptor。创建scInfo的时候也只是根据scURL，调用Coordinator的gerOrCreate方法给该scInfo分配一个coordinatorDescriptor。这个getOrCreate如下,
1 static CoordinatorDescriptor getOrCreate(String aCoURL)
2 {
3 if (aCoURL == null) return null;
4 CoordinatorDescriptor cd =
5 (CoordinatorDescriptor) knownServers.get(getServerID(aCoURL));
6 if (cd == null) cd = new CoordinatorDescriptor(aCoURL);
7 return cd;
8 }
从这我们可以看到，CoordinatorDescriptor也是通过ServerID标示其唯一性的，knownServers是个process-wide变量，tlog recover的时候，就会向其中加入对象。因为我的tlog如下：
如果我删掉tlog，客户端程序运行正常。因为tlog被我破坏了，没法重现这个问题，也无法作进一步的debug,所以不能证明那个错误的coordinatorDescriptor就是tlog recover时创建的。95%应该是这样的吧。
好了，问题解决了，虽然我的问题中只涉及了IP，但我认为，server端口变化也应该会引起类似的问题。这个问题算是weblogic的bug吗？应该算是吧！
补充点信息，这个是我在server端加的debug信息，可以看到，的确是在tlog中server checkpoint做recover的时候，创建了变更前IP对应的CoordinatorDescriptor信息。但因为weblogic内部比较coordinator的时候，只比较domain name + server name，而不关心address、port等信息，最终出现subcoordinator出错。
to put follow coordinator to knownServers of CoordinatorDescriptor:
serverID: driver_test_domain+server_2
coordinatorURLserver_2+10.182.216.189:7021+driver_test_domain+t3+
java.lang.Exception
at weblogic.transaction.internal.CoordinatorDescriptor.init(CoordinatorDescriptor.java:176)
at weblogic.transaction.internal.CoordinatorDescriptor.<init>(CoordinatorDescriptor.java:128)
at weblogic.transaction.internal.ServerCoordinatorDescriptor.<init>(ServerCoordinatorDescriptor.java:258)
at weblogic.transaction.internal.ServerCoordinatorDescriptor.getOrCreate(ServerCoordinatorDescriptor.java:953)
at weblogic.transaction.internal.ServerCoordinatorDescriptor.getOrCreate(ServerCoordinatorDescriptor.java:371)
at weblogic.transaction.internal.ServerCheckpoint.onRecovery(ServerCheckpoint.java:175)
at weblogic.transaction.internal.StoreTransactionLoggerImpl.recover(StoreTransactionLoggerImpl.java:441)
at weblogic.transaction.internal.StoreTransactionLoggerImpl.init(StoreTransactionLoggerImpl.java:230)
at weblogic.transaction.internal.StoreTransactionLoggerImpl.init(StoreTransactionLoggerImpl.java:212)
at weblogic.transaction.internal.StoreTransactionLoggerImpl.<init>(StoreTransactionLoggerImpl.java:121)
at weblogic.transaction.internal.ServerTransactionManagerImpl.recover(ServerTransactionManagerImpl.java:933)
at weblogic.transaction.internal.TransactionRecoveryService.startOwnRecoveryIfNeeded(TransactionRecoveryService.java:214)
at weblogic.transaction.internal.TransactionRecoveryService.resume(TransactionRecoveryService.java:165)
at weblogic.transaction.internal.TransactionRecoveryService.start(TransactionRecoveryService.java:181)
at weblogic.t3.srvr.SubsystemRequest.run(SubsystemRequest.java:64)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)
posted on 2009-02-23 08:07
走走停停又三年 阅读(3344)
评论(7) 编辑 收藏 所属分类:
Weblogic