search

github / gh-ost

GitHub's Online Schema-migration Tool for MySQL
MIT License
12.44k stars 1.26k forks source link

-test-on-replica: errors on 'replication not running' then on 'cut-over failure' then on 'table already exist' #408

Open mizioumt opened 7 years ago

mizioumt commented 7 years ago

v1.0.36, this is repeatable. seemingly a successful test migration that just did ALTER TABLE x ROW_FORMAT=COMPACT. However the output has some troublesome messages:


2017-04-24 18:12:35 DEBUG Iteration complete: no further range to iterate
2017-04-24 18:12:35 INFO Row copy complete
2017-04-24 18:12:35 DEBUG Iteration complete: no further range to iterate
2017-04-24 18:12:35 DEBUG Getting nothing in the write queue. Sleeping...
2017-04-24 18:12:35 DEBUG checking for cut-over postpone
2017-04-24 18:12:35 DEBUG checking for cut-over postpone: complete
2017-04-24 18:12:35 DEBUG testing on replica. Stopping replication IO thread
Copy: 19058539/19058539 100.0%; Applied: 61434; Backlog: 0/100; Time: 2h35m0s(total), 2h34m29s(copy); streamer: binlog.037230:557720; State: migrating; ETA: due
2017-04-24 18:12:35 INFO Stopping replication IO thread
2017-04-24 18:12:36 INFO Replication IO thread stopped
2017-04-24 18:12:36 INFO Verifying SQL thread is stopped
2017-04-24 18:12:36 DEBUG Getting nothing in the write queue. Sleeping...
2017-04-24 18:12:36 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=Yes
goroutine 257227 [running]:
runtime/debug.Stack(0x5d, 0x43, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcce0, 0xc427b20fd0, 0x60d9d0, 0xc4204acf88)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcce0, 0xc427b20fd0, 0x8fcce0, 0xc427b20fd0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0xc4206ad7a8, 0x1)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/throttler.go:105 +0xa8
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/throttler.go:124 +0x12b
2017-04-24 18:12:36 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 257845 [running]:
runtime/debug.Stack(0x5c, 0x42, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcce0, 0xc42a2e4380, 0x60d9d0, 0xc422887f88)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcce0, 0xc42a2e4380, 0x8fcce0, 0xc42a2e4380)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0xc4206ad7a8, 0x1)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/throttler.go:105 +0xa8
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/throttler.go:124 +0x12b

... more like this ... but then:


2017-04-24 18:13:17 ERROR Error 1050: Table '_TableName_gho' already exists
goroutine 1 [running]:
runtime/debug.Stack(0x5a, 0x40, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcda0, 0xc4202364a0, 0x8fcda0, 0xc4202364a0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcda0, 0xc4202364a0, 0xae, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils.ExecNoPrepare(0xc4200b9180, 0xc4200f82c0, 0xae, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils/sqlutils.go:283 +0x154
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 13/100; Time: 2h43m15s(total), 2h34m29s(copy); streamer: binlog.037259:72140140; State: throttled, lag=2.000000s; ETA: due
github.com/github/gh-ost/go/logic.(*Applier).RenameTablesRollback(0xc42018ab40, 0x708b80, 0xc42a33e3e0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/applier.go:564 +0x4be
github.com/github/gh-ost/go/logic.(*Migrator).handleCutOverResult(0xc42009c480, 0x8fcce0, 0xc420015610, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:391 +0x202
github.com/github/gh-ost/go/logic.(*Migrator).cutOver(0xc42009c480, 0x2, 0xc4205d2480)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:479 +0x2cb
github.com/github/gh-ost/go/logic.(*Migrator).(github.com/github/gh-ost/go/logic.cutOver)-fm(0x3b9aca00, 0xc429564120)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x2a
github.com/github/gh-ost/go/logic.(*Migrator).retryOperation(0xc42009c480, 0xc4205e3c90, 0x0, 0x0, 0x0, 0xc428925c50, 0x2a)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:158 +0x67
github.com/github/gh-ost/go/logic.(*Migrator).Migrate(0xc42009c480, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x7e7
main.main()
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/cmd/gh-ost/main.go:243 +0x1bec
2017-04-24 18:13:17 INFO Renaming back to ghost table
2017-04-24 18:13:17 ERROR Error 1050: Table '_TableName_gho' already exists
goroutine 1 [running]:
runtime/debug.Stack(0x5a, 0x40, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcda0, 0xc4202365a0, 0x8fcda0, 0xc4202365a0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcda0, 0xc4202365a0, 0x63, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils.ExecNoPrepare(0xc4200b9180, 0xc4200782a0, 0x63, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils/sqlutils.go:283 +0x154
github.com/github/gh-ost/go/logic.(*Applier).RenameTablesRollback(0xc42018ab40, 0x708b80, 0xc42a33e3e0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/applier.go:575 +0x783
github.com/github/gh-ost/go/logic.(*Migrator).handleCutOverResult(0xc42009c480, 0x8fcce0, 0xc420015610, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:391 +0x202
github.com/github/gh-ost/go/logic.(*Migrator).cutOver(0xc42009c480, 0x2, 0xc4205d2480)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:479 +0x2cb
github.com/github/gh-ost/go/logic.(*Migrator).(github.com/github/gh-ost/go/logic.cutOver)-fm(0x3b9aca00, 0xc429564120)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x2a
github.com/github/gh-ost/go/logic.(*Migrator).retryOperation(0xc42009c480, 0xc4205e3c90, 0x0, 0x0, 0x0, 0xc428925c50, 0x2a)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:158 +0x67
github.com/github/gh-ost/go/logic.(*Migrator).Migrate(0xc42009c480, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x7e7
main.main()
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/cmd/gh-ost/main.go:243 +0x1bec
2017-04-24 18:13:17 INFO Renaming back to original table
2017-04-24 18:13:17 ERROR Error 1050: Table 'TableName' already exists
goroutine 1 [running]:
runtime/debug.Stack(0x55, 0x3b, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcda0, 0xc420236680, 0x8fcda0, 0xc420236680)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcda0, 0xc420236680, 0x63, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils.ExecNoPrepare(0xc4200b9180, 0xc420078310, 0x63, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/sqlutils/sqlutils.go:283 +0x154
github.com/github/gh-ost/go/logic.(*Applier).RenameTablesRollback(0xc42018ab40, 0x708b80, 0xc42a33e3e0)
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 0/100; Time: 2h43m20s(total), 2h34m29s(copy); streamer: binlog.037259:94763393; State: throttled, lag=3.000000s; ETA: due
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/applier.go:585 +0xa4e
github.com/github/gh-ost/go/logic.(*Migrator).handleCutOverResult(0xc42009c480, 0x8fcce0, 0xc420015610, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:391 +0x202
github.com/github/gh-ost/go/logic.(*Migrator).cutOver(0xc42009c480, 0x2, 0xc4205d2480)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:479 +0x2cb
github.com/github/gh-ost/go/logic.(*Migrator).(github.com/github/gh-ost/go/logic.cutOver)-fm(0x3b9aca00, 0xc429564120)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x2a
github.com/github/gh-ost/go/logic.(*Migrator).retryOperation(0xc42009c480, 0xc4205e3c90, 0x0, 0x0, 0x0, 0xc428925c50, 0x2a)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:158 +0x67
github.com/github/gh-ost/go/logic.(*Migrator).Migrate(0xc42009c480, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x7e7
main.main()
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/cmd/gh-ost/main.go:243 +0x1bec
2017-04-24 18:13:17 ERROR Error 1050: Table 'TableName' already exists
goroutine 1 [running]:
runtime/debug.Stack(0x55, 0x3b, 0x0)
    /usr/lib64/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/lib64/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x8fcda0, 0xc420236680, 0x8fcda0, 0xc420236680)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xfd
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(0x8fcda0, 0xc420236680, 0x63, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 +0x3e
github.com/github/gh-ost/go/logic.(*Applier).RenameTablesRollback(0xc42018ab40, 0x708b80, 0xc42a33e3e0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/applier.go:588 +0xa6b
github.com/github/gh-ost/go/logic.(*Migrator).handleCutOverResult(0xc42009c480, 0x8fcce0, 0xc420015610, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:391 +0x202
github.com/github/gh-ost/go/logic.(*Migrator).cutOver(0xc42009c480, 0x2, 0xc4205d2480)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:479 +0x2cb
github.com/github/gh-ost/go/logic.(*Migrator).(github.com/github/gh-ost/go/logic.cutOver)-fm(0x3b9aca00, 0xc429564120)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x2a
github.com/github/gh-ost/go/logic.(*Migrator).retryOperation(0xc42009c480, 0xc4205e3c90, 0x0, 0x0, 0x0, 0xc428925c50, 0x2a)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:158 +0x67
github.com/github/gh-ost/go/logic.(*Migrator).Migrate(0xc42009c480, 0x0, 0x0)
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/logic/migrator.go:367 +0x7e7
main.main()
    /builddir/build/BUILD/gh-ost-v1.0.36-1_f693aeede4fa.el7/gopath/src/github.com/github/gh-ost/go/cmd/gh-ost/main.go:243 +0x1bec
.... more like this

now it stops complaining about replication not running and says the cutover has failed. What follows is the tail of the log.

2017-04-24 18:13:17 DEBUG testing on replica. Starting replication IO thread after cut-over failure
2017-04-24 18:13:17 INFO Starting replication IO thread
2017-04-24 18:13:17 INFO Replication IO thread started
2017-04-24 18:13:17 INFO Verifying SQL thread is running
2017-04-24 18:13:17 INFO SQL thread started
2017-04-24 18:13:17 INFO Replication started
2017-04-24 18:13:18 DEBUG throttling before swapping tables
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 1/100; Time: 2h43m25s(total), 2h34m29s(copy); streamer: binlog.037260:13486064; State: migrating; ETA: due
2017-04-24 18:13:18 DEBUG throttling before swapping tables
2017-04-24 18:13:18 DEBUG throttling before swapping tables
2017-04-24 18:13:19 DEBUG throttling before swapping tables
2017-04-24 18:13:19 DEBUG throttling before swapping tables
2017-04-24 18:13:19 DEBUG throttling before swapping tables
2017-04-24 18:13:19 DEBUG throttling before swapping tables
2017-04-24 18:13:20 DEBUG throttling before swapping tables
2017-04-24 18:13:20 DEBUG throttling before swapping tables
2017-04-24 18:13:20 DEBUG throttling before swapping tables
2017-04-24 18:13:20 DEBUG throttling before swapping tables
2017-04-24 18:13:21 DEBUG throttling before swapping tables
2017-04-24 18:13:21 DEBUG throttling before swapping tables
2017/04/24 18:13:21 binlogsyncer.go:568: [info] rotate to (binlog.037232, 4)
2017/04/24 18:13:21 binlogsyncer.go:568: [info] rotate to (binlog.037232, 4)
2017-04-24 18:13:21 INFO rotate to next log name: binlog.037232
2017-04-24 18:13:21 INFO rotate to next log name: binlog.037232
2017-04-24 18:13:21 DEBUG throttling before swapping tables
2017-04-24 18:13:21 DEBUG throttling before swapping tables
2017-04-24 18:13:22 DEBUG throttling before swapping tables
2017-04-24 18:13:22 DEBUG throttling before swapping tables
2017-04-24 18:13:22 DEBUG throttling before swapping tables
2017-04-24 18:13:22 DEBUG throttling before swapping tables
2017-04-24 18:13:23 DEBUG throttling before swapping tables
2017-04-24 18:13:23 DEBUG throttling before swapping tables
2017-04-24 18:13:23 DEBUG throttling before swapping tables
2017-04-24 18:13:23 DEBUG throttling before swapping tables
2017-04-24 18:13:24 DEBUG throttling before swapping tables
2017-04-24 18:13:24 DEBUG throttling before swapping tables
2017-04-24 18:13:24 DEBUG throttling before swapping tables
2017/04/24 18:13:24 binlogsyncer.go:568: [info] rotate to (binlog.037233, 4)
2017/04/24 18:13:24 binlogsyncer.go:568: [info] rotate to (binlog.037233, 4)
2017-04-24 18:13:24 INFO rotate to next log name: binlog.037233
2017-04-24 18:13:24 INFO rotate to next log name: binlog.037233
2017-04-24 18:13:24 DEBUG throttling before swapping tables
2017-04-24 18:13:25 DEBUG throttling before swapping tables
2017-04-24 18:13:25 DEBUG throttling before swapping tables
2017-04-24 18:13:25 DEBUG throttling before swapping tables
2017-04-24 18:13:25 DEBUG throttling before swapping tables
2017-04-24 18:13:26 DEBUG throttling before swapping tables
2017-04-24 18:13:26 DEBUG throttling before swapping tables
2017-04-24 18:13:26 DEBUG throttling before swapping tables
2017-04-24 18:13:26 DEBUG throttling before swapping tables
2017-04-24 18:13:27 DEBUG throttling before swapping tables
2017-04-24 18:13:27 DEBUG throttling before swapping tables
2017-04-24 18:13:27 DEBUG throttling before swapping tables
2017-04-24 18:13:27 DEBUG throttling before swapping tables
2017-04-24 18:13:28 DEBUG throttling before swapping tables
2017-04-24 18:13:28 DEBUG throttling before swapping tables
2017-04-24 18:13:28 DEBUG throttling before swapping tables
2017-04-24 18:13:28 DEBUG throttling before swapping tables
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 1/100; Time: 2h43m30s(total), 2h34m29s(copy); streamer: binlog.037260:42613044; State: migrating; ETA: due
2017-04-24 18:13:29 DEBUG throttling before swapping tables
2017-04-24 18:13:29 DEBUG throttling before swapping tables
2017-04-24 18:13:29 DEBUG throttling before swapping tables
2017-04-24 18:13:29 DEBUG throttling before swapping tables
2017-04-24 18:13:30 DEBUG throttling before swapping tables
2017-04-24 18:13:30 DEBUG throttling before swapping tables
2017-04-24 18:13:30 DEBUG throttling before swapping tables
2017-04-24 18:13:30 DEBUG throttling before swapping tables
2017-04-24 18:13:31 DEBUG throttling before swapping tables
2017-04-24 18:13:31 DEBUG throttling before swapping tables
2017-04-24 18:13:31 DEBUG throttling before swapping tables
2017-04-24 18:13:31 DEBUG throttling before swapping tables
2017-04-24 18:13:32 DEBUG throttling before swapping tables
2017-04-24 18:13:32 DEBUG throttling before swapping tables
2017-04-24 18:13:32 DEBUG throttling before swapping tables
2017-04-24 18:13:32 DEBUG throttling before swapping tables
2017-04-24 18:13:33 DEBUG throttling before swapping tables
2017-04-24 18:13:33 DEBUG throttling before swapping tables
2017-04-24 18:13:33 DEBUG throttling before swapping tables
2017-04-24 18:13:33 DEBUG throttling before swapping tables
2017/04/24 18:13:33 binlogsyncer.go:568: [info] rotate to (binlog.037234, 4)
2017/04/24 18:13:33 binlogsyncer.go:568: [info] rotate to (binlog.037234, 4)
2017-04-24 18:13:33 INFO rotate to next log name: binlog.037234
2017-04-24 18:13:33 INFO rotate to next log name: binlog.037234
2017-04-24 18:13:34 DEBUG throttling before swapping tables
2017-04-24 18:13:34 DEBUG throttling before swapping tables
2017-04-24 18:13:34 DEBUG throttling before swapping tables
2017-04-24 18:13:34 DEBUG throttling before swapping tables
2017-04-24 18:13:35 DEBUG throttling before swapping tables
2017-04-24 18:13:35 DEBUG throttling before swapping tables
2017-04-24 18:13:35 DEBUG throttling before swapping tables
2017-04-24 18:13:35 DEBUG throttling before swapping tables
2017-04-24 18:13:36 DEBUG throttling before swapping tables
2017-04-24 18:13:36 DEBUG throttling before swapping tables
2017-04-24 18:13:36 DEBUG throttling before swapping tables
2017-04-24 18:13:36 DEBUG throttling before swapping tables
2017-04-24 18:13:37 DEBUG throttling before swapping tables
2017-04-24 18:13:37 DEBUG throttling before swapping tables
2017-04-24 18:13:37 DEBUG throttling before swapping tables
2017-04-24 18:13:37 DEBUG throttling before swapping tables
2017-04-24 18:13:38 DEBUG throttling before swapping tables
2017-04-24 18:13:38 DEBUG throttling before swapping tables
2017-04-24 18:13:38 DEBUG throttling before swapping tables
2017-04-24 18:13:38 DEBUG throttling before swapping tables
2017-04-24 18:13:39 DEBUG throttling before swapping tables
2017-04-24 18:13:39 DEBUG throttling before swapping tables
2017-04-24 18:13:39 DEBUG throttling before swapping tables
2017-04-24 18:13:39 DEBUG throttling before swapping tables
2017/04/24 18:13:40 binlogsyncer.go:568: [info] rotate to (binlog.037235, 4)
2017/04/24 18:13:40 binlogsyncer.go:568: [info] rotate to (binlog.037235, 4)
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 5/100; Time: 2h43m35s(total), 2h34m29s(copy); streamer: binlog.037260:58013120; State: throttled, lag=3.000000s; ETA: due
2017-04-24 18:13:40 INFO rotate to next log name: binlog.037235
2017-04-24 18:13:40 INFO rotate to next log name: binlog.037235
2017-04-24 18:13:40 DEBUG throttling before swapping tables
2017-04-24 18:13:40 DEBUG throttling before swapping tables
2017-04-24 18:13:40 DEBUG throttling before swapping tables
2017-04-24 18:13:40 DEBUG throttling before swapping tables
2017-04-24 18:13:41 DEBUG throttling before swapping tables
2017-04-24 18:13:41 DEBUG throttling before swapping tables
2017-04-24 18:13:41 DEBUG throttling before swapping tables
2017-04-24 18:13:41 DEBUG throttling before swapping tables
2017-04-24 18:13:42 DEBUG throttling before swapping tables
2017-04-24 18:13:42 DEBUG throttling before swapping tables
# Migrating `app`.`TableName`; Ghost table is `app`.`_TableName_gho`
# Migrating hostname.somewhere.com:3306; inspecting HOSTNAME:3306; executing on HOSTNAME
# Migration started at Mon Apr 24 15:38:03 +0200 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# throttle-control-replicas count: 1
# Serving on unix socket: /tmp/gh-ost.app.TableName.sock
Copy: 19058539/19058539 100.0%; Applied: 90780; Backlog: 0/100; Time: 2h43m36s(total), 2h34m29s(copy); streamer: binlog.037260:58855906; State: migrating; ETA: due
2017-04-24 18:13:42 DEBUG throttling before swapping tables
2017-04-24 18:13:42 DEBUG throttling before swapping tables
2017-04-24 18:13:43 DEBUG throttling before swapping tables
2017-04-24 18:13:43 DEBUG throttling before swapping tables
# Done
2017-04-24 18:13:43 DEBUG throttling before swapping tables

2017-04-24 18:13:43 DEBUG throttling before swapping tables
2017-04-24 18:13:44 DEBUG throttling before swapping tables
2017-04-24 18:13:44 DEBUG throttling before swapping tables
2017-04-24 18:13:44 DEBUG throttling before swapping tables
2017-04-24 18:13:44 DEBUG throttling before swapping tables
2017-04-24 18:13:45 DEBUG throttling before swapping tables
2017-04-24 18:13:45 DEBUG throttling before swapping tables
2017-04-24 18:13:45 DEBUG throttling before swapping tables
2017-04-24 18:13:45 DEBUG throttling before swapping tables
2017-04-24 18:13:46 DEBUG throttling before swapping tables

and now it exits successfully, the new and old tables have identical content and replication is NOT running. I didn't

So in the log there is a fair amount of confusion: gh-ost stops replication but then complains about it not running, complains about tables already existing, says cut-over failed, says it starts replication, stops it without saying so.

shlomi-noach commented 7 years ago

What is the command you executed?

shlomi-noach commented 7 years ago

As per https://github.com/github/gh-ost/blob/master/doc/testing-on-replica.md, a --test-on-replica execution stops replication at the end of operation.

mizioumt commented 7 years ago

not with one of my tests with 1.0.35 but this is past. The problem of this issue is that it stops replication then complains about replication being stopped then restarts it. It also complains about tables existing when they should have existed. This doesn't constitute a successful test-on-replica to me no matter how fine the resulting tables are. The command was:

gh-ost -database app -host HOSTNAME -conf config-file -table TableName -alter row_format=compact -execute -verbose -test-on-replica -debug -stack
shlomi-noach commented 7 years ago

Thank you, I will look into it.