Some webapps fail with "Class org.apache.juli.logging.impl.SLF4JLogFactory does not implement org.apache.commons.logging.LogFactory" about tomcat-slf4j-logback HOT 14 CLOSED

What version of tomcat and this library are being used?

Sent by Outlook for Android

On Fri, Sep 18, 2015 at 2:37 PM -0700, "Andreas Ntaflos" [email protected] wrote:
This is not directly related to this project but I figure this is a good place to possibly get some insight :)

We have some webapps that, when deployed in a Tomcat instance that uses Logback for logging (using this project's excellent efforts), fail with exceptions like this:

org.apache.commons.discovery.DiscoveryException:
  Class org.apache.juli.logging.impl.SLF4JLogFactory does not implement \
  org.apache.commons.logging.LogFactory

We have to set this Java property for these webapps to work again:

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

These webapps usually use Log4j (e.g. log4j-1.2.17.jar) and SLF4j (e.g. slf4j-api-1.7.5.jar and sometimes slf4j-log4j12-1.7.5.jar) internally for logging, but are not really similar in any special way. Some include commons-logging-1.1.jar or commons-logging-1.0.4.jar and others include nothing related to commons-logging.

Do you have an idea what these webapps are doing wrong (if anything) or what they are missing in order to work correctly with a Tomcat instance that uses Logback internally? Or is setting the above property really the solution?

Reply to this email directly or view it on GitHub:
#72

from tomcat-slf4j-logback.

Sorry, should have mentioned that of course.

Tomcat 7.0.64, using tomcat-juli-7.0.64-slf4j-1.7.12-logback-1.1.3.zip from here. Java 7 (1.7.0_80-b15) and Java 8 (1.8.0_45-b14, a bit out of date), doesn't seem to make a difference.

Running on Ubuntu 12.04 and 14.04.

from tomcat-slf4j-logback.

Juli wraps commos-logging both in the original tomcat-juli and this library in order to avoid classloading issues with loggers thus allowing users to use other loggers. I'm not exactly sure how this specific item is occuring unless there was another logging library dropped in the bin directory and/or other loggers dropped in tomcat lib directory. The issue is pretty well documented when mixing loggers with duplicate class path elements under webapps or tomcat lib so I sort of expect there are too many loggers at play. Can you confirm no other loggers in bin/lib? And can you repeat this easily?

from tomcat-slf4j-logback.

Thanks for following up on this, much appreciated! We run multiple instances of Tomcat, i.e. we separate CATALINA_HOME and CATALINA_BASE, but in neither of these does the lib or bin directory contain other loggers, as far as I can tell. Here is the output of ls -la for the relevant directories, just to be sure (CATALINA_HOME is /opt/tomcat7 and CATALINA_BASE is /opt/tomcats/foo-instance for the Tomcat instance in question):

/opt/tomcat7/bin:
total 1588
drwxr-xr-x 2 root root   4096 Sep 21 09:30 .
drwxr-xr-x 6 root root   4096 Sep  7 18:42 ..
-rw-r--r-- 1 root root  28064 Sep  7 19:06 bootstrap.jar
-rw-r--r-- 1 root root  13007 Sep  7 19:06 catalina.bat
-rwxr-xr-x 1 root root  20909 Sep  7 19:06 catalina.sh
-rw-r--r-- 1 root root   1647 Sep  7 19:06 catalina-tasks.xml
-rw-r--r-- 1 root root  24283 Sep  7 19:06 commons-daemon.jar
-rw-r--r-- 1 root root 204944 Sep  7 19:06 commons-daemon-native.tar.gz
-rw-r--r-- 1 root root   2040 Sep  7 19:06 configtest.bat
-rwxr-xr-x 1 root root   1922 Sep  7 19:06 configtest.sh
-rwxr-xr-x 1 root root   7888 Sep  7 19:06 daemon.sh
-rw-r--r-- 1 root root   2091 Sep  7 19:06 digest.bat
-rwxr-xr-x 1 root root   1965 Sep  7 19:06 digest.sh
-rw-r--r-- 1 root root   3430 Sep  7 19:06 setclasspath.bat
-rwxr-xr-x 1 root root   3547 Sep  7 19:06 setclasspath.sh
-rw-r--r-- 1 root root   2020 Sep  7 19:06 shutdown.bat
-rwxr-xr-x 1 root root   1902 Sep  7 19:06 shutdown.sh
-rw-r--r-- 1 root root   2022 Sep  7 19:06 startup.bat
-rwxr-xr-x 1 root root   1904 Sep  7 19:06 startup.sh
-rw-r--r-- 1 root root 848835 Sep  7 19:06 tomcat-juli.jar
-rw-r--r-- 1 root root 388787 Sep  7 19:06 tomcat-native.tar.gz
-rw-r--r-- 1 root root   4021 Sep  7 19:06 tool-wrapper.bat
-rwxr-xr-x 1 root root   5024 Sep  7 19:06 tool-wrapper.sh
-rw-r--r-- 1 root root   2026 Sep  7 19:06 version.bat
-rwxr-xr-x 1 root root   1908 Sep  7 19:06 version.sh

/opt/tomcat7/lib:
total 10524
drwxr-xr-x 2 root root    4096 Sep 21 09:30 .
drwxr-xr-x 6 root root    4096 Sep  7 18:42 ..
-rw-r--r-- 1 root root   15979 Sep  7 19:06 annotations-api.jar
-rw-r--r-- 1 root root  119683 Sep  7 18:34 aspectjrt.jar
-rw-r--r-- 1 root root 1850391 Sep  7 18:34 aspectjweaver.jar
-rw-r--r-- 1 root root   54970 Sep  7 19:06 catalina-ant.jar
-rw-r--r-- 1 root root  131028 Sep  7 19:06 catalina-ha.jar
-rw-r--r-- 1 root root 1637803 Sep  7 19:06 catalina.jar
-rw-r--r-- 1 root root  260203 Sep  7 19:06 catalina-tribes.jar
-rw-r--r-- 1 root root 2310271 Sep  7 19:06 ecj-4.4.2.jar
-rw-r--r-- 1 root root   55535 Sep  7 19:06 el-api.jar
-rw-r--r-- 1 root root  124750 Sep  7 19:06 jasper-el.jar
-rw-r--r-- 1 root root  600156 Sep  7 19:06 jasper.jar
-rw-r--r-- 1 root root   87805 Sep  7 19:06 jsp-api.jar
-rw-r--r-- 1 root root  101994 Sep  7 19:06 logback-access-1.1.3.jar
-rw-r--r-- 1 root root  455041 Sep  7 19:06 logback-core-1.1.3.jar
-rw-r--r-- 1 root root  521157 Sep  7 19:06 mail-1.4.7.jar
-rw-r--r-- 1 root root  592322 Sep  7 19:06 postgresql-9.3-1102.jdbc41.jar
-rw-r--r-- 1 root root  198039 Sep  7 19:06 servlet-api.jar
-rw-r--r-- 1 root root  212231 Sep  7 19:06 tomcat7-websocket.jar
-rw-r--r-- 1 root root    6522 Sep  7 19:06 tomcat-api.jar
-rw-r--r-- 1 root root  789850 Sep  7 19:06 tomcat-coyote.jar
-rw-r--r-- 1 root root  234043 Sep  7 19:06 tomcat-dbcp.jar
-rw-r--r-- 1 root root   71864 Sep  7 19:06 tomcat-i18n-es.jar
-rw-r--r-- 1 root root   43793 Sep  7 19:06 tomcat-i18n-fr.jar
-rw-r--r-- 1 root root   47036 Sep  7 19:06 tomcat-i18n-ja.jar
-rw-r--r-- 1 root root  127334 Sep  7 19:06 tomcat-jdbc.jar
-rw-r--r-- 1 root root   31948 Sep  7 19:06 tomcat-util.jar
-rw-r--r-- 1 root root   36271 Sep  7 19:06 websocket-api.jar

$ ls -la /opt/tomcats/foo-instance/{bin,lib}
/opt/tomcats/foo-instance/bin:
total 12
drwxr-xr-x 2 root root 4096 Sep 15 16:37 .
drwxr-xr-x 9 root root 4096 Sep  7 18:37 ..
-rwxr-xr-x 1 root root  432 Sep 15 16:37 setenv.sh

/opt/tomcats/foo-instance/lib:
total 8
drwxr-xr-x 2 root root 4096 Sep 11 17:52 .
drwxr-xr-x 9 root root 4096 Sep  7 18:37 ..

As you can see we package JavaMail (mail-1.4.7.jar) and the JDBC drivers for Postgres as well, but I don't think that should make any difference, should it?

The Java commandline for this Tomcat instance looks like this:

/usr/lib/jvm/java-8-oracle/bin/java -Dnop -Dnop -Dapp=foo-app -Dhostname=dev03 \
-javaagent:/opt/tomcat7/lib/aspectjweaver.jar -Djava.awt.headless=true \
-Djuli-logback.configurationFile=file:/opt/tomcat7/conf/logback.xml \
-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl \
-Xms128m -Xmx384m -XX:MaxPermSize=256m -XX:MaxMetaspaceSize=128m \
-Djava.endorsed.dirs=/opt/tomcat7/endorsed -classpath \
/opt/tomcat7/bin/bootstrap.jar:/opt/tomcat7/bin/tomcat-juli.jar \
-Dcatalina.base=/opt/tomcats/foo-instance \
-Dcatalina.home=/opt/tomcat7 \
-Djava.io.tmpdir=/opt/tomcats/foo-instance/temp org.apache.catalina.startup.Bootstrap start

Once I remove the property

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

I get exceptions like this as soon as a request is being processed by the Tomcat instance:

2015-09-11T18:34:18.941 [INFO ] [apr-8080-exec-1] [o.a.c.c.C.[.[.[/ringring]     ] Marking servlet AxisServlet as unavailable
2015-09-11T18:34:18.961 [ERROR] [apr-8080-exec-1] [o.a.c.c.C.[.[.[.[AxisServlet] ] Allocate exception for servlet AxisServlet
org.apache.commons.discovery.DiscoveryException: Class org.apache.juli.logging.impl.SLF4JLogFactory does not implement org.apache.commons.logging.LogFactory
        at org.apache.commons.discovery.tools.ClassUtils.verifyAncestory(ClassUtils.java:180) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.commons.discovery.tools.SPInterface.verifyAncestory(SPInterface.java:201) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.commons.discovery.tools.SPInterface.newInstance(SPInterface.java:195) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.commons.discovery.tools.DiscoverClass.newInstance(DiscoverClass.java:579) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.commons.discovery.tools.DiscoverSingleton.find(DiscoverSingleton.java:418) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.commons.discovery.tools.DiscoverSingleton.find(DiscoverSingleton.java:378) ~[commons-discovery-0.2.jar:0.2]
        at org.apache.axis.components.logger.LogFactory$1.run(LogFactory.java:45) ~[axis.jar:na]
        at java.security.AccessController.doPrivileged(Native Method) ~[na:1.7.0_25]
...

Once I add the property again everything seems to work, but I am not quite sure what the implications of setting the LogFactory property this way are (as you can tell I am not really a Java developer).

Does this help in any way?

from tomcat-slf4j-logback.

Hm, I may have found something after reading in META-INF/services/org.apache.commons.logging.LogFactory in tomcat-juli.jar that "Axis gets at JCL through its own mechanism as defined by Commons Discovery", which lead me to Alfresco/alfresco-sdk#150.

It seems that adding jcl-over-slf4j-1.6.4.jar to the problematic webapp in question does the trick and I no longer need to set the LogFactory property from above. The webapps seems to log correctly (using Log4j and SLF4j) and I get no exceptions from Axis or Commons Discovery.

Does that make sense? Should we instruct our developers to start packaging jcl-over-slf4j with their webapps? Or is this just a workaround for the symptom and not the solution for the actual problem?

from tomcat-slf4j-logback.

Sounds like axis is crossing boundaries. That looks like axis 1. Commons Digester comes as 0.2 with that version. Axis sucks. It's from 2006 if you happen to be on 1.4 and it's chuck full of vulnerabilties. I'd suggest upgrading to CXF. I know that isn't the easiest pill to swallow but even if this was Axis2, I'd give the same advice. You certainly could use the above solution if Axis works when that is done but it won't be needed anywhere but where commons digester is used. I would first though suggest upgrading commons digester to the last version 0.5. I used to work with axis and from what I recall that version works. It's possible the issue is fixed by that alone but I don't know for sure as I didn't start using this library until after we migrated to java metro stack back in 2011. However, that is exactly what we are doing as well and class paths are isolated so axis / digester should have never been looking there. Anyway, I don't see much jumping out at me in your configuration but I do see some things that certainly could impact performance. -Xms128m -Xmx384m --> These settings should be the same for a server so it doesn't cause reallocation which will slow down processing. These are really low. I've ran tomcat successfuly on not much more (222mb) so I know that is possible but the max perm space is all wrong with the current settings. If you are running on a system that has available resources, I would bump that to 512mb for both xms and xmx. Considering your max perm is at 256mb that would spell major issues later but would be fine if you bumped memory to 512mb as it would fit the correct setting requirements. It should be somewhere between 1/4 to 1/2 of your max memory. Other thing that can be cleaned up is to remove -Dnop from there. It gets added by tomcat so as you can see two end up in the arguments. We use to suggest adding that which ultimately became obsolete over time.

Couple of other things. If you are not using internationalization of tomcat for the 3 extras they provide you can delete those (i18n). I'd bump java mail up to 1.5.4 if you can. It's backwards compatable. I'd also drop annotatons api and el-api and use the ones provided from java. Use the two from the EE7 stack given you are there.

I'd at least try some of the above although I didn't give a direct fix I think you will like the stability tomcat gains otherwise by making some of those changes.

from tomcat-slf4j-logback.

Thank you so much for the insightful comments, and sorry for following up so late (I was on vacation)!

It is good to know that Axis seems to be the culprit here, and not our modified Tomcat setup (with SLF4j/Logback). Unfortunately the problematic web apps can almost all be categorised as "legacy" so I don't think I can get the devs to move from Axis to CXF. We'll have to keep using the workaround:

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

For one of the webapps I tested if upgrading commons-discovery to 0.5 helps but it doesn't look like it. I'll keep looking into that.

And thanks for the memory primer! The -Xms and -Xmx settings are not optimal here but this is only a dev machine with no load or anything so we didn't pay much attention to that. Our productive Tomcat instances, however, are all configured properly, much like you suggested.

I'll update Java Mail and look into removing the i18n jars, as well as annotations and el-api.

Not sure about the -Dnop thing, though. It comes from us setting LOGGING_MANAGER=-Dnop for our Tomcat instances and Tomcat itself also sets LOGGING_CONFIG: when "$CATALINA_BASE"/conf/logging.properties exists then LOGGING_CONFIG="-Djava.util.logging.config.file=$CATALINA_BASE/conf/logging.properties", otherwise LOGGING_CONFIG=-Dnop. In our case there exists no conf/logging.properties so this ends up being -Dnop. The result is two -Dnop in the Java commandline, one from Tomcat (LOGGING_CONFIG) and one from us (LOGGING_MANAGER).

Do you mean to say that it is no longer necessary to set LOGGING_MANAGER=-Dnop? Because Tomcat still has this in catalina.sh:

if [ -z "$LOGGING_MANAGER" ]; then
  LOGGING_MANAGER="-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager"
fi

from tomcat-slf4j-logback.

On -nop we used to mention needing it ourselves and tomcat does it now. So I thought maybe that is why you had two of them. Thanks for explaining that. If the work around otherwise works for you that's great. Maybe on day axis will be gone.

Thanks.

Jeremy

Sent by Outlook for Android

On Thu, Oct 8, 2015 at 10:15 AM -0700, "Andreas Ntaflos" [email protected] wrote:
Thank you so much for the insightful comments, and sorry for following up so late (I was on vacation)!

It is good to know that Axis seems to be the culprit here, and not our modified Tomcat setup (with SLF4j/Logback). Unfortunately the problematic web apps can almost all be categorised as "legacy" so I don't think I can get the devs to move from Axis to CXF. We'll have to keep using the workaround:

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

For one of the webapps I tested if upgrading commons-discovery to 0.5 helps but it doesn't look like it. I'll keep looking into that.

And thanks for the memory primer! The -Xms and -Xmx settings are not optimal here but this is only a dev machine with no load or anything so we didn't pay much attention to that. Our productive Tomcat instances, however, are all configured properly, much like you suggested.

I'll update Java Mail and look into removing the i18n jars, as well as annotations and el-api.

Not sure about the -Dnop thing, though. It comes from us setting LOGGING_MANAGER=-Dnop for our Tomcat instances and Tomcat itself also sets LOGGING_CONFIG: when "$CATALINA_BASE"/conf/logging.properties exists then LOGGING_CONFIG="-Djava.util.logging.config.file=$CATALINA_BASE/conf/logging.properties", otherwise LOGGING_CONFIG=-Dnop. In our case there exists no conf/logging.properties so this ends up being -Dnop. The result is two -Dnop in the Java commandline, one from Tomcat (LOGGING_CONFIG) and one from us (LOGGING_MANAGER).

Do you mean to say that it is no longer necessary to set LOGGING_MANAGER=-Dnop? Because Tomcat still has this in catalina.sh:

if [ -z "$LOGGING_MANAGER" ]; then
  LOGGING_MANAGER="-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager"
fi

Reply to this email directly or view it on GitHub:
#72 (comment)

from tomcat-slf4j-logback.

Work around exists for legacy setup, closing.

from tomcat-slf4j-logback.

@antaflos reopening issue as I discovered we have internally a patch from logback for axis. However, the services file name is listed as 'org.apache.commons.logging.LogFactory' which internally was switching to juli. thus the stack trace you described. I think the services file itself had to be renamed to 'org.apache.juli.loging.LogFactory' instead as all the work around you had was to reset it back to commons logging and in our case we want it to hit slf4j under juli logging. If I submit a patch for this, is this something you might still be able to test? I know it's been forever...

from tomcat-slf4j-logback.

@hazendaz interesting! Yes, I'll probably still be able to test this.

from tomcat-slf4j-logback.

@antaflos The more I look at this the more I think we shouldn't have included that override inside this classloader as it's intended for axis which isn't going to be in this classloader to start with. So I need to research a bit more and check with @grgrzybek as to why that was done in the first place. I'm leaning more now towards simply deleting that piece which I thnk would also solve the issue you encountered.

from tomcat-slf4j-logback.

@grgrzybek Do you recall any reason to pull in the axis patch slf4j team made? After review, I think this doesn't belong in the classloader we use for this project. It makes more sense at tomcat/lib or application/lib where axis would live. I think we just need to delete this. Slf4j recently added another similar feature and again doesn't apply in our classloader so that makes me think the same here. I just want to confirm before I delete it. I did make a patch that might work but I cannot for the life of me see why this is needed at our level.

org.apache.commons.logging.impl.SLF4JLogFactory

# Axis gets at JCL through its own mechanism as defined by Commons Discovery, which
# in turn follows the instructions found at: 
# http://java.sun.com/j2se/1.3/docs/guide/jar/jar.html#Service Provider

from tomcat-slf4j-logback.

@antaflos @grgrzybek I'm going to remove the override from the builds. This doesn't make sense in this classloader and simply shouldn't be applied from slf4j. I will save off a branch in case with a patch to correct it but I don't think this makes sense on the library in our use case. I will close this issue again.

from tomcat-slf4j-logback.