Created
June 6, 2019 04:02
-
-
Save zmoazeni/4ea85d89fa07280f6fc5c41c0e2020c0 to your computer and use it in GitHub Desktop.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 2019-06-05 23:14:38 INFO starting gh-ost 1.0.48 | |
| 2019-06-05 23:14:38 INFO Migrating `test`.`gh_ost_test` | |
| 2019-06-05 23:14:38 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 INFO User has ALL privileges | |
| 2019-06-05 23:14:38 INFO binary logs validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 INFO Inspector initiated on f17262bbdece:5722, version 5.7.21-log | |
| 2019-06-05 23:14:38 INFO Table found. Engine=InnoDB | |
| 2019-06-05 23:14:38 DEBUG Estimated number of rows via STATUS: 2 | |
| 2019-06-05 23:14:38 DEBUG Validated no foreign keys exist on table | |
| 2019-06-05 23:14:38 DEBUG Validated no triggers exist on table | |
| 2019-06-05 23:14:38 INFO Estimated number of rows via EXPLAIN: 2 | |
| 2019-06-05 23:14:38 DEBUG Potential unique keys in gh_ost_test: [PRIMARY (auto_increment): [id]; has nullable: false] | |
| 2019-06-05 23:14:38 INFO Master forced to be 127.0.0.1:5721 | |
| 2019-06-05 23:14:38 INFO --test-on-replica or --migrate-on-replica given. Will not execute on master 127.0.0.1:5721 but rather on replica f17262bbdece:5722 itself | |
| 2019-06-05 23:14:38 INFO log_slave_updates validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 DEBUG Streamer binlog coordinates: mysql-bin.000002:2524 | |
| 2019-06-05 23:14:38 INFO Connecting binlog streamer at mysql-bin.000002:2524 | |
| [2019/06/05 23:14:38] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 5722 gh-ost false false <nil> false UTC true 0 0s 0s 0 false} | |
| [2019/06/05 23:14:38] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000002, 2524) | |
| [2019/06/05 23:14:38] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 DEBUG Beginning streaming | |
| 2019-06-05 23:14:38 INFO rotate to next log from mysql-bin.000002:0 to mysql-bin.000002 | |
| [2019/06/05 23:14:38] [info] binlogsyncer.go:723 rotate to (mysql-bin.000002, 2524) | |
| 2019-06-05 23:14:38 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-05 23:14:38 INFO will use time_zone='SYSTEM' on applier | |
| 2019-06-05 23:14:38 INFO Examining table structure on applier | |
| 2019-06-05 23:14:38 INFO Applier initiated on f17262bbdece:5722, version 5.7.21-log | |
| 2019-06-05 23:14:38 INFO Dropping table `test`.`_gh_ost_test_gho` | |
| 2019-06-05 23:14:38 INFO Table dropped | |
| 2019-06-05 23:14:38 INFO Dropping table `test`.`_gh_ost_test_del` | |
| 2019-06-05 23:14:38 INFO Table dropped | |
| 2019-06-05 23:14:38 INFO Dropping table `test`.`_gh_ost_test_ghc` | |
| 2019-06-05 23:14:38 INFO Table dropped | |
| 2019-06-05 23:14:38 INFO Creating changelog table `test`.`_gh_ost_test_ghc` | |
| 2019-06-05 23:14:38 INFO Changelog table created | |
| 2019-06-05 23:14:38 INFO Creating ghost table `test`.`_gh_ost_test_gho` | |
| 2019-06-05 23:14:38 INFO Ghost table created | |
| 2019-06-05 23:14:38 INFO Altering ghost table `test`.`_gh_ost_test_gho` | |
| 2019-06-05 23:14:38 DEBUG ALTER statement: alter /* gh-ost */ table `test`.`_gh_ost_test_gho` engine=innodb | |
| 2019-06-05 23:14:38 INFO Ghost table altered | |
| 2019-06-05 23:14:38 INFO Intercepted changelog state GhostTableMigrated | |
| 2019-06-05 23:14:38 INFO Waiting for ghost table to be migrated. Current lag is 0s | |
| 2019-06-05 23:14:38 DEBUG ghost table migrated | |
| 2019-06-05 23:14:38 INFO Handled changelog state GhostTableMigrated | |
| 2019-06-05 23:14:38 DEBUG Potential unique keys in _gh_ost_test_gho: [PRIMARY (auto_increment): [id]; has nullable: false] | |
| 2019-06-05 23:14:38 INFO Chosen shared unique key is PRIMARY | |
| 2019-06-05 23:14:38 INFO Shared columns are id,i,bi,iu,biu | |
| 2019-06-05 23:14:38 INFO Listening on unix socket file: /tmp/gh-ost.test.sock | |
| 2019-06-05 23:14:38 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on | |
| 2019-06-05 23:14:38 DEBUG Reading migration range according to key: PRIMARY | |
| 2019-06-05 23:14:38 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while | |
| 2019-06-05 23:14:38 INFO Migration min values: [1] | |
| 2019-06-05 23:14:38 DEBUG Reading migration range according to key: PRIMARY | |
| 2019-06-05 23:14:38 INFO Migration max values: [2] | |
| 2019-06-05 23:14:38 INFO Waiting for first throttle metrics to be collected | |
| 2019-06-05 23:14:38 INFO First throttle metrics collected | |
| 2019-06-05 23:14:38 DEBUG Operating until row copy is complete | |
| # Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho` | |
| # Migrating f17262bbdece:5722; inspecting f17262bbdece:5722; executing on dagobah | |
| # Migration started at Wed Jun 05 23:14:38 -0400 2019 | |
| # chunk-size: 100; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 | |
| # throttle-flag-file: /tmp/gh-ost-test.ghost.throttle.flag | |
| # throttle-additional-flag-file: /tmp/gh-ost.throttle | |
| # throttle-query: select timestampdiff(second, min(last_update), now()) < 5 from _gh_ost_test_ghc | |
| # throttle-control-replicas count: 1 | |
| # Serving on unix socket: /tmp/gh-ost.test.sock | |
| 2019-06-05 23:14:38 INFO Exact number of rows via COUNT: 2 | |
| 2019-06-05 23:14:38 DEBUG Issued INSERT on range: [1]..[2]; iteration: 0; chunk-size: 100 | |
| Copy: 0/2 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:4681; State: migrating; ETA: N/A | |
| 2019-06-05 23:14:38 DEBUG Iteration complete: no further range to iterate | |
| 2019-06-05 23:14:38 DEBUG Getting nothing in the write queue. Sleeping... | |
| 2019-06-05 23:14:38 INFO Row copy complete | |
| # Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho` | |
| # Migrating f17262bbdece:5722; inspecting f17262bbdece:5722; executing on dagobah | |
| # Migration started at Wed Jun 05 23:14:38 -0400 2019 | |
| # chunk-size: 100; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 | |
| # throttle-flag-file: /tmp/gh-ost-test.ghost.throttle.flag | |
| # throttle-additional-flag-file: /tmp/gh-ost.throttle | |
| # throttle-query: select timestampdiff(second, min(last_update), now()) < 5 from _gh_ost_test_ghc | |
| # throttle-control-replicas count: 1 | |
| # Serving on unix socket: /tmp/gh-ost.test.sock | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:6114; State: migrating; ETA: due | |
| 2019-06-05 23:14:38 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:39 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:39 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:39 DEBUG throttling before swapping tables | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 2/1000; Time: 1s(total), 0s(copy); streamer: mysql-bin.000002:11490; State: throttled, throttle-query; ETA: due | |
| 2019-06-05 23:14:39 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:40 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:40 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:40 DEBUG throttling before swapping tables | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 4/1000; Time: 2s(total), 0s(copy); streamer: mysql-bin.000002:16147; State: throttled, throttle-query; ETA: due | |
| 2019-06-05 23:14:40 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:41 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:41 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:41 DEBUG throttling before swapping tables | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 6/1000; Time: 3s(total), 0s(copy); streamer: mysql-bin.000002:21199; State: throttled, throttle-query; ETA: due | |
| 2019-06-05 23:14:41 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:42 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:42 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:42 DEBUG throttling before swapping tables | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 8/1000; Time: 4s(total), 0s(copy); streamer: mysql-bin.000002:26654; State: throttled, throttle-query; ETA: due | |
| 2019-06-05 23:14:42 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:43 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:43 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:43 DEBUG throttling before swapping tables | |
| Copy: 2/2 100.0%; Applied: 0; Backlog: 10/1000; Time: 5s(total), 0s(copy); streamer: mysql-bin.000002:31704; State: throttled, throttle-query; ETA: due | |
| 2019-06-05 23:14:43 DEBUG throttling before swapping tables | |
| 2019-06-05 23:14:44 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction | |
| 2019-06-05 23:14:44 DEBUG Getting nothing in the write queue. Sleeping... | |
| 2019-06-05 23:14:44 DEBUG checking for cut-over postpone | |
| 2019-06-05 23:14:44 DEBUG checking for cut-over postpone: complete | |
| 2019-06-05 23:14:44 DEBUG testing on replica. Stopping replication IO thread | |
| 2019-06-05 23:14:44 INFO Stopping replication IO thread | |
| 2019-06-05 23:14:44 INFO Replication IO thread stopped | |
| 2019-06-05 23:14:44 INFO Verifying SQL thread is stopped | |
| 2019-06-05 23:14:44 INFO SQL thread stopped | |
| 2019-06-05 23:14:44 INFO Replication IO thread at mysql-bin.000002:5621. SQL thread is at mysql-bin.000002:5621 | |
| 2019-06-05 23:14:44 INFO Grabbing voluntary lock: gh-ost.12.lock | |
| 2019-06-05 23:14:44 INFO Setting LOCK timeout as 6 seconds | |
| 2019-06-05 23:14:44 INFO Looking for magic cut-over table | |
| 2019-06-05 23:14:44 INFO Creating magic cut-over table `test`.`_gh_ost_test_del` | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 111 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000456190) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0001da570, 0xc0001da570, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 INFO Magic cut-over table created | |
| 2019-06-05 23:14:44 INFO Locking `test`.`gh_ost_test`, `test`.`_gh_ost_test_del` | |
| 2019-06-05 23:14:44 INFO Tables locked | |
| 2019-06-05 23:14:44 INFO Session locking original & magic tables is 12 | |
| 2019-06-05 23:14:44 INFO Writing changelog state: AllEventsUpToLockProcessed:1559790884204617620 | |
| 2019-06-05 23:14:44 INFO Intercepted changelog state AllEventsUpToLockProcessed | |
| 2019-06-05 23:14:44 INFO Handled changelog state AllEventsUpToLockProcessed | |
| 2019-06-05 23:14:44 INFO Waiting for events up to lock | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 140 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000468140) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000238880, 0xc000238880, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 155 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc0003e4050) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc00015ab50, 0xc00015ab50, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 112 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000456280) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0001da710, 0xc0001da710, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 141 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000468230) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0002389e0, 0xc0002389e0, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 94 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000456370) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0001da870, 0xc0001da870, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 156 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc0003e4140) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc00015ac20, 0xc00015ac20, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 142 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000468320) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000238a60, 0xc000238a60, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| Copy: 2/2 100.0%; Applied: 10; Backlog: 1/1000; Time: 6s(total), 0s(copy); streamer: mysql-bin.000002:39476; State: migrating; ETA: due | |
| 2019-06-05 23:14:44 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 157 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000468410) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000238c70, 0xc000238c70, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:45 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 144 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000468500) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000238cf0, 0xc000238cf0, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:45 DEBUG Getting nothing in the write queue. Sleeping... | |
| 2019-06-05 23:14:45 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1559790884204617620 | |
| 2019-06-05 23:14:45 INFO Done waiting for events up to lock; duration=947.332851ms | |
| # Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho` | |
| # Migrating f17262bbdece:5722; inspecting f17262bbdece:5722; executing on dagobah | |
| # Migration started at Wed Jun 05 23:14:38 -0400 2019 | |
| # chunk-size: 100; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 | |
| # throttle-flag-file: /tmp/gh-ost-test.ghost.throttle.flag | |
| # throttle-additional-flag-file: /tmp/gh-ost.throttle | |
| # throttle-query: select timestampdiff(second, min(last_update), now()) < 5 from _gh_ost_test_ghc | |
| # throttle-control-replicas count: 1 | |
| # Serving on unix socket: /tmp/gh-ost.test.sock | |
| Copy: 2/2 100.0%; Applied: 10; Backlog: 0/1000; Time: 6s(total), 0s(copy); streamer: mysql-bin.000002:40732; State: migrating; ETA: due | |
| 2019-06-05 23:14:45 INFO Setting RENAME timeout as 3 seconds | |
| 2019-06-05 23:14:45 INFO Session renaming tables is 17 | |
| 2019-06-05 23:14:45 INFO Issuing and expecting this to block: rename /* gh-ost */ table `test`.`gh_ost_test` to `test`.`_gh_ost_test_del`, `test`.`_gh_ost_test_gho` to `test`.`gh_ost_test` | |
| 2019-06-05 23:14:45 INFO Looking for magic cut-over table | |
| 2019-06-05 23:14:45 INFO Will now proceed to drop magic table and unlock tables | |
| 2019-06-05 23:14:45 INFO Dropping magic cut-over table | |
| 2019-06-05 23:14:45 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 95 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc0003b00a0) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000059500, 0xc000059500, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x435201, 0x81afe0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-05 23:14:45 INFO Releasing lock from `test`.`gh_ost_test`, `test`.`_gh_ost_test_del` | |
| 2019-06-05 23:14:45 INFO Tables unlocked | |
| 2019-06-05 23:14:45 INFO Tables renamed | |
| 2019-06-05 23:14:45 INFO Renaming back both tables | |
| 2019-06-05 23:14:45 DEBUG testing on replica. Starting replication IO thread after cut-over failure | |
| 2019-06-05 23:14:45 INFO Starting replication IO thread | |
| 2019-06-05 23:14:45 INFO Replication IO thread started | |
| 2019-06-05 23:14:45 INFO Verifying SQL thread is running | |
| 2019-06-05 23:14:45 INFO SQL thread started | |
| 2019-06-05 23:14:45 INFO Replication started | |
| 2019-06-05 23:14:45 INFO Removing socket file: /tmp/gh-ost.test.sock | |
| 2019-06-05 23:14:45 INFO Tearing down inspector | |
| 2019-06-05 23:14:45 FATAL Cannot find process. Hints: metadata lock, rename | |
| goroutine 19 [running]: | |
| runtime/debug.Stack(0x4b, 0xc0, 0xc00049e540) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x0, 0x87e700, 0xc0002393e0, 0x1, 0x101) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Fatale(0x87e700, 0xc0002393e0, 0x0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:255 +0x3e | |
| github.com/github/gh-ost/go/logic.(*Migrator).listenOnPanicAbort(0xc000158000) | |
| /go/src/github.com/github/gh-ost/go/logic/migrator.go:252 +0x60 | |
| created by github.com/github/gh-ost/go/logic.(*Migrator).Migrate | |
| /go/src/github.com/github/gh-ost/go/logic/migrator.go:323 +0x21d | |
| 2019-06-05 23:14:45 INFO Tearing down applier | |
| *************************** 1. row *************************** | |
| Table: _gh_ost_test_gho | |
| Create Table: CREATE TABLE `_gh_ost_test_gho` ( | |
| `id` int(11) NOT NULL AUTO_INCREMENT, | |
| `i` int(11) NOT NULL, | |
| `bi` bigint(20) NOT NULL, | |
| `iu` int(10) unsigned NOT NULL, | |
| `biu` bigint(20) unsigned NOT NULL, | |
| PRIMARY KEY (`id`) | |
| ) ENGINE=InnoDB AUTO_INCREMENT=8 DEFAULT CHARSET=latin1 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 2019-06-03 23:12:11 INFO starting gh-ost 1.0.48 | |
| 2019-06-03 23:12:11 INFO Migrating `test`.`gh_ost_test` | |
| 2019-06-03 23:12:11 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 INFO User has ALL privileges | |
| 2019-06-03 23:12:11 INFO binary logs validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 INFO Inspector initiated on 8850973d0f37:5722, version 5.7.21-log | |
| 2019-06-03 23:12:11 INFO Table found. Engine=InnoDB | |
| 2019-06-03 23:12:11 DEBUG Estimated number of rows via STATUS: 4 | |
| 2019-06-03 23:12:11 DEBUG Validated no foreign keys exist on table | |
| 2019-06-03 23:12:11 DEBUG Validated no triggers exist on table | |
| 2019-06-03 23:12:11 INFO Estimated number of rows via EXPLAIN: 4 | |
| 2019-06-03 23:12:11 DEBUG Potential unique keys in gh_ost_test: [PRIMARY (auto_increment): [id]; has nullable: false] | |
| 2019-06-03 23:12:11 INFO Master forced to be 127.0.0.1:5721 | |
| 2019-06-03 23:12:11 INFO --test-on-replica or --migrate-on-replica given. Will not execute on master 127.0.0.1:5721 but rather on replica 8850973d0f37:5722 itself | |
| 2019-06-03 23:12:11 INFO log_slave_updates validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 DEBUG Streamer binlog coordinates: mysql-bin.000002:3717 | |
| 2019-06-03 23:12:11 INFO Connecting binlog streamer at mysql-bin.000002:3717 | |
| [2019/06/03 23:12:11] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 5722 gh-ost false false <nil> false UTC true 0 0s 0s 0 false} | |
| [2019/06/03 23:12:11] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000002, 3717) | |
| [2019/06/03 23:12:11] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 DEBUG Beginning streaming | |
| [2019/06/03 23:12:11] [info] binlogsyncer.go:723 rotate to (mysql-bin.000002, 3717) | |
| 2019-06-03 23:12:11 INFO rotate to next log from mysql-bin.000002:0 to mysql-bin.000002 | |
| 2019-06-03 23:12:11 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 INFO connection validated on 127.0.0.1:5722 | |
| 2019-06-03 23:12:11 INFO will use time_zone='SYSTEM' on applier | |
| 2019-06-03 23:12:11 INFO Examining table structure on applier | |
| 2019-06-03 23:12:11 INFO Applier initiated on 8850973d0f37:5722, version 5.7.21-log | |
| 2019-06-03 23:12:11 INFO Dropping table `test`.`_gh_ost_test_gho` | |
| 2019-06-03 23:12:11 INFO Table dropped | |
| 2019-06-03 23:12:11 INFO Dropping table `test`.`_gh_ost_test_del` | |
| 2019-06-03 23:12:11 INFO Table dropped | |
| 2019-06-03 23:12:11 INFO Dropping table `test`.`_gh_ost_test_ghc` | |
| 2019-06-03 23:12:11 INFO Table dropped | |
| 2019-06-03 23:12:11 INFO Creating changelog table `test`.`_gh_ost_test_ghc` | |
| 2019-06-03 23:12:11 INFO Changelog table created | |
| 2019-06-03 23:12:11 INFO Creating ghost table `test`.`_gh_ost_test_gho` | |
| 2019-06-03 23:12:11 INFO Ghost table created | |
| 2019-06-03 23:12:11 INFO Altering ghost table `test`.`_gh_ost_test_gho` | |
| 2019-06-03 23:12:11 DEBUG ALTER statement: alter /* gh-ost */ table `test`.`_gh_ost_test_gho` change column t t timestamp not null default current_timestamp | |
| 2019-06-03 23:12:11 INFO Ghost table altered | |
| 2019-06-03 23:12:11 INFO Intercepted changelog state GhostTableMigrated | |
| 2019-06-03 23:12:11 INFO Waiting for ghost table to be migrated. Current lag is 0s | |
| 2019-06-03 23:12:11 DEBUG ghost table migrated | |
| 2019-06-03 23:12:11 INFO Handled changelog state GhostTableMigrated | |
| 2019-06-03 23:12:11 DEBUG Potential unique keys in _gh_ost_test_gho: [PRIMARY (auto_increment): [id]; has nullable: false] | |
| 2019-06-03 23:12:11 INFO Chosen shared unique key is PRIMARY | |
| 2019-06-03 23:12:11 INFO Shared columns are id,i,ts0,ts1,dt2,t,updated | |
| 2019-06-03 23:12:11 INFO Listening on unix socket file: /tmp/gh-ost.test.sock | |
| 2019-06-03 23:12:11 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on | |
| 2019-06-03 23:12:11 DEBUG Reading migration range according to key: PRIMARY | |
| 2019-06-03 23:12:11 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while | |
| 2019-06-03 23:12:11 INFO Exact number of rows via COUNT: 4 | |
| 2019-06-03 23:12:11 INFO Migration min values: [1] | |
| 2019-06-03 23:12:11 DEBUG Reading migration range according to key: PRIMARY | |
| 2019-06-03 23:12:11 INFO Migration max values: [4] | |
| 2019-06-03 23:12:11 INFO Waiting for first throttle metrics to be collected | |
| 2019-06-03 23:12:11 INFO First throttle metrics collected | |
| 2019-06-03 23:12:11 DEBUG Operating until row copy is complete | |
| # Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho` | |
| # Migrating 8850973d0f37:5722; inspecting 8850973d0f37:5722; executing on dagobah | |
| 2019-06-03 23:12:11 DEBUG Getting nothing in the write queue. Sleeping... | |
| # Migration started at Mon Jun 03 23:12:11 -0400 2019 | |
| # chunk-size: 100; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 | |
| # throttle-flag-file: /tmp/gh-ost-test.ghost.throttle.flag | |
| # throttle-additional-flag-file: /tmp/gh-ost.throttle | |
| # throttle-query: select timestampdiff(second, min(last_update), now()) < 5 from _gh_ost_test_ghc | |
| # throttle-control-replicas count: 1 | |
| # Serving on unix socket: /tmp/gh-ost.test.sock | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:6263; State: migrating; ETA: N/A | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 2/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000002:11931; State: throttled, throttle-query; ETA: N/A | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 4/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin.000002:16963; State: throttled, throttle-query; ETA: N/A | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 6/1000; Time: 3s(total), 3s(copy); streamer: mysql-bin.000002:21997; State: throttled, throttle-query; ETA: N/A | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 8/1000; Time: 4s(total), 4s(copy); streamer: mysql-bin.000002:27031; State: throttled, throttle-query; ETA: N/A | |
| Copy: 0/4 0.0%; Applied: 0; Backlog: 10/1000; Time: 5s(total), 5s(copy); streamer: mysql-bin.000002:32061; State: throttled, throttle-query; ETA: N/A | |
| 2019-06-03 23:12:16 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction | |
| 2019-06-03 23:12:16 DEBUG Issued INSERT on range: [1]..[4]; iteration: 0; chunk-size: 100 | |
| 2019-06-03 23:12:16 DEBUG Iteration complete: no further range to iterate | |
| 2019-06-03 23:12:16 DEBUG Getting nothing in the write queue. Sleeping... | |
| 2019-06-03 23:12:16 INFO Row copy complete | |
| Copy: 4/4 100.0%; Applied: 10; Backlog: 0/1000; Time: 5s(total), 5s(copy); streamer: mysql-bin.000002:35902; State: migrating; ETA: due | |
| 2019-06-03 23:12:16 DEBUG checking for cut-over postpone | |
| 2019-06-03 23:12:16 DEBUG checking for cut-over postpone: complete | |
| 2019-06-03 23:12:16 DEBUG testing on replica. Stopping replication IO thread | |
| 2019-06-03 23:12:16 INFO Stopping replication IO thread | |
| 2019-06-03 23:12:16 INFO Replication IO thread stopped | |
| 2019-06-03 23:12:16 INFO Verifying SQL thread is stopped | |
| 2019-06-03 23:12:16 INFO SQL thread stopped | |
| 2019-06-03 23:12:16 INFO Replication IO thread at mysql-bin.000002:6835. SQL thread is at mysql-bin.000002:6835 | |
| 2019-06-03 23:12:16 INFO Grabbing voluntary lock: gh-ost.12.lock | |
| 2019-06-03 23:12:16 INFO Setting LOCK timeout as 6 seconds | |
| 2019-06-03 23:12:16 INFO Looking for magic cut-over table | |
| 2019-06-03 23:12:16 INFO Creating magic cut-over table `test`.`_gh_ost_test_del` | |
| 2019-06-03 23:12:16 INFO Magic cut-over table created | |
| 2019-06-03 23:12:16 INFO Locking `test`.`gh_ost_test`, `test`.`_gh_ost_test_del` | |
| 2019-06-03 23:12:16 INFO Tables locked | |
| 2019-06-03 23:12:16 INFO Session locking original & magic tables is 12 | |
| 2019-06-03 23:12:16 INFO Writing changelog state: AllEventsUpToLockProcessed:1559617936954005954 | |
| 2019-06-03 23:12:16 INFO Intercepted changelog state AllEventsUpToLockProcessed | |
| 2019-06-03 23:12:16 INFO Handled changelog state AllEventsUpToLockProcessed | |
| 2019-06-03 23:12:16 INFO Waiting for events up to lock | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 165 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000022280) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0002211b0, 0xc0002211b0, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 135 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000022370) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0002212a0, 0xc0002212a0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 136 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000486050) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc00050ae40, 0xc00050ae40, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 137 [running]: | |
| runtime/debug.Stack(0x5c, 0x180, 0xc0000c2050) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc0001741b0, 0xc0001741b0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 122 [running]: | |
| runtime/debug.Stack(0x5c, 0x180, 0xc0000ce050) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc00033b470, 0xc00033b470, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 123 [running]: | |
| runtime/debug.Stack(0x5c, 0x200, 0xc0000a6280) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000384bb0, 0xc000384bb0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 124 [running]: | |
| runtime/debug.Stack(0x5c, 0x180, 0xc0000c2140) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000174310, 0xc000174310, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| Copy: 4/4 100.0%; Applied: 10; Backlog: 1/1000; Time: 6s(total), 5s(copy); streamer: mysql-bin.000002:40581; State: migrating; ETA: due | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 63 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc0000ce140) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc00033b6c0, 0xc00033b6c0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 166 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc000022460) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000221450, 0xc000221450, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| 2019-06-03 23:12:17 DEBUG Getting nothing in the write queue. Sleeping... | |
| 2019-06-03 23:12:17 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1559617936954005954 | |
| 2019-06-03 23:12:17 INFO Done waiting for events up to lock; duration=939.590568ms | |
| # Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho` | |
| # Migrating 8850973d0f37:5722; inspecting 8850973d0f37:5722; executing on dagobah | |
| # Migration started at Mon Jun 03 23:12:11 -0400 2019 | |
| # chunk-size: 100; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 | |
| # throttle-flag-file: /tmp/gh-ost-test.ghost.throttle.flag | |
| # throttle-additional-flag-file: /tmp/gh-ost.throttle | |
| # throttle-query: select timestampdiff(second, min(last_update), now()) < 5 from _gh_ost_test_ghc | |
| # throttle-control-replicas count: 1 | |
| # Serving on unix socket: /tmp/gh-ost.test.sock | |
| 2019-06-03 23:12:17 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No | |
| goroutine 167 [running]: | |
| runtime/debug.Stack(0x5c, 0xc0, 0xc0000225a0) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x87e700, 0xc000221590, 0xc000221590, 0x725eb5) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Errore(...) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:224 | |
| github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag.func1(0x1, 0x0) | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xbc | |
| created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag | |
| /go/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xca | |
| Copy: 4/4 100.0%; Applied: 10; Backlog: 0/1000; Time: 6s(total), 5s(copy); streamer: mysql-bin.000002:41837; State: migrating; ETA: due | |
| 2019-06-03 23:12:17 INFO Setting RENAME timeout as 3 seconds | |
| 2019-06-03 23:12:17 INFO Session renaming tables is 16 | |
| 2019-06-03 23:12:17 INFO Issuing and expecting this to block: rename /* gh-ost */ table `test`.`gh_ost_test` to `test`.`_gh_ost_test_del`, `test`.`_gh_ost_test_gho` to `test`.`gh_ost_test` | |
| 2019-06-03 23:12:17 INFO Looking for magic cut-over table | |
| 2019-06-03 23:12:17 INFO Will now proceed to drop magic table and unlock tables | |
| 2019-06-03 23:12:17 INFO Dropping magic cut-over table | |
| 2019-06-03 23:12:17 INFO Releasing lock from `test`.`gh_ost_test`, `test`.`_gh_ost_test_del` | |
| 2019-06-03 23:12:17 INFO Tables unlocked | |
| 2019-06-03 23:12:17 INFO Tables renamed | |
| 2019-06-03 23:12:17 INFO Renaming back both tables | |
| 2019-06-03 23:12:17 DEBUG testing on replica. Starting replication IO thread after cut-over failure | |
| 2019-06-03 23:12:17 INFO Starting replication IO thread | |
| 2019-06-03 23:12:17 INFO Replication IO thread started | |
| 2019-06-03 23:12:17 INFO Verifying SQL thread is running | |
| 2019-06-03 23:12:17 INFO SQL thread started | |
| 2019-06-03 23:12:17 INFO Replication started | |
| 2019-06-03 23:12:17 INFO Removing socket file: /tmp/gh-ost.test.sock | |
| 2019-06-03 23:12:17 INFO Tearing down inspector | |
| 2019-06-03 23:12:17 FATAL Cannot find process. Hints: metadata lock, rename | |
| goroutine 23 [running]: | |
| runtime/debug.Stack(0x4b, 0x200, 0xc00017c440) | |
| /usr/local/go/src/runtime/debug/stack.go:24 +0x9d | |
| runtime/debug.PrintStack() | |
| /usr/local/go/src/runtime/debug/stack.go:16 +0x22 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x0, 0x87e700, 0xc000174670, 0x1, 0x101) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:178 +0xe7 | |
| github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.Fatale(0x87e700, 0xc000174670, 0x0, 0x0) | |
| /go/src/github.com/github/gh-ost/vendor/github.com/outbrain/golib/log/log.go:255 +0x3e | |
| github.com/github/gh-ost/go/logic.(*Migrator).listenOnPanicAbort(0xc000172000) | |
| /go/src/github.com/github/gh-ost/go/logic/migrator.go:252 +0x60 | |
| created by github.com/github/gh-ost/go/logic.(*Migrator).Migrate | |
| /go/src/github.com/github/gh-ost/go/logic/migrator.go:323 +0x21d | |
| *************************** 1. row *************************** | |
| Table: _gh_ost_test_gho | |
| Create Table: CREATE TABLE `_gh_ost_test_gho` ( | |
| `id` int(11) NOT NULL AUTO_INCREMENT, | |
| `i` int(11) NOT NULL, | |
| `ts0` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP, | |
| `ts1` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP, | |
| `dt2` datetime DEFAULT NULL, | |
| `t` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP, | |
| `updated` tinyint(3) unsigned DEFAULT '0', | |
| PRIMARY KEY (`id`), | |
| KEY `i_idx` (`i`) | |
| ) ENGINE=InnoDB AUTO_INCREMENT=15 DEFAULT CHARSET=latin1 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment