[SLF4J-548] Fix ServiceLoader usage in servlet environment #304

ppkarwasz · 2022-09-02T21:15:33Z

If both the servlet container and a web application use SLF4J,
ServiceLoader calls are susceptible to three problems:

The SLF4J copy in the webapp detects the common providers by can not
instantiate them (they implement a different copy of
SLF4JProviderService),
The SLF4J copy in the common classloader can bind the providers in
the webapp classloader and cause a memory leak,
If the server uses a SecurityManager the static initialization of
LoggerFactory fails if called by unprivileged code.

This PR should solve these problems.

If both the servlet container and a web application use SLF4J, `ServiceLoader` calls are susceptible to three problems: 1. The SLF4J copy in the webapp detects the common providers by can not instantiate them (they implement a different copy of `SLF4JProviderService`), 2. The SLF4J copy in the common classloader can bind the providers in the webapp classloader and cause a memory leak, 3. If the server uses a SecurityManager the static initialization of `LoggerFactory` fails if called by unprivileged code. This PR should solve these problems. Signed-off-by: Piotr P. Karwasz <piotr.github@karwasz.org>

ceki · 2022-09-28T12:08:24Z

PRs without a related issue tend to fall in between the cracks. I have created a jira issue for this PR SLF4J-568

ppkarwasz · 2022-09-28T13:29:33Z

@ceki,
I believe this PR addresses the concerns of the open Jira issue SLF4J-548.

ceki · 2022-09-28T20:02:41Z

@ppkarwasz Indeed, thank you.

boris-unckel · 2022-10-11T18:24:26Z

@ceki Could you check this, please? We have issues to adopt SLF4J 2 in WildFly-Core downstream. The service load based on TCCL is a mess. @ppkarwasz solution solved it for log4j2 API service load of the corresponding impl.
It would be great to get minor release for it.

ceki · 2022-10-11T18:42:23Z

@boris-unckel Do you have a description of the problem you are facing? Or a reference to the original problem?

From a cursory look, Piotr's patch

invokes AccessController.doPrivileged if a SecurityManager is present
catches instantiations problems of found services.

Am I missing anything?

You mention TCCL but the code in question does not use TCCL (on purpose).

ppkarwasz · 2022-10-11T19:25:30Z

@ceki,

The patch also calls ServiceLoader.load with a classloader parameter (the classloader that loaded SLF4J), so it doesn't use the TCCL. ServiceLoader.load(Class) uses the TCCL.

It's basically a simplified version of ServiceLoaderUtil in log4j-api, which is used by other Log4j2 modules, so it has to deal with caller sensitivity problems. ServiceLoaderUtil also deals with OSGI directly, whereas SLF4J requires a Service Loader Mediator (Apache Aries) to be present in the OSGI container.

boris-unckel · 2022-10-12T05:02:59Z

Hello @ceki ,

steps to reproduce:

General: setup latest Maven and a Java 11 environment

clone and build https://github.com/boris-unckel/slf4j-jboss-logmanager/tree/JBLOGGING-165_upgrade_slf4j2 with
mvn clean install
git clone https://github.com/wildfly/wildfly-core.git
2a) optional run to proove everything is OK with WF-Core before:
mvn clean install -Dsecurity.manager -DallTests -Dmaven.test.failure.ignore=true >../buildlog.txt 2>&1
upgrade pom.xml line 246 (version.org.jboss.slf4j.slf4j-jboss-logmanager) to 1.2.1.Final-SNAPSHOT ( https://github.com/wildfly/wildfly-core/blob/main/pom.xml#L246 )
upgrade pom.xml line 256 (version.org.slf4j) to 2.0.2 ( https://github.com/wildfly/wildfly-core/blob/main/pom.xml#L256 )
upgrade testsuite/embedded/pom.xml line (version.ch.qos.logback) to 1.4.1 ( https://github.com/wildfly/wildfly-core/blob/main/testsuite/embedded/pom.xml#L41 )
mvn clean install -Dsecurity.manager -DallTests -Dmaven.test.failure.ignore=true >../buildlog.txt 2>&1

The issues occur without SecurityManager, too. To check simply remove -Dsecurity.manager.

I thought I could develop a workaround, initializing slf4j early in the log subsystem:
https://github.com/boris-unckel/wildfly-core/tree/upgrade_slf4j2_showcase
but it fails for the embedded server edition and breaks existing usecases. The second downside is the increase of dependencies and length of startup.

Kind regards
Boris

ceki · 2022-10-12T16:21:47Z

@boris-unckel Thanks for the information. I am quite swamped at the moment. I'll deal with this when I can, but it make take a few days.

boris-unckel · 2022-11-05T09:53:14Z

@ceki Hope you're fine. Any updates on this one?

ceki · 2022-11-05T12:41:11Z

@ceki Hope you're fine. Any updates on this one?

Hi @boris-unckel, I am sorry for not having attended to this PR. It is at the top of my SLF4J todo list. I expect to start working on SLF4J on the week of Monday 14th and there should be a new release before the end of November.

If you wish things to go a little faster, there is also the option of championing a release.

ceki · 2022-11-17T20:51:11Z

@boris-unckel Can you please check if release 2.0.4 solves the issue for you?

Here is a quote from the release notes:

LoggerFactory now uses the class loader that loaded LoggerFactory class itself to find providers of type SLF4JServiceProvider. Previously, the thread context class loader was used. This was unintentional and the current behavior more closely matches that of the SLF4J 1.7 series and earlier. This tentatively fixes SLF4J-544 as well as several other related/duplicating issues.

boris-unckel · 2022-11-22T16:53:39Z

Hello @ceki @ppkarwasz

I have tested it with WildFly-Core and 2.0.4 still has issues. I have ported the ServiceLoaderUtil from Log4j2 and it works immediately. This is the showcase[1]:
https://github.com/boris-unckel/slf4j/tree/serviceloader

The requirement is to have the API provided by the server, and the implementation by one of the deployed applications.
The service load must work with Security Manager activated, as we still support Java11+
The server module (API) is known by the deployed application, but the server module(API) does not have a relationship (for example a parent classloader) to the application.

The WildFly-Core integrated version of it is here:
https://github.com/boris-unckel/wildfly-core/tree/upgrade_slf4j2_showcase2

[1] The showcase contains copies of code from log4j2. The commit message shows source URLs.

ceki · 2022-11-22T17:20:29Z

@boris-unckel Can you please clarify whether slf4j-api version 1.7.x works for WildFly-Core?

ppkarwasz · 2022-11-22T17:58:49Z

@boris-unckel,

Thanks for the tests. I was pretty sure this patch is equivalent to what we did in Log4j2 (minus the MethodHandles stuff that Log4j2 needs because the caller of ServiceLoaderUtil and the class itself can be in different JPMS modules). I'll look into it this weekend.

Given the amount of debugging that ServiceLoaderUtil has seen (and a couple of bug reports :-) ), I think that including it into SLF4J would be the safest and easiest solution.

Full disclosure: there is still an open Log4j2 bug report (cf. LOG4J2-3624) that might be related to ServiceLoaderUtil, but I was unable to reproduce it.

boris-unckel · 2022-11-22T19:33:42Z

@ceki @ppkarwasz thanks for your fast reply

@boris-unckel Can you please clarify whether slf4j-api version 1.7.x works for WildFly-Core?

Yes, sure: It's used in the current production version https://github.com/wildfly/wildfly-core/blob/19.0.0.Final/pom.xml#L257 you can download it here: https://www.wildfly.org/downloads/

It's also a implicit module: https://docs.wildfly.org/27/Developer_Guide.html#how-and-when-is-an-implicit-module-dependency-added

ceki · 2022-11-22T19:47:15Z

@boris-unckel Slf4j's LoggerFactory in both version 1.7.x and version 2.0.4 (but not 2.0.3) use the same class loader, i.e. the class loader that loaded the LoggerFactory class to look for the logging implementation. Thus, why would 1.7.36 work in a given context, in this case WildFly, and 2.0.4 fail in the same context?

Running the tests under "wildfly-core/testsuite/embedded" with SLF4J 2.0.4, more specifically the test LogbackStandaloneTestCase.testLogback, I observe the following exception:

Caused by: org.wildfly.core.embedded.EmbeddedProcessStartException: WFLYEMB0021: Cannot start embedded process
        at org.wildfly.embedded@20.0.0.Beta3-SNAPSHOT//org.wildfly.core.embedded.EmbeddedStandaloneServerFactory$StandaloneServerImpl.start(EmbeddedStandaloneServerFactory.java:324)
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
        at java.base/java.lang.reflect.Method.invoke(Method.java:578)
        at org.wildfly.core.embedded.EmbeddedManagedProcessImpl.invokeOnServer(EmbeddedManagedProcessImpl.java:107)
        ... 47 more
Caused by: java.util.concurrent.ExecutionException: JBTHR00005: Operation failed
        at org.jboss.threads.AsyncFutureTask.get(AsyncFutureTask.java:253)
        at org.wildfly.embedded@20.0.0.Beta3-SNAPSHOT//org.wildfly.core.embedded.EmbeddedStandaloneServerFactory$StandaloneServerImpl.start(EmbeddedStandaloneServerFactory.java:305)
        ... 50 more
Caused by: java.lang.Exception: WFLYSRV0056: Server boot has failed in an unrecoverable manner; exiting. See previous messages for details. - Server configuration file in use: standalone.xml
        at org.jboss.as.server@20.0.0.Beta3-SNAPSHOT//org.jboss.as.server.BootstrapListener.bootFailure(BootstrapListener.java:87)
        at org.jboss.as.server@20.0.0.Beta3-SNAPSHOT//org.jboss.as.server.ServerService.boot(ServerService.java:440)
        at org.jboss.as.controller@20.0.0.Beta3-SNAPSHOT//org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:473)
        at java.base/java.lang.Thread.run(Thread.java:1589)

I also observe that SLF4J provider finds logback and can create logger instances apparently with no problems. As for the actual cause of the failure, that remains a mystery.

ceki · 2022-11-23T00:07:15Z

Update: setting pom entries to use slf4j 2.0.4 and logback 1.4.5, the following commands complete successfully.

git clone https://github.com/wildfly/wildfly-core.git 
cd wildcore-core
mvn clean
mvn install -Dmaven.test.skip=true
cd testsuite/embedded/
mvn install

Here are the edits on the project:

diff --git a/pom.xml b/pom.xml
index c514d93798..9f3bab98e7 100644
--- a/pom.xml
+++ b/pom.xml
@@ -241,7 +241,7 @@
         <version.org.jboss.remoting>5.0.26.Final</version.org.jboss.remoting>
         <version.org.jboss.remotingjmx.remoting-jmx>3.0.4.Final</version.org.jboss.remotingjmx.remoting-jmx>
         <version.org.jboss.shrinkwrap.shrinkwrap>1.2.6</version.org.jboss.shrinkwrap.shrinkwrap>
-        <version.org.jboss.slf4j.slf4j-jboss-logmanager>1.1.0.Final</version.org.jboss.slf4j.slf4j-jboss-logmanager>
+        <version.org.jboss.slf4j.slf4j-jboss-logmanager>1.2.1.Final-SNAPSHOT</version.org.jboss.slf4j.slf4j-jboss-logmanager>
         <version.org.jboss.staxmapper>1.3.0.Final</version.org.jboss.staxmapper>
         <version.org.jboss.stdio>1.1.0.Final</version.org.jboss.stdio>
         <version.org.jboss.threads>2.4.0.Final</version.org.jboss.threads>
@@ -251,7 +251,7 @@
         <version.org.jmockit>1.39</version.org.jmockit>
         <version.org.mockito>3.10.0</version.org.mockito>
         <version.org.projectodd.vdx>1.1.6</version.org.projectodd.vdx>
-        <version.org.slf4j>1.7.36</version.org.slf4j>
+        <version.org.slf4j>2.0.4</version.org.slf4j>
         <version.org.syslog4j>0.9.30</version.org.syslog4j>
         <version.org.wildfly.client.config>1.0.1.Final</version.org.wildfly.client.config>
         <version.org.wildfly.common>1.6.0.Final</version.org.wildfly.common>
diff --git a/testsuite/embedded/pom.xml b/testsuite/embedded/pom.xml
index 244db51955..79f6f0ae94 100644
--- a/testsuite/embedded/pom.xml
+++ b/testsuite/embedded/pom.xml
@@ -38,7 +38,7 @@
         <jbossas.ts.dir>${jbossas.ts.integ.dir}/..</jbossas.ts.dir>
         <jbossas.project.dir>${jbossas.ts.dir}</jbossas.project.dir>
         <wildfly.home>${project.basedir}/target/wildfly-core</wildfly.home>
-        <version.ch.qos.logback>1.2.9</version.ch.qos.logback>
+        <version.ch.qos.logback>1.4.5</version.ch.qos.logback>
     </properties>

     <dependencies>

boris-unckel · 2022-11-23T21:01:58Z

@ceki Thanks for checking it. Please don't -Dmaven.test.skip=true but mvn clean install -Dsecurity.manager -DallTests -Dmaven.test.failure.ignore=true >../buildlog.txt 2>&1 The logging subsystem has tests, there are integration tests and some tests are embedded and CLI client relevant, where logging is needed.
It's late today, I'm posting a gist with the result tomorrow, hopefully morning.

ceki · 2022-11-23T23:08:01Z

@boris-unckel I have rerun the tests a second time without the security manager.

I am seeing Slf4jLoggingProfilesTestCase.testProfiles failing. The strange part is that it looks like Slf4jServiceActivator is not being called at all.

boris-unckel · 2022-11-24T05:58:09Z

@boris-unckel Slf4j's LoggerFactory in both version 1.7.x and version 2.0.4 (but not 2.0.3) use the same class loader, i.e. the class loader that loaded the LoggerFactory class to look for the logging implementation. Thus, why would 1.7.36 work in a given context, in this case WildFly, and 2.0.4 fail in the same context?

@ceki Good morning, including the SecurityManager (why do you run without?) it seems down to last one error. It's not about the classloader, you're correct for this part.

* [ERROR] Failures: 
* [ERROR]   Slf4jLoggingProfilesTestCase.testDeploymentConfigurationResource:29->AbstractLoggingProfilesTestCase.testDeploymentConfigurationResource:301->AbstractLoggingProfilesTe* stCase.deploy:321->AbstractLoggingProfilesTestCase.deploy:332->AbstractLoggingTestCase.deploy:210 Failed to deploy logging1.jar: 10 assets: {"WFLYCTL0080: Failed services" => {"* jboss.deployment.unit.\"logging1.jar\".INSTALL" => "WFLYSRV0153: Failed to process phase INSTALL of deployment \"logging1.jar\"
      Caused by: java.util.ServiceConfigurationError: org.jboss.msc.service.ServiceActivator: Provider org.jboss.as.test.integration.logging.profiles.Slf4jServiceActivator could n  ot be instantiated
      Caused by: java.lang.ExceptionInInitializerError
      Caused by: java.lang.IllegalStateException: org.slf4j.LoggerFactory in failed state. Original exception was thrown EARLIER. See also https://www.slf4j.org/codes.html#unsucce  ssfulInit"}}
* [ERROR]   Slf4jLoggingProfilesTestCase.testProfiles:29->AbstractLoggingProfilesTestCase.testProfiles:202->AbstractLoggingProfilesTestCase.deploy:321->AbstractLoggingProfilesTest* Case.deploy:332->AbstractLoggingTestCase.deploy:210 Failed to deploy logging1.jar: 10 assets: {"WFLYCTL0080: Failed services" => {"jboss.deployment.unit.\"logging1.jar\".INSTALL* " => "WFLYSRV0153: Failed to process phase INSTALL of deployment \"logging1.jar\"
      Caused by: java.util.ServiceConfigurationError: org.jboss.msc.service.ServiceActivator: Provider org.jboss.as.test.integration.logging.profiles.Slf4jServiceActivator could n  ot be instantiated
      Caused by: java.lang.ExceptionInInitializerError
      Caused by: java.lang.IllegalStateException: Unexpected initialization failure
      Caused by: java.security.AccessControlException: WFSM000001: Permission check failed (permission \"(\"java.io.FilePermission\" \"/home/borisunckel/.m2/repository/org/jboss/s  lf4j/slf4j-jboss-logmanager/1.2.1.Final-SNAPSHOT/slf4j-jboss-logmanager-1.2.1.Final-SNAPSHOT.jar\" \"read\")\" in code source \"(vfs:/content/logging1.jar <no signer certificate  s>)\" of \"ModuleClassLoader for Module \"deployment.logging1.jar\" from Service Module Loader\")"}}

and I assume it fails due to this change, removing the privileged action: 43a3630#diff-204f23f1c787a5f1f6162f79eae7d8694d723ef7788e23b79ed270a15c677b00L108-L111

I am seeing Slf4jLoggingProfilesTestCase.testProfiles failing. The strange part is that it looks like Slf4jServiceActivator is not being called at all.

My guess is <version.org.jboss.slf4j.slf4j-jboss-logmanager>1.2.1.Final-SNAPSHOT is Maven central/JBoss public rep based, correct? And the following PR is missing, I have tested with a locally built version: jboss-logging/slf4j-jboss-logmanager#16

Some background information regarding the Security Manager, modules and PriviligedAction use: https://docs.wildfly.org/27/WildFly_Elytron_Security.html#Elytron_JSM_Further_Background

ceki · 2022-11-24T14:00:53Z

The version of slf4j-jboss-logmanager I am using is from https://github.com/boris-unckel/slf4j-jboss-logmanager/

The git log command yields the following output:

Author: boris-unckel <bu.githubcom@mail.unckel.net>
Date:   Fri Sep 23 17:56:20 2022 +0200

    [JBLOGGING-165] Upgrade slf4j 2.0.4

    Fixes https://issues.redhat.com/browse/JBLOGGING-165
[cut]

So it looks like I am using the same version of slf4j-jboss-logmanager.

boris-unckel · 2022-11-24T16:48:08Z

@ceki I have tested mvn clean install -DallTests -Dsecurity.manager -Dmaven.test.failure.ignore=true >../2022-11-23_2131.txt 2>&1 leading to the error described above: #304 (comment)

and mvn clean install -DallTests -Dmaven.test.failure.ignore=true >../2022-11-24_1647.txt 2>&1 which runs without any error. Please turn back to the original patch 06d6c81

ceki · 2022-11-24T17:21:39Z

@boris-unckel Sorry for not having been clearer earlier. I rather not change the class loading behavior of org.slf4j.LoggerFactory without very solid justification.

Given Apache (Jakarta) Commnons-Logging experience, SLF4J was created in 2005 chiefly to avoid class loading problems during logging. It does so by adopting the simplest class loading model possible. Patch 06d6c81 offers a more dynamic model, and from your previous comments, which is apparently not even needed.

As for using SecurityManager that is a different question and I am open to that.

ppkarwasz · 2022-11-24T18:22:02Z

@boris-unckel Sorry for not having been clearer earlier. I rather not change the class loading behavior of org.slf4j.LoggerFactory without very solid justification.

@ceki, the following code does not change the class loading behavior: since the action lambda was created by LoggerFactory, running action is equivalent to calling the function directly. The SecurityManager part is required by WildFly, because the code that initiates SLF4J is not privileged enough to access Logback, while slf4j-api is.

final ClassLoader cl = LoggerFactory.class.getClassLoader();
final PrivilegedAction<ServiceLoader<SLF4JServiceProvider>> action = () -> ServiceLoader.load(SLF4JServiceProvider.class, cl);
final ServiceLoader<SLF4JServiceProvider> serviceLoader = System.getSecurityManager() != null
    ? AccessController.doPrivileged(action)
     : action.run();

I am far from being an expert on SecurityManager, but I believe that Boris known what he is doing.

boris-unckel · 2022-11-24T18:22:57Z

@ceki Yes, sure. It was meant only regarding the Security Manager, the ClassLoading works as the tests have shown.
@ppkarwasz thanks for the snipplet

ceki · 2022-11-24T18:29:26Z

Cool. We are all in agreement then.

boris-unckel · 2022-11-24T18:45:20Z

@ceki Just to be sure: You're preparing the fix? Or do you expect a PR?

ceki · 2022-11-24T18:49:33Z

I am preparing a fix.

boris-unckel · 2022-11-24T18:52:14Z

Thanks to you both for all your support.

ceki · 2022-11-24T19:13:44Z

@boris-unckel Can you please verify that 3bc58f3 committed a few moments ago works as expected?

boris-unckel · 2022-11-24T19:36:27Z

@ceki Thanks, I have prepared a local snapshot build and the test is running right now. I'm going to give a status with the result tomorrow morning.

boris-unckel · 2022-11-25T07:24:47Z

@ceki The test run completed successfully. Thanks for your ongoing support to get this solved.

ppkarwasz force-pushed the service-loader branch from 2e26cf7 to 06d6c81 Compare September 2, 2022 21:17

ceki merged commit 557bf7c into qos-ch:master Nov 17, 2022

ppkarwasz deleted the service-loader branch November 17, 2022 20:54

mst-ableton mentioned this pull request Nov 28, 2022

Bump slf4j-api from 2.0.4 to 2.0.5 Ableton/groovylint#305

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[SLF4J-548] Fix ServiceLoader usage in servlet environment #304

[SLF4J-548] Fix ServiceLoader usage in servlet environment #304

ppkarwasz commented Sep 2, 2022

ceki commented Sep 28, 2022 •

edited

ppkarwasz commented Sep 28, 2022

ceki commented Sep 28, 2022

boris-unckel commented Oct 11, 2022

ceki commented Oct 11, 2022 •

edited

ppkarwasz commented Oct 11, 2022 •

edited

boris-unckel commented Oct 12, 2022

ceki commented Oct 12, 2022

boris-unckel commented Nov 5, 2022

ceki commented Nov 5, 2022

ceki commented Nov 17, 2022

boris-unckel commented Nov 22, 2022

ceki commented Nov 22, 2022

ppkarwasz commented Nov 22, 2022

boris-unckel commented Nov 22, 2022

ceki commented Nov 22, 2022 •

edited

ceki commented Nov 23, 2022 •

edited

boris-unckel commented Nov 23, 2022

ceki commented Nov 23, 2022 •

edited

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022 •

edited

ppkarwasz commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022 •

edited

boris-unckel commented Nov 24, 2022

boris-unckel commented Nov 25, 2022

[SLF4J-548] Fix ServiceLoader usage in servlet environment #304

[SLF4J-548] Fix ServiceLoader usage in servlet environment #304

Conversation

ppkarwasz commented Sep 2, 2022

ceki commented Sep 28, 2022 • edited

ppkarwasz commented Sep 28, 2022

ceki commented Sep 28, 2022

boris-unckel commented Oct 11, 2022

ceki commented Oct 11, 2022 • edited

ppkarwasz commented Oct 11, 2022 • edited

boris-unckel commented Oct 12, 2022

ceki commented Oct 12, 2022

boris-unckel commented Nov 5, 2022

ceki commented Nov 5, 2022

ceki commented Nov 17, 2022

boris-unckel commented Nov 22, 2022

ceki commented Nov 22, 2022

ppkarwasz commented Nov 22, 2022

boris-unckel commented Nov 22, 2022

ceki commented Nov 22, 2022 • edited

ceki commented Nov 23, 2022 • edited

boris-unckel commented Nov 23, 2022

ceki commented Nov 23, 2022 • edited

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022 • edited

ppkarwasz commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022

boris-unckel commented Nov 24, 2022

ceki commented Nov 24, 2022 • edited

boris-unckel commented Nov 24, 2022

boris-unckel commented Nov 25, 2022

ceki commented Sep 28, 2022 •

edited

ceki commented Oct 11, 2022 •

edited

ppkarwasz commented Oct 11, 2022 •

edited

ceki commented Nov 22, 2022 •

edited

ceki commented Nov 23, 2022 •

edited

ceki commented Nov 23, 2022 •

edited

ceki commented Nov 24, 2022 •

edited

ceki commented Nov 24, 2022 •

edited