Bug #66127 SHOW FULL COLUMNS: Behaviour change:-(
Submitted: 31 Jul 2012 18:00 Modified: 6 Sep 2012 18:16
Reporter: Marco Walther Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Information schema Severity:S2 (Serious)
Version:5.5.25a OS:Solaris (S11 - MySQL built from source)
Assigned to: CPU Architecture:Any

[31 Jul 2012 18:00] Marco Walther
Description:
There is a difference in how `SHOW FULL COLUMNS' behaves between versions 5.1.30 (believe up to 5.5.20) and 5.5.25a:-( The query below was taken from the MySQL JDBC connector 5.1.21 log, so there is no easy way to change that:-(

That basically prevents Jira from starting:-(

--------------- 5.1.30 -------------------------------
$ mysql -ujirarw -pword -host
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2045482
Server version: 5.1.30-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%';
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| Field       | Type          | Collation | Null | Key | Default | Extra | Privileges           | Comment |
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| ID          | decimal(18,0) | NULL      | NO   | PRI | NULL    |       | select,insert,update |         | 
| PREVIOUS_ID | decimal(18,0) | NULL      | NO   | PRI | NULL    |       | select,insert,update |         | 
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
2 rows in set (0.00 sec)

mysql> use jira402db;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%';
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| Field       | Type          | Collation | Null | Key | Default | Extra | Privileges           | Comment |
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| ID          | decimal(18,0) | NULL      | NO   | PRI | NULL    |       | select,insert,update |         | 
| PREVIOUS_ID | decimal(18,0) | NULL      | NO   | PRI | NULL    |       | select,insert,update |         | 
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
2 rows in set (0.00 sec)

The same query on 5.5.25a with the same user/permissions:
-------------- mysql 5.5.25a ------------------------
$ mysql -ujirarw -pword -host
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 5955
Server version: 5.5.25a-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%';
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| Field       | Type          | Collation | Null | Key | Default | Extra | Privileges           | Comment |
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
| ID          | decimal(18,0) | NULL      | NO   | PRI | NULL |       | select,insert,update |         |
| PREVIOUS_ID | decimal(18,0) | NULL      | NO   | PRI | NULL |       | select,insert,update |         |
+-------------+---------------+-----------+------+-----+---------+-------+----------------------+---------+
2 rows in set (0.00 sec)

mysql> use jira402db;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'jira402db'
------------------------------------------------------------------------

The original JDBC exception from the Tomcat logs:
--------------------------------------------------------------------
Jul 31 01:19:15 Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Incorrect database name 'jira402db'
Jul 31 01:19:15 Query being executed when exception was thrown:
Jul 31 01:19:15 SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%'
Jul 31 01:19:15 last message repeated 1 time
Jul 31 01:19:15      at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
Jul 31 01:19:15      at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
Jul 31 01:19:15      at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
Jul 31 01:19:15      at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
Jul 31 01:19:15      at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
Jul 31 01:19:15      at com.mysql.jdbc.Util.getInstance(Util.java:386)
Jul 31 01:19:15      at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1053)
Jul 31 01:19:15      at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
Jul 31 01:19:15      at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
Jul 31 01:19:15      at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
Jul 31 01:19:15      at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
Jul 31 01:19:15      at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2713)
Jul 31 01:19:15      at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2663)
Jul 31 01:19:15      at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1599)
Jul 31 01:19:15      at com.mysql.jdbc.DatabaseMetaData$2.forEach(DatabaseMetaData.java:2528)
Jul 31 01:19:15      at com.mysql.jdbc.DatabaseMetaData$2.forEach(DatabaseMetaData.java:2406)
Jul 31 01:19:15      at com.mysql.jdbc.IterateBlock.doForAll(IterateBlock.java:51)
Jul 31 01:19:15      at com.mysql.jdbc.DatabaseMetaData.getColumns(DatabaseMetaData.java:2405)
Jul 31 01:19:15      at org.apache.tomcat.dbcp.dbcp.DelegatingDatabaseMetaData.getColumns(DelegatingDatabaseMetaData.java:218)
Jul 31 01:19:15      at com.atlassian.jira.upgrade.util.UpgradeUtils.getExactColumnName(UpgradeUtils.java:187)

How to repeat:
See queries above!
[31 Jul 2012 18:44] Valeriy Kravchuk
Please, send the output of:

show grants;

while connected as the same user in mysql command line client.
[31 Jul 2012 19:10] Marco Walther
------------- on the 5.1.30 server -----------------
mysql> show grants;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for jirarw@%                                                                                                                                                    |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT USAGE ON *.* TO 'jirarw'@'%' IDENTIFIED BY PASSWORD 'xxxxx'                                                                  | 
| GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, CREATE TEMPORARY TABLES, CREATE VIEW, CREATE ROUTINE, ALTER ROUTINE ON `jiradb402`.* TO 'jirarw'@'%' | 
| GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, CREATE TEMPORARY TABLES, CREATE VIEW, CREATE ROUTINE, ALTER ROUTINE ON `jira402db`.* TO 'jirarw'@'%' | 
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)

--------------- on the 5.5.25a server ----------------------------
mysql> show grants;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for jirarw@%                                                                                                                                                    |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT USAGE ON *.* TO 'jirarw'@'%' IDENTIFIED BY PASSWORD 'xxx'                                                                  |
| GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, CREATE TEMPORARY TABLES, CREATE VIEW, CREATE ROUTINE, ALTER ROUTINE ON `jira402db`.* TO 'jirarw'@'%' |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)
[1 Aug 2012 19:05] Marco Walther
More strange things:
---------------- 5.5.25a as root -------------------------------
$ mysql -uroot -pword
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 10465
Server version: 5.5.25a-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show grants;
+----------------------------------------------------------------------------------------------------------------------------------------+
| Grants for root@localhost                                                                                           |
+--------------------------------------------------------------------------------------------------------+
| GRANT ALL PRIVILEGES ON *.* TO 'root'@'localhost' IDENTIFIED BY PASSWORD 'xxx' WITH GRANT OPTION  |
| GRANT PROXY ON ''@'' TO 'root'@'localhost' WITH GRANT OPTION                   |
+--------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxx` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'xxxxxxx'
mysql> use mysql;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxx` LIKE '%';
ERROR 1146 (42S02): Table 'xxxxxxx.OS_CURRENTSTEP_PREV' doesn't exist
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxx` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'xxxxxxxx'
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxxx` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'xxxxxxxxx'
mysql> use jira402db;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxx` LIKE '%';
ERROR 1146 (42S02): Table 'xxxxxxx.OS_CURRENTSTEP_PREV' doesn't exist
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxx` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'xxxxxxxx'
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxxx` LIKE '%';
ERROR 1102 (42000): Incorrect database name 'xxxxxxxxx'
mysql> 

----------- 5.5.20 built on the same box with the same compiler/scripts -------
$ mysql -uroot -pword
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.5.20 Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show grants;
+--------------------------------------------------------------------------------------------------------+
| Grants for root@localhost                                                                                           |
+--------------------------------------------------------------------------------------------------------+
| GRANT ALL PRIVILEGES ON *.* TO 'root'@'localhost' IDENTIFIED BY PASSWORD 'xxx' WITH GRANT OPTION  |
| GRANT PROXY ON ''@'' TO 'root'@'localhost' WITH GRANT OPTION                   |
+--------------------------------------------------------------------------------------------------------+
2 rows in set (0.01 sec)
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `jira402db` LIKE '%';
ERROR 1146 (42S02): Table 'jira402db.OS_CURRENTSTEP_PREV' doesn't exist
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxx` LIKE '%';
ERROR 1146 (42S02): Table 'xxxxxxx.OS_CURRENTSTEP_PREV' doesn't exist
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxx` LIKE '%';
ERROR 1146 (42S02): Table 'xxxxxxxx.OS_CURRENTSTEP_PREV' doesn't exist
mysql> SHOW FULL COLUMNS FROM `OS_CURRENTSTEP_PREV` FROM `xxxxxxxxx` LIKE '%';
ERROR 1146 (42S02): Table 'xxxxxxxxx.OS_CURRENTSTEP_PREV' doesn't exist
[2 Aug 2012 2:44] Marco Walther
Even more strange:-( It seems to be related to some [buffer|memory] size:-(

From pure heuristic experiments, the following my.cnf, when (key_buffer_size + query_cache_size) > 3G, I see the problem. When it's <= 3G, the queries seem to work.

That problem is actually there in both 5.5.20 & 5.5.25a with this my.cnf:-( Before I was just running the test 5.5.20 server with the defaults:-( So the problem did not show up:-(

----------------------------------
[mysqld]
server-id = 1
log-bin = mysql-bin
report-host = xx

max_connections = 500
port = 3306
socket = /tmp/mysql.sock
skip-external-locking

key_buffer_size = 2G # 4G does not seem to work any more ## 9G
max_allowed_packet = 16M
max_heap_table_size =  3G
query_cache_size = 1G ## 6G

read_buffer_size = 64K
read_rnd_buffer_size = 256K
sort_buffer_size = 256K
table_cache = 1000

thread_cache_size = 8
thread_concurrency = 32
tmp_table_size = 3G

master-retry-count=10
relay-log = slave-relay.log
relay-log-index = slave-relay-log.index
expire_logs_days = 10
max_binlog_size = 500M
replicate-ignore-db=mysql

innodb_additional_mem_pool_size = 364M
innodb_buffer_pool_size = 10G
innodb_flush_log_at_trx_commit = 1
innodb_log_buffer_size = 16M
innodb_lock_wait_timeout = 100
innodb_thread_concurrency = 32

myisam_sort_buffer_size = 512M
[6 Aug 2012 18:16] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior with latest development sources. Additionally version 5.5.27 has been released. Please try with current version 5.5.27 (MySQL command line client test) and inform us if problem still exists.
[8 Sep 2012 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".