flyway-sbt icon indicating copy to clipboard operation
flyway-sbt copied to clipboard

Flyway logs missing on the console when running commands

Open lawrencej004 opened this issue 11 months ago • 2 comments

Hello, it seems that in both the recent versions of the plugin v9.22.0 and v10.21.0 the logs from Flyway commands are missing in the console when running commands through SBT. In Flyway v8 the LogFactory added a call to set the Flyway configuration on calls to Flyway.load() which in turn sets the logCreator to null. This means that the SbtLogCreator is dropped as it is set before this point, and means that the logs to the SBT logger are missing from Flyway commands. If the logger is set after the call to load Flyway then this seems to fix the problem.

Example of before and after running the test1 test in the repo:

[info] Running flyway-sbt/test1
[info] [info] set current project to flyway-sbt-test1 (in build file:/private/var/folders/8t/f_6nqpkx0_q55_z0nrfcz8cw0000gn/T/sbt_3c9b75ad/)
[info] [info] welcome to sbt 1.5.8 (Amazon.com Inc. Java 17.0.13)
[info] [info] loading settings for project sbt_3c9b75ad-build from plugins.sbt ...
[info] [info] loading project definition from /private/var/folders/8t/f_6nqpkx0_q55_z0nrfcz8cw0000gn/T/sbt_3c9b75ad/project
[info] [info] loading settings for project sbt_3c9b75ad from build.sbt ...
[info] [info] set current project to flyway-sbt-test1 (in build file:/private/var/folders/8t/f_6nqpkx0_q55_z0nrfcz8cw0000gn/T/sbt_3c9b75ad/)
[info] [info] ans: String = null
[info] [success] Total time: 1 s, completed 6 Jan 2025, 16:51:05
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:51:06
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [info] | Category  | Version | Description    | Type | Installed On        | State   | Undoable |
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [info] | Versioned | 1       | First          | SQL  | 2025-01-06 16:51:06 | Success | No       |
[info] [info] | Versioned | 1.1     | Populate table | SQL  | 2025-01-06 16:51:06 | Success | No       |
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:51:06
[info] [info] ans: String = null
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:51:07
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:51:07
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [info] | Category  | Version | Description         | Type | Installed On        | State   | Undoable |
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [info] | Versioned | 1       | First               | SQL  | 2025-01-06 16:51:07 | Success | No       |
[info] [info] | Versioned | 1.1     | Populate test table | SQL  | 2025-01-06 16:51:07 | Success | No       |
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:51:07
[info] + flyway-sbt/test1 

With the logger set after the call to load Flyway with missing logs in bold:

[info] Running flyway-sbt/test1
[info] [info] set current project to flyway-sbt-test1 (in build file:/private/var/folders/8t/f_6nqpkx0_q55_z0nrfcz8cw0000gn/T/sbt_2e0bbebd/)
[info] [info] ans: String = null
[info] [info] Flyway Community Edition 9.22.0 by Redgate
[info] [info] See release notes here: https://rd.gt/416ObMi
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] Schema history table "PUBLIC"."flyway_schema_history" does not exist yet
[info] [info] Successfully dropped pre-schema database level objects (execution time 00:00.000s)
[info] [info] Successfully cleaned schema "PUBLIC" (execution time 00:00.001s)
[info] [info] Successfully cleaned schema "PUBLIC" (execution time 00:00.000s)
[info] [info] Successfully dropped post-schema database level objects (execution time 00:00.000s)
[info] [success] Total time: 1 s, completed 6 Jan 2025, 16:52:00
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] Schema history table "PUBLIC"."flyway_schema_history" does not exist yet
[info] [info] Successfully validated 2 migrations (execution time 00:00.011s)
[info] [info] Creating Schema History table "PUBLIC"."flyway_schema_history" ...
[info] [info] Current version of schema "PUBLIC": >
[info] [info] Migrating schema "PUBLIC" to version "1 - First"
[info] [info] Migrating schema "PUBLIC" to version "1.1 - Populate table"
[info] [info] Successfully applied 2 migrations to schema "PUBLIC", now at version v1.1 (execution time 00:00.001s)
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:52:00
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [info] | Category  | Version | Description    | Type | Installed On        | State   | Undoable |
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [info] | Versioned | 1       | First          | SQL  | 2025-01-06 16:52:00 | Success | No       |
[info] [info] | Versioned | 1.1     | Populate table | SQL  | 2025-01-06 16:52:00 | Success | No       |
[info] [info] +-----------+---------+----------------+------+---------------------+---------+----------+
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:52:01
[info] [info] ans: String = null
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] Successfully dropped pre-schema database level objects (execution time 00:00.000s)
[info] [info] Successfully cleaned schema "PUBLIC" (execution time 00:00.001s)
[info] [info] Successfully cleaned schema "PUBLIC" (execution time 00:00.000s)
[info] [info] Successfully dropped post-schema database level objects (execution time 00:00.000s)
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:52:01
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] Schema history table "PUBLIC"."flyway_schema_history" does not exist yet
[info] [info] Successfully validated 2 migrations (execution time 00:00.007s)
[info] [info] Creating Schema History table "PUBLIC"."flyway_schema_history" ...
[info] [info] Current version of schema "PUBLIC": >
[info] [info] Migrating schema "PUBLIC" to version "1 - First"
[info] [info] Migrating schema "PUBLIC" to version "1.1 - Populate test table"
[info] [info] Successfully applied 2 migrations to schema "PUBLIC", now at version v1.1 (execution time 00:00.001s)
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:52:02
[info] [info] Database: jdbc:hsqldb:file:target/flyway_sample;shutdown=true (HSQL Database Engine 2.5)
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [info] | Category  | Version | Description         | Type | Installed On        | State   | Undoable |
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [info] | Versioned | 1       | First               | SQL  | 2025-01-06 16:52:02 | Success | No       |
[info] [info] | Versioned | 1.1     | Populate test table | SQL  | 2025-01-06 16:52:02 | Success | No       |
[info] [info] +-----------+---------+---------------------+------+---------------------+---------+----------+
[info] [success] Total time: 0 s, completed 6 Jan 2025, 16:52:02
[info] + flyway-sbt/test1 

The changed code was on the configure function:

    def configure(config: Config): Flyway = {
      val flywayInstance = flyway
        .configure(config.base)
        .configure(config.migrationLoading)
        .configure(config.sqlMigration)
        .configure(config.migrate)
        .configure(config.placeholder)
        .configureSysProps(config.dataSource)
        .load()
      // Log creator needs to be set after calling Flyway.load() as it clears the log creator in the log factory
      LogFactory.setLogCreator(SbtLogCreator)
      flywayInstance
    }

lawrencej004 avatar Jan 06 '25 17:01 lawrencej004

I just ran into this exact same issue and came up with the exact same fix as you. I was about to come here to report it when I found your issue already reported. Do you happen to already have a 10.21.0 fork that has the fix? If not, I'll fork it in my local git repo (until a fix is incorporated into the main repo).

clintmiller1 avatar Feb 12 '25 18:02 clintmiller1

@mkurz Could this get addressed in the next release? It hurts the usability not having the execution log, and the fix is pretty straightforward

john-joe-givery avatar Apr 12 '25 04:04 john-joe-givery

  • Fixed by #176

mkurz avatar Aug 06 '25 08:08 mkurz

I try to push out release today.

mkurz avatar Aug 06 '25 08:08 mkurz

Pushed a tag - https://github.com/sbt/flyway-sbt/releases/tag/v11.11.0

eed3si9n avatar Aug 11 '25 07:08 eed3si9n