Connection time out in flyway

Question

I'm using flyway 1.5 and mysql Ver 14.14 Distrib 5.1.52, for unknown-linux-gnu (x86_64) using readline 5.1

I wrote the following migration:

alter table table1 add column col_11 blob;
alter table table1 add column col_12 varchar(255) DEFAULT NULL;

alter table table2 add column col_21 blob;
alter table table2 add column col_22 varchar(255) DEFAULT NULL;

Where table1 is small and table2 has 283,018 rows.

The migration succeed (the columns were added to both table1 and table2) but the update of the version failed ( I got com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. ).

My my.cnf file holds the next line wait_timeout=30 and I thought that what happened was that adding these two columns to table2 took more than wait_timout - which "failed" the migration - and now I have this situation: the migration was success but the version is not updated. But then I ran this sql query:

show variables like "%timeout%";

And got this:

+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| connect_timeout            | 10    |
| delayed_insert_timeout     | 300   |
| innodb_lock_wait_timeout   | 50    |
| innodb_rollback_on_timeout | OFF   |
| interactive_timeout        | 28800 |
| net_read_timeout           | 30    |
| net_write_timeout          | 60    |
| slave_net_timeout          | 3600  |
| table_lock_wait_timeout    | 50    |
| wait_timeout               | 28800 |
+----------------------------+-------+

Which suggests that the wait_timeout is about 8 hours...

So my question is Why this connection timeout occurs?

And mainly - how can I fix it?

EDIT: Both the app and the database are on the same machine.

Here is the full stack trace:

Current schema version: 12.9.3
Migrating to version 12.9.3.1

Error while extracting database product name - falling back to empty error codes
org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
    at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:296)
    at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:320)
    at org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(SQLErrorCodesFactory.java:216)
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(SQLErrorCodeSQLExceptionTranslator.java:140)
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(SQLErrorCodeSQLExceptionTranslator.java:103)
    at org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator(JdbcAccessor.java:99)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:522)
    at com.googlecode.flyway.core.metadatatable.MetaDataTable.insert(MetaDataTable.java:149)
    at com.googlecode.flyway.core.migration.DbMigrator.applyMigration(DbMigrator.java:248)
    at com.googlecode.flyway.core.migration.DbMigrator$1.doInTransaction(DbMigrator.java:148)
    at com.googlecode.flyway.core.migration.DbMigrator$1.doInTransaction(DbMigrator.java:114)
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128)
    at com.googlecode.flyway.core.migration.DbMigrator.migrate(DbMigrator.java:113)
    at com.googlecode.flyway.core.Flyway.migrate(Flyway.java:619)
    at com.googlecode.flyway.commandline.Main.main(Main.java:79)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.Util.getInstance(Util.java:386)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927)
    at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1205)
    at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1197)
    at com.mysql.jdbc.ConnectionImpl.getMetaData(ConnectionImpl.java:3061)
    at com.mysql.jdbc.ConnectionImpl.getMetaData(ConnectionImpl.java:3056)
    at org.springfra
mework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:285)
    ... 15 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 654,699 milliseconds ago.  The last packet sent successfully to the server was 17 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
    at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1749)
    at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1666)
    at org.springframework.jdbc.core.JdbcTemplate$1UpdateStatementCallback.doInStatement(JdbcTemplate.java:512)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:396)
    ... 9 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
    ... 18 more
Application exception overridden by rollback exception
org.springframework.dao.RecoverableDataAccessException: StatementCallback; SQL [UPDATE schema_version SET current_version=0]; Communications link failure
The last packet successfully received from the server was 654,699 milliseconds ago.  The last packet sent successfully to the server was 17 milliseconds ago.; nested exception is com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 654,699 milliseconds ago.  The last packet sent successfully to the server was 17 milliseconds ago.
    at org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:97)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:522)
    at com.googlecode.flyway.core.metadatatable.MetaDataTable.insert(MetaDataTable.java:149)
    at com.googlecode.flyway.core.migration.DbMigrator.applyMigration(DbMigrator.java:248)
    at com.googlecode.flyway.core.migration.DbMigrator$1.doInTransaction(DbMigrator.java:148)
    at com.googlecode.flyway.core.migration.DbMigrator$1.doInTransaction(DbMigrator.java:114)
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128)
    at com.googlecode.flyway.core.migration.DbMigrator.migrate(DbMigrator.java:113)
    at com.googlecode.flyway.core.Flyway.migrate(Flyway.java:619)
    at com.googlecode.flyway.commandline.Main.main(Main.java:79)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 654,699 milliseconds ago.  The last packet sent successfully to the server was 17 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
    at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1749)
    at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1666)
    at org.springframework.jdbc.core.JdbcTemplate$1UpdateStatementCallback.doInStatement(JdbcTemplate.java:512)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:396)
    ... 9 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
    ... 18 more
FlywayException: Migration failed !
Occured in com.googlecode.flyway.core.migration.DbMigrator in method migrate, line number 164
Caused by java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
Occured in com.mysql.jdbc.MysqlIO in method readFully, line number 2552

Answer 1

We just ran into this issue and managed to find a solution that worked for us. It seems that Flyway uses at least two connections: one to lock the schema_version table, and one to actually run the alters. This issue occurs when the alters take long enough to cause the connection locking the schema_version table to timeout. The easiest way to fix this is the bump up the MySQL wait_timeout to something relatively large. In our case we set it to 480 minutes (or 28800 seconds):

set global wait_timeout=28800;

Answer 2

A bit of analysis:

As the Flyway Command-line Tool creates two new connections when it starts, connection staleness can be ruled out.

Flyway will then first open a connection for the metadata table and lock it.

It will then open a second connection and execute the migration. I am assuming this step takes very long (+- 11mins from the logs).

When the migration completes, the transaction on the second connection commits and the new row is added in the metadata table through the first connection.

This is where it bombs... But with a communication and not with a connection timeout or a lock timeout exception.

Could it be that some piece of network equipment (router/switch/proxy) between the app and the DB is dropping inactive connections?