drainer: ddl order is not guaranteed

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do?
   If possible, provide a recipe for reproducing the error.

Test drainer in #1031, 0abd1b8 with amend-random change column.

2. What did you expect to see?

No ddl execution error.

3. What did you see instead?

Drainer's log

[2020/12/31 09:45:41.323 +00:00] [INFO] [collector.go:305] ["get ddl job"] [job="ID:61, Type:drop table, State:synced, SchemaState:none, SchemaID:45, TableID:54, RowCount:0, ArgLen:0, start time: 2020-12-31 09:45:24.673 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/12/31 09:45:41.323 +00:00] [INFO] [collector.go:283] ["start query job"] [id=62] [binlog="tp:Commit start_ts:421896631188717569 commit_ts:421896631188717576 prewrite_key:\"mDB:45\\000\\000\\000\\374\\000\\000\\000\\000\\000\\000\\000hTable:49\\377\\000\\000\\000\\000\\000\\000\\000\\000\\367\" ddl_query:\"ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL\" ddl_job_id:62 ddl_schema_state:5 "]
[2020/12/31 09:45:41.323 +00:00] [INFO] [syncer.go:482] ["add ddl item to syncer, you can add this commit ts to `ignore-txn-commit-ts` to skip this ddl if needed"] [sql="DROP TABLE IF EXISTS t_1609407923761894252"] ["commit ts"=421896631162765313]
[2020/12/31 09:45:41.326 +00:00] [INFO] [collector.go:305] ["get ddl job"] [job="ID:62, Type:modify column, State:synced, SchemaState:public, SchemaID:45, TableID:49, RowCount:0, ArgLen:0, start time: 2020-12-31 09:45:24.772 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/12/31 09:45:41.326 +00:00] [INFO] [collector.go:283] ["start query job"] [id=63] [binlog="tp:Commit start_ts:421896631241408513 commit_ts:421896631254515713 prewrite_key:\"mDB:45\\000\\000\\000\\374\\000\\000\\000\\000\\000\\000\\000H\" ddl_query:\"DROP TABLE IF EXISTS t_1609407924190495219\" ddl_job_id:63 "]
[2020/12/31 09:45:41.326 +00:00] [INFO] [syncer.go:482] ["add ddl item to syncer, you can add this commit ts to `ignore-txn-commit-ts` to skip this ddl if needed"] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] ["commit ts"=421896631188717576]
[2020/12/31 09:45:41.330 +00:00] [INFO] [collector.go:305] ["get ddl job"] [job="ID:63, Type:drop table, State:synced, SchemaState:none, SchemaID:45, TableID:56, RowCount:0, ArgLen:0, start time: 2020-12-31 09:45:25.123 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/12/31 09:45:41.330 +00:00] [INFO] [collector.go:283] ["start query job"] [id=64] [binlog="tp:Commit start_ts:421896631333158914 commit_ts:421896631346003969 prewrite_key:\"mDB:45\\000\\000\\000\\374\\000\\000\\000\\000\\000\\000\\000hTable:49\\377\\000\\000\\000\\000\\000\\000\\000\\000\\367\" ddl_query:\"ALTER TABLE t_column ADD COLUMN new_col_2 DATE NULL\" ddl_job_id:64 ddl_schema_state:5 "]
[2020/12/31 09:45:41.331 +00:00] [INFO] [syncer.go:482] ["add ddl item to syncer, you can add this commit ts to `ignore-txn-commit-ts` to skip this ddl if needed"] [sql="DROP TABLE IF EXISTS t_1609407924190495219"] ["commit ts"=421896631254515713]
[2020/12/31 09:45:41.334 +00:00] [INFO] [collector.go:305] ["get ddl job"] [job="ID:64, Type:add column, State:synced, SchemaState:public, SchemaID:45, TableID:49, RowCount:0, ArgLen:0, start time: 2020-12-31 09:45:25.372 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/12/31 09:45:41.334 +00:00] [INFO] [collector.go:283] ["start query job"] [id=65] [binlog="tp:Commit start_ts:421896631359111172 commit_ts:421896631372480513 prewrite_key:\"mDB:45\\000\\000\\000\\374\\000\\000\\000\\000\\000\\000\\000hTable:49\\377\\000\\000\\000\\000\\000\\000\\000\\000\\367\" ddl_query:\"ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL\" ddl_job_id:65 ddl_schema_state:5 "]
[2020/12/31 09:45:41.334 +00:00] [INFO] [syncer.go:482] ["add ddl item to syncer, you can add this commit ts to `ignore-txn-commit-ts` to skip this ddl if needed"] [sql="ALTER TABLE t_column ADD COLUMN new_col_2 DATE NULL"] ["commit ts"=421896631346003969]
[2020/12/31 09:45:41.337 +00:00] [INFO] [collector.go:305] ["get ddl job"] [job="ID:65, Type:modify column, State:synced, SchemaState:public, SchemaID:45, TableID:49, RowCount:0, ArgLen:0, start time: 2020-12-31 09:45:25.473 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/12/31 09:45:41.337 +00:00] [INFO] [collector.go:283] ["start query job"] [id=66] [binlog="tp:Commit start_ts:421896631411802113 commit_ts:421896631411802114 prewrite_key:\"mDB:45\\000\\000\\000\\374\\000\\000\\000\\000\\000\\000\\000hTable:49\\377\\000\\000\\000\\000\\000\\000\\000\\000\\367\" ddl_query:\"ALTER TABLE t_column DROP COLUMN col_111\" ddl_job_id:66 ddl_schema_state:1 "]
[2020/12/31 09:45:41.337 +00:00] [INFO] [syncer.go:482] ["add ddl item to syncer, you can add this commit ts to `ignore-txn-commit-ts` to skip this ddl if needed"] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL"] ["commit ts"=421896631372480513]
...
[2020/12/31 09:45:47.915 +00:00] [INFO] [load.go:423] ["exec ddl success"] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"]
...
[2020/12/31 09:45:50.655 +00:00] [FATAL] [syncer.go:264] ["save checkpoint failed"] [ts=421896630979264514] [error="query sql failed: replace into tidb_binlog.checkpoint values(6912353930102251564, '{\"consistent\":false,\"commitTS\":421896630979264514,\"ts-map\":{\"primary-ts\":421896630821978115,\"secondary-ts\":421896636673556481},\"schema-version\":40}'): Error 1105: commit failed"] [errorVerbose="Error 1105: commit failed\nquery sql failed: replace into tidb_binlog.checkpoint values(6912353930102251564, '{\"consistent\":false,\"commitTS\":421896630979264514,\"ts-map\":{\"primary-ts\":421896630821978115,\"secondary-ts\":421896636673556481},\"schema-version\":40}')\ngithub.com/pingcap/tidb-binlog/drainer/checkpoint.(*MysqlCheckPoint).Save\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/checkpoint/mysql.go:174\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).savePoint\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:262\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).handleSuccess\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:236\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).run.func1\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:283\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb-binlog/drainer.(*Syncer).savePoint\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:264\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).handleSuccess\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:236\ngithub.com/pingcap/tidb-binlog/drainer.(*Syncer).run.func1\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:283"]
[2020/12/31 09:46:05.977 +00:00] [INFO] [version.go:50] ["Welcome to Drainer"] ["Release Version"=v4.0.9-13-g0abd1b89] ["Git Commit Hash"=0abd1b891fd86493c5a64a1ecdf4a5199e936606] ["Build TS"="2020-12-31 09:34:39"] ["Go Version"=go1.13] ["Go OS/Arch"=linux/amd64]...
...
[2020/12/31 09:46:40.239 +00:00] [ERROR] [load.go:776] ["exec failed"] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] [metadata="commit ts: 421896631188717576"] [error="Error 8200: Unsupported modify column: length 248 is less than origin 249"] [errorVerbose="Error 8200: Unsupported modify column: length 248 is less than origin 249\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/juju_adaptor.go:15\ngithub.com/pingcap/tidb-binlog/pkg/loader.(*loaderImpl).execDDL\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/pkg/loader/load.go:431\ngithub.com/pingcap/tidb-binlog/pkg/loader.(*batchManager).execDDL\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/pkg/loader/load.go:748\ngithub.com/pingcap/tidb-binlog/pkg/loader.(*batchManager).put\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/pkg/loader/load.go:770\ngithub.com/pingcap/tidb-binlog/pkg/loader.(*loaderImpl).Run\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/pkg/loader/load.go:602\ngithub.com/pingcap/tidb-binlog/drainer/sync.(*MysqlSyncer).run\n\t/home/jenkins/agent/workspace/binlog_ghpr_build_new3/go/src/github.com/pingcap/tidb-binlog/drainer/sync/mysql.go:237\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357"]```

Upstream TiDB's log

[2020/12/31 09:45:24.779 +00:00] [INFO] [session.go:2269] ["CRUCIAL OPERATION"] [conn=32] [schemaVersion=41] [cur_db=test0] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] [user=root@172.16.4.58]
[2020/12/31 09:45:24.792 +00:00] [INFO] [ddl.go:486] ["[ddl] start DDL job"] [job="ID:62, Type:modify column, State:none, SchemaState:none, SchemaID:45, TableID:49, RowCount:0, ArgLen:5, start time: 2020-12-31 09:45:24.772 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"]
...
[2020/12/31 09:45:25.450 +00:00] [INFO] [session.go:2269] ["CRUCIAL OPERATION"] [conn=32] [schemaVersion=49] [cur_db=test0] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL"] [user=root@172.16.4.58]
[2020/12/31 09:45:25.463 +00:00] [INFO] [ddl.go:486] ["[ddl] start DDL job"] [job="ID:65, Type:modify column, State:none, SchemaState:none, SchemaID:45, TableID:49, RowCount:0, ArgLen:5, start time: 2020-12-31 09:45:25.473 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL"]

Downstream TiDB's log

[2020/12/31 09:45:47.787 +00:00] [INFO] [session.go:2269] ["CRUCIAL OPERATION"] [conn=8] [schemaVersion=51] [cur_db=test0] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] [user=root@172.16.5.196]
[2020/12/31 09:45:47.797 +00:00] [INFO] [ddl.go:486] ["[ddl] start DDL job"] [job="ID:67, Type:modify column, State:none, SchemaState:none, SchemaID:49, TableID:53, RowCount:0, ArgLen:5, start time: 2020-12-31 09:45:47.795 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"]
...
[2020/12/31 09:45:50.598 +00:00] [INFO] [session.go:2269] ["CRUCIAL OPERATION"] [conn=8] [schemaVersion=59] [cur_db=test0] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL"] [user=root@172.16.5.196]
[2020/12/31 09:45:50.609 +00:00] [INFO] [ddl.go:486] ["[ddl] start DDL job"] [job="ID:70, Type:modify column, State:none, SchemaState:none, SchemaID:49, TableID:53, RowCount:0, ArgLen:5, start time: 2020-12-31 09:45:50.595 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(249) NULL"]
...
[2020/12/31 09:46:35.195 +00:00] [INFO] [session.go:2269] ["CRUCIAL OPERATION"] [conn=16] [schemaVersion=61] [cur_db=test0] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] [user=root@172.16.5.196]
[2020/12/31 09:46:35.196 +00:00] [WARN] [session.go:1123] ["run statement failed"] [conn=16] [schemaVersion=61] [error="[ddl:8200]Unsupported modify column: length 248 is less than origin 249"] [session="{\n  \"currDBName\": \"test0\",\n  \"id\": 16,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": {\n    \"Username\": \"root\",\n    \"Hostname\": \"172.16.5.196\",\n    \"CurrentUser\": false,\n    \"AuthUsername\": \"root\",\n    \"AuthHostname\": \"%\"\n  }\n}"]
[2020/12/31 09:46:35.196 +00:00] [INFO] [conn.go:793] ["command dispatched failed"] [conn=16] [connInfo="id:16, addr:172.16.5.196:49818 status:10, collation:utf8mb4_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="ALTER TABLE t_column CHANGE COLUMN col_45 col_45 VARCHAR(248) NULL"] [txn_mode=OPTIMISTIC] [err="[ddl:8200]Unsupported modify column: length 248 is less than origin 249\ngithub.com/pingcap/errors.AddStack\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201029093017-5a7df2af2ac7/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201029093017-5a7df2af2ac7/normalize.go:156\ngithub.com/pingcap/tidb/ddl.CheckModifyTypeCompatible\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:2784\ngithub.com/pingcap/tidb/ddl.checkModifyTypes\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:2805\ngithub.com/pingcap/tidb/ddl.(*ddl).getModifiableColumnJob\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:3020\ngithub.com/pingcap/tidb/ddl.(*ddl).ChangeColumn\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:3181\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTable\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:2145\ngithub.com/pingcap/tidb/executor.(*DDLExec).executeAlterTable\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/ddl.go:362\ngithub.com/pingcap/tidb/executor.(*DDLExec).Next\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/ddl.go:86\ngithub.com/pingcap/tidb/executor.Next\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/executor.go:262\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/adapter.go:519\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/adapter.go:401\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/executor/adapter.go:354\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/session/tidb.go:308\ngithub.com/pingcap/tidb/session.(*session).executeStatement\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/session/session.go:1120\ngithub.com/pingcap/tidb/session.(*session).execute\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/session/session.go:1236\ngithub.com/pingcap/tidb/session.(*session).Execute\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/session/session.go:1163\ngithub.com/pingcap/tidb/server.(*TiDBContext).Execute\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/server/driver_tidb.go:248\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/server/conn.go:1374\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/server/conn.go:1005\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/server/conn.go:778\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/tidb_ghpr_build/go/src/github.com/pingcap/tidb/server/server.go:439\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357"]

4. Please provide the relate downstream type and version of drainer.
   (run drainer -V in terminal to get drainer's version)

Release Version: v4.0.9-13-g0abd1b89
Git Commit Hash: 0abd1b891fd86493c5a64a1ecdf4a5199e936606
Build TS: 2020-12-31 09:34:39
Go Version: go1.13
Go OS/Arch: linux/amd64

Start with drainer/syncer.go and the DDL execution path in pkg/loader/load.go, then compare the ordering shown in the Drainer, upstream TiDB, and downstream TiDB logs. Check the checkpoint handling in drainer/checkpoint/mysql.go and sync path in drainer/sync/mysql.go; done means DDLs execute in the required order without the reported modify-column error.