這幾天在做一些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
走走停停又三年 閱讀(3364)
評論(7) 編輯 收藏 所屬分類:
Weblogic