Flyway ignoring logback logging configuration #3651

juggernaut0 · 2023-04-05T19:33:35Z

Which version and edition of Flyway are you using?

Communtiy Edition version 9.16.3

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

Java API

What did you do? (Please include the content causing the issue, any relevant configuration settings, the SQL statement(s) that failed (if any), and the command you ran)

Using the Java API to run the migrate command in a project that has slf4j-api and logback-classic on the classpath and a logback.xml in the resources:

    Flyway.configure()
        .dataSource(config.url, config.user, config.pass)
        .load()
        .migrate()

logback.xml:

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%.-12thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

What did you expect to see?

Flyway logs should use my log format as specified in logback.xml. This is the behavior up to and including 9.16.1.

11:33:13.720 [main] INFO  o.f.c.i.license.VersionPrinter - Flyway Community Edition 9.16.1 by Redgate
11:33:13.721 [main] INFO  o.f.c.i.license.VersionPrinter - See release notes here: https://rd.gt/416ObMi
11:33:13.721 [main] INFO  o.f.c.i.license.VersionPrinter - 
11:33:13.886 [main] INFO  o.f.c.i.d.base.BaseDatabaseType - Database: jdbc:postgresql://localhost:6432/auth (PostgreSQL 15.1)
11:33:13.921 [main] INFO  o.f.core.internal.command.DbValidate - Successfully validated 3 migrations (execution time 00:00.020s)
11:33:13.957 [main] INFO  o.f.core.internal.command.DbMigrate - Current version of schema "public": 3
11:33:13.958 [main] INFO  o.f.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.

What did you see instead?

Flyway logs use the default format (same as if there was no slf4j present)

Apr 05, 2023 11:33:35 AM org.flywaydb.core.internal.license.VersionPrinter info
INFO: Flyway Community Edition 9.16.3 by Redgate
Apr 05, 2023 11:33:35 AM org.flywaydb.core.internal.license.VersionPrinter info
INFO: See release notes here: https://rd.gt/416ObMi
Apr 05, 2023 11:33:35 AM org.flywaydb.core.internal.license.VersionPrinter info
INFO: 
Apr 05, 2023 11:33:36 AM org.flywaydb.core.internal.database.base.BaseDatabaseType info
INFO: Database: jdbc:postgresql://localhost:6432/auth (PostgreSQL 15.1)
Apr 05, 2023 11:33:36 AM org.flywaydb.core.internal.command.DbValidate info
INFO: Successfully validated 3 migrations (execution time 00:00.017s)
Apr 05, 2023 11:33:36 AM org.flywaydb.core.internal.command.DbMigrate info
INFO: Current version of schema "public": 3
Apr 05, 2023 11:33:36 AM org.flywaydb.core.internal.command.DbMigrate info
INFO: Schema "public" is up to date. No migration necessary.

The text was updated successfully, but these errors were encountered:

szymonprz · 2023-04-12T07:16:26Z

Same issue here, it stopped working on 9.16.2 version, probably because of that change 8e3af28#diff-a5cc1a4d8df15413b1af4e826332b71fc715d8a654cbc020bcf3be437a9df22dR64-R67

spissvinkel · 2023-04-17T14:16:06Z

I have this issue as well.
As a workaround it may help to configure the logger explicitly, e.g.

    Flyway.configure()
        .loggers("slf4j")
        .dataSource(config.url, config.user, config.pass)
        .load()
        .migrate()

https://documentation.red-gate.com/fd/loggers-184127516.html

wilkinsona · 2023-04-26T18:26:51Z

Spring Boot users are hitting this problem too. I believe that @szymonprz is correct and the problem is due to a failure to detect that SLF4J is available. Here's a minimal project that reproduces the problem by calling FeatureDetector directly:
flyway-slf4j-detection.zip. ./gradlew test should fail. If you change build.gradle to use Flyway 9.16.1 the tests will pass.

flyway/flyway-core/src/main/java/org/flywaydb/core/internal/util/FeatureDetector.java

Lines 57 to 67 in 8e3af28

    
           // We need to ensure there's an actual implementation; AWS SDK pulls in the Logger interface but doesn't 
        
           // provide any implementation, causing SLF4J to drop what we want to be console output on the floor. 
        
           // Versions up to 1.7 have a StaticLoggerBinder 
        
           slf4jAvailable = ClassUtils.isPresent("org.slf4j.Logger", classLoader) 
        
                   && ClassUtils.isPresent("org.slf4j.impl.StaticLoggerBinder", classLoader); 
        
           // Versions 1.8 and later use a ServiceLocator to bind to the implementation 
        
           slf4jAvailable |= ClassUtils.isImplementationPresent("org.slf4j.spi.SLF4JServiceProvider", classLoader); 
        
           if(slf4jAvailable) { 
        
               slf4jAvailable = !StreamSupport.stream(ServiceLoader.load(org.slf4j.Logger.class, classLoader).spliterator(),false) 
        
                                                            .allMatch(logger -> logger instanceof org.slf4j.helpers.NOPLogger); 
        
           }

Lines 65 and 66 are the root of the problem. SLF4J doesn't use the ServiceLoader to load Logger implementations so the stream is empty. As a result, allMatch returns true.

I think lines 57 - 67 could be replaced with the following:

slf4jAvailable = ClassUtils.isPresent("org.slf4j.LoggerFactory", classLoader) 
    && !(LoggerFactory.getILoggerFactory() instanceof NOPLoggerFactory);

This is compatible with SLF4J 1.7.x and 2.0.x as LoggerFactory, its getILoggerFactory() method and NOPLoggerFactory all exist in both versions.

flyway/flyway#3651

hho · 2023-09-06T18:38:18Z

This should be fixed by my PR #3731

ex-ratt · 2023-10-23T16:15:40Z

For me, this did not fix the issue. As far as I am aware, with versions prior to 1.8, slf4j did not use the service loader to find logging implementations. Instead, it looks for org.slf4j.impl.StaticLoggerBinder, which is also tested for. The comment in the code of the FeatureDetector seems to be correct, the code may need some further tweaking.

With slf4j version 1.7.36 and an implementation, I get the following results:

var classLoader = getClass().getClassLoader();
ClassUtils.isPresent("org.slf4j.Logger", classLoader); // true
ClassUtils.isPresent("org.slf4j.impl.StaticLoggerBinder", classLoader); // true
StreamSupport.stream(ServiceLoader.load(classOf[Logger], classLoader).spliterator, false).count(); // 0
StreamSupport.stream(ServiceLoader.load(classOf[Logger], classLoader).spliterator, false).allMatch(_.isInstanceOf[NOPLogger]); // true
ClassUtils.isImplementationPresent("org.slf4j.spi.SLF4JServiceProvider", classLoader); // false

What if the current code:

slf4jAvailable = ClassUtils.isPresent("org.slf4j.Logger", classLoader)
        && ClassUtils.isPresent("org.slf4j.impl.StaticLoggerBinder", classLoader)
        && !StreamSupport.stream(ServiceLoader.load(org.slf4j.Logger.class, classLoader)
                .spliterator(), false).allMatch(logger -> logger instanceof org.slf4j.helpers.NOPLogger);
// Versions 1.8 and later use a ServiceLocator to bind to the implementation
slf4jAvailable |= ClassUtils.isImplementationPresent("org.slf4j.spi.SLF4JServiceProvider", classLoader);

... was changed to this:

boolean slf4jIsPresent = ClassUtils.isPresent("org.slf4j.Logger", classLoader);
// Versions 1.7 and prior use a fixed class name to bind to the implementation
boolean oldImplementationIsPresent = ClassUtils.isPresent("org.slf4j.impl.StaticLoggerBinder", classLoader)
        && !(LoggerFactory.getILoggerFactory() instanceof NOPLoggerFactory);
// Versions 1.8 and later use a ServiceLocator to bind to the implementation
boolean newImplementationIsPresent = ClassUtils.isImplementationPresent("org.slf4j.spi.SLF4JServiceProvider", classLoader)
        && !StreamSupport.stream(ServiceLoader.load(org.slf4j.Logger.class, classLoader).spliterator(), false)
                .allMatch(logger -> logger instanceof org.slf4j.helpers.NOPLogger);
slf4jAvailable = slf4jIsPresent && (oldImplementationIsPresent || newImplementationIsPresent);

Would this work? But the idea of @wilkinsona seems simpler and I did not even test this code.

JasonLuo-Redgate · 2023-11-30T11:59:51Z

This issue has been fixed in the latest version of Flyway, so closing this ticket.

ex-ratt · 2023-12-19T08:57:10Z

I am sorry to bother again, but I just tested version 10.3.0 (the latest version as far as I am aware) and still see this issue. In the FeatureDetector I still see the broken code that does and cannot work with slf4j 1.7.x.

In the attachment (FlywaySlf4j.zip) you can find a small Maven project that you can use to verify it for yourself. If you use version 2.0.9 of slf4j, then the output looks as expected:

[main] INFO org.example.Main - Hello world!
[main] INFO org.flywaydb.core.internal.scanner.classpath.ClassPathScanner - Flyway OSS Edition 10.3.0 by Redgate
[main] INFO org.flywaydb.core.internal.scanner.classpath.ClassPathScanner -
[main] INFO org.flywaydb.core.internal.scanner.classpath.ClassPathScanner - See release notes here: https://rd.gt/416ObMi
[main] INFO org.flywaydb.core.FlywayExecutor - Database: jdbc:postgresql://localhost:5432/postgres (PostgreSQL 15.4)
[main] INFO org.flywaydb.core.internal.command.DbValidate - Successfully validated 0 migrations (execution time 00:00.019s)
[main] WARN org.flywaydb.core.internal.command.DbValidate - No migrations found. Are your locations set up correctly?
[main] INFO org.flywaydb.core.internal.command.DbMigrate - Current version of schema "public": << Empty Schema >>
[main] INFO org.flywaydb.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.

With version 1.7.36, the logging output of Flyway looks different, because it does not recognize that a slf4j logger is available and uses a different one:

[main] INFO org.example.Main - Hello world!
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.scanner.classpath.ClassPathScanner <init>
INFO: Flyway OSS Edition 10.3.0 by Redgate
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.scanner.classpath.ClassPathScanner <init>
INFO:
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.scanner.classpath.ClassPathScanner <init>
INFO: See release notes here: https://rd.gt/416ObMi
Dec 18, 2023 3:45:30 PM org.flywaydb.core.FlywayExecutor execute
INFO: Database: jdbc:postgresql://localhost:5432/postgres (PostgreSQL 15.4)
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.command.DbValidate validate
INFO: Successfully validated 0 migrations (execution time 00:00.020s)
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.command.DbValidate validate
WARNING: No migrations found. Are your locations set up correctly?
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.command.DbMigrate migrateGroup
INFO: Current version of schema "public": << Empty Schema >>
Dec 18, 2023 3:45:30 PM org.flywaydb.core.internal.command.DbMigrate logSummary
INFO: Schema "public" is up to date. No migration necessary.

Please consider what @wilkinsona wrote in April or what I wrote in October. Of course we can always force a specific logger via configuration, but it would be nice if the FeatureDetector would work correctly. Thank you :)

wilkinsona mentioned this issue Apr 26, 2023

Ensure that Flyway uses SLF4J by default and provide a configuration property to override the setting spring-projects/spring-boot#35158

Closed

mhalbritter mentioned this issue May 10, 2023

Flyway 9.16.3 doesn't work with SLF4J loggers oracle/graalvm-reachability-metadata#281

Closed

This was referenced May 10, 2023

Flyway fails to get loggers on native runs after upgrading to 3.1.0-RC1 spring-projects/spring-boot#35116

Closed

9.16.3: VersionPrinter fails initializing log4j logger when running the application natively #3659

Closed

JasonLuo-Redgate added the s: needs investigation label Jul 12, 2023

yannicklamprecht mentioned this issue Jul 19, 2023

Bump io.micronaut.application from 3.7.10 to 4.0.x devcordde/devmarkt-backend#216

Merged

csieflyman added a commit to csieflyman/multi-projects-architecture-with-Ktor that referenced this issue Sep 3, 2023

workaround flyway logger issue

968ebcf

flyway/flyway#3651

JasonLuo-Redgate mentioned this issue Sep 6, 2023

SLF4J Autodetection doesn't work with SLF4J 2.0 #3730

Closed

JasonLuo-Redgate closed this as completed Nov 30, 2023

geirolz mentioned this issue Jan 8, 2024

Options regarding loggers? geirolz/fly4s#273

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flyway ignoring logback logging configuration #3651

Flyway ignoring logback logging configuration #3651

juggernaut0 commented Apr 5, 2023 •

edited

szymonprz commented Apr 12, 2023

spissvinkel commented Apr 17, 2023

wilkinsona commented Apr 26, 2023 •

edited

hho commented Sep 6, 2023

ex-ratt commented Oct 23, 2023 •

edited

JasonLuo-Redgate commented Nov 30, 2023

ex-ratt commented Dec 19, 2023

Flyway ignoring logback logging configuration #3651

Flyway ignoring logback logging configuration #3651

Comments

juggernaut0 commented Apr 5, 2023 • edited

Which version and edition of Flyway are you using?

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

What did you do? (Please include the content causing the issue, any relevant configuration settings, the SQL statement(s) that failed (if any), and the command you ran)

What did you expect to see?

What did you see instead?

szymonprz commented Apr 12, 2023

spissvinkel commented Apr 17, 2023

wilkinsona commented Apr 26, 2023 • edited

hho commented Sep 6, 2023

ex-ratt commented Oct 23, 2023 • edited

JasonLuo-Redgate commented Nov 30, 2023

ex-ratt commented Dec 19, 2023

juggernaut0 commented Apr 5, 2023 •

edited

wilkinsona commented Apr 26, 2023 •

edited

ex-ratt commented Oct 23, 2023 •

edited