StreamEvents encountered unexpected error: Err: runtime error: index out of range #268

palexvs · 2016-10-12T22:25:57Z

I tried to migrate table with 200M records and I it crashed after 24 hours on 89% with exception runtime error: index out of range. I did the same migration on staging successfully.

I use MySQL 5.7.11 on AWS RDS
Run gh-ost v1.0.20 on Ubuntu 14.04

./gh-ost \
  --assume-rbr \
  --max-load=Threads_running=25 \
  --critical-load=Threads_running=1000 \
  --chunk-size=1000 \
  --nice-ratio=2 \
  --throttle-control-replicas='sql02.xxx.us-east-1.rds.amazonaws.com' \
  --max-lag-millis=2000 \
  --host='sql01.xxx.us-east-1.rds.amazonaws.com' \
  --user='root' \
  --password='***' \
  --database='production' \
  --table='origins' \
  --verbose \
  --alter="CHANGE COLUMN deprecated_order_date deprecated_order_date datetime" \
  --allow-on-master \
  --cut-over=default \
  --exact-rowcount \
  --default-retries=120 \
  --panic-flag-file=/tmp/ghost.panic.flag \
  --postpone-cut-over-flag-file=/tmp/ghost.postpone.flag \
  --throttle-additional-flag-file=/tmp/ghost.throttle.flag \
  --initially-drop-ghost-table \
  --execute


# chunk-size: 3000; max-lag-millis: 2000ms; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 1.000000
# throttle-additional-flag-file: /tmp/ghost.throttle.flag
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag [set]
# panic-flag-file: /tmp/ghost.panic.flag
# Serving on unix socket: /tmp/gh-ost.production.origins.sock
Copy: 207141700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m0s(total), 24h31m18s(copy); streamer: mysql-bin-changelog.117854:38741575; State: migrating; ETA: 2h57m3s
2016-10-12 20:43:45 INFO Reconnecting... Will resume at mysql-bin-changelog.117854:38741318
2016-10-12 20:43:45 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-12 20:43:45 INFO Connecting binlog streamer at mysql-bin-changelog.117854:4
2016-10-12 20:43:45 INFO rotate to next log name: mysql-bin-changelog.117854
Copy: 207153700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m5s(total), 24h31m23s(copy); streamer: mysql-bin-changelog.117854:1876416; State: migrating; ETA: 2h56m58s
2016-10-12 20:43:48 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 457822 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc8204ffcc0, 0xc82045a900)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000a090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82040129a, 0x7d, 0x566, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8203f7400, 0xc82040129a, 0x7d, 0x566, 0xa00f6,
Copy: 207168700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m10s(total), 24h31m28s(copy); streamer: mysql-bin-changelog.117854:38738560; State: migrating; ETA: 2h56m51s
2016-10-12 20:43:53 INFO Reconnecting... Will resume at mysql-bin-changelog.117854:38741318
2016-10-12 20:43:53 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-12 20:43:53 INFO Connecting binlog streamer at mysql-bin-changelog.117854:4
2016-10-12 20:43:53 INFO rotate to next log name: mysql-bin-changelog.117854
Copy: 207180700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m15s(total), 24h31m33s(copy); streamer: mysql-bin-changelog.117854:32530931; State: migrating; ETA: 2h56m46s
2016-10-12 20:43:55 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 457874 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc820221b80, 0xc8204ca9c0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000a090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc820360c9a, 0x7d, 0x566, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8203f7b80, 0xc820360c9a, 0x7d, 0x566, 0xa00f6,
Copy: 207198700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m20s(total), 24h31m38s(copy); streamer: mysql-bin-changelog.117854:38739132; State: migrating; ETA: 2h56m38s
2016-10-12 20:44:00 INFO Reconnecting... Will resume at mysql-bin-changelog.117854:38741318
2016-10-12 20:44:00 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-12 20:44:00 INFO Connecting binlog streamer at mysql-bin-changelog.117854:4
2016-10-12 20:44:00 INFO rotate to next log name: mysql-bin-changelog.117854
2016-10-12 20:44:03 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 457902 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc8200fc5c0, 0xc8204cad80)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000a090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc8201a6c9a, 0x7d, 0x566, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8203f65a0, 0xc8201a6c9a, 0x7d, 0x566, 0xa00f6,
Copy: 207210700/232068606 89.3%; Applied: 1374017; Backlog: 0/100; Time: 24h40m25s(total), 24h31m43s(copy); streamer: mysql-bin-changelog.117854:38741575; State: migrating; ETA: 2h56m33s
2016-10-12 20:44:08 FATAL {%!!(MISSING)d(string=mysql-bin-changelog.117854) 38741318 0} successive failures in streamer reconnect at coordinates %!!(MISSING)v(MISSING)

The text was updated successfully, but these errors were encountered:

shlomi-noach · 2016-10-13T05:39:21Z

Can you please paste the table definition? Feel free to anonymize column names

shlomi-noach · 2016-10-13T07:01:32Z

Similar: #179

shlomi-noach · 2016-10-13T07:13:41Z

@palexvs I'd like to negate a few potential factors, namely:

connections getting killed
traffic going stale.

As per #179 , are you using HEARTBEAT_PERIOD on your replication setup?

Is there a mechanism to kill connections on your setup?

palexvs · 2016-10-13T17:55:55Z

connections getting killed

Is it connection to slave or to master? I'm sure that we don't kill any connection manually and we do not have any automatic mechanism for that.

traffic going stale.

Sorry, I don't understand what does it mean. Please, can you explain?

There is table definition:

CREATE TABLE `origins` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c1` varchar(255) NOT NULL,
  `c2` int(11) NOT NULL,
  `c3` decimal(25,2) NOT NULL,
  `deprecated_order_date` datetime NOT NULL,
  `c5` varchar(255) DEFAULT NULL,
  `c6` varchar(45) DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  `c9` int(11) DEFAULT NULL,
  `c10` int(11) DEFAULT NULL,
  `c11` tinyint(1) NOT NULL DEFAULT '0',
  `c12` varchar(25) DEFAULT NULL,
  `c13` int(11) NOT NULL,
  `c14` int(11) NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `index_origins_on_c2_and_c1_and_c12_and_event` (`c2`,`c1`,`c12`,`c14`),
  KEY `index_origins_on_c9` (`c9`),
  KEY `index_origins_on_created_at_and_c2` (`created_at`,`c2`),
  KEY `index_origins_on_c10` (`c10`),
  KEY `index_origins_on_c12` (`c12`),
  KEY `index_origins_on_c13` (`c13`),
  KEY `index_origins_on_c2_and_c12_and_created_at_and_c3` (`c2`,`c12`,`created_at`,`c3`) USING BTREE,
  KEY `index_origins_on_c11_and_created_at_and_c2_and_c12` (`c11`,`created_at`,`c2`,`c12`) USING BTREE,
  KEY `index_origins_on_c2_and_c12_and_c13_and_created` (`c2`,`c12`,`c13`,`created_at`),
  KEY `index_origins_on_c14` (`c14`)
) ENGINE=InnoDB AUTO_INCREMENT=250232480 DEFAULT CHARSET=utf8

In the migration, I tried to remove NOT NULL from column deprecated_order_date.

I don't manage slave, it does for me RDS. There is some info from slave:

mysql> select * from mysql.slave_master_info\G;
*************************** 1. row ***************************
       Number_of_lines: 25
       Master_log_name: mysql-bin-changelog.118105
        Master_log_pos: 8079113
                  Host: X.X.X.X
             User_name: rdsrepladmin
         User_password: ******
                  Port: 3306
         Connect_retry: 60
           Enabled_ssl: 0
                Ssl_ca: 
            Ssl_capath: 
              Ssl_cert: 
            Ssl_cipher: 
               Ssl_key: 
Ssl_verify_server_cert: 0
             Heartbeat: 30
                  Bind: 
    Ignored_server_ids: 0
                  Uuid: xxx-xxx-xxx-xxx-xxx
           Retry_count: 86400
               Ssl_crl: 
           Ssl_crlpath: 
 Enabled_auto_position: 0
           Tls_version: 
          Channel_name: 
1 row in set (0.01 sec)

I tried to migrate again and got the same error after 8 hours on 51%:

        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82022805e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8200b4960, 0xc82022805e, 0x3, 0x5a2, 0xa00f6, 0
Copy: 105777000/206709093 51.2%; Applied: 557965; Backlog: 0/100; Time: 9h23m20s(total), 9h23m20s(copy); streamer: mysql-bin-changelog.117999:26761533; State: migrating; ETA: 8h57m31s
2016-10-13 08:36:35 INFO Reconnecting... Will resume at mysql-bin-changelog.117999:26764024
2016-10-13 08:36:35 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-13 08:36:35 INFO Connecting binlog streamer at mysql-bin-changelog.117999:4
2016-10-13 08:36:35 INFO rotate to next log name: mysql-bin-changelog.117999
Copy: 105798000/206709093 51.2%; Applied: 557965; Backlog: 0/100; Time: 9h23m25s(total), 9h23m25s(copy); streamer: mysql-bin-changelog.117999:26170224; State: migrating; ETA: 8h57m23s
2016-10-13 08:36:37 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 137735 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc820195d80, 0xc820230840)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000c090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82019e05e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8201cd2c0, 0xc82019e05e, 0x3, 0x5a2, 0xa00f6, 0
Copy: 105810000/206709093 51.2%; Applied: 557965; Backlog: 0/100; Time: 9h23m30s(total), 9h23m30s(copy); streamer: mysql-bin-changelog.117999:26761564; State: migrating; ETA: 8h57m20s
2016-10-13 08:36:42 INFO Reconnecting... Will resume at mysql-bin-changelog.117999:26764024
2016-10-13 08:36:42 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-13 08:36:42 INFO Connecting binlog streamer at mysql-bin-changelog.117999:4
2016-10-13 08:36:42 INFO rotate to next log name: mysql-bin-changelog.117999
2016-10-13 08:36:44 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 137780 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc8201b9f00, 0xc8202303c0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000c090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82038ec5e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc82007cdc0, 0xc82038ec5e, 0x3, 0x5a2, 0xa00f6, 0
Copy: 105828000/206709093 51.2%; Applied: 557965; Backlog: 0/100; Time: 9h23m35s(total), 9h23m35s(copy); streamer: mysql-bin-changelog.117999:26760584; State: migrating; ETA: 8h57m14s
2016-10-13 08:36:49 INFO Reconnecting... Will resume at mysql-bin-changelog.117999:26764024
2016-10-13 08:36:49 INFO Registering replica at sql01.xxx.us-east-1.rds.amazonaws.com:3306
2016-10-13 08:36:49 INFO Connecting binlog streamer at mysql-bin-changelog.117999:4
2016-10-13 08:36:49 INFO rotate to next log name: mysql-bin-changelog.117999
2016-10-13 08:36:51 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 137807 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc820149fa0, 0xc820264540)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x797b60, 0xc82000c090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc8200da65e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc82010cd20, 0xc8200da65e, 0x3, 0x5a2, 0xa00f6, 0
Copy: 105840000/206709093 51.2%; Applied: 557965; Backlog: 0/100; Time: 9h23m40s(total), 9h23m40s(copy); streamer: mysql-bin-changelog.117999:26764107; State: migrating; ETA: 8h57m11s
2016-10-13 08:36:56 FATAL {%!!(MISSING)d(string=mysql-bin-changelog.117999) 26764024 0} successive failures in streamer reconnect at coordinates %!!(MISSING)v(MISSING)

palexvs · 2016-10-13T21:06:02Z

I just got this exception in the third time (after 2 hours of migration that stoped on 17.5%). But I can't reproduce it on staging with the same configuration but without real load.

palexvs · 2016-10-14T00:00:18Z

There is an output when run with --debug --stack

....
2016-10-13 23:58:37 DEBUG Skipping handled query at mysql-bin-changelog.118202:68962384
2016-10-13 23:58:37 DEBUG Skipping handled query at mysql-bin-changelog.118202:68962798
2016-10-13 23:58:37 DEBUG Skipping handled query at mysql-bin-changelog.118202:68963213
2016-10-13 23:58:37 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 14539 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc8202e4240, 0xc820114d80)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x798ea0, 0xc82000a090)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82036465e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8204cbf40, 0xc82036465e, 0x3, 0x5a2, 0xa00f6, 0x
2016-10-13 23:58:38 DEBUG Issued INSERT on range: [9951659]..[9952717]; iteration: 9562; chunk-size: 1000
....

shlomi-noach · 2016-10-14T13:42:09Z

Is it connection to slave or to master? I'm sure that we don't kill any connection manually and we do not have any automatic mechanism for that.

From your command line I see you connect directly to master, correct? In which case the answer is "to master"

traffic going stale

long seconds where there's literally no traffic on the database. I suspect this is not the case, and anyway I see your timeouts are very quick.

Question: will you be able to build your own binary given that I publish an experimental branch? You will need to clone the repo and ./build sh to generate a binary.

palexvs · 2016-10-14T20:29:02Z

Question: will you be able to build your own binary given that I publish an experimental branch? You will need to clone the repo and ./build sh to generate a binary.

Yes. Which branch I should try?

shlomi-noach · 2016-10-17T17:27:49Z

I will of course let you know once I create it

palexvs · 2016-10-24T04:36:37Z

I tried to migrate table 10 times and always get the same error unexpected error: Err: runtime error: index out of range. It happens in different time (sometimes on 1%, sometimes on 50%, sometimes on 99%, ...), with different load (different nice-ratio and chunk-size). No idea how to resolve the issue

This ticket looks similar: go-sql-driver/mysql#467 but I have not found any requests with ? in my sql_queries.log

The are errors from the last 2 attempts:

Copy: 133042000/230731904 57.7%; Applied: 733059; Backlog: 2/100; Time: 15h45m30s(total), 15h45m30s(copy); streamer: mysql-bin-changelog.121115:5175397; State: migrating; ETA: 11h34m15s
Copy: 133093500/230731904 57.7%; Applied: 733633; Backlog: 2/100; Time: 15h46m0s(total), 15h46m0s(copy); streamer: mysql-bin-changelog.121115:11560193; State: migrating; ETA: 11h33m59s
2016-10-23 20:31:10 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 13 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc82000b720, 0xc820112480)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x798ea0, 0xc82000c080)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82022a05e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc8201c6d20, 0xc82022a05e, 0x3, 0x5a2, 0xa00f6, 0x0,
Copy: 133133000/230731904 57.7%; Applied: 733949; Backlog: 0/100; Time: 15h46m20s(total), 15h46m20s(copy); streamer: mysql-bin-changelog.121115:15175743; State: migrating; ETA: 11h33m45s
2016-10-23 20:31:15 INFO Reconnecting... Will resume at mysql-bin-changelog.121115:15175647

Copy: 34779000/231377969 15.0%; Applied: 236135; Backlog: 0/100; Time: 3h30m0s(total), 3h30m0s(copy); streamer: mysql-bin-changelog.121165:53342039; State: migrating; ETA: 19h47m5s
2016-10-24 00:43:18 INFO StreamEvents encountered unexpected error: Err: runtime error: index out of range
 Stack: goroutine 16 [running]:
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql.Pstack(0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/mysql/util.go:18 +0x7b
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*BinlogSyncer).onStream.func1(0xc82000bf60, 0xc8200d80c0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:488 +0x66
panic(0x798ea0, 0xc82000c080)
        /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:443 +0x4e9
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.decodeDecimal(0xc82042385e, 0x3, 0x5a2, 0x0, 0xa, 0x13, 0x5, 0x0, 0x0)
        /Users/shlomi-noach/dev/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/row_event.go:513 +0xcc7
github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication.(*RowsEvent).decodeValue(0xc82007dcc0, 0xc82042385e, 0x3, 0x5a2, 0xa00f6, 0x0, 
Copy: 34816000/231377969 15.0%; Applied: 236424; Backlog: 0/100; Time: 3h30m15s(total), 3h30m15s(copy); streamer: mysql-bin-changelog.121165:57578299; State: migrating; ETA: 19h47m1s

siddontang · 2016-10-24T05:08:47Z

Maybe go-mysql-org/go-mysql#69 can fix it.

shlomi-noach · 2016-10-24T05:30:23Z

@siddontang that was my intention, thank you!

shlomi-noach · 2016-10-24T12:02:27Z

@palexvs would you mind trying out #286? This fetches latest go-mysql library, which potentially fixes your issue

palexvs · 2016-10-24T18:17:22Z

@shlomi-noach Thank you. I run migration using gh-ost from update-go-mysql branch a few hours ago and I hope I will get results in ~28 hours.

palexvs · 2016-10-24T23:44:35Z

@shlomi-noach @siddontang migration has failed with error:

2016/10/24 23:37:57 row_event.go:267: [fatal] parse rows event panic runtime error: index out of range, data "F\x01\x00\x00\x00\x00\x01\x00\x02\x00\x0f\xff\xff8\x89\xdd|\r\x00x<\x00\x00\x10\x00PredefinedMetric\x06\x00offers\x06\x00Offers\x01\x00\x00\x00\x00\x99\x9a\xb1yr\x99\x9a\xb1yr\x80\x00\x00\x00\x00", parsed rows &replication.RowsEvent{Version:2, tableIDSize:6, tables:map[uint64]*replication.TableMapEvent{0x146:(*replication.TableMapEvent)(0xc8200a1540)}, needBitmap2:false, Table:(*replication.TableMapEvent)(0xc8200a1540), TableID:0x146, Flags:0x1, ExtraData:[]uint8{}, ColumnCount:0xf, ColumnBitmap1:[]uint8{0xff, 0xff}, ColumnBitmap2:[]uint8(nil), Rows:[][]interface {}(nil)}, table map &replication.TableMapEvent{tableIDSize:6, TableID:0x146, Flags:0x1, Schema:[]uint8{0x70, 0x72, 0x6f, 0x64, 0x75, 0x63, 0x74, 0x69, 0x6f, 0x6e}, Table:[]uint8{0x6d, 0x65, 0x74, 0x72, 0x69, 0x63, 0x73}, ColumnCount:0xf, ColumnType:[]uint8{0x3, 0x3, 0xf, 0x3, 0x3, 0x3, 0xf, 0xf, 0xfc, 0x1, 0x3, 0xf5, 0x12, 0x12, 0xf6}, ColumnMeta:[]uint16{0x0, 0x0, 0x2fd, 0x0, 0x0, 0x0, 0x2fd, 0x2fd, 0x2, 0x0, 0x0, 0x0, 0x4, 0x0, 0xa}, NullBitmap:[]uint8{0x38, 0x39}}

I see one similar request in sql.log

[2016-10-24 23:37:49]   INSERT INTO `metrics` (`type`, `account_id`, `identifier`, `name`, `visible`, `result_type`, `priority`, `created_at`, `updated_at`) VALUES ('PredefinedMetric', 15480, 'offers', 'Offers', 1, 0, 0, '2016-10-24 23:37:50', '2016-10-24 23:37:50')

but it is valid insert and I' trying to migrate another table

siddontang · 2016-10-25T10:14:32Z

Hi @palexvs

Can we give me the detailed table schema? Do you use the #286 ?

palexvs · 2016-10-25T15:44:16Z

Do you use the #286 ?

yes

Can we give me the detailed table schema?

There 100% reproduce:

CREATE TABLE `t10` (
  `c1` json DEFAULT NULL,
  `c2` decimal(10,0)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `t10` (`c2`) VALUES (1);

Insert crashes migration:

2016/10/25 23:06:47 row_event.go:267: [fatal] parse rows event panic runtime error: index out of range, data "@\x03\x00\x00\x00\x00\x01\x00\x02\x00\x02\xff\xfd\x80\x00\x00\x00\x01", parsed rows &replication.RowsEvent{Version:2, tableIDSize:6, tables:map[uint64]*replication.TableMapEvent{0x340:(*replication.TableMapEvent)(0xc8200a7540)}, needBitmap2:false, Table:(*replication.TableMapEvent)(0xc8200a7540), TableID:0x340, Flags:0x1, ExtraData:[]uint8{}, ColumnCount:0x2, ColumnBitmap1:[]uint8{0xff}, ColumnBitmap2:[]uint8(nil), Rows:[][]interface {}(nil)}, table map &replication.TableMapEvent{tableIDSize:6, TableID:0x340, Flags:0x1, Schema:[]uint8{0x70, 0x72, 0x6f, 0x64, 0x75, 0x63, 0x74, 0x69, 0x6f, 0x6e}, Table:[]uint8{0x74, 0x31, 0x30}, ColumnCount:0x2, ColumnType:[]uint8{0xf5, 0xf6}, ColumnMeta:[]uint16{0x0, 0x40a}, NullBitmap:[]uint8{0x3}}

siddontang · 2016-10-26T07:36:13Z

Thank you @palexvs

I will see it.

siddontang · 2016-10-26T08:11:40Z

Hi @palexvs
Seem that we have not supported json type.

shlomi-noach · 2016-10-26T08:27:16Z

@palexvs @siddontang I will meanwhile add this to known limitations

siddontang · 2016-10-26T12:39:50Z

I will try to support 5.7 json and geometry later, maybe this weekend.

shlomi-noach · 2016-10-31T09:48:33Z

reference: JSON support PR go-mysql-org/go-mysql#88

palexvs · 2016-11-01T00:55:18Z

Thank you! Very much. I will try it with next migration in 1-2 weeks.
I just successfully finished a migration ... from 17th attempt

siddontang · 2016-11-01T03:09:49Z

Hi @shlomi-noach @palexvs

Sorry that I am too busy these days. Now I only support not panic for parsing the json field, but I have not supported converting MySQL binary json to readable json string so we can re-insert directly.
I will try to support it this week.

shlomi-noach · 2016-11-01T10:12:02Z

@siddontang take your time and enjoy life

shlomi-noach · 2016-11-02T09:43:38Z

Meanwhile documenting that JSON is unsupported: https://github.com/github/gh-ost/pull/305/files#diff-06311f5cbcfa9255bb9a7f4e8a0a227eR31

palexvs · 2017-02-27T20:22:18Z

https://github.com/siddontang/go-mysql (master) and have not got this issue anymore

shlomi-noach · 2017-02-27T20:35:00Z

See further notes in comment: #275 (comment)

palexvs · 2017-03-21T22:58:34Z

I tried v1.0.35 and I have not got this issue, so I close it
Thank you!

bbeaudreault · 2017-04-02T11:13:44Z

@shlomi-noach should docs be updated to express support for json columns? Not sure if that's what I'm gathering here, but seems like it.

shlomi-noach · 2017-06-21T06:28:07Z

@bbeaudreault sorry for this late response. Unfortunately gh-ost still does not support JSON. I'm likely to look into this in the near future.

palexvs mentioned this issue Oct 24, 2016

StreamEvents encountered unexpected error: Err: runtime error: index out of range go-mysql-org/go-mysql#83

Closed

siddontang mentioned this issue Oct 26, 2016

support json type go-mysql-org/go-mysql#87

Closed

palexvs closed this as completed Mar 21, 2017

shlomi-noach mentioned this issue Jun 21, 2017

FR: Support JSON datatype #434

Closed

shlomi-noach mentioned this issue Aug 22, 2017

Supporting JSON columns #473

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

StreamEvents encountered unexpected error: Err: runtime error: index out of range #268

StreamEvents encountered unexpected error: Err: runtime error: index out of range #268

palexvs commented Oct 12, 2016 •

edited

shlomi-noach commented Oct 13, 2016

shlomi-noach commented Oct 13, 2016

shlomi-noach commented Oct 13, 2016

palexvs commented Oct 13, 2016

palexvs commented Oct 13, 2016 •

edited

palexvs commented Oct 14, 2016 •

edited

shlomi-noach commented Oct 14, 2016

palexvs commented Oct 14, 2016 •

edited

shlomi-noach commented Oct 17, 2016

palexvs commented Oct 24, 2016

siddontang commented Oct 24, 2016

shlomi-noach commented Oct 24, 2016

shlomi-noach commented Oct 24, 2016

palexvs commented Oct 24, 2016 •

edited

palexvs commented Oct 24, 2016 •

edited

siddontang commented Oct 25, 2016

palexvs commented Oct 25, 2016 •

edited

siddontang commented Oct 26, 2016

siddontang commented Oct 26, 2016

shlomi-noach commented Oct 26, 2016

siddontang commented Oct 26, 2016

shlomi-noach commented Oct 31, 2016

palexvs commented Nov 1, 2016 •

edited

siddontang commented Nov 1, 2016

shlomi-noach commented Nov 1, 2016

shlomi-noach commented Nov 2, 2016

palexvs commented Feb 27, 2017

shlomi-noach commented Feb 27, 2017

palexvs commented Mar 21, 2017

bbeaudreault commented Apr 2, 2017

shlomi-noach commented Jun 21, 2017

StreamEvents encountered unexpected error: Err: runtime error: index out of range #268

StreamEvents encountered unexpected error: Err: runtime error: index out of range #268

Comments

palexvs commented Oct 12, 2016 • edited

shlomi-noach commented Oct 13, 2016

shlomi-noach commented Oct 13, 2016

shlomi-noach commented Oct 13, 2016

palexvs commented Oct 13, 2016

palexvs commented Oct 13, 2016 • edited

palexvs commented Oct 14, 2016 • edited

shlomi-noach commented Oct 14, 2016

palexvs commented Oct 14, 2016 • edited

shlomi-noach commented Oct 17, 2016

palexvs commented Oct 24, 2016

siddontang commented Oct 24, 2016

shlomi-noach commented Oct 24, 2016

shlomi-noach commented Oct 24, 2016

palexvs commented Oct 24, 2016 • edited

palexvs commented Oct 24, 2016 • edited

siddontang commented Oct 25, 2016

palexvs commented Oct 25, 2016 • edited

siddontang commented Oct 26, 2016

siddontang commented Oct 26, 2016

shlomi-noach commented Oct 26, 2016

siddontang commented Oct 26, 2016

shlomi-noach commented Oct 31, 2016

palexvs commented Nov 1, 2016 • edited

siddontang commented Nov 1, 2016

shlomi-noach commented Nov 1, 2016

shlomi-noach commented Nov 2, 2016

palexvs commented Feb 27, 2017

shlomi-noach commented Feb 27, 2017

palexvs commented Mar 21, 2017

bbeaudreault commented Apr 2, 2017

shlomi-noach commented Jun 21, 2017

palexvs commented Oct 12, 2016 •

edited

palexvs commented Oct 13, 2016 •

edited

palexvs commented Oct 14, 2016 •

edited

palexvs commented Oct 14, 2016 •

edited

palexvs commented Oct 24, 2016 •

edited

palexvs commented Oct 24, 2016 •

edited

palexvs commented Oct 25, 2016 •

edited

palexvs commented Nov 1, 2016 •

edited