Problem with replaying UPDATE or DELETE using key of BINARY(N) ending in `00`'s

[jrgm]

First, thanks for the development and open sourcing of this tool.

However, I was running a migration and left it postponed for a while, and before cutover I noticed that I had some differences between the master table and the gh-ost table involving columns with BINARY(N) type when values end in 00's. Perhaps I was using this incorrectly, but I distilled the problem down to these steps to reproduce. Apologies for the length.

Setup is on AWS RDS, mysql 5.6.40, gh-ost 1.0.46. RDS master is set to binlog_format of MIXED. RDS read replica is set to binlog_format of ROW.

RDS master parameter group settings difference from default:

Parameter           test-rdsparamgroup   default.mysql5.6
---------------------------------------------------------
general_log           1                  <engine-default>
innodb_file_format    Barracuda          <engine-default>
innodb_flush_method   O_DIRECT           <system>
log_output            FILE               TABLE
long_query_time       0.9                <engine-default>
slow_query_log        1                  <engine-default>

Steps to reproduce:

1. Create a new test database with a single test table.

DROP DATABASE IF EXISTS `test_ghost`;
CREATE DATABASE `test_ghost` DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_bin;
USE `test_ghost`;

DROP TABLE IF EXISTS `_test_table_gho`;
DROP TABLE IF EXISTS `_test_table_ghc`;
DROP TABLE IF EXISTS `test_table`;
CREATE TABLE `test_table` (
  `id` binary(16) NOT NULL,
  `info` varchar(255) COLLATE utf8_unicode_ci NOT NULL,
  `data` binary(8) NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `info` (`info`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;

INSERT INTO `test_table` (id, info, data) VALUES
 (X'11ffffffffffffffffffffffffffff00', 'item 1', X'11ffffffffffffff'), -- id ends in 00
 (X'22ffffffffffffffffffffffffffff00', 'item 2', X'22ffffffffffffff'), -- id ends in 00
 (X'33ffffffffffffffffffffffffffffff', 'item 3', X'33ffffffffffffff'),
 (X'44ffffffffffffffffffffffffffffff', 'item 4', X'44ffffffffffffff'),
 (X'55ffffffffffffffffffffffffffffff', 'item 5', X'55ffffffffffffff'),
 (X'99ffffffffffffffffffffffffffffff', 'item 9', X'99ffffffffffff00'); -- data ends in 00

SELECT HEX(id) AS id, info, HEX(data) AS data FROM test_table;

mysql -NBe 'source ./bin/create-test-table.sql'

2. Run a migration to add a new column to the test table and leave it postponed.

#!/usr/bin/env sh

./gh-ost \
  --execute \
  --max-load=Threads_running=25                                                                  \
  --critical-load=Threads_running=1000                                                           \
  --assume-rbr                                                                                   \
  --chunk-size=1000                                                                              \
  --max-lag-millis=15000                                                                         \
  --user='the_user'                                                                              \
  --password='the-password'                                                                      \
  --host='the-slave-hostname'                                                                    \
  --assume-master-host='the-master-hostname'                                                     \
  --database='test_ghost'                                                                        \
  --table='test_table'                                                                           \
  --verbose                                                                                      \
  --alter='ADD COLUMN testColumn BIGINT UNSIGNED DEFAULT NULL, ALGORITHM = INPLACE, LOCK = NONE' \
  --cut-over=default                                                                             \
  --exact-rowcount                                                                               \
  --concurrent-rowcount                                                                          \
  --default-retries=120                                                                          \
  --panic-flag-file=/tmp/ghost.panic.flag                                                        \
  --postpone-cut-over-flag-file=/tmp/ghost.postpone.flag

I'll add the gh-ost output in a further comment below.

3. Compare the test table to the ghost table.

#!/usr/bin/env sh

mysql test_ghost -NBe 'SELECT HEX(id) AS id, info, HEX(data) AS data FROM test_table'      > /tmp/test_table.dump
mysql test_ghost -NBe 'SELECT HEX(id) AS id, info, HEX(data) AS data FROM _test_table_gho' > /tmp/_test_table_gho.dump

diff -U8 /tmp/test_table.dump /tmp/_test_table_gho.dump
md5sum /tmp/test_table.dump /tmp/_test_table_gho.dump

$ sh ./bin/compare-test-table.sh
689e658d47fd8b0e987f8356446aa05a  /tmp/test_table.dump
689e658d47fd8b0e987f8356446aa05a  /tmp/_test_table_gho.dump

After the initial migration, everything matches between the two tables.

4. Now do an INSERT, UPDATE, and DELETE with a BINARY(16) primary key ending in 00.

-- FAIL 1. is an existing row with `id` ending in `00` mirrored correctly if deleted from master table
-- This row was not deleted from the ghost table.
DELETE FROM `test_table` WHERE id = X'11ffffffffffffffffffffffffffff00';

-- FAIL 2. is an existing row with `id` ending in `00` mirrored correctly if updated on master table
-- The ghost table was not updated
UPDATE `test_table` SET info = 'item 2++' WHERE id = X'22ffffffffffffffffffffffffffff00';

-- PASS 3. is an existing row with `id` NOT ending in `00` but `data` ending in `00` mirrored correctly if updated on master table
UPDATE `test_table` SET info = 'item 3++', data = X'33ffffffffffff00' WHERE id = X'33ffffffffffffffffffffffffffffff';

-- PASS 4. is an existing row with `id` NOT ending in `00` mirrored correctly if deleted from master table
DELETE FROM `test_table` WHERE id = X'44ffffffffffffffffffffffffffffff';

-- PASS 5. is an existing row with `id` NOT ending in `00` mirrored correctly if updated on master table
UPDATE `test_table` SET info = 'item 5++', data = X'55ffffffffffffee'  WHERE id = X'55ffffffffffffffffffffffffffffff';

-- PASS 6. is a row with `id` ending in `00` mirrored correctly if inserted into master table
-- but maybe lucky with auto-padding of replace into?
INSERT INTO `test_table` (id, info, data) VALUES (X'66ffffffffffffffffffffffffffff00', 'item 6', X'66ffffffffffffff');

-- PASS 7. is a row with `id` NOT ending in `00` but `data` ending in `00` mirrored correctly if inserted into master table
INSERT INTO `test_table` (id, info, data) VALUES (X'77ffffffffffffffffffffffffffffff', 'item 7', X'77ffffffffffff00');

-- PASS 8. is a row with `id` NOT ending in `00` mirrored correctly if inserted into master table
INSERT INTO `test_table` (id, info, data) VALUES (X'88ffffffffffffffffffffffffffffff', 'item 8', X'88ffffffffffffff');

mysql test_ghost -e 'source ./bin/change-test-table.sql'

5. Re-compare the test table to the ghost table. There are two differences now:

1. The deletion using a BINARY(16) key has not been done on the gh-ost table.
2. The update using a BINARY(16) key has not been done on the gh-ost table.

$ sh ./bin/compare-test-table.sh
--- /tmp/test_table.dump        2018-10-29 01:07:39.349169830 +0000
+++ /tmp/_test_table_gho.dump   2018-10-29 01:07:39.357169511 +0000
@@ -1,7 +1,8 @@
-22FFFFFFFFFFFFFFFFFFFFFFFFFFFF00       item 2++        22FFFFFFFFFFFFFF
+11FFFFFFFFFFFFFFFFFFFFFFFFFFFF00       item 1  11FFFFFFFFFFFFFF
+22FFFFFFFFFFFFFFFFFFFFFFFFFFFF00       item 2  22FFFFFFFFFFFFFF
 33FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF       item 3++        33FFFFFFFFFFFF00
 55FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF       item 5++        55FFFFFFFFFFFFEE
 66FFFFFFFFFFFFFFFFFFFFFFFFFFFF00       item 6  66FFFFFFFFFFFFFF
 77FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF       item 7  77FFFFFFFFFFFF00
 88FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF       item 8  88FFFFFFFFFFFFFF
 99FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF       item 9  99FFFFFFFFFFFF00
8a363b2e25dceb1928df81b1ef48bba4  /tmp/test_table.dump
d65973974ef97bb8b7b95caca4bce937  /tmp/_test_table_gho.dump

6. Remove the /tmp/ghost.postpone.flag file to complete the migration. A compare of the test_table to the test_table_del shows the same difference as above.

I dumped the slave and master binary log with:

./mysql-5.6.42-linux-glibc2.12-x86_64/bin/mysqlbinlog \
  --no-defaults \
  --set-charset=utf8mb4 \
  --base64-output=decode-rows \
  --verbose \
  /path/to/mysql-bin-changelog.NNNNNN

On the slave's ROW binlog, for the key rows changing test_ghost.test_table, I see:

# at 135553
#181029  1:07:25 server id 1879241316  end_log_pos 135620 CRC32 0xf4be343c      Table_map: `test_ghost`.`test_table` mapped to number 1410
# at 135620
#181029  1:07:25 server id 1879241316  end_log_pos 135689 CRC32 0xd5a24b62      Delete_rows: table id 1410 flags: STMT_END_F
### DELETE FROM `test_ghost`.`test_table`
### WHERE
###   @1='\x11\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
###   @2='item 1'
###   @3='\x11\377\377\377\377\377\377\377'
# at 135689
#181029  1:07:25 server id 1879241316  end_log_pos 135720 CRC32 0x045e1201      Xid = 3491148
COMMIT/*!*/;
# at 135720
#181029  1:07:25 server id 1879241316  end_log_pos 135798 CRC32 0xaffbabb7      Query   thread_id=4947  exec_time=0     error_code=0
SET TIMESTAMP=1540775245/*!*/;
BEGIN
/*!*/;
# at 135798
#181029  1:07:25 server id 1879241316  end_log_pos 135865 CRC32 0x7728f223      Table_map: `test_ghost`.`test_table` mapped to number 1410
# at 135865
#181029  1:07:25 server id 1879241316  end_log_pos 135971 CRC32 0xdf24d1dc      Update_rows: table id 1410 flags: STMT_END_F
### UPDATE `test_ghost`.`test_table`
### WHERE
###   @1='"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
###   @2='item 2'
###   @3='"\377\377\377\377\377\377\377'
### SET
###   @1='"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
###   @2='item 2++'
###   @3='"\377\377\377\377\377\377\377'
# at 135971
#181029  1:07:25 server id 1879241316  end_log_pos 136002 CRC32 0xc507994b      Xid = 3491150
COMMIT/*!*/;

On the master's MIXED binlog, for the key rows changing test_ghost.test_table_gho, I see:

# at 150176
#181029  1:07:26 server id 1879241316  end_log_pos 150401 CRC32 0x1de6ff71      Query   thread_id=4943  exec_time=0     error_code=0
SET TIMESTAMP=1540775246/*!*/;
delete /* gh-ost `test_ghost`.`_test_table_gho` */
                                from
                                        `test_ghost`.`_test_table_gho`
                                where
                                        ((`id` = '\021\377\377\377\377\377\377\377\377\377\377\377\377\377\377'))
/*!*/;
# at 150401
#181029  1:07:26 server id 1879241316  end_log_pos 150696 CRC32 0x21b0348e      Query   thread_id=4943  exec_time=0     error_code=0
SET TIMESTAMP=1540775246/*!*/;
update /* gh-ost `test_ghost`.`_test_table_gho` */
                                        `test_ghost`.`_test_table_gho`
                                set
                                        `id`='\"\377\377\377\377\377\377\377\377\377\377\377\377\377\377', `info`='item 2++', `data`='\"\377\377\377\377\377\377\377'
                                where
                                        ((`id` = '\"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'))
/*!*/;

(Note: I changed the actual binary values above to the four character sequence '\377' for readability. Otherwise putting this into github was converting them to '???????????????'.)

Note in the above the id keys used are, in hex, are X'11FFFFFFFFFFFFFFFFFFFFFFFFFFFF' for the DELETE, and X'22FFFFFFFFFFFFFFFFFFFFFFFFFFFF' which are both 15 bytes long, not 16 bytes. The WHERE condition fails to match in both statements, and the DELETE and UPDATE change nothing in the ghost table.

[jrgm]

$ sh ./bin/migrate-test-table.sh
2018-10-29 01:06:48 INFO starting gh-ost 1.0.46
2018-10-29 01:06:48 INFO Migrating `test_ghost`.`test_table`
2018-10-29 01:06:48 INFO connection validated on the-slave-hostname:3306
2018-10-29 01:06:48 INFO User has REPLICATION CLIENT, REPLICATION SLAVE privileges, and has ALL privileges on `test_ghost`.*
2018-10-29 01:06:48 INFO binary logs validated on the-slave-hostname:3306
2018-10-29 01:06:48 INFO Inspector initiated on ip-10-1-4-174:3306, version 5.6.40-log
2018-10-29 01:06:48 INFO Table found. Engine=InnoDB
2018-10-29 01:06:48 INFO Estimated number of rows via EXPLAIN: 6
2018-10-29 01:06:48 INFO Master forced to be the-master-hostname:3306
2018-10-29 01:06:48 INFO log_slave_updates validated on the-slave-hostname:3306
2018-10-29 01:06:48 INFO connection validated on the-slave-hostname:3306
2018/10/29 01:06:48 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql the-slave-hostname 3306 the_user   false false <nil>}
2018-10-29 01:06:48 INFO Connecting binlog streamer at mysql-bin-changelog.001564:2346
2018/10/29 01:06:48 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin-changelog.001564, 2346)
2018/10/29 01:06:48 binlogsyncer.go:139: [info] register slave for master server the-slave-hostname:3306
2018/10/29 01:06:48 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001564, 2346)
2018-10-29 01:06:48 INFO rotate to next log name: mysql-bin-changelog.001564
2018-10-29 01:06:48 INFO connection validated on the-master-hostname:3306
2018-10-29 01:06:48 INFO connection validated on the-master-hostname:3306
2018-10-29 01:06:48 INFO will use time_zone='UTC' on applier
2018-10-29 01:06:48 INFO Examining table structure on applier
2018-10-29 01:06:48 INFO Applier initiated on ip-10-1-1-147:3306, version 5.6.40-log
2018-10-29 01:06:48 INFO Dropping table `test_ghost`.`_test_table_ghc`
2018-10-29 01:06:48 INFO Table dropped
2018-10-29 01:06:48 INFO Creating changelog table `test_ghost`.`_test_table_ghc`
2018-10-29 01:06:48 INFO Changelog table created
2018-10-29 01:06:48 INFO Creating ghost table `test_ghost`.`_test_table_gho`
2018-10-29 01:06:48 INFO Ghost table created
2018-10-29 01:06:48 INFO Altering ghost table `test_ghost`.`_test_table_gho`
2018-10-29 01:06:48 INFO Ghost table altered
2018-10-29 01:06:48 INFO Waiting for ghost table to be migrated. Current lag is 0s
2018-10-29 01:06:48 INFO Intercepted changelog state GhostTableMigrated
2018-10-29 01:06:48 INFO Handled changelog state GhostTableMigrated
2018-10-29 01:06:48 INFO Chosen shared unique key is PRIMARY
2018-10-29 01:06:48 INFO Shared columns are id,info,data
2018-10-29 01:06:48 INFO Listening on unix socket file: /tmp/gh-ost.test_ghost.test_table.sock
2018-10-29 01:06:48 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on
2018-10-29 01:06:48 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while
2018-10-29 01:06:48 INFO Migration min values: [??????????????]
2018-10-29 01:06:48 INFO Exact number of rows via COUNT: 6
2018-10-29 01:06:48 INFO Migration max values: [????????????????]
2018-10-29 01:06:48 INFO Waiting for first throttle metrics to be collected
2018-10-29 01:06:48 INFO First throttle metrics collected
# Migrating `test_ghost`.`test_table`; Ghost table is `test_ghost`.`_test_table_gho`
# Migrating ip-10-1-1-147:3306; inspecting ip-10-1-4-174:3306; executing on ip-172-31-57-98
# Migration started at Mon Oct 29 01:06:48 +0000 2018
# chunk-size: 1000; max-lag-millis: 15000ms; dml-batch-size: 10; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag [set]
# panic-flag-file: /tmp/ghost.panic.flag
# Serving on unix socket: /tmp/gh-ost.test_ghost.test_table.sock
Copy: 0/6 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin-changelog.001564:4067; State: migrating; ETA: N/A
Copy: 0/6 0.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin-changelog.001564:7575; State: migrating; ETA: N/A
2018-10-29 01:06:49 INFO Row copy complete
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin-changelog.001564:7575; State: migrating; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin-changelog.001564:11882; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 3s(total), 1s(copy); streamer: mysql-bin-changelog.001564:15401; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 4s(total), 1s(copy); streamer: mysql-bin-changelog.001564:18918; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 5s(total), 1s(copy); streamer: mysql-bin-changelog.001564:22439; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 6s(total), 1s(copy); streamer: mysql-bin-changelog.001564:25956; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 7s(total), 1s(copy); streamer: mysql-bin-changelog.001564:29475; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 8s(total), 1s(copy); streamer: mysql-bin-changelog.001564:32993; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 9s(total), 1s(copy); streamer: mysql-bin-changelog.001564:36513; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 10s(total), 1s(copy); streamer: mysql-bin-changelog.001564:40034; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 11s(total), 1s(copy); streamer: mysql-bin-changelog.001564:43552; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 12s(total), 1s(copy); streamer: mysql-bin-changelog.001564:47074; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 13s(total), 1s(copy); streamer: mysql-bin-changelog.001564:50592; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 14s(total), 1s(copy); streamer: mysql-bin-changelog.001564:54112; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 15s(total), 1s(copy); streamer: mysql-bin-changelog.001564:57632; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 16s(total), 1s(copy); streamer: mysql-bin-changelog.001564:61148; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 17s(total), 1s(copy); streamer: mysql-bin-changelog.001564:64668; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 18s(total), 1s(copy); streamer: mysql-bin-changelog.001564:68187; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 19s(total), 1s(copy); streamer: mysql-bin-changelog.001564:71706; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 20s(total), 1s(copy); streamer: mysql-bin-changelog.001564:75226; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 21s(total), 1s(copy); streamer: mysql-bin-changelog.001564:78748; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 22s(total), 1s(copy); streamer: mysql-bin-changelog.001564:82268; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 23s(total), 1s(copy); streamer: mysql-bin-changelog.001564:85790; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 24s(total), 1s(copy); streamer: mysql-bin-changelog.001564:89310; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 25s(total), 1s(copy); streamer: mysql-bin-changelog.001564:92832; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 26s(total), 1s(copy); streamer: mysql-bin-changelog.001564:96352; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 27s(total), 1s(copy); streamer: mysql-bin-changelog.001564:99870; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 28s(total), 1s(copy); streamer: mysql-bin-changelog.001564:103392; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 29s(total), 1s(copy); streamer: mysql-bin-changelog.001564:106915; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 30s(total), 1s(copy); streamer: mysql-bin-changelog.001564:110438; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 31s(total), 1s(copy); streamer: mysql-bin-changelog.001564:113954; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 32s(total), 1s(copy); streamer: mysql-bin-changelog.001564:117472; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 33s(total), 1s(copy); streamer: mysql-bin-changelog.001564:120989; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 34s(total), 1s(copy); streamer: mysql-bin-changelog.001564:124510; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 35s(total), 1s(copy); streamer: mysql-bin-changelog.001564:128031; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 36s(total), 1s(copy); streamer: mysql-bin-changelog.001564:131552; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 0/1000; Time: 37s(total), 1s(copy); streamer: mysql-bin-changelog.001564:135072; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 0; Backlog: 8/1000; Time: 38s(total), 1s(copy); streamer: mysql-bin-changelog.001564:140668; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 39s(total), 1s(copy); streamer: mysql-bin-changelog.001564:145229; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 40s(total), 1s(copy); streamer: mysql-bin-changelog.001564:148750; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 41s(total), 1s(copy); streamer: mysql-bin-changelog.001564:152271; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 42s(total), 1s(copy); streamer: mysql-bin-changelog.001564:155792; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 43s(total), 1s(copy); streamer: mysql-bin-changelog.001564:159311; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 44s(total), 1s(copy); streamer: mysql-bin-changelog.001564:162834; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 45s(total), 1s(copy); streamer: mysql-bin-changelog.001564:166353; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 46s(total), 1s(copy); streamer: mysql-bin-changelog.001564:169874; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 47s(total), 1s(copy); streamer: mysql-bin-changelog.001564:173396; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 48s(total), 1s(copy); streamer: mysql-bin-changelog.001564:176916; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 49s(total), 1s(copy); streamer: mysql-bin-changelog.001564:180435; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 50s(total), 1s(copy); streamer: mysql-bin-changelog.001564:183956; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 51s(total), 1s(copy); streamer: mysql-bin-changelog.001564:187477; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 52s(total), 1s(copy); streamer: mysql-bin-changelog.001564:190997; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 53s(total), 1s(copy); streamer: mysql-bin-changelog.001564:194515; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 54s(total), 1s(copy); streamer: mysql-bin-changelog.001564:198036; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 55s(total), 1s(copy); streamer: mysql-bin-changelog.001564:201559; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 56s(total), 1s(copy); streamer: mysql-bin-changelog.001564:205082; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 57s(total), 1s(copy); streamer: mysql-bin-changelog.001564:208605; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 58s(total), 1s(copy); streamer: mysql-bin-changelog.001564:212126; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 59s(total), 1s(copy); streamer: mysql-bin-changelog.001564:215645; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m0s(total), 1s(copy); streamer: mysql-bin-changelog.001564:219168; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m5s(total), 1s(copy); streamer: mysql-bin-changelog.001564:235170; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m10s(total), 1s(copy); streamer: mysql-bin-changelog.001564:251154; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m15s(total), 1s(copy); streamer: mysql-bin-changelog.001564:267151; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m20s(total), 1s(copy); streamer: mysql-bin-changelog.001564:283138; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m25s(total), 1s(copy); streamer: mysql-bin-changelog.001564:299133; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m30s(total), 1s(copy); streamer: mysql-bin-changelog.001564:315134; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m35s(total), 1s(copy); streamer: mysql-bin-changelog.001564:331132; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m40s(total), 1s(copy); streamer: mysql-bin-changelog.001564:347122; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m45s(total), 1s(copy); streamer: mysql-bin-changelog.001564:363112; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m50s(total), 1s(copy); streamer: mysql-bin-changelog.001564:379114; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 1m55s(total), 1s(copy); streamer: mysql-bin-changelog.001564:394805; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m0s(total), 1s(copy); streamer: mysql-bin-changelog.001564:411114; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m5s(total), 1s(copy); streamer: mysql-bin-changelog.001564:427109; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m10s(total), 1s(copy); streamer: mysql-bin-changelog.001564:443104; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m15s(total), 1s(copy); streamer: mysql-bin-changelog.001564:459101; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m20s(total), 1s(copy); streamer: mysql-bin-changelog.001564:475100; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m25s(total), 1s(copy); streamer: mysql-bin-changelog.001564:491097; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m30s(total), 1s(copy); streamer: mysql-bin-changelog.001564:507090; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m35s(total), 1s(copy); streamer: mysql-bin-changelog.001564:523083; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m40s(total), 1s(copy); streamer: mysql-bin-changelog.001564:539084; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m45s(total), 1s(copy); streamer: mysql-bin-changelog.001564:555081; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m50s(total), 1s(copy); streamer: mysql-bin-changelog.001564:571064; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 2m55s(total), 1s(copy); streamer: mysql-bin-changelog.001564:587049; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 3m0s(total), 1s(copy); streamer: mysql-bin-changelog.001564:603042; State: postponing cut-over; ETA: due
2018/10/29 01:10:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001565, 4)
2018/10/29 01:10:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001565, 4)
2018-10-29 01:10:00 INFO rotate to next log name: mysql-bin-changelog.001565
2018-10-29 01:10:00 INFO rotate to next log name: mysql-bin-changelog.001565
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 3m30s(total), 1s(copy); streamer: mysql-bin-changelog.001565:58746; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 4m0s(total), 1s(copy); streamer: mysql-bin-changelog.001565:152899; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 4m30s(total), 1s(copy); streamer: mysql-bin-changelog.001565:246855; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 5m0s(total), 1s(copy); streamer: mysql-bin-changelog.001565:340796; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 5m30s(total), 1s(copy); streamer: mysql-bin-changelog.001565:434718; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 6m0s(total), 1s(copy); streamer: mysql-bin-changelog.001565:528647; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 6m30s(total), 1s(copy); streamer: mysql-bin-changelog.001565:622589; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 7m0s(total), 1s(copy); streamer: mysql-bin-changelog.001565:716531; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 7m30s(total), 1s(copy); streamer: mysql-bin-changelog.001565:810464; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 8m0s(total), 1s(copy); streamer: mysql-bin-changelog.001565:904408; State: postponing cut-over; ETA: due
2018/10/29 01:15:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001566, 4)
2018/10/29 01:15:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001566, 4)
2018-10-29 01:15:00 INFO rotate to next log name: mysql-bin-changelog.001566
2018-10-29 01:15:00 INFO rotate to next log name: mysql-bin-changelog.001566
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 8m30s(total), 1s(copy); streamer: mysql-bin-changelog.001566:58726; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 9m0s(total), 1s(copy); streamer: mysql-bin-changelog.001566:152893; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 9m30s(total), 1s(copy); streamer: mysql-bin-changelog.001566:246833; State: postponing cut-over; ETA: due
# Migrating `test_ghost`.`test_table`; Ghost table is `test_ghost`.`_test_table_gho`
# Migrating ip-10-1-1-147:3306; inspecting ip-10-1-4-174:3306; executing on ip-172-31-57-98
# Migration started at Mon Oct 29 01:06:48 +0000 2018
# chunk-size: 1000; max-lag-millis: 15000ms; dml-batch-size: 10; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag [set]
# panic-flag-file: /tmp/ghost.panic.flag
# Serving on unix socket: /tmp/gh-ost.test_ghost.test_table.sock
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 10m0s(total), 1s(copy); streamer: mysql-bin-changelog.001566:340770; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 10m30s(total), 1s(copy); streamer: mysql-bin-changelog.001566:434734; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 11m0s(total), 1s(copy); streamer: mysql-bin-changelog.001566:528693; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 11m30s(total), 1s(copy); streamer: mysql-bin-changelog.001566:622634; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 12m0s(total), 1s(copy); streamer: mysql-bin-changelog.001566:716568; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 12m30s(total), 1s(copy); streamer: mysql-bin-changelog.001566:812168; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 13m0s(total), 1s(copy); streamer: mysql-bin-changelog.001566:906099; State: postponing cut-over; ETA: due
2018/10/29 01:20:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001567, 4)
2018/10/29 01:20:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001567, 4)
2018-10-29 01:20:00 INFO rotate to next log name: mysql-bin-changelog.001567
2018-10-29 01:20:00 INFO rotate to next log name: mysql-bin-changelog.001567
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 13m30s(total), 1s(copy); streamer: mysql-bin-changelog.001567:58413; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 14m0s(total), 1s(copy); streamer: mysql-bin-changelog.001567:152595; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 14m30s(total), 1s(copy); streamer: mysql-bin-changelog.001567:246536; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 15m0s(total), 1s(copy); streamer: mysql-bin-changelog.001567:340462; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 15m30s(total), 1s(copy); streamer: mysql-bin-changelog.001567:434389; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 16m0s(total), 1s(copy); streamer: mysql-bin-changelog.001567:528323; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 16m30s(total), 1s(copy); streamer: mysql-bin-changelog.001567:622266; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 17m0s(total), 1s(copy); streamer: mysql-bin-changelog.001567:716210; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 17m30s(total), 1s(copy); streamer: mysql-bin-changelog.001567:810152; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 18m0s(total), 1s(copy); streamer: mysql-bin-changelog.001567:904087; State: postponing cut-over; ETA: due
2018/10/29 01:25:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001568, 4)
2018/10/29 01:25:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001568, 4)
2018-10-29 01:25:00 INFO rotate to next log name: mysql-bin-changelog.001568
2018-10-29 01:25:00 INFO rotate to next log name: mysql-bin-changelog.001568
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 18m30s(total), 1s(copy); streamer: mysql-bin-changelog.001568:58752; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 19m0s(total), 1s(copy); streamer: mysql-bin-changelog.001568:152687; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 19m30s(total), 1s(copy); streamer: mysql-bin-changelog.001568:246859; State: postponing cut-over; ETA: due
# Migrating `test_ghost`.`test_table`; Ghost table is `test_ghost`.`_test_table_gho`
# Migrating ip-10-1-1-147:3306; inspecting ip-10-1-4-174:3306; executing on ip-172-31-57-98
# Migration started at Mon Oct 29 01:06:48 +0000 2018
# chunk-size: 1000; max-lag-millis: 15000ms; dml-batch-size: 10; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag [set]
# panic-flag-file: /tmp/ghost.panic.flag
# Serving on unix socket: /tmp/gh-ost.test_ghost.test_table.sock
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 20m0s(total), 1s(copy); streamer: mysql-bin-changelog.001568:340793; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 20m30s(total), 1s(copy); streamer: mysql-bin-changelog.001568:434731; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 21m0s(total), 1s(copy); streamer: mysql-bin-changelog.001568:528647; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 21m30s(total), 1s(copy); streamer: mysql-bin-changelog.001568:622579; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 22m0s(total), 1s(copy); streamer: mysql-bin-changelog.001568:716519; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 22m30s(total), 1s(copy); streamer: mysql-bin-changelog.001568:810462; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 23m0s(total), 1s(copy); streamer: mysql-bin-changelog.001568:904396; State: postponing cut-over; ETA: due
2018/10/29 01:30:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001569, 4)
2018/10/29 01:30:00 binlogsyncer.go:573: [info] rotate to (mysql-bin-changelog.001569, 4)
2018-10-29 01:30:00 INFO rotate to next log name: mysql-bin-changelog.001569
2018-10-29 01:30:00 INFO rotate to next log name: mysql-bin-changelog.001569
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 23m30s(total), 1s(copy); streamer: mysql-bin-changelog.001569:58731; State: postponing cut-over; ETA: due
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 24m0s(total), 1s(copy); streamer: mysql-bin-changelog.001569:152673; State: postponing cut-over; ETA: due
2018-10-29 01:30:55 INFO Grabbing voluntary lock: gh-ost.4941.lock
2018-10-29 01:30:55 INFO Setting LOCK timeout as 6 seconds
2018-10-29 01:30:55 INFO Looking for magic cut-over table
2018-10-29 01:30:55 INFO Creating magic cut-over table `test_ghost`.`_test_table_del`
2018-10-29 01:30:55 INFO Magic cut-over table created
2018-10-29 01:30:55 INFO Locking `test_ghost`.`test_table`, `test_ghost`.`_test_table_del`
2018-10-29 01:30:55 INFO Tables locked
2018-10-29 01:30:55 INFO Session locking original & magic tables is 4941
2018-10-29 01:30:55 INFO Writing changelog state: AllEventsUpToLockProcessed:1540776655075457399
2018-10-29 01:30:55 INFO Waiting for events up to lock
2018-10-29 01:30:55 INFO Intercepted changelog state AllEventsUpToLockProcessed
2018-10-29 01:30:55 INFO Handled changelog state AllEventsUpToLockProcessed
2018-10-29 01:30:56 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1540776655075457399
2018-10-29 01:30:56 INFO Done waiting for events up to lock; duration=966.387359ms
# Migrating `test_ghost`.`test_table`; Ghost table is `test_ghost`.`_test_table_gho`
# Migrating ip-10-1-1-147:3306; inspecting ip-10-1-4-174:3306; executing on ip-172-31-57-98
# Migration started at Mon Oct 29 01:06:48 +0000 2018
# chunk-size: 1000; max-lag-millis: 15000ms; dml-batch-size: 10; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag 
# panic-flag-file: /tmp/ghost.panic.flag
# Serving on unix socket: /tmp/gh-ost.test_ghost.test_table.sock
Copy: 6/6 100.0%; Applied: 8; Backlog: 0/1000; Time: 24m7s(total), 1s(copy); streamer: mysql-bin-changelog.001569:176348; State: migrating; ETA: due
2018-10-29 01:30:56 INFO Setting RENAME timeout as 3 seconds
2018-10-29 01:30:56 INFO Session renaming tables is 4954
2018-10-29 01:30:56 INFO Issuing and expecting this to block: rename /* gh-ost */ table `test_ghost`.`test_table` to `test_ghost`.`_test_table_del`, `test_ghost`.`_test_table_gho` to `test_ghost`.`test_table`
2018-10-29 01:30:56 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place (though I don't strictly have to)
2018-10-29 01:30:56 INFO Checking session lock: gh-ost.4941.lock
2018-10-29 01:30:56 INFO Connection holding lock on original table still exists
2018-10-29 01:30:56 INFO Will now proceed to drop magic table and unlock tables
2018-10-29 01:30:56 INFO Dropping magic cut-over table
2018-10-29 01:30:56 INFO Releasing lock from `test_ghost`.`test_table`, `test_ghost`.`_test_table_del`
2018-10-29 01:30:56 INFO Tables unlocked
2018-10-29 01:30:56 INFO Tables renamed
2018-10-29 01:30:56 INFO Lock & rename duration: 1.021151836s. During this time, queries on `test_table` were blocked
2018-10-29 01:30:56 INFO Looking for magic cut-over table
2018/10/29 01:30:56 binlogsyncer.go:107: [info] syncer is closing... 
2018/10/29 01:30:56 binlogstreamer.go:47: [error] close sync with err: sync is been closing...
2018/10/29 01:30:56 binlogsyncer.go:122: [info] syncer is closed 
2018-10-29 01:30:56 INFO Closed streamer connection. err=<nil>
2018-10-29 01:30:56 INFO Dropping table `test_ghost`.`_test_table_ghc`
2018-10-29 01:30:56 INFO Table dropped
2018-10-29 01:30:56 INFO Am not dropping old table because I want this operation to be as live as possible. If you insist I should do it, please add `--ok-to-drop-table` next time. But I prefer you do not. To drop the old table, issue:
2018-10-29 01:30:56 INFO -- drop table `test_ghost`.`_test_table_del`
2018-10-29 01:30:56 INFO Done migrating `test_ghost`.`test_table`
2018-10-29 01:30:56 INFO Removing socket file: /tmp/gh-ost.test_ghost.test_table.sock
2018-10-29 01:30:56 INFO Tearing down inspector
2018-10-29 01:30:56 INFO Tearing down applier
2018-10-29 01:30:56 INFO Tearing down streamer
2018-10-29 01:30:56 INFO Tearing down throttler
# Done

[shlomi-noach]

Thank you for this elaborate bug report. I'm trying to reproduce the behavior by adding explicit BINARY tests. Can you please take a look at https://github.com/github/gh-ost/pull/655 ? In https://github.com/github/gh-ost/pull/655 I copied your exact setup, but I'm unable to reproduce the error.

• I'm currently testing on MySQL 5.7.17. 5.6 tests coming up shortly.
• While the test suite uses standard diff on column values, I did double check via select HEX(id) AS id, info, HEX(data) AS data from gh_ost_test and select HEX(id) AS id, info, HEX(data) AS data from _gh_ost_test_gho.

[shlomi-noach]

5.7, 5.6, 5.5 tests all pass.

Can you please clarify if the problem only happens on a MIXED-ROW combination? Or does it also happen when all servers are ROW?

[jrgm]

Hi, thanks for the response. I had a very busy day today, and couldn't get back to this, but I will review your test and try again with master and read replica slave set to ROW tomorrow.

[shlomi-noach]

Take your time. I'm having extremely busy days myself.

[jrgm]

Hi. I can imagine you have had a busy couple of weeks. Thanks for getting things safe and back online.

So I set the RDS master to have binlog_format of ROW. With that, I can still reproduce my issue.

Focusing only on the DELETE part of the issue, these are simpler steps to reproduce.

1. Create the test table.

DROP DATABASE IF EXISTS `test_ghost`;
CREATE DATABASE `test_ghost`;
USE `test_ghost`;
CREATE TABLE `test_table` (`id` binary(2) NOT NULL,  PRIMARY KEY (`id`)) ENGINE=InnoDB;
INSERT INTO `test_table` (id) VALUES (X'ff00');
SELECT HEX(id) AS id FROM test_table;

2. Start the migration with the command provided above.

3. On the master, delete the only row by primary key.

DELETE FROM `test_table` WHERE id = X'ff00';

4. On the master, after pausing to let replication/gh-ost round-trip, do:

MySQL [test_ghost]> SELECT HEX(id) AS id FROM _test_table_gho;
+------+
| id   |
+------+
| FF00 |
+------+
1 row in set (0.01 sec)

5. Inspect the binary and query logs.

In the query log on the master I can see:

181102  1:40:25  6471 Query START TRANSACTION
     6471 Query SET
      SESSION time_zone = '+00:00',
      sql_mode = CONCAT(@@session.sql_mode, ',STRICT_ALL_TABLES')
     6471 Query delete /* gh-ost `test_ghost`.`_test_table_gho` */
        from
          `test_ghost`.`_test_table_gho`
        where
          ((`id` = X'FF'))        <---- Note: X'FF', not X'FF00'
     6471 Query COMMIT

(Note: the value in the where is actually a binary value, not X'FF', but pasting in here will make the value '?')

In the decode of the master's binary log, there is no corresponding DELETE on _test_table_gho.

Why? Because nothing changed on the _test_table_gho table. DELETE FROM _test_table_gho WHERE id = X'FF' matches no rows in _test_table_gho.

[jrgm]

I set up a local master-slave both running mysql5.6. I also setup master-slave both on mysql5.7.

With this branch https://github.com/jrgm/gh-ost/tree/test-varbinary-plus-fix-sha256-go-darwin, I can replicate this issue, running in the ./localtests/test.sh harness, in both versions of mysql.

[jrgm]

Running the test:

# on branch test-varbinary-plus-fix-sha256-go-darwin

$ ./localtests/test.sh -b ./bin/gh-ost varbinary
./localtests/test.sh -b ./bin/gh-ost varbinary
# master verified at 127.0.0.1:3307
sql_mode on master is NO_ENGINE_SUBSTITUTION
# replica verified at 127.0.0.1:3308
Building
Using binary: ./bin/gh-ost
Testing: varbinary...Postponing: 20 /tmp/gh-ost.postpone.flag
...ERROR varbinary: checksum mismatch
---
0a1
> \377\377\377\000
diff /tmp/gh-ost-test.orig.content.csv /tmp/gh-ost-test.ghost.content.csv
+ FAIL
$

[vladikoff]

@jrgm Going to try to run the repro script locally here...