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

Flyway with "multiple datasources" does not migrate at start #9415

Closed
michael-schnell opened this issue May 18, 2020 · 15 comments · Fixed by #9436
Closed

Flyway with "multiple datasources" does not migrate at start #9415

michael-schnell opened this issue May 18, 2020 · 15 comments · Fixed by #9436
Labels
kind/bug Something isn't working
Milestone

Comments

@michael-schnell
Copy link
Contributor

Describe the bug
There are two datasources that should be be migrated on startup by Flyway, but the scripts are not executed. From the logs it can bee seen that the directories are recognized correctly by the Flyway extension, but not applied later. This has been working before (~1.3.x) and stopped working with current master source.

Example (database/mycompany)

Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/mycompany/' using protocol 'file'
Database: jdbc:postgresql://localhost:5433/mycompany
Current version of schema "mycompany": null
Schema "mycompany" is up to date. No migration necessary.

Expected behavior
The scripts in "src/main/resources/database" should be used for migration on startup.

Actual behavior
The scripts in "src/main/resources/database" are not applied on startup.

To Reproduce
Steps to reproduce the behavior:

  1. Checkout Quickstart fork: https://github.com/michael-schnell/quarkus-quickstarts/
  2. Change into hibernate-orm-quickstart-multi-tenancy
  3. Execute "DATABASE Multitenancy" example as described in README.md
  4. Check the log output: The two datasource schemas "base" and "mycompany" are not applied

Configuration
See https://github.com/michael-schnell/quarkus-quickstarts/blob/master/hibernate-orm-quickstart-multi-tenancy/src/main/resources/application.properties

Log

2020-05-18 16:04:33,275 INFO  [io.qua.fly.FlywayProcessor] (build-61) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/db/migration/' using protocol 'file'
2020-05-18 16:04:33,277 INFO  [io.qua.fly.FlywayProcessor] (build-61) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/mycompany/' using protocol 'file'
2020-05-18 16:04:33,291 INFO  [io.qua.fly.FlywayProcessor] (build-61) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/base/' using protocol 'file'
2020-05-18 16:04:33,291 INFO  [io.qua.fly.FlywayProcessor] (build-61) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/db/migration/' using protocol 'file'
2020-05-18 16:04:36,831 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2020-05-18 16:04:36,835 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'mycompany': Initial size smaller than min. Connections will be created when necessary
2020-05-18 16:04:36,840 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'base': Initial size smaller than min. Connections will be created when necessary
2020-05-18 16:04:36,938 INFO  [org.fly.cor.int.lic.VersionPrinter] (Quarkus Main Thread) Flyway Community Edition 6.4.2 by Redgate
2020-05-18 16:04:37,092 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5433/mycompany (PostgreSQL 12.2)
2020-05-18 16:04:37,123 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "mycompany": null
2020-05-18 16:04:37,124 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Schema "mycompany" is up to date. No migration necessary.
2020-05-18 16:04:37,140 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5432/quarkus_test (PostgreSQL 12.2)
2020-05-18 16:04:37,153 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "public": << Empty Schema >>
2020-05-18 16:04:37,153 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Schema "public" is up to date. No migration necessary.
2020-05-18 16:04:37,685 INFO  [io.quarkus] (Quarkus Main Thread) hibernate-orm-quickstart-multi-tenancy 1.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 6.337s. Listening on: http://0.0.0.0:8080
2020-05-18 16:04:37,687 INFO  [io.quarkus] (Quarkus Main Thread) Profile database activated. Live Coding activated.
2020-05-18 16:04:37,688 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, flyway, hibernate-orm, jdbc-postgresql, mutiny, narayana-jta, resteasy, resteasy-jsonb]
^C2020-05-18 16:04:42,798 INFO  [io.quarkus] (Quarkus Main Thread) hibernate-orm-quickstart-multi-tenancy stopped in 0.029s

Environment (please complete the following information):

Additional context
I'm currently preparing a quickstart for the new Hibernate multi-tenancy feature. This example was already working fine with 999-SNAPSHOT from source ~1.3.x, but it fails now with current Quarkus master source. The problem is actually not related to the new feature as it happens before anything from that code is executed. The problem is just the missing Flyway migration. It seems to be something that changed between ~1.3.x and the current master most likely in the Flyway extension.

@michael-schnell michael-schnell added the kind/bug Something isn't working label May 18, 2020
@michael-schnell
Copy link
Contributor Author

michael-schnell commented May 18, 2020

@barreiro @Sanne @geoand @gsmet Any idea?

Funny thing is, that in the integration test it's working with a very similar setup...

@geoand
Copy link
Contributor

geoand commented May 18, 2020

I'll take a look

@geoand
Copy link
Contributor

geoand commented May 18, 2020

I am using the absolute latest Quarkus from master, and I see

2020-05-18 17:52:39,102 INFO  [io.qua.fly.FlywayProcessor] (build-25) Adding application migrations in path '/home/gandrian/Desktop/quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/mycompany/' using protocol 'file'
2020-05-18 17:52:39,104 INFO  [io.qua.fly.FlywayProcessor] (build-25) Adding application migrations in path '/home/gandrian/Desktop/quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/base/' using protocol 'file'
2020-05-18 17:52:39,850 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2020-05-18 17:52:39,851 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'mycompany': Initial size smaller than min. Connections will be created when necessary
2020-05-18 17:52:39,851 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'base': Initial size smaller than min. Connections will be created when necessary
2020-05-18 17:52:39,879 INFO  [org.fly.cor.int.lic.VersionPrinter] (Quarkus Main Thread) Flyway Community Edition 6.4.2 by Redgate
2020-05-18 17:52:39,880 WARN  [org.fly.cor.int.sca.cla.ClassPathScanner] (Quarkus Main Thread) Unable to resolve location classpath:db/migration. Note this warning will become an error in Flyway 7.
2020-05-18 17:52:39,939 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5433/mycompany (PostgreSQL 12.2)
2020-05-18 17:52:39,954 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "public": << Empty Schema >>
2020-05-18 17:52:39,954 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Schema "public" is up to date. No migration necessary.
2020-05-18 17:52:39,956 WARN  [org.fly.cor.int.sca.cla.ClassPathScanner] (Quarkus Main Thread) Unable to resolve location classpath:db/migration. Note this warning will become an error in Flyway 7.
2020-05-18 17:52:39,962 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5432/quarkus_test (PostgreSQL 12.2)
2020-05-18 17:52:39,969 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "public": << Empty Schema >>
2020-05-18 17:52:39,969 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Schema "public" is up to date. No migration necessary.

Which suggests to me that it's working (I am not really a Flyway user so I might be missing something).
Are you seeing something else or am I missing something?

@gsmet gsmet added this to the 1.5.0 milestone May 18, 2020
@michael-schnell
Copy link
Contributor Author

michael-schnell commented May 18, 2020

It says "Current version of schema "public": << Empty Schema >>" and " Schema "public" is up to date. No migration necessary." which means nothing is applied. If you look at the database it has the Flyway table, but no version - Should be "V1.0.0__create_fruits.sql" for both databases. Before it worked fine and both scripts were picked up on startup and there was a table "fruits" created by the scripts in both databases. Now there is no table created.

Should be something like:

INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Migrating schema "public" to version 1.0.0 - create fruits

@geoand
Copy link
Contributor

geoand commented May 18, 2020

Turns out that this problem is rather serious.

What I am seeing is that when multiple datasources are being used, dev-mode does not populate the named datasources of FlywayBuildTimeConfig.

Here is a screenshot from the debugger of the non-working dev-mode (notice the 0 in namedDataSources of flywayBuildConfig, the flywayRuntimeConfig however seems correct):

dev-mode

and here is the screenshot of the same point in the code for a prod-mode jar:

prod-mode

I could keep digging to try and figure out what the problem is, but I would appreciate some input from @stuartwdouglas and @dmlloyd

@michael-schnell
Copy link
Contributor Author

Same when using the 'database' profile that is required for the quickstart when using a database per tenant.

Example in native mode which also does not work:

./target/hibernate-orm-quickstart-multi-tenancy-1.0-SNAPSHOT-runner -Dquarkus.profile=database

@geoand
Copy link
Contributor

geoand commented May 18, 2020

In any case, if no one beats me to it, I'll continue debugging tomorrow

@stuartwdouglas
Copy link
Member

stuartwdouglas commented May 19, 2020 via email

@stuartwdouglas
Copy link
Member

stuartwdouglas commented May 19, 2020 via email

@geoand
Copy link
Contributor

geoand commented May 19, 2020

I'll look as well

@stuartwdouglas
Copy link
Member

stuartwdouglas commented May 19, 2020 via email

@geoand
Copy link
Contributor

geoand commented May 19, 2020

Cool, looking

stuartwdouglas added a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
geoand added a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
geoand added a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 19, 2020
geoand added a commit to stuartwdouglas/quarkus that referenced this issue May 20, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 20, 2020
gsmet pushed a commit to stuartwdouglas/quarkus that referenced this issue May 20, 2020
@michael-schnell
Copy link
Contributor Author

michael-schnell commented May 20, 2020

I tested with the new quickstart project again and dev mode works now fine.

Unfortunately in native mode the profile is still not picked up (Flyway is not started for migartion).

Starting with ./mvnw quarkus:dev -Dquarkus.profile=database works:

2020-05-20 15:23:39,881 INFO  [io.qua.fly.FlywayProcessor] (build-34) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/db/migration/' using protocol 'file'
2020-05-20 15:23:39,903 INFO  [io.qua.fly.FlywayProcessor] (build-34) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/mycompany/' using protocol 'file'
2020-05-20 15:23:39,904 INFO  [io.qua.fly.FlywayProcessor] (build-34) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/database/base/' using protocol 'file'
2020-05-20 15:23:39,904 INFO  [io.qua.fly.FlywayProcessor] (build-34) Adding application migrations in path 'quarkus-quickstarts/hibernate-orm-quickstart-multi-tenancy/target/classes/db/migration/' using protocol 'file'
2020-05-20 15:23:42,652 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2020-05-20 15:23:42,656 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Pool interceptors: []
2020-05-20 15:23:42,662 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'mycompany': Initial size smaller than min. Connections will be created when necessary
2020-05-20 15:23:42,663 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'mycompany': Pool interceptors: []
2020-05-20 15:23:42,666 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'base': Initial size smaller than min. Connections will be created when necessary
2020-05-20 15:23:42,666 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource 'base': Pool interceptors: []
2020-05-20 15:23:42,681 INFO  [org.fly.cor.int.lic.VersionPrinter] (Quarkus Main Thread) Flyway Community Edition 6.4.2 by Redgate
2020-05-20 15:23:42,868 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5433/mycompany (PostgreSQL 12.2)
2020-05-20 15:23:42,917 INFO  [org.fly.cor.int.sch.JdbcTableSchemaHistory] (Quarkus Main Thread) Creating Schema History table "public"."flyway_schema_history" ...
2020-05-20 15:23:42,996 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "public": << Empty Schema >>
2020-05-20 15:23:43,001 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Migrating schema "public" to version 1.0.0 - create fruits
2020-05-20 15:23:43,005 INFO  [org.fly.cor.int.sql.DefaultSqlScriptExecutor] (Quarkus Main Thread) +--------+
| setval |
+--------+
| 3      |
+--------+

2020-05-20 15:23:43,023 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Successfully applied 1 migration to schema "public" (execution time 00:00.043s)
2020-05-20 15:23:43,042 INFO  [org.fly.cor.int.dat.DatabaseFactory] (Quarkus Main Thread) Database: jdbc:postgresql://localhost:5432/quarkus_test (PostgreSQL 12.2)
2020-05-20 15:23:43,056 INFO  [org.fly.cor.int.sch.JdbcTableSchemaHistory] (Quarkus Main Thread) Creating Schema History table "public"."flyway_schema_history" ...
2020-05-20 15:23:43,108 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Current version of schema "public": << Empty Schema >>
2020-05-20 15:23:43,111 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Migrating schema "public" to version 1.0.0 - create fruits
2020-05-20 15:23:43,114 INFO  [org.fly.cor.int.sql.DefaultSqlScriptExecutor] (Quarkus Main Thread) +--------+
| setval |
+--------+
| 3      |
+--------+

2020-05-20 15:23:43,132 INFO  [org.fly.cor.int.com.DbMigrate] (Quarkus Main Thread) Successfully applied 1 migration to schema "public" (execution time 00:00.033s)
2020-05-20 15:23:43,642 INFO  [io.quarkus] (Quarkus Main Thread) hibernate-orm-quickstart-multi-tenancy 1.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 5.393s. Listening on: http://0.0.0.0:8080
2020-05-20 15:23:43,645 INFO  [io.quarkus] (Quarkus Main Thread) Profile database activated. Live Coding activated.
2020-05-20 15:23:43,645 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, flyway, hibernate-orm, jdbc-postgresql, mutiny, narayana-jta, resteasy, resteasy-jsonb]

Same in native mode with ./target/hibernate-orm-quickstart-multi-tenancy-1.0-SNAPSHOT-runner -Dquarkus.profile=database does not show any Flyway activity:

2020-05-20 15:28:19,661 INFO  [io.agr.pool] (main) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2020-05-20 15:28:19,662 INFO  [io.agr.pool] (main) Datasource '<default>': Pool interceptors: []
2020-05-20 15:28:19,667 INFO  [io.quarkus] (main) hibernate-orm-quickstart-multi-tenancy 1.0-SNAPSHOT native (powered by Quarkus 999-SNAPSHOT) started in 0.022s. Listening on: http://0.0.0.0:8080
2020-05-20 15:28:19,667 INFO  [io.quarkus] (main) Profile database activated. 
2020-05-20 15:28:19,667 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, flyway, hibernate-orm, jdbc-postgresql, mutiny, narayana-jta, resteasy, resteasy-jsonb]

It seems again to be related to the profile, as Flyway correctly shows up if no profile is used with ./target/hibernate-orm-quickstart-multi-tenancy-1.0-SNAPSHOT-runner:

2020-05-20 15:29:34,842 INFO  [io.agr.pool] (main) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
2020-05-20 15:29:34,843 INFO  [io.agr.pool] (main) Datasource '<default>': Pool interceptors: []
2020-05-20 15:29:34,843 INFO  [org.fly.cor.int.lic.VersionPrinter] (main) Flyway Community Edition 6.4.2 by Redgate
2020-05-20 15:29:34,849 INFO  [org.fly.cor.int.dat.DatabaseFactory] (main) Database: jdbc:postgresql://localhost:5432/quarkus_test (PostgreSQL 12.2)
2020-05-20 15:29:34,860 INFO  [org.fly.cor.int.dat.bas.Schema] (main) Creating schema "base" ...
2020-05-20 15:29:34,861 INFO  [org.fly.cor.int.dat.bas.Schema] (main) Creating schema "mycompany" ...
2020-05-20 15:29:34,863 INFO  [org.fly.cor.int.sch.JdbcTableSchemaHistory] (main) Creating Schema History table "base"."flyway_schema_history" ...
2020-05-20 15:29:34,900 INFO  [org.fly.cor.int.com.DbMigrate] (main) Current version of schema "base": null
2020-05-20 15:29:34,903 INFO  [org.fly.cor.int.com.DbMigrate] (main) Migrating schema "base" to version 1.0.0 - create fruits
2020-05-20 15:29:34,904 INFO  [org.fly.cor.int.sql.DefaultSqlScriptExecutor] (main) +--------+
| setval |
+--------+
| 3      |
+--------+

2020-05-20 15:29:34,907 INFO  [org.fly.cor.int.sql.DefaultSqlScriptExecutor] (main) +--------+
| setval |
+--------+
| 3      |
+--------+

2020-05-20 15:29:34,920 INFO  [org.fly.cor.int.com.DbMigrate] (main) Successfully applied 1 migration to schema "base" (execution time 00:00.021s)
2020-05-20 15:29:34,928 INFO  [io.quarkus] (main) hibernate-orm-quickstart-multi-tenancy 1.0-SNAPSHOT native (powered by Quarkus 999-SNAPSHOT) started in 0.103s. Listening on: http://0.0.0.0:8080
2020-05-20 15:29:34,928 INFO  [io.quarkus] (main) Profile prod activated. 
2020-05-20 15:29:34,928 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, flyway, hibernate-orm, jdbc-postgresql, mutiny, narayana-jta, resteasy, resteasy-jsonb]

Seems as if the fix only was half the way.

@stuartwdouglas @geoand Any idea?

@geoand
Copy link
Contributor

geoand commented May 20, 2020

The fix was indeed only for dev-mode. Can you please open a new issue for the problem you are seeing in native?

@michael-schnell
Copy link
Contributor Author

OK

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants