Skip to content
This repository has been archived by the owner on Nov 24, 2023. It is now read-only.

relay report error if --binlog-annotate-row-event enabled for MariaDB #52

Closed
csuzhangxc opened this issue Feb 19, 2019 · 1 comment
Closed

relay report error if --binlog-annotate-row-event enabled for MariaDB #52

csuzhangxc opened this issue Feb 19, 2019 · 1 comment
Labels
type/bug This issue is a bug report

Comments

@csuzhangxc
Copy link
Member

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.

    1. enable --binlog-annotate-row-event in upstream MariaDB
    2. use DM-worker to pull binlog from upstream MariaDB (set or not set enable-gtid for DM-worker)

  2. What did you expect to see?

    • relay works correctly

  3. What did you see instead?

    set enable-gtid with debug log level:

    2019/02/19 21:24:07.708 relay.go:751: [info] [relay] start sync for master(127.0.0.1:3307, 0-1.000001) from GTID set 
2019/02/19 21:24:07.718 relay.go:741: [info] [relay] last slave connection id 14
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:0 EventType:RotateEvent ServerID:1 EventSize:43 LogPos:0 Flags:32}
2019/02/19 21:24:07.731 relay.go:366: [info] [relay] rotate to (mysql-bin.000001, 887)
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:FormatDescriptionEvent ServerID:1 EventSize:245 LogPos:249 Flags:0}
2019/02/19 21:24:07.731 relay.go:701: [debug] [relay] the first 4 bytes are [254 98 105 110]
2019/02/19 21:24:07.731 relay.go:729: [info] [relay] binlog file mysql-bin.000001 already has Format_desc event, so ignore it
2019/02/19 21:24:07.731 relay.go:586: [info] [relay] mysql-bin.000001 seek to end (887)
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:MariadbGTIDListEvent ServerID:1 EventSize:25 LogPos:274 Flags:0}
2019/02/19 21:24:07.731 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573719 EventType:MariadbGTIDListEvent ServerID:1 EventSize:25 LogPos:274 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:MariadbBinLogCheckPointEvent ServerID:1 EventSize:39 LogPos:313 Flags:0}
2019/02/19 21:24:07.731 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573719 EventType:MariadbBinLogCheckPointEvent ServerID:1 EventSize:39 LogPos:313 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:351 Flags:8}
2019/02/19 21:24:07.731 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:351 Flags:8} (with relay file size 887)
2019/02/19 21:24:07.731 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:88 LogPos:439 Flags:0}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:88 LogPos:439 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:477 Flags:8}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:477 Flags:8} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:93 LogPos:570 Flags:0}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:93 LogPos:570 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:608 Flags:8}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:608 Flags:8} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:99 LogPos:707 Flags:0}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:99 LogPos:707 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:745 Flags:8}
2019/02/19 21:24:07.732 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:745 Flags:8} (with relay file size 887)
2019/02/19 21:24:07.732 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:104 LogPos:849 Flags:0}
2019/02/19 21:24:07.733 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:QueryEvent ServerID:1 EventSize:104 LogPos:849 Flags:0} (with relay file size 887)
2019/02/19 21:24:07.733 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:887 Flags:8}
2019/02/19 21:24:07.733 relay.go:439: [warning] [relay] skip obsolete event &{Timestamp:1550573720 EventType:MariadbGTIDEvent ServerID:1 EventSize:38 LogPos:887 Flags:8} (with relay file size 887)
2019/02/19 21:24:07.733 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:24:07.733 relay.go:417: [info] [relay] gap detected from 887 to 959 in mysql-bin.000001, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:24:07.747 relay.go:263: [info] [relay] start to fill gap in relay log file from (mysql-bin.000001, 887)
2019/02/19 21:24:07.747 relay.go:271: [info] [relay] binlog events in the gap for file relay_binlog/0-1.000001/mysql-bin.000001 not exists in previous sub directory, no need to add a LOG_EVENT_RELAY_LOG_F flag. current GTID set , previous sub directory end GTID set %!s(<nil>)
2019/02/19 21:24:07.756 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:0 EventType:RotateEvent ServerID:1 EventSize:43 LogPos:0 Flags:32}
2019/02/19 21:24:07.756 relay.go:366: [info] [relay] rotate to (mysql-bin.000001, 849)
2019/02/19 21:24:07.756 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:FormatDescriptionEvent ServerID:1 EventSize:245 LogPos:0 Flags:0}
2019/02/19 21:24:07.756 relay.go:701: [debug] [relay] the first 4 bytes are [254 98 105 110]
2019/02/19 21:24:07.757 relay.go:729: [info] [relay] binlog file mysql-bin.000001 already has Format_desc event, so ignore it
2019/02/19 21:24:07.757 relay.go:586: [info] [relay] mysql-bin.000001 seek to end (887)
2019/02/19 21:24:07.757 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:24:07.757 relay.go:424: [info] [relay] fill gap reaching the end pos (mysql-bin.000001, 1011), current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:24:07.757 relay.go:155: [error] [relay] process exit with error some events missing, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}, lastPos (mysql-bin.000001, 849), current GTID 0-1-4, relay file size 887
github.com/pingcap/dm/relay.(*Relay).process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:443
github.com/pingcap/dm/relay.(*Relay).Process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:152
github.com/pingcap/dm/dm/worker.(*RelayHolder).run
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:106
github.com/pingcap/dm/dm/worker.(*RelayHolder).Start.func1
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:82
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1333
2019/02/19 21:24:07.757 relay.go:112: [error] process error with type UnknownError:
 some events missing, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}, lastPos (mysql-bin.000001, 849), current GTID 0-1-4, relay file size 887
github.com/pingcap/dm/relay.(*Relay).process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:443
github.com/pingcap/dm/relay.(*Relay).Process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:152
github.com/pingcap/dm/dm/worker.(*RelayHolder).run
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:106
github.com/pingcap/dm/dm/worker.(*RelayHolder).Start.func1
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:82
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1333

    not set enable-gtid still with debug log level:

    2019/02/19 21:25:23.489 relay.go:770: [info] [relay] start sync for master (127.0.0.1:3307, 0-1.000001) from (mysql-bin.000001, 887)
2019/02/19 21:25:23.497 relay.go:741: [info] [relay] last slave connection id 17
2019/02/19 21:25:23.506 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:0 EventType:RotateEvent ServerID:1 EventSize:43 LogPos:0 Flags:32}
2019/02/19 21:25:23.506 relay.go:366: [info] [relay] rotate to (mysql-bin.000001, 887)
2019/02/19 21:25:23.506 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:FormatDescriptionEvent ServerID:1 EventSize:245 LogPos:0 Flags:0}
2019/02/19 21:25:23.506 relay.go:701: [debug] [relay] the first 4 bytes are [254 98 105 110]
2019/02/19 21:25:23.506 relay.go:729: [info] [relay] binlog file mysql-bin.000001 already has Format_desc event, so ignore it
2019/02/19 21:25:23.506 relay.go:586: [info] [relay] mysql-bin.000001 seek to end (887)
2019/02/19 21:25:23.506 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:25:23.507 relay.go:417: [info] [relay] gap detected from 887 to 959 in mysql-bin.000001, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:25:23.519 relay.go:263: [info] [relay] start to fill gap in relay log file from (mysql-bin.000001, 887)
2019/02/19 21:25:23.530 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:0 EventType:RotateEvent ServerID:1 EventSize:43 LogPos:0 Flags:32}
2019/02/19 21:25:23.530 relay.go:366: [info] [relay] rotate to (mysql-bin.000001, 887)
2019/02/19 21:25:23.530 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573719 EventType:FormatDescriptionEvent ServerID:1 EventSize:245 LogPos:0 Flags:0}
2019/02/19 21:25:23.530 relay.go:701: [debug] [relay] the first 4 bytes are [254 98 105 110]
2019/02/19 21:25:23.530 relay.go:729: [info] [relay] binlog file mysql-bin.000001 already has Format_desc event, so ignore it
2019/02/19 21:25:23.530 relay.go:586: [info] [relay] mysql-bin.000001 seek to end (887)
2019/02/19 21:25:23.531 relay.go:344: [debug] [relay] receive binlog event with header &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:25:23.531 relay.go:424: [info] [relay] fill gap reaching the end pos (mysql-bin.000001, 1011), current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}
2019/02/19 21:25:23.531 relay.go:155: [error] [relay] process exit with error some events missing, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}, lastPos (mysql-bin.000001, 887), current GTID , relay file size 887
github.com/pingcap/dm/relay.(*Relay).process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:443
github.com/pingcap/dm/relay.(*Relay).Process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:152
github.com/pingcap/dm/dm/worker.(*RelayHolder).run
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:106
github.com/pingcap/dm/dm/worker.(*RelayHolder).Start.func1
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:82
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1333
2019/02/19 21:25:23.531 relay.go:112: [error] process error with type UnknownError:
 some events missing, current event &{Timestamp:1550573720 EventType:TableMapEvent ServerID:1 EventSize:52 LogPos:1011 Flags:0}, lastPos (mysql-bin.000001, 887), current GTID , relay file size 887
github.com/pingcap/dm/relay.(*Relay).process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:443
github.com/pingcap/dm/relay.(*Relay).Process
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/relay/relay.go:152
github.com/pingcap/dm/dm/worker.(*RelayHolder).run
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:106
github.com/pingcap/dm/dm/worker.(*RelayHolder).Start.func1
	/Users/zhangxc/gopath/src/github.com/csuzhangxc/dm/dm/worker/relay.go:82
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1333

  4. Versions of the cluster

    • DM version (run dmctl -V or dm-worker -V or dm-master -V):

      Release Version: v1.0.0-alpha-10-g4d01d79
Git Commit Hash: 4d01d798415e835417bb6db7250c56fa2d964d47
Git Branch: master
UTC Build Time: 2019-02-11 14:50:57
Go Version: go version go1.11.2 linux/amd64

    • Upstream MySQL/MariaDB server version:

      erver version: 5.5.5-10.1.21-MariaDB-1~jessie mariadb.org binary distribution

  5. some binlog events in upstream MariaDB

    mysql> SHOW BINLOG EVENTS IN 'mysql-bin.000001' FROM 313 LIMIT 15;
+------------------+------+---------------+-----------+-------------+------------------------------------------------------------------------------------------+
| Log_name         | Pos  | Event_type    | Server_id | End_log_pos | Info                                                                                     |
+------------------+------+---------------+-----------+-------------+------------------------------------------------------------------------------------------+
| mysql-bin.000001 |  313 | Gtid          |         1 |         351 | GTID 0-1-1                                                                               |
| mysql-bin.000001 |  351 | Query         |         1 |         439 | use `mysql`; TRUNCATE TABLE time_zone                                                    |
| mysql-bin.000001 |  439 | Gtid          |         1 |         477 | GTID 0-1-2                                                                               |
| mysql-bin.000001 |  477 | Query         |         1 |         570 | use `mysql`; TRUNCATE TABLE time_zone_name                                               |
| mysql-bin.000001 |  570 | Gtid          |         1 |         608 | GTID 0-1-3                                                                               |
| mysql-bin.000001 |  608 | Query         |         1 |         707 | use `mysql`; TRUNCATE TABLE time_zone_transition                                         |
| mysql-bin.000001 |  707 | Gtid          |         1 |         745 | GTID 0-1-4                                                                               |
| mysql-bin.000001 |  745 | Query         |         1 |         849 | use `mysql`; TRUNCATE TABLE time_zone_transition_type                                    |
| mysql-bin.000001 |  849 | Gtid          |         1 |         887 | BEGIN GTID 0-1-5                                                                         |
| mysql-bin.000001 |  887 | Annotate_rows |         1 |         959 | INSERT INTO time_zone (Use_leap_seconds) VALUES ('N')                                    |
| mysql-bin.000001 |  959 | Table_map     |         1 |        1011 | table_id: 18 (mysql.time_zone)                                                           |
| mysql-bin.000001 | 1011 | Write_rows_v1 |         1 |        1046 | table_id: 18 flags: STMT_END_F                                                           |
| mysql-bin.000001 | 1046 | Query         |         1 |        1116 | COMMIT                                                                                   |
| mysql-bin.000001 | 1116 | Gtid          |         1 |        1154 | BEGIN GTID 0-1-6                                                                         |
| mysql-bin.000001 | 1154 | Annotate_rows |         1 |        1261 | INSERT INTO time_zone_name (Name, Time_zone_id) VALUES ('Africa/Abidjan', @time_zone_id) |
+------------------+------+---------------+-----------+-------------+------------------------------------------------------------------------------------------+

According to the log and events in the upstream MariaDB, we can see the relay unit did not receive the following event:

| mysql-bin.000001 |  887 | Annotate_rows |         1 |         959 | INSERT INTO time_zone (Use_leap_seconds) VALUES ('N')

It seems events with Annotate_rows type are not sent to slave (here is relay unit) default, ref http://worklog.askmonty.org/worklog/Server-Sprint/?tid=47.
@csuzhangxc csuzhangxc added the type/bug This issue is a bug report label Feb 19, 2019
@csuzhangxc csuzhangxc mentioned this issue Mar 13, 2019
Merged
@csuzhangxc
Copy link
Member Author

fixed in #80

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
type/bug This issue is a bug report
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@csuzhangxc