MySQL Bugs: #45268: Backup database fails with error "Failed to obtain meta-data for stored routine"

Bug #45268	Backup database fails with error "Failed to obtain meta-data for stored routine"
Submitted:	2 Jun 2009 15:47	Modified:	17 Jul 2009 22:14
Reporter:	Hema Sridharan	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S2 (Serious)
Version:	mysql-6.0-backup, mysql-6.0	OS:	Linux
Assigned to:	Chuck Bell	CPU Architecture:	Any

Description:
I created grammar file that will
- create databases db1 and db2
- create tables and procedures in db1 and db2
The grammar file will also set different character sets and collations randomly while creating tables and procedures.
Create reporter.pm file which will execute periodic backup and restore operation

Execution of backup fails with an error "Failed to obtain meta-data for stored routine `db2`.`o` at lib/GenTest/Reporter/inter_backup.pm line 25"

How to repeat:
Run the script with RQG load as follows,

perl runall.pl --basedir=/export/home/tmp/wl4195c/mysql-6.0-backup/ --grammar=/export/home/tmp/perl_new/mysql-test-extra-6.0/mysql-test/gentest/conf/mytest2_onlyproc.yy --reporter=inter_backup

The test fails intermittently. I was able to reproduce the failure (5 out of 10 times). Although I am not able to find out the root cause for the failure.

Please take a look at the attached grammar file and reporter file

Attachment: mytest2_onlyproc.yy (application/octet-stream, text), 2.21 KiB.

Reporter file is below:

Attachment: inter_backup.pm (application/octet-stream, text), 3.06 KiB.

Thank you for the report.

Verified with different error:

# 23:15:27 Query: CALL db1.s failed: 1457 Failed to load routine db1.s. The table mysql.proc is missing, corrupt, or contains bad data (internal code -6)

Sveta,

You can notice the error of "Failed to obtain meta-data for stored routine" along with the above error that you mentioned.

This is a duplicate of BUG#45249. It has the same cause.

I don't think this is the duplicate of BUG#45249 as they produce different error messages. Moreover this error is related to metadata missing during backup. I will do more analysis on this and will change the status to duplicate if it is really related to BUG#45249.

Yes, it produces a different error message but the cause of the problem remains the same. I've done the analysis. It is the same problem as BUG#45249. 

The real issue here is whether this is a bug at all. The problem lies in si_objects because it was designed to fail if a query against IS tables (in this case, INFORMATION_SCHEMA.ROUTINES, for both bugs -- nearly the same query) returns a warning. But this is not the behavior of the system. So if there is a bug, it is in how si_objects is handling warning messages.

I will rerun my analysis and change the bug report if some new anomoly occurs.

I recommend closing both of these bugs and opening a new bug that describes the real problem with a real (MTR) test case.

I did some analysis for this bug and found out much simpler test case that reproduces the error. Here it is,

CREATE DATABASE x;
USE x;
CREATE TABLE x.t1(tt SET('s','p','s'));
# Note that because of repeated values in SET, warning occurs
BACKUP DATABASE x to 'x1.bak';

# Backup passes

CREATE PROCEDURE x.p1(tt SET('s','p','s'));
# This will also issue warning because of repeated values in SET
BACKUP DATABASE x TO 'x2.bak';

# Backup will fail by giving error "Failed to obtain meta-data"

Ideally, backup should not fail because of wrong definition of objects. Moreover the procedure x.p1 gets created and only warning message is issued.

BUG#45249 defines the problem with the usage of reserved characters while creating stored routines. Therefore, I see that to be different issue and not related to this defect.

mysql> create database x;
Query OK, 1 row affected (0.00 sec)

mysql> use x;
Database changed

mysql> create table t3(tt SET('s','p','s'));
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings;
+-------+------+---------------------------------------------+
| Level | Code | Message                                     |
+-------+------+---------------------------------------------+
| Note  | 1291 | Column 'tt' has duplicated value 's' in SET |
+-------+------+---------------------------------------------+
1 row in set (0.00 sec)

mysql> backup database x to 'x2.bak';
+-----------+
| backup_id |
+-----------+
| 272       |
+-----------+
1 row in set (0.25 sec)

mysql> create procedure x.p2(tt SET('s','p','s')) SET @y=100;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings;
+-------+------+-------------------------------------------+
| Level | Code | Message                                   |
+-------+------+-------------------------------------------+
| Note  | 1291 | Column '' has duplicated value 's' in SET |
+-------+------+-------------------------------------------+

mysql> backup database x to 'x5.bak';
ERROR 1717 (HY000): Failed to obtain meta-data for stored routine `x`.`p2`

Hema, it would be interesting to see how SHOW CREATE ... works for these objects (t1 and p1). 

I expect it will fail with error for p1 which would be the reason for BACKUP failing. If I'm right then the SHOW CREATE statement should be fixed so that it consistently does not error in such cases.

Rafal,

The show create procedure for t1 and p1 succeeds. Please see the following:

mysql> show create procedure x.p2;
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| Procedure | sql_mode | Create Procedure                                                                 | character_set_client | collation_connection | Database Collation |
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| p2        |          | CREATE DEFINER=`root`@`localhost` PROCEDURE `p2`(tt SET('s','p','s'))
SET @y=100 | latin1               | latin1_swedish_ci    | latin1_swedish_ci  |
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+

mysql> show create table t1;
+-------+-------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                    |
+-------+-------------------------------------------------------------------------------------------------+
| t1    | CREATE TABLE `t1` (
  `tt` set('s','p','s') DEFAULT NULL
) ENGINE=MyISAM DEFAULT CHARSET=latin1 |
+-------+-----------------------------------------------------------------------
--------------------------+

The problem seems to be fixed. Attempted test case presented:

mysql> CREATE DATABASE x;
Query OK, 1 row affected (0.00 sec)

mysql> USE x;
Database changed
mysql> CREATE TABLE x.t1(tt SET('s','p','s'));
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> BACKUP DATABASE x to 'x1.bak';
+-----------+
| backup_id |
+-----------+
| 276       | 
+-----------+
1 row in set (0.35 sec)

mysql> create procedure x.p2(tt SET('s','p','s')) SET @y=100;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> SHOW warnings;
+-------+------+-------------------------------------------+
| Level | Code | Message                                   |
+-------+------+-------------------------------------------+
| Note  | 1291 | Column '' has duplicated value 's' in SET | 
+-------+------+-------------------------------------------+
1 row in set (0.00 sec)

mysql> BACKUP DATABASE x TO 'x2.bak';
+-----------+
| backup_id |
+-----------+
| 277       | 
+-----------+
1 row in set, 1 warning (0.09 sec)

mysql> show warnings;
+-------+------+-------------------------------------------+
| Level | Code | Message                                   |
+-------+------+-------------------------------------------+
| Note  | 1291 | Column '' has duplicated value 's' in SET | 
+-------+------+-------------------------------------------+
1 row in set (0.00 sec)

mysql> drop database x;
Query OK, 1 row affected (0.01 sec)

mysql> restore from 'x2.bak';
+-----------+
| backup_id |
+-----------+
| 278       | 
+-----------+
1 row in set, 2 warnings (0.01 sec)

mysql> show warnings;
+-------+------+---------------------------------------------+
| Level | Code | Message                                     |
+-------+------+---------------------------------------------+
| Note  | 1291 | Column 'tt' has duplicated value 's' in SET | 
| Note  | 1291 | Column '' has duplicated value 's' in SET   | 
+-------+------+---------------------------------------------+
2 rows in set (0.00 sec)

mysql> show create procedure x.p2;
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| Procedure | sql_mode | Create Procedure                                                                 | character_set_client | collation_connection | Database Collation |
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| p2        |          | CREATE DEFINER=`root`@`localhost` PROCEDURE `p2`(tt SET('s','p','s'))
SET @y=100 | utf8                 | utf8_general_ci      | latin1_swedish_ci  | 
+-----------+----------+----------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
1 row in set, 1 warning (0.00 sec)

mysql> show create table x.t1;
+-------+-------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                    |
+-------+-------------------------------------------------------------------------------------------------+
| t1    | CREATE TABLE `t1` (
  `tt` set('s','p','s') DEFAULT NULL
) ENGINE=MyISAM DEFAULT CHARSET=latin1 | 
+-------+-------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

Hema will verify my findings.

I agree with Chuck and I am not able to reproduce the issue for the
above sample test but that doesn't mean that there is no problem. I am
still able to reproduce the error with grammar and reporter file
attached in the bug report.

The error "Failed to obtain meta-data for stored routine" is not limited
to the the simple test case that I created. We need to fix this error in
test case related to stored routines. The grammar and reporter file
that I added doesn't have any problem, so I still see this as a defect.

Patch to MTR needed for source tree to allow random query generator to run.

Attachment: rqg.diff (text/x-diff), 1.41 KiB.

Bug has been tested with the latest code from mysql-test-extra-6.0 and mysql-6.0-backup

Note: This requires the patch rqg.diff (attached) to fix a problem with MTR in the backup tree.

Note: This also requires changing the grammar file from:

49 : procedure_name:
50 :        letter;

to:

49 : procedure_name:

50 :        letter-letter;

This was needed to avoid a problem with single character procedure and function names.

Note: You must also ensure the Falcon storage engine is installed because the grammar file uses it. The test will still pass, but a lot of error messages having to do with unable to create table for Falcon will occur.

Conclusion
----------
The test was run in succession 21 times. Why 21? Ask my statistics professor. :))

A typical run produces the following output:

Servers started, exiting
# 18:11:42 Starting 
# 18:11:42  gentest.pl \ 
# 18:11:42  --gendata= \ 
# 18:11:42  --reporters=inter_backup \ 
# 18:11:42  --threads=10 \ 
# 18:11:42  --queries=1000 \ 
# 18:11:42  --duration=3600 \ 
# 18:11:42  --dsn1=dbi:mysql:host=127.0.0.1:port=19306:user=root:database=test \ 
# 18:11:42  --grammar=mytest2_onlyproc.yy
# 18:11:42 Starting 
# 18:11:42 # gendata-old.pl \ 
# 18:11:42 # --dsn=dbi:mysql:host=127.0.0.1:port=19306:user=root:database=test
# 18:11:42 Creating table A, size 0 rows, engine  .
# 18:11:42 Creating table B, size 2 rows, engine  .
# 18:11:42 Creating table C, size 20 rows, engine  .
# 18:11:42 Creating table D, size 100 rows, engine  .
# 18:11:42 Creating table E, size 1000 rows, engine  .
# 18:11:43 Creating table AA, size 0 rows, engine  .
# 18:11:43 Creating table BB, size 2 rows, engine  .
# 18:11:43 Creating table CC, size 20 rows, engine  .
# 18:11:43 Creating table DD, size 100 rows, engine  .
# 18:11:43 Creating table AAA, size 0 rows, engine  .
# 18:11:43 Creating table BBB, size 1 rows, engine  .
# 18:11:43 Creating table CCC, size 20 rows, engine  .
# 18:11:43 Reporters: inter_backup
# 18:11:43 Validators: ErrorMessageCorruption
# 18:11:43 Starting 10 processes, 1000 queries each, duration 3600 seconds.
# 18:11:43 Query: CREATE PROCEDURE db2.b-a () SET @pro=100 failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:43 Query: CREATE TABLE IF NOT EXISTS db2.t10 (c5 BIGINT NULL, c2 BLOB NOT NULL, c2 TIMESTAMP NOT NULL) ENGINE = Myisam failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:43 Query: CREATE PROCEDURE db2.w-z () SET @pro=100 failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:43 Query: CREATE TABLE IF NOT EXISTS db1.t8 (c2 TINYINT NOT NULL, c2 TEXT NOT NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: DROP PROCEDURE IF EXISTS db1.k-i failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CREATE TABLE IF NOT EXISTS db1.t10 (c10 BLOB NULL, c5 VARCHAR(255) NOT NULL, c10 TIMESTAMP NULL) ENGINE = Myisam failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CALL db1.n-q failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CREATE TABLE IF NOT EXISTS db1.t6 (c9 SMALLINT NULL, c9 DATE NOT NULL, c6 YEAR NOT NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CALL db2.r-i failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: DROP PROCEDURE IF EXISTS db1.b-h failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: DROP PROCEDURE IF EXISTS db2.f-i failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CREATE TABLE IF NOT EXISTS db2.t9 (c1 YEAR NOT NULL, c1 BLOB NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CALL db2.p-c failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CALL db2.i-k failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CREATE TABLE IF NOT EXISTS db2.t7 (c7 TIMESTAMP NULL, c10 TIME NOT NULL, c10 CHAR(255) NOT NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CREATE TABLE IF NOT EXISTS db1.t6 (c9 CHAR(255) NULL, c9 TEXT NOT NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:44 Query: CALL db2.m-t failed: 1064 %d. Further errors of this kind will be suppressed.
# 18:11:44 Started periodic reporting process...
# 18:11:44 Executing BACKUP DATABASE.
# 18:11:45 Query: CREATE TABLE IF NOT EXISTS db2.t3 (c8 BIGINT NULL, c8 TINYINT NOT NULL, c3 TIMESTAMP NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:46 Query: CREATE TABLE IF NOT EXISTS db2.t5 (c4 BIGINT NOT NULL, c4 TEXT NOT NULL, c8 BLOB NULL) ENGINE = Innodb failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:46 Query: CREATE TABLE IF NOT EXISTS db1.t8 (c10 INT NOT NULL, c10 CHAR(255) NULL) ENGINE = Myisam failed: 1060 Unknown error %d. Further errors of this kind will be suppressed.
# 18:11:55 Executing BACKUP DATABASE.
# 18:11:57 Child process completed successfully.
# 18:11:58 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:11:59 Child process completed successfully.
# 18:12:01 Killing periodic reporting process with pid 3825...
sh: mysqldump: not found
# 18:12:01 Executing RESTORE FROM.
# 18:12:01 Test completed successfully.
# 18:12:01 gentest.pl exited with exit status 0

Therefore, I must conclude the problem no longer exists and we close this bug report with "can't repeat."