search

qos-ch / slf4j

Simple Logging Facade for Java
http://www.slf4j.org
MIT License
2.35k stars 990 forks source link

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

Closed ppkarwasz closed 2 years ago

ppkarwasz commented 2 years ago

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.

ceki commented 2 years ago

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

ppkarwasz commented 2 years ago

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

ceki commented 2 years ago

@ppkarwasz Indeed, thank you.

boris-unckel commented 2 years ago

@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 commented 2 years ago

@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 1) invokes AccessController.doPrivileged if a SecurityManager is present 2) 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 commented 2 years ago

@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 commented 2 years ago

Hello @ceki ,

steps to reproduce:

General: setup latest Maven and a Java 11 environment 1) clone and build https://github.com/boris-unckel/slf4j-jboss-logmanager/tree/JBLOGGING-165_upgrade_slf4j2 with mvn clean install 2) 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 3) 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 ) 4) upgrade pom.xml line 256 (version.org.slf4j) to 2.0.2 ( https://github.com/wildfly/wildfly-core/blob/main/pom.xml#L256 ) 5) 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 ) 5) 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 commented 2 years ago

@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 commented 2 years ago

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

ceki commented 2 years ago

@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 commented 2 years ago

@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 commented 2 years ago

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 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 commented 2 years ago

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

ppkarwasz commented 2 years ago

@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 commented 2 years ago

@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 commented 2 years ago

@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 commented 2 years ago

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 commented 2 years ago

@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 commented 2 years ago

@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 commented 2 years ago

@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: https://github.com/qos-ch/slf4j/commit/43a36303e5a2338c22ec9aad5b01a401034eb553#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: https://github.com/jboss-logging/slf4j-jboss-logmanager/pull/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 commented 2 years ago

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 commented 2 years ago

@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: https://github.com/qos-ch/slf4j/pull/304#issuecomment-1325990974

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 https://github.com/qos-ch/slf4j/pull/304/commits/06d6c81cbcbe4a8d3844cccd09d471f95029a987

ceki commented 2 years ago

@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 06d6c81c 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 commented 2 years ago

@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 commented 2 years ago

@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 commented 2 years ago

Cool. We are all in agreement then.

boris-unckel commented 2 years ago

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

ceki commented 2 years ago

I am preparing a fix.

boris-unckel commented 2 years ago

Thanks to you both for all your support.

ceki commented 2 years ago

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

boris-unckel commented 2 years ago

@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 commented 2 years ago

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

prrvchr commented 4 months ago

Thanks for making the SLF4J API embeddable in a jar archive...