gh-ost icon indicating copy to clipboard operation
gh-ost copied to clipboard
verified publisher icon github

StreamEvents encountered unexpected error ... Err: invalid json type 122

Open derekPNM opened this issue 4 years ago • 7 comments

We recently added some json datatype fields to our database . While running even a basic gh-ost migration (against a small , totally unrelated table of three records), we've run into issues with what appears to be gh-ost not being able to parse the json from the binlogs. The database values appear to be fine, other tools don't have an issue parsing or displaying them, and our production systems have no issue with the json we are creating), but as soon as there's a binlog event for one of these columns, gh-ost starts emitting errors and warnings and the migrations eventually stop processing.

We'll see the migration progressing as expected: Copy: 10348000/15658439 66.1%; Applied: 0; Backlog: 0/1000; Time: 25m0s(total), 25m0s(copy); streamer: mysql-bin-changelog.059183:109285857; Lag: 0.11s, State: migrating; ETA: 12m49s Copy: 10543000/15658439 67.3%; Applied: 0; Backlog: 0/1000; Time: 25m30s(total), 25m30s(copy); streamer: mysql-bin-changelog.059183:125594568; Lag: 0.11s, State: migrating; ETA: 12m22s [2021/05/26 16:06:25] [info] binlogsyncer.go:723 rotate to (mysql-bin-changelog.059184, 4) [2021/05/26 16:06:25] [info] binlogsyncer.go:723 rotate to (mysql-bin-changelog.059184, 4)

Then based on the output we are seeing (and we've replicated this in one of our labs) it looks like changes to the JSON values leads to errors like this: 2021-05-26 16:06:25 INFO rotate to next log from mysql-bin-changelog.059184:134246668 to mysql-bin-changelog.059184 2021-05-26 16:06:25 INFO rotate to next log from mysql-bin-changelog.059184:0 to mysql-bin-changelog.059184 Copy: 10733000/15658439 68.5%; Applied: 0; Backlog: 0/1000; Time: 26m0s(total), 26m0s(copy); streamer: mysql-bin-changelog.059184:7101260; Lag: 0.01s, State: migrating; ETA: 11m55s [2021/05/26 16:07:03] [error] binlogstreamer.go:77 close sync with err: Header &replication.EventHeader{Timestamp:0x60aed497, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x9ba, LogPos:0x132492d, Flags:0x0}, Data <bunch of private stuff we can't share, but we are working on a test case> , Err: invalid json type 122

followed by errors like: 2021-05-26 16:07:03 INFO StreamEvents encountered unexpected error: Header &replication.EventHeader{Timestamp:0x60aed497, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x9ba, LogPos:0x132492d, Flags:0x0}, Data <bunch of private stuff we can't share, but we are working on a test case> ", Err: invalid json type 122

and finally FATAL 121 successive failures in streamer reconnect at coordinates mysql-bin-changelog.059184:4

We upgraded to gh-ost v1.1.1 and are running on Amazon Aurora MySQL version 5.7.mysql_aurora.2.08.0

Has anyone seen this behaviour before?

Thank you kindly,

?d

derekPNM avatar May 26 '21 23:05 derekPNM

This looks to be an error in the underlying go-mysql library. Worth updating it.

shlomi-noach avatar May 27 '21 05:05 shlomi-noach

I'll be happy to have a test case so I can reproduce. Also, I won't be testing on Aurora MySQL, only on standard MySQL.

shlomi-noach avatar May 27 '21 05:05 shlomi-noach

Thank you. I'll work on providing you with a succinct test case soon.

derekPNM avatar May 27 '21 16:05 derekPNM

This is what we have used to replicate the issue:

  • create a reference table against which we will use gh-ost to add an empty column
CREATE TABLE reference_table (
  id INT NOT NULL AUTO_INCREMENT,
  sample_field VARCHAR(45) NULL,
  PRIMARY KEY (id)
  );

# put some data in
insert into reference_table (sample_field) values ('we are a simple field');
# check it just to make sure
select * from reference_table;
  • create a table with the JSON structures we are attempting to leverage
  • note we are using virtual columns, and one of the columns includes a json array
  • we've narrowed down the errors to this virtual generated column (json2_json_virtual) that includes a json array, but oddly enough we need to update the values for json2 multiple times for the behaviour to be exhibited in our labs
CREATE TABLE json_table (
  id INT NOT NULL AUTO_INCREMENT,
  json2 json NULL,
  json2_json_virtual json GENERATED ALWAYS AS (json_extract(json2,'$.json_in_json')) VIRTUAL
  , PRIMARY KEY (id)
);

  • this point you can start a gh-ost migration that adds a column to reference_table

  • we've found it useful to use a manual cutover so that gh-ost keeps on reading the binlogs for changes "ADD COLUMN ddh varchar(3) DEFAULT NULL"

  • insert a value to the json_table

insert into json_table (json2)
values
(
'{"our_string": "complete",  "json_in_json": [{"2021-05-27 08:36:59 -0700": [null, "complete"]}]}'
);

# we like to verify 
SELECT * FROM json_table;

  • at this point the migration is doing just fine and is waiting for manual cutover

  • let's update the json via update (we are a rails shop and this is the type of query that ActiveRecord sends to the database)

update json_table
 set json2 = '{"our_string": "complete",  "json_in_json": [{"2021-05-28 08:36:59 -0700": [null, "we are borg"]}, {"2021-05-29 08:36:59 -0700": ["we are borg", "you have been assimilated"]}]}'
where id = 1;

# we like to verify 
SELECT * FROM json_table;

  • at this point the migration is doing just fine and is waiting for manual cutover

  • let's update that json column again (same values as above, but with !! after "assimilated" so we can see the change to the row)

update json_table
 set json2 = '{"our_string": "complete",  "json_in_json": [{"2021-05-28 08:36:59 -0700": [null, "we are borg"]}, {"2021-05-29 08:36:59 -0700": ["we are borg", "you have been assimilated!!"]}]}'
where id = 1;
  • soon as the above statement is run, the migration writes out what follows below
  • the specific type of error we see depends on which json values we are updating, etc.. Original post had the error invalid json type but we this error is just as common Err: data len 152 < expected 154. We suspect there are two related errors, and we've only had time to replicate one of them
  • we've found it necessary to change the same row in json_table multiple times while the migration is running that leads to this error.
[2021/05/27 13:39:36] [error] binlogstreamer.go:77 close sync with err: Header &replication.EventHeader{Timestamp:0x60b00388, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x308, LogPos:0x251c9cb, Flags:0x0}, Data "[\x05\x00\x00\x00\x00\x01\x00\x02\x00\x03\xff\xff\xf8\x01\x00\x00\x00\xca\x00\x00\x00\x00\x02\x00\xc9\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x02\x00\x98\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00T\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x000\x00\f\n\x00\f\x16\x00\vwe are borg\x19you have been assimilated\x99\x00\x00\x00\x02\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated\xf8\x01\x00\x00\x00\xcc\x00\x00\x00\x00\x02\x00\xcb\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated!!\x9b\x00\x00\x00\x02\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated!!", Err: data len 152 < expected 154
2021-05-27 13:39:36 INFO StreamEvents encountered unexpected error: Header &replication.EventHeader{Timestamp:0x60b00388, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x308, LogPos:0x251c9cb, Flags:0x0}, Data "[\x05\x00\x00\x00\x00\x01\x00\x02\x00\x03\xff\xff\xf8\x01\x00\x00\x00\xca\x00\x00\x00\x00\x02\x00\xc9\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x02\x00\x98\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00T\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x000\x00\f\n\x00\f\x16\x00\vwe are borg\x19you have been assimilated\x99\x00\x00\x00\x02\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated\xf8\x01\x00\x00\x00\xcc\x00\x00\x00\x00\x02\x00\xcb\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated!!\x9b\x00\x00\x00\x02\x02\x00\x9a\x00\x00\n\x00\x00D\x00\x01\x00:\x00\v\x00\x19\x00\x02$\x002021-05-28 08:36:59 -0700\x02\x00\x16\x00\x04\x00\x00\f\n\x00\vwe are borg\x01\x00V\x00\v\x00\x19\x00\x02$\x002021-05-29 08:36:59 -0700\x02\x002\x00\f\n\x00\f\x16\x00\vwe are borg\x1byou have been assimilated!!", Err: data len 152 < expected 154

# we like to verify, and we'll see the update took just fine
SELECT * FROM json_table;

derekPNM avatar May 27 '21 21:05 derekPNM

Thank you! I will look into this.

shlomi-noach avatar May 28 '21 05:05 shlomi-noach

Looking into this in downstream PR https://github.com/openark/gh-ost/pull/19

shlomi-noach avatar May 31 '21 08:05 shlomi-noach

I am facing the same issue, but with error Err: invalid json type 97.

  • gh-ost 1.1.5
  • command
gh-ost \
--max-load=Threads_running=250 \
--critical-load=Threads_running=1000 \
--chunk-size=1000 \
--throttle-control-replicas="vm-dev-infra-mysql-1:3307" \
--max-lag-millis=1500 \
--user="ghost" \
--password="xxx" \
--host=127.0.0.1 \
--port=3307 \
--allow-on-master \
--database="bigbang" \
--table="sales_quote" \
--verbose \
--alter="MODIFY freegift_option text column_format compressed, MODIFY warehouse_data text column_format compressed, MODIFY extra json DEFAULT NULL column_format compressed" \
--switch-to-rbr \
--allow-master-master \
--cut-over=default \
--concurrent-rowcount \
--default-retries=120 \
--panic-flag-file=/tmp/ghost.panic.flag \
--postpone-cut-over-flag-file=/tmp/ghost.postpone.flag \
--hooks-path=/tiki/dba-tools/gh-ost/hooks/ \
--execute --ok-to-drop-table

v0112358 avatar Apr 08 '23 08:04 v0112358