pt-osc segfaults on mysql alter errors

Bug #1446928 reported by Agustín
56
This bug affects 11 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Fix Released
High
Frank Cizmich

Bug Description

It would be useful to have the tool report more meaningful errors, like mysql does. Take the following two examples:

mysql> ALTER TABLE t2 ADD COLUMN created_at DATETIME DEFAULT now();
ERROR 1067 (42000): Invalid default value for 'created_at'

mysql> ALTER TABLE t2 ADD COLUMN created_at non_existent_datatype;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'non_existent_datatype' at line 1

pt-osc, instead, silently fails with a strange "Bus error" line at the end:

shell> pt-online-schema-change --execute --alter "ADD COLUMN created_at DATETIME DEFAULT now()" S=/tmp/mysql_sandbox5542.sock,u=msandbox,p=msandbox,D=test,t=t2
No slaves found. See --recursion-method if host bm-support01 has slaves.
Not checking slave lag because no slaves were found and --check-slave-lag was not specified.
Operation, tries, wait:
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
Altering `test`.`t2`...
Creating new table...
Created new table test._t2_new OK.
Altering new table...
2015-04-21T21:08:38 Dropping new table...
2015-04-21T21:08:38 Dropped new table OK.
`test`.`t2` was not altered.
Bus error

shell> pt-online-schema-change --execute --alter "ADD COLUMN created_at non_existent_datatype" S=/tmp/mysql_sandbox5542.sock,u=msandbox,p=msandbox,D=test,t=t2
No slaves found. See --recursion-method if host bm-support01 has slaves.
Not checking slave lag because no slaves were found and --check-slave-lag was not specified.
Operation, tries, wait:
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
Altering `test`.`t2`...
Creating new table...
Created new table test._t2_new OK.
Altering new table...
2015-04-21T21:10:00 Dropping new table...
2015-04-21T21:10:00 Dropped new table OK.
`test`.`t2` was not altered.
Bus error

Snippet from using PTDEBUG=1:

shell> PTDEBUG=1 pt-online-schema-change --execute --alter "ADD COLUMN created_at non_existent_datatype" S=/tmp/mysql_sandbox5542.sock,u=msandbox,p=msandbox,D=test,t=t2

[...]
Operation, tries, wait:
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
# pt_online_schema_change:10054 6242 Finding child tables
# pt_online_schema_change:10060 6242 SELECT table_schema, table_name FROM information_schema.key_column_usage WHERE referenced_table_schema='test' AND referenced_table_name='t2'
# pt_online_schema_change:10063 6242 No child tables found
Altering `test`.`t2`...
# CleanupTask:6170 6242 Created cleanup task CODE(0x1aca270)
# pt_online_schema_change:9737 6242 Renamed columns (old => new): $VAR1 = {};
#
# Percona::XtraDB::Cluster:7621 6242 bm-support01 SHOW VARIABLES LIKE 'wsrep_on'
# Percona::XtraDB::Cluster:7623 6242 $VAR1 = undef;
#
# TableParser:3119 6242 /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := '', @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
# TableParser:3124 6242 DBI::db=HASH(0x1a31410) USE `test`
# TableParser:3128 6242 SHOW CREATE TABLE `test`.`t2`
# TableParser:3138 6242 /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
Creating new table...
# pt_online_schema_change:9866 6242 CREATE TABLE `test`.`_t2_new` (
# `id` int(11) NOT NULL AUTO_INCREMENT,
# PRIMARY KEY (`id`)
# ) ENGINE=InnoDB AUTO_INCREMENT=5 DEFAULT CHARSET=latin1
Created new table test._t2_new OK.
Altering new table...
# pt_online_schema_change:8819 6242 ALTER TABLE `test`.`_t2_new` ADD COLUMN created_at non_existent_datatype
# CleanupTask:6178 6242 Calling cleanup task CODE(0x1aca270)
# pt_online_schema_change:8710 6242 Clean up new table
# TableParser:3290 6242 Checking `test`.`_t2_new`
# TableParser:3294 6242 SHOW TABLES FROM `test` LIKE '\_t2\_new'
# TableParser:3308 6242 Table test _t2_new exists
# pt_online_schema_change:8716 6242 New table exists: yes
2015-04-21T21:14:21 Dropping new table...
# pt_online_schema_change:8752 6242 DROP TABLE IF EXISTS `test`.`_t2_new`;
2015-04-21T21:14:21 Dropped new table OK.
# pt_online_schema_change:8587 6242 Clean up done, report if orig table was altered
`test`.`t2` was not altered.
Bus error

More information on versions used, etc:

shell> pt-online-schema-change --version
pt-online-schema-change 2.2.13

mysql> SHOW VARIABLES LIKE '%version%';
+-------------------------+------------------------------------------------------+
| Variable_name | Value |
+-------------------------+------------------------------------------------------+
| innodb_version | 5.5.42-37.1 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.5.42-37.1 |
| version_comment | Percona Server (GPL), Release 37.1, Revision 39acee0 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+------------------------------------------------------+
7 rows in set (0.00 sec)

mysql> SHOW CREATE TABLE test.t2\G
*************************** 1. row ***************************
       Table: t2
Create Table: CREATE TABLE `t2` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=5 DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

Changed in percona-toolkit:
status: New → In Progress
importance: Undecided → High
assignee: nobody → Frank Cizmich (frank-cizmich)
tags: added: pt-online-schema-change
Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

Attached a patch for this. The problem was a loop in the error handling routines.

Revision history for this message
Agustín (agustin-gallego) wrote :

Confirming this patch helps with this. Thanks Frank!

agustin.gallego@bm-support01:~/tmp$ ./pt-online-schema-change --execute --alter "ADD COLUMN created_at non_existent_datatype" S=/tmp/mysql_sandbox5542.sock,u=msandbox,p=msandbox,D=test,t=t2
[...]
2015-04-23T18:43:41 Dropping new table...
2015-04-23T18:43:41 Dropped new table OK.
`test`.`t2` was not altered.
Error altering new table `test`.`_t2_new`: DBD::mysql::db do failed: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'non_existent_datatype' at line 1 [for Statement "ALTER TABLE `test`.`_t2_new` ADD COLUMN created_at non_existent_datatype"] at ./pt-online-schema-change line 8821.

agustin.gallego@bm-support01:~/tmp$ ./pt-online-schema-change --execute --alter "ADD COLUMN created_at DATETIME DEFAULT now()" S=/tmp/mysql_sandbox5542.sock,u=msandbox,p=msandbox,D=test,t=t2
[...]
2015-04-23T18:46:31 Dropping new table...
2015-04-23T18:46:31 Dropped new table OK.
`test`.`t2` was not altered.
Error altering new table `test`.`_t2_new`: DBD::mysql::db do failed: Invalid default value for 'created_at' [for Statement "ALTER TABLE `test`.`_t2_new` ADD COLUMN created_at DATETIME DEFAULT now()"] at ./pt-online-schema-change line 8821.

Changed in percona-toolkit:
milestone: none → 2.3.1
Revision history for this message
Daniël van Eeden (dveeden) wrote :

I've tested this and the patch seems to fix it. I now get a useful error. (pt-online-schema-change 2.2.13)

Changed in percona-toolkit:
status: In Progress → Fix Committed
Changed in percona-toolkit:
milestone: 2.3.1 → none
Changed in percona-toolkit:
milestone: none → 2.2.15
Changed in percona-toolkit:
status: Fix Committed → Fix Released
summary: - pt-online-schema-change not reporting meaningful errors.
+ pt-online-schema-change not reporting meaningful errors due to
+ segfaulting on alter errors
Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

changed title to something I think is more descriptive of the real issue.

summary: - pt-online-schema-change not reporting meaningful errors due to
- segfaulting on alter errors
+ pt-osc segfaults on mysql alter errors
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PT-388

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.