close sync with err: data len 166 < expected 3587

[luoxiaocai91]

hi ,
the version is 1.0.40. mysql version is 5.7.20-18-log Percona Server (GPL), Release 18, Revision 7ce54a6deef.
command:
gh-ost_v1.0.40 --max-load=Threads_running=32 --critical-load=Threads_running=48 --chunk-size=1000 --throttle-control-replicas="xx:xx,xx:xx" --max-lag-millis=1000 --initially-drop-old-table --initially-drop-ghost-table --initially-drop-socket-file --conf="xx.cnf" --host="xx" --port="xx" --database="xx" --table="a" --verbose --alter=" add index idx_base_cust(base_cust_id)" --switch-to-rbr=false --cut-over=default --assume-rbr=true --exact-rowcount=false --default-retries=3 --critical-load-interval-millis=3000 --panic-flag-file=/tmp/ghost.panic.flag.xx.a.6601652 --postpone-cut-over-flag-file=/tmp/ghost.postpone.flag.xx.a.6601652 --throttle-flag-file=/tmp/ghost.throttle.flag.xx.a.6601652 --execute --allow-on-master
the log:

Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 36s(total), 35s(copy); streamer: mysql-bin.000183:4056848; State: migrating; ETA: due
2018-08-09 16:17:37 INFO Reconnecting... Will resume at mysql-bin.000183:907636574
2018/08/09 16:17:37 binlogsyncer.go:75: �[0;37m[info] create BinlogSyncer with config &{99999 mysql xx xx xx xx  false false }�[0m
2018-08-09 16:17:37 INFO Connecting binlog streamer at mysql-bin.000183:4
2018/08/09 16:17:37 binlogsyncer.go:241: �[0;37m[info] begin to sync binlog from position (mysql-bin.000183, 4)�[0m
2018/08/09 16:17:37 binlogsyncer.go:134: �[0;37m[info] register slave for master server 10.xx:xx�[0m
2018/08/09 16:17:37 binlogsyncer.go:568: �[0;37m[info] rotate to (mysql-bin.000183, 4)�[0m
2018-08-09 16:17:37 INFO rotate to next log name: mysql-bin.000183
2018/08/09 16:17:37 binlogstreamer.go:47: �[0;31m[error] close sync with err: data len 166 < expected 3587�[0m
2018-08-09 16:17:37 INFO StreamEvents encountered unexpected error: data len 166 < expected 3587
Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 37s(total), 35s(copy); streamer: mysql-bin.000183:4062381; State: migrating; ETA: due
Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 38s(total), 35s(copy); streamer: mysql-bin.000183:4062381; State: migrating; ETA: due
2018-08-09 16:17:39 ERROR Timeout while waiting for events up to lock
2018-08-09 16:17:39 ERROR 2018-08-09 16:17:39 ERROR Timeout while waiting for events up to lock
2018-08-09 16:17:39 INFO Looking for magic cut-over table
2018-08-09 16:17:39 INFO Will now proceed to drop magic table and unlock tables
2018-08-09 16:17:39 INFO Dropping magic cut-over table
2018-08-09 16:17:39 INFO Dropping magic cut-over table
2018-08-09 16:17:39 INFO Droppping table `xx`.`_a_del`
2018-08-09 16:17:39 INFO Table dropped
2018-08-09 16:17:39 INFO Releasing lock from `xx`.`a`, `xx`.`_a_del`
2018-08-09 16:17:39 INFO Tables unlocked
Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 39s(total), 35s(copy); streamer: mysql-bin.000183:4062381; State: migrating; ETA: due
2018-08-09 16:17:40 INFO Grabbing voluntary lock: gh-ost.8482269.lock
2018-08-09 16:17:40 INFO Setting LOCK timeout as 6 seconds
2018-08-09 16:17:40 INFO Looking for magic cut-over table
2018-08-09 16:17:40 INFO Creating magic cut-over table `xx`.`_a_del`
2018-08-09 16:17:40 INFO Magic cut-over table created
2018-08-09 16:17:40 INFO Locking `xx`.`a`, `xx`.`_a_del`
2018-08-09 16:17:40 INFO Tables locked
2018-08-09 16:17:40 INFO Session locking original & magic tables is 8482269
2018-08-09 16:17:40 INFO Writing changelog state: AllEventsUpToLockProcessed:1533802660582469107
2018-08-09 16:17:40 INFO Waiting for events up to lock
Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 40s(total), 35s(copy); streamer: mysql-bin.000183:4062381; State: migrating; ETA: due
Copy: 1227096/1227096 100.0%; Applied: 2; Backlog: 0/1000; Time: 41s(total), 35s(copy); streamer: mysql-bin.000183:4062381; State: migrating; ETA: due
2018-08-09 16:17:42 FATAL 4 successive failures in streamer reconnect at coordinates mysql-bin.000183:4

the table :

CREATE TABLE `a` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT ,
  `tenant_id` int(10) DEFAULT '0' ,
  `biz_line_id` int(10) NOT NULL DEFAULT '0' ,
  `customer_type_id` int(10) NOT NULL DEFAULT '0' ,
  `base_cust_id` bigint(20) NOT NULL ,
  `cust_id` bigint(20) NOT NULL,
  `sub_biz_line_id` int(10) NOT NULL DEFAULT '0' ,
  `is_deleted` tinyint(1) DEFAULT '0' ,
  `gmt_created` datetime DEFAULT NULL ,
  `creator` int(10) DEFAULT '0' ,
  `gmt_modified` datetime DEFAULT NULL ,
  `modifier` int(10) DEFAULT '0' ,
  PRIMARY KEY (`id`),
  UNIQUE KEY `uk_cust_sub_biz_line` (`cust_id`,`sub_biz_line_id`),
  KEY `idx_sub_biz_line_tenant_type` (`sub_biz_line_id`,`biz_line_id`,`tenant_id`,`customer_type_id`),
  KEY `idx_base_cust` (`base_cust_id`)
) ENGINE=InnoDB AUTO_INCREMENT=1338565 DEFAULT CHARSET=utf8mb4 

I have run this command about 3 times with both release code and the latest master code. Is there and clues about what happened and how to fix it? Thanks!

[shlomi-noach]

Sorry for the late response. I'm not entire sure the sync with err is the cause for what then presents as Timeout while waiting for events up to lock.

On Sep 17th we merged #611 into master, which happened to solve Timeout while waiting for events up to lock in multiple cases. Would you care to test master again please?