Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-16920

Issues with thread context class loader

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • 26.1.0.Final
    • Logging, Web (Undertow)
    • None
    • Hide
      • Start the WildFly server
      • Unpack the attached small deployment project
      • From its directory build and deploy it (assuming the server is in ~/wildfly), Java 17 is required:

      $ ./gradlew clean war && cp build/libs/class-loaders.war ~/wildfly/standalone/deployments/

      • Now check the server output:

      @@@ configuring logback
      my class loader: ModuleClassLoader for Module "deployment.class-loaders.war" from Service Module Loader
      thread class loader: ModuleClassLoader for Module "org.jboss.as.server" version 18.1.1.Final from local module loader @7ceb3185 (finder: local module finder @436c81a3 (roots: /home/developer/wildfly/modules,/home/developer/wildfly/modules/system/layers/base))
      !!!
      java.lang.ClassNotFoundException: foo.TestDeployment$A from [Module "org.jboss.as.server" version 18.1.1.Final from local module loader @7ceb3185 (finder: local module finder @436c81a3 (roots: /home/developer/wildfly/modules,/home/developer/wildfly/modules/system/layers/base))]
      [[stacktrace]]

      The output comes from class foo.TestDeployment, so you can relate with what it is doing (it is of course not sensible per se, but is derived from a real failure in our application).

      There are two issues here:

      1. Thread context class loader is not the same as the one used to load the deployment class.
      2. Class initialization of A and B fails with the shown exception. I have determined that it is required that A uses B, which in turn loads A (e.g. via Class.forName()) from the thread context class loader during its own initialization. In all other setups no exception seems to happen.

      Why this is a bug. The deployment contains three ways class TestDeployment can be loaded: from LogbackConfigurator (the one triggered by default), from TestDeploymentInitializer (would be trigerred next) and from a JSP page. You can make the second active e.g. by commenting out the 'new TestDeployment...' line in LogbackConfigurator, and similarly for the third (you additionally then need to open URL '.../class-loaders' on localhost or whatever your server is exposed to). Only the first way exhibits the bug. If TestDeployment is initialized via the second or the third way, then 1) class loaders are the same; 2) initialization of A and B doesn't lead to an exception.

      A few notes about the deployment and why it looks like this. It is derived from our real application, therefore I have used the same libraries (only those that appeared in the real stacktrace). File 'jboss-deployment-structure.xml' disables built-in WildFly logging and replaces it with Logback bundled with the deployment. Otherwise the bug doesn't happen. During initialization, org.camunda.bpm.application.impl.ServletProcessApplicationDeployer fires up, creates a logger, which in turn loads our application's logger configurator (class foo.LogbackConfigurator in the attached deployment), at which point the bug happens.

      Show
      Start the WildFly server Unpack the attached small deployment project From its directory build and deploy it (assuming the server is in ~/wildfly), Java 17 is required: $ ./gradlew clean war && cp build/libs/class-loaders.war ~/wildfly/standalone/deployments/ Now check the server output: @@@ configuring logback my class loader: ModuleClassLoader for Module "deployment.class-loaders.war" from Service Module Loader thread class loader: ModuleClassLoader for Module "org.jboss.as.server" version 18.1.1.Final from local module loader @7ceb3185 (finder: local module finder @436c81a3 (roots: /home/developer/wildfly/modules,/home/developer/wildfly/modules/system/layers/base)) !!! java.lang.ClassNotFoundException: foo.TestDeployment$A from [Module "org.jboss.as.server" version 18.1.1.Final from local module loader @7ceb3185 (finder: local module finder @436c81a3 (roots: /home/developer/wildfly/modules,/home/developer/wildfly/modules/system/layers/base))] [ [stacktrace] ] The output comes from class foo.TestDeployment, so you can relate with what it is doing (it is of course not sensible per se, but is derived from a real failure in our application). There are two issues here: Thread context class loader is not the same as the one used to load the deployment class. Class initialization of A and B fails with the shown exception. I have determined that it is required that A uses B, which in turn loads A (e.g. via Class.forName()) from the thread context class loader during its own initialization. In all other setups no exception seems to happen. Why this is a bug. The deployment contains three ways class TestDeployment can be loaded: from LogbackConfigurator (the one triggered by default), from TestDeploymentInitializer (would be trigerred next) and from a JSP page. You can make the second active e.g. by commenting out the 'new TestDeployment...' line in LogbackConfigurator, and similarly for the third (you additionally then need to open URL '.../class-loaders' on localhost or whatever your server is exposed to). Only the first way exhibits the bug. If TestDeployment is initialized via the second or the third way, then 1) class loaders are the same; 2) initialization of A and B doesn't lead to an exception. A few notes about the deployment and why it looks like this. It is derived from our real application, therefore I have used the same libraries (only those that appeared in the real stacktrace). File 'jboss-deployment-structure.xml' disables built-in WildFly logging and replaces it with Logback bundled with the deployment. Otherwise the bug doesn't happen. During initialization, org.camunda.bpm.application.impl.ServletProcessApplicationDeployer fires up, creates a logger, which in turn loads our application's logger configurator (class foo.LogbackConfigurator in the attached deployment), at which point the bug happens.
    • ---
    • ---

      Thread context class loader in some cases (can't understand in which) doesn't match the class loader from which application classes are loaded. I have created a relatively small (several libraries, but very few custom code) test deployment to reproduce this.

      Additionally, different class loaders exhibit different behavior when loading classes recursively. I'm not sure which is correct. See below for what I mean.

      Added by jperkins-rhn:

      Full Stack Trace
      12:32:17,742 INFO  [stdout] (MSC service thread 1-6) @@@ configuring logback
12:32:17,743 INFO  [stdout] (MSC service thread 1-6) my class loader: ModuleClassLoader for Module "deployment.class-loaders.war" from Service Module Loader
12:32:17,743 INFO  [stdout] (MSC service thread 1-6) thread class loader: ModuleClassLoader for Module "org.jboss.as.server" version 18.1.1.Final from local module loader @43b9fd5 (finder: local module finder @79dc5318 (roots: /home/jperkins/tmp/WFLY-16920/wildfly-26.1.1.Final/modules,/home/jperkins/tmp/WFLY-16920/wildfly-26.1.1.Final/modules/system/layers/base))
12:32:17,743 INFO  [stdout] (MSC service thread 1-6) !!!
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) java.lang.ClassNotFoundException: foo.TestDeployment$A from [Module "org.jboss.as.server" version 18.1.1.Final from local module loader @43b9fd5 (finder: local module finder @79dc5318 (roots: /home/jperkins/tmp/WFLY-16920/wildfly-26.1.1.Final/modules,/home/jperkins/tmp/WFLY-16920/wildfly-26.1.1.Final/modules/system/layers/base))]
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:200)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at java.base/java.lang.Class.forName0(Native Method)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at java.base/java.lang.Class.forName(Class.java:398)
12:32:17,744 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//foo.TestDeployment$B.<clinit>(TestDeployment.java:28)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//foo.TestDeployment$A.<clinit>(TestDeployment.java:17)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//foo.TestDeployment.<init>(TestDeployment.java:12)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//foo.LogbackConfigurator.configure(LogbackConfigurator.java:18)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:140)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:417)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.camunda.commons.logging.BaseLogger.createLogger(BaseLogger.java:91)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.camunda.bpm.engine.impl.ProcessEngineLogger.<clinit>(ProcessEngineLogger.java:49)
12:32:17,745 INFO  [stdout] (MSC service thread 1-6) 	at deployment.class-loaders.war//org.camunda.bpm.application.impl.ServletProcessApplicationDeployer.<clinit>(ServletProcessApplicationDeployer.java:42)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at java.base/java.lang.Class.newInstance(Class.java:584)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.wildfly.extension.undertow@26.1.1.Final//org.wildfly.extension.undertow.deployment.ServletContainerInitializerDeploymentProcessor.loadSci(ServletContainerInitializerDeploymentProcessor.java:225)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.wildfly.extension.undertow@26.1.1.Final//org.wildfly.extension.undertow.deployment.ServletContainerInitializerDeploymentProcessor.deploy(ServletContainerInitializerDeploymentProcessor.java:135)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.as.server@18.1.1.Final//org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:182)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.msc@1.4.13.Final//org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1739)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.msc@1.4.13.Final//org.jboss.msc.service.ServiceControllerImpl$StartTask.execute(ServiceControllerImpl.java:1701)
12:32:17,746 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.msc@1.4.13.Final//org.jboss.msc.service.ServiceControllerImpl$ControllerTask.run(ServiceControllerImpl.java:1559)
12:32:17,747 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
12:32:17,747 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
12:32:17,747 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
12:32:17,747 INFO  [stdout] (MSC service thread 1-6) 	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1363)
12:32:17,747 INFO  [stdout] (MSC service thread 1-6) 	at java.base/java.lang.Thread.run(Thread.java:829)
12:32:17,767 INFO  [stdout] (ServerService Thread Pool -- 82) @@@ startup
12:32:17,768 INFO  [stdout] (ServerService Thread Pool -- 82) my class loader: ModuleClassLoader for Module "deployment.class-loaders.war" from Service Module Loader
12:32:17,768 INFO  [stdout] (ServerService Thread Pool -- 82) thread class loader: ModuleClassLoader for Module "deployment.class-loaders.war" from Service Module Loader

        1. test-deployment.tar.gz
          58 kB

              jperkins-rhn James Perkins
              doublep_ Paul Pogonyshev (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated: