客户端数据没有进行回滚 about tx-lcn

[xlorne]

你主要观察一下参与模块的日志信息，看一下参与模块有没有参与到事务中。正常会看到tx-running-start end 的日志打印。再就是提交或者回滚的日志打印消息

[juneryo]

@1991wangliang 看了下客户端日志，start 和 end 是有的，但是没有回滚相关的信息。

2017-11-20 18:20:04,941:INFO 56:http-nio-7071-exec-1(5) TxStartTransactionServerImpl.java:36 - tx-start
2017-11-20 18:20:04,945:INFO 83:pool-4-thread-2(5) SocketManager.java:84 - send-msg->{"a":"cg","k":"tMZ9NGnl","p":{}}
2017-11-20 18:20:04,947:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"{\"st\":1511173204945,\"s\":0,\"nt\":1511173204946,\"g\":\"VIvaGzTf\",\"i\":0,\"o\":0}","k":"tMZ9NGnl"}
2017-11-20 18:20:04,963:INFO 56:http-nio-7071-exec-1(5) ServiceLogAspect.java:36 - SERVICE START: classMethod=>com.tangdi.boot.sample.service.impl.ClientServiceImpl.addOne, args=>[com.tangdi.boot.sample.entity.Client@e392521[name=test01,version=0.0.1,status=1,createTime=<null>,updateTime=<null>,id=<null>]]
2017-11-20 18:20:06,021:WARN 90:hystrix-sample-cloud-server-1(5) ServerConsumerFallback.java:20 - [post] consumer /server fallback
2017-11-20 18:20:06,054:INFO 56:http-nio-7071-exec-1(5) ServiceLogAspect.java:41 - SERVICE END: spendTime=>1105ms, return=>com.tangdi.boot.sample.entity.Client@e392521[name=test01,version=0.0.1,status=1,createTime=20171120182005,updateTime=<null>,id=8]
2017-11-20 18:20:06,070:INFO 92:pool-4-thread-3(5) SocketManager.java:84 - send-msg->{"a":"ctg","k":"wMHBuV7C","p":{"s":1,"g":"VIvaGzTf"}}
2017-11-20 18:20:06,072:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"1","k":"wMHBuV7C"}
2017-11-20 18:20:06,106:INFO 56:http-nio-7071-exec-1(5) TxStartTransactionServerImpl.java:81 - tx-end-VIvaGzTf>1

倒是服务端没有 start end 这些信息。

[xlorne]

tx-start、tx-end 是客户端（启动方）的日志，tx-running-start/tx-running-end 是服务（参与方）的日志，你的参与方没有这样的日志那么首先怀疑你的参与方没有配置好，可能与你的配置有关系。再就是你的发起方既然有日志了 但是没有回滚，是由于你客户端发起并没有出现异常，你只是走了fallback而已。（LCN本身不会创建事务的，只是会协调事务）

[xlorne]

{"a":"ctg","k":"wMHBuV7C","p":{"s":1,"g":"VIvaGzTf"}} 协议文档有介绍，其中s标示的事务模块正常执行。非异常状态，这也是不会回滚事务的

[juneryo]

@1991wangliang
话说启动方和参与方，在配置文件上，应该没区别吧。
我对比了一下两方的配置文件，是一样的。
在使用方面，也和demo一样，启动方的service加上@TxTransaction，但参与方的不需要。
但是参与方的日志里面始终没有出现 tx-running-start/tx-running-end 这样的日志。。。

[xlorne]

那说明应该是你在发起方的时候没有将数据传递给参与方模块（groupId），你可以在configuration下的配置requestintercept是否将数据传递出去。可以加断点看一下。怀疑你这里是多线程的方式调用的，threadlocal就拿不到数据了.

[juneryo]

@1991wangliang
一提到多线程，突然发现demo中，
只有在feign.hystrix.enabled=true的情况下，才有调整hystrix的策略：
hystrix.command.default.execution.isolation.strategy= SEMAPHORE

修改之后，果然参与方出现了相关日志。。。

