Adding test to validate JSON reported issue

[shlomi-noach]

Validating and potentially fixing github#976

Initial commit adds a local test that attempts to reproduce github#976. We expect that test to fail.

cc @derekPNM

[shlomi-noach]

Hmmm sadly the tests pass and do not reproduce the error depicted in github#976

@derekPNM would you like to verify the tests introduced here are legit?

[shlomi-noach]

Either the test is not representative enough, or this could be a Amazon Aurora problem (issue reports Amazon Aurora MySQL version 5.7.mysql_aurora.2.08.0)

[derekPNM]

Hi Shlomi -

The tests appear legit, to the best of my knowledge. For clarification - gh-ost is running while those sql statements are being executed?

We'll look into upgrading our Aurora version, and I'll try to replicate locally using mysql 5.7..32 (to gather more information).

[derekPNM]

We are unable to replicate this issue against mysql 5.7.32 running the recent OSX distribution of gh-ost.

We've even updated Aurora to 2.10 to no avail. This does seem to be related to Aurora binlog formats.

We'll be running a few more experiments to share with the community (in the event that someone else eventually will benefit).

Thank you.

[shlomi-noach]

For clarification - gh-ost is running while those sql statements are being executed?

That is correct. The migration runs for (at least) 5 seoncds, during which an event issues those insert and update queries.

[shlomi-noach]

We'll be running a few more experiments to share with the community (in the event that someone else eventually will benefit).

Appreciate your efforts in pinning down the issue!

Assuming the tests would fail, my thought was to update to latest https://github.com/go-mysql-org/go-mysql, which may still solve your issue, I just don't know.

[derekPNM]

Would it be difficult to get a test build of gh-ost with the latest version of go-mysql? That might help. At this point we are looking into refactoring our code to not leverage a virtual json-in-json column

[derekPNM]

@shlomi-noach We dove deep into this and got the 16.4 version of go on our system, and built an executable for gh-ost following the instructions. We aren't sure if we did this correctly (go is new to us) , as we continue to see the error.

We were wondering, however, should we be using to use a different version of go-mysql instead of the bundled version?

[2021/06/02 13:12:09] [error] binlogstreamer.go:77 close sync with err: Header &replication.EventHeader{Timestamp:0x60b661f4, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x254, LogPos:0x601a5, Flags:0x0}, Data "S\x01\x00\x00\x00\x00\x01\x00\x02\x00\x03\xff\xff\xf8\x02\x00\x00\x00p\x00\x00\x00\x00\x02\x00o\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x01\x00>\x00\x00\a\x00\x01\x007\x00\v\x00\x19\x00\x02$\x002021-05-27 08:36:59 -0700\x02\x00\x13\x00\x04\x00\x00\f\n\x00\bcomplete?\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 ar\xf8\x02\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 62 < expected 154 2021-06-02 13:12:09 INFO StreamEvents encountered unexpected error: Header &replication.EventHeader{Timestamp:0x60b661f4, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x254, LogPos:0x601a5, Flags:0x0}, Data "S\x01\x00\x00\x00\x00\x01\x00\x02\x00\x03\xff\xff\xf8\x02\x00\x00\x00p\x00\x00\x00\x00\x02\x00o\x00\x12\x00\n\x00\x1c\x00\f\x00\f(\x00\x021\x00our_stringjson_in_json\bcomplete\x01\x00>\x00\x00\a\x00\x01\x007\x00\v\x00\x19\x00\x02$\x002021-05-27 08:36:59 -0700\x02\x00\x13\x00\x04\x00\x00\f\n\x00\bcomplete?\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 ar\xf8\x02\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 62 < expected 154 /home/deploy/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:712:

Specifically we wonder about this line?
/home/deploy/go/src/github.com/github/gh-ost/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go:712:

Any thoughts?

[shlomi-noach]

@derekPNM sorry was sidetracked with other stuff. go version shouldn't be an issue here. Yes to go-mysql version, which is outdated. I can try and set up a PR + binary with updated go-mysql early next week.

[derekPNM]

@derekPNM sorry was sidetracked with other stuff. go version shouldn't be an issue here. Yes to go-mysql version, which is outdated. I can try and set up a PR + binary with updated go-mysql early next week.

Thank you kindly. We appreciate your help.

[shlomi-noach]

Let's see how #22 goes

[shlomi-noach]

Artifact generated here: https://github.com/openark/gh-ost/suites/2923311567/artifacts/65612096

[derekPNM]

Assuming that artifact is for us to test with... when trying to execute our script we receive the following error:

2021-06-07 08:08:36 FATAL Unable to read osc chunk size: strconv.ParseInt: parsing "": invalid syntax goroutine 1 [running]: runtime/debug.Stack(0x65, 0xc000182190, 0x4b) /opt/hostedtoolcache/go/1.16.5/x64/src/runtime/debug/stack.go:24 +0x9f runtime/debug.PrintStack() /opt/hostedtoolcache/go/1.16.5/x64/src/runtime/debug/stack.go:16 +0x25 github.com/openark/golib/log.logErrorEntry(0x0, 0x87d140, 0xc000119a80, 0x26, 0xc000200000) /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/openark/golib/log/log.go:188 +0xf4 github.com/openark/golib/log.Fatale(0x87d140, 0xc000119a80, 0xc0001ba1d0, 0x828e00) /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/openark/golib/log/log.go:265 +0x3e github.com/github/gh-ost/go/base.(*simpleLogger).Fatale(0xad07e0, 0x87d140, 0xc000119a80, 0x0, 0x0) /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/go/base/default_logger.go:62 +0x35 main.main() /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/go/cmd/gh-ost/main.go:248 +0x3059
Ideas?

[shlomi-noach]

Assuming that artifact is for us to test with.

Yep!

Ideas?

Seems completely unrelated to the new build? What is the command you're trying to run?

[shlomi-noach]

specifically, do you have -conf=/path/to/config.file and what is the content of the config file?

[derekPNM]

I noticed something similar happened with the related PR that

Here's the command (same command we've been using since we encountered the binlog issue, BTW):
`
which gh-ost

for _tbl in reference_table

do

gh-ost
--max-load=Threads_running=24
--critical-load=Threads_running=1000
--chunk-size=1000
--throttle-control-replicas="${replicadb}"
--max-lag-millis=2500
--nice-ratio=0.15
--conf=/home/user/gh-ost/gh-ost_user.cnf
--host="${primarydb}"
--database="${databasename}"
--table="${_tbl}"
--verbose
--stack
--debug
--alter="ADD COLUMN ddh varchar(3) DEFAULT NULL"
--assume-rbr
--allow-on-master
--cut-over=default
--exact-rowcount
--concurrent-rowcount
--default-retries=120
--panic-flag-file=/home/user/ghost.${tbl}.panic.flag
--postpone-cut-over-flag-file /home/user/gh-ost/gh-ost${_tbl}.postpone
--initially-drop-old-table
--initially-drop-ghost-table
--execute \

done

`

The configuration file has only a client section, and has the username and password for connecting to the database.

[shlomi-noach]

OK maybe go mod updated the cfg library which is now not backwards compatible. It's a bit out of my capacity right now to check it out, I'll admit. Quick hack: add

[osc]
chunk_size=100

I hope this doesn't just push to the next validation error.

🤞

[derekPNM]

Thank you. It pushed us to the next validation error :( . I'll keep on working my way through them to see if the new go-mysql helps.

In the meantime: github#935 (comment)

[derekPNM]

We needed to add max_lag_millis to proceed:
[osc] chunk_size=100 max_lag_millis=2500

Unfortunately we are receiving the same types of errors (but with more information):

[2021/06/07 09:45:52] [error] binlogstreamer.go:78 close sync with err: Header &replication.EventHeader{Timestamp:0x60be4d40, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x308, LogPos:0xc7a51f, Flags:0x0}, Data "\xff\x02\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-06-07 09:45:52 INFO StreamEvents encountered unexpected error: Header &replication.EventHeader{Timestamp:0x60be4d40, EventType:0x1f, ServerID:0x6813be2c, EventSize:0x308, LogPos:0xc7a51f, Flags:0x0}, Data "\xff\x02\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 github.com/pingcap/errors.AddStack /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/pingcap/errors/errors.go:174 github.com/pingcap/errors.Trace /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/pingcap/errors/juju_adaptor.go:15 github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).parseEvent /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/go-mysql-org/go-mysql/replication/binlogsyncer.go:757 github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).onStream /home/runner/work/gh-ost/gh-ost/.gopath/src/github.com/github/gh-ost/vendor/github.com/go-mysql-org/go-mysql/replication/binlogsyncer.go:722 runtime.goexit /opt/hostedtoolcache/go/1.16.5/x64/src/runtime/asm_amd64.s:1371

[derekPNM]

Hi Shlomi,

We appreciate your help on this issue we've stumbled across. At this point we think it "best" for us to remove the json-in-json virtual columns we are using with Aurora. If the gh-ost team ever wants to revisit this issue, just let me know and I can try to reproduce it in our environment (it's simple for me to do now).

[shlomi-noach]

Sure thing. Thank you.