gh-ost exits after issuing cutover

Probably related to #403. Upon issuing a cut-over, `gh-ost` exits after several attempts to wait for `AllEventsUpToLockProcessed` event to appear. Have verified that `AllEventsUpToLockProcessed` is indeed written to the change log table.

This is how we run `gh-ost`.
```bash
real_migrate() {
local dryrun=$1;
echo "--- Real migration, dryrun = ${dryrun}"

if [[ "${dryrun}" == false && ! -f "${CUTOVER_FILE}" ]]; then
echo "--- Writing cutover flag file to ${CUTOVER_FILE}. "
echo "--- Once migration is complete, rm this file to perform cutover"
touch "${CUTOVER_FILE}"
fi

local ghost_opts=( --assume-rbr --verbose --skip-foreign-key-checks \
--user="${DB_USER}" --password="${DB_PASSWORD}" \
--host="${DB_MIGRATION_REPLICA}" --database="${DB_NAME}" --table="${DB_TABLE}" \
--alter="${ALTER_STMT}" --assume-master-host="${DB_MASTER}" --exact-rowcount \
--concurrent-rowcount --initially-drop-ghost-table \
--discard-foreign-keys --hooks-path="${HOOKS_PATH}" \
--postpone-cut-over-flag-file="${CUTOVER_FILE}" \
--throttle-flag-file="${THROTTLE_FILE}" \
--heartbeat-interval-millis=200 --max-lag-millis=500 \
--throttle-control-replicas="${DB_THROTTLE_CTL_REPLICA_0},${DB_THROTTLE_CTL_REPLICA_1},${DB_THROTTLE_CTL_REPLICA_2}" \
--panic-flag-file="${PANIC_FILE}" )

if [[ "${dryrun}" == false ]]; then
ghost_opts+=( --execute )
fi

echo "--- Running ghost with params ${ghost_opts[@]}"
./gh-ost "${ghost_opts[@]}"
echo "--- All done"
}
...
```

And the last few lines of the log file.
```
2018-04-18 06:22:26 INFO Tables unlocked
Copy: 874748309/874748309 100.0%; Applied: 4818139; Backlog: 0/1000; Time: 54h26m55s(total), 50h51m33s(copy); streamer: mysql-bin-changelog.074245:62075216; State: throttled, lag=1.214406s; ETA: due
2018-04-18 06:22:30 INFO Grabbing voluntary lock: gh-ost.8823949.lock
2018-04-18 06:22:30 INFO Setting LOCK timeout as 6 seconds
2018-04-18 06:22:30 INFO Looking for magic cut-over table
2018-04-18 06:22:30 INFO Creating magic cut-over table `media`.`_media_bundle_del`
2018-04-18 06:22:30 INFO Magic cut-over table created
2018-04-18 06:22:30 INFO Locking `media`.`media_bundle`, `media`.`_media_bundle_del`
2018-04-18 06:22:31 INFO Tables locked
2018-04-18 06:22:31 INFO Session locking original & magic tables is 8823949
2018-04-18 06:22:31 INFO Writing changelog state: AllEventsUpToLockProcessed:1524032551099143693
2018-04-18 06:22:31 INFO Waiting for events up to lock
Copy: 874748309/874748309 100.0%; Applied: 4818139; Backlog: 0/1000; Time: 54h27m0s(total), 50h51m33s(copy); streamer: mysql-bin-changelog.074245:62075216; State: migrating; ETA: due
2018-04-18 06:22:34 ERROR Timeout while waiting for events up to lock
2018-04-18 06:22:34 ERROR 2018-04-18 06:22:34 ERROR Timeout while waiting for events up to lock
2018-04-18 06:22:34 INFO Looking for magic cut-over table
2018-04-18 06:22:34 INFO Will now proceed to drop magic table and unlock tables
2018-04-18 06:22:34 INFO Dropping magic cut-over table
2018-04-18 06:22:34 INFO Releasing lock from `media`.`media_bundle`, `media`.`_media_bundle_del`
2018-04-18 06:22:34 INFO Tables unlocked
2018-04-18 06:22:35 INFO Grabbing voluntary lock: gh-ost.8823871.lock
2018-04-18 06:22:35 INFO Setting LOCK timeout as 6 seconds
2018-04-18 06:22:35 INFO Looking for magic cut-over table
2018-04-18 06:22:35 INFO Creating magic cut-over table `media`.`_media_bundle_del`
2018-04-18 06:22:35 INFO Magic cut-over table created
2018-04-18 06:22:35 INFO Locking `media`.`media_bundle`, `media`.`_media_bundle_del`
2018-04-18 06:22:35 INFO Tables locked
2018-04-18 06:22:35 INFO Session locking original & magic tables is 8823871
2018-04-18 06:22:35 INFO Writing changelog state: AllEventsUpToLockProcessed:1524032555651985046
2018-04-18 06:22:35 INFO Waiting for events up to lock
Copy: 874748309/874748309 100.0%; Applied: 4818139; Backlog: 0/1000; Time: 54h27m5s(total), 50h51m33s(copy); streamer: mysql-bin-changelog.074245:62075216; State: migrating; ETA: due
2018-04-18 06:22:38 ERROR Timeout while waiting for events up to lock
2018-04-18 06:22:38 ERROR 2018-04-18 06:22:38 ERROR Timeout while waiting for events up to lock
2018-04-18 06:22:38 INFO Looking for magic cut-over table
2018-04-18 06:22:38 INFO Will now proceed to drop magic table and unlock tables
2018-04-18 06:22:38 INFO Dropping magic cut-over table
2018-04-18 06:22:38 INFO Removing socket file: /tmp/gh-ost.media.media_bundle.sock
2018-04-18 06:22:38 INFO Tearing down inspector
2018-04-18 06:22:38 FATAL 2018-04-18 06:22:38 ERROR Timeout while waiting for events up to lock
```
We are using `MySQL 5.6.34` on RDS, 1 master and 3 read replicas plus 1 more replica dedicated for the `gh-ost` migration.

We are using the default value for `CutOverLockTimeoutSeconds` (which is `3` seconds), but I don't think the timeout being too low is the issue. I did some digging and looks like `gh-ost` doesn't receive any bin_log events after issuing the cutover. Based on the snippet below I should see a line similar to 'Intercepted changelog state ' in the log file, but grepping only yields `Intercepted changelog state GhostTableMigrated`. _Disclaimer: My go-fu is so-so, I may have misread some parts of the code._

```go
// onChangelogStateEvent is called when a binlog event operation on the changelog table is intercepted.
func (this *Migrator) onChangelogStateEvent(dmlEvent *binlog.BinlogDMLEvent) (err error) {
// Hey, I created the changelog table, I know the type of columns it has!
if hint := dmlEvent.NewColumnValues.StringColumn(2); hint != "state" {
return nil
}
changelogStateString := dmlEvent.NewColumnValues.StringColumn(3)
changelogState := ReadChangelogState(changelogStateString)
log.Infof("Intercepted changelog state %s", changelogState)
switch changelogState {
case GhostTableMigrated:
{
this.ghostTableMigrated <- true
}
case AllEventsUpToLockProcessed:
{
var applyEventFunc tableWriteFunc = func() error {
this.allEventsUpToLockProcessed <- changelogStateString
return nil
}
// at this point we know all events up to lock have been read from the streamer,
// because the streamer works sequentially. So those events are either already handled,
// or have event functions in applyEventsQueue.
// So as not to create a potential deadlock, we write this func to applyEventsQueue
// asynchronously, understanding it doesn't really matter.
go func() {
this.applyEventsQueue <- newApplyEventStructByFunc(&applyEventFunc)
}()
}
default:
{
return fmt.Errorf("Unknown changelog state: %+v", changelogState)
}
}
log.Infof("Handled changelog state %s", changelogState)
return nil
}
```
Tried to run the same migration twice (currently retrying for the 3rd time) and the result is exactly the same. We already have run several successful migrations before on the same table and others.