2017-11-21 12:00:58,846:INFO 56:http-nio-7070-exec-3(5) TxRunningTransactionServerImpl.java:44 - tx-running-start->p4k8h93u
2017-11-21 12:00:58,848:INFO 56:http-nio-7070-exec-3(5) ServiceLogAspect.java:36 - SERVICE START: classMethod=>com.tangdi.boot.sample.service.impl.ServerServiceImpl.addOne, args=>[com.tangdi.boot.sample.entity.Server@374ac92c[name=test01-server,version=0.0.1,status=1,createTime=<null>,updateTime=<null>,id=<null>]]
2017-11-21 12:00:58,849:INFO 56:http-nio-7070-exec-3(5) LCNDBConnection.java:60 - task-create-> datasource_fx1lQvI4
2017-11-21 12:00:58,850:INFO 56:http-nio-7070-exec-3(5) LCNTransactionDataSource.java:38 - get new connection ->p4k8h93u
2017-11-21 12:00:58,851:INFO 56:http-nio-7070-exec-3(5) LCNDBConnection.java:103 - rollback
2017-11-21 12:00:58,858:INFO 56:http-nio-7070-exec-3(5) LCNDBConnection.java:128 - close-state->0,p4k8h93u
2017-11-21 12:00:58,860:INFO 56:http-nio-7070-exec-3(5) LCNDBConnection.java:113 - close-connection->p4k8h93u
2017-11-21 12:00:58,861:INFO 56:http-nio-7070-exec-3(5) LCNDBConnection.java:139 - rollback->p4k8h93u
2017-11-21 12:00:58,861:INFO 56:http-nio-7070-exec-3(5) TxRunningTransactionServerImpl.java:100 - tx-running-end->p4k8h93u,time->14

但是发起方仍未做回滚。。。

2017-11-21 12:00:58,830:INFO 58:http-nio-7071-exec-3(5) TxStartTransactionServerImpl.java:36 - tx-start
2017-11-21 12:00:58,831:INFO 102:pool-4-thread-4(5) SocketManager.java:84 - send-msg->{"a":"cg","k":"pWo9HVuq","p":{}}
2017-11-21 12:00:58,833:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"{\"st\":1511236858832,\"s\":0,\"nt\":1511236858832,\"g\":\"p4k8h93u\",\"i\":0,\"o\":0}","k":"pWo9HVuq"}
2017-11-21 12:00:58,834:INFO 58:http-nio-7071-exec-3(5) ServiceLogAspect.java:36 - SERVICE START: classMethod=>com.tangdi.boot.sample.service.impl.ClientServiceImpl.addOne, args=>[com.tangdi.boot.sample.entity.Client@44810af7[name=test01,version=0.0.1,status=1,createTime=<null>,updateTime=<null>,id=<null>]]
Hibernate: insert into CLIENT (CREATE_TIME, UPDATE_TIME, STATUS, NAME, VERSION) values (?, ?, ?, ?, ?)
2017-11-21 12:00:58,879:INFO 58:http-nio-7071-exec-3(5) ServiceLogAspect.java:41 - SERVICE END: spendTime=>45ms, return=>com.tangdi.boot.sample.entity.Client@44810af7[name=test01,version=0.0.1,status=1,createTime=20171121120058,updateTime=<null>,id=10]
2017-11-21 12:00:58,880:INFO 107:pool-4-thread-5(5) SocketManager.java:84 - send-msg->{"a":"ctg","k":"8zm3LLvj","p":{"s":1,"g":"p4k8h93u"}}
2017-11-21 12:00:58,882:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"1","k":"8zm3LLvj"}
2017-11-21 12:00:58,886:INFO 58:http-nio-7071-exec-3(5) TxStartTransactionServerImpl.java:81 - tx-end-p4k8h93u>1

也就是说，发起方必须手动抛出异常，才能引发回滚操作，而不是tx-manager通过消息通知触发？

[xlorne]

是的，只有触发异常才会执行回滚的。

[juneryo]

@1991wangliang 原来如此，了解了，感谢。

[juneryo]

@1991wangliang 再咨询一个问题。。。
发起方调用的某个方法如果抛出RuntimeException，为啥不会触发参与方的事物回滚。。。
而直接在在service方法中抛出则没问题。

    @Override
    @TxTransaction
    @Transactional(rollbackFor = Exception.class)
    public Client addOne(Client entity) {
        Map<String, String> map = new HashMap<>(3);
        map.put("name", entity.getName() + "-server");
        map.put("version", entity.getVersion());
        map.put("status", entity.getStatus().toString());
        String result = serverConsumer.addOne(map);

        // 这个方法抛出 RuntimeException 不会触发参与方回滚
        parseConsumerResult(result, true);

        // 这里可以成功触发参与方回滚
        // lcn tx starter should throw exception to make service provider rollback
        if (entity.getStatus() == 1) {
            throw new RuntimeException("status should be 0");
        }

        return super.addOne(entity);
    }

更新一下，上面的描述不对，
应该是参与方调用超时(参与方再保存数据之后，sleep了5秒钟)，发起方进入_fallback_之后
parseConsumerResult这个方法解析了_fallback_的返回值，抛出RuntimeException
这个情况下无法触发参与方的回滚。。。

[xlorne]

看一下tx-start的打印日志

[juneryo]

@1991wangliang 刚才更新了一下描述。。。

更新一下，上面的描述不对，
应该是参与方调用超时(参与方再保存数据之后，sleep了5秒钟)，发起方进入fallback之后
parseConsumerResult这个方法解析了fallback的返回值，抛出RuntimeException
这个情况下无法触发参与方的回滚。。。

日志方面的话：

• 发起方：

2017-11-21 17:05:39,426:INFO 57:http-nio-7071-exec-2(5) TxStartTransactionServerImpl.java:36 - tx-start
2017-11-21 17:05:39,429:INFO 97:pool-4-thread-4(5) SocketManager.java:84 - send-msg->{"a":"cg","k":"Z04sl2YI","p":{}}
2017-11-21 17:05:39,431:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"{\"st\":1511255139430,\"s\":0,\"nt\":1511255139430,\"g\":\"Lkl1ZPMZ\",\"i\":0,\"o\":0}","k":"Z04sl2YI"}
2017-11-21 17:05:39,435:INFO 57:http-nio-7071-exec-2(5) ServiceLogAspect.java:36 - SERVICE START: classMethod=>com.tangdi.boot.sample.service.impl.ClientServiceImpl.addOne, args=>[com.tangdi.boot.sample.entity.Client@79f5a58e[name=test01,version=0.0.1,status=1,createTime=<null>,updateTime=<null>,id=<null>]]
2017-11-21 17:05:44,438:WARN 88:HystrixTimer-1(5) ConsumerHelper.java:25 - [POST /server] fallback
2017-11-21 17:05:44,441:INFO 57:http-nio-7071-exec-2(5) ConsumerHelper.java:41 - Call consumer result: {"code":201,"message":"[POST /server] Service fallback"}
2017-11-21 17:05:44,496:INFO 101:pool-4-thread-5(5) SocketManager.java:84 - send-msg->{"a":"ctg","k":"YrofVsoI","p":{"s":0,"g":"Lkl1ZPMZ"}}
2017-11-21 17:05:44,500:INFO 40:nioEventLoopGroup-2-1(10) TransactionHandler.java:51 - 接受->{"d":"0","k":"YrofVsoI"}
2017-11-21 17:05:44,506:INFO 57:http-nio-7071-exec-2(5) TxStartTransactionServerImpl.java:81 - tx-end-Lkl1ZPMZ>0
2017-11-21 17:05:44,508:ERROR 57:http-nio-7071-exec-2(5) GlobalExceptionHandler.java:28 - [POST /server] Service fallback
 java.lang.RuntimeException: [POST /server] Service fallback
	at com.tangdi.boot.common.helper.ConsumerHelper.parseConsumerResult(ConsumerHelper.java:49) ~[classes/:?]
	at com.tangdi.boot.sample.service.impl.ClientServiceImpl.addOne(ClientServiceImpl.java:44) ~[classes/:?]

• 参与方：

2017-11-21 17:05:39,442:INFO 55:http-nio-7070-exec-2(5) TxRunningTransactionServerImpl.java:44 - tx-running-start->Lkl1ZPMZ
2017-11-21 17:05:39,443:INFO 55:http-nio-7070-exec-2(5) ServiceLogAspect.java:36 - SERVICE START: classMethod=>com.tangdi.boot.sample.service.impl.ServerServiceImpl.addOne, args=>[com.tangdi.boot.sample.entity.Server@5c1cc194[name=test01-server,version=0.0.1,status=1,createTime=<null>,updateTime=<null>,id=<null>]]
Hibernate: insert into SERVER (CREATE_TIME, UPDATE_TIME, STATUS, NAME, VERSION) values (?, ?, ?, ?, ?)
2017-11-21 17:05:44,461:INFO 55:http-nio-7070-exec-2(5) ServiceLogAspect.java:41 - SERVICE END: spendTime=>5019ms, return=>com.tangdi.boot.sample.entity.Server@5c1cc194[name=test01-server,version=0.0.1,status=1,createTime=20171121170539,updateTime=<null>,id=9]
2017-11-21 17:05:44,463:INFO 55:http-nio-7070-exec-2(5) TxRunningTransactionServerImpl.java:100 - tx-running-end->Lkl1ZPMZ,time->5020

[xlorne]

参与方模块应该会有提交或者回滚的指令数据吧？你现在tx-start状态确实是回滚的状态。

[juneryo]

@1991wangliang
Orz。。。实在不好意思。。。
刚才在修改参与方service的时候，发现忘记添加@Transactional了。。。
现在应该可以了，日志里提示 事务模块网络异常回滚
非常感谢。。。

[xlorne]

ok 好的