Drainer Fails to Start After Offline Upgrading TiDB from v5.4 to v6.5

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: TiDB版本由v5.4离线升级到v6.5,drainer无法正常启动

| username: Boomballa

[TiDB Usage Environment] Test
[TiDB Version] v6.5.0
[Reproduction Path] Offline upgrade from v5.4 to v6.5
[Encountered Issue: drainer node status is abnormal]

drainer log output: [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

| username: xfworld | Original post link

Support for binlog is no longer compatible in 5.X. By the time it reaches 6.X, it should be abandoned and replaced with TiCDC.

| username: 胡杨树旁 | Original post link

Are you talking about upgrading? Does version 6.X not support binlog? I haven’t seen any official documentation about this.

| username: Boomballa | Original post link

Well, the test environment originally had these components, but after the upgrade, things didn’t look right, so I’m checking to see what the issue is. The key problem is that the drainer scale-in is also unsuccessful…

| username: buddyyuan | Original post link

To the downstream? It looks like a syncer issue. What is the downstream database? MySQL?

| username: Boomballa | Original post link

I haven’t configured the downstream, the test database. I just deployed these components without configuration.

| username: buddyyuan | Original post link

Try configuring one to a file and see.

| username: xfworld | Original post link

Is this line of text too small and not noticeable enough?

| username: system | Original post link

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.