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.23k stars 8.76k forks source link

seata 1.0.0 undo_log没有及时删除，全局事务回滚没有执行回滚sql，seata-server日志报错刷屏 #2183

Closed azbh111 closed 3 years ago

azbh111 commented 4 years ago

Ⅰ. Issue Description

  1. 开启全局事务，分支1提交，分之二提交，全局事务提交，没有删除undo_log
  2. 开启全局事务，分支1提交，分之二提交，然后在全局事务中抛异常，触发了回滚： rollback status: RollbackRetrying。 但实际上没有执行回滚sql，undo_log也没删除。
  3. 不知道在什么情况下, 触发undo回滚操作后，会无限报错，原因是回滚sql的表名被解析成了 saas_yibao.saas_yibao.test_model
  4. seata-server狂刷报错

case1日志

2020-01-14 14:56:19.850 qtp1682973478-90 reqId:6420476651811917438 INFO  EnhancedServiceLoader:236 - load ContextCore[null] extension by class[io.seata.core.context.ThreadLocalContextCore]
2020-01-14 14:56:19.854 qtp1682973478-90 reqId:6420476651811917438 INFO  EnhancedServiceLoader:236 - load TransactionManager[null] extension by class[io.seata.tm.DefaultTransactionManager]
2020-01-14 14:56:19.854 qtp1682973478-90 reqId:6420476651811917438 INFO  TransactionManagerHolder:40 - TransactionManager Singleton io.seata.tm.DefaultTransactionManager@207fcb50
2020-01-14 14:56:19.859 qtp1682973478-90 reqId:6420476651811917438 INFO  EnhancedServiceLoader:236 - load LoadBalance[null] extension by class[io.seata.discovery.loadbalance.RandomLoadBalance]
2020-01-14 14:56:19.979 qtp1682973478-90 reqId:6420476651811917438 INFO  DefaultGlobalTransaction:106 - Begin new global transaction [172.20.4.224:8091:2032712768]
2020-01-14 14:56:19.998 configOperate_2_2 reqId: WARN  FileConfiguration:266 - Could not found property client.report.success.enable, try to use default value instead.
2020-01-14 14:56:20.093 qtp1682973478-90 reqId:6420476651811917438 INFO  RSReflector:39 - detect mybatis PropertyCustomizerFactory: com.ruoshui.starter.mybatis.reflect.impl.JdbcPropertyCustomizerFactory
2020-01-14 14:56:20.361 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 56 0 Seata1Service.insert.insertUseGeneratedKeys.31 SELECT * FROM saas_yibao.test_model LIMIT 1;
2020-01-14 14:56:20.599 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 83 0 Seata1Service.insert.insertUseGeneratedKeys.31 INSERT INTO saas_yibao.test_model ( id, name ) VALUES( null, '768a3912-b4d9-405e-a0ff-61a94bb1a4c8' );
2020-01-14 14:56:20.647 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 41 0 Seata1Service.insert.insertUseGeneratedKeys.31 SELECT * FROM saas_yibao.test_model WHERE id in ('313');
2020-01-14 14:56:20.783 qtp1682973478-90 reqId:6420476651811917438 WARN  EnhancedServiceLoader:318 - load [io.seata.rm.datasource.undo.parser.ProtostuffUndoLogParser] class fail. io/protostuff/runtime/RuntimeEnv
2020-01-14 14:56:20.784 qtp1682973478-90 reqId:6420476651811917438 INFO  EnhancedServiceLoader:236 - load UndoLogParser[jackson] extension by class[io.seata.rm.datasource.undo.parser.JacksonUndoLogParser]
2020-01-14 14:56:20.875 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 41 1 Seata1Controller.insertInsert.insert.36 INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (2032712771, '172.20.4.224:8091:2032712768', 'serializer=jackson',..., 0, now(), now());
2020-01-14 14:56:21.164 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 41 0 Seata1Controller.insertInsert.selectByPrimaryKey.37 SELECT id,name FROM saas_yibao.test_model WHERE id = 313;
2020-01-14 14:56:21.169 qtp1682973478-90 reqId:6420476651811917438 INFO  Seata1Controller:38 - 1: TestModel(id=313, name=768a3912-b4d9-405e-a0ff-61a94bb1a4c8)
2020-01-14 14:56:21.436 qtp1682973478-90 reqId:6420476651811917438 INFO  FeignCommonInterceptor:106 - call feign request, set appName=hospital
2020-01-14 14:56:21.436 qtp1682973478-90 reqId:6420476651811917438 WARN  FeignCommonInterceptor:116 - does not have reqId context, gen new one, 4435624419708747775
2020-01-14 14:56:21.436 qtp1682973478-90 reqId:6420476651811917438 INFO  FeignCommonInterceptor:126 - call feign request, reqId:4435624419708747775 , url:/gateway/seata/test/insert
2020-01-14 14:56:21.659 qtp1682973478-88 reqId:4435624419708747775 INFO  sql:62 - 82 0 Seata2Service.insert.insertUseGeneratedKeys.22 INSERT INTO saas_yibao.test_model ( id, name ) VALUES( null, '73dd57f5-dce6-4442-b49d-17ecb43422c5' );
2020-01-14 14:56:21.702 qtp1682973478-88 reqId:4435624419708747775 INFO  sql:62 - 41 0 Seata2Service.insert.insertUseGeneratedKeys.22 SELECT * FROM saas_yibao.test_model WHERE id in ('314');
2020-01-14 14:56:21.805 qtp1682973478-88 reqId:4435624419708747775 INFO  sql:62 - 40 1 Seata2Service.insert.insertUseGeneratedKeys.22 INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (2032712775, '172.20.4.224:8091:2032712768', 'serializer=jackson', ..., 0, now(), now());
2020-01-14 14:56:22.021 qtp1682973478-88 reqId:4435624419708747775 INFO  GatewayFilter:8 - totaltime=509,method=POST,command=/gateway/seata/test/insert,httpStatus=200,clientId=402a7889-e636-4b90-aee1-efd0be757cdb,systemVersion=null,from 172.17.0.1,userAgent=okhttp/3.11.0
2020-01-14 14:56:22.075 qtp1682973478-90 reqId:6420476651811917438 INFO  sql:62 - 41 0 Seata1Controller.insertInsert.selectByPrimaryKey.40 SELECT id,name FROM saas_yibao.test_model WHERE id = 314;
2020-01-14 14:56:22.076 qtp1682973478-90 reqId:6420476651811917438 INFO  Seata1Controller:41 - 2: TestModel(id=314, name=73dd57f5-dce6-4442-b49d-17ecb43422c5)
2020-01-14 14:56:22.146 qtp1682973478-90 reqId:6420476651811917438 INFO  DefaultGlobalTransaction:145 - [172.20.4.224:8091:2032712768] commit status: Committed
2020-01-14 14:56:22.153 qtp1682973478-90 reqId:6420476651811917438 INFO  CoreFilter:8 - totaltime=2400,method=GET,command=/wapi/seata/test/insertInsert,httpStatus=200,clientId=402a7889-e636-4b90-aee1-efd0be757cdb,systemVersion=null,from 127.0.0.1,userAgent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.117 Safari/537.36

