Bug #1540 "Communication link failure" when Connect/J hasn't been exercised for a while
Submitted: 13 Oct 2003 1:39 Modified: 19 Nov 2003 11:33
Reporter: Phil Sladen Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:3.0.9-stable OS:Linux (Linux)
Assigned to: Mark Matthews CPU Architecture:Any

[13 Oct 2003 1:39] Phil Sladen
Description:
During normal usage Connector/J seems to work fine. However, if the connection hasn't been used for a while, then when the first query happens I get one of 2 stack traces. Subsequent queries appear to work fine.
Either:
java.io.IOException: Unexpected end of input stream
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1405)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1775)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1020)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1109)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2030)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1563)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:445)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:394)
 
Or:
java.sql.SQLException: Communication link failure: java.io.IOException
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1629)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:889)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:956)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1874)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1538)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:445)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:394)

I am using MySQL 3.23.58-1 and Connector/J 3.0.9-stable and Tomcat 4.1.27 is trying to do authentication using a JDBC realm, ie. using tables in MySQL. 

How to repeat:
Hopefully, you already know about this problem (although I couldn't find it on you bug database), or you have a good idea what the cause of the problem is. However, if you need further information to reproduce the Tomcat environment then please let me know.
[13 Oct 2003 7:20] Phil Sladen
OK. I've now seem in the documentation that the server closes connections that haven't been used for 8 hours... this is probably what I've been seeing and I've added the 'autoReconnect=true' to the connection urls. Downgraded severity and priority, although I don't really see why the server should do what it does!
[14 Oct 2003 4:36] Phil Sladen
Adding 'autoReconnect=true' to the connect string hasn't fixed the problem so I've upped the priority and severity back to what I had used on the original submission. Also, I am now using MySQL 4.0.15 and get this error after not using the connection for a while:

java.io.IOException: Unexpected end of input stream
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1405)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1775)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1020)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1109)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2030)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1563)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:445)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:394)
        ...

Nested exception:
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1527)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1775)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1020)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1109)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2030)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1563)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:445)
        at org.apache.catalina.realm.JDBCRealm.authenticate(JDBCRealm.java:394)
        ...
[31 Oct 2003 20:51] Mark Matthews
Is the connection in autoCommit(true)? If not, the reconnection code won't work until it is (or attempted to be put into that mode).
[2 Nov 2003 6:09] Phil Sladen
I don't do anything with the autoCommit setting, since I just configure Tomcat's server.xml file with the following to have authentication by JDBCRealm for my web application:

<Context path="/MyWebApp" docBase="MyWebApp" reloadable="true" override="true">
  <Realm  className="org.apache.catalina.realm.JDBCRealm" debug="0"                           driverName="com.mysql.jdbc.Driver"	connectionURL="jdbc:mysql://localhost/MyDB?user=reader&amp;password=reader&amp;autoReconnect=true"
userTable="users" userNameCol="username" userCredCol="userpass"
userRoleTable="userroles" roleNameCol="rolename"
  />
</Context>

a) I don't know what Connector/J is doing with autoCommit setting. I imagine the      default is 'true'.
b) Most of the time I rely on transactions, so the authentication tables
are also of type InnoDB.
c) I didn't used to have this problem with my previous driver mysql-connector-java-2.0.14, but then again it didn't appear to require the 'autoReconnect' setting and I was using BDB type tables, and it was on Windows. I hope this is enough information. Thanks.
[3 Nov 2003 1:09] Denis Signoretto
I had the same behaviour and exception in a stand-alone application developed with SUN SDK 1.4.1_02, Connector/J-3.0.9 and MySQL 3.23.52 and (after an update 3.23.58) on Sun  Solaris 2.8.

At the moment I'm rolling back to version 3.0.6 og Connector/J and it seems to work fine. I hope this could help. 

Denis.
[3 Nov 2003 11:22] Mark Matthews
If you dig into the source code of Tomcat's JDBC Realm, you will see that it has two problems (wrt. autoReconnect, and robustness in general).

1. It grabs a connection and sets it to 'autoCommit=false', and never returns it to autoCommit=true state (so Connector/J's autoReconnect functionality won't work here).

2. It doesn't ever try to recover from SQLExceptions, so it is not a set-it-and-forget it type of thing (the JDBC spec doesn't state that JDBC connections are an everlasting resource that 'automagically' survice I/O errors, for good reason, the appropriate behavior for recovering from a lost connection differs from application to application, especially when dealing with transactions). 

If your application doesn't ever set a connection into autoCommit=true mode, autoReconnect from version 3.0.7 on will _not_ work for you (this includes Tomcat's JDBCRealm).

The reason it worked before 3.0.7 is that the driver would 'ping' the database server before _every_ query, regardless of autoCommit state, which incurs too much overhead, and can be dangerous (i.e. reconnecting in the middle of a transaction would cause the application and the database to become 'out-of-sync' with eachother). This behavior was fixed to be less resource intensive (i.e. only ping when needed, and when safe), and works with most connection pools, as they always set autoCommit=true when a connection is returned, because it is the default state of a 'new' connection as stated by the JDBC spec.

As a work-around, I am working on adding a 'reconnectAtTxEnd' parameter to Connector/J that will allow applications that can not be re-worked to have the reconnection code run at Connection.commit()/rollback(). This is still hack-ish, in that the applications themselves should _really_ be fixed to handle this, because only the developer of the application can determine when it is appropriate to continue a transaction, re-try a transaction, or abort.

I suggest that you either file a bug report or patch against Tomcat's JDBCRealm to have it attempt to 'recover' from a bad connection (which would improve it for all people trying to run it in a 24/7 production environment with pretty much any JDBC driver), or setup a datasource realm, backed by a DBCP connection pool that has been configured to test idle and bad connections (see http://jakarta.apache.org/tomcat/tomcat-4.1-doc/realm-howto.html#DataSourceRealm), or snag the source to JDBCRealm from the Tomcat sourcecode, and create your own version that catches SQLExceptions, determines if the connection is dead (a simple check for SQLState.equals("08S01") should do that), and create a new connection.
[6 Nov 2003 4:44] Phil Sladen
Thanks Denis and Mark for your help/analysis. I will raise an issue with Tomcat as to why it doesn't just open the authentication connection when needed and then close it again, instead of opening it at startup and keeping it open. In terms of the MySQL server dropping connections after 8 hours, the variable 'wait_timeout' (or 'interative_timeout' for interactive connections?) controls this behaviour except that it doesn't accept 0 or -1 to indicate that the connection should never be timed-out, and is a global setting. So I've set mine to 365 days, which has worked for about 11 hours so far :)
Many thanks.
[6 Nov 2003 4:49] Phil Sladen
Since there's no particular fault with MySQL or Connector/J then I've downgraded this problem status to Non-critical and low priority, I hope that's ok. You might even want to close it :)
[11 Nov 2003 3:28] Denis Signoretto
Sorry, but I'm still having a similar problem with a standalone
application written in Java SDK 1.4.1_01 on Sun Solaris. I'm connecting
to mysql-3.23.58 running on the same machine (Sun Solaris 8) with Connector/J
3.0.9-stable.

I'm connecting to DB throught a singleton class with this method:

public Connection getConnection() {        

        Connection conn = null;
        try {
            conn = DriverManager.getConnection("jdbc:mysql://" +
                    ConfigFactory.getInstance().getDatabaseHost() + "/" +
                    ConfigFactory.getInstance().getDatabaseName() + "?user=" +
                    ConfigFactory.getInstance().getDatabaseUser() + "&password=" +
                    ConfigFactory.getInstance().getDatabasePasswd() +
                    "&autoReconnect=true" +                    
            );

        } catch (Exception e) {
            PrintLog.printOnError("Database Connection Failure on connect() method.", e);
            // System.exit(1);
        }
        return conn;
    }

My problem is that connecting to MySQL seems to work fine at application
startup. After a while the connecion with DB fails and the application hangs up.
I can see that a tcp connection is esthablised throug a netstat command:
> netstat -a
> 127.0.0.1.38077      127.0.0.1.3306       32768      0 32768      0 ESTABLISHED
> 127.0.0.1.3306       127.0.0.1.38077      32768      0 32768      0 ESTABLISHED

After 8 hour, the connection with DB give restart giving this exception:

[Mon 2003-10-27 19:35:00] Starting SnmpStoreDataMultipleThread.
[Tue 2003-10-28 03:35:00] Database Failure on insertSnmpCollectedData method.
[Tue 2003-10-28 03:35:00] Communication link failure: java.io.IOException, under
lying cause: Unexpected end of input stream

** BEGIN NESTED EXCEPTION **

java.io.IOException
MESSAGE: Unexpected end of input stream

STACKTRACE:

java.io.IOException: Unexpected end of input stream
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1405)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1775)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1020)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1109)
        at com.mysql.jdbc.MysqlIO.sqlQuery(MysqlIO.java:1070)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2027)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1984)
        at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1248)
        at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1194)
        at com.acplab.astanet.archivi.SnmpDataDB.insertMultipleSnmpCollectedData
(SnmpDataDB.java:167)
        at com.acplab.astanet.services.pollerd.StoreDataMultipleThread.storeAllT
hreadsData(StoreDataMultipleThread.java:105)
        at com.acplab.astanet.services.pollerd.Pollerd.run(Pollerd.java:194)
        at java.util.TimerThread.mainLoop(Timer.java:432)
        at java.util.TimerThread.run(Timer.java:382)

** END NESTED EXCEPTION **

[Tue 2003-10-28 03:35:00] java.sql.SQLException: Communication link failure: jav
a.io.IOException, underlying cause: Unexpected end of input stream
[11 Nov 2003 5:51] Mark Matthews
Phil, does your standalone app use 'autoReconnect=true', and if it does, does it ever mess with Connection.setAutoCommit()? If you remember from earlier, autoReconnect=true only works when auto-commit is 'on', because otherwise your data could get scrambled.

In any case, your application should be handling the case when connections die due to communications errors (they happen all the time, and many times have nothing to do with the driver or the server, networks get unplugged, machines get restarted, etc, etc).

It is the application's responsibility to detect, and recover from errors such as this. Nowhere does the JDBC spec say that the lifetime of a connection is indefinite and not subject to network errors (I actually brought this up with the JDBC spec lead and everyone on the JDBC-4.0 expert group, and they all agreed). Connector/J does make this easy to detect, if an error occurs, and it is due to a network issue, the SQLState of the exception thrown will be "08S01". If that is the case, your application can determine what is the correct action to take (re-connect, and re-try the transaction, abort the current transaction and reconnect later, etc). Only your application knows what the correct path to take would be.
[12 Nov 2003 5:17] Phil Sladen
Mark, my application tries to ensure data integrity by using database transactions. It uses 'autoReconnect=true' and sets 'autoCommit(false) for all connections [in addition, 'read-only' connections are given the hint 'setReadOnly(true)]. It explicitly commits updates when it has successfully determined and made a set of them. So, if the connection goes down during the updates then all the updates should be rolled-back automatically (I've tested this and it does work). From what you've said, my 'autoReconnect=true' setting will do nothing... but I've left it in for now with no apparent problem... but if you're telling me that this will scramble my data at some point then I'm gonna take it out right now :)
[12 Nov 2003 5:22] Mark Matthews
What I'm saying is that if the autoReconnect functionality _actually_ re-connected when autoCommit was false, it could potentially scramble your data, as your transaction up to the point where the disconnect happened would be automatically rolled back, but your application would just proceed 'blindly' on after the re-connect, operating on different data than it thought it was.

If you want autoReconnect to work in your situation, you would need to set autoCommit=true after committing, and set it back to false before you start your transaction. (Which is what would happen in a connection pooling scenario).
[12 Nov 2003 6:22] Phil Sladen
Mark, I'd prefer to take the 'autoReconnect=true' off my connection string so that the user gets visual feedback of the failure and can retry the operation (application should reconnect automatically). Thanks.
[20 Nov 2003 1:31] Denis Signoretto
Hi Mark,

As you suggested I modified my Java code to detect, and recover from connection errors. My problem is that the exception on a connection is not generated immediatly but after an 8 ours internal time out. I tryed also to setup connectionTimeout and socketTimeout parameters on connection string but it seems to be ignored.

This is my code and log. As you can see the exception log
is produced only after a long 8 hours period, so I can't recover
the connection in a useful time. I also tried with or without autoCommit
and autoReconnect. The only difference is that anabling them after 8 hours
period I get a successful reconnection without exception (but always after 8
8 hours).

Can you give me any suggestion?

public Connection getConnection() {
        Log.writelnDetails("Opening a new Database Connection.");

        Connection conn = null;
        try {            

            conn = DriverManager.getConnection("jdbc:mysql://" +
                    ConfigFactory.getInstance().getDatabaseHost() + "/" +
                    ConfigFactory.getInstance().getDatabaseName() + "?user=" +
                    ConfigFactory.getInstance().getDatabaseUser() + "&password=" +
                    ConfigFactory.getInstance().getDatabasePasswd() +
               //     "&autoReconnect=true" +
                    "&=socketTimeout" + ConfigFactory.getInstance().getDatabaseTimeout() +
                    "&=connectTimeout" + ConfigFactory.getInstance().getDatabaseTimeout() +
                    ""
            );
            // conn.setAutoCommit(true);
            Log.writelnDetails("Connection Opened.");
        } catch (SQLException e) {

            PrintLog.printOnError("Database Connection Failure on connect() method.\n" +
                    "SQLState=" + e.getSQLState() + ", ErrorCode=" + e.getErrorCode(), e);
            final int RETRIES = ConfigFactory.getInstance().getDatabaseRetries();
            Connection retriedConn = null;
            for (int i=0; i<RETRIES; i++) {
                retriedConn = reconnect();
                if (retriedConn != null) {
                    PrintLog.printOnError("Re-Connection on retries " + (i+1) + " esthablished.", e);
                } else {
                    PrintLog.printOnError("Re-Connection on retries " + (i+1) + " still failed.", e);
                }
            }
            // System.exit(1);
        }
        return conn;
    }

[Wed 2003-11-19 18:55:00] Opening a new Database Connection.
[Thu 2003-11-20 02:55:00] Database Connection Failure on connect() method.
SQLState=08S01, ErrorCode=0
[Thu 2003-11-20 02:55:00] Communication link failure: java.io.IOException, underlying cause: Unexpected end of input stream

** BEGIN NESTED EXCEPTION **

java.io.IOException
MESSAGE: Unexpected end of input stream

STACKTRACE:

java.io.IOException: Unexpected end of input stream
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1405)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1775)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1020)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1109)
        at com.mysql.jdbc.MysqlIO.sqlQuery(MysqlIO.java:1070)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2027)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1996)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:1977)
        at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:654)
        at com.mysql.jdbc.Connection.initializePropsFromServer(Connection.java:2623)
        at com.mysql.jdbc.Connection.createNewIO(Connection.java:1750)
        at com.mysql.jdbc.Connection.<init>(Connection.java:562)
        at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:361)
        at java.sql.DriverManager.getConnection(DriverManager.java:512)
        at java.sql.DriverManager.getConnection(DriverManager.java:193)
        at com.acplab.astanet.archivi.Database.getConnection(Database.java:372)
        at com.acplab.astanet.archivi.SnmpDataDB.insertMultipleSnmpCollectedData(SnmpDataDB.java:151)
        at com.acplab.astanet.services.pollerd.StoreDataMultipleThread.storeAllThreadsData(StoreDataMultipleThread.java:105)
        at com.acplab.astanet.services.pollerd.Pollerd.run(Pollerd.java:194)
        at java.util.TimerThread.mainLoop(Timer.java:432)
        at java.util.TimerThread.run(Timer.java:382)

** END NESTED EXCEPTION **

Thanks,
Denis.
[1 Jun 2011 11:10] Ricardo Amillategui
Hey!

I´m suffering the same problem with mysql-connector-java-3.0.16-ga-bin.jar in Apache Tomcat:

java.sql.SQLException: Communication link failure: java.io.IOException
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1629)

After some time of inactivity in the database, Apache Tomcat cannot connect to the database. I´ve been reading about "autoreconnect=true". Las week we set that parameter to "true". But I realized that apllication sends commands to the database like "set autocommit = 1" and I understood in the web that this is not compatible with "autoreconnect=true". What´s true all about this? 

Should I install newer version of the driver? What should I do? Any help will be appreciated.
[1 Jun 2011 11:11] Ricardo Amillategui
Actual variables in my database

Attachment: variables.txt (text/plain), 4.58 KiB.

[2 Jun 2011 14:37] Tonci Grgin
Ricardo, please do not submit problem related to too long deprecated software.