pingcap / tidb

TiDB is an open-source, cloud-native, distributed, MySQL-Compatible database for elastic scale and real-time analytics. Try AI-powered Chat2Query free at : https://www.pingcap.com/tidb-serverless/
https://pingcap.com
Apache License 2.0
37.02k stars 5.82k forks source link

add index fail for "Error 8221 (HY000): invalid key - "7480000000000000f35f698000000000000002038000000000000001038000000002eac9f9"" #47853

Open seiya-annie opened 11 months ago

seiya-annie commented 11 months ago

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

  1. br import sysbench tables;
  2. alter table test.user_data1 add unique index j2(uid,(cast(j2->'$[*]' as signed array)));
  3. flashback to before add index
  4. alter table test.user_data1 add unique index j2(uid,(cast(j2->'$[*]' as signed array)));

2. What did you expect to see? (Required)

add index can successful

3. What did you see instead (Required)

add index fail

2023/10/18 11:22:37.955 +00:00] [INFO] [tidb.go:285] ["rollbackTxn called due to ddl/autocommit failure"]
[2023/10/18 11:22:37.955 +00:00] [WARN] [session.go:2272] ["run statement failed"] [conn=8077496202758719657] [schemaVersion=147] [error="[xeval:8221]invalid key - \"7480000000000000f35f698000000000000006038000000000000001038000000002eac9f9\""] [session="{\n  \"currDBName\": \"test\",\n  \"id\": 8077496202758719657,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": {\n    \"Username\": \"root\",\n    \"Hostname\": \"[10.200.52.163](http://10.200.52.163/)\",\n    \"CurrentUser\": false,\n    \"AuthUsername\": \"root\",\n    \"AuthHostname\": \"%\",\n    \"AuthPlugin\": \"mysql_native_password\"\n  }\n}"]
[2023/10/18 11:22:37.955 +00:00] [INFO] [conn.go:1184] ["command dispatched failed"] [conn=8077496202758719657] [connInfo="id:8077496202758719657, addr:[10.200.52.163:52112](http://10.200.52.163:52112/) status:10, collation:utf8mb4_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="alter table test.user_data1 add unique index j2(uid,(cast(j2->'$[*]' as signed array)));"] [txn_mode=PESSIMISTIC] [timestamp=445023002795180037] [err="[xeval:8221]invalid key - \"7480000000000000f35f698000000000000006038000000000000001038000000002eac9f9\"\[ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20221009092201-b66cddb77c32/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20221009092201-b66cddb77c32/juju_adaptor.go:15\ngithub.com/pingcap/tidb/ddl.(*ddl).DoDDLJob\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl.go:1184\ngithub.com/pingcap/tidb/ddl.(*ddl).createIndex\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:6821\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTable\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:3432\ngithub.com/pingcap/tidb/executor.(*DDLExec).executeAlterTable\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/ddl.go:384\ngithub.com/pingcap/tidb/executor.(*DDLExec).Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/ddl.go:148\ngithub.com/pingcap/tidb/executor.Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/executor.go:326\ngithub.com/pingcap/tidb/executor.(*ExecStmt).next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1202\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:947\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:773\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:568\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2403\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2260\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/driver_tidb.go:294\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2094\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1885\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1372\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1153\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:677\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1598](http://ngithub.com/pingcap/errors.AddStack/n/t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20221009092201-b66cddb77c32/errors.go:174/ngithub.com/pingcap/errors.Trace/n/t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20221009092201-b66cddb77c32/juju_adaptor.go:15/ngithub.com/pingcap/tidb/ddl.(*ddl).DoDDLJob/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl.go:1184/ngithub.com/pingcap/tidb/ddl.(*ddl).createIndex/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:6821/ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTable/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:3432/ngithub.com/pingcap/tidb/executor.(*DDLExec).executeAlterTable/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/ddl.go:384/ngithub.com/pingcap/tidb/executor.(*DDLExec).Next/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/ddl.go:148/ngithub.com/pingcap/tidb/executor.Next/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/executor.go:326/ngithub.com/pingcap/tidb/executor.(*ExecStmt).next/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:1202/ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:947/ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:773/ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/adapter.go:568/ngithub.com/pingcap/tidb/session.runStmt/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2403/ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/session/session.go:2260/ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/driver_tidb.go:294/ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:2094/ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1885/ngithub.com/pingcap/tidb/server.(*clientConn).dispatch/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1372/ngithub.com/pingcap/tidb/server.(*clientConn).Run/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/conn.go:1153/ngithub.com/pingcap/tidb/server.(*Server).onConn/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:677/nruntime.goexit/n/t/usr/local/go/src/runtime/asm_amd64.s:1598)"]

4. What is your TiDB version? (Required)

7.1.2

seiya-annie commented 11 months ago

tidb (1).log

tidb (3).log

seiya-annie commented 9 months ago

test in v7.1.3, same scenarios, get new error:"Error 1062 (23000): Duplicate entry '%-.64s' for key '%-.192s'"

[2023/12/12 14:31:42.802 +00:00] [ERROR] [terror.go:324] ["encountered error"] [error="close tcp [10.233.111.33:4000](http://10.233.111.33:4000/)->[172.16.6.42:42986](http://172.16.6.42:42986/): use of closed network connection"] [stack="[github.com/pingcap/tidb/parser/terror.Log\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/parser/terror/terror.go:324\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:647](http://github.com/pingcap/tidb/parser/terror.Log/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/parser/terror/terror.go:324/ngithub.com/pingcap/tidb/server.(*Server).onConn/n/t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/server/server.go:647)"]
[2023/12/12 14:31:43.787 +00:00] [WARN] [pd.go:156] ["get timestamp too slow"] ["cost time"=67.970657ms]
[2023/12/12 14:31:44.369 +00:00] [WARN] [pd.go:156] ["get timestamp too slow"] ["cost time"=52.495836ms]
[2023/12/12 14:31:46.893 +00:00] [INFO] [duplicate.go:966] ["[detect-dupe] collect remote duplicate keys completed"] [table=user_data1] [takeTime=9.481951494s] []
[2023/12/12 14:31:46.893 +00:00] [ERROR] [backend.go:147] ["[ddl-ingest] remote duplicate index key exist"] [table=user_data1] ["index ID"=2]
[2023/12/12 14:31:46.893 +00:00] [WARN] [index.go:942] ["[ddl] import index duplicate key, convert job to rollback"] [job="ID:261, Type:add index, State:running, SchemaState:write reorganization, SchemaID:91, TableID:243, RowCount:1000000, ArgLen:6, start time: 2023-12-12 14:30:01.675 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:446271691666227206, UniqueWarnings:0"] [error="[kv:1062]Duplicate entry '%-.64s' for key '%-.192s'"]
lance6716 commented 5 months ago

One cause is FLASHBACK CLUSTER will write "delete" kv modification but old version of lightning does not support use "delete" to clean up data for duplicate detection. It was supported in v7.3.0 ~for CLUSTERED tables ~in https://github.com/pingcap/tidb/issues/44723 .

And I'll check why key can't be decoded.

lance6716 commented 5 months ago

It can be reproduced in v7.1.4

mysql> set global tidb_ddl_enable_fast_reorg=1;
Query OK, 0 rows affected (0.01 sec)
mysql> use test
Database changed
mysql> create table t(c int key, c2 int);
Query OK, 0 rows affected (0.10 sec)

mysql> show create table t;
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                               |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| t     | CREATE TABLE `t` (
  `c` int(11) NOT NULL,
  `c2` int(11) DEFAULT NULL,
  PRIMARY KEY (`c`) /*T![clustered_index] CLUSTERED */
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> insert into t values (1,1), (2,2);
Query OK, 2 rows affected (0.01 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT @@tidb_current_ts;
+--------------------+
| @@tidb_current_ts  |
+--------------------+
| 449255684275699713 |
+--------------------+
1 row in set (0.00 sec)

mysql> ROLLBACK;
Query OK, 0 rows affected (0.00 sec)

mysql> alter table t add unique index idx(c2);
Query OK, 0 rows affected (2.75 sec)

mysql> FLASHBACK CLUSTER TO TSO 449255684275699713;
Query OK, 0 rows affected (0.81 sec)

mysql> alter table t add unique index idx(c2);
ERROR 1062 (23000): Duplicate entry '%-.64s' for key '%-.192s'
lance6716 commented 5 months ago

v7.5 can not reproduce this problem, it's fixed by https://github.com/tikv/tikv/pull/14960

mysql> admin show ddl jobs;
+--------+---------+-------------------------+------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
| JOB_ID | DB_NAME | TABLE_NAME              | JOB_TYPE               | SCHEMA_STATE | SCHEMA_ID | TABLE_ID | ROW_COUNT | CREATE_TIME         | START_TIME          | END_TIME            | STATE  |
+--------+---------+-------------------------+------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
|    106 | test    | t                       | add index /* ingest */ | public       |         2 |      102 |         2 | 2024-04-22 16:34:14 | 2024-04-22 16:34:14 | 2024-04-22 16:34:15 | synced |
|    105 |         |                         | flashback cluster      | public       |         0 |        0 |         0 | 2024-04-22 16:34:09 | 2024-04-22 16:34:09 | 2024-04-22 16:34:10 | synced |
|    104 | test    | t                       | add index /* ingest */ | public       |         2 |      102 |         2 | 2024-04-22 16:33:43 | 2024-04-22 16:33:43 | 2024-04-22 16:33:46 | synced |