Logback unable to find a 3rd party class when running in test VM

I have this simple java project. The relevant part of the build.gradle looks like this:

dependencies {
    compile 'org.apache.commons:commons-lang3:3.1'
    compile 'org.slf4j:slf4j-api:1.7.5'
    testRuntime 'org.slf4j:jcl-over-slf4j:1.7.5'
    testRuntime 'org.perf4j:perf4j:0.9.16'
}
test {
  // enable TestNG support (default is JUnit)
  useTestNG {
      suites(*(fileTree(dir: 'test/src', includes: ['**/testng.xml']).getFiles().toArray()))
  }
    // set a system property for the test JVM(s)
  systemProperty 'logback.configurationFile', "file:$projectDir/test/logback-test.xml"
    // show standard out and standard error of the test JVM(s) on the console
  testLogging.showStandardStreams = false
}

The logback-test.xml file above references several perf4j classes for gathering performance data.

When I run “gradle test”, logback does not initialize successfully, with this error (via --debug):

13:29:33.884 [QUIET] [system.out] 13:29:33,842 |-ERROR in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Could not create component [layout] of type [org.perf4j.logback.StatisticsCsvLayout] java.lang.ClassNotFoundException: org.perf4j.logback.StatisticsCsvLayout
13:29:33.885 [QUIET] [system.out]
at java.lang.ClassNotFoundException: org.perf4j.logback.StatisticsCsvLayout
13:29:33.886 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
13:29:33.887 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
13:29:33.888 [QUIET] [system.out]
at
at java.security.AccessController.doPrivileged(Native Method)
13:29:33.889 [QUIET] [system.out]
at
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
13:29:33.890 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
13:29:33.891 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
13:29:33.891 [QUIET] [system.out]
at
at ch.qos.logback.core.util.Loader.loadClass(Loader.java:124)
13:29:33.892 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.begin(NestedComplexPropertyIA.java:100)
13:29:33.893 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:275)
13:29:33.894 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:147)
13:29:33.895 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:129)
13:29:33.896 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
13:29:33.896 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
13:29:33.897 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
13:29:33.898 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
13:29:33.899 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
13:29:33.900 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
13:29:33.901 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
13:29:33.902 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
13:29:33.903 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
13:29:33.904 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
13:29:33.904 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
13:29:33.905 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
13:29:33.906 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.doConfigure(LogbackLoggingConfigurer.java:67)
13:29:33.907 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.configure(LogbackLoggingConfigurer.java:59)
13:29:33.908 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingConfigurer.configure(DefaultLoggingConfigurer.java:34)
13:29:33.909 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.setLevel(LoggingSystemAdapter.java:55)
13:29:33.910 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.on(LoggingSystemAdapter.java:42)
13:29:33.911 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager$StartableLoggingSystem.start(DefaultLoggingManager.java:168)
13:29:33.912 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:57)
13:29:33.913 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:28)
13:29:33.913 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:58)
13:29:33.914 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:41)
13:29:33.915 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:43)
13:29:33.916 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:32)
13:29:33.917 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:46)
13:29:33.918 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:32)
13:29:33.918 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.run(GradleWorkerMain.java:32)
13:29:33.919 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.main(GradleWorkerMain.java:37)
13:29:33.920 [QUIET] [system.out] 13:29:33,843 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@27:29 - no applicable action for [printNonStatistics], current ElementPath
is [[configuration][appender][encoder][layout][printNonStatistics]]
13:29:33.921 [QUIET] [system.out] 13:29:33,843 |-INFO in ch.qos.logback.core.FileAppender[perfFileAppender] - File property is set to [test/perf4j.csv]
13:29:33.922 [QUIET] [system.out] 13:29:33,843 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.perf4j.logback.AsyncCoalescingStatisticsAppender]
13:29:33.923 [QUIET] [system.out] 13:29:33,843 |-ERROR in ch.qos.logback.core.joran.action.AppenderAction - Could not create an Appender of type [org.perf4j.logback.AsyncCoalescingStatisticsAppender]. ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:33.924 [QUIET] [system.out]
at ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:33.925 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:73)
13:29:33.925 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:48)
13:29:33.926 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:35)
13:29:33.927 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:54)
13:29:33.928 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:275)
13:29:33.929 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:147)
13:29:33.930 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:129)
13:29:33.931 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
13:29:33.931 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
13:29:33.932 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
13:29:33.933 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
13:29:33.934 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
13:29:33.935 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
13:29:33.936 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
13:29:33.937 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
13:29:33.937 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
13:29:33.938 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
13:29:33.939 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
13:29:33.940 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
13:29:33.941 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.doConfigure(LogbackLoggingConfigurer.java:67)
13:29:33.942 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.configure(LogbackLoggingConfigurer.java:59)
13:29:33.943 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingConfigurer.configure(DefaultLoggingConfigurer.java:34)
13:29:33.944 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.setLevel(LoggingSystemAdapter.java:55)
13:29:33.945 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.on(LoggingSystemAdapter.java:42)
13:29:33.945 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager$StartableLoggingSystem.start(DefaultLoggingManager.java:168)
13:29:33.946 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:57)
13:29:33.947 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:28)
13:29:33.948 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:58)
13:29:33.949 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:41)
13:29:33.950 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:43)
13:29:33.951 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:32)
13:29:33.952 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:46)
13:29:33.952 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:32)
13:29:33.953 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.run(GradleWorkerMain.java:32)
13:29:33.954 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.main(GradleWorkerMain.java:37)
13:29:33.955 [QUIET] [system.out] Caused by: java.lang.ClassNotFoundException: org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:33.956 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
13:29:33.957 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
13:29:33.958 [QUIET] [system.out]
at
at java.security.AccessController.doPrivileged(Native Method)
13:29:33.959 [QUIET] [system.out]
at
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
13:29:33.960 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
13:29:33.960 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
13:29:33.962 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:60)
13:29:33.962 [QUIET] [system.out]
at
... 34 common frames omitted
13:29:33.963 [QUIET] [system.out] 13:29:33,844 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@33:74 - ActionException in Action for tag [appender] ch.qos.logback.core.joran.spi.ActionException: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:33.964 [QUIET] [system.out]
at ch.qos.logback.core.joran.spi.ActionException: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:33.965 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:82)
13:29:33.966 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:275)
13:29:33.967 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:147)
13:29:33.968 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:129)
13:29:33.969 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
13:29:33.970 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
13:29:33.971 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
13:29:33.971 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
13:29:33.972 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
13:29:33.973 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
13:29:33.974 [QUIET] [system.out]
at
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
13:29:33.975 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
13:29:33.976 [QUIET] [system.out]
at
at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
13:29:33.977 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
13:29:33.978 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
13:29:33.978 [QUIET] [system.out]
at
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
13:29:33.979 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.doConfigure(LogbackLoggingConfigurer.java:67)
13:29:33.980 [QUIET] [system.out]
at
at org.gradle.logging.internal.logback.LogbackLoggingConfigurer.configure(LogbackLoggingConfigurer.java:59)
13:29:33.981 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingConfigurer.configure(DefaultLoggingConfigurer.java:34)
13:29:33.982 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.setLevel(LoggingSystemAdapter.java:55)
13:29:33.983 [QUIET] [system.out]
at
at org.gradle.logging.internal.LoggingSystemAdapter.on(LoggingSystemAdapter.java:42)
13:29:33.984 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager$StartableLoggingSystem.start(DefaultLoggingManager.java:168)
13:29:33.985 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:57)
13:29:33.986 [QUIET] [system.out]
at
at org.gradle.logging.internal.DefaultLoggingManager.start(DefaultLoggingManager.java:28)
13:29:33.986 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:58)
13:29:33.987 [QUIET] [system.out]
at
at org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:41)
13:29:33.988 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:43)
13:29:33.989 [QUIET] [system.out]
at
at org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:32)
13:29:33.991 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:46)
13:29:33.992 [QUIET] [system.out]
at
at org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:32)
13:29:33.997 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.run(GradleWorkerMain.java:32)
13:29:33.998 [QUIET] [system.out]
at
at jarjar.org.gradle.process.internal.launcher.GradleWorkerMain.main(GradleWorkerMain.java:37)
13:29:33.999 [QUIET] [system.out] Caused by: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:34.000 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:73)
13:29:34.001 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:48)
13:29:34.002 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:35)
13:29:34.003 [QUIET] [system.out]
at
at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:54)
13:29:34.004 [QUIET] [system.out]
at
... 31 common frames omitted
13:29:34.004 [QUIET] [system.out] Caused by: java.lang.ClassNotFoundException: org.perf4j.logback.AsyncCoalescingStatisticsAppender
13:29:34.009 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
13:29:34.010 [QUIET] [system.out]
at
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
13:29:34.011 [QUIET] [system.out]
at
at java.security.AccessController.doPrivileged(Native Method)
13:29:34.011 [QUIET] [system.out]
at
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
13:29:34.012 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
13:29:34.013 [QUIET] [system.out]
at
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
13:29:34.014 [QUIET] [system.out]
at
at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:60)
13:29:34.015 [QUIET] [system.out]
at
... 34 common frames omitted

Any thoughts? Thanks for any help.

can you share your logback-test.xml file to reproduce the issue?

Sure, I put it here: http://digizenstudio.com/static/logback-test.xml Thanks

I can reproduce this issue now. Most likely it’s an classloader issue because the classloader which contains slf4j setup does not know about perf4j here. The rootcause for that is the way we fork the test jvm. I’ll let you know once I figured out a workaround/fix for this

org.perf4j

perf4j

0.9.16

Add the above dependency in the pom.