case2日志

2020-01-14 14:37:29.303 qtp1262638455-111 reqId:5540008332684446657 INFO  DefaultGlobalTransaction:106 - Begin new global transaction [172.20.4.223:8091:2032717310]
2020-01-14 14:37:29.478 qtp1262638455-111 reqId:5540008332684446657 INFO  sql:62 - 84 0 Seata1Service.insert.insertUseGeneratedKeys.31 INSERT INTO saas_yibao.test_model ( id, name ) VALUES( null, 'f4cece1f-0624-49ac-bbcf-78e4c4918d93' );
2020-01-14 14:37:29.522 qtp1262638455-111 reqId:5540008332684446657 INFO  sql:62 - 42 0 Seata1Service.insert.insertUseGeneratedKeys.31 SELECT * FROM saas_yibao.test_model WHERE id in ('311');
2020-01-14 14:37:29.621 qtp1262638455-111 reqId:5540008332684446657 INFO  sql:62 - 42 1 Seata1Controller.insertInsert.insert.36 INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (2032717355, '172.20.4.223:8091:2032717310', 'serializer=jackson',此处省略一千字。。, 0, now(), now());
2020-01-14 14:37:29.885 qtp1262638455-111 reqId:5540008332684446657 INFO  sql:62 - 42 0 Seata1Controller.insertInsert.selectByPrimaryKey.37 SELECT id,name FROM saas_yibao.test_model WHERE id = 311;
2020-01-14 14:37:29.885 qtp1262638455-111 reqId:5540008332684446657 INFO  Seata1Controller:38 - 1: TestModel(id=311, name=f4cece1f-0624-49ac-bbcf-78e4c4918d93)
2020-01-14 14:37:29.886 qtp1262638455-111 reqId:5540008332684446657 INFO  FeignCommonInterceptor:106 - call feign request, set appName=hospital
2020-01-14 14:37:29.886 qtp1262638455-111 reqId:5540008332684446657 WARN  FeignCommonInterceptor:116 - does not have reqId context, gen new one, 4269181073072737645
2020-01-14 14:37:29.886 qtp1262638455-111 reqId:5540008332684446657 INFO  FeignCommonInterceptor:126 - call feign request, reqId:4269181073072737645 , url:/gateway/seata/test/insert
2020-01-14 14:37:30.058 qtp1262638455-149 reqId:5540008332684446657 INFO  sql:62 - 84 0 Seata2Service.insert.insertUseGeneratedKeys.22 INSERT INTO saas_yibao.test_model ( id, name ) VALUES( null, 'afefd751-d475-4f53-8ad5-c94f130d1343' );
2020-01-14 14:37:30.101 qtp1262638455-149 reqId:5540008332684446657 INFO  sql:62 - 41 0 Seata2Service.insert.insertUseGeneratedKeys.22 SELECT * FROM saas_yibao.test_model WHERE id in ('312');
2020-01-14 14:37:30.202 qtp1262638455-149 reqId:5540008332684446657 INFO  sql:62 - 42 1 Seata2Service.insert.insertUseGeneratedKeys.22 INSERT INTO undo_log (branch_id, xid, context, rollback_info, log_status, log_created, log_modified) VALUES (2032717358, '172.20.4.223:8091:2032717310', 'serializer=jackson', 此处省略一千字。。, 0, now(), now());
2020-01-14 14:37:30.380 qtp1262638455-149 reqId:5540008332684446657 INFO  GatewayFilter:8 - totaltime=452,method=POST,command=/gateway/seata/test/insert,httpStatus=200,clientId=402a7889-e636-4b90-aee1-efd0be757cdb,systemVersion=null,from 172.17.0.1,userAgent=okhttp/3.11.0
2020-01-14 14:37:30.429 qtp1262638455-111 reqId:5540008332684446657 INFO  sql:62 - 42 0 Seata1Controller.insertInsert.selectByPrimaryKey.40 SELECT id,name FROM saas_yibao.test_model WHERE id = 312;
2020-01-14 14:37:30.430 qtp1262638455-111 reqId:5540008332684446657 INFO  Seata1Controller:41 - 2: TestModel(id=312, name=afefd751-d475-4f53-8ad5-c94f130d1343)
2020-01-14 14:37:30.493 qtp1262638455-111 reqId:5540008332684446657 INFO  DefaultGlobalTransaction:185 - [172.20.4.223:8091:2032717310] rollback status: RollbackRetrying

case3的undo_log中的rollback_info （日志没能保留下来，没有再复现成功）

{
  "@class": "io.seata.rm.datasource.undo.BranchUndoLog",
  "xid": "172.20.4.224:8091:2032712768",
  "branchId": 2032712771,
  "sqlUndoLogs": [
    "java.util.ArrayList",
    [
      {
        "@class": "io.seata.rm.datasource.undo.SQLUndoLog",
        "sqlType": "INSERT",
        "tableName": "saas_yibao.test_model",
        "beforeImage": {
          "@class": "io.seata.rm.datasource.sql.struct.TableRecords$EmptyTableRecords",
          "tableName": "test_model",
          "rows": [
            "java.util.ArrayList",
            []
          ]
        },
        "afterImage": {
          "@class": "io.seata.rm.datasource.sql.struct.TableRecords",
          "tableName": "test_model",
          "rows": [
            "java.util.ArrayList",
            [
              {
                "@class": "io.seata.rm.datasource.sql.struct.Row",
                "fields": [
                  "java.util.ArrayList",
                  [
                    {
                      "@class": "io.seata.rm.datasource.sql.struct.Field",
                      "name": "id",
                      "keyType": "PrimaryKey",
                      "type": -5,
                      "value": [
                        "java.math.BigInteger",
                        313
                      ]
                    },
                    {
                      "@class": "io.seata.rm.datasource.sql.struct.Field",
                      "name": "name",
                      "keyType": "NULL",
                      "type": 12,
                      "value": "768a3912-b4d9-405e-a0ff-61a94bb1a4c8"
                    }
                  ]
                ]
              }
            ]
          ]
        }
      }
    ]
  ]
}

case4日志 （可能是心跳检测？）

2020-01-14 14:46:44,619 INFO channel exx:Connection reset by peer,channel:[id: 0xae81334e, L:/172.20.3.81:8091 - R:/100.121.120.129:63028]
2020-01-14 14:46:44,620 ERROR 0318
java.io.IOException: Connection reset by peer
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
    at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1128)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
2020-01-14 14:46:44,620 INFO will destroy channel:[id: 0xae81334e, L:/172.20.3.81:8091 - R:/100.121.120.129:63028],address:100.121.120.129:63028
2020-01-14 14:46:44,620 INFO ChannelHandlerContext(RpcServer#0, [id: 0xae81334e, L:/172.20.3.81:8091 - R:/100.121.120.129:63028]) will closed
2020-01-14 14:46:44,620 INFO ChannelHandlerContext(RpcServer#0, [id: 0xae81334e, L:/172.20.3.81:8091 ! R:/100.121.120.129:63028]) will closed
2020-01-14 14:46:44,620 INFO 100.121.120.129:63028 to server channel inactive.
2020-01-14 14:46:44,621 INFO remove unused channel:[id: 0xae81334e, L:/172.20.3.81:8091 ! R:/100.121.120.129:63028]

Ⅱ. Describe what happened

If there is an exception, please attach the exception trace:

Just paste your stack trace here!

Ⅲ. Describe what you expected to happen

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

  1. xxx
  2. xxx
  3. xxx

Ⅴ. Anything else we need to know?

Ⅵ. Environment:

zjinlei commented 4 years ago

1.undo async delete, If it is not deleted, it has no effect, it will be cleaned up by the job. 2.RollbackRetrying indicates that no retry was successful and will continue to retry 3.Please temporarily remove the scheam in front of the table, it is a bug, will fix https://github.com/seata/seata/pull/2126.

azbh111 commented 4 years ago
  1. 实际上，等了好几分钟，都没回滚。偶遇回滚，就会触发3
azbh111 commented 4 years ago
  1. 补充： 分支一和分支二是在同一个jvm里，直接调用分支一，http调用分支二