DM任务创建失败failed to create schema tracker

sgjr · 2022 年8 月 2 日 12:18

【 TiDB 使用环境】生产
【 TiDB 版本】DM2.0.6、TiDB5.1.4、MySQL5.7.28
【遇到的问题】创建dm-task任务失败
【复现路径】做过哪些操作出现的问题
【问题现象及影响】
【附件】

相关日志、配置文件、Grafana 监控（https://metricstool.pingcap.com/)
- dm-task配置文件

name: "210021_1659407811"
# 全量+增量 (all) 同步模式
task-mode: all
meta-schema: dm_meta
online-ddl-scheme: "gh-ost"
# 下游 TiDB 配置信息
target-database:
  host: "10.xxxx"
  port: 3306
  user: "user"
  password: "xxxx"

# 当前数据同步任务需要的全部上游 MySQL 实例配置


block-allow-list:
  rule-1:
    do-tables:
    - db-name: "os-server-test"
      tbl-name: "login_entry_points"

filters:
  filter-01:
    schema-pattern: "os-server-test"
    table-pattern: login_entry_points
    events:
    - delete
    - drop table
    sql-pattern: []
    action: Ignore
  filter-02:
    schema-pattern: '*'
    table-pattern: ""
    events: []
    sql-pattern:
    - ALTER\s+TABLE[\s\S]*ADD\s+PARTITION
    - ALTER\s+TABLE[\s\S]*DROP\s+PARTITION
    action: Ignore


mysql-instances:
-
  source-id: "os-server-test"
  block-allow-list: "rule-1"
  filter-rules: ["filter-01", "filter-02"]
  mydumper-config-name: "global"
  syncer-config-name: "global"
  loader-config-name: "global"


# 黑白名单全局配置，各实例通过配置项名引用

# Mydumper 全局配置，各实例通过配置项名引用
mydumpers:
  global:
    chunk-filesize: 64
    threads: 4
loaders:
  global:
    pool-size: 32

syncers:
  global:
    worker-count: 64
    batch: 3000
    safe-mode: true

TiUP Cluster Display 信息
TiUP CLuster Edit config 信息
TiDB-Overview 监控
对应模块的 Grafana 监控（如有 BR、TiDB-binlog、TiCDC 等）
对应模块日志（包含问题前后 1 小时日志）

[2022/08/02 19:52:08.474 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:52:39.475 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:53:10.477 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:53:41.478 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:53:45.449 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [type=MySQL]
[2022/08/02 19:53:45.449 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [version=5.7.28-log]
[2022/08/02 19:53:46.994 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [type=TiDB]
[2022/08/02 19:53:46.994 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [version=5.1.4]
[2022/08/02 19:53:46.994 +08:00] [ERROR] [baseconn.go:105] ["query statement failed"] [component=schema-tracker] [task=210021_1659407811] [query="SHOW VARIABLES LIKE 'tidb_skip_utf8_check'"] [argument="[]"] [error="context deadline exceeded"]
[2022/08/02 19:53:46.995 +08:00] [INFO] [rollback.go:59] ["rolling back"] [functon=close-DBs] [onwer=syncer]
[2022/08/02 19:53:46.996 +08:00] [INFO] [loader.go:787] ["stop importing data process"] [task=210021_1659407811] [unit=load]
[2022/08/02 19:53:46.996 +08:00] [ERROR] [subtask.go:198] ["fail to initial subtask"] [subtask=210021_1659407811] [error="[code=44012:class=schema-tracker:scope=internal:level=high], Message: fail to initial unit Sync of subtask 210021_1659407811 : failed to create schema tracker, RawCause: context deadline exceeded"]
[2022/08/02 19:53:48.156 +08:00] [INFO] [worker.go:476] ["auto_resume sub task"] [component="worker controller"] [task=210021_1659407811]
[2022/08/02 19:53:48.156 +08:00] [INFO] [syncer.go:3294] ["use timezone"] [task=210021_1659407811] [unit="binlog replication"] [location=UTC]
[2022/08/02 19:53:50.099 +08:00] [INFO] [dumpling.go:300] ["found upstream SQL mode"] [task=210021_1659407811] [unit=dump] ["SQL mode"=ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION]
[2022/08/02 19:53:50.099 +08:00] [INFO] [dumpling.go:67] ["create dumpling"] [task=210021_1659407811] [unit=dump] [config="{\"s3\":{\"endpoint\":\"\",\"region\":\"\",\"storage-class\":\"\",\"sse\":\"\",\"sse-kms-key-id\":\"\",\"acl\":\"\",\"access-key\":\"\",\"secret-access-key\":\"\",\"provider\":\"\",\"force-path-style\":false,\"use-accelerate-endpoint\":false},\"gcs\":{\"endpoint\":\"\",\"storage-class\":\"\",\"predefined-acl\":\"\",\"credentials-file\":\"\"},\"AllowCleartextPasswords\":false,\"SortByPk\":true,\"NoViews\":true,\"NoHeader\":false,\"NoSchemas\":false,\"NoData\":false,\"CompleteInsert\":true,\"TransactionalConsistency\":true,\"EscapeBackslash\":true,\"DumpEmptyDatabase\":true,\"PosAfterConnect\":false,\"CompressType\":0,\"Host\":\"mpay-app16-os-in.i.nease.net\",\"Port\":16388,\"Threads\":4,\"User\":\"root\",\"Security\":{\"CAPath\":\"\",\"CertPath\":\"\",\"KeyPath\":\"\"},\"LogLevel\":\"\",\"LogFile\":\"\",\"LogFormat\":\"\",\"OutputDirPath\":\"./dumped_data.210021_1659407811\",\"StatusAddr\":\"\",\"Snapshot\":\"\",\"Consistency\":\"auto\",\"CsvNullValue\":\"\\\\N\",\"SQL\":\"\",\"CsvSeparator\":\"\",\"CsvDelimiter\":\"\",\"Databases\":null,\"Where\":\"\",\"FileType\":\"\",\"ServerInfo\":{\"ServerType\":0,\"ServerVersion\":null},\"Rows\":200000,\"ReadTimeout\":0,\"TiDBMemQuotaQuery\":0,\"FileSize\":67108864,\"StatementSize\":1000000,\"SessionParams\":{\"time_zone\":\"+00:00\"},\"Tables\":null}"]
[2022/08/02 19:53:54.209 +08:00] [INFO] [loader.go:540] ["loader's sql_mode is"] [task=210021_1659407811] [unit=load] [sqlmode=NO_ENGINE_SUBSTITUTION,ALLOW_INVALID_DATES,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,IGNORE_SPACE]
[2022/08/02 19:56:06.071 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload=]
[2022/08/02 19:56:28.309 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [type=MySQL]
[2022/08/02 19:56:28.309 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [version=5.7.28-log]
[2022/08/02 19:56:29.853 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [type=TiDB]
[2022/08/02 19:56:29.854 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [version=5.1.4]
[2022/08/02 19:56:29.854 +08:00] [ERROR] [baseconn.go:105] ["query statement failed"] [component=schema-tracker] [task=210021_1659407811] [query="SHOW VARIABLES LIKE 'tidb_skip_utf8_check'"] [argument="[]"] [error="context deadline exceeded"]
[2022/08/02 19:56:29.854 +08:00] [INFO] [rollback.go:59] ["rolling back"] [functon=close-DBs] [onwer=syncer]
[2022/08/02 19:56:29.855 +08:00] [INFO] [loader.go:787] ["stop importing data process"] [task=210021_1659407811] [unit=load]
[2022/08/02 19:56:29.855 +08:00] [ERROR] [subtask.go:198] ["fail to initial subtask"] [subtask=210021_1659407811] [error="[code=44012:class=schema-tracker:scope=internal:level=high], Message: fail to initial unit Sync of subtask 210021_1659407811 : failed to create schema tracker, RawCause: context deadline exceeded"]
[2022/08/02 19:56:29.855 +08:00] [INFO] [task_checker.go:401] ["dispatch auto resume task"] [component="task checker"] [task=210021_1659407811]
[2022/08/02 19:56:29.855 +08:00] [WARN] [task_checker.go:393] ["backoff skip auto resume task"] [component="task checker"] [task=210021_1659407811] [latestResumeTime=2022/08/02 19:56:29.855 +08:00] [duration=1.517956931s]
[2022/08/02 19:56:33.156 +08:00] [INFO] [worker.go:476] ["auto_resume sub task"] [component="worker controller"] [task=210021_1659407811]
[2022/08/02 19:56:33.156 +08:00] [INFO] [syncer.go:3294] ["use timezone"] [task=210021_1659407811] [unit="binlog replication"] [location=UTC]
[2022/08/02 19:56:35.025 +08:00] [INFO] [dumpling.go:300] ["found upstream SQL mode"] [task=210021_1659407811] [unit=dump] ["SQL mode"=ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION]
[2022/08/02 19:56:35.025 +08:00] [INFO] [dumpling.go:67] ["create dumpling"] [task=210021_1659407811] [unit=dump] [config="{\"s3\":{\"endpoint\":\"\",\"region\":\"\",\"storage-class\":\"\",\"sse\":\"\",\"sse-kms-key-id\":\"\",\"acl\":\"\",\"access-key\":\"\",\"secret-access-key\":\"\",\"provider\":\"\",\"force-path-style\":false,\"use-accelerate-endpoint\":false},\"gcs\":{\"endpoint\":\"\",\"storage-class\":\"\",\"predefined-acl\":\"\",\"credentials-file\":\"\"},\"AllowCleartextPasswords\":false,\"SortByPk\":true,\"NoViews\":true,\"NoHeader\":false,\"NoSchemas\":false,\"NoData\":false,\"CompleteInsert\":true,\"TransactionalConsistency\":true,\"EscapeBackslash\":true,\"DumpEmptyDatabase\":true,\"PosAfterConnect\":false,\"CompressType\":0,\"Host\":\"mpay-app16-os-in.i.nease.net\",\"Port\":16388,\"Threads\":4,\"User\":\"root\",\"Security\":{\"CAPath\":\"\",\"CertPath\":\"\",\"KeyPath\":\"\"},\"LogLevel\":\"\",\"LogFile\":\"\",\"LogFormat\":\"\",\"OutputDirPath\":\"./dumped_data.210021_1659407811\",\"StatusAddr\":\"\",\"Snapshot\":\"\",\"Consistency\":\"auto\",\"CsvNullValue\":\"\\\\N\",\"SQL\":\"\",\"CsvSeparator\":\"\",\"CsvDelimiter\":\"\",\"Databases\":null,\"Where\":\"\",\"FileType\":\"\",\"ServerInfo\":{\"ServerType\":0,\"ServerVersion\":null},\"Rows\":200000,\"ReadTimeout\":0,\"TiDBMemQuotaQuery\":0,\"FileSize\":67108864,\"StatementSize\":1000000,\"SessionParams\":{\"time_zone\":\"+00:00\"},\"Tables\":null}"]
[2022/08/02 19:56:39.146 +08:00] [INFO] [loader.go:540] ["loader's sql_mode is"] [task=210021_1659407811] [unit=load] [sqlmode=NO_ENGINE_SUBSTITUTION,ALLOW_INVALID_DATES,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,IGNORE_SPACE]
[2022/08/02 19:57:02.696 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:57:02.697 +08:00] [INFO] [worker.go:660] ["receive subtask stage change"] [stage="{\"expect\":0,\"source\":\"mpay-os-server-test\",\"task\":\"210021_1659407811\"}"] ["is deleted"=true]
[2022/08/02 19:57:33.699 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:58:04.700 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:58:35.701 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:58:52.669 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload=]
[2022/08/02 19:59:06.702 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 19:59:13.165 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [type=MySQL]
[2022/08/02 19:59:13.165 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [version=5.7.28-log]
[2022/08/02 19:59:14.714 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [type=TiDB]
[2022/08/02 19:59:14.714 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [version=5.1.4]
[2022/08/02 19:59:14.714 +08:00] [ERROR] [baseconn.go:105] ["query statement failed"] [component=schema-tracker] [task=210021_1659407811] [query="SHOW VARIABLES LIKE 'tidb_skip_utf8_check'"] [argument="[]"] [error="context deadline exceeded"]
[2022/08/02 19:59:14.714 +08:00] [INFO] [rollback.go:59] ["rolling back"] [functon=close-DBs] [onwer=syncer]
[2022/08/02 19:59:14.715 +08:00] [INFO] [loader.go:787] ["stop importing data process"] [task=210021_1659407811] [unit=load]
[2022/08/02 19:59:14.715 +08:00] [ERROR] [subtask.go:198] ["fail to initial subtask"] [subtask=210021_1659407811] [error="[code=44012:class=schema-tracker:scope=internal:level=high], Message: fail to initial unit Sync of subtask 210021_1659407811 : failed to create schema tracker, RawCause: context deadline exceeded"]
[2022/08/02 19:59:14.715 +08:00] [INFO] [task_checker.go:401] ["dispatch auto resume task"] [component="task checker"] [task=210021_1659407811]
[2022/08/02 19:59:14.716 +08:00] [WARN] [task_checker.go:393] ["backoff skip auto resume task"] [component="task checker"] [task=210021_1659407811] [latestResumeTime=2022/08/02 19:59:14.716 +08:00] [duration=3.094165933s]
[2022/08/02 19:59:16.650 +08:00] [INFO] [worker.go:466] ["stop sub task"] [component="worker controller"] [task=210021_1659407811]
[2022/08/02 19:59:16.650 +08:00] [INFO] [subtask.go:463] [closing] [subtask=210021_1659407811]
[2022/08/02 20:00:26.808 +08:00] [INFO] [worker.go:660] ["receive subtask stage change"] [stage="{\"expect\":2,\"source\":\"mpay-os-server-test\",\"task\":\"210021_1659407811\"}"] ["is deleted"=false]
[2022/08/02 20:00:26.808 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:00:26.810 +08:00] [WARN] [task.go:920] ["session variable 'time_zone' is overwritten by default UTC timezone."] [time_zone=+00:00]
[2022/08/02 20:00:26.810 +08:00] [WARN] [task.go:920] ["session variable 'time_zone' is overwritten by default UTC timezone."] [time_zone=+00:00]
[2022/08/02 20:00:26.811 +08:00] [INFO] [worker.go:694] ["start to create subtask"] [sourceID=mpay-os-server-test] [task=210021_1659407811]
[2022/08/02 20:00:27.757 +08:00] [INFO] [worker.go:426] ["subtask created"] [component="worker controller"] [config="{\"is-sharding\":false,\"shard-mode\":\"\",\"online-ddl\":true,\"online-ddl-scheme\":\"\",\"case-sensitive\":false,\"name\":\"210021_1659407811\",\"mode\":\"all\",\"ignore-checking-items\":null,\"source-id\":\"mpay-os-server-test\",\"server-id\":429524578,\"flavor\":\"mysql\",\"meta-schema\":\"dm_meta\",\"heartbeat-update-interval\":1,\"heartbeat-report-interval\":10,\"enable-heartbeat\":false,\"meta\":null,\"timezone\":\"\",\"relay-dir\":\"./relay_log\",\"use-relay\":false,\"from\":{\"host\":\"mpay-app16-os-in.i.nease.net\",\"port\":16388,\"user\":\"root\",\"max-allowed-packet\":null,\"session\":{\"time_zone\":\"+00:00\"},\"security\":null},\"to\":{\"host\":\"10.67.103.138\",\"port\":3306,\"user\":\"tidb_loader_user\",\"max-allowed-packet\":null,\"session\":{\"tidb_txn_mode\":\"optimistic\",\"time_zone\":\"+00:00\"},\"security\":null},\"route-rules\":[],\"filter-rules\":[],\"mapping-rule\":[],\"expression-filter\":[],\"black-white-list\":null,\"block-allow-list\":{\"do-tables\":[{\"db-name\":\"mpay-os-server-test\",\"tbl-name\":\"login_entry_points\"}],\"do-dbs\":null,\"ignore-tables\":null,\"ignore-dbs\":null},\"mydumper-path\":\"./bin/mydumper\",\"threads\":4,\"chunk-filesize\":\"64\",\"statement-size\":0,\"rows\":0,\"where\":\"\",\"skip-tz-utc\":true,\"extra-args\":\"\",\"pool-size\":32,\"dir\":\"./dumped_data.210021_1659407811\",\"meta-file\":\"\",\"worker-count\":64,\"batch\":3000,\"queue-size\":1024,\"checkpoint-flush-interval\":30,\"max-retry\":0,\"auto-fix-gtid\":false,\"enable-gtid\":false,\"disable-detect\":false,\"safe-mode\":true,\"enable-ansi-quotes\":false,\"log-level\":\"\",\"log-file\":\"\",\"log-format\":\"\",\"log-rotate\":\"\",\"pprof-addr\":\"\",\"status-addr\":\"\",\"config-file\":\"\",\"clean-dump-file\":true,\"ansi-quotes\":false}"]
[2022/08/02 20:00:27.758 +08:00] [INFO] [syncer.go:3294] ["use timezone"] [task=210021_1659407811] [unit="binlog replication"] [location=UTC]
[2022/08/02 20:00:28.760 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:00:29.599 +08:00] [INFO] [dumpling.go:300] ["found upstream SQL mode"] [task=210021_1659407811] [unit=dump] ["SQL mode"=ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION]
[2022/08/02 20:00:29.599 +08:00] [INFO] [dumpling.go:67] ["create dumpling"] [task=210021_1659407811] [unit=dump] [config="{\"s3\":{\"endpoint\":\"\",\"region\":\"\",\"storage-class\":\"\",\"sse\":\"\",\"sse-kms-key-id\":\"\",\"acl\":\"\",\"access-key\":\"\",\"secret-access-key\":\"\",\"provider\":\"\",\"force-path-style\":false,\"use-accelerate-endpoint\":false},\"gcs\":{\"endpoint\":\"\",\"storage-class\":\"\",\"predefined-acl\":\"\",\"credentials-file\":\"\"},\"AllowCleartextPasswords\":false,\"SortByPk\":true,\"NoViews\":true,\"NoHeader\":false,\"NoSchemas\":false,\"NoData\":false,\"CompleteInsert\":true,\"TransactionalConsistency\":true,\"EscapeBackslash\":true,\"DumpEmptyDatabase\":true,\"PosAfterConnect\":false,\"CompressType\":0,\"Host\":\"mpay-app16-os-in.i.nease.net\",\"Port\":16388,\"Threads\":4,\"User\":\"root\",\"Security\":{\"CAPath\":\"\",\"CertPath\":\"\",\"KeyPath\":\"\"},\"LogLevel\":\"\",\"LogFile\":\"\",\"LogFormat\":\"\",\"OutputDirPath\":\"./dumped_data.210021_1659407811\",\"StatusAddr\":\"\",\"Snapshot\":\"\",\"Consistency\":\"auto\",\"CsvNullValue\":\"\\\\N\",\"SQL\":\"\",\"CsvSeparator\":\"\",\"CsvDelimiter\":\"\",\"Databases\":null,\"Where\":\"\",\"FileType\":\"\",\"ServerInfo\":{\"ServerType\":0,\"ServerVersion\":null},\"Rows\":200000,\"ReadTimeout\":0,\"TiDBMemQuotaQuery\":0,\"FileSize\":67108864,\"StatementSize\":1000000,\"SessionParams\":{\"time_zone\":\"+00:00\"},\"Tables\":null}"]
[2022/08/02 20:00:33.408 +08:00] [INFO] [loader.go:540] ["loader's sql_mode is"] [task=210021_1659407811] [unit=load] [sqlmode=NO_ENGINE_SUBSTITUTION,ALLOW_INVALID_DATES,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,IGNORE_SPACE]
[2022/08/02 20:00:42.736 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:00:59.762 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:01:30.764 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:02:01.765 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:02:32.767 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:03:03.769 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:03:07.647 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [type=MySQL]
[2022/08/02 20:03:07.647 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [version=5.7.28-log]
[2022/08/02 20:03:09.168 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [type=TiDB]
[2022/08/02 20:03:09.168 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [version=5.1.4]
[2022/08/02 20:03:09.168 +08:00] [ERROR] [baseconn.go:105] ["query statement failed"] [component=schema-tracker] [task=210021_1659407811] [query="SHOW VARIABLES LIKE 'tidb_skip_utf8_check'"] [argument="[]"] [error="context deadline exceeded"]
[2022/08/02 20:03:09.168 +08:00] [INFO] [rollback.go:59] ["rolling back"] [functon=close-DBs] [onwer=syncer]
[2022/08/02 20:03:09.170 +08:00] [INFO] [loader.go:787] ["stop importing data process"] [task=210021_1659407811] [unit=load]
[2022/08/02 20:03:09.170 +08:00] [ERROR] [subtask.go:198] ["fail to initial subtask"] [subtask=210021_1659407811] [error="[code=44012:class=schema-tracker:scope=internal:level=high], Message: fail to initial unit Sync of subtask 210021_1659407811 : failed to create schema tracker, RawCause: context deadline exceeded"]
[2022/08/02 20:03:13.155 +08:00] [INFO] [worker.go:476] ["auto_resume sub task"] [component="worker controller"] [task=210021_1659407811]
[2022/08/02 20:03:13.155 +08:00] [INFO] [syncer.go:3294] ["use timezone"] [task=210021_1659407811] [unit="binlog replication"] [location=UTC]
[2022/08/02 20:03:15.049 +08:00] [INFO] [dumpling.go:300] ["found upstream SQL mode"] [task=210021_1659407811] [unit=dump] ["SQL mode"=ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION]
[2022/08/02 20:03:15.049 +08:00] [INFO] [dumpling.go:67] ["create dumpling"] [task=210021_1659407811] [unit=dump] [config="{\"s3\":{\"endpoint\":\"\",\"region\":\"\",\"storage-class\":\"\",\"sse\":\"\",\"sse-kms-key-id\":\"\",\"acl\":\"\",\"access-key\":\"\",\"secret-access-key\":\"\",\"provider\":\"\",\"force-path-style\":false,\"use-accelerate-endpoint\":false},\"gcs\":{\"endpoint\":\"\",\"storage-class\":\"\",\"predefined-acl\":\"\",\"credentials-file\":\"\"},\"AllowCleartextPasswords\":false,\"SortByPk\":true,\"NoViews\":true,\"NoHeader\":false,\"NoSchemas\":false,\"NoData\":false,\"CompleteInsert\":true,\"TransactionalConsistency\":true,\"EscapeBackslash\":true,\"DumpEmptyDatabase\":true,\"PosAfterConnect\":false,\"CompressType\":0,\"Host\":\"mpay-app16-os-in.i.nease.net\",\"Port\":16388,\"Threads\":4,\"User\":\"root\",\"Security\":{\"CAPath\":\"\",\"CertPath\":\"\",\"KeyPath\":\"\"},\"LogLevel\":\"\",\"LogFile\":\"\",\"LogFormat\":\"\",\"OutputDirPath\":\"./dumped_data.210021_1659407811\",\"StatusAddr\":\"\",\"Snapshot\":\"\",\"Consistency\":\"auto\",\"CsvNullValue\":\"\\\\N\",\"SQL\":\"\",\"CsvSeparator\":\"\",\"CsvDelimiter\":\"\",\"Databases\":null,\"Where\":\"\",\"FileType\":\"\",\"ServerInfo\":{\"ServerType\":0,\"ServerVersion\":null},\"Rows\":200000,\"ReadTimeout\":0,\"TiDBMemQuotaQuery\":0,\"FileSize\":67108864,\"StatementSize\":1000000,\"SessionParams\":{\"time_zone\":\"+00:00\"},\"Tables\":null}"]
[2022/08/02 20:03:19.171 +08:00] [INFO] [loader.go:540] ["loader's sql_mode is"] [task=210021_1659407811] [unit=load] [sqlmode=NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,IGNORE_SPACE,NO_ENGINE_SUBSTITUTION,ALLOW_INVALID_DATES]
[2022/08/02 20:03:31.851 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:03:31.856 +08:00] [INFO] [worker.go:660] ["receive subtask stage change"] [stage="{\"expect\":0,\"source\":\"mpay-os-server-test\",\"task\":\"210021_1659407811\"}"] ["is deleted"=true]
[2022/08/02 20:04:02.851 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:04:33.853 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:05:04.854 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:05:35.855 +08:00] [INFO] [server.go:753] [request=QueryStatus] [payload="name:\"210021_1659407811\" "]
[2022/08/02 20:05:53.412 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [type=MySQL]
[2022/08/02 20:05:53.412 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=upstream] [version=5.7.28-log]
[2022/08/02 20:05:54.935 +08:00] [INFO] [config.go:599] ["detect server type"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [type=TiDB]
[2022/08/02 20:05:54.935 +08:00] [INFO] [config.go:618] ["detect server version"] [task=210021_1659407811] [unit="binlog replication"] [scope=downstream] [version=5.1.4]
[2022/08/02 20:05:54.935 +08:00] [ERROR] [baseconn.go:105] ["query statement failed"] [component=schema-tracker] [task=210021_1659407811] [query="SHOW VARIABLES LIKE 'tidb_skip_utf8_check'"] [argument="[]"] [error="context deadline exceeded"]
[2022/08/02 20:05:54.935 +08:00] [INFO] [rollback.go:59] ["rolling back"] [functon=close-DBs] [onwer=syncer]
[2022/08/02 20:05:54.936 +08:00] [INFO] [loader.go:787] ["stop importing data process"] [task=210021_1659407811] [unit=load]
[2022/08/02 20:05:54.937 +08:00] [ERROR] [subtask.go:198] ["fail to initial subtask"] [subtask=210021_1659407811] [error="[code=44012:class=schema-tracker:scope=internal:level=high], Message: fail to initial unit Sync of subtask 210021_1659407811 : failed to create schema tracker, RawCause: context deadline exceeded"]
[2022/08/02 20:05:54.937 +08:00] [INFO] [task_checker.go:401] ["dispatch auto resume task"] [component="task checker"] [task=210021_1659407811]
[2022/08/02 20:05:54.937 +08:00] [WARN] [task_checker.go:393] ["backoff skip auto resume task"] [component="task checker"] [task=210021_1659407811] [latestResumeTime=2022/08/02 20:05:54.937 +08:00] [duration=1.868813356s]
[2022/08/02 20:05:55.888 +08:00] [INFO] [worker.go:466] ["stop sub task"] [component="worker controller"] [task=210021_1659407811]
[2022/08/02 20:05:55.888 +08:00] [INFO] [subtask.go:463] [closing] [subtask=210021_1659407811]

xfworld · 2022 年8 月 3 日 00:50

[2022/08/02 20:03:09.168 +08:00] [ERROR] [baseconn.go:105] [“query statement failed”] [component=schema-tracker] [task=210021_1659407811] [query=“SHOW VARIABLES LIKE ‘tidb_skip_utf8_check’”] [argument="[]"] [error=“context deadline exceeded”]

SHOW VARIABLES LIKE 'tidb_skip_utf8_check
给的啥权限，执行这个都可以失败…

sgjr · 2022 年8 月 3 日 02:21

跟权限没关系的，权限都是all privileges 了

上游 MySQL 权限

image693×293 24.2 KB
下游 TiDB 权限

image949×298 27.2 KB

cheng · 2022 年8 月 3 日 03:04

检查一下配置文件，然后重启试试看

sgjr · 2022 年8 月 3 日 03:06

配置文件在上边贴了，暂时没发现哪里不对的，重启也试过很多次了，每次都是一样卡住

xfworld · 2022 年8 月 3 日 04:20

那以下这些限制有没有不满足的

https://docs.pingcap.com/zh/tidb/stable/dm-overview

建议看一下

sgjr · 2022 年8 月 3 日 07:28

MySQL版本是5.7.28，上游表的字符集是utf8mb4

sgjr · 2022 年8 月 4 日 11:52

补充一下，task-mode 改成 full就正常的，改成all 或者 incremental 就会异常

Min_Chen · 2022 年8 月 8 日 03:13

Hi，从日志看是执行超时了，请确认 worker 到下游网络情况，以及下游 tidb 响应时间性能等问题。

sgjr · 2022 年8 月 8 日 05:11

查到问题问题原因了，是 syncers 的 worker-count 设置过大，调整小后正常了

system · 2022 年10 月 7 日 05:11

该主题在最后一个回复创建后60天后自动关闭。不再允许新的回复。