Incorrect values when making column nullable

[kwburgess]

Confirmed: #684 (related issue: #681 ) did not fix this problem.

Using gh-ost to make a column to be nullable results in incorrect values for the column. Initial guess is an overflow issue of some sort.

Reproduction steps:

CREATE TABLE ghost_overflow_test (primary_key BIGINT(20) NOT NULL, 
test_id BIGINT(20) NOT NULL, 
PRIMARY KEY (primary_key));
INSERT INTO ghost_overflow_test VALUES (1,18446744073709551615);

./gh-ost --host=localhost --user=test --password=test --database=test \
--allow-on-master --alter="CHANGE test_id test_id bigint(20);" \
--table=ghost_overflow_test --execute

select * from ghost_overflow_test;
+-------------+---------------------+
| primary_key | test_id             |
+-------------+---------------------+
|           1 | 9223372036854775807 |
+-------------+---------------------+
1 row in set (0.00 sec)

id went from 18446744073709551615 -> 9223372036854775807

Versions:

$ mysql --version
mysql  Ver 14.14 Distrib 5.7.11, for Linux (x86_64) using  EditLine wrapper
$ go version
go version go1.9.2 linux/amd64

tested on gh-ost master branch and test-decimal branch

[shlomi-noach]

@kwburgess can you please clarify, #681 was about the DECIMAL datatype. Your reproduction steps do not include DECIMAL. If there is a problem, how does it relate to #681 and #684?

[shlomi-noach]

@kwburgess https://github.com/github/gh-ost/pull/692 tests your scenario and passes. Can you please examine?

[kwburgess]

Thank you @shlomi-noach ch for the rapid replies and careful attention. Agreed, #684 was DECIMAL not BIGINT, but it was the most similar issue to my current one so I was being extra careful and making sure it didn't solve this peripherally. Unfortunately I followed your instructions https://github.com/github/gh-ost/blob/master/doc/coding-ghost.md to attempt to run the tests locally and examine the tables created by your test and more understand how your test environment works, but I could not get past running the test.sh script in the gh-ost repo.

I've determined your tests can't run on Mac OS, which is fine. eventually, I got by on a Centos. but I still can't run your localtests.

$ go get -v github.com/github/gh-ost
$ cd src/github.com/github/gh-ost/
$ ./script/cibuild # runs successfully
$ git checkout bigint-change-nullable
$ ./localtests/test.sh 
./localtests/test.sh: line 39: gh-ost-test-mysql-master: command not found
Cannot verify gh-ost-test-mysql-master

Wondering if you had any extended setup instructions?

[kwburgess]

With a little more investigation (couldn't find this in the docs), I'm guessing I have to run ./script/cibuild-gh-ost-replica-tests instead of running ./localtests/test.sh

so I attempted to do so:

./script/cibuild-gh-ost-replica-tests output

I initially ran as my own user, and it failed even earlier.

$ sudo ./script/cibuild-gh-ost-replica-tests
root
remote commit is: e50f7ac0a75c7ec395895b1f3743e116aa7df412
local commit is:  e50f7ac0a75c7ec395895b1f3743e116aa7df412
Building...
which: no go in (/sbin:/bin:/usr/sbin:/usr/bin)
go version go1.9.2 linux/amd64 found in /home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19: Go Binary: /home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/bin/go
+++ rm -rf .gopath
+++ mkdir -p .gopath/src/github.com/github
+++ ln -s /home/kburgess/gowork/src/github.com/github/gh-ost .gopath/src/github.com/github/gh-ost
+++ export GOPATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath:/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor
+++ GOPATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath:/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor
++ mkdir -p bin
++ bindir=/home/kburgess/gowork/src/github.com/github/gh-ost/bin
++ scriptdir=/home/kburgess/gowork/src/github.com/github/gh-ost/script
+++ git rev-parse HEAD
++ version=dd41d9a4b1b4b0511152aea81920c0eead8873a3
+++ git describe --tags --always --dirty
++ describe=v1.0.47-35-gdd41d9a
++ export GOPATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath
++ GOPATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath
++ cd .gopath/src/github.com/github/gh-ost
++ go build -o /home/kburgess/gowork/src/github.com/github/gh-ost/bin/gh-ost -ldflags '-X main.AppVersion=dd41d9a4b1b4b0511152aea81920c0eead8873a3 -X main.BuildDescribe=v1.0.47-35-gdd41d9a' ./go/cmd/gh-ost/main.go
+ find gh-ost-ci-env/mysql-tarballs/ -name '*.tar.gz'
+ sort -r
+ read f
+ read mysql_version
+ basename gh-ost-ci-env/mysql-tarballs/5.7.21.tar.gz .tar.gz
+ read f
+ basename gh-ost-ci-env/mysql-tarballs/5.6.33.tar.gz .tar.gz
+ read f
+ basename gh-ost-ci-env/mysql-tarballs/5.5.52.tar.gz .tar.gz
+ read f
+ test_mysql_version 5.7.21
+ local mysql_version
+ mysql_version=5.7.21
+ echo '##### Testing 5.7.21'
##### Testing 5.7.21
+ echo '### Setting up sandbox for 5.7.21'
### Setting up sandbox for 5.7.21
+ find sandboxes -name stop_all
+ bash
# executing "stop" on /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes/rsandbox
executing "stop" on slave 1
executing "stop" on master
+ mkdir -p sandbox/binary
+ rm -rf sandbox/binary/5.7.21
+ gh-ost-ci-env/bin/linux/dbdeployer unpack gh-ost-ci-env/mysql-tarballs/5.7.21.tar.gz --unpack-version=5.7.21 --sandbox-binary /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandbox/binary
Unpacking tarball gh-ost-ci-env/mysql-tarballs/5.7.21.tar.gz to /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandbox/binary/5.7.21
.........98
+ mkdir -p sandboxes
+ rm -rf sandboxes/rsandbox
+ echo 5.7.21
+ egrep '5[.]5[.]'
+ gtid=--gtid
+ gh-ost-ci-env/bin/linux/dbdeployer deploy replication 5.7.21 --nodes 2 --sandbox-binary /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandbox/binary --sandbox-home /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes --gtid --my-cnf-options log_slave_updates --my-cnf-options log_bin --my-cnf-options binlog_format=ROW --sandbox-directory rsandbox
Installing and starting master
Database installed in /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes/rsandbox/master
. sandbox server started
Installing and starting slave 1
Database installed in /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes/rsandbox/node1
. sandbox server started
/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes/rsandbox/initialize_slaves
initializing slave 1
Replication directory installed in /home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/sandboxes/rsandbox
run 'dbdeployer usage multiple' for basic instructions'
+ sed /sandboxes/d -i gh-ost-ci-env/bin/gh-ost-test-mysql-master
+ echo 'sandboxes/rsandbox/m "$@"'
+ sed /sandboxes/d -i gh-ost-ci-env/bin/gh-ost-test-mysql-replica
+ echo 'sandboxes/rsandbox/s1 "$@"'
+ export PATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/gh-ost-ci-env/bin/:/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/bin:/sbin:/bin:/usr/sbin:/usr/bin
+ PATH=/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/gh-ost-ci-env/bin/:/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/bin:/sbin:/bin:/usr/sbin:/usr/bin
+ gh-ost-test-mysql-master -uroot -e 'grant all on *.* to '\''gh-ost'\''@'\''%'\'' identified by '\''gh-ost'\'''
+ echo '### Running gh-ost tests for 5.7.21'
### Running gh-ost tests for 5.7.21
+ ./localtests/test.sh -b bin/gh-ost
# master verified at 127.0.0.1:18822
sql_mode on master is ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
# replica verified at 127.0.0.1:18823
Building
Using binary: bin/gh-ost
Testing: tz......
+ pass
Testing: datetime......
+ pass
Testing: bigint-change-nullable......
+ pass
Testing: rename-inserts-only......
+ pass
Testing: timestamp-to-datetime......
+ pass
Testing: datetime-to-timestamp-pk-fail.....
+ pass
Testing: fail-password-length.....
+ pass
Testing: unsigned.....
ERROR unsigned execution failure. cat /tmp/gh-ost-test.log:
2019-01-17 19:14:54 INFO starting gh-ost dd41d9a4b1b4b0511152aea81920c0eead8873a3
2019-01-17 19:14:54 INFO Migrating `test`.`gh_ost_test`
2019-01-17 19:14:54 INFO connection validated on 127.0.0.1:18823
2019-01-17 19:14:54 INFO User has ALL privileges
2019-01-17 19:14:54 INFO binary logs validated on 127.0.0.1:18823
2019-01-17 19:14:54 INFO Inspector initiated on lo:18823, version 5.7.21-log
2019-01-17 19:14:54 INFO Table found. Engine=InnoDB
2019-01-17 19:14:54 DEBUG Estimated number of rows via STATUS: 2
2019-01-17 19:14:54 DEBUG Validated no foreign keys exist on table
2019-01-17 19:14:54 DEBUG Validated no triggers exist on table
2019-01-17 19:14:54 INFO Estimated number of rows via EXPLAIN: 2
2019-01-17 19:14:54 DEBUG Potential unique keys in gh_ost_test: [PRIMARY (auto_increment): [id]; has nullable: false]
2019-01-17 19:14:54 INFO Master forced to be 127.0.0.1:18822
2019-01-17 19:14:54 INFO --test-on-replica or --migrate-on-replica given. Will not execute on master 127.0.0.1:18822 but rather on replica lo:18823 itself
2019-01-17 19:14:54 INFO log_slave_updates validated on 127.0.0.1:18823
2019-01-17 19:14:54 INFO connection validated on 127.0.0.1:18823
2019-01-17 19:14:54 DEBUG Streamer binlog coordinates: mysql-bin.000001:251772
2019/01/17 19:14:54 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql 127.0.0.1 18823 gh-ost   false false <nil>}
2019-01-17 19:14:54 INFO Connecting binlog streamer at mysql-bin.000001:251772
2019/01/17 19:14:54 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000001, 251772)
2019/01/17 19:14:54 binlogsyncer.go:139: [info] register slave for master server 127.0.0.1:18823
2019-01-17 19:14:54 DEBUG Beginning streaming
2019/01/17 19:14:54 binlogsyncer.go:573: [info] rotate to (mysql-bin.000001, 251772)
2019-01-17 19:14:54 INFO rotate to next log from mysql-bin.000001:0 to mysql-bin.000001
2019-01-17 19:14:54 INFO connection validated on 127.0.0.1:18823
2019-01-17 19:14:54 INFO connection validated on 127.0.0.1:18823
2019-01-17 19:14:54 INFO will use time_zone='SYSTEM' on applier
2019-01-17 19:14:54 INFO Examining table structure on applier
2019-01-17 19:14:54 INFO Applier initiated on lo:18823, version 5.7.21-log
2019-01-17 19:14:54 INFO Dropping table `test`.`_gh_ost_test_gho`
2019-01-17 19:14:54 INFO Table dropped
2019-01-17 19:14:54 INFO Dropping table `test`.`_gh_ost_test_del`
2019-01-17 19:14:54 INFO Table dropped
2019-01-17 19:14:54 INFO Dropping table `test`.`_gh_ost_test_ghc`
2019-01-17 19:14:54 INFO Table dropped
2019-01-17 19:14:54 INFO Creating changelog table `test`.`_gh_ost_test_ghc`
2019-01-17 19:14:54 INFO Changelog table created
2019-01-17 19:14:54 INFO Creating ghost table `test`.`_gh_ost_test_gho`
2019-01-17 19:14:54 INFO Ghost table created
2019-01-17 19:14:54 INFO Altering ghost table `test`.`_gh_ost_test_gho`
2019-01-17 19:14:54 DEBUG ALTER statement: alter /* gh-ost */ table `test`.`_gh_ost_test_gho` engine=innodb
2019-01-17 19:14:54 INFO Ghost table altered
2019-01-17 19:14:54 INFO Intercepted changelog state GhostTableMigrated
2019-01-17 19:14:54 INFO Waiting for ghost table to be migrated. Current lag is 0s
2019-01-17 19:14:54 DEBUG ghost table migrated
2019-01-17 19:14:54 INFO Handled changelog state GhostTableMigrated
2019-01-17 19:14:54 DEBUG Potential unique keys in _gh_ost_test_gho: [PRIMARY (auto_increment): [id]; has nullable: false]
2019-01-17 19:14:54 INFO Chosen shared unique key is PRIMARY
2019-01-17 19:14:54 INFO Shared columns are id,i,bi,iu,biu
2019-01-17 19:14:54 INFO Listening on unix socket file: /tmp/gh-ost.test.sock
2019-01-17 19:14:54 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on
2019-01-17 19:14:54 DEBUG Reading migration range according to key: PRIMARY
2019-01-17 19:14:54 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while
2019-01-17 19:14:54 INFO Migration min values: [1]
2019-01-17 19:14:54 DEBUG Reading migration range according to key: PRIMARY
2019-01-17 19:14:54 INFO Exact number of rows via COUNT: 2
2019-01-17 19:14:54 INFO Migration max values: [2]
2019-01-17 19:14:54 INFO Waiting for first throttle metrics to be collected
2019-01-17 19:14:54 INFO First throttle metrics collected
2019-01-17 19:14:54 DEBUG Operating until row copy is complete
# Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho`
# Migrating lo:18823; inspecting lo:18823; executing on lo
# Migration started at Thu Jan 17 19:14:54 +0000 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-01-17 19:14:54 DEBUG Getting nothing in the write queue. Sleeping...
Copy: 0/2 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000001:254262; State: migrating; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 2/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000001:259463; State: throttled, throttle-query; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 4/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin.000001:264804; State: throttled, throttle-query; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 6/1000; Time: 3s(total), 3s(copy); streamer: mysql-bin.000001:269369; State: throttled, throttle-query; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 8/1000; Time: 4s(total), 4s(copy); streamer: mysql-bin.000001:274322; State: throttled, throttle-query; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 10/1000; Time: 5s(total), 5s(copy); streamer: mysql-bin.000001:280020; State: throttled, throttle-query; ETA: N/A
2019-01-17 19:14:59 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2019-01-17 19:14:59 DEBUG Issued INSERT on range: [1]..[2]; iteration: 0; chunk-size: 100
2019-01-17 19:14:59 DEBUG Iteration complete: no further range to iterate
2019-01-17 19:14:59 DEBUG Getting nothing in the write queue. Sleeping...
2019-01-17 19:14:59 INFO Row copy complete
Copy: 2/2 100.0%; Applied: 10; Backlog: 0/1000; Time: 5s(total), 5s(copy); streamer: mysql-bin.000001:282589; State: migrating; ETA: due
2019-01-17 19:14:59 DEBUG checking for cut-over postpone
2019-01-17 19:14:59 DEBUG checking for cut-over postpone: complete
2019-01-17 19:14:59 DEBUG testing on replica. Stopping replication IO thread
2019-01-17 19:14:59 INFO Stopping replication IO thread
2019-01-17 19:14:59 INFO Replication IO thread stopped
2019-01-17 19:14:59 INFO Verifying SQL thread is stopped
2019-01-17 19:14:59 INFO SQL thread stopped
2019-01-17 19:14:59 INFO Replication IO thread at mysql-bin.000001:81656. SQL thread is at mysql-bin.000001:81656
2019-01-17 19:14:59 INFO Grabbing voluntary lock: gh-ost.121.lock
2019-01-17 19:14:59 INFO Setting LOCK timeout as 6 seconds
2019-01-17 19:14:59 INFO Looking for magic cut-over table
2019-01-17 19:14:59 INFO Creating magic cut-over table `test`.`_gh_ost_test_del`
2019-01-17 19:14:59 INFO Magic cut-over table created
2019-01-17 19:14:59 INFO Locking `test`.`gh_ost_test`, `test`.`_gh_ost_test_del`
2019-01-17 19:14:59 INFO Tables locked
2019-01-17 19:14:59 INFO Session locking original & magic tables is 121
2019-01-17 19:14:59 INFO Writing changelog state: AllEventsUpToLockProcessed:1547752499990225802
2019-01-17 19:14:59 INFO Intercepted changelog state AllEventsUpToLockProcessed
2019-01-17 19:14:59 INFO Handled changelog state AllEventsUpToLockProcessed
2019-01-17 19:14:59 INFO Waiting for events up to lock
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 173 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc420022280)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc4201b2de0, 0x6139d0, 0xc4201d8f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc4201b2de0, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 229 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202f41e0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc42007df90, 0x6139d0, 0xc4202f9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc42007df90, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 231 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202f42d0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc420044020, 0x6139d0, 0xc4202f9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc420044020, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 175 [running]:
runtime/debug.Stack(0x5c, 0xc0, 0xc4200e01e0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc420468910, 0x6139d0, 0xc4201d8f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc420468910, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 233 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202f43c0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc4200440c0, 0x6139d0, 0xc4202f9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc4200440c0, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 214 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202c8050)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc42023b9d0, 0x6139d0, 0xc42003ff90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc42023b9d0, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 235 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202c8140)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc42023bae0, 0x6139d0, 0xc4202f9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc42023bae0, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 217 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202c8230)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc42023bb80, 0x6139d0, 0xc4202f9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc42023bb80, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 176 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202f44b0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc420044230, 0x6139d0, 0xc4201d9f90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc420044230, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
2019-01-17 19:15:00 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
goroutine 177 [running]:
runtime/debug.Stack(0x5c, 0x180, 0xc4202c8320)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x2, 0x944d00, 0xc42023bc10, 0x6139d0, 0xc4201daf90)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x944d00, 0xc42023bc10, 0x0, 0x944d00)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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(0x1, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:145 +0xca
created by github.com/github/gh-ost/go/logic.(*Throttler).collectReplicationLag
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/throttler.go:167 +0xdd
Copy: 2/2 100.0%; Applied: 10; Backlog: 1/1000; Time: 6s(total), 5s(copy); streamer: mysql-bin.000001:287582; State: migrating; ETA: due
2019-01-17 19:15:00 DEBUG Getting nothing in the write queue. Sleeping...
2019-01-17 19:15:00 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1547752499990225802
2019-01-17 19:15:00 INFO Done waiting for events up to lock; duration=961.33092ms
# Migrating `test`.`gh_ost_test`; Ghost table is `test`.`_gh_ost_test_gho`
# Migrating lo:18823; inspecting lo:18823; executing on lo
# Migration started at Thu Jan 17 19:14:54 +0000 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), 5s(copy); streamer: mysql-bin.000001:288431; State: migrating; ETA: due
2019-01-17 19:15:00 INFO Setting RENAME timeout as 3 seconds
2019-01-17 19:15:00 INFO Session renaming tables is 117
2019-01-17 19:15:00 INFO Looking for magic cut-over table
2019-01-17 19:15:00 INFO Will now proceed to drop magic table and unlock tables
2019-01-17 19:15:00 INFO Dropping magic cut-over table
2019-01-17 19:15:00 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-01-17 19:15:00 INFO Renaming back both tables
2019-01-17 19:15:00 INFO Releasing lock from `test`.`gh_ost_test`, `test`.`_gh_ost_test_del`
2019-01-17 19:15:00 INFO Tables unlocked
2019-01-17 19:15:00 INFO Tables renamed
2019-01-17 19:15:00 DEBUG testing on replica. Starting replication IO thread after cut-over failure
2019-01-17 19:15:00 INFO Starting replication IO thread
2019-01-17 19:15:00 INFO Replication IO thread started
2019-01-17 19:15:00 INFO Verifying SQL thread is running
2019-01-17 19:15:01 INFO SQL thread started
2019-01-17 19:15:01 INFO Replication started
2019-01-17 19:15:01 INFO Removing socket file: /tmp/gh-ost.test.sock
2019-01-17 19:15:01 INFO Tearing down inspector
2019-01-17 19:15:01 FATAL Cannot find process. Hints: metadata lock, rename
goroutine 38 [running]:
runtime/debug.Stack(0x4b, 0x180, 0xc420160280)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/home/kburgess/gowork/src/github.com/github/gh-ost/.vendor/go19/go/src/runtime/debug/stack.go:16 +0x22
github.com/github/gh-ost/vendor/github.com/outbrain/golib/log.logErrorEntry(0x0, 0x944d00, 0xc420468bf0, 0x1, 0x101)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.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.Fatale(0x944d00, 0xc420468bf0, 0x0, 0x0)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/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(0xc42014c090)
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/migrator.go:252 +0x6a
created by github.com/github/gh-ost/go/logic.(*Migrator).Migrate
	/home/kburgess/gowork/src/github.com/github/gh-ost/.gopath/src/github.com/github/gh-ost/go/logic/migrator.go:323 +0x26e
+ FAIL

I can see that the test you wrote passed, but how might I inspect the table it created to verify your test syntax with the test reproduction steps I gave you above? see, I need to validate that:

create table gh_ost_test (
  id bigint auto_increment,
  val bigint not null,
  primary key(id)
) auto_increment=1;

is the same as

CREATE TABLE ghost_overflow_test (primary_key BIGINT(20) NOT NULL, 
test_id BIGINT(20) NOT NULL, 
PRIMARY KEY (primary_key));

[shlomi-noach]

Hi, I'm actually running tests on MacOS.

What you need, and this isn't well documented:

• To setup your own replication topology (I recommend https://github.com/datacharmer/dbdeployer)
• setup aliases or scripts called gh-ost-test-mysql-master and gh-ost-test-mysql-replica that will connect to the master and replica, respectively. Here's my setup:

  $ cat /Users/shlomi-noach/bin/gh-ost-test-mysql-master
  #!/bin/bash
  
  /Users/shlomi-noach/sandboxes/rsandbox_mysql-5_7_17/m "$@"
  

As per your 2nd question, "how might I inspect the table it created to verify your test syntax with the test reproduction steps I gave you above?", you will want to look at the Replica server, into test.gh_ost_test and test._gh_ost_test_gho.

Last,

I need to validate that: .. is the same as ...

It is indeed the same. Only thing that changed are the names, but otherwise it's the exact same table definition.

[evanelias]

18446744073709551615 is 2^64-1, which exceeds the max value of a signed BIGINT. @kwburgess, are you getting a WARNING after that insert? What sql_mode are you using? (try SELECT @@session.sql_mode, @@global.sql_mode for more insight) What does select * from ghost_overflow_test; show if run before gh-ost?

[RainbowDashy]

I'm using

+-----------+
| @@version |
+-----------+
| 8.0.27    |
+-----------+

And I cannot insert it into the table following your steps.

mysql> CREATE TABLE ghost_overflow_test (primary_key BIGINT(20) NOT NULL,
    -> test_id BIGINT(20) NOT NULL,
    -> PRIMARY KEY (primary_key));
Query OK, 0 rows affected, 2 warnings (0.01 sec)

mysql> show warnings;
+---------+------+------------------------------------------------------------------------------+
| Level   | Code | Message                                                                      |
+---------+------+------------------------------------------------------------------------------+
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
| Warning | 1681 | Integer display width is deprecated and will be removed in a future release. |
+---------+------+------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

mysql> INSERT INTO ghost_overflow_test VALUES (1,18446744073709551615);
ERROR 1264 (22003): Out of range value for column 'test_id' at row 1
mysql> select * from ghost_overflow_test;
Empty set (0.00 sec)

I guess that it's not a problem caused by gh-ost.