MySQL Bugs: #3826: Mysql Connector/J (3.1.1-alpha) hangs on useCompress=true

Bug #3826	Mysql Connector/J (3.1.1-alpha) hangs on useCompress=true
Submitted:	19 May 2004 2:37	Modified:	4 Aug 2004 16:37
Reporter:	Mudit Wahal	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / J	Severity:	S1 (Critical)
Version:	3.1.1-alpha	OS:	Windows (Windows XP)
Assigned to:	Mark Matthews	CPU Architecture:	Any

Description:
My enviroment:

Windows XP Pro (also tried on Windows 2000)
JDK j2sdk1.4.2_03-b02
mysql 3.1.1 alpha-bin.jar

URL String =
jdbc:mysql://192.168.123.2:3306/dummy?autoReconnect=true&useCompression=true
user and passwd are protected.

Output from "mysql --version"
mysql  Ver 11.19 Distrib 4.0.1-alpha, for pc-linux-gnu (i686)

Problem:

I've been using the mm.mysql-2.0.12-bin.jar file for more than 2 years. I just
wanted to try compression feature of connector/J to reduce the bandwidth.
My URL (without the &useCompression=true) string and my username, password and
mysql server has been working fine for over 2 years. Very satisfied.

If I set compression to true, my connection to the mysql server hangs indefinitely. 
If I change it back to false, I connect immediately. I'm using JBuilder X to debug.
I paused the program and the thread is something like. Sorry for any typos, I had
to type everything as I can't seems to cut and paste.

(in reverse order obviously)

getConnection - java.sql.DriverManager
getConnection - java.sql.DriverManager
connect - com.mysql.jdbc.NonRegisteringDriver
<init> - com.mysql.jdbc.Connection
createNewIO - com.mysql.jdbc.Connection
ping - com.mysql.jdbc.Connection
sqlQueryDirect - com.mysql.jdbc.MySqlIO
readAllResults - com.mysql.jdbc.MySqlIO
readResultsForQueryOrUpdate - com.mysql.jdbc.MySqlIO
getResultSet - com.mysql.jdbc.MySqlIO
readSingleRowSet - com.mysql.jdbc.MySqlIO
nextRow - com.mysql.jdbc.MySqlIO
checkErrorPacket (629) - com.mysql.jdbc.MySqlIO
checkErrorPacket(2179) - com.mysql.jdbc.MySqlIO
reuseAndReadPacket - com.mysql.jdbc.MySqlIO
readFully - com.mysql.jdbc.MySqlIO
read - com.mysql.jdbc.CompressedInputStream
getNextPacketIfRequired - com.mysql.jdbc.CompressedInputStream
getNextPacketFromServer - com.mysql.jdbc.CompressedInputStream
read - java.net.SocketInputStrream
socketRead - java.net.SocketInputStrream

Thanks

Mudit

How to repeat:
Just use useCompress=true when connecting to the mysql server.

This doesn't appear repeatable with the current 3.1 codebase. Could you please try a nightly snapshot of 3.1 from http://downloads.mysql.com/snapshots.php ?

I'm running mysql 4.0.1-alpha. By any chance compress/uncompress
is not implemented in it ? How can I verify is compress/uncompress is
implemented in it ?

I'll download the nightly snapshot and try it out.

Thanks

Mudit

Just tried nightly build, also hangs with it. My guess is that probably
uncompress/compress is not implemented in 4.0.1-alpha. I'll try to upgrade my server in the weekend and will let you know.

Thanks

Mudit

I've upgraded to latest mysql server. It doesn't hang any more but there are other issues when useCompress is enabled. Shall I file a new bug or just update this one ?

Thanks

Mudit

What version of Connector/J are you using with what version (_exactly_, i.e. 4.1.0 from the website, a build from BK, etc.) of MySQL?

Just upgraded to mysql-standard alpha 4.1.1.

----------- output from mysql --version ----
mysql  Ver 14.3 Distrib 4.1.1-alpha, for pc-linux (i686)
-----------

When I set useCompress=true, here is the stack trace and exception message.
With useCompress=false, everything is fine. The java application remains
same, everything is constant except for the useCompress flag.

------------

C:\mystocks>java -Xmx384m -classpath  hb15.jar;jcommon-0.6.1.jar;jfreechart-0.8.
1.jar;mysql-connector-java-3.1.1-alpha-bin.jar;scrollabledesktop.jar;. mymdinewD
T
myTickerName.getTickerName : JDBC exception Server connection failure during tra
nsaction. Due to underlying exception: 'java.sql.SQLException: Communication lin
k failure message from server: "Unknown command"'.
Attempted reconnect 3 times. Giving up.
java.sql.SQLException: Server connection failure during transaction. Due to unde
rlying exception: 'java.sql.SQLException: Communication link failure message fro
m server: "Unknown command"'.
Attempted reconnect 3 times. Giving up.
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1549)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1891)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1847)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:1182)
        at mysqlhand.getResultSet(mysqlhand.java:212)
        at myTickerName.getTickerName(myTickerName.java:213)
        at myTickerDB.getTickerName(myTickerDB.java:409)
        at mystocks.processForm(mystocks.java:221)
        at mystocks.doForm(mystocks.java:164)
        at mystocks.newForm(mystocks.java:157)
        at mystocks.<init>(mystocks.java:119)
        at mymdinewDT$ChartOpenAction.open_charts_later(mymdinewDT.java:2744)
        at mymdinewDT$11.run(mymdinewDT.java:2789)
        at myThreadPool.run(myThreadPool.java:100)
        at java.lang.Thread.run(Thread.java:534)

It appears from the command line that you just posted, you've reverted to a non-nightly build, which has the issue with compression. Can you please try (again) a nightly build?

I tried the nightly build which I downloaded on 18th .. same message.
Will download the latest snapshot (today's) and try that out and post
the messages.

Thanks for quick replies !!!

Mudit

Seems like snapshot server is down .. will try again later

Just downloaded the May 24th nightly build. Here is the stacktrace. Once
again the problem only happens with useCompress=true. If you want I can
zip my program and send you the link privately along with instructions
how to setup the application. Its very easy to configure and run.

Thanks

Mudit

-------------------------------

C:\mystocks>java -Xmx384m -classpath  hb15.jar;jcommon-0.6.1.jar;jfreechart-0.8.
1.jar;mysql-connector-java-3.1-nightly-20040524-bin.jar;scrollabledesktop.jar;.
mymdinewDT
myTickerName.getTickerName : JDBC exception Server connection failure during tra
nsaction. Due to underlying exception: 'java.sql.SQLException: Communication lin
k failure message from server: "Unknown command"'.

** BEGIN NESTED EXCEPTION **

java.sql.SQLException
MESSAGE: Communication link failure message from server: "Unknown command"

STACKTRACE:

java.sql.SQLException: Communication link failure message from server: "Unknown
command"
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2441)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1396)
        at com.mysql.jdbc.Connection.ping(Connection.java:3207)
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1799)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2248)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2199)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:1182)
        at mysqlhand.getResultSet(mysqlhand.java:212)
        at myTickerName.getTickerName(myTickerName.java:213)
        at myTickerDB.getTickerName(myTickerDB.java:409)
        at mystocks.processForm(mystocks.java:221)
        at mystocks.doForm(mystocks.java:164)
        at mystocks.newForm(mystocks.java:157)
        at mystocks.<init>(mystocks.java:119)
        at mymdinewDT$ChartOpenAction.open_charts_later(mymdinewDT.java:2744)
        at mymdinewDT$11.run(mymdinewDT.java:2789)
        at myThreadPool.run(myThreadPool.java:100)
        at java.lang.Thread.run(Thread.java:534)

** END NESTED EXCEPTION **

Attempted reconnect 3 times. Giving up.
java.sql.SQLException: Server connection failure during transaction. Due to unde
rlying exception: 'java.sql.SQLException: Communication link failure message fro
m server: "Unknown command"'.

** BEGIN NESTED EXCEPTION **

java.sql.SQLException
MESSAGE: Communication link failure message from server: "Unknown command"

STACKTRACE:

java.sql.SQLException: Communication link failure message from server: "Unknown
command"
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2441)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1396)
        at com.mysql.jdbc.Connection.ping(Connection.java:3207)
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1799)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2248)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2199)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:1182)
        at mysqlhand.getResultSet(mysqlhand.java:212)
        at myTickerName.getTickerName(myTickerName.java:213)
        at myTickerDB.getTickerName(myTickerDB.java:409)
        at mystocks.processForm(mystocks.java:221)
        at mystocks.doForm(mystocks.java:164)
        at mystocks.newForm(mystocks.java:157)
        at mystocks.<init>(mystocks.java:119)
        at mymdinewDT$ChartOpenAction.open_charts_later(mymdinewDT.java:2744)
        at mymdinewDT$11.run(mymdinewDT.java:2789)
        at myThreadPool.run(myThreadPool.java:100)
        at java.lang.Thread.run(Thread.java:534)

** END NESTED EXCEPTION **

Attempted reconnect 3 times. Giving up.
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1858)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2248)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2199)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:1182)
        at mysqlhand.getResultSet(mysqlhand.java:212)
        at myTickerName.getTickerName(myTickerName.java:213)
        at myTickerDB.getTickerName(myTickerDB.java:409)
        at mystocks.processForm(mystocks.java:221)
        at mystocks.doForm(mystocks.java:164)
        at mystocks.newForm(mystocks.java:157)
        at mystocks.<init>(mystocks.java:119)
        at mymdinewDT$ChartOpenAction.open_charts_later(mymdinewDT.java:2744)
        at mymdinewDT$11.run(mymdinewDT.java:2789)
        at myThreadPool.run(myThreadPool.java:100)
        at java.lang.Thread.run(Thread.java:534)
myTradingDays : JDBC exception in  Server connection failure during transaction.
 Due to underlying exception: 'java.sql.SQLException: Communication link failure
 message from server: "Unknown command"'.

** BEGIN NESTED EXCEPTION **

java.sql.SQLException
MESSAGE: Communication link failure message from server: "Unknown command"

STACKTRACE:

java.sql.SQLException: Communication link failure message from server: "Unknown
command"
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2441)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1396)
        at com.mysql.jdbc.Connection.ping(Connection.java:3207)
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1799)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2248)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2199)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:1182)
        at mysqlhand.getResultSet(mysqlhand.java:212)
        at myTradingDays.<init>(myTradingDays.java:54)
        at myTradingDays.getNthDay(myTradingDays.java:157)
        at myTradingDays.getLastDayFromOffset(myTradingDays.java:134)
        at mystocks.createHiLowDB(mystocks.java:267)
        at mystocks.makechart(mystocks.java:243)
        at mystocks.doForm(mystocks.java:165)
        at mystocks.newForm(mystocks.java:157)
        at mystocks.<init>(mystocks.java:119)
        at mymdinewDT$ChartOpenAction.open_charts_later(mymdinewDT.java:2744)
        at mymdinewDT$11.run(mymdinewDT.java:2789)
        at myThreadPool.run(myThreadPool.java:100)
        at java.lang.Thread.run(Thread.java:534)

** END NESTED EXCEPTION **

Attempted reconnect 3 times. Giving up.

We'd prefer (for many reasons) a standalone testcase that shows the bug. Any chance you could come up with one? Does something as simple as a 'SELECT' trigger this, or is it due to some given size of recordset retrieved?

Mark,

Since the application works without useCompress set to true, we know that there is nothing wrong with the select statements. Its the compress/uncompress
logic of the driver and/OR the mysql server which has issues.

Are there any debug flags I can turn on the mysql server side to track the error messages, extra logging etc ? Can I print all the requests coming
to the mysql server and the responses from the server to the client ?

Thanks

Mudit

I found the -log option and saved the log from the java app to the server with and without the useCompress option. Look at the timestamp of 13:58:40.

Look for all the queries made by sqluser.

There is an extra "se^N" going to the server when the useCompress is true.

It also has another application coming in and accessing/loading the database. I'll try to remove it later and reproduce the problem.

/usr/local/mysql/bin/mysqld, Version: 4.1.1-alpha-standard-log, started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
040524 13:57:23       1 Connect     root@localhost on
              2 Connect     wmudit@localhost on
              2 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3865' replace into table intra_snapshot.intra
              2 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3865' replace into table intra_snapshot.allday
040524 13:57:24       2 Quit
040524 13:57:27       1 Query       show databases
040524 13:57:28       1 Quit
040524 13:57:56       3 Connect     wmudit@localhost on
              3 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3905' replace into table intra_snapshot.intra
              3 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3905' replace into table intra_snapshot.allday
              3 Quit
040524 13:58:04       4 Connect     sqluser@xx.xx.xx.xx on
              4 Query       SELECT 1
              4 Query       SET character_set_results = NULL
040524 13:58:05       4 Query       SHOW VARIABLES
              4 Query       SHOW COLLATION
              4 Query       SET autocommit=1
              4 Query       select * from groups.allticks
040524 13:58:10       4 Query       select * from groups.a
040524 13:58:11       4 Query       select * from names.names where ticker='A'
              4 Query       select * from stocks_info.yahoo where ticker='A'
              4 Query       select * from stocks_info.gics where ticker='A'
              4 Query       select * from tradingdays.tradingdays
040524 13:58:19       4 Query       select * from eod_stocks.A where date >= '20030
521' && date <= '20040524' && volume >= 0
040524 13:58:20       4 Query       select * from intra_snapshot.intra where ticker
 = 'A' order by time
040524 13:58:34       5 Connect     sqluser@dhcp-171-69-117-111.cisco.com on
              5 Query       SELECT 1
              5 Query       SET character_set_results = NULL
              5 Query       SHOW VARIABLES
              5 Query       SHOW COLLATION
              5 Query       SET autocommit=1
040524 13:58:35       5 Query       select * from groups.allticks
040524 13:58:37       6 Connect     wmudit@localhost on
              6 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3948' replace into table intra_snapshot.intra
              6 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3948' replace into table intra_snapshot.allday
              6 Quit
040524 13:58:40       5 Query       select * from groups.a
              5 Query       se^N
040524 13:58:41       7 Connect     sqluser@xx.xx.xx.xx on
040524 13:58:43       8 Connect     sqluser@xx.xx.xx.xx on
040524 13:58:47       9 Connect     sqluser@xx.xx.xx.xx on
040524 13:58:55      10 Connect     sqluser@xx.xx.xx.xx on
040524 13:58:58      11 Connect     sqluser@xx.xx.xx.xx on
040524 13:59:02      12 Connect     sqluser@xx.xx.xx.xx on
040524 13:59:08      13 Connect     wmudit@localhost on
             13 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3991' replace into table intra_snapshot.intra
             13 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.3991' replace into table intra_snapshot.allday
             13 Quit
040524 13:59:13      14 Connect     sqluser@xx.xx.xx.xx on
040524 13:59:37      15 Connect     wmudit@localhost on
             15 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.4030' replace into table intra_snapshot.intra
             15 Query       load data infile '/home/wmudit/tmp/moretmp/addtointradb
.4030' replace into table intra_snapshot.allday
             15 Quit

Final comment for today.

The problem only happens after this statement
---------------
select * from groups.a
---------------

BTW, there is no table "a" inside the groups database. Normally, its okay and the application continues when the compression is disabled. But seems like
if the compression is enabled, there is some issue with the return code or
whatever and the jdbc driver gets stuck.

So, may be this is how you can try to recreate it. Try to access a nonexisting table from a database with compression enabled and see if you get same stack trace/error messages.

The mysql cli with --compress option works okay
--------------
wmudit $ mysql -A --compress
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2 to server version: 4.1.1-alpha-standard

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

mysql> select * from groups.a;
ERROR 1146 (42S02): Table 'groups.a' doesn't exist
mysql> quit
Bye
wmudit $ 
--------------------------------

Thanks

Mudit

Tonight's nightly build should have the fixes you need. I can run our entire regression test suite with compression enabled. Could you please test your application with http://downloads.mysql.com/snapshots/mysql-connector-java-3.1/mysql-connector-java-3.1-nig...

(it was just uploaded to the staging server and should be available within the hour).

The 26th may snapshot works !! Thanks !! 

TestQuery.java works fine with both compression enabled and disabled.

Thanks for the fast response !!!!!

Mudit