dm同步错误 only support ROW format binlog, unexpected DML statement found in query event

chendapao · 2020 年9 月 24 日 03:19

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

【TiDB 版本】：

5.7.25-TiDB-v3.0.12

dm_version = v1.0.4

【问题描述】：

上游mysql配置

mysql> show global variables like 'server_id';
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| server_id     | 104313318 |
+---------------+-----------+
1 row in set (0.00 sec)

mysql> show global variables like 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin       | ON    |
+---------------+-------+
1 row in set (0.00 sec)

mysql> select variable_name, variable_value from information_schema.global_variables where variable_name in ('binlog_format','binlog_row_image');
+------------------+----------------+
| variable_name    | variable_value |
+------------------+----------------+
| BINLOG_FORMAT    | ROW            |
| BINLOG_ROW_IMAGE | FULL           |
+------------------+----------------+
2 rows in set, 1 warning (0.00 sec)

mysql> show grants;
+-------------------------------------------------------------------------------------------------+
| Grants for tidb_sync@ip地址.%                                                                |
+-------------------------------------------------------------------------------------------------+
| GRANT SELECT, RELOAD, REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'tidb_sync'@'ip地址.%' |
+-------------------------------------------------------------------------------------------------+

dm 的配置

# Worker Configuration.
# Log configuration.
log-file = "******"
#
# # DM-worker listen address.
worker-addr = ":8304"


server-id = 1007318

source-id = "********"

flavor = "mysql"

enable-gtid = false

relay-binlog-name = "mysql-bin.001641"

#charset of DSN of source mysql/mariadb instance
charset = ""
meta-dir = "********"

relay-dir = "********"

[from]
host = "********"
user = "tidb_sync"
password = "********"
port = 3306

#relay log purge strategy
[purge]
interval = 3600
expires = 240
remain-space = 15

dm task的配置

name: ********* 
task-mode: incremental
ignore-checking-items: ["table_schema","binlog_format"]

target-database:
  host: "******"
  port: 4000
  user: "sync"
  password: "*********"

mysql-instances:
  -
    source-id: "*****"
    black-white-list:  "instance"
    route-rules: ["routes01"]
    filter-rules: ["filter1"]
    meta:
      binlog-name: mysql-bin.001641
      binlog-pos: 1041208944

    # number of threads to use for dump data
    mydumper-thread: 4

    # number of threads to use for load data
    loader-thread: 16

    # number of threads to use for replicate binlog
    syncer-thread: 20
filters:
  filter1:
    schema-pattern: "*"
    table-pattern: "*"
    events: ["truncate table", "drop table"]
    sql-pattern: ["^DROP\\s+PROCEDURE", "^CREATE\\s+PROCEDURE", "XA START", "XA END", "XA COMMIT", "XA PREPARE", "XA ROLLBACK", "XA RECOVER", "XA BEGIN"]
    action: Ignore

routes:      
  routes01:
    schema-pattern: "库名"    
    target-schema: "ods_库名"
syncers:                             
  global:                            
    safe-mode: true


black-white-list:
  instance:
    do-dbs: ["库名"]
    do-tables:
    ignore-tables:
    - db-name: "库名"
      tbl-name: "表名"

dm worker的日志

[2020/09/24 11:14:45.824 +08:00] [INFO] [reader.go:197] ["start to parse relay log files in sub directory"] [task=task名字] [unit="binlog replication"] [component="binlog reader"] [directory=dm-relay_log/dm-worker-credithc_hydt3-100-73-18/41d17892-730c-19e6-bcfc-801844ee2da8.000001] [position="(mysql-bin.001641, 1041208944)"]
[2020/09/24 11:14:45.824 +08:00] [INFO] [reader.go:320] ["rotate binlog"] [task=task名字] [unit="binlog replication"] [component="binlog reader"] [position="(mysql-bin|000001.001641, 1041208944)"]
[2020/09/24 11:14:45.824 +08:00] [INFO] [reader.go:346] ["start parse relay log file"] [task=task名字] [unit="binlog replication"] [component="binlog reader"] [file=dm-relay_log/dm-worker-credithc_hydt3-100-73-18/41d17892-730c-19e6-bcfc-801844ee2da8.000001/mysql-bin.001641] [offset=1041208944]
[2020/09/24 11:14:45.825 +08:00] [INFO] [syncer.go:1402] [task=task名字] [unit="binlog replication"] [event=rotate] [position="(mysql-bin|000001.001641, 1041208944)"]
[2020/09/24 11:14:45.869 +08:00] [ERROR] [syncer.go:1568] ["fail to parse statement"] [task=task名字] [unit="binlog replication"] [event=query] [statement="UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {\"url\":\"/v1/loan/repay-frozen\",\"server\":\"10.100.14.15\",\"reqid\":\"b5284cff2ed93692432e559da0956e25\"} ctx*/"] [schema=credithc_hydt3] ["last position"="(mysql-bin|000001.001641, 1041208944)"] [position="(mysql-bin|000001.001641, 1041209458)"] ["gtid set"=NULL] [error="[code=36014:class=sync-unit:scope=internal:level=high] query UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {\"url\":\"/v1/loan/repay-frozen\",\"server\":\"10.100.14.15\",\"reqid\":\"b5284cff2ed93692432e559da0956e25\"} ctx*/: only support ROW format binlog, unexpected DML statement found in query event"]
[2020/09/24 11:14:45.870 +08:00] [INFO] [syncer.go:871] ["flushed checkpoint"] [task=task名字] [unit="binlog replication"] [checkpoint="(mysql-bin.001641, 1041208944)(flushed (mysql-bin.001641, 1041208944))"]
[2020/09/24 11:14:45.870 +08:00] [INFO] [relay.go:113] ["current earliest active relay log"] [task=task名字] [unit="binlog replication"] ["active relay log"=41d17892-730c-19e6-bcfc-801844ee2da8.000001/mysql-bin.001641]
[2020/09/24 11:14:45.870 +08:00] [INFO] [mode.go:99] ["change count"] [task=task名字] [unit="binlog replication"] ["previous count"=1] ["new count"=0]
[2020/09/24 11:14:45.870 +08:00] [INFO] [syncer.go:2006] ["print status routine exits"] [task=task名字] [unit="binlog replication"] [error="context canceled"]
[2020/09/24 11:14:45.877 +08:00] [INFO] [reader.go:408] ["binlog reader closing"] [task=task名字] [unit="binlog replication"] [component="binlog reader"]
[2020/09/24 11:14:45.877 +08:00] [INFO] [reader.go:365] ["more relay log files need to parse"] [task=task名字] [unit="binlog replication"] [component="binlog reader"] [directory=dm-relay_log/dm-worker-credithc_hydt3-100-73-18/41d17892-730c-19e6-bcfc-801844ee2da8.000001]
[2020/09/24 11:14:45.877 +08:00] [WARN] [reader.go:137] ["parse relay finished"] [task=task名字] [unit="binlog replication"] [component="binlog reader"] [error="context canceled"]
[2020/09/24 11:14:45.878 +08:00] [INFO] [reader.go:413] ["binlog reader closed"] [task=task名字] [unit="binlog replication"] [component="binlog reader"]
[2020/09/24 11:14:45.878 +08:00] [INFO] [subtask.go:236] ["unit process returned"] [subtask=task名字] [unit=Sync] [stage=Paused] [status="{\"masterBinlog\":\"(mysql-bin.001650, 528783845)\",\"syncerBinlog\":\"(mysql-bin.001641, 1041208944)\"}"]
[2020/09/24 11:14:45.878 +08:00] [ERROR] [subtask.go:255] ["unit process error"] [subtask=task名字] [unit=Sync] ["error information"="{\"msg\":\"[code=36014:class=sync-unit:scope=internal:level=high] current pos (mysql-bin|000001.001641, 1041209458): query UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {\\\"url\\\":\\\"/v1/loan/repay-frozen\\\",\\\"server\\\":\\\"10.100.14.15\\\",\\\"reqid\\\":\\\"b5284cff2ed93692432e559da0956e25\\\"} ctx*/: only support ROW format binlog, unexpected DML statement found in query event\\
github.com/pingcap/dm/pkg/terror.(*Error).Generate\\
\\t/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/pkg/terror/terror.go:232\\
github.com/pingcap/dm/syncer.(*Syncer).parseDDLSQL\\
\\t/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/ddl.go:116\\
github.com/pingcap/dm/syncer.(*Syncer).handleQueryEvent\\
\\t/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:1566\\
github.com/pingcap/dm/syncer.(*Syncer).Run\\
\\t/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:1312\\
github.com/pingcap/dm/syncer.(*Syncer).Process\\
\\t/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:599\\
runtime.goexit\\
\\t/usr/local/go/src/runtime/asm_amd64.s:1357\",\"error\":{\"ErrCode\":36014,\"ErrClass\":11,\"ErrScope\":3,\"ErrLevel\":3,\"Message\":\"current pos (mysql-bin|000001.001641, 1041209458): query UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {\\\"url\\\":\\\"/v1/loan/repay-frozen\\\",\\\"server\\\":\\\"10.100.14.15\\\",\\\"reqid\\\":\\\"b5284cff2ed93692432e559da0956e25\\\"} ctx*/: only support ROW format binlog, unexpected DML statement found in query event\"}}"]
[2020/09/24 11:14:46.165 +08:00] [INFO] [server.go:229] [request=QueryTaskOperation] [payload="name:\"task名字\" logID:127 "]
[2020/09/24 11:14:50.784 +08:00] [WARN] [task_checker.go:354] ["backoff skip auto resume task"] [component="task checker"] [task=task名字] [latestResumeTime=2020/09/24 11:14:50.784 +08:00] [duration=1s]
[2020/09/24 11:14:50.879 +08:00] [INFO] [relay.go:568] ["flush meta finished"] [component="relay log"] [meta="master-uuid = 41d17892-730c-19e6-bcfc-801844ee2da8.000001, relay-binlog = (mysql-bin.001650, 528795838), relay-binlog-gtid = "]
[2020/09/24 11:14:55.784 +08:00] [INFO] [worker.go:314] ["operate subtask"] [component="worker controller"] [operation=AutoResume] [task=task名字]
[2020/09/24 11:14:55.784 +08:00] [INFO] [task_checker.go:365] ["dispatch auto resume task"] [component="task checker"] [task=task名字] [opLogID=128]
[2020/09/24 11:14:56.784 +08:00] [INFO] [worker.go:793] ["start to execute operation"] [component="worker controller"] [oplog="{\"id\":128,\"task\":{\"op\":6,\"name\":\"task名字\"},\"ts\":1600917295784465373}"]
[2020/09/24 11:14:56.784 +08:00] [INFO] [worker.go:880] ["auto_resume sub task"] [component="worker controller"] [task=task名字]

对应附近的binlog

# at 1041208944
#200921 14:23:14 server id 104313314  end_log_pos 1041209009 CRC32 0xe6b02d59   GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1041209009
#200921 14:23:14 server id 104313314  end_log_pos 1041209108 CRC32 0x76580b16   Query   thread_id=1894497       exec_time=2     error_code=0
SET TIMESTAMP=1600669394/*!*/;
SET @@session.sql_mode=8/*!*/;
BEGIN
/*!*/;
# at 1041209108
#200921 14:23:14 server id 104313314  end_log_pos 1041209458 CRC32 0x6c715dfc   Query   thread_id=1894497       exec_time=2     error_code=0
SET TIMESTAMP=1600669394/*!*/;
UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {"url":"/v1/loan/repay-frozen","server":"10.100.14.15","reqid":"b5284cff2ed93692432e559da0956e25"} ctx*/
/*!*/;
# at 1041209458
#200921 14:23:14 server id 104313314  end_log_pos 1041209489 CRC32 0x03376ba6   Xid = 978484716
COMMIT/*!*/;
# at 1041209489
#200921 14:23:17 server id 104307520  end_log_pos 1041209554 CRC32 0x738c321d   GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1041209554
#200921 14:23:17 server id 104307520  end_log_pos 1041209653 CRC32 0x20b264ad   Query   thread_id=851665780     exec_time=4294967295    error_code=0
SET TIMESTAMP=1600669397/*!*/;
SET @@session.sql_mode=0/*!*/;
BEGIN
/*!*/;
# at 1041209653
#200921 14:23:17 server id 104307520  end_log_pos 1041210050 CRC32 0xd25c3d7a   Query   thread_id=851665780     exec_time=4294967295    error_code=0
SET TIMESTAMP=1600669397/*!*/;
UPDATE `hyr_frozenlist` SET `status`='2', `trx_id`='16006693984342503061', `order_id`='16006693984342503061', `fz_time`='2020-09-21 14:23:18' WHERE (`id`='10488542') AND (`status`='0') /*ctx {"url":"/v1/system/update-frozen-list","server":"10.100.36.39","reqid":"3f2fc84b1b657642f463a7a58c1c6d93"} ctx*/
/*!*/;
# at 1041210050
#200921 14:23:17 server id 104307520  end_log_pos 1041210081 CRC32 0x226215f6   Xid = 978484714
COMMIT/*!*/;

错误描述: dm接增量数据同步出错

错误内容

[code=36014:class=sync-unit:scope=internal:level=high] 
current pos (mysql-bin|000001.001641, 1041209458): 
query 

UPDATE `user_account` SET `acctbal`='1043.31', `avlbal`='0.00', `frzbal`='1043.31', `sync_time`='1600669398' WHERE `usrcustid`='8000000000847070' /*ctx {\\\"url\\\":\\\"/v1/loan/repay-frozen\\\",\\\"server\\\":\\\"10.100.14.15\\\",\\\"reqid\\\":\\\"b5284cff2ed93692432e559da0956e25\\\"} ctx*/

only support ROW format binlog, unexpected DML statement found in query event\


github.com/pingcap/dm/pkg/terror.(*Error).Generate\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/pkg/terror/terror.go:232\


github.com/pingcap/dm/syncer.(*Syncer).parseDDLSQL\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/ddl.go:116\


github.com/pingcap/dm/syncer.(*Syncer).handleQueryEvent\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:1566\


github.com/pingcap/dm/syncer.(*Syncer).Run\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:1312\


github.com/pingcap/dm/syncer.(*Syncer).Process\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:599\


github.com/pingcap/dm/syncer.(*Syncer).Resume\
\t
/home/jenkins/agent/workspace/build_dm_master/go/src/github.com/pingcap/dm/syncer/syncer.go:2320\


runtime.goexit\
\t/usr/local/go/src/runtime/asm_amd64.s:1357

Lucien-卢西恩 · 2020 年9 月 24 日 06:11

确认一下 binlog 格式是否存在非 row 格式的数据写入，这个基本可以确认是因为格式不对导致的。

chendapao · 2020 年9 月 24 日 06:29

那么该如何检查 binlog是否存在非row格式写入呢? 检查配置里已经是row了,还会存在非row的写入吗?

此时同步该如何操作呢?修改好binlog然后重新同步,还是可以跳过还是其他呢?

小王同学 · 2020 年9 月 24 日 07:51

可以从 binlog 中内容确认下格式，另外如何检查 MySQL binlog 是否存在非 row 格式写入可以 Google 搜索一下其他方式。
binlog 格式为同步的硬性条件，修改后重新同步。

chendapao · 2020 年9 月 24 日 08:30

谢谢

找到问题了

上游mysql,修改了row模式后,没有重启,导致参数没生效.

那以后这类的问题除了去检查binlog内容,还有其他方法来检查吗?

小王同学 · 2020 年9 月 24 日 11:08

最直观方式是检查 binlog 中的内容，其他方式不太了解，可以去 MySQL 相关社区了解下。

system · 2022 年10 月 31 日 19:07

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。