Skip to content

Instantly share code, notes, and snippets.

@zmoazeni

zmoazeni/gh-ost-intermittent-failure.txt

Created June 7, 2019 21:45
Show Gist options
  • Save zmoazeni/e40ba08113bc5f8e3843443d51e03b66 to your computer and use it in GitHub Desktop.
Save zmoazeni/e40ba08113bc5f8e3843443d51e03b66 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gh-ost-intermittent-failure.txt
% ./force-failure
Building linux binary in build/bin
Building darwin binary in build/bin
# command-line-arguments
clang: warning: argument unused during compilation: '-nopie'
Binaries found in:
build/dist/gh-ost-binary-linux-20190607173922.tar.gz
build/dist/gh-ost-binary-osx-20190607173922.tar.gz
### Building docker image for 5.7.21
Sending build context to Docker daemon 4.608kB
Step 1/9 : FROM buildpack-deps:stretch
---> ed706ee09078
Step 2/9 : RUN apt update && apt install -y libaio1 libnuma1
---> Using cache
---> 80a04e09aa6d
Step 3/9 : ENV DBDEPLOYER_VERSION=1.30.1 DB_DEPLOYER_SHA256=b54eb047fdea2d3bece820c8c309f6610cfcea858a268b6c51be7ee53c9812bc
---> Using cache
---> d5278bc62c1f
Step 4/9 : RUN origin=https://github.com/datacharmer/dbdeployer/releases/download/v$DBDEPLOYER_VERSION && tarball=dbdeployer-$DBDEPLOYER_VERSION.linux.tar.gz && mkdir /dbdeployer && cd /dbdeployer && wget --progress=bar:force:noscroll $origin/$tarball && sha256sum $tarball | grep $DBDEPLOYER_VERSION && tar -xzf $tarball && chmod +x dbdeployer-$DBDEPLOYER_VERSION.linux && mv dbdeployer-$DBDEPLOYER_VERSION.linux /usr/local/bin/dbdeployer && cd / && rm -rf /dbdeployer
---> Using cache
---> 8b4f9f9dcc8a
Step 5/9 : ARG MYSQL_VERSION
---> Using cache
---> 94e2e90b36a9
Step 6/9 : ARG DBDEPLOYER_ARGS
---> Using cache
---> cc2a2393eae4
Step 7/9 : RUN wget --progress=bar:force:noscroll https://github.com/github/gh-ost-ci-env/raw/master/mysql-tarballs/${MYSQL_VERSION}.tar.gz && mkdir -p /sandbox/binary && mkdir /sandboxes && dbdeployer unpack ${MYSQL_VERSION}.tar.gz --unpack-version=${MYSQL_VERSION} --flavor mysql --sandbox-binary /sandbox/binary/ && dbdeployer deploy replication ${MYSQL_VERSION} --nodes 2 --sandbox-binary /sandbox/binary --sandbox-home /sandboxes/ --sandbox-directory rsandbox --my-cnf-options bind_address=0.0.0.0 --my-cnf-options log_slave_updates --my-cnf-options log_bin --my-cnf-options binlog_format=ROW --my-cnf-options event_scheduler=ON ${DBDEPLOYER_ARGS} && /sandboxes/rsandbox/test_replication && /sandboxes/rsandbox/m -uroot -e "grant all on *.* to 'gh-ost'@'%' identified by 'gh-ost'; flush privileges"
---> Using cache
---> 74c02da48c5b
Step 8/9 : COPY start.sh /usr/local/bin/start.sh
---> Using cache
---> 47477b443f05
Step 9/9 : CMD ["/usr/local/bin/start.sh"]
---> Using cache
---> 8e63791a726a
Successfully built 8e63791a726a
Successfully tagged gh-ost/dbdeployer:5.7.21
### Running gh-ost tests for 5.7.21
Testing: rename-none-comment..........
+ pass
----- attempt: 1----
### Building docker image for 5.7.21
Sending build context to Docker daemon 4.608kB
Step 1/9 : FROM buildpack-deps:stretch
---> ed706ee09078
Step 2/9 : RUN apt update && apt install -y libaio1 libnuma1
---> Using cache
---> 80a04e09aa6d
Step 3/9 : ENV DBDEPLOYER_VERSION=1.30.1 DB_DEPLOYER_SHA256=b54eb047fdea2d3bece820c8c309f6610cfcea858a268b6c51be7ee53c9812bc
---> Using cache
---> d5278bc62c1f
Step 4/9 : RUN origin=https://github.com/datacharmer/dbdeployer/releases/download/v$DBDEPLOYER_VERSION && tarball=dbdeployer-$DBDEPLOYER_VERSION.linux.tar.gz && mkdir /dbdeployer && cd /dbdeployer && wget --progress=bar:force:noscroll $origin/$tarball && sha256sum $tarball | grep $DBDEPLOYER_VERSION && tar -xzf $tarball && chmod +x dbdeployer-$DBDEPLOYER_VERSION.linux && mv dbdeployer-$DBDEPLOYER_VERSION.linux /usr/local/bin/dbdeployer && cd / && rm -rf /dbdeployer
---> Using cache
---> 8b4f9f9dcc8a
Step 5/9 : ARG MYSQL_VERSION
---> Using cache
---> 94e2e90b36a9
Step 6/9 : ARG DBDEPLOYER_ARGS
---> Using cache
---> cc2a2393eae4
Step 7/9 : RUN wget --progress=bar:force:noscroll https://github.com/github/gh-ost-ci-env/raw/master/mysql-tarballs/${MYSQL_VERSION}.tar.gz && mkdir -p /sandbox/binary && mkdir /sandboxes && dbdeployer unpack ${MYSQL_VERSION}.tar.gz --unpack-version=${MYSQL_VERSION} --flavor mysql --sandbox-binary /sandbox/binary/ && dbdeployer deploy replication ${MYSQL_VERSION} --nodes 2 --sandbox-binary /sandbox/binary --sandbox-home /sandboxes/ --sandbox-directory rsandbox --my-cnf-options bind_address=0.0.0.0 --my-cnf-options log_slave_updates --my-cnf-options log_bin --my-cnf-options binlog_format=ROW --my-cnf-options event_scheduler=ON ${DBDEPLOYER_ARGS} && /sandboxes/rsandbox/test_replication && /sandboxes/rsandbox/m -uroot -e "grant all on *.* to 'gh-ost'@'%' identified by 'gh-ost'; flush privileges"
---> Using cache
---> 74c02da48c5b
Step 8/9 : COPY start.sh /usr/local/bin/start.sh
---> Using cache
---> 47477b443f05
Step 9/9 : CMD ["/usr/local/bin/start.sh"]
---> Using cache
---> 8e63791a726a
Successfully built 8e63791a726a
Successfully tagged gh-ost/dbdeployer:5.7.21
### Running gh-ost tests for 5.7.21
Testing: rename-none-comment..........
+ pass
----- attempt: 2----
### Building docker image for 5.7.21
Sending build context to Docker daemon 4.608kB
Step 1/9 : FROM buildpack-deps:stretch
---> ed706ee09078
Step 2/9 : RUN apt update && apt install -y libaio1 libnuma1
---> Using cache
---> 80a04e09aa6d
Step 3/9 : ENV DBDEPLOYER_VERSION=1.30.1 DB_DEPLOYER_SHA256=b54eb047fdea2d3bece820c8c309f6610cfcea858a268b6c51be7ee53c9812bc
---> Using cache
---> d5278bc62c1f
Step 4/9 : RUN origin=https://github.com/datacharmer/dbdeployer/releases/download/v$DBDEPLOYER_VERSION && tarball=dbdeployer-$DBDEPLOYER_VERSION.linux.tar.gz && mkdir /dbdeployer && cd /dbdeployer && wget --progress=bar:force:noscroll $origin/$tarball && sha256sum $tarball | grep $DBDEPLOYER_VERSION && tar -xzf $tarball && chmod +x dbdeployer-$DBDEPLOYER_VERSION.linux && mv dbdeployer-$DBDEPLOYER_VERSION.linux /usr/local/bin/dbdeployer && cd / && rm -rf /dbdeployer
---> Using cache
---> 8b4f9f9dcc8a
Step 5/9 : ARG MYSQL_VERSION
---> Using cache
---> 94e2e90b36a9
Step 6/9 : ARG DBDEPLOYER_ARGS
---> Using cache
---> cc2a2393eae4
Step 7/9 : RUN wget --progress=bar:force:noscroll https://github.com/github/gh-ost-ci-env/raw/master/mysql-tarballs/${MYSQL_VERSION}.tar.gz && mkdir -p /sandbox/binary && mkdir /sandboxes && dbdeployer unpack ${MYSQL_VERSION}.tar.gz --unpack-version=${MYSQL_VERSION} --flavor mysql --sandbox-binary /sandbox/binary/ && dbdeployer deploy replication ${MYSQL_VERSION} --nodes 2 --sandbox-binary /sandbox/binary --sandbox-home /sandboxes/ --sandbox-directory rsandbox --my-cnf-options bind_address=0.0.0.0 --my-cnf-options log_slave_updates --my-cnf-options log_bin --my-cnf-options binlog_format=ROW --my-cnf-options event_scheduler=ON ${DBDEPLOYER_ARGS} && /sandboxes/rsandbox/test_replication && /sandboxes/rsandbox/m -uroot -e "grant all on *.* to 'gh-ost'@'%' identified by 'gh-ost'; flush privileges"
---> Using cache
---> 74c02da48c5b
Step 8/9 : COPY start.sh /usr/local/bin/start.sh
---> Using cache
---> 47477b443f05
Step 9/9 : CMD ["/usr/local/bin/start.sh"]
---> Using cache
---> 8e63791a726a
Successfully built 8e63791a726a
Successfully tagged gh-ost/dbdeployer:5.7.21
### Running gh-ost tests for 5.7.21
Testing: rename-none-comment.........
ERROR rename-none-comment execution failure. cat /tmp/gh-ost-test-5.7.21.log:
2019-06-07 17:40:18 INFO starting gh-ost 1.0.48
2019-06-07 17:40:18 INFO Migrating `test`.`gh_ost_test`
2019-06-07 17:40:18 INFO connection validated on 127.0.0.1:5722
2019-06-07 17:40:18 INFO User has ALL privileges
2019-06-07 17:40:18 INFO binary logs validated on 127.0.0.1:5722
2019-06-07 17:40:18 INFO Inspector initiated on d5384f4d58ab:5722, version 5.7.21-log
2019-06-07 17:40:18 INFO Table found. Engine=InnoDB
2019-06-07 17:40:18 DEBUG Estimated number of rows via STATUS: 0
2019-06-07 17:40:18 DEBUG Validated no foreign keys exist on table
2019-06-07 17:40:18 DEBUG Validated no triggers exist on table
2019-06-07 17:40:18 INFO Estimated number of rows via EXPLAIN: 1
2019-06-07 17:40:18 DEBUG Potential unique keys in gh_ost_test: [PRIMARY (auto_increment): [id]; has nullable: false]
2019-06-07 17:40:18 INFO Master forced to be 127.0.0.1:5721
2019-06-07 17:40:18 INFO --test-on-replica or --migrate-on-replica given. Will not execute on master 127.0.0.1:5721 but rather on replica d5384f4d58ab:5722 itself
2019-06-07 17:40:18 INFO log_slave_updates validated on 127.0.0.1:5722
2019-06-07 17:40:18 INFO connection validated on 127.0.0.1:5722
2019-06-07 17:40:18 DEBUG Streamer binlog coordinates: mysql-bin.000002:817
2019-06-07 17:40:18 INFO Connecting binlog streamer at mysql-bin.000002:817
[2019/06/07 17:40:18] [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/07 17:40:18] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000002, 817)
[2019/06/07 17:40:18] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:5722
2019-06-07 17:40:18 DEBUG Beginning streaming
[2019/06/07 17:40:18] [info] binlogsyncer.go:723 rotate to (mysql-bin.000002, 817)
2019-06-07 17:40:18 INFO rotate to next log from mysql-bin.000002:0 to mysql-bin.000002
2019-06-07 17:40:18 INFO connection validated on 127.0.0.1:5722
2019-06-07 17:40:18 INFO connection validated on 127.0.0.1:5722
2019-06-07 17:40:18 INFO will use time_zone='SYSTEM' on applier
2019-06-07 17:40:18 INFO Examining table structure on applier
2019-06-07 17:40:18 INFO Applier initiated on d5384f4d58ab:5722, version 5.7.21-log
2019-06-07 17:40:18 INFO Dropping table `test`.`_gh_ost_test_gho`
2019-06-07 17:40:18 INFO Table dropped
2019-06-07 17:40:18 INFO Dropping table `test`.`_gh_ost_test_del`
2019-06-07 17:40:18 INFO Table dropped
2019-06-07 17:40:18 INFO Dropping table `test`.`_gh_ost_test_ghc`
2019-06-07 17:40:18 INFO Table dropped
2019-06-07 17:40:18 INFO Creating changelog table `test`.`_gh_ost_test_ghc`
2019-06-07 17:40:18 INFO Changelog table created
2019-06-07 17:40:18 INFO Creating ghost table `test`.`_gh_ost_test_gho`
2019-06-07 17:40:18 INFO Ghost table created
2019-06-07 17:40:18 INFO Altering ghost table `test`.`_gh_ost_test_gho`
2019-06-07 17:40:18 DEBUG ALTER statement: alter /* gh-ost */ table `test`.`_gh_ost_test_gho` add column exchange_rate double comment 'change rate used for pay in your own currency'
2019-06-07 17:40:18 INFO Ghost table altered
2019-06-07 17:40:18 INFO Intercepted changelog state GhostTableMigrated
2019-06-07 17:40:18 INFO Waiting for ghost table to be migrated. Current lag is 0s
2019-06-07 17:40:18 DEBUG ghost table migrated
2019-06-07 17:40:18 INFO Handled changelog state GhostTableMigrated
2019-06-07 17:40:18 DEBUG Potential unique keys in _gh_ost_test_gho: [PRIMARY (auto_increment): [id]; has nullable: false]
2019-06-07 17:40:18 INFO Chosen shared unique key is PRIMARY
2019-06-07 17:40:18 INFO Shared columns are id,c1
2019-06-07 17:40:18 INFO Listening on unix socket file: /tmp/gh-ost.test.sock
2019-06-07 17:40:18 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on
2019-06-07 17:40:18 DEBUG Reading migration range according to key: PRIMARY
2019-06-07 17:40:18 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while
2019-06-07 17:40:18 INFO Migration min values: [<nil>]
2019-06-07 17:40:18 DEBUG Reading migration range according to key: PRIMARY
2019-06-07 17:40:18 INFO Exact number of rows via COUNT: 0
2019-06-07 17:40:18 INFO Migration max values: [<nil>]
2019-06-07 17:40:18 INFO Waiting for first throttle metrics to be collected
2019-06-07 17:40:18 INFO First throttle metrics collected
2019-06-07 17:40:18 DEBUG Operating until row copy is complete
# Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho`
# Migrating d5384f4d58ab:5722; inspecting d5384f4d58ab:5722; executing on dagobah
# Migration started at Fri Jun 07 17:40:18 -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-07 17:40:18 DEBUG Getting nothing in the write queue. Sleeping...
2019-06-07 17:40:18 DEBUG No rows found in table. Rowcopy will be implicitly empty
2019-06-07 17:40:18 INFO Row copy complete
# Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho`
# Migrating d5384f4d58ab:5722; inspecting d5384f4d58ab:5722; executing on dagobah
# Migration started at Fri Jun 07 17:40:18 -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/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:3385; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:3385; State: migrating; ETA: due
2019-06-07 17:40:18 DEBUG checking for cut-over postpone
2019-06-07 17:40:18 DEBUG checking for cut-over postpone: complete
2019-06-07 17:40:18 DEBUG testing on replica. Stopping replication IO thread
2019-06-07 17:40:18 INFO Stopping replication IO thread
2019-06-07 17:40:18 INFO Replication IO thread stopped
2019-06-07 17:40:18 INFO Verifying SQL thread is stopped
2019-06-07 17:40:18 INFO SQL thread stopped
2019-06-07 17:40:18 INFO Replication IO thread at mysql-bin.000002:817. SQL thread is at mysql-bin.000002:817
2019-06-07 17:40:18 INFO Grabbing voluntary lock: gh-ost.17.lock
2019-06-07 17:40:18 INFO Setting LOCK timeout as 6 seconds
2019-06-07 17:40:18 INFO Looking for magic cut-over table
2019-06-07 17:40:18 INFO Creating magic cut-over table `test`.`_gh_ost_test_del`
2019-06-07 17:40:18 INFO Magic cut-over table created
2019-06-07 17:40:18 INFO Locking `test`.`gh_ost_test`, `test`.`_gh_ost_test_del`
2019-06-07 17:40:18 INFO Tables locked
2019-06-07 17:40:18 INFO Session locking original & magic tables is 17
2019-06-07 17:40:18 INFO Writing changelog state: AllEventsUpToLockProcessed:1559943618681871362
2019-06-07 17:40:18 INFO Intercepted changelog state AllEventsUpToLockProcessed
2019-06-07 17:40:18 INFO Handled changelog state AllEventsUpToLockProcessed
2019-06-07 17:40:18 INFO Waiting for events up to lock
2019-06-07 17:40:18 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 28 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc000022550)
/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, 0x87f040, 0xc0002625b0, 0xc0002625b0, 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-07 17:40:18 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 70 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc000240320)
/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, 0x87f040, 0xc000208e70, 0xc000208e70, 0x7264e5)
/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-07 17:40:18 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 58 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc000240410)
/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, 0x87f040, 0xc000209030, 0xc000209030, 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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 71 [running]:
runtime/debug.Stack(0x5c, 0xc0, 0xc00021a1e0)
/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, 0x87f040, 0xc0001a8dd0, 0xc0001a8dd0, 0x7264e5)
/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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 59 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc000240500)
/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, 0x87f040, 0xc0002092b0, 0xc0002092b0, 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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 60 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc000022640)
/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, 0x87f040, 0xc000262800, 0xc000262800, 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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 29 [running]:
runtime/debug.Stack(0x5c, 0x100, 0xc0002405f0)
/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, 0x87f040, 0xc0002093e0, 0xc0002093e0, 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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 39 [running]:
runtime/debug.Stack(0x5c, 0xc0, 0xc0002362d0)
/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, 0x87f040, 0xc0001fae60, 0xc0001fae60, 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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 72 [running]:
runtime/debug.Stack(0x5c, 0xc0, 0xc00021a2d0)
/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, 0x87f040, 0xc0001a9140, 0xc0001a9140, 0x7264e5)
/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-07 17:40:19 DEBUG Getting nothing in the write queue. Sleeping...
2019-06-07 17:40:19 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1559943618681871362
2019-06-07 17:40:19 INFO Done waiting for events up to lock; duration=937.134972ms
# Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho`
# Migrating d5384f4d58ab:5722; inspecting d5384f4d58ab:5722; executing on dagobah
# Migration started at Fri Jun 07 17:40:18 -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-07 17:40:19 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 30 [running]:
runtime/debug.Stack(0x5c, 0xc0, 0xc00021a3c0)
/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, 0x87f040, 0xc0001a9320, 0xc0001a9320, 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: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 0s(copy); streamer: mysql-bin.000002:12525; State: migrating; ETA: due
2019-06-07 17:40:19 INFO Setting RENAME timeout as 3 seconds
2019-06-07 17:40:19 INFO Session renaming tables is 18
2019-06-07 17:40:19 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`
we had a problem finding the connection
map[connection_id:{16 true} id:{3 true} info:{ false} state:{Waiting on empty queue true}]
map[connection_id:{16 true} id:{16 true} info:{select
id,
connection_id() as connection_id,
state,
info
from information_schema.processlist true} state:{executing true}]
map[connection_id:{16 true} id:{17 true} info:{ false} state:{ true}]
map[connection_id:{16 true} id:{15 true} info:{ false} state:{ true}]
map[connection_id:{16 true} id:{13 true} info:{ false} state:{Master has sent all binlog to slave; waiting for more updates true}]
map[connection_id:{16 true} id:{14 true} info:{ false} state:{ true}]
map[connection_id:{16 true} id:{18 true} info:{ false} state:{ true}]
map[connection_id:{16 true} id:{19 true} info:{insert /* gh-ost */ into `test`.`_gh_ost_test_ghc`
(id, hint, value)
values
(NULLIF(0, 0), 'throttle at 1559943619623768733', 'throttle-query')
on duplicate key update
last_update=NOW(),
value=VALUES(value) true} state:{query end true}]
sessionId: 18
stateHint: metadata lock
infoHint: rename
2019-06-07 17:40:19 INFO Looking for magic cut-over table
2019-06-07 17:40:19 INFO Will now proceed to drop magic table and unlock tables
2019-06-07 17:40:19 INFO Dropping magic cut-over table
2019-06-07 17:40:19 INFO Releasing lock from `test`.`gh_ost_test`, `test`.`_gh_ost_test_del`
2019-06-07 17:40:19 INFO Tables unlocked
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 0s(copy); streamer: mysql-bin.000002:13382; State: migrating; ETA: due
2019-06-07 17:40:19 INFO Tables renamed
2019-06-07 17:40:19 INFO Renaming back both tables
2019-06-07 17:40:19 DEBUG testing on replica. Starting replication IO thread after cut-over failure
2019-06-07 17:40:19 INFO Starting replication IO thread
2019-06-07 17:40:19 INFO Replication IO thread started
2019-06-07 17:40:19 INFO Verifying SQL thread is running
2019-06-07 17:40:19 INFO SQL thread started
2019-06-07 17:40:19 INFO Replication started
2019-06-07 17:40:19 INFO Removing socket file: /tmp/gh-ost.test.sock
2019-06-07 17:40:19 INFO Tearing down inspector
2019-06-07 17:40:19 FATAL Cannot find process. Hints: metadata lock, rename
goroutine 10 [running]:
runtime/debug.Stack(0x4b, 0x100, 0xc00001e9c0)
/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, 0x87f040, 0xc0003a8570, 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(0x87f040, 0xc0003a8570, 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(0xc0000e2480)
/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
+ FAIL
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment