Failure on creation of a schema history table on an empty database when autoCommit is false

[apanasevich]

Which version and edition of Flyway are you using?

Bug is reproduced in 5.0.* versions.

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

Java API.

Which database are you using (type & version)?

PostgreSQL 9.6

Which operating system are you using?

Windows 7 and Ubuntu 14

What did you do?

I simultaneously start several instances of a service on the same empty database. The service consists of his own DB schema which it migrates on startup, and it inherits another one: the core DB schema that migrates DB after completion of the service's DB migrations (similar to this approach https://stackoverflow.com/a/48272834/4070983). It uses baseline to run core migrations on non-empty DB:

flyway.setBaselineOnMigrate(true);
flyway.setBaselineVersionAsString("0");
flyway.setLocations("db/common/migration");

The service uses table schema_version table as history table and its core part uses schema_version_common as a name for history table.

What did you expect to see?

I expect that all migrations will be completed successfully.

What did you see instead?

I see the following stacktrace:

Caused by: org.flywaydb.core.internal.exception.FlywaySqlException:
Error restoring current schema to its original setting
------------------------------------------------------
SQL State  : 25P02
Error Code : 0
Message    : ERROR: current transaction is aborted, commands ignored until end of transaction block
 
        at org.flywaydb.core.internal.database.Connection.restoreCurrentSchema(Connection.java:131)
        at org.flywaydb.core.internal.command.DbBaseline.baseline(DbBaseline.java:150)
        at org.flywaydb.core.Flyway$1.execute(Flyway.java:1192)
        at org.flywaydb.core.Flyway$1.execute(Flyway.java:1168)
        at org.flywaydb.core.Flyway.execute(Flyway.java:1650)
        at org.flywaydb.core.Flyway.migrate(Flyway.java:1168)
        at does.not.matter.DBContext.migrate(DBContext.java:83)
        ... 4 more
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2476)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2189)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169)
        at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:158)
        at com.jolbox.bonecp.PreparedStatementHandle.execute(PreparedStatementHandle.java:140)
        at org.flywaydb.core.internal.util.jdbc.JdbcTemplate.execute(JdbcTemplate.java:246)
        at org.flywaydb.core.internal.database.postgresql.PostgreSQLConnection.doChangeCurrentSchemaTo(PostgreSQLConnection.java:100)
        at org.flywaydb.core.internal.database.Connection.restoreCurrentSchema(Connection.java:129)
        ... 10 more
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"
  Detail: Key (typname, typnamespace)=(schema_version_common, 2200) already exists.
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2476)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2189)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:301)
        at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:287)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:264)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:260)
        at com.jolbox.bonecp.StatementHandle.execute(StatementHandle.java:254)
        at org.flywaydb.core.internal.util.jdbc.JdbcTemplate.executeStatement(JdbcTemplate.java:265)
        at org.flywaydb.core.internal.database.StandardSqlStatement.execute(StandardSqlStatement.java:41)
        at org.flywaydb.core.internal.database.SqlScript.execute(SqlScript.java:163)
        at org.flywaydb.core.internal.schemahistory.JdbcTableSchemaHistory.create(JdbcTableSchemaHistory.java:125)
        at org.flywaydb.core.internal.command.DbBaseline.baseline(DbBaseline.java:107)
        ... 9 more

If I start service instances one by one I don't get the error. Error is reproduced only with simultaneous start.

Apparently, this issue is somehow related to issue #1067

[axelfontaine]

Thanks for the report. Could you share a small repo that reproduces the issue?

[apanasevich]

Hi Axel,

I've found that the root cause is that I use data sources with autoCommit mode set to false. In this case even extremely simple case (just schema history table creation without any migration) fails in concurrent environment. I've reproduced it in naive test here in a separate branch.

Also, I've commited a fix in another branch. Could you take a look on it? If you find it correct, I'll create a PR.

Unfortunately, I can't find any test in the repository. So, I've checked the fix only with PostgreSQL. But I think the problem is related to other DBMSes.

[axelfontaine]

I am wondering whether you could be running in #1959 here.

Can you try building master and see if the problem persists?

[apanasevich]

Can you try building master and see if the problem persists?

The issue is actual for master. Actually, I've created the test in a branch just for the reason of separating it from master branch.

[nolequen]

@apanasevich, nice catch! Thanks for the fix!

[axelfontaine]

I had a deeper look into this and there were a number of other issues when autoCommit was set to false. We have now addressed them all by switching to autoCommit at the beginning of the process and restoring the connection's original setting at the end.