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

LogFactory not initialized with the right classloader if first log is from the Flyway class #2270

Closed
sofoklis opened this issue Jan 22, 2019 · 8 comments

Comments

@sofoklis
Copy link

@sofoklis sofoklis commented Jan 22, 2019

5.2.4 Which version and edition of Flyway are you using?

Latest Version

Java API

Postgres 10.5

Ubuntu

Upgraded from 5.0.7 to 5.2.4 What did you do?
If i have an exception in the SQL the logger would fail with the regular message now i get the exception bellow, I believe that the Flyway o:
java.lang.ExceptionInInitializerError
at org.flywaydb.core.internal.util.FeatureDetector.isSlf4jAvailable(FeatureDetector.java:96)
at org.flywaydb.core.internal.logging.LogCreatorFactory.getLogCreator(LogCreatorFactory.java:39)
at org.flywaydb.core.api.logging.LogFactory.getLog(LogFactory.java:78)
at org.flywaydb.core.internal.util.FeatureDetector.(FeatureDetector.java:25)
at org.flywaydb.core.internal.logging.LogCreatorFactory.getLogCreator(LogCreatorFactory.java:35)
at org.flywaydb.core.api.logging.LogFactory.getLog(LogFactory.java:78)
at org.flywaydb.core.Flyway.(Flyway.java:86)
...
Caused by: java.lang.ClassCastException: org.flywaydb.core.internal.logging.slf4j.Slf4jLogCreator cannot be cast to org.flywaydb.core.api.logging.LogCreator
at org.flywaydb.core.internal.logging.LogCreatorFactory.getLogCreator(LogCreatorFactory.java:40)
at org.flywaydb.core.api.logging.LogFactory.getLog(LogFactory.java:78)
at org.flywaydb.core.internal.util.ClassUtils.(ClassUtils.java:39)
... 17 more

Normal log messages

What did you see instead? The exception above.

It seems to me that after the change to fluid configuration the default log creator is no longer initialized with the same class loader we use for the Configuration object. I think the default log creator should be using the same class loader as the parameter in the configuration object. If you are using multiple threads then depending on which thread you happen to be you randomly get this error.

As a workaround i make sure the first log is in the main method of my migration script.

@axelfontaine
Copy link
Contributor

@axelfontaine axelfontaine commented Jan 22, 2019

Please share the necessary code to reproduce this.

@sofoklis
Copy link
Author

@sofoklis sofoklis commented Jan 28, 2019

I think there should be a connection between the log factory and the config object. Now the log factory is a singleton but when and where it is created can cause issues.

public class LogFactory{ ...
     public static Log getLog(Class<?> clazz) {
        if (logCreator == null) {
            // Here the class loader is not necessarily the same as the one you specified in the
            // configuration object, and if it is not the you get the exception above.
            ClassLoader classLoader = Thread.currentThread().getContextClassLoader();
            logCreator = LogCreatorFactory.getLogCreator(classLoader, fallbackLogCreator);
        }

        return logCreator.createLogger(clazz);
    }
}

To reproduce all you have to do is create the config object this migration in a different thread than the main thread, i believe this should be enough, and of cause have some failing migration so the getLog is triggered:

main(){
    val config = Flyway.configure(this.getClass.getClassLoader)
          .dataSource(url, ownerUser, password);

    // Make sure the log is initialized with the right class loader, uncomment and it works.
    // val log = LogFactory.getLog(config.getClass)

    new Thread(() -> {
          // Here i expect that the class loader that i setup in my config will be used but 
          // it is not necessarily.
          Flyway flyway = new Flyway(config);

          // Start the migration
        flyway.migrate();
    }).start();
}

@nigredo-tori
Copy link

@nigredo-tori nigredo-tori commented Feb 14, 2019

Hit this as well using SBT.

I'm using Flyway to set up the test database. When running tests manually, on the first test run everything is OK, but on the second one I get the exception above. I explicitly initialize Flyway with a classloader from my project, and the tests are ran without forking - meaning they are run from two different classloaders in the same JVM.

@nigredo-tori
Copy link

@nigredo-tori nigredo-tori commented Feb 14, 2019

In the first place, does LogFactory even need the thread classloader? It's only used in LogCreatorFactory to instantiate one of the known LogCreators, which are in the same artifact as LogFactory. LogFactory.getClass().getClassLoader() should be enough here, IMO.

UPD: It's probably because FeatureDetector uses it to check whether some external libraries are present.

@axelfontaine
Copy link
Contributor

@axelfontaine axelfontaine commented Feb 14, 2019

@nigredo-tori @sofoklis Can you confirm the problem goes away if you switch to LogFactory.getClass().getClassLoader() instead?

@nigredo-tori
Copy link

@nigredo-tori nigredo-tori commented Feb 14, 2019

@axelfontaine, it seems to solve the issue for my case (though it's LogFactory.class.getClassLoader()). But there's probably a use case somewhere for which this breaks things instead... Honestly, I'd prefer it if Flyway didn't reinvent logging bridges at all.

@m4dc4p
Copy link

@m4dc4p m4dc4p commented Apr 12, 2019

Seeing this problem from SBT myself. First run is fine, second run fails. Restarting SBT is the only thing that fixes.

I'm using log4s w/ logback for logging.

axelfontaine pushed a commit to flyway/flywaydb.org that referenced this issue Apr 15, 2019
@axelfontaine axelfontaine added this to the Flyway 6.0.0 milestone Apr 15, 2019
@axelfontaine
Copy link
Contributor

@axelfontaine axelfontaine commented Apr 15, 2019

This has now been changed to use LogFactory.class.getClassLoader()

@axelfontaine axelfontaine removed this from the Flyway 6.0.0 milestone May 22, 2019
@axelfontaine axelfontaine added this to the Flyway 6.0.0-beta2 milestone May 22, 2019
dohrayme pushed a commit to dohrayme/flyway that referenced this issue Feb 3, 2020
…der if first log is from the Flyway class
remerle pushed a commit to remerle/vinyldns that referenced this issue Oct 15, 2021
- Remove old, unused scripts in `bin/`
- Remove old images from release
  - `test` and `test-bind` are no longer necessary. Test images are in a different repo now
- Remove Docker image creation from sbt build config - actual `Dockerfile` files are easier to deal with

- Update scripts in `bin/` to utilize new Docker images
- Update documentation for changes
- Update all Docker Compose and configuration to use exposed ports on the `integration` image (19001, 19002, etc) both inside the container and outside to make testing more consistent irrespective of method
- Update FlywayDB dependency to v8 to fix a weird logging bug that showed up during integration testing. See: flyway/flyway#2270

- Add `test/api/integration` Docker container definition to be used for any integration testing

- Move `module/api/functional_test` to `test/api/functional` to centralize the "integration-type" external tests and testing utilities

- Move functional testing and integration image to the `test/` folder off of the root to reduce confusion with `bin/` and `docker/`
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants