Use context Classloader first if it is defined

[jeantil]

This PR was initally motivated by an issue where logback was unable to resolve a
custom filter in a play 2.3 and 2.4 application in dev mode.
The issue is that for all dependencies, including logback, the classes are
loaded in a DependencyClassloader which is stable, while the project code is i
loaded in a ReloadableClassloader which is a child of the stable class loader
and is discarded whenever project source code changes.

Since logback doesn't allow to pass a custom classloader, nor does it lookup the
context classloader, it tries to resolve project classes in the stable
classloader and fails to find project classes.

This small change tries to use the context classloader first if it is set, and
then falls back to the original behaviour. This effectively fixes the problem
for play applications in dev mode (tried using maven install and depending on the patched version locally)

More background on the classloader architecture in Play applications can be found in playframework/playframework#2847

[jeantil]

a sample play 2.4 application demonstrating the issue is available at http://s000.tinyupload.com/index.php?file_id=23910239419295528828

simply change the version of logback to 1.1.2 or an unpatched 1.1.3 to get the error below and install a patched 1.1.3 to see it go away.

4:01:35,527 |-ERROR in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Could not create component [filter] of type [logback.NamespaceFilter] java.lang.ClassNotFoundException: logback.NamespaceFilter
    at java.lang.ClassNotFoundException: logback.NamespaceFilter
    at  at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
    at  at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at  at ch.qos.logback.core.util.Loader.loadClass(Loader.java:125)
    at  at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.begin(NestedComplexPropertyIA.java:100)
    at  at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:275)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:147)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:129)
    at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
    at  at play.api.Logger$.configure(Logger.scala:300)
    at  at play.api.Logger$.configure(Logger.scala:254)
    at  at play.api.inject.guice.GuiceApplicationBuilder.injector(GuiceApplicationBuilder.scala:73)
    at  at play.api.inject.guice.GuiceApplicationBuilder.build(GuiceApplicationBuilder.scala:89)
    at  at play.api.inject.guice.GuiceApplicationLoader.load(GuiceApplicationLoader.scala:25)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1$$anonfun$1$$anonfun$2.apply(ApplicationProvider.scala:182)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1$$anonfun$1$$anonfun$2.apply(ApplicationProvider.scala:179)
    at  at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1$$anonfun$1.apply(ApplicationProvider.scala:179)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1$$anonfun$1.apply(ApplicationProvider.scala:148)
    at  at scala.Option.map(Option.scala:145)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1.apply(ApplicationProvider.scala:148)
    at  at play.core.ReloadableApplication$$anonfun$get$1$$anonfun$apply$1.apply(ApplicationProvider.scala:146)
    at  at scala.util.Success.flatMap(Try.scala:200)
    at  at play.core.ReloadableApplication$$anonfun$get$1.apply(ApplicationProvider.scala:146)
    at  at play.core.ReloadableApplication$$anonfun$get$1.apply(ApplicationProvider.scala:138)
    at  at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
    at  at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
    at  at scala.concurrent.forkjoin.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1361)
    at  at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at  at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at  at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at  at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

[panchenko]

@jeantil What would happen, when ReloadableClassloader used to load that filter is discarded?
Is logback reinitialized also or does it keep the filter instance from discarded class loader? In the latter case I am not sure if it will be working correctly.

As a workaround, can you just put that filter into DependencyClassloader?

[jeantil]

@panchenko I have not witnessed any adverse effect caused by a reload, even after forcing a full gc through jcmd.

I would not expect Logback to be reinitialized. It would keep its reference to the old instance and work just fine albeit with the old behaviour.

The only way I can think of for loading the filter in the DependencyClassLoader would be to package it in its own artifact and add a dependency on it. That's a lot of hassle for one 4 lines class, I did go through it for my current project but would much prefer if it could be reintegrated in the main project. Explaining why we had to create a separate artifact for that one class and documenting it for long term maintenance is not exactly foolproof :(

[ceki]

This commit default to the TCL effectively changing logback behavior for all our users. It may be fine in your use case, but not for other users. There is a need for a more controlled way to set the class loader in effect. Sneaking in the TCL is certainly not the way go.

[jeantil]

Would you consider a PR that falls back to TCL if the class is not found using the current algorithm first ?

[mkurz]

This is still a huge problem, see playframework/playframework#8125.

More than two years after this issue was opened it is still not possible to pass a custom classloader to logback, nor does it lookup the context classloader...

Would you consider a PR that falls back to TCL if the class is not found using the current algorithm first ?

@panchenko @ceki What about that suggestion? Would that be ok for you?

[ceki]

Passing custom class loader or using the TCCL is a rabbit hole I do not wish to descend into. As far as I am concerned, if the class loader that loaded logback cannot find a class, then tough luck. Resources are quite different because they don't have the class loader mismatch issue that classes have.

[nafg]

I'm affected by this issue