search

apache / incubator-seata

:fire: Seata is an easy-to-use, high-performance, open source distributed transaction solution.
https://seata.apache.org/
Apache License 2.0
25.28k stars 8.78k forks source link

Sharding + Seata Transaction commit failed #3362

Closed sokeung closed 3 years ago

sokeung commented 3 years ago

Ⅰ. Issue Description

Sharding 和 Seata 的示例分别都是正常的。

使用 Sharding + Seata 没有异常时提交事务正常，当出现异常时事务回滚时失败。

i.s.r.d.u.parser.JacksonUndoLogParser : json decode exception, Unexpected character ('¬' (code 172)): expected a valid value (JSON String, Number, Array, Object or token 'null', 'true' or 'false')

Ⅱ. Describe what happened

两个服务：order，product，order 服务通过 feign 远程调用 product 服务。

依赖

<dependency>
    <groupId>com.alibaba.cloud</groupId>
    <artifactId>spring-cloud-alibaba-seata</artifactId>
    <version>2.2.0.RELEASE</version>
</dependency>
<dependency>
    <groupId>org.apache.shardingsphere</groupId>
    <artifactId>shardingsphere-jdbc-core-spring-boot-starter</artifactId>
    <version>5.0.0-alpha</version>
</dependency>
<dependency>
    <groupId>org.apache.shardingsphere</groupId>
    <artifactId>shardingsphere-transaction-base-seata-at</artifactId>
    <version>5.0.0-alpha</version>
</dependency>

配置

server:
  port: 8082
spring:
  application:
    name: product-service
  shardingsphere:
    datasource:
      common:
        driver-class-name: com.mysql.cj.jdbc.Driver
        password: 123456
        type: com.zaxxer.hikari.HikariDataSource
        username: root
      ds-p0:
        jdbc-url: jdbc:mysql://192.168.177.135:3306/seata_storage?serverTimezone=UTC&useSSL=false&useUnicode=true&characterEncoding=UTF-8
      ds-p0-r0:
        jdbc-url: jdbc:mysql://192.168.177.135:3307/seata_storage?serverTimezone=UTC&useSSL=false&useUnicode=true&characterEncoding=UTF-8
      ds-p0-r1:
        jdbc-url: jdbc:mysql://192.168.177.135:3308/seata_storage?serverTimezone=UTC&useSSL=false&useUnicode=true&characterEncoding=UTF-8
      names: ds-p0,ds-p0-r0,ds-p0-r1
    props:
      sql-show: true
    rules:
      replica-query:
        data-sources:
          ds-0:
            load-balancer-name: robin-0
            primary-data-source-name: ds-p0
            replica-data-source-names: ds-p0-r0,ds-p0-r1
        load-balancers:
          robin-0:
            props:
              sql-show: true
            type: ROUND_ROBIN
      sharding:
        binding-tables: product
        default-database-strategy:
          standard:
            sharding-algorithm-name: database-inline
            sharding-column: id
        key-generators:
          snowflake:
            props:
              worker-id: 123
            type: SNOWFLAKE
        sharding-algorithms:
          product-inline:
            props:
              algorithm-expression: product_$->{id % 3}
            type: INLINE
        tables:
          product:
            actual-data-nodes: ds-p0.product_$->{0..2}
            key-generate-strategy:
              column: id
              key-generator-name: snowflake
            table-strategy:
              standard:
                sharding-algorithm-name: product-inline
                sharding-column: id
  cloud:
    loadbalancer: # 重试机制
      retry:
        enabled: true
        retryable-status-codes: 500
        retry-on-all-operations: false
        max-retries-on-next-service-instance: 3
        max-retries-on-same-service-instance: 3
    nacos:
      server-addr: 192.168.177.135:8848,192.168.177.135:8849,192.168.177.135:8850
      username: nacos
      password: yY1C9Qh3bs8a72
      discovery:
        namespace: fd84373c-fd56-41b6-8906-c972e462d529
        service: ${spring.application.name}
  aop:
    proxy-target-class: true
mybatis:
  config-location: classpath:mybatis/mybatis-config.xml

feign:
  compression:
    request:
      enabled: true
      min-request-size: 2048
      mime-types: text/xml,application/xml,application/json
    response:
      enabled: true
      useGzipDecoder: true
  client:
    config:
      default:
        connectTimeout: 5000
        readTimeout: 5000
        loggerLevel: FULL
seata:
  application-id: ${spring.application.name}
  tx-service-group: product-service-group
  service:
    vgroup-mapping:
      product-service-group: default
    disable-global-transaction: false
  registry:
    type: nacos
    nacos:
      application: seata-server
      serverAddr: 192.168.177.135:8848,192.168.177.135:8849,192.168.177.135:8850
      group: SEATA_GROUP
      namespace: fd84373c-fd56-41b6-8906-c972e462d529
      cluster: default
      username: nacos
      password: yY1C9Qh3bs8a72
  enable-auto-data-source-proxy: true
  use-jdk-proxy: true

代码

OrderServiceImpl

@Override
@GlobalTransactional // <1>
@ShardingTransactionType(TransactionType.BASE)
public Long createOrder(Long userId, Long productId, Integer price) {
    Integer amount = 1; // 购买数量，暂时设置为 1。

    log.info("[createOrder] 当前 XID: {}", RootContext.getXID());

    // <2> 扣减库存
    ProductReduceStockDTO productReduceStockDTO = new ProductReduceStockDTO().setProductId(productId).setAmount(amount);
    productService.reduceStock(productReduceStockDTO);

    // <3> 扣减余额
    accountService.reduceBalance(new AccountReduceBalanceDTO().setUserId(userId).setPrice(price));

    // <4> 保存订单
    OrderDO order = new OrderDO().setUserId(userId).setProductId(productId).setPayAmount(amount * price);
    orderDao.saveOrder(order);
    log.info("[createOrder] 保存订单: {}", order.getId());

    // 返回订单编号
    return order.getId();
}

ProductServiceImpl

@Override
@Transactional // <1> 开启新事物
//@ShardingTransactionType(TransactionType.LOCAL)
public void reduceStock(Long productId, Integer amount) throws Exception {
    log.info("[reduceStock] 当前 XID: {}", RootContext.getXID());

    // <2> 检查库存
    checkStock(productId, amount);

    log.info("[reduceStock] 开始扣减 {} 库存", productId);
    // <3> 扣减库存
    int updateCount = productDao.reduceStock(productId, amount);
    // 扣除成功
    if (updateCount == 0) {
        log.warn("[reduceStock] 扣除 {} 库存失败", productId);
        throw new Exception("库存不足");
    }
    // 扣除失败
    log.info("[reduceStock] 扣除 {} 库存成功", productId);
}

数据库

image

错误日志

2020-12-11 04:25:27.621  INFO 5020 --- [nio-8082-exec-8] c.l.p.controller.ProductController       : [reduceStock] 收到减少库存请求, 商品:543746752445394966, 价格:1
2020-12-11 04:25:27.623  INFO 5020 --- [nio-8082-exec-8] c.l.p.service.impl.ProductServiceImpl    : [reduceStock] 当前 XID: 192.168.177.135:8092:80516910965346304
2020-12-11 04:25:27.623  INFO 5020 --- [nio-8082-exec-8] c.l.p.service.impl.ProductServiceImpl    : [checkStock] 检查 543746752445394966 库存
2020-12-11 04:25:27.625  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: SELECT stock FROM product WHERE id = ?
2020-12-11 04:25:27.625  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLSelectStatement(limit=Optional.empty, lock=Optional.empty)
2020-12-11 04:25:27.625  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT stock FROM product_0 WHERE id = ? ::: [543746752445394966]
2020-12-11 04:25:27.637  INFO 5020 --- [nio-8082-exec-8] c.l.p.service.impl.ProductServiceImpl    : [reduceStock] 开始扣减 543746752445394966 库存
2020-12-11 04:25:27.783  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: SELECT * FROM product LIMIT 1
2020-12-11 04:25:27.783  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLSelectStatement(limit=Optional[org.apache.shardingsphere.sql.parser.sql.common.segment.dml.pagination.limit.LimitSegment@888706f], lock=Optional.empty)
2020-12-11 04:25:27.783  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT * FROM product_0 LIMIT 1
2020-12-11 04:25:27.783  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT * FROM product_1 LIMIT 1
2020-12-11 04:25:27.783  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT * FROM product_2 LIMIT 1
2020-12-11 04:25:27.869  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: SELECT id, stock FROM product WHERE id = ? AND stock >= ? FOR UPDATE
2020-12-11 04:25:27.870  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLSelectStatement(limit=Optional.empty, lock=Optional[org.apache.shardingsphere.sql.parser.sql.common.segment.dml.predicate.LockSegment@16fe4ee])
2020-12-11 04:25:27.870  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT id, stock FROM product_0 WHERE id = ? AND stock >= ? FOR UPDATE ::: [543746752445394966, 1]
2020-12-11 04:25:27.887  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: UPDATE product SET stock = stock - ? WHERE id = ? AND stock >= ?
2020-12-11 04:25:27.887  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLUpdateStatement(orderBy=Optional.empty, limit=Optional.empty)
2020-12-11 04:25:27.887  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: UPDATE product_0 SET stock = stock - ? WHERE id = ? AND stock >= ? ::: [1, 543746752445394966, 1]
2020-12-11 04:25:27.916  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: SELECT id, stock FROM product WHERE  (id ) in (  (?)  )
2020-12-11 04:25:27.916  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLSelectStatement(limit=Optional.empty, lock=Optional.empty)
2020-12-11 04:25:27.916  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT id, stock FROM product_0 WHERE  (id ) in (  (?)  ) ::: [543746752445394966]
2020-12-11 04:25:28.464  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Logic SQL: INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (?, ?, ?, ?, ?, now(6), now(6))
2020-12-11 04:25:28.464  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : SQLStatement: MySQLInsertStatement(setAssignment=Optional.empty, onDuplicateKeyColumns=Optional.empty)
2020-12-11 04:25:28.464  INFO 5020 --- [nio-8082-exec-8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (?, ?, ?, ?, ?, now(6), now(6)) ::: [80516912693399553, 192.168.177.135:8092:80516910965346304, serializer=jackson, javax.sql.rowset.serial.SerialBlob@e1cbd966, 0]
2020-12-11 04:25:28.481  INFO 5020 --- [nio-8082-exec-8] c.l.p.service.impl.ProductServiceImpl    : [reduceStock] 扣除 543746752445394966 库存成功
2020-12-11 04:25:28.482  INFO 5020 --- [nio-8082-exec-8] c.l.p.controller.ProductController       : [reduceStock] 减少库存请求执行完成
2020-12-11 04:25:28.482  WARN 5020 --- [nio-8082-exec-8] c.a.c.seata.web.SeataHandlerInterceptor  : xid in change during RPC from 192.168.177.135:8092:80516910965346304 to null
2020-12-11 04:25:28.881  INFO 5020 --- [ch_RMROLE_1_1_8] i.s.c.r.p.c.RmBranchRollbackProcessor    : rm handle branch rollback process:xid=192.168.177.135:8092:80516910965346304,branchId=80516912693399553,branchType=AT,resourceId=jdbc:mysql://192.168.177.135:3306/seata_storage,applicationData=null
2020-12-11 04:25:28.885  INFO 5020 --- [ch_RMROLE_1_1_8] io.seata.rm.AbstractRMHandler            : Branch Rollbacking: 192.168.177.135:8092:80516910965346304 80516912693399553 jdbc:mysql://192.168.177.135:3306/seata_storage
2020-12-11 04:25:28.897  INFO 5020 --- [ch_RMROLE_1_1_8] ShardingSphere-SQL                       : Logic SQL: SELECT * FROM undo_log WHERE branch_id = ? AND xid = ? FOR UPDATE
2020-12-11 04:25:28.897  INFO 5020 --- [ch_RMROLE_1_1_8] ShardingSphere-SQL                       : SQLStatement: MySQLSelectStatement(limit=Optional.empty, lock=Optional[org.apache.shardingsphere.sql.parser.sql.common.segment.dml.predicate.LockSegment@319da564])
2020-12-11 04:25:28.897  INFO 5020 --- [ch_RMROLE_1_1_8] ShardingSphere-SQL                       : Actual SQL: ds-p0 ::: SELECT * FROM undo_log WHERE branch_id = ? AND xid = ? FOR UPDATE ::: [80516912693399553, 192.168.177.135:8092:80516910965346304]
2020-12-11 04:25:28.902 ERROR 5020 --- [ch_RMROLE_1_1_8] i.s.r.d.u.parser.JacksonUndoLogParser    : json decode exception, Unexpected character ('¬' (code 172)): expected a valid value (JSON String, Number, Array, Object or token 'null', 'true' or 'false')
 at [Source: (byte[])"�� sr "javax.sql.rowset.serial.SerialBlob��kQ��� J lenJ origLenL blobt Ljava/sql/Blob;[ buft [Bxp      �      �pur [B���T�  xp  �{"@class":"io.seata.rm.datasource.undo.BranchUndoLog","xid":"192.168.177.135:8092:80516910965346304","branchId":80516912693399553,"sqlUndoLogs":["java.util.ArrayList",[{"@class":"io.seata.rm.datasource.undo.SQLUndoLog","sqlType":"UPDATE","tableName":"product","beforeImage":{"@class":"io.seata.rm.datasource.sql.struct.TableRecords","tableName":"product"[truncated 879 bytes]; line: 1, column: 2]

com.fasterxml.jackson.core.JsonParseException: Unexpected character ('¬' (code 172)): expected a valid value (JSON String, Number, Array, Object or token 'null', 'true' or 'false')
 at [Source: (byte[])"�� sr "javax.sql.rowset.serial.SerialBlob��kQ��� J lenJ origLenL blobt Ljava/sql/Blob;[ buft [Bxp      �      �pur [B���T�  xp  �{"@class":"io.seata.rm.datasource.undo.BranchUndoLog","xid":"192.168.177.135:8092:80516910965346304","branchId":80516912693399553,"sqlUndoLogs":["java.util.ArrayList",[{"@class":"io.seata.rm.datasource.undo.SQLUndoLog","sqlType":"UPDATE","tableName":"product","beforeImage":{"@class":"io.seata.rm.datasource.sql.struct.TableRecords","tableName":"product"[truncated 879 bytes]; line: 1, column: 2]
    at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1851) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:707) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.core.base.ParserMinimalBase._reportUnexpectedChar(ParserMinimalBase.java:632) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._handleUnexpectedValue(UTF8StreamJsonParser.java:2686) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._nextTokenNotInObject(UTF8StreamJsonParser.java:865) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.nextToken(UTF8StreamJsonParser.java:757) ~[jackson-core-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:4664) ~[jackson-databind-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4513) ~[jackson-databind-2.11.3.jar:2.11.3]
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3529) ~[jackson-databind-2.11.3.jar:2.11.3]
    at io.seata.rm.datasource.undo.parser.JacksonUndoLogParser.decode(JacksonUndoLogParser.java:139) ~[seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.datasource.undo.AbstractUndoLogManager.undo(AbstractUndoLogManager.java:276) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.datasource.DataSourceManager.branchRollback(DataSourceManager.java:178) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:125) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:67) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:63) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:116) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.AbstractRMHandler.handle(AbstractRMHandler.java:63) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.DefaultRMHandler.handle(DefaultRMHandler.java:63) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.core.protocol.transaction.BranchRollbackRequest.handle(BranchRollbackRequest.java:35) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.rm.AbstractRMHandler.onRequest(AbstractRMHandler.java:150) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.handleBranchRollback(RmBranchRollbackProcessor.java:63) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:58) [seata-all-1.3.0.jar:1.3.0]
    at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:265) [seata-all-1.3.0.jar:1.3.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_261]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_261]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
    at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_261]

2020-12-11 04:25:28.907  INFO 5020 --- [ch_RMROLE_1_1_8] i.seata.rm.datasource.DataSourceManager  : branchRollback failed. branchType:[AT], xid:[192.168.177.135:8092:80516910965346304], branchId:[80516912693399553], resourceId:[jdbc:mysql://192.168.177.135:3306/seata_storage], applicationData:[null]. reason:[Branch session rollback failed and try again later xid = 192.168.177.135:8092:80516910965346304 branchId = 80516912693399553 com.fasterxml.jackson.core.JsonParseException: Unexpected character ('¬' (code 172)): expected a valid value (JSON String, Number, Array, Object or token 'null', 'true' or 'false')
 at [Source: (byte[])"�� sr "javax.sql.rowset.serial.SerialBlob��kQ��� J lenJ origLenL blobt Ljava/sql/Blob;[ buft [Bxp      �      �pur [B���T�  xp  �{"@class":"io.seata.rm.datasource.undo.BranchUndoLog","xid":"192.168.177.135:8092:80516910965346304","branchId":80516912693399553,"sqlUndoLogs":["java.util.ArrayList",[{"@class":"io.seata.rm.datasource.undo.SQLUndoLog","sqlType":"UPDATE","tableName":"product","beforeImage":{"@class":"io.seata.rm.datasource.sql.struct.TableRecords","tableName":"product"[truncated 879 bytes]; line: 1, column: 2]]
2020-12-11 04:25:28.908  INFO 5020 --- [ch_RMROLE_1_1_8] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_RollbackFailed_Retryable

Ⅲ. Describe what you expected to happen

Ⅳ. How to reproduce it (as minimally and precisely as possible)

Ⅴ. Anything else we need to know?

Ⅵ. Environment:

sokeung commented 3 years ago

Sharding configuration issues.

Zhrey commented 3 years ago

我也有同样问题，请问是sharding 哪里配置错了？

sokeung commented 3 years ago

我也有同样的问题，请问是分片吗？哪里配置错了？

Sharding 官方没有给出正确的处理方式。如果使用 Sharding + Seata 分库分表的方案下会出现此问题（当初 alpha 版本没去深究），读写分离不会出现，只能等正式版在重现此问题看是否修复。

zysimple commented 1 year ago

问题在这里有解答：https://github.com/seata/seata/issues/3541