Getting this error intermittently while running migration

[Dhanasekar93]

Tried a simple migration, got the below error.

Runner logs:

I0305 06:57:00.697588 00015 migration.go:350] mig_id=1: Running query 'SELECT DATA_LENGTH, INDEX_LENGTH, TABLE_ROWS FROM information_schema.tables WHERE table_schema=? AND table_name=?' (args: [world sbtest1]).
I0305 06:57:00.747675 00015 migration.go:357] mig_id=1: Query response was 'map[DATA_LENGTH:[22593536] INDEX_LENGTH:[2637824] TABLE_ROWS:[98712]]'
E0305 06:57:02.613776 00015 runner.go:363] mig_id=1: RestError [NextStep]: invalid character '<' looking for beginning of value.
I0305 06:57:03.552564 00015 runner.go:373] mig_id=1: Successfully failed migration.
I0305 06:57:13.576634 00015 runner.go:240] Getting staged migrations.
I0305 06:57:13.661886 00015 runner.go:247] No new staged migrations.

pt-osc logs:

[2020-03-05 06:56:58] stdout: Operation, tries, wait:
[2020-03-05 06:56:59] stdout:   analyze_table, 10, 1
[2020-03-05 06:56:59] stdout:   copy_rows, 10, 0.25
[2020-03-05 06:56:59] stdout:   create_triggers, 10, 1
[2020-03-05 06:56:59] stdout:   drop_triggers, 10, 1
[2020-03-05 06:56:59] stdout:   swap_tables, 10, 1
[2020-03-05 06:56:59] stdout:   update_foreign_keys, 10, 1
[2020-03-05 06:56:59] stdout: Starting a dry run.  `world`.`sbtest1` will not be altered.  Specify --execute instead of --dry-run to alter the table.
[2020-03-05 06:56:59] stdout: Creating new table...
[2020-03-05 06:56:59] stdout: Created new table world._sbtest1_new OK.
[2020-03-05 06:56:59] stdout: Altering new table...
[2020-03-05 06:56:59] stdout: Altered `world`.`_sbtest1_new` OK.
[2020-03-05 06:56:59] stdout: Not creating triggers because this is a dry run.
[2020-03-05 06:56:59] stdout: Not copying rows because this is a dry run.
[2020-03-05 06:56:59] stdout: Not swapping tables because this is a dry run.
[2020-03-05 06:56:59] stdout: Not dropping old table because this is a dry run.
[2020-03-05 06:56:59] stdout: Not dropping triggers because this is a dry run.
[2020-03-05 06:56:59] stdout: 2020-03-05T06:56:59 Dropping new table...
[2020-03-05 06:56:59] stdout: 2020-03-05T06:56:59 Dropped new table OK.
[2020-03-05 06:56:59] stdout: Dry run complete.  `world`.`sbtest1` was not altered.

If possible please share your skype id / slack details so that we exchange the logs instead of creating the issues here.

[michaelfinch]

@Dhanasekar93 could you take the diff here and apply it to your runner? #79. And if it happens again, share the runner output with the additional logging.

Looking back at this code now, it doesn't handle errors as well as it should. There's nothing to be concerned about; it just means some error messages are not helpful.

[Dhanasekar93]

@michaelfinch I have applied the same in runner. Still i didn't see such cases. Will update here if I found the same errors

[robertomczak]

It looks like Rest communication issue between Runner and UI.
Runner is simply failing to make a call for whatever reason to UI. I would look into UI logs for some traces of errors with REST API.
Have you made any changes to REST related functions etc in UI ?

[Dhanasekar93]

Got this messages from running log now.

I0401 14:49:22.122626 00015 migration.go:357] mig_id=2: Query response was 'map[DATA_LENGTH:[16384] INDEX_LENGTH:[0] TABLE_ROWS:[3]]'
E0401 14:49:22.138048 00015 runner.go:363] mig_id=2: RestError [Update]: invalid character '<' looking for beginning of value.
W0401 14:49:22.152254 00015 rest.go:115] Errer decoding response. Status: %d. Body: %s500 Internal Server Error &{0xc820413280 {0 0} false <nil> 0x623290 0x623230}
E0401 14:49:22.152285 00015 runner.go:370] mig_id=2: RestError [Fail]: invalid character '<' looking for beginning of value.

Its not moving to the next step as it is failed at this process. This is occurring for every DDL requests now.

[Dhanasekar93]

Logs for create table statements

I0401 15:58:06.749932 00014 migration.go:350] mig_id=1: Running query 'SELECT COUNT(*) as count FROM information_schema.tables WHERE table_schema=? AND table_name=?' (args: [world test]).
I0401 15:58:06.751960 00014 migration.go:357] mig_id=1: Query response was 'map[count:[0]]'
I0401 15:58:06.751980 00014 migration.go:364] mig_id=1: Running query 'create table test ( id int auto_increment primary key , vals varchar ( 100 ) default 'dummy' )'.
I0401 15:58:06.762261 00014 migration.go:364] mig_id=1: Running query 'DROP TABLE test'.
W0401 15:58:06.823356 00014 rest.go:115] Errer decoding response. Status: %d. Body: %s500 Internal Server Error &{0xc820251a00 {0 0} false <nil> 0x623290 0x623230}
E0401 15:58:06.823414 00014 runner.go:363] mig_id=1: RestError [NextStep]: invalid character '<' looking for beginning of value.
W0401 15:58:06.837583 00014 rest.go:115] Errer decoding response. Status: %d. Body: %s500 Internal Server Error &{0xc82023fdc0 {0 0} false <nil> 0x623290 0x623230}
E0401 15:58:06.837628 00014 runner.go:370] mig_id=1: RestError [Fail]: invalid character '<' looking for beginning of value.