Bug #54425 | Unknown command when connecting to MySQL 5.1 with MysqlConnectionPoolDataSource | ||
---|---|---|---|
Submitted: | 11 Jun 2010 11:00 | Modified: | 15 Apr 2011 15:30 |
Reporter: | Martin Kirchner | Email Updates: | |
Status: | Closed | Impact on me: | |
Category: | Connector / J | Severity: | S1 (Critical) |
Version: | 5.1.12 + 5.1.13 + 5.1.14 + 5.1.15 | OS: | Any |
Assigned to: | CPU Architecture: | Any |
[11 Jun 2010 11:00]
Martin Kirchner
[14 Jul 2010 10:28]
Martin Kirchner
Tested today with 5.1.13. It still does not work. Appreciate any help.
[20 Jul 2010 6:41]
Martin Kirchner
The bug occurs using Java 5 as well as Java 6. I need help. Any ideas? I'd appreciate any hint on how to debug the connection. It ought to be possible to find out which command is "unknown".
[20 Jul 2010 7:23]
Ingo Siebert
I've the same problem on my machine(s). Please fix it ASAP, because I have to migrate to MySQL 5.1.
[20 Jul 2010 7:27]
Tonci Grgin
Martin, you changed the credentials on MySQL server thus the handshake is failing. You did not get nowhere close to statement execution from what I see in the trace. Please turn on general query log and check what's happening. at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:920) at com.mysql.jdbc.MysqlIO.secureAuth411(MysqlIO.java:4000) at com.mysql.jdbc.MysqlIO.changeUser(MysqlIO.java:875) at com.mysql.jdbc.ConnectionImpl.changeUser(ConnectionImpl.java:1147)
[20 Jul 2010 7:35]
Tonci Grgin
Running same regression test (public void testBug35489()) against remote 5.1.31 shows no problems.
[20 Jul 2010 8:52]
Martin Kirchner
Tonci, thanks for your answer. The general query log shows: C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld, Version: 5.1.47-community-log (MySQL Community Server (GPL)). started with: TCP Port: 3308, Named Pipe: (null) Time Id Command Argument 100720 9:37:48 1 Connect EIM@localhost on 1 Query /* mysql-connector-java-5.1.13 ( Revision: ${bzr.revision-id} ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect' 1 Query SHOW WARNINGS 1 Query /* mysql-connector-java-5.1.13 ( Revision: ${bzr.revision-id} ) */SELECT @@session.auto_increment_increment 1 Query SHOW COLLATION 1 Query SET character_set_results = NULL 1 Query SET autocommit=1 The warning returned by the SHOW VARIABLES...-query is: Warning | 1366 | Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE' at row 1 All other commands can be executed in the mysql commandline client without errors/warnings. I'll try a Linux server later and post the results.
[20 Jul 2010 8:58]
Tonci Grgin
MArtin, apparently you use some characters that are outside the BMP of charset in use: '\xE4ische...' Can you please determine which character is causing the confusion and add proper "&characterEncoding=..." in your connection string (probably &characterEncoding=utf8 will do the trick).
[21 Jul 2010 8:05]
Martin Kirchner
Tonci, unfortunately that did not solve my problem. Can I activate any logging in the Connector?
[21 Jul 2010 8:25]
Tonci Grgin
Martin, sure you can, check http://dev.mysql.com/doc/refman/5.5/en/connector-j-reference-configuration-properties.html. But this will show nothing more than already visible from your general server log. Now > Tonci, unfortunately that did not solve my problem. What exactly "did not solve your problem"? Did you tried &characterEncoding=utf8 or what? You need to understand the meaning of "Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE'" error. There has been double encoding somewhere forcing the driver to try to represent the character just before "ische" as "\xE4". There could be multitude reasons for this; you might have improper connection charset, there might be an incompatibility between charset you're using (whether willingly or just by trying to stuff character outside the BMP into your table) and a server/database/table/field charset and so on and so on... Since test that fails for you works for me and since only you have your database and code I am powerless. Unless you can come up with small but complete test case that fails every time I will be forced to close the report as !Bg. So, again, do check the character \xE4 and see what is it you're trying to stuff into 'VARIABLE_VALUE' field. Then check Server/Database/Table/Field charsets and see where the problem comes from. Good tutorial can be found in: http://forge.mysql.com/wiki/How_to_Use_Charsets_and_Collations_Properly#How_to_Use_Charset...
[21 Jul 2010 9:37]
Martin Kirchner
Hi Tonci, first of all thanks for your help. I could solve the problem with the encoding problem by switching my system's timezone from "Mitteleuropäische Sommerzeit" (Central european summer time) to UTC. However that did not solve the "UNKNOWN COMMAND" problem. Now when running the SHOW VARIABLES query I don't get a warning and the Connector/J does not execute SHOW WARNINGS anymore. So it must be something else. Do you have any idea how I can find out which is the command that the server does not understand? Can I set a breakpoint somewhere to find out which commands are sent by the connector? Below is the general log without warnings and encoding problems: 100721 9:23:08 2 Connect EIM@localhost on 2 Query /* mysql-connector-java-5.1.13 ( Revision: ${bzr.revision-id} ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect' 2 Query /* mysql-connector-java-5.1.13 ( Revision: ${bzr.revision-id} ) */SELECT @@session.auto_increment_increment 2 Query SHOW COLLATION 2 Query SET character_set_results = NULL 2 Query SET autocommit=1 The result of the SHOW VARIABLES query (EXECUTED IN MYSQL COMMANDLINECLIENT): +--------------------------+----------------------------------------------------------------+ | Variable_name | Value | +--------------------------+----------------------------------------------------------------+ | character_set_client | utf8 | | character_set_connection | utf8 | | character_set_results | utf8 | | character_set_server | utf8 | | init_connect | | | interactive_timeout | 28800 | | language | C:\Program Files\MySQL\MySQL Server 5.1\share\english\ | | lower_case_table_names | 1 | | max_allowed_packet | 33554432 | | net_buffer_length | 16384 | | net_write_timeout | 60 | | query_cache_size | 17825792 | | query_cache_type | ON | | sql_mode | STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION | | system_time_zone | Koordinierte Weltzeit | | time_zone | SYSTEM | | tx_isolation | REPEATABLE-READ | | wait_timeout | 28800 | +--------------------------+----------------------------------------------------------------+ By the way, I tried the test on several machines using Windows and Linux on the server side (Windows on the client side) and it fails every time. I'll try to run it on a Linux client.
[21 Jul 2010 10:08]
Tonci Grgin
Martin, we still do not know what the mysterious character is nor did you attach small but complete test case so I can check (incl. conn-string!). As for debugging, it is enough to have Eclipse installed and then you create new project by cloning c/J public source tree.
[21 Jul 2010 10:10]
Tonci Grgin
You can also use WireShark or add "traceprotocol=true" to connection string to see the actual communication between your client and MySQL server.
[21 Jul 2010 10:36]
Martin Kirchner
final String dbUrl = "jdbc:mysql://localhost:3308/?characterEncoding=utf8&traceprotocol=true"; final MysqlConnectionPoolDataSource pds = new MysqlConnectionPoolDataSource(); pds.setUrl(dbUrl); final PooledConnection pooledConnection = pds.getPooledConnection(); final Connection connection = pooledConnection.getConnection(); final PreparedStatement pstmt = connection .prepareStatement("SHOW SCHEMAS;"); final ResultSet rs = pstmt.executeQuery(); while (rs.next()) { System.out.println(rs.getString(1)); } pstmt.close();
[21 Jul 2010 10:44]
Tonci Grgin
Martin, final PreparedStatement pstmt = connection .prepareStatement("SHOW SCHEMAS;"); is *NOT* preparable at all so please remove thins unnecessary call and use normal statement. Still, this does not show me what the actual character just before "ische" is (\xE4). AFAIS, your problem is not a result of bug but rather of mish-mash in your encodings.
[21 Jul 2010 10:53]
Susanne Ebrecht
Tonci, \xE4 is latin1 encoded 'ä' ... means word will be äische and encoding used for typing is latin1.
[21 Jul 2010 11:09]
Martin Kirchner
Ok, I replaced the PreparedStatement with a normal. Still doesn't work: final String dbUrl = "jdbc:mysql://localhost:3308/?characterEncoding=utf8&traceprotocol=true"; final MysqlConnectionPoolDataSource pds = new MysqlConnectionPoolDataSource(); pds.setUrl(dbUrl); final PooledConnection pooledConnection = pds.getPooledConnection(); final Connection connection = pooledConnection.getConnection(); final Statement stmt = connection.createStatement(); final ResultSet rs = stmt.executeQuery("SHOW SCHEMAS"); while (rs.next()) { System.out.println(rs.getString(1)); } stmt.close();
[21 Jul 2010 11:17]
Tonci Grgin
Luckily I have Susanne here or otherwise I would have never found out what is the schema name that's bothering you... Now, you obviously have unnecessary utf8 - latin1 conversion somewhere like environment encoding latin1, charset client utf8 or similar. Please fix your environment first and then check server/database/table/field encodings as explained in that link I gave you. Just a note from Susanne: ä = e4 in latin1 .... ä=c3a4 in utf8
[21 Jul 2010 13:56]
Martin Kirchner
So, once again. I solved all encoding problems. No warnings anymore. I set up a fresh Linux machine installed a MySQL 5.1, Java 6, my little test program from the last comment, started it and again: Unknown command I monitored the network traffic using Wireshark (client and Wireshark on my Windows machine). You'll find the traffic in an attached file. The problem is the change user command that is send by the connector.
[21 Jul 2010 13:56]
Martin Kirchner
Traffic between Connector/J and MySQL 5.1
Attachment: Wireshark.txt (text/plain), 16.15 KiB.
[21 Jul 2010 13:58]
Martin Kirchner
Change User command sent to the server
Attachment: ScreenShot 247 MySQL Bugs_ #54425_ Unknown command when connecting to MySQL 5.1 with MysqlConnectionPoolDataSource - Mozilla Firefox.png (image/png, text), 37.90 KiB.
[21 Jul 2010 13:59]
Martin Kirchner
Response: Unknown command
Attachment: ScreenShot 248 MySQL Bugs_ #54425_ Unknown command when connecting to MySQL 5.1 with MysqlConnectionPoolDataSource - Mozilla Firefox.png (image/png, text), 37.47 KiB.
[21 Jul 2010 14:22]
Martin Kirchner
I built a small demo. You can download it here: http://support.cas.de/support_download_Kunde/oj5ui7oAgfZJgGVdQcUYugd5soOgzKY2mLW82BThE1UNv... The archive contains: - the Eclipse project, - the compiled JAR (just edit db.properties in the resources folder and run it with java -jar MySQL51.jar - the my.cnf from the Linux server
[23 Aug 2010 8:27]
Tonci Grgin
Martin, using protocol's CHANGE_USER to reset the connection when coming from the connection pool is not a good idea... This is why my tests (and regression test suite) worked and your test fails. Will have to consult on this.
[1 Feb 2011 13:41]
Martin Kirchner
I'm waiting for that bug to be fixed. And I'm waiting quite some time. Are there any status updates? Regards, Martin
[1 Feb 2011 15:34]
Tonci Grgin
Martin, sorry I missed this report. Let me check with colleagues, there might have been a protocol bug in certain versions of 5.1 regarding this but I have to be sure.
[1 Feb 2011 15:48]
Tonci Grgin
Martin, versions 5.1.13-5.1.18 were affected with Bug#25371 so this might be the case here. There is also a Bug#30472. To be sure what's happening, we would need a complete data from Wireshark so that we see actual bytes transmitted. Can you please attach it?
[3 Feb 2011 7:59]
Tonci Grgin
Martin?
[26 Feb 2011 13:56]
Martin Kirchner
Sorry, my mail filter sorted out your emails. Attached you'll find the traffic captured by Wireshark. Capturing was restricted to port 3306. Thanks.
[26 Feb 2011 13:56]
Martin Kirchner
traffic captured with Wireshark
Attachment: MySQL51.pcap (application/octet-stream, text), 9.16 KiB.
[26 Feb 2011 14:00]
Martin Kirchner
I just checked version 5.1.15 of the Connector/J
[26 Feb 2011 14:01]
Martin Kirchner
MySQL Server 5.5.9 is not working either. Same error message "Unknown command".
[26 Feb 2011 17:54]
Mark Matthews
Martin, I'm not able to repeat this issue running your testcase locally with C/J 5.1.15 connecting to MySQL-5.5.8. However, are you sure you actually require the use of MysqlConnectionPoolDataSource? Are you using it to vend connections to a connection pooling implementation (which it is designed for), or to be a connection pool (which it is not)? Are you using an official binary of MySQL-5.5.8 or something compiled locally or not by the MySQL build team?
[28 Feb 2011 9:27]
Martin Kirchner
Mark, we use a org.apache.commons.dbcp.datasources.SharedPoolDataSource from the Apache Commons Pool project which requires a javax.sql.ConnectionPoolDataSource. That is why we use the com.mysql.jdbc.jdbc2.optional.MysqlConnectionPoolDataSource. // init dataSource final SharedPoolDataSource dataSource = new SharedPoolDataSource(); dataSource.setConnectionPoolDataSource(this.connectionPoolDataSourceFactory .createConnectionPoolDataSource(dbUrl, "user", "password")); dataSource.setValidationQuery("SELECT 1"); dataSource.setTestOnReturn(true); dataSource.setTestWhileIdle(true); dataSource.setTestOnBorrow(true); dataSource.setTimeBetweenEvictionRunsMillis(10000); dataSource.setMinEvictableIdleTimeMillis(1200000); dataSource.setMaxActive(40); dataSource.setMaxIdle(40); I use the official MySQL Community Server 5.5.9 from http://www.mysql.com/downloads/mysql/ as well as MySQL Community Server 5.1.55. Both versions show the described error (Unknown command), whereas the problem does not occur with several version of MySQL Community Server 5.0 (5.0.32 - 5.0.91), which I use in our productive environment. Thanks for your help.
[22 Mar 2011 17:11]
Tonci Grgin
Martin, there is indeed a malformed packet in your trace. Since there is no database parameter, offending packet should have 0x0 at the end: user is EMI, then 0x0 20 bytes for scramble then 0x0f After the scramble usually there is DB, or 0x0 if no db but there is nothing in your trace thus: db+= passwd_len + 1; /* Database name is always NUL-terminated, so in case of empty database the packet must contain at least the trailing '\0'. */ if (db >= packet_end) { my_message(ER_UNKNOWN_COM_ERROR, ER(ER_UNKNOWN_COM_ERROR), MYF(0)); break; } So, the server looks for 0x0, but there is none and you get 1047, UNKNOWN_COMMAND. Data coming from the client is not correct.
[15 Apr 2011 15:30]
Tonci Grgin
Pushed up to revision 1056.
[10 Oct 2014 7:55]
Bernhard Haumacher
What does "Pushed up to revision 1056." mean? In which version (server/connector?) will it be fixed?
[10 Oct 2014 9:09]
Tonci Grgin
Hello Bernhard. The fix is there since version 5.1.16 but the web changelog does not reflect the fact. You can find it as 3rd fix in 5.1.16 in changelog provided with c/J driver.
[16 Oct 2014 7:51]
Bernhard Haumacher
Hi Tonci, thanks for your info - unfortunately, this fix does not help for the problem, that a warning is still logged when querying "show variables" on a localized system in e.g. Germany (timezone CEST) with character set "utf-8". This still produces "Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE' at row 1" and a corrupted value for "system_time_zone". My version is 5.1.44-community. Is it worth opening another ticket? Best regards Bernhard Haumacher
[16 Oct 2014 8:52]
Tonci Grgin
Bernhard, let me check with developers first.
[16 Oct 2014 12:34]
Filipe Silva
Hi Bernhard, For us to be able proceed, could you please provide the following information? If your OS is a Linux, your system's time zone: (one of these should do it) - cat /etc/timezone - echo $ZONE - echo $TZ - find /usr/share/zoneinfo -type f -exec sh -c "diff -q /etc/localtime '{}' > /dev/null && echo {}" \; and also: - date +%Z If not, please try to get this information by other means. The results of executing in the mysql command-line tool: - show variables like '%zone%'; - show variables like '%char%'; - show variables like '%lang%'; If any of these queries produces as warning, please send us the result of SHOW WARNINGS too. Thank you,
[16 Oct 2014 13:27]
Bernhard Haumacher
Hi Filipe, the operation system information is Betriebssystemname Microsoft Windows 7 Professional Version 6.1.7601 Service Pack 1 Build 7601 Prozessor Intel(R) Core(TM) i7-2640M CPU @ 2.80GHz, 2801 MHz, 2 Kern(e), 4 logische(r) Prozessor(en) BIOS-Version/-Datum Dell Inc. A19, 14.11.2013 Zeitzone Mitteleuropäische Sommerzeit But the problem occurs on a variety of other machines, too (up to my knowledge all Windows systems). MySQL delivers the following results: mysql> show variables like '%zone%'; +------------------+-------------+ | Variable_name | Value | +------------------+-------------+ | system_time_zone | Mitteleurop | | time_zone | SYSTEM | +------------------+-------------+ 2 rows in set, 1 warning (0.00 sec) mysql> show warnings; +---------+------+-----------------------------------------------------------------------------+ | Level | Code | Message | +---------+------+-----------------------------------------------------------------------------+ | Warning | 1366 | Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE' at row 1 | +---------+------+-----------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> show variables like '%char%'; +--------------------------+---------------------------------------------------------+ | Variable_name | Value | +--------------------------+---------------------------------------------------------+ | character_set_client | latin1 | | character_set_connection | latin1 | | character_set_database | latin1 | | character_set_filesystem | binary | | character_set_results | latin1 | | character_set_server | latin1 | | character_set_system | utf8 | | character_sets_dir | C:\Program Files\MySQL\MySQL Server 5.1\share\charsets\ | +--------------------------+---------------------------------------------------------+ 8 rows in set (0.00 sec) mysql> show warnings; Empty set (0.00 sec) mysql> show variables like '%lang%'; +---------------+--------------------------------------------------------+ | Variable_name | Value | +---------------+--------------------------------------------------------+ | language | C:\Program Files\MySQL\MySQL Server 5.1\share\english\ | +---------------+--------------------------------------------------------+ 1 row in set (0.00 sec) mysql> show warnings; Empty set (0.00 sec) If I manually change the character set settings, by setting the corresponding variables to "utf8", the problem with the warning and the incorrect value of "system_time_zone" keeps the same: mysql> show variables like '%char%'; +--------------------------+---------------------------------------------------------+ | Variable_name | Value | +--------------------------+---------------------------------------------------------+ | character_set_client | utf8 | | character_set_connection | utf8 | | character_set_database | latin1 | | character_set_filesystem | binary | | character_set_results | utf8 | | character_set_server | utf8 | | character_set_system | utf8 | | character_sets_dir | C:\Program Files\MySQL\MySQL Server 5.1\share\charsets\ | +--------------------------+---------------------------------------------------------+ 8 rows in set (0.00 sec) mysql> show variables like '%zone%'; +------------------+-------------+ | Variable_name | Value | +------------------+-------------+ | system_time_zone | Mitteleurop | | time_zone | SYSTEM | +------------------+-------------+ 2 rows in set, 1 warning (0.00 sec) mysql> show warnings; +---------+------+-----------------------------------------------------------------------------+ | Level | Code | Message | +---------+------+-----------------------------------------------------------------------------+ | Warning | 1366 | Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE' at row 1 | +---------+------+-----------------------------------------------------------------------------+ 1 row in set (0.00 sec) Best regards, Bernhard Haumacher
[16 Oct 2014 15:49]
Filipe Silva
Hi Bernhard, Is there any chance you could try this with the latest MySQL 5.1.73 and/or MySQL 5.6.21 or do you have a good reason to not upgrade? Best regards,
[17 Oct 2014 6:56]
Bernhard Haumacher
Hi Filipe, no, there is no good reason not to upgrade - except laziness. I now upgraded my local server to 5.1.73-community, but there is no difference in behavior: mysql> show variables like "%version%"; +-------------------------+------------------------------+ | Variable_name | Value | +-------------------------+------------------------------+ | protocol_version | 10 | | version | 5.1.73-community | | version_comment | MySQL Community Server (GPL) | | version_compile_machine | unknown | | version_compile_os | Win64 | +-------------------------+------------------------------+ 5 rows in set (0.00 sec) mysql> show variables like "%char%"; +--------------------------+---------------------------------------------------------+ | Variable_name | Value | +--------------------------+---------------------------------------------------------+ | character_set_client | utf8 | | character_set_connection | utf8 | | character_set_database | latin1 | | character_set_filesystem | binary | | character_set_results | utf8 | | character_set_server | utf8 | | character_set_system | utf8 | | character_sets_dir | C:\Program Files\MySQL\MySQL Server 5.1\share\charsets\ | +--------------------------+---------------------------------------------------------+ 8 rows in set (0.00 sec) mysql> show variables like "%zone%"; +------------------+-------------+ | Variable_name | Value | +------------------+-------------+ | system_time_zone | Mitteleurop | | time_zone | SYSTEM | +------------------+-------------+ 2 rows in set, 1 warning (0.01 sec) mysql> show warnings; +---------+------+-----------------------------------------------------------------------------+ | Level | Code | Message | +---------+------+-----------------------------------------------------------------------------+ | Warning | 1366 | Incorrect string value: '\xE4ische...' for column 'VARIABLE_VALUE' at row 1 | +---------+------+-----------------------------------------------------------------------------+ 1 row in set (0.00 sec) Best regards, Bernhard Haumacher
[17 Oct 2014 11:46]
Filipe Silva
Hi Bernhard, Thank you very much for your collaboration. Meanwhile we verified the same behavior in other MySQL versions. From now on, this bug will be taken care of by the server development team. New bug reported in http://bugs.mysql.com/bug.php?id=74429 (may take a while to become public). Thank you,
[27 Oct 2014 10:44]
Bernhard Haumacher
> ...may take a while to become public Is it normal that the new ticket is still not yet accessible?
[28 Oct 2014 10:09]
Filipe Silva
Hi Bernhard, Thank you for your interest. The Bug#74429 is public now.