【 TiDB 使用环境】测试
【 TiDB 版本】v6.5.0
【复现路径】由v5.4离线升级到v6.5
【遇到的问题：drainer节点状态不正常】
drainer日志输出：[2023/02/28 17:14:11.519 +08:00] [INFO] [version.go:50] [“Welcome to Drainer”] [“Release Version”=v6.5.0] [“Git Commit Hash”=589d79bcc4f0e9fa982847192baf6dd3eb3a0f41] [“Build TS”=“2022-12-16 08:21:03”] [“Go Version”=go1.19.3] [“Go OS/Arch”=linux/amd64]
[2023/02/28 17:14:11.520 +08:00] [INFO] [main.go:46] [“start drainer…”] [config=“{"log-level":"info","node-id":"10.196.3.190:8250","addr":"http://10.196.3.190:8250","advertise-addr":"http://10.196.3.190:8250","data-dir":"/data0/dba/tidb54_data/drainer8250","detect-interval":5,"pd-urls":"http://10.196.3.188:2400,http://10.196.3.190:2400,http://10.196.3.191:2400","log-file":"/home/dba/tidb54/drainer8250/log/drainer.log","initial-commit-ts":-1,"sycner":{"sql-mode":null,"ignore-txn-commit-ts":null,"ignore-schemas":"INFORMATION_SCHEMA,PERFORMANCE_SCHEMA,mysql","ignore-table":null,"txn-batch":20,"loopback-control":false,"sync-ddl":true,"channel-id":0,"worker-count":16,"to":{"host":"10.196.3.188","user":"root","password":"pwd4dba","security":{"ssl-ca":"","ssl-cert":"","ssl-key":"","cert-allowed-cn":null},"encrypted_password":"","sync-mode":0,"port":4121,"checkpoint":{"type":"","schema":"","table":"","host":"","user":"","password":"","encrypted_password":"","port":0,"security":{"ssl-ca":"","ssl-cert":"","ssl-key":"","cert-allowed-cn":null},"oracle-service-name":"","oracle-connect-string":""},"dir":"","retention-time":0,"params":null,"read-timeout":"","merge":false,"zookeeper-addrs":"","kafka-addrs":"","kafka-version":"","kafka-max-messages":0,"kafka-client-id":"","kafka-max-message-size":0,"topic-name":"","oracle-service-name":"","oracle-connect-string":""},"replicate-do-table":null,"replicate-do-db":null,"db-type":"tidb","relay":{"log-dir":"","max-file-size":10485760},"disable-dispatch-flag":null,"enable-dispatch-flag":null,"disable-dispatch":null,"enable-dispatch":null,"safe-mode":false,"disable-detect-flag":null,"enable-detect-flag":null,"disable-detect":null,"enable-detect":null,"case-sensitive":false,"table-migrate-rule":null},"security":{"ssl-ca":"","ssl-cert":"","ssl-key":"","cert-allowed-cn":null},"synced-check-time":5,"compressor":"","EtcdTimeout":5000000000,"MetricsAddr":"","MetricsInterval":15}”]
[2023/02/28 17:14:11.520 +08:00] [INFO] [client.go:397] [“[pd] create pd client with endpoints”] [pd-address=“[http://10.196.3.188:2400,http://10.196.3.190:2400,http://10.196.3.191:2400]”]
[2023/02/28 17:14:11.526 +08:00] [INFO] [base_client.go:378] [“[pd] switch leader”] [new-leader=http://10.196.3.188:2400] [old-leader=]
[2023/02/28 17:14:11.526 +08:00] [INFO] [base_client.go:105] [“[pd] init cluster id”] [cluster-id=7077841219380562968]
[2023/02/28 17:14:11.526 +08:00] [INFO] [client.go:690] [“[pd] tso dispatcher created”] [dc-location=global]
[2023/02/28 17:14:11.526 +08:00] [INFO] [server.go:122] [“get cluster id from pd”] [id=7077841219380562968]
[2023/02/28 17:14:11.526 +08:00] [INFO] [server.go:131] [“set InitialCommitTS”] [ts=439766391588651014]
[2023/02/28 17:14:11.526 +08:00] [INFO] [client.go:771] [“[pd] stop fetching the pending tso requests due to context canceled”] [dc-location=global]
[2023/02/28 17:14:11.526 +08:00] [INFO] [client.go:709] [“[pd] exit tso dispatcher”] [dc-location=global]
[2023/02/28 17:14:11.532 +08:00] [INFO] [checkpoint.go:69] [“initialize checkpoint”] [type=tidb] [checkpoint=439745999413706758] [version=0] [cfg=“{"CheckpointType":"tidb","Db":{"host":"10.196.3.188","user":"root","password":"pwd4dba","port":4121,"oracle-service-name":"","oracle-connect-string":""},"Schema":"tidb_binlog","Table":"checkpoint","ClusterID":7077841219380562968,"InitialCommitTS":439766391588651014,"dir":"/data0/dba/tidb54_data/drainer8250/savepoint"}”]
[2023/02/28 17:14:11.532 +08:00] [INFO] [store.go:75] [“new store”] [path=“tikv://10.196.3.188:2400,10.196.3.190:2400,10.196.3.191:2400?disableGC=true”]
[2023/02/28 17:14:11.532 +08:00] [INFO] [client.go:397] [“[pd] create pd client with endpoints”] [pd-address=“[10.196.3.188:2400,10.196.3.190:2400,10.196.3.191:2400]”]
[2023/02/28 17:14:11.536 +08:00] [INFO] [base_client.go:378] [“[pd] switch leader”] [new-leader=http://10.196.3.188:2400] [old-leader=]
[2023/02/28 17:14:11.536 +08:00] [INFO] [base_client.go:105] [“[pd] init cluster id”] [cluster-id=7077841219380562968]
[2023/02/28 17:14:11.536 +08:00] [INFO] [client.go:690] [“[pd] tso dispatcher created”] [dc-location=global]
[2023/02/28 17:14:11.538 +08:00] [INFO] [store.go:81] [“new store with retry success”]
[2023/02/28 17:14:11.625 +08:00] [INFO] [load.go:241] [“new loader”] [opts=“{workerCount:16 batchSize:20 loopBackSyncInfo:0xc001b214c0 metrics:0xc000832048 saveAppliedTS:true syncMode:1 enableDispatch:true enableCausality:true merge:false destDBType:2}”]
[2023/02/28 17:14:11.627 +08:00] [INFO] [client.go:771] [“[pd] stop fetching the pending tso requests due to context canceled”] [dc-location=global]
[2023/02/28 17:14:11.627 +08:00] [INFO] [client.go:709] [“[pd] exit tso dispatcher”] [dc-location=global]
[2023/02/28 17:14:11.627 +08:00] [INFO] [store.go:75] [“new store”] [path=“tikv://10.196.3.188:2400,10.196.3.190:2400,10.196.3.191:2400?disableGC=true”]
[2023/02/28 17:14:11.627 +08:00] [INFO] [client.go:397] [“[pd] create pd client with endpoints”] [pd-address=“[10.196.3.188:2400,10.196.3.190:2400,10.196.3.191:2400]”]
[2023/02/28 17:14:11.632 +08:00] [INFO] [base_client.go:378] [“[pd] switch leader”] [new-leader=http://10.196.3.188:2400] [old-leader=]
[2023/02/28 17:14:11.632 +08:00] [INFO] [base_client.go:105] [“[pd] init cluster id”] [cluster-id=7077841219380562968]
[2023/02/28 17:14:11.632 +08:00] [INFO] [client.go:690] [“[pd] tso dispatcher created”] [dc-location=global]
[2023/02/28 17:14:11.632 +08:00] [INFO] [store.go:81] [“new store with retry success”]
[2023/02/28 17:14:11.636 +08:00] [INFO] [server.go:264] [“register success”] [“drainer node id”=10.196.3.190:8250]
[2023/02/28 17:14:11.636 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:279, Type:create view, State:cancelled, SchemaState:none, SchemaID:3, TableID:278, RowCount:0, ArgLen:0, start time: 2023-02-27 19:27:41.049 +0800 CST, Err:[meta:1146]DDL job rollback, error msg: table doesn’t exist, ErrCount:514, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.636 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:256, Type:create table, State:cancelled, SchemaState:none, SchemaID:3, TableID:255, RowCount:0, ArgLen:0, start time: 2023-02-27 19:27:38.499 +0800 CST, Err:[schema:1050]Table ‘stats_meta_history’ already exists, ErrCount:1, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.636 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:254, Type:create table, State:cancelled, SchemaState:none, SchemaID:3, TableID:253, RowCount:0, ArgLen:0, start time: 2023-02-27 19:27:38.499 +0800 CST, Err:[schema:1050]Table ‘stats_meta_history’ already exists, ErrCount:1, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.636 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:303, Type:add column, State:synced, SchemaState:none, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.833 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.637 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:300, Type:add column, State:synced, SchemaState:none, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.333 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.637 +08:00] [WARN] [schema.go:302] [“ddl job schema version is less than current version, skip this ddl job”] [job=“ID:283, Type:create table, State:cancelled, SchemaState:none, SchemaID:3, TableID:282, RowCount:0, ArgLen:0, start time: 2023-02-27 19:27:43.049 +0800 CST, Err:[schema:1050]Table ‘plan_replayer_task’ already exists, ErrCount:1, SnapshotVersion:0”] [currentVersion=0]
[2023/02/28 17:14:11.637 +08:00] [INFO] [server.go:330] [“start to server request”] [addr=http://10.196.3.190:8250]
[2023/02/28 17:14:11.637 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=10.196.3.190:8249]
[2023/02/28 17:14:11.637 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=10.196.3.191:8249]
[2023/02/28 17:14:11.637 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=10.196.3.188:8249]
[2023/02/28 17:14:11.637 +08:00] [INFO] [pump.go:140] [“pump create pull binlogs client”] [id=10.196.3.190:8249]
[2023/02/28 17:14:11.637 +08:00] [INFO] [pump.go:140] [“pump create pull binlogs client”] [id=10.196.3.191:8249]
[2023/02/28 17:14:11.637 +08:00] [INFO] [pump.go:140] [“pump create pull binlogs client”] [id=10.196.3.188:8249]
[2023/02/28 17:14:12.633 +08:00] [INFO] [collector.go:285] [“start query job”] [id=300] [binlog="tp:Commit start_ts:439745999439659018 commit_ts:439745999439659020 prewrite_key:"t\200\000\377\377\377\377\377\376_r\200\000\000\000\000\000\001," ddl_query:"ALTER TABLE mysql.user ADD COLUMN IF NOT EXISTS Password_last_changed TIMESTAMP DEFAULT CURRENT_TIMESTAMP();" ddl_job_id:300 "]
[2023/02/28 17:14:12.639 +08:00] [INFO] [collector.go:307] [“get ddl job”] [job=“ID:300, Type:add column, State:synced, SchemaState:none, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.333 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [collector.go:285] [“start query job”] [id=301] [binlog=“tp:Commit start_ts:439745999439659040 commit_ts:439745999439659047 prewrite_key:"mDB:3\000\000\000\000\373\000\000\000\000\000\000\000hTable:5\000\376" ddl_query:"ALTER TABLE mysql.user CHANGE COLUMN Repl_slave_priv Repl_slave_priv ENUM(‘N’,‘Y’) NOT NULL DEFAULT _UTF8MB4’N’ AFTER Execute_priv;" ddl_job_id:301 ddl_schema_state:5 “]
[2023/02/28 17:14:12.639 +08:00] [INFO] [load.go:916] [“Loader has been closed. Start quitting txnManager”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [load.go:906] [“run()… in txnManager quit”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [load.go:962] [“txnManager has been closed”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [load.go:640] [”{16 20 0xc001b214c0 0xc000832048 true 1 true true false 2}”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [load.go:641] [“Run()… in Loader quit”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [mysql.go:299] [“Successes chan quit”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [syncer.go:271] [“handleSuccess quit”]
[2023/02/28 17:14:12.639 +08:00] [ERROR] [server.go:292] [“syncer exited abnormal”] [error=“version: 0 not found”] [errorVerbose=“version: 0 not found\ngithub.com/pingcap/errors.NotFoundf\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:117\ngithub.com/pingcap/tidb-binlog/drainer.(*Schema).getSchemaTableAndDelete\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/schema.go:587\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:469\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).Start\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:152\ngithub.com/pingcap/tidb-binlog/drainer.(*Server).Start.func4\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/server.go:291\ngithub.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:82\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594”]
[2023/02/28 17:14:12.639 +08:00] [INFO] [util.go:79] [Exit] [name=syncer]
[2023/02/28 17:14:12.639 +08:00] [INFO] [server.go:466] [“begin to close drainer server”]
[2023/02/28 17:14:12.641 +08:00] [INFO] [collector.go:307] [“get ddl job”] [job=“ID:301, Type:modify column, State:synced, SchemaState:public, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.483 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”]
[2023/02/28 17:14:12.641 +08:00] [INFO] [collector.go:285] [“start query job”] [id=302] [binlog="tp:Commit start_ts:439745999518564354 commit_ts:439745999518564358 prewrite_key:"mDB:3\000\000\000\000\373\000\000\000\000\000\000\000hTable:5\000\376" ddl_query:"ALTER TABLE mysql.user ADD COLUMN IF NOT EXISTS Password_lifetime SMALLINT UNSIGNED DEFAULT NULL;" ddl_job_id:302 ddl_schema_state:5 "]
[2023/02/28 17:14:12.641 +08:00] [INFO] [server.go:431] [“has already update status”] [id=10.196.3.190:8250]
[2023/02/28 17:14:12.641 +08:00] [INFO] [server.go:470] [“commit status done”]
[2023/02/28 17:14:12.641 +08:00] [INFO] [pump.go:79] [“pump is closing”] [id=10.196.3.190:8249]
[2023/02/28 17:14:12.641 +08:00] [INFO] [pump.go:79] [“pump is closing”] [id=10.196.3.191:8249]
[2023/02/28 17:14:12.641 +08:00] [INFO] [pump.go:79] [“pump is closing”] [id=10.196.3.188:8249]
[2023/02/28 17:14:12.641 +08:00] [INFO] [util.go:79] [Exit] [name=heartbeat]
[2023/02/28 17:14:12.643 +08:00] [INFO] [collector.go:307] [“get ddl job”] [job=“ID:302, Type:add column, State:synced, SchemaState:public, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.632 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”]
[2023/02/28 17:14:12.643 +08:00] [INFO] [collector.go:285] [“start query job”] [id=303] [binlog="tp:Commit start_ts:439745999531409437 commit_ts:439745999544516609 prewrite_key:"t\200\000\377\377\377\377\377\376_r\200\000\000\000\000\000\001/" ddl_query:"ALTER TABLE mysql.user ADD COLUMN IF NOT EXISTS Password_lifetime SMALLINT UNSIGNED DEFAULT NULL;" ddl_job_id:303 "]
[2023/02/28 17:14:12.643 +08:00] [INFO] [merge.go:245] [“Merger is closed successfully”]
[2023/02/28 17:14:12.644 +08:00] [INFO] [collector.go:307] [“get ddl job”] [job=“ID:303, Type:add column, State:synced, SchemaState:none, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2023-02-27 19:37:41.833 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0”]
[2023/02/28 17:14:12.644 +08:00] [INFO] [collector.go:139] [“publishBinlogs quit”]
[2023/02/28 17:14:12.644 +08:00] [INFO] [util.go:79] [Exit] [name=collect]
[2023/02/28 17:14:12.644 +08:00] [INFO] [server.go:485] [“drainer exit”]
[2023/02/28 17:14:12.644 +08:00] [INFO] [server.go:326] [“drainer http server stopped”] [error=“mux: server closed”]
[2023/02/28 17:14:12.644 +08:00] [ERROR] [main.go:69] [“start drainer server failed”] [error=“version: 0 not found”] [errorVerbose=“version: 0 not found\ngithub.com/pingcap/errors.NotFoundf\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:117\ngithub.com/pingcap/tidb-binlog/drainer.(*Schema).getSchemaTableAndDelete\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/schema.go:587\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:469\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).Start\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:152\ngithub.com/pingcap/tidb-binlog/drainer.(*Server).Start.func4\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/server.go:291\ngithub.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:82\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594”]
