github / gh-ost

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

Incorrect values when making column nullable #691

Open kwburgess opened 5 years ago

kwburgess commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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

kwburgess commented 5 years ago

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 commented 5 years ago

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 } 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 commented 5 years ago

Hi, I'm actually running tests on MacOS.

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

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 commented 5 years ago

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 commented 2 years ago

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.