Slave_IO_Running: Connecting

[jrmyio]

When I am testing ghost on a slave located at localhost I get the error that replication is broken because
Slave_IO_Running returned "Connecting" instead of "Yes".

However, for some reason whenever I run SHOW SLAVE STATUS it returns for both Slave_IO_Running: yes and Slave_SQL_running: yes. My slave is running fine and syncing with the master...

Only when Ghost checks the Slave_IO_Running it seems to return connecting. Does this have to do with any work Ghost does in preparation and doesn't wait for my slave re-connecting to the master?

Here is the log.

./gh-ost --max-load=Threads_running=25 --critical-load=Threads_running=1000 --chunk-size=1000 --max-lag-millis=1500 --user="root" --password="root" --host=localhost --database="test_database" --table="test_table" --verbose --alter="engine=innodb" --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 [--execute]
> 2016-12-12 06:44:06 INFO starting gh-ost 1.0.30
> 2016-12-12 06:44:06 INFO Migrating `test_database`.`test_table`
> 2016-12-12 06:44:06 INFO connection validated on localhost:3306
> 2016-12-12 06:44:06 INFO User has ALL privileges
> 2016-12-12 06:44:06 INFO binary logs validated on localhost:3306
> 2016-12-12 06:44:06 INFO Restarting replication on localhost:3306 to make sure binlog settings apply to replication thread
> 2016-12-12 06:44:06 INFO Table found. Engine=InnoDB
> 2016-12-12 06:44:06 INFO Estimated number of rows via EXPLAIN: 2
> 2016-12-12 06:44:06 INFO Recursively searching for replication master
> 2016-12-12 06:44:06 INFO FATAL Replication on localhost:3306 is broken: Slave_IO_Running: Connecting, Slave_SQL_Running: Yes.  Please make sure replication runs before using gh-ost.

[shlomi-noach]

@ConneXNL thank you, yes, this is likely because gh-ost doesn't wait following START SLAVE to allow the replica to actually finish handshaking with the master. In orchestrator I always make sure to sleep some 500ms following START SLAVE and I should be doing the same here.

Until I submit a fix for this, and assuming you know your replica uses row based logging, you can --assume-rbr which skips the STOP SLAVE; START SLAVE step.

[jrmyio]

Thanks for the quick reply. --assume-master-host= and/or --assume-rbr indeed worked as a work-around. However, I am running into the next problem and before I post yet another issue (as maybe this might be related though I doubt it). Everything get's stuck on: Waiting for ghost table to be migrated. Current lag is 0s. When I investigate the 2 tables, then _test_table_gho actually contains no rows yet.

Here is the log:

./gh-ost \
> --max-load=Threads_running=25 \
> --critical-load=Threads_running=1000 \
> --chunk-size=1000 \
> --max-lag-millis=1500 \
> --user="??????" \
> --password="???????" \
> --host=localhost \
> --database="test_database" \
> --table="test_table" \
> --verbose \
> --alter="engine=innodb" \
> --assume-rbr \
> --allow-master-master \
> --assume-master-host=???.???.???.??? \
> --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 \
> --initially-drop-ghost-table \
> --execute
2016-12-12 07:23:14 INFO starting gh-ost 1.0.30
2016-12-12 07:23:14 INFO Migrating `test_database`.`test_table`
2016-12-12 07:23:14 INFO connection validated on localhost:3306
2016-12-12 07:23:14 INFO User has ALL privileges
2016-12-12 07:23:14 INFO binary logs validated on localhost:3306
2016-12-12 07:23:14 INFO Table found. Engine=InnoDB
2016-12-12 07:23:14 INFO Estimated number of rows via EXPLAIN: 4
2016-12-12 07:23:14 INFO Master forced to be ???.???.???.???:3306
2016-12-12 07:23:14 INFO log_slave_updates validated on localhost:3306
2016-12-12 07:23:14 INFO connection validated on localhost:3306
2016-12-12 07:23:14 INFO Registering replica at localhost:3306
2016-12-12 07:23:14 INFO Connecting binlog streamer at mysql-bin.000003:1338
2016-12-12 07:23:14 INFO rotate to next log name: mysql-bin.000003
2016-12-12 07:23:15 INFO connection validated on ???.???.???.???:3306
2016-12-12 07:23:16 INFO connection validated on ???.???.???.???:3306
2016-12-12 07:23:16 INFO will use time_zone='SYSTEM' on applier
2016-12-12 07:23:16 INFO Examining table structure on applier
2016-12-12 07:23:16 INFO Droppping table `test_database`.`_test_table_gho`
2016-12-12 07:23:17 INFO Table dropped
2016-12-12 07:23:17 INFO Droppping table `test_database`.`_test_table_ghc`
2016-12-12 07:23:18 INFO Table dropped
2016-12-12 07:23:18 INFO Creating changelog table `test_database`.`_test_table_ghc`
2016-12-12 07:23:19 INFO Changelog table created
2016-12-12 07:23:19 INFO Creating ghost table `test_database`.`_test_table_gho`
2016-12-12 07:23:20 INFO Ghost table created
2016-12-12 07:23:20 INFO Altering ghost table `test_database`.`_test_table_gho`
2016-12-12 07:23:21 INFO Ghost table altered
2016-12-12 07:23:22 INFO Waiting for ghost table to be migrated. Current lag is 0s

[shlomi-noach]

what is the binlog_format on the replica?

[shlomi-noach]

Also, why --assume-master-host= ? I did not suggest it

[jrmyio]

The slave binlog_format is set to ROW.
The master binlog_format is set to MIXED.

On slave:

show variables like 'binlog_format'
binlog_format
ROW

Before you responded I figured --assume-master-host= would skip the code that checks the slave status so that also worked.

I removed --assume-master-host= now but everything is still stuck at 2016-12-12 07:43:12 INFO Waiting for ghost table to be migrated. Current lag is 0s

[shlomi-noach]

can you please:

1. before running gh-ost, and just to be sure, stop slave;start slave on the replica?
2. when you see this Waiting for ghost table to be migrated, message, can you please verify the master has the table _test_table_gho and whether the replica also has it?

[jrmyio]

The answer to question 2 was YES.

However, found a problem in my slave's binlog_do_db setting. Currently retrying again to see if it was related. Will update this comment.

[shlomi-noach]

binlog-do-* and binlog-ignore-* are definitely suspects here...

[jrmyio]

This was the issue. I had the specific database not listed in binlog_do_db on the Slave's configuration.

[shlomi-noach]

Thank you for checking. For visibility, always prefer to add a new comment rather than editing your comment. I only get a notification when you add a comment, and also it's difficult to look back and search for changes in stuff you've already read.

[jrmyio]

Ok, will do! Thanks for helping here. I am not sure whether the system should give reasons whenever it gets stuck or maybe something regarding this could be listed in the FAQ.

[shlomi-noach]

@ConneXNL good idea, can you please open a new issue with this suggestion?
If you're able to, opening a PR for this would be even better.