codingapi / tx-lcn

LCN distributed transaction framework, compatible with dubbo, spring cloud and Motan framework, supports various relational databases
https://www.codingapi.com
Apache License 2.0
4.22k stars 1.46k forks source link

服务a调用服务b,服务b中人制造了异常,结果服务a跟服务b都实现了事务回滚,但两个服务的事务组id不一致 #286

Closed 84yy closed 5 years ago

84yy commented 5 years ago

服务a调用服务b,服务b中人制造了异常,结果服务a跟服务b都实现了事务回滚,但两个服务的事务组id不一致时什么原因。

2. Environment:

日志:
==========================服务a的日志==============================

:59:14.310  INFO  [  XNIO-2 task-4] AspectBeforeServiceImpl                  46 : around--> groupId-> null,txTransactionLocal->null
2019-03-08 10:59:14.310  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             45 : 事务发起方切面处开启分布式事务--->begin start transaction
2019-03-08 10:59:14.312  INFO  [ol-15-thread-14] SocketManager                            86 : send-msg->{"a":"cg","k":"XzITiAub","p":{}}
2019-03-08 10:59:14.315  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"{\"st\":1552013954312,\"r\":0,\"s\":0,\"nt\":1552013954315,\"g\":\"JcvQ8ILr\",\"i\":0,\"o\":0}","k":"XzITiAub"}
2019-03-08 10:59:14.316  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    124 : initLCNConnection
2019-03-08 10:59:14.316  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    130 : lcn datasource transaction control 
2019-03-08 10:59:14.317  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    140 : lcn transaction 
2019-03-08 10:59:14.317  INFO  [  XNIO-2 task-4] LCNStartConnection                       64 : transaction is start-connection.
2019-03-08 10:59:14.318  INFO  [  XNIO-2 task-4] LCNStartConnection                       72 : lcn start connection init ok .
2019-03-08 10:59:14.318  INFO  [  XNIO-2 task-4] LCNTransactionDataSource                 45 : get new start connection - > JcvQ8ILr
2019-03-08 10:59:17.444 DEBUG  [  XNIO-2 task-4] insertSelective                          159 : ==>  Preparing: INSERT INTO tag ( id,name,crt_user_name,crt_time,upd_user_name,upd_time ) VALUES( ?,?,?,?,?,? ) 
2019-03-08 10:59:17.445 DEBUG  [  XNIO-2 task-4] insertSelective                          159 : ==> Parameters: 553532186708545536(String), 分布式事务测试(String), (String), 2019-03-08 10:59:17.442(Timestamp), (String), 2019-03-08 10:59:17.442(Timestamp)
2019-03-08 10:59:17.449 DEBUG  [  XNIO-2 task-4] insertSelective                          159 : <==    Updates: 1
2019-03-08 10:59:17.451 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] ---> POST http://198.0.169.104:8769/tenant/txTest HTTP/1.1
2019-03-08 10:59:17.451 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] client-token: eyJhbGciOiJSUzI1NiJ9.eyJzdWIiOiJjYW5kaWRhdGUtbWFuYWdlciIsInVzZXJJZCI6IjkiLCJ1c2VyTmFtZSI6ImNhbmRpZGF0ZS1tYW5hZ2VyIiwiZXhwaXJlIjoxNTUyMDE0MDAwMDQyfQ.YuYAYKHtm4ow_ecc4M0CwnGOt5KWEPeqreuiavIz6hvdVhC7WxMDV_3xWeQjCf-5PGinH4tkb1gSUfJsHj_eVcsCQVyyJGi4YUSEmFWsNEm-0Mw0G7HZztyRpuM3MQYIrIcDLlevsQeiEhEDMdatlGxxHqguKHzeiQ_8aab4-wg
2019-03-08 10:59:17.451 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] Authorization: 
2019-03-08 10:59:17.451 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] ---> END HTTP (0-byte body)
2019-03-08 10:59:17.518 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] <--- HTTP/1.1 500 Internal Server Error (66ms)
2019-03-08 10:59:17.518 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] connection: keep-alive
2019-03-08 10:59:17.518 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] content-type: application/json;charset=UTF-8
2019-03-08 10:59:17.518 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] date: Fri, 08 Mar 2019 02:59:17 GMT
2019-03-08 10:59:17.518 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] transfer-encoding: chunked
2019-03-08 10:59:17.519 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] x-application-context: grouppower-admin:dev:8769
2019-03-08 10:59:17.519 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] 
2019-03-08 10:59:17.519 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] {"status":500,"message":"MessageCenterFeign#aaa() failed and no fallback available."}
2019-03-08 10:59:17.519 DEBUG  [uppower-admin-7] UserFeign                                72 : [UserFeign#txTest] <--- END HTTP (85-byte body)

巴西 2019/3/8 11:05:44
2019-03-08 10:59:17.522  INFO  [  XNIO-2 task-4] LCNStartConnection                       101 : rollback label
2019-03-08 10:59:17.566  INFO  [ol-15-thread-15] SocketManager                            86 : send-msg->{"a":"ctg","k":"XX2IkP3l","p":{"s":0,"g":"JcvQ8ILr"}}
2019-03-08 10:59:17.581  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"0","k":"XX2IkP3l"}
2019-03-08 10:59:17.581  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             145 : <---end start transaction
2019-03-08 10:59:17.582  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             146 : start transaction over, res -> groupId:JcvQ8ILr, now state:rollback
2019-03-08 10:59:17.585 ERROR  [  XNIO-2 task-4] request                                  80 : UT005023: Exception handling request to /test

================服务b日志=========================
2019-03-08 10:59:08.003  INFO  [ntLoopGroup-2-1] TransactionHandler                       106 : heart data --->{"p":"{}","a":"h","k":"h"}
2019-03-08 10:59:08.004  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"5","k":"h"}
2019-03-08 10:59:16.041  INFO  [     Thread-105] ExecutorRegistryThread                   60 : >>>>>>>>>>> xxl-job registry success, registryParam:RegistryParam{registGroup='EXECUTOR', registryKey='admin', registryValue='198.0.169.104:18769'}, registryResult:ReturnT [code=200, msg=null, content=null]
2019-03-08 10:59:17.457  INFO  [  XNIO-2 task-4] AspectBeforeServiceImpl                  46 : around--> groupId-> null,txTransactionLocal->null
2019-03-08 10:59:17.458  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             45 : 事务发起方切面处开启分布式事务--->begin start transaction
2019-03-08 10:59:17.459  INFO  [ool-15-thread-9] SocketManager                            86 : send-msg->{"a":"cg","k":"KWMI3dYS","p":{}}
2019-03-08 10:59:17.462  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"{\"st\":1552013957460,\"r\":0,\"s\":0,\"nt\":1552013957462,\"g\":\"CgB7c0EY\",\"i\":0,\"o\":0}","k":"KWMI3dYS"}
2019-03-08 10:59:17.463  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    124 : initLCNConnection
2019-03-08 10:59:17.463  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    130 : lcn datasource transaction control 
2019-03-08 10:59:17.463  INFO  [  XNIO-2 task-4] AbstractResourceProxy                    140 : lcn transaction 
2019-03-08 10:59:17.464  INFO  [  XNIO-2 task-4] LCNStartConnection                       64 : transaction is start-connection.
2019-03-08 10:59:17.464  INFO  [  XNIO-2 task-4] LCNStartConnection                       72 : lcn start connection init ok .

巴西 2019/3/8 11:06:23
2019-03-08 10:59:17.464  INFO  [  XNIO-2 task-4] LCNTransactionDataSource                 45 : get new start connection - > CgB7c0EY
2019-03-08 10:59:17.469  INFO  [essage-center-4] TransactionRestTemplateInterceptor       26 : LCN-SpringCloud TxGroup info -> groupId:CgB7c0EY,maxTimeOut:20000
2019-03-08 10:59:17.470  INFO  [essage-center-4] LcnZoneAwareLoadBalancerProxy            29 : enter chooseServer method, key:null
2019-03-08 10:59:17.470  INFO  [essage-center-4] LcnLoadBalancerRule                      30 : LCNBalanceProxy - > start
2019-03-08 10:59:17.470  INFO  [essage-center-4] LcnLoadBalancerRule                      70 : putServer->address->198.0.169.104:8863,md5-->5fb6a8bed1d411a23670f1ff097a076d
2019-03-08 10:59:17.471  INFO  [essage-center-4] TxTransactionLocal                       120 : putLoadBalance--> start 
2019-03-08 10:59:17.471  INFO  [ol-15-thread-10] SocketManager                            86 : send-msg->{"a":"plb","k":"5mJfwowL","p":{"d":"5fb6a8bed1d411a23670f1ff097a076d","g":"CgB7c0EY","k":"c4da63075e70eee3c2b27bf1dae265f9"}}
2019-03-08 10:59:17.474  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"1","k":"5mJfwowL"}
2019-03-08 10:59:17.474  INFO  [essage-center-4] TxTransactionLocal                       123 : putLoadBalance--> end ,res ->1
2019-03-08 10:59:17.475  INFO  [essage-center-4] LcnLoadBalancerRule                      43 : LCNBalanceProxy -> only one server available
2019-03-08 10:59:17.475  INFO  [essage-center-4] LcnLoadBalancerRule                      58 : LCNBalanceProxy - > end
2019-03-08 10:59:17.493  INFO  [  XNIO-2 task-4] LCNStartConnection                       101 : rollback label
2019-03-08 10:59:17.496  INFO  [ol-15-thread-11] SocketManager                            86 : send-msg->{"a":"ctg","k":"KZTLrd3l","p":{"s":0,"g":"CgB7c0EY"}}
2019-03-08 10:59:17.512  INFO  [ntLoopGroup-2-1] TransactionHandler                       52 : TxManager-response->{"d":"0","k":"KZTLrd3l"}
2019-03-08 10:59:17.512  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             145 : <---end start transaction
2019-03-08 10:59:17.513  INFO  [  XNIO-2 task-4] TxStartTransactionServerImpl             146 : start transaction over, res -> groupId:CgB7c0EY, now state:rollback
2019-03-08 10:59:17.514 ERROR  [  XNIO-2 task-4] GlobalExceptionHandler                   40 : MessageCenterFeign#aaa() failed and no fallback available.
com.netflix.hystrix.exception.HystrixRuntimeException: MessageCenterFeign#aaa() failed and no fallback available.
84yy commented 5 years ago

服务a的groupId为:JcvQ8ILr 服务b的groupId为 : CgB7c0EY

xlorne commented 5 years ago

应该是由于feign调用的时候开启了多线程导致的,ThreadLocal信息未能传递然后B就再次创建了一个新的groupId

xlorne commented 5 years ago

你现在是测试吗?建议升级到5.x

84yy commented 5 years ago

应该是由于feign调用的时候开启了多线程导致的,ThreadLocal信息未能传递然后B就再次创建了一个新的groupId

是的,我使用了Hystrix做多线程处理,隔离策略是线程池隔离。就你们目前的框架而言,能不能在不升级的基础上,通过自定义隔离策略实现ThreadLocal信息的传递。

84yy commented 5 years ago

问题解决了,通过实现自定义的隔离策略解决了问题。参考这篇文章实用技巧:Hystrix传播ThreadLocal对象(两种方案)