hanchuanchuan/bingo2sql

MySQL Binlog 解析

bingo2sql's Issues

[BUG] NULL值未处理导致进程崩溃

panic: interface conversion: interface {} is nil, not []uint8

goroutine 1 [running]:
github.com/hanchuanchuan/bingo2sql.compareValue(0xcf5220, 0xc00054ae80, 0x0, 0x0, 0x1)
/root/hcc/bingo2sql/parser.go:2058 +0x1a5
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).generateUpdateSQL(0xc000237900, 0xc0011b8640, 0xc0005accc0, 0xc0005af500, 0xc00036412a, 0xc000100301)
/root/hcc/bingo2sql/parser.go:1347 +0xf21
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).parseSingleEvent(0xc000237900, 0xc0005af500, 0xc00120d860, 0xc0005af500, 0x0)
/root/hcc/bingo2sql/parser.go:2237 +0xa29
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).Parser(0xc000237900, 0x0, 0x0)
/root/hcc/bingo2sql/parser.go:390 +0x4e0
main.runParse()
/root/hcc/bingo2sql/cmd/bingo2sql.go:185 +0x3dd
main.main()
/root/hcc/bingo2sql/cmd/bingo2sql.go:128 +0x199

invalid event size 0, must >= 19

请问下这个提示是什么意思呢？是解析的日志里有无效格式么，我使用的是本地binlog文件解析，正常情况下应该有2000条insert，最终解析到约100条出现这个提示并终止了程序

本地模式只解析了首个binlog，没有连续解析的疑问。

bingo2sql --start-file=mysql-bin.004097 --stop-file=mysql-bin.004152 -t /home/work/table.sql > x.sql
不管是只用了--start-file还是--start-file和--stop-file都用了，都只解析出了第一个binlog里的内容，后面的都没有解析，请问是哪里姿势不对。
测试过用=号、用空格，也测试了相对路径、绝对路径，都还是一样。

thanks

本地解析binlog日志,解析多个表时会出现异常

bingo2sql -d psmsdb -B --start-file ./mysql-bin.000002 --start-time '2021-09-15 00:00:00' --stop-time '2021-09-16 23:59:59' -t x.sql,y.sql

返回

time="2021-09-17T17:15:36+08:00" level=error msg="binlog解析操作失败" file=bingo2sql.go line=181
time="2021-09-17T17:15:36+08:00" level=error msg="读取表结构文件失败(x.sql,y.sql): CreateFile x.sql,y.sql: The system cannot find the file specified." file=bingo2sql.go line=182

--start-time有用么？

解析mariadb10.1.45的时候 用此./bingo2sql --host=x.x.x.x -P 3306 --user=test --password=1234qwer -d jiexi --start-time="2020-07-01 16:04:05" --stop-time="2020-07-06 16:11:05" -t students -B --debug
INFO[2020-07-07T09:59:33+08:00] binlog信息 binlogFile=mysql-145bin.000001 file=parser.go line=915 起始时间="2020-07-01 13:48:48"
INFO[2020-07-07T09:59:33+08:00] 根据指定的时间段,解析出的开始binlog文件是:mysql-145bin.000001,结束文件是:mysql-145bin.000001 file=parser.go line=932
INFO[2020-07-07T09:59:33+08:00] create BinlogSyncer with config {2000000111 192.168.137.145 3306 test false false false UTC true 0 0s 0s 0 false false 0} file=binlogsyncer.go line=144
INFO[2020-07-07T09:59:33+08:00] begin to sync binlog from position (mysql-145bin.000001, 0) file=binlogsyncer.go line=359
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000001, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000002, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000003, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000004, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000005, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000006, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000007, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000008, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000009, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000010, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000011, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000012, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] rotate to (mysql-145bin.000013, 4) file=binlogsyncer.go line=776
INFO[2020-07-07T09:59:33+08:00] 已超出指定位置 file=parser.go line=502 当前位置=4 当前文件=mysql-145bin.000002 结束位置=0 结束文件=mysql-145bin.000001
WARN[2020-07-07T09:59:33+08:00] is finish file=parser.go line=2143
INFO[2020-07-07T09:59:33+08:00] 解析完成 file=parser.go line=449
INFO[2020-07-07T09:59:33+08:00] syncer is closing... file=binlogsyncer.go line=175
INFO[2020-07-07T09:59:33+08:00] kill last connection id 145 file=binlogsyncer.go line=849
INFO[2020-07-07T09:59:33+08:00] syncer is closed file=binlogsyncer.go line=202
什么也没有解析出来，但是./bingo2sql --host=192.168.137.145 -P 3306 --user=test --password=1234qwer -d jiexi --start-file=mysql-145bin.000010 --start-time="2020-07-01 16:04:05" --stop-time="2020-07-06 16:11:05" -t students -B --debug 就可以解析出来了。为什么？看你的参数解释，没明白为啥？

如果--stop-pos和MySQL最新position一样，且MySQL binlog只有DDL、没有其他更新，会导致bingo2sql无法正常结束

如何复现：
1 flush logs生成新的binlog，该binlog只执行DDL，show master status; 得到binlog file和position
flush logs;
create table t2(id int);
show master status; -- | mysql-bin.004720 | 402 |
---后续不再执行其他SQL、binlog保持不变。

2 bingo2sql解析时，--stop-file --stop-pos使用第一步获取的binlog file和position。由于MySQL binlog 一直没有更新，bingo2sql将无法结束，需要Ctrl+C kill：
./bingo2sql -h=xxx -P 3306 -uxxx -p'xxx' -d monitor --start-file="mysql-bin.004720" --start-pos=4 --stop-file="mysql-bin.004720" --stop-pos=402 -B

[2023/10/17 07:00:08] [info] binlogsyncer.go:392 begin to sync binlog from position (mysql-bin.004720, 4)
[2023/10/17 07:00:08] [info] binlogsyncer.go:808 rotate to (mysql-bin.004720, 4)
INFO[2023-10-17T07:00:08Z] 超出最新binlog位置 file=parser.go line=571 当前位置=402 当前文件=mysql-bin.004720 结束位置=402 结束文件=mysql-bin.004720

原因：
checkFinish(https://github.com/hanchuanchuan/bingo2sql/blob/master/core/parser.go#L523) 和finishFlag(https://github.com/hanchuanchuan/bingo2sql/blob/master/core/parser.go#L2271) 可能需要对只有DDL的场景做处理？

解析出来的update没有set条件

解析出来的update没有set条件，很奇怪

输出的日志没有显示pos位置

看了bingo2sql，没有输入当前语句的pos，是我哪里没用好麽？

当使用了--show-thread参数后，--ddl则不生效，无法显示ddl语句

单独使用--ddl
--stop-never --show-gtid --show-time --show-all-time --show-thread --ddl --max 0 --debug

# 64f83485-8ec1-11ec-9822-005056a8e9ea:495
USE `test`;
create table test02(id int); # 2024-03-01 11:29:03

# 64f83485-8ec1-11ec-9822-005056a8e9ea:496
INSERT INTO `test`.`test02`(`id`) VALUES(1); # 2024-03-01 11:29:24

# 64f83485-8ec1-11ec-9822-005056a8e9ea:497
USE `test`;
DROP TABLE `test02` /* generated by server */; # 2024-03-01 11:29:35

# 64f83485-8ec1-11ec-9822-005056a8e9ea:498
USE `test`;
create table test02(id int); # 2024-03-01 14:25:37

# 64f83485-8ec1-11ec-9822-005056a8e9ea:499
INSERT INTO `test`.`test02`(`id`) VALUES(1); # 2024-03-01 14:27:40

当加上--show-thread后
--stop-never --show-gtid --show-time --show-all-time --show-thread --ddl --max 0 --debug

# 64f83485-8ec1-11ec-9822-005056a8e9ea:496
INSERT INTO `test`.`test02`(`id`) VALUES(1); # 2024-03-01 11:29:24 # thread_id=2892331

# 64f83485-8ec1-11ec-9822-005056a8e9ea:499
INSERT INTO `test`.`test02`(`id`) VALUES(1); # 2024-03-01 14:27:40 # thread_id=2897475

--ddl 参数不生效啊

测试语句

CREATE TABLE `DATABASECHANGELOGLOCK1` (
  `ID` int(11) NOT NULL,
  `LOCKED` bit(1) NOT NULL,
  `LOCKGRANTED` datetime DEFAULT NULL,
  `LOCKEDBY` varchar(255) DEFAULT NULL,
  PRIMARY KEY (`ID`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 ROW_FORMAT=COMPACT;

INSERT INTO `pdms_hospital`.`DATABASECHANGELOGLOCK1`(`ID`, `LOCKED`, `LOCKGRANTED`, `LOCKEDBY`) VALUES (1, b'0', NULL, NULL);
UPDATE `pdms_hospital`.`DATABASECHANGELOGLOCK1` SET `LOCKED` = b'1', `LOCKGRANTED` = NULL, `LOCKEDBY` = NULL WHERE `ID` = 1;

drop table DATABASECHANGELOGLOCK2;

生成的回滚语句：

DELETE FROM `pdms_hospital`.`DATABASECHANGELOGLOCK1` WHERE `ID`=1; # 2020-09-17 17:15:19
UPDATE `pdms_hospital`.`DATABASECHANGELOGLOCK1` SET `LOCKED`=0 WHERE `ID`=1;

执行的命令：

./bingo2sql -u root -p mysql123 -h 127.0.0.1 -d pdms_hospital -B --ddl true --start-time "$start_time" --stop-time "$end_time" --start-file "$new_binlog_file" > cpcs-mysql/mysql/sqlback/$sql_file

for 循环里面调用 defer cancel() 的调用导致内存泄露，程序OOM

代码段 parser.go

	for {
		if p.cfg.StopNever {
			ctx = context.Background()
		} else {
			ctx, cancel = context.WithTimeout(context.Background(), 10*time.Second)
			defer cancel()  // 此处在 每次循环中并不会被调用 
		}
		// e, err := s.GetEvent(context.Background())
		e, err := s.GetEvent(ctx)
		if err != nil {
			// Try to output all left events
			// events := s.DumpEvents()
			// for _, e := range events {
			//  // e.Dump(os.Stdout)
			//  log.Info("===============")
			//  log.Info(e.Header.EventType)
			// }
			log.Errorf("Get event error: %v\n", err)
			break
		}

pprof head

` ``
go tool pprof http://127.0.0.1:9999/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:9999/debug/pprof/heap
Saved profile in /root/pprof/pprof.bingo2sql.alloc_objects.alloc_space.inuse_objects.inuse_space.019.pb.gz
File: bingo2sql
Type: inuse_space
Time: Jun 26, 2021 at 10:27am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 2.99GB, 97.40% of 3.07GB total
Dropped 40 nodes (cum <= 0.02GB)
Showing top 10 nodes out of 28
flat flat% sum% cum cum%
1.04GB 33.82% 33.82% 1.11GB 36.04% context.WithDeadline
0.94GB 30.54% 64.36% 0.94GB 30.54% context.(*cancelCtx).Done.
0.76GB 24.77% 89.13% 0.76GB 24.77% runtime.systemstack.
0.06GB 1.94% 91.06% 0.07GB 2.22% time.AfterFunc
0.04GB 1.38% 92.45% 0.10GB 3.10% github.com/hanchuanchuan/go-mysql/replication.(*RowsEvent).Decode
0.04GB 1.32% 93.77% 0.16GB 5.10% github.com/hanchuanchuan/go-mysql/replication.(*BinlogParser).parseEvent
0.04GB 1.30% 95.07% 0.05GB 1.67% github.com/hanchuanchuan/go-mysql/packet.(*Conn).ReadPacket
0.03GB 1.06% 96.13% 0.03GB 1.06% time.goFunc
0.02GB 0.73% 96.86% 0.05GB 1.72% github.com/hanchuanchuan/go-mysql/replication.(*RowsEvent).decodeRows
0.02GB 0.54% 97.40% 0.02GB 0.54% github.com/hanchuanchuan/go-mysql/replication.(*BinlogParser).newRowsEvent

能提供解析效率的对比不

先关注大佬的新项目，666

比如说一样是go实现的https://github.com/GoDannyLai/binlog_rollback

bingo2sql 本地解析异常

大佬看看原因

解析成功，但是输出ERR日志

$ ./bingo2sql -hxxxx -Pxxx -uxxx -pxxx -d xx -t xxx,xxx,xxx,xxx --start-file='mysql-bin.000003' --start-time='2020-05-26 20:00:00' --stop-time='2020-05-26 23:50:00' -B --debug > flashback_xxx.sql
INFO[2020-05-27T13:43:36+08:00] create BinlogSyncer with config {2000000111 xxx xxx xxx false false false UTC true 0 0s 0s 0 false false 0} file=binlogsyncer.go line=144
INFO[2020-05-27T13:43:36+08:00] begin to sync binlog from position (mysql-bin.000003, 0) file=binlogsyncer.go line=359
INFO[2020-05-27T13:43:36+08:00] rotate to (mysql-bin.000003, 4) file=binlogsyncer.go line=776
WARN[2020-05-27T13:43:39+08:00] 已超出结束时间 file=parser.go line=2267
INFO[2020-05-27T13:43:39+08:00] 解析完成 file=parser.go line=449
INFO[2020-05-27T13:43:39+08:00] syncer is closing... file=binlogsyncer.go line=175
ERRO[2020-05-27T13:43:39+08:00] close sync with err: sync is been closing... file=binlogstreamer.go line=77
INFO[2020-05-27T13:43:39+08:00] kill last connection id 2230086 file=binlogsyncer.go line=849
INFO[2020-05-27T13:43:39+08:00] syncer is closed file=binlogsyncer.go line=202

-M, --minimal-update这个参数不起作用

我有个update修改了一个表中其中一个字段，利用bingo2sql查看的update语句只有我修改的那个字段，而不是set where部分为表的全部字段，不管改了没改

我以为是-M, --minimal-update，但是我发现加不加这个参数都达不到我的目的，而且加不加参数对输出没任何变化，这个应该怎么办

测试空binlog显示数据

./bingo2sql -h 192.168.60.152 -u ops -p 123456 -d sbtest -B --start-file='mysql-binlog.000002' --minimal-insert=false -o test.sql

mysqlbinlog /home/mysql/data/mysql-binlog.000002

python binlog2sql/binlog2sql/binlog2sql.py -h 192.168.60.152 -u ops -p 123456 -d sbtest -B --start-file='mysql-binlog.000002' > test.sql

ERRO Get event error: context deadline exceeded file=parser.go line=386 啥意思？

使用的是bingo2sql-linux-v1.0.2-25-g74b264a.tar.gz版本，数据库版本mariadb 10.1.48
[root@formysql8 opt]# ./bingo2sql --host=127.0.0.1 -P 3306 --user=root --password=1234qwer -d test --start-time="2020-07-01 16:04:05" --stop-time="2020-12-02 10:50:05" -t user -B --debug
INFO[2020-12-02T11:09:02+08:00] binlog信息 binlogFile=mysql-bin138.000001 file=parser.go line=915 起始时间="2020-12-01 14:03:22"
INFO[2020-12-02T11:09:02+08:00] binlog信息 binlogFile=mysql-bin138.000002 file=parser.go line=915 起始时间="2020-12-01 14:50:46"
INFO[2020-12-02T11:09:02+08:00] binlog信息 binlogFile=mysql-bin138.000003 file=parser.go line=915 起始时间="2020-12-02 10:22:52"
INFO[2020-12-02T11:09:02+08:00] 根据指定的时间段,解析出的开始binlog文件是:mysql-bin138.000001,结束文件是: file=parser.go line=931
INFO[2020-12-02T11:09:02+08:00] create BinlogSyncer with config {2000000111 127.0.0.1 3306 root false false false UTC true 0 0s 0s 0 false false 0} file=binlogsyncer.go line=144
INFO[2020-12-02T11:09:02+08:00] begin to sync binlog from position (mysql-bin138.000001, 0) file=binlogsyncer.go line=359
INFO[2020-12-02T11:09:02+08:00] rotate to (mysql-bin138.000001, 4) file=binlogsyncer.go line=776
INFO[2020-12-02T11:09:02+08:00] rotate to (mysql-bin138.000002, 4) file=binlogsyncer.go line=776
INFO[2020-12-02T11:09:02+08:00] rotate to (mysql-bin138.000003, 4) file=binlogsyncer.go line=776
INFO[2020-12-02T11:09:02+08:00] 超出最新binlog位置 file=parser.go line=502 当前位置=4588 当前文件=mysql-bin138.000003 结束位置=0 结束文件=
DELETE FROM test.user WHERE id=12; # 2020-12-02 10:49:26
DELETE FROM test.user WHERE id=13;
DELETE FROM test.user WHERE id=14;
DELETE FROM test.user WHERE id=15;
DELETE FROM test.user WHERE id=16;
DELETE FROM test.user WHERE id=17;
DELETE FROM test.user WHERE id=18;
DELETE FROM test.user WHERE id=19;
DELETE FROM test.user WHERE id=20;
DELETE FROM test.user WHERE id=21;
UPDATE test.user SET end_time=NULL WHERE id=12;
UPDATE test.user SET end_time=NULL WHERE id=13;
UPDATE test.user SET end_time=NULL WHERE id=14;
UPDATE test.user SET end_time=NULL WHERE id=15;
UPDATE test.user SET end_time=NULL WHERE id=16;
UPDATE test.user SET end_time=NULL WHERE id=17;
UPDATE test.user SET end_time=NULL WHERE id=18;
UPDATE test.user SET end_time=NULL WHERE id=19;
UPDATE test.user SET end_time=NULL WHERE id=20;
UPDATE test.user SET end_time=NULL WHERE id=21;
ERRO[2020-12-02T11:09:12+08:00] Get event error: context deadline exceeded file=parser.go line=386
INFO[2020-12-02T11:09:12+08:00] 解析完成 file=parser.go line=449
INFO[2020-12-02T11:09:12+08:00] syncer is closing... file=binlogsyncer.go line=175
INFO[2020-12-02T11:09:12+08:00] kill last connection id 116 file=binlogsyncer.go line=849
INFO[2020-12-02T11:09:12+08:00] syncer is closed file=binlogsyncer.go line=202
解析倒是出来了，但是有ERRO[2020-12-02T11:09:12+08:00] Get event error: context deadline exceeded file=parser.go line=386 请问这个是啥原因？（其他的解析语句也会出现这个 Get event error: context deadline exceeded file=parser.go的错误提示）

还有就是解析的sql中user表已经delete数据，后面的update已经没有意义了。

取其中一列相关数据

只取id = 1的数据

insert into t (id )values (1);
delete from t id = 2;
delete from t id = 1;

数据库中某些表已经删除后，解析会报错。

使用中发现，如果数据库中某些曾经存在的表已经删除了，工具会在解析中报错，形如：表db.table缺少列!当前列数:0,table的列数7。

解析的文件数据不全

使用同一个binlog文件做解析，缺失了几条insert和update语句，但单独指定--sql-type=insert 又能解析到对应的sql

driver: skip fast-path; continue as if unimplemented

ERRO[2020-03-19T17:27:36+08:00] driver: skip fast-path; continue as if unimplemented file=parser.go line=1043
ERRO[2020-03-19T17:27:37+08:00] close sync with err: sync is been closing... file=binlogstreamer.go line=77
panic: driver: skip fast-path; continue as if unimplemented

goroutine 1 [running]:
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).checkError(0xc000241900, 0xfa8580, 0xc004c22680)
/Users/hanchuanchuan/hcc/bingo2sql/parser.go:1050 +0x24d
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).generateUpdateSQL(0xc000241900, 0xc000128000, 0xc019eea000, 0xc0190202a0, 0xc00035412a, 0xc019ecc001)
/Users/hanchuanchuan/hcc/bingo2sql/parser.go:1373 +0x117c
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).parseSingleEvent(0xc000241900, 0xc0190202a0, 0xc019ece240, 0xc0190202a0, 0x0)
/Users/hanchuanchuan/hcc/bingo2sql/parser.go:2246 +0xa14
github.com/hanchuanchuan/bingo2sql.(*MyBinlogParser).Parser(0xc000241900, 0x0, 0x0)
/Users/hanchuanchuan/hcc/bingo2sql/parser.go:390 +0x543
main.runParse()
/Users/hanchuanchuan/hcc/bingo2sql/cmd/bingo2sql.go:185 +0x3d5
main.main()
/Users/hanchuanchuan/hcc/bingo2sql/cmd/bingo2sql.go:128 +0x1c3