Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Dry run doesn't intercept UPDATE run with executeQuery() #2374

Closed
jwheeler31 opened this issue May 3, 2019 · 7 comments

Comments

Projects
None yet
2 participants
@jwheeler31
Copy link

commented May 3, 2019

Which version and edition of Flyway are you using?

6.0.0-beta Pro

If this is not the latest version, can you reproduce the issue with the latest one as well?

(Many bugs are fixed in newer releases and upgrading will often resolve the issue)

Which client are you using? (Command-line, Java API, Maven plugin, Gradle plugin)

Command-line

Which database are you using (type & version)?

MariaDB 10.3

Which operating system are you using?

CentOS

What did you do?

(Please include the content causing the issue, any relevant configuration settings, the SQL statement that failed (if relevant) and the command you ran.)
$> flyway migrate -dryRunOutput=true -validateOnMigrate=false

What did you expect to see?

I should have seen the same successful output with dryRunOutput=true as I do without the flag.

Flyway Pro Edition (10 schemas) 6.0.0-beta by Boxfuse licensed to Alert Innovation until 2020-04-09
=================================================================================================================================
Dry Run: Database will NOT be modified. The following messages only represent what would happen in a normal Flyway migration run.
=================================================================================================================================
Flyway Pro Edition (10 schemas) 6.0.0-beta by Boxfuse licensed to Alert Innovation until 2020-04-09
Database: jdbc:mariadb://localhost:9306/racedb (MySQL 10.3)
scheduler concurrency = 3
concurrency throttle = TRUE
Current version of schema `racedb`: 99
Migrating schema `racedb` to version 102 - add mcs dyn wkstn
Migrating schema `racedb` to version 103 - MigrateMCSDynWkstn
Migrating schema `racedb` to version 104 - add mcs host columns
Migrating schema `racedb` to version 105 - MigrateMCSHostColumns
Migrating schema `racedb` to version 106 - add lane dir column
Migrating schema `racedb` to version 107 - RenameWkstnClass
Migrating schema `racedb` to version 109 - RenameSWKSTNPortClass
Migrating schema `racedb` to version 110 - RenameWkstnClasses
Successfully applied 8 migrations to schema `racedb` (execution time 00:00.272s)
What did you see instead?
Flyway Pro Edition (10 schemas) 6.0.0-beta by Boxfuse licensed to Alert Innovation until 2020-04-09
=================================================================================================================================
Dry Run: Database will NOT be modified. The following messages only represent what would happen in a normal Flyway migration run.
=================================================================================================================================
Database: jdbc:mariadb://localhost:9306/racedb (MySQL 10.3)
scheduler concurrency = 3
concurrency throttle = TRUE
Current version of schema `racedb`: 99
Migrating schema `racedb` to version 102 - add mcs dyn wkstn
Migrating schema `racedb` to version 103 - MigrateMCSDynWkstn
ERROR: Migration of schema `racedb` to version 103 - MigrateMCSDynWkstn failed! Please restore backups and roll back database and code!
ERROR: org.flywaydb.core.internal.command.DbMigrate$FlywayMigrateException: SQL State  : 42S02
Error Code : 1146
Message    : (conn=19) Table 'racedb.mcs_dyn_wkstn_device' doesn't exist
User comments:

I ran the command (as I fully expected the migration to succeed):
flyway migrate -validateOnMigrate=false
Which reported a success; output follows:

Flyway Pro Edition (10 schemas) 6.0.0-beta by Boxfuse licensed to Alert Innovation until 2020-04-09
Database: jdbc:mariadb://localhost:9306/racedb (MySQL 10.3)
scheduler concurrency = 3
concurrency throttle = TRUE
Current version of schema `racedb`: 99
Migrating schema `racedb` to version 102 - add mcs dyn wkstn
Migrating schema `racedb` to version 103 - MigrateMCSDynWkstn
Migrating schema `racedb` to version 104 - add mcs host columns
Migrating schema `racedb` to version 105 - MigrateMCSHostColumns
Migrating schema `racedb` to version 106 - add lane dir column
Migrating schema `racedb` to version 107 - RenameWkstnClass
Migrating schema `racedb` to version 109 - RenameSWKSTNPortClass
Migrating schema `racedb` to version 110 - RenameWkstnClasses
Successfully applied 8 migrations to schema `racedb` (execution time 00:00.272s)
@axelfontaine

This comment has been minimized.

Copy link
Contributor

commented May 9, 2019

Hmmm I must admit I am little puzzled here as to what may be causing this. Could you share instructions and/or a small GitHub repository to reproduce this? Also, could you share the debug output by adding -X?

@axelfontaine

This comment has been minimized.

Copy link
Contributor

commented May 15, 2019

Any news?

@jwheeler31

This comment has been minimized.

Copy link
Author

commented May 21, 2019

Working on a contrived example. Should have something in a few days.

@axelfontaine

This comment has been minimized.

Copy link
Contributor

commented May 21, 2019

That would be very helpful. Thanks.

@jwheeler31

This comment has been minimized.

Copy link
Author

commented May 22, 2019

Unfortunately, I wasn't able to reproduce the issue outside of the proprietary framework we're using. I've included the debug logs when performing the dry run as well as the logs on the actual run (minus the 8,000-ish locating/filtering lines). I understand if this isn't enough to find the source of the bug, but I'd like you to take a look regardless. It may be important to note that I'm running with the flag -validateOnMigrate=false.

Dry run output:

Current version of schema `racedb`: 110
Migrating schema `racedb` to version 111 - add failed column
DEBUG: Executing SQL: -- Author: <redacted>
 ALTER TABLE mcs_bag
 ADD COLUMN failed   BOOLEAN        NOT NULL DEFAULT FALSE
DEBUG: Successfully completed migration of schema `racedb` to version 111 - add failed column
Migrating schema `racedb` to version 112 - add position IO mode
DEBUG: Executing SQL: -- Appends a column for IO Mode on MCS position. The IO modes
-- are defined in <redacted>
-- Note that this MUST be coupled with a content migration
-- indicating the IO Mode for each position.
-- Author: <redacted>
ALTER TABLE mcs_position
ADD COLUMN io_mode TINYINT NOT NULL
DEBUG: Successfully completed migration of schema `racedb` to version 112 - add position IO mode
Migrating schema `racedb` to version 113 - SetIOMode
DEBUG: Executing statement:[sql : 'UPDATE mcs_position SET io_mode = ?', parameters : [3]]
DEBUG: Execution Successful. 0 rows affected.
DEBUG: Versioned content update:[V113__SetIOMode]
DEBUG: Successfully completed migration of schema `racedb` to version 113 - SetIOMode
Migrating schema `racedb` to version 114 - add mcs host columns
DEBUG: Executing SQL: ALTER TABLE mcs_wmt_host ADD (ims_svc_host VARCHAR(64) NOT NULL,
                              ims_svc_port INT NOT NULL,
                              ims_svc_time INT NOT NULL,
                              ims_svc_sgln VARCHAR(64) NOT NULL)
DEBUG: Successfully completed migration of schema `racedb` to version 114 - add mcs host columns
Migrating schema `racedb` to version 115 - MigrateMCSHostColumns
DEBUG: Updating mcs_wmt_host rows.
DEBUG: Executing statement:[sql : 'UPDATE mcs_wmt_host SET ims_svc_host = ?, ims_svc_port = ?,ims_svc_time = ?, ims_svc_sgln = ?', parameters : ['localhost',443,0,'17387']].
DEBUG: Rolling back transaction...
DEBUG: Transaction rolled back
ERROR: Migration of schema `racedb` to version 115 - MigrateMCSHostColumns failed! Please restore backups and roll back database and code!
DEBUG: Memory usage: 136 of 212M
ERROR: Unexpected error
org.flywaydb.core.api.FlywayException: org.flywaydb.core.internal.command.DbMigrate$FlywayMigrateException: SQL State  : 42S22
Error Code : 1054
Message    : (conn=39) Unknown column 'ims_svc_host' in 'field list'

	at org.flywaydb.core.internal.schemahistory.pro.InMemorySchemaHistory.lock(InMemorySchemaHistory.java:61)
	at org.flywaydb.core.internal.command.DbMigrate.migrateAll(DbMigrate.java:161)
	at org.flywaydb.core.internal.command.DbMigrate.migrate(DbMigrate.java:139)
	at org.flywaydb.core.Flyway$1.execute(Flyway.java:175)
	at org.flywaydb.core.Flyway$1.execute(Flyway.java:136)
	at org.flywaydb.core.Flyway.execute(Flyway.java:453)
	at org.flywaydb.core.Flyway.migrate(Flyway.java:136)
	at org.flywaydb.commandline.Main.executeOperation(Main.java:160)
	at org.flywaydb.commandline.Main.main(Main.java:107)
Caused by: org.flywaydb.core.internal.command.DbMigrate$FlywayMigrateException: SQL State  : 42S22
Error Code : 1054
Message    : (conn=39) Unknown column 'ims_svc_host' in 'field list'

	at org.flywaydb.core.internal.command.DbMigrate.doMigrateGroup(DbMigrate.java:373)
	at org.flywaydb.core.internal.command.DbMigrate.access$200(DbMigrate.java:54)
	at org.flywaydb.core.internal.command.DbMigrate$3.call(DbMigrate.java:284)
	at org.flywaydb.core.internal.jdbc.TransactionTemplate.execute(TransactionTemplate.java:74)
	at org.flywaydb.core.internal.command.DbMigrate.applyMigrations(DbMigrate.java:281)
	at org.flywaydb.core.internal.command.DbMigrate.migrateGroup(DbMigrate.java:246)
	at org.flywaydb.core.internal.command.DbMigrate.access$100(DbMigrate.java:54)
	at org.flywaydb.core.internal.command.DbMigrate$2.call(DbMigrate.java:164)
	at org.flywaydb.core.internal.command.DbMigrate$2.call(DbMigrate.java:161)
	at org.flywaydb.core.internal.schemahistory.pro.InMemorySchemaHistory.lock(InMemorySchemaHistory.java:57)
	... 8 more
Caused by: java.sql.SQLSyntaxErrorException: (conn=39) Unknown column 'ims_svc_host' in 'field list'
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:177)
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:110)
	at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:228)
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:216)
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:150)
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeQuery(MariaDbPreparedStatementClient.java:164)
	at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.flywaydb.core.internal.jdbc.pro.JdbcProxies$3.invoke(JdbcProxies.java:114)
	at com.sun.proxy.$Proxy1.executeQuery(Unknown Source)
	at com.romaric.mcs.mgr.db.migration.V115__MigrateMCSHostColumns.migrate(V115__MigrateMCSHostColumns.java:80)
	at org.flywaydb.core.internal.resolver.java.JavaMigrationExecutor.execute(JavaMigrationExecutor.java:48)
	at org.flywaydb.core.internal.command.DbMigrate.doMigrateGroup(DbMigrate.java:367)
	... 17 more
Caused by: java.sql.SQLException: Unknown column 'ims_svc_host' in 'field list'
Query is: UPDATE mcs_wmt_host SET ims_svc_host = ?, ims_svc_port = ?,ims_svc_time = ?, ims_svc_sgln = ?, parameters ['localhost',443,0,'17387']
	at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:153)
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:255)
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:209)
	... 27 more

Actual run output:

Current version of schema `racedb`: 110
Migrating schema `racedb` to version 111 - add failed column
DEBUG: Executing SQL: -- Author: <redacted>
 ALTER TABLE mcs_bag
 ADD COLUMN failed   BOOLEAN        NOT NULL DEFAULT FALSE
DEBUG: Update Count: 0
DEBUG: Successfully completed migration of schema `racedb` to version 111 - add failed column
DEBUG: Locking table `racedb`.`flyway_schema_history`...
DEBUG: Lock acquired for table `racedb`.`flyway_schema_history`
DEBUG: Schema History table `racedb`.`flyway_schema_history` successfully updated to reflect changes
Migrating schema `racedb` to version 112 - add position IO mode
DEBUG: Executing SQL: -- Appends a column for IO Mode on MCS position. The IO modes
-- are defined in <redacted>.
-- Note that this MUST be coupled with a content migration
-- indicating the IO Mode for each position.
-- Author: Josh Wheeler
ALTER TABLE mcs_position
ADD COLUMN io_mode TINYINT NOT NULL
DEBUG: Update Count: 0
DEBUG: Successfully completed migration of schema `racedb` to version 112 - add position IO mode
DEBUG: Locking table `racedb`.`flyway_schema_history`...
DEBUG: Lock acquired for table `racedb`.`flyway_schema_history`
DEBUG: Schema History table `racedb`.`flyway_schema_history` successfully updated to reflect changes
Migrating schema `racedb` to version 114 - add mcs host columns
DEBUG: Executing SQL: ALTER TABLE mcs_wmt_host ADD (ims_svc_host VARCHAR(64) NOT NULL,
                              ims_svc_port INT NOT NULL,
                              ims_svc_time INT NOT NULL,
                              ims_svc_sgln VARCHAR(64) NOT NULL)
DEBUG: Update Count: 0
DEBUG: Successfully completed migration of schema `racedb` to version 114 - add mcs host columns
DEBUG: Locking table `racedb`.`flyway_schema_history`...
DEBUG: Lock acquired for table `racedb`.`flyway_schema_history`
DEBUG: Schema History table `racedb`.`flyway_schema_history` successfully updated to reflect changes
Successfully applied 3 migrations to schema `racedb` (execution time 00:00.187s)
DEBUG: Memory usage: 16 of 150M

Let me know if there's something else I can find for you.

Extra note: I just realized that extra debug output (from the Java classes) was logged. I can pull those out if it'll help.
Extra note: the versions in the original post to this one are different as we've had a lot of database modifications since then.

@axelfontaine

This comment has been minimized.

Copy link
Contributor

commented May 23, 2019

Thanks for the debug output. That yielded the clue! You are executing an UPDATE statement with executeQuery() instead of execute() or executeUpdate(). We have now expanded our interceptor to catch this rare case where executeQuery() is used with something else than SELECT.

Fixed.

@axelfontaine axelfontaine added this to the Flyway 6.0.0-beta2 milestone May 23, 2019

@axelfontaine axelfontaine changed the title Flyway dry run reports false failure Dry run doesn't intercept UPDATE run with executeQuery() May 23, 2019

axelfontaine pushed a commit to flyway/flywaydb.org that referenced this issue May 23, 2019

@jwheeler31

This comment has been minimized.

Copy link
Author

commented May 23, 2019

@axelfontaine, thank you very much for your support! I'll make sure our developers are more cognizant of the method calls they're using :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.