FlywayDB: Migration fails with "Error executing statement", but manually running migration SQL code works

Question

I have a play framework 2.2.2 scala application and use play-flyway 1.0.3.

The following migration should be run by flyway:

ALTER TABLE  `user_visits` ADD  `FirstSiteRequestTime` DATETIME NOT NULL ;
UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1) ;

So I add a column to a table and then programatically fill it using an update statement.

The first line executes fine, but the update statemens fails with

FlywaySqlScriptException: Error executing statement at line 2: UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1)
com.googlecode.flyway.core.command.FlywaySqlScriptException: Error executing statement at line 2: UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1)
com.googlecode.flyway.core.dbsupport.SqlScript.execute(SqlScript.java:92)
com.googlecode.flyway.core.resolver.sql.SqlMigrationExecutor.execute(SqlMigrationExecutor.java:72)
com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:243)
com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:241)
com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)

However, when I take the migration SQL code and run it using phpmyadmin, it works fine (although it takes 2-5 seconds to run, the tables are quite big).

My mysql.log looks like

                  128 Query SET autocommit=0
                  128 Query ALTER TABLE  `user_visits` ADD  `FirstSiteRequestTime` DATETIME NOT NULL
140412  4:40:43   128 Query UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1)
140412  4:40:44   128 Query rollback
                  128 Query SET autocommit=1

Is flyway having some kind of timeout? The log file shows it sends the query to the mysql server but then rolls back. Why? As stated before, the query is correct. It works when I run it manually.

edit:

After running the migration, the ALTER TABLE statement was executed and committed (the table is altered), although the mysql.log says it was rolled back. The second command was really rolled back.

I also tried splitting the two SQL commands in two migrations. Then the first one (ALTER TABLE) runs fine and the second one fails.

edit2:

It might be some kind of timeout problem. Making it execute faster (by only updating some of the rows)

ALTER TABLE  `user_visits` ADD  `FirstSiteRequestTime` DATETIME NOT NULL ;
UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1) WHERE user_visits.id<1000;

runs correctly, also in flyway.

score 0 · Answer 1 · answered Apr 12 '14 at 14:13

0

MySQL documentation says that as of MySQL 5.5.3, "most statements" that cause an implicit commit before executing also do so after executing. This seems to include the ALTER TABLE statement (in MySQL 5.5.3 and later).

Notice that in the log shown in the question, autocommit is disable. To be sure, either use an explicit COMMIT between the statements like this:

ALTER TABLE  `user_visits` ADD  `FirstSiteRequestTime` DATETIME NOT NULL ;
COMMIT ;
UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1) ;

or place them in separate and contiguous migration files, like this:

File V1__alter_table.sql:

ALTER TABLE  `user_visits` ADD  `FirstSiteRequestTime` DATETIME NOT NULL ;

File V2__update_table.sql:

UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1) ;

answered Apr 12 '14 at 14:13

Fernando Correia

21,803
13
83
116

Adding a Commit doesn't change anything. Also when splitting it in two migrations, the second one still fails (see edit above) – Heinzi Apr 12 '14 at 14:20
I seem to have misdiagnosed the issue. I apologize. But at least now, with the migrations separated, the issue should be easier to debug. Please verify if Flyway considers the first migration (`ALTER TABLE`) to have succeeded. Use `flyway info` or inspect the `schema_version` table. If the first migration failed (as the rollback seems to imply), this is the issue. If it succeeded, please inspect the database structure to make sure the `ALTER TABLE` command succeeded, then try running the `UPDATE` command again with phpmyadmin and verify the result. – Fernando Correia Apr 12 '14 at 15:33
The first migration succeeds, the second one fails. log for the second one: 256 Query SET autocommit=0 256 Query UPDATE `user_visits` SET `FirstSiteRequestTime`=(SELECT `Time` FROM `user_siterequests` WHERE `user_siterequests`.`Visit`=`user_visits`.`ID` ORDER BY `Time` ASC LIMIT 1) 256 Query rollback 256 Query SET autocommit=1 Running second one in phpmyadmin still works. I think it is a timeout issue (see my edits above) – Heinzi Apr 12 '14 at 15:47
Now the issue is clearer. It seems the transaction is being rolled back because of a timeout. I suspect it's MySQL that's rolling it back, but it could be something in the Flyway/Java stack. Please verify the output of `show variables like "%timeout%";`. The variables are explained [in this documentation page](https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html). This seems similar to [this unresolved question](http://stackoverflow.com/q/12339164/376366). – Fernando Correia Apr 12 '14 at 16:17
connect_timeout 10; delayed_insert_timeout 300; innodb_lock_wait_timeout 50; innodb_rollback_on_timeout OFF; interactive_timeout 28800; lock_wait_timeout 31536000; net_read_timeout 30; net_write_timeout 60; slave_net_timeout 3600; wait_timeout 28800; But these values are from phpmyadmin. And in phpmyadmin, the query runs. Can it be, that flyway has different timeout settings in its connection? How can I get them? – Heinzi Apr 12 '14 at 18:11
I'm afraid I'm out of my depth since I don't know much about MySQL. It also may be that Flyway or the JDBC stack is aborting due to timeout. I suggest you check for errors in `mysql_error.log` and that you inspect JDBC operations and errors, for instance using [log4jdbc](https://code.google.com/p/log4jdbc/) with `jdbc.audit` (see [this answer](http://stackoverflow.com/a/17988232/376366)). – Fernando Correia Apr 12 '14 at 18:57
1

Flyway doesn't set any specific timeouts. It all happens on the DB side. – Axel Fontaine Apr 16 '14 at 07:28

FlywayDB: Migration fails with "Error executing statement", but manually running migration SQL code works

1 Answers1