Commons Logging
  1. Commons Logging
  2. LOGGING-114

Silent Swallowing of NoClassDefFoundError

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Duplicate
    • Affects Version/s: 1.1.0
    • Fix Version/s: 1.1.1
    • Labels:
      None
    • Environment:

      Various OSs, in combination with log4j 1.2.14.

      Description

      Hi. I'm using commons logging with log4j; my team ship a library which uses log4j, and some of our clients use it with commons-logging.

      If commons-logging is in its default configuration, and log4j is present but fails to load its configuration with an unhandled exception, the results are pretty nasty:

      • commons-logging silently swallows the exception and logs with something else. If diagnostics are turned on, the message is:
        Could not instantiate Log 'org.apache.commons.logging.impl.Log4JLogger' – java.lang.reflect.InvocationTargetException: null
      • future attempts to use log4j directly get a pretty unhelpful error:
        java.lang.NoClassDefFoundError at org.apache.log4j.Logger.getLogger(Logger.java:117).

      I realise you're trying to deal with a very large number of cases in this code, but it does seem like something better could be done here. If nothing else is possible, at least recognising the InvocationTargetException and pulling out the target exception for the diagnostic log would have helped with tracking this one down.

        Issue Links

          Activity

          Hide
          Malcolm Cleaton added a comment -

          Sorry, distracted.

          Yes, I see that the bad reporting of the InvocationTargetException we set out to fix here is in fact a duplicate of LOGGING-111. I attempted to verify that the latest code exhibited the same behaviour before reporting the problem, but obviously I've suffered a brainfart there, as it's been fixed for some time. Apologies for wasting time with a duplicate issue.

          Show
          Malcolm Cleaton added a comment - Sorry, distracted. Yes, I see that the bad reporting of the InvocationTargetException we set out to fix here is in fact a duplicate of LOGGING-111 . I attempted to verify that the latest code exhibited the same behaviour before reporting the problem, but obviously I've suffered a brainfart there, as it's been fixed for some time. Apologies for wasting time with a duplicate issue.
          Hide
          Dennis Lundberg added a comment -

          That is my current standpoint.
          I was hoping to hear back from Malcolm before closing this as won't fix.

          Show
          Dennis Lundberg added a comment - That is my current standpoint. I was hoping to hear back from Malcolm before closing this as won't fix.
          Hide
          Henri Yandell added a comment -

          Is this issue going to be a 'WONTFIX' then?

          Show
          Henri Yandell added a comment - Is this issue going to be a 'WONTFIX' then?
          Hide
          Dennis Lundberg added a comment -

          Yea, I get line 117 as well if I switch to use a Class.

          With Diagnostic Logging turned on I get the following output, which states that commons-logging was unable to instantiate the log4j logging implementation due to a NoClassDefFoundError: javax/mail/Multipart

          [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Attempting to instantiate 'org.apache.commons.logging.impl.Log4JLogger'
          [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Trying to load 'org.apache.commons.logging.impl.Log4JLogger'
            from classloader sun.misc.Launcher$AppClassLoader@5487165
          [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Class 'org.apache.commons.logging.impl.Log4JLogger' was found at
            'jar:file:/G:/test/LOGGING-114/target/commons-logging-1.1.1-SNAPSHOT.jar!/org/apache/commons/logging/impl/Log4JLogger.class'
          [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Could not instantiate Log 'org.apache.commons.logging.impl.Log4JLogger' --
            java.lang.reflect.InvocationTargetException: null
          [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] ... InvocationTargetException: java.lang.NoClassDefFoundError: javax/mail/Multipart
          
          Show
          Dennis Lundberg added a comment - Yea, I get line 117 as well if I switch to use a Class. With Diagnostic Logging turned on I get the following output, which states that commons-logging was unable to instantiate the log4j logging implementation due to a NoClassDefFoundError: javax/mail/Multipart [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Attempting to instantiate 'org.apache.commons.logging.impl.Log4JLogger' [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Trying to load 'org.apache.commons.logging.impl.Log4JLogger' from classloader sun.misc.Launcher$AppClassLoader@5487165 [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Class 'org.apache.commons.logging.impl.Log4JLogger' was found at 'jar:file:/G:/test/LOGGING-114/target/commons-logging-1.1.1-SNAPSHOT.jar!/org/apache/commons/logging/impl/Log4JLogger.class' [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] Could not instantiate Log 'org.apache.commons.logging.impl.Log4JLogger' -- java.lang.reflect.InvocationTargetException: null [LogFactoryImpl@18426253 from sun.misc.Launcher$AppClassLoader@5487165] ... InvocationTargetException: java.lang.NoClassDefFoundError: javax/mail/Multipart
          Hide
          Malcolm Cleaton added a comment -

          Yes, that's the one. We were getting java.lang.NoClassDefFoundError at org.apache.log4j.Logger.getLogger(Logger.java:117), but I believe that difference is just using a class rather than a string to create the Logger, it's the same underlying error.

          Show
          Malcolm Cleaton added a comment - Yes, that's the one. We were getting java.lang.NoClassDefFoundError at org.apache.log4j.Logger.getLogger(Logger.java:117), but I believe that difference is just using a class rather than a string to create the Logger, it's the same underlying error.
          Hide
          Dennis Lundberg added a comment -

          If I remove the commons-logging.properties file I get this output on the console (same with or without Diagniostic Logging)

          2007-aug-03 16:18:19 TestLogging main
          INFO: commons-logging logs something
          Exception in thread "main" java.lang.NoClassDefFoundError
                  at org.apache.log4j.Logger.getLogger(Logger.java:104)
                  at TestLogging.main(TestLogging.java:27)
          

          You can see here that commons-logging is using java.util.logging instead. But I do get an exception telling me that log4j is missing some class. Is this the message that you are getting as well?

          Show
          Dennis Lundberg added a comment - If I remove the commons-logging.properties file I get this output on the console (same with or without Diagniostic Logging) 2007-aug-03 16:18:19 TestLogging main INFO: commons-logging logs something Exception in thread "main" java.lang.NoClassDefFoundError at org.apache.log4j.Logger.getLogger(Logger.java:104) at TestLogging.main(TestLogging.java:27) You can see here that commons-logging is using java.util.logging instead. But I do get an exception telling me that log4j is missing some class. Is this the message that you are getting as well?
          Hide
          Malcolm Cleaton added a comment -

          > there is a commons-logging.properties file that tells commons-logging to use log4j

          This is the difference. In my case there was no such commons-logging.properties file. I suspect this is what causes a visible error when log4j is unusable.

          Show
          Malcolm Cleaton added a comment - > there is a commons-logging.properties file that tells commons-logging to use log4j This is the difference. In my case there was no such commons-logging.properties file. I suspect this is what causes a visible error when log4j is unusable.
          Hide
          Dennis Lundberg added a comment -

          OK, I've set up a small test project to test this. Here is the java file:

          import org.apache.commons.logging.Log;
          import org.apache.commons.logging.LogFactory;
          import org.apache.log4j.Logger;
          
          public class TestLogging
          {
              public static void main(String[] args) {
                  Log log = LogFactory.getLog(TestLogging.class);
                  log.info("commons-logging logs something");
                  Logger logger = Logger.getLogger("myLog4jLogger");
                  logger.info("log4j logs something");
              }
          }
          

          Log4j is present in the classpath along with commons-logging 1.1 or 1.1.1-SNAPSHOT (I tried both) and there is a commons-logging.properties file that tells commons-logging to use log4j. There is also a log4j.xml file that configures a DailyRollingFileAppender and an SMTPAppender. Neither activation.jar or mail.jar is present.

          However, when I run this I get the following output on the console (with or without Diagnostic Logging):

          Exception in thread "main" org.apache.commons.logging.LogConfigurationException: User-specified log class 'org.apache.commons.logging.impl.Log4JLogger' cannot be found or is not useable.
                  at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:798)
                  at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:601)
                  at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:333)
                  at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:307)
                  at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:645)
                  at TestLogging.main(TestLogging.java:25)
          

          Is that not good enough or am I missing something here?

          If I comment out the SMTPAppender in the configuration file everything works and two log entries are output to the file every time the program runs.

          Show
          Dennis Lundberg added a comment - OK, I've set up a small test project to test this. Here is the java file: import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.log4j.Logger; public class TestLogging { public static void main( String [] args) { Log log = LogFactory.getLog(TestLogging.class); log.info( "commons-logging logs something" ); Logger logger = Logger.getLogger( "myLog4jLogger" ); logger.info( "log4j logs something" ); } } Log4j is present in the classpath along with commons-logging 1.1 or 1.1.1-SNAPSHOT (I tried both) and there is a commons-logging.properties file that tells commons-logging to use log4j. There is also a log4j.xml file that configures a DailyRollingFileAppender and an SMTPAppender. Neither activation.jar or mail.jar is present. However, when I run this I get the following output on the console (with or without Diagnostic Logging): Exception in thread "main" org.apache.commons.logging.LogConfigurationException: User-specified log class 'org.apache.commons.logging.impl.Log4JLogger' cannot be found or is not useable. at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:798) at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:601) at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:333) at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:307) at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:645) at TestLogging.main(TestLogging.java:25) Is that not good enough or am I missing something here? If I comment out the SMTPAppender in the configuration file everything works and two log entries are output to the file every time the program runs.
          Hide
          Malcolm Cleaton added a comment -

          No, the case of an appender which does not exist is handled differently by log4j. It has to be an appender which exists but causes an Error when created, the most common of which is a NoClassDefFoundError when dependent classes are missing. However, any error will do, so an alternative way to test would be to create a trivial appender which raises an error whenever instantiated.

          Yes, if you just want to check that JCL is writing an appropriate error when log4j configuration fails, there's no need to exercise log4j to test this, obviously. Exercising log4j directly is only necessary if you want to reproduce the original problem.

          Show
          Malcolm Cleaton added a comment - No, the case of an appender which does not exist is handled differently by log4j. It has to be an appender which exists but causes an Error when created, the most common of which is a NoClassDefFoundError when dependent classes are missing. However, any error will do, so an alternative way to test would be to create a trivial appender which raises an error whenever instantiated. Yes, if you just want to check that JCL is writing an appropriate error when log4j configuration fails, there's no need to exercise log4j to test this, obviously. Exercising log4j directly is only necessary if you want to reproduce the original problem.
          Hide
          Simon Kitching added a comment -

          Rather than use smtp appender, presumably the log4j config file could also just reference an appender that doesn't exist, eg "example.no.such.appender".

          However why should log4j be called directly? I thought the problem is that when JCL is called directly and log4j is not yet initialised, this causes log4j to auto-initialise which then fails.
          JCL then silently selects a different logging system where it should at least write a message to the diagnostics.

          Presumably this test would need to catch stderr (ie the diagnostics output) and search that output text for a message stating that log4j was not selected because it failed to initialise.

          The test will need to be careful to restore stderr to its original destination in all situations; it would be awkward if the unit test left stderr redirected

          Another useful test might be to check what happens when the commons-logging.properties file explicitly selects log4j and it fails. I don't actually know what we do in that case (will check...)

          Show
          Simon Kitching added a comment - Rather than use smtp appender, presumably the log4j config file could also just reference an appender that doesn't exist, eg "example.no.such.appender". However why should log4j be called directly? I thought the problem is that when JCL is called directly and log4j is not yet initialised, this causes log4j to auto-initialise which then fails. JCL then silently selects a different logging system where it should at least write a message to the diagnostics. Presumably this test would need to catch stderr (ie the diagnostics output) and search that output text for a message stating that log4j was not selected because it failed to initialise. The test will need to be careful to restore stderr to its original destination in all situations; it would be awkward if the unit test left stderr redirected Another useful test might be to check what happens when the commons-logging.properties file explicitly selects log4j and it fails. I don't actually know what we do in that case (will check...)
          Hide
          Malcolm Cleaton added a comment -

          Yes.

          Your steps should successfully reproduce a situation where log4j is screwed up, but you won't see any errors until you try to exercise it. In order to exercise it you'll have to do it directly, as commons logging will have given up on log4j and be using something else by now.

          Just creating a log4j logger with Logger.getLogger should do it. But make sure not to do this until after logging something with commons logging.

          Show
          Malcolm Cleaton added a comment - Yes. Your steps should successfully reproduce a situation where log4j is screwed up, but you won't see any errors until you try to exercise it. In order to exercise it you'll have to do it directly, as commons logging will have given up on log4j and be using something else by now. Just creating a log4j logger with Logger.getLogger should do it. But make sure not to do this until after logging something with commons logging.
          Hide
          Dennis Lundberg added a comment -

          I'm going to try to set up a test case for this issue. Do you think that this setup would reproduce this problem:

          • Create a small java class that uses commons logging
          • Put log4j in the class path
          • Put a valid configuration for log4j in the class path, that tries to use an smtp appender, which requires activation.jar and mail.jar to be present in the class path
          • Do not put activation.jar and mail.jar in the class path
          • Log a message using commons logging

          After this do I also need to

          • call log4j directly?
          Show
          Dennis Lundberg added a comment - I'm going to try to set up a test case for this issue. Do you think that this setup would reproduce this problem: Create a small java class that uses commons logging Put log4j in the class path Put a valid configuration for log4j in the class path, that tries to use an smtp appender, which requires activation.jar and mail.jar to be present in the class path Do not put activation.jar and mail.jar in the class path Log a message using commons logging After this do I also need to call log4j directly?
          Hide
          Malcolm Cleaton added a comment -

          Dennis: Commons-logging is entirely in its default configuration, no properties are provided. Yes, I'm sure commons-logging is the first to initialize log4j. log4j doesn't print any messages, but it's not the case that it can't find its configuration file. It finds the file, and fails with a NoClassDefFoundError while trying to instantiate the appenders specified in the file. The log4j code doesn't handle this error, so it doesn't print anything, just allows the error to propagate.

          Simon: Yes, I agree that's probably the only fix you can make, although it's unfortunate that this means the JCL dynamic discovery mechanism can leave anything it fails to load in a broken state, causing very difficult debugging later on. In our case, JCL was being used by our client for very basic logging, so the fact that their logging of our startup error was coming out of the jdk 1.4 logging library rather than log4j made almost no visible difference and was not noticed. Once we'd ruled out the famous classloader problems early on, it took quite a while before JCL came back under suspicion - we didn't realise it could also cause this kind of problem. Better information in the diagnostic log would indeed be an improvement - but once we'd turned on diagnostics and had that exception with the bad message, we were very near the end of our debugging journey.

          I've also raised a bug on log4j, suggesting that, since they already print on stderr when there's no logging configuration, they could also do so when the clinit of LogManager is about to die: http://issues.apache.org/bugzilla/show_bug.cgi?id=42855.

          Show
          Malcolm Cleaton added a comment - Dennis: Commons-logging is entirely in its default configuration, no properties are provided. Yes, I'm sure commons-logging is the first to initialize log4j. log4j doesn't print any messages, but it's not the case that it can't find its configuration file. It finds the file, and fails with a NoClassDefFoundError while trying to instantiate the appenders specified in the file. The log4j code doesn't handle this error, so it doesn't print anything, just allows the error to propagate. Simon: Yes, I agree that's probably the only fix you can make, although it's unfortunate that this means the JCL dynamic discovery mechanism can leave anything it fails to load in a broken state, causing very difficult debugging later on. In our case, JCL was being used by our client for very basic logging, so the fact that their logging of our startup error was coming out of the jdk 1.4 logging library rather than log4j made almost no visible difference and was not noticed. Once we'd ruled out the famous classloader problems early on, it took quite a while before JCL came back under suspicion - we didn't realise it could also cause this kind of problem. Better information in the diagnostic log would indeed be an improvement - but once we'd turned on diagnostics and had that exception with the bad message, we were very near the end of our debugging journey. I've also raised a bug on log4j, suggesting that, since they already print on stderr when there's no logging configuration, they could also do so when the clinit of LogManager is about to die: http://issues.apache.org/bugzilla/show_bug.cgi?id=42855 .
          Hide
          Dennis Lundberg added a comment -

          Malcolm,

          Just so I understand your setup fully:

          Do you configure commons-logging in any way? Either via a system property or through the use of a commons-logging.properties file? If yes, please tell us how.

          Do you get any message from log4j, saying that it couldn't find its configuration file? If yes, what does it say.

          Are you sure that your code that uses commons logging is the one that causes log4j to be loaded? Or could it be that the other library of yours, that use log4j directly, is the first user?

          Show
          Dennis Lundberg added a comment - Malcolm, Just so I understand your setup fully: Do you configure commons-logging in any way? Either via a system property or through the use of a commons-logging.properties file? If yes, please tell us how. Do you get any message from log4j, saying that it couldn't find its configuration file? If yes, what does it say. Are you sure that your code that uses commons logging is the one that causes log4j to be loaded? Or could it be that the other library of yours, that use log4j directly, is the first user?
          Hide
          Simon Kitching added a comment -

          JCL has adopted the principle that logging problems should never stop an app from running. In the past exceptions from logging libs were allowed through JCL in some cases and there were loud user complaints. In many cases, the users didn't actually want logging output anyway, and didn't know how to fix the logging problems because they were complex and involved classloaders with different classpaths etc. So now, JCL never fails to init. In particular, if log4j is present but cannot be initialised (eg due to classloader problems) JCL quite deliberately ignores this problem and lets the app start.

          If someone really does want logging output but aren't getting what they expect then they can turn on JCL diagnostic output to see what's happening.

          I don't think there is likely to be agreement for any change to JCL's behaviour for this.

          Writing problems stuff to stdout etc is also unacceptable when diagnostics are not enabled. Again, this can cause problems for users who don't actually care about logging output anyway.

          However I would agree that when diagnostics are enabled, JCL should write out the message from the original exception. If it's not doing this then I would call that a bug.

          Show
          Simon Kitching added a comment - JCL has adopted the principle that logging problems should never stop an app from running. In the past exceptions from logging libs were allowed through JCL in some cases and there were loud user complaints. In many cases, the users didn't actually want logging output anyway, and didn't know how to fix the logging problems because they were complex and involved classloaders with different classpaths etc. So now, JCL never fails to init. In particular, if log4j is present but cannot be initialised (eg due to classloader problems) JCL quite deliberately ignores this problem and lets the app start. If someone really does want logging output but aren't getting what they expect then they can turn on JCL diagnostic output to see what's happening. I don't think there is likely to be agreement for any change to JCL's behaviour for this. Writing problems stuff to stdout etc is also unacceptable when diagnostics are not enabled. Again, this can cause problems for users who don't actually care about logging output anyway. However I would agree that when diagnostics are enabled, JCL should write out the message from the original exception. If it's not doing this then I would call that a bug.
          Hide
          Joerg Schaible added a comment -

          IMHO this is really a JCL problem. It detects log4j and tries to use it. It is fine that it searches for something else if log4j is not present. But here it even suppresses a thrown Error that indicates also a problem for JCL. From user's PoV either the presence of log4j was not expected at all, he failed to configure to Log4J or he failed to configure JCL. In any case he must realize that something is not working as expected.

          Show
          Joerg Schaible added a comment - IMHO this is really a JCL problem. It detects log4j and tries to use it. It is fine that it searches for something else if log4j is not present. But here it even suppresses a thrown Error that indicates also a problem for JCL. From user's PoV either the presence of log4j was not expected at all, he failed to configure to Log4J or he failed to configure JCL. In any case he must realize that something is not working as expected.
          Hide
          Malcolm Cleaton added a comment -

          Hi Dennis.

          Yes, log4j does usually tell you when it cannot load its configuration. In this case it tells me through a NoClassDefFoundError when runtime dependencies fail to load during configuration loading. If commons-logging is not in use, the error is easy to understand and quickly fixed.

          Unfortunately, if commons-logging is the first to try to load log4j, the error is swallowed silently. Since it is a problem during the clinint of the LogManager class, log4j is now broken internally and will not give good errors again - any future use gets incomprehensible errors. What's more, if commons-logging diagnostics are enabled, the diagnostic error is logged with most of the information missing. But I'm repeating myself here, all this is in the bug report, along with the actual messages involved.

          To understand my problem, imagine the other side of it, which will probably shortly be happening - imagine my attempts to file a bug in log4j on the basis that, if a class can't be found during configuration loading, they simply allow the NoClassDefFoundError to propagate. How is that wrong?

          But if you're adamant that silently swallowing this error is also not wrong, it's not their problem and it's not your problem. Where does that leave the user? I guess it's just my problem.

          Show
          Malcolm Cleaton added a comment - Hi Dennis. Yes, log4j does usually tell you when it cannot load its configuration. In this case it tells me through a NoClassDefFoundError when runtime dependencies fail to load during configuration loading. If commons-logging is not in use, the error is easy to understand and quickly fixed. Unfortunately, if commons-logging is the first to try to load log4j, the error is swallowed silently. Since it is a problem during the clinint of the LogManager class, log4j is now broken internally and will not give good errors again - any future use gets incomprehensible errors. What's more, if commons-logging diagnostics are enabled, the diagnostic error is logged with most of the information missing. But I'm repeating myself here, all this is in the bug report, along with the actual messages involved. To understand my problem, imagine the other side of it, which will probably shortly be happening - imagine my attempts to file a bug in log4j on the basis that, if a class can't be found during configuration loading, they simply allow the NoClassDefFoundError to propagate. How is that wrong? But if you're adamant that silently swallowing this error is also not wrong, it's not their problem and it's not your problem. Where does that leave the user? I guess it's just my problem.
          Hide
          Dennis Lundberg added a comment -

          It is not the job of commons-logging to report on errors regarding the underlying logging implementations failure to configure itself.

          Commons-logging tries its best to send the messages, that the author of a library wants to log, to the logging implementation. Which logging implementation commons-logging sends these messages to is either
          A. configured in commons logging explicitly or
          B. found dynamically

          There is no way for the underlying logging implementation to "tell" commons-logging anything. So if the underlying logging implementation cannot configure itself correctly, as I understand is your situation here, commons-logging can't do much about it. It is the job of log4j, in this case, to tell you that it cannot load its configuration and from my experience it usually does.

          Show
          Dennis Lundberg added a comment - It is not the job of commons-logging to report on errors regarding the underlying logging implementations failure to configure itself. Commons-logging tries its best to send the messages, that the author of a library wants to log, to the logging implementation. Which logging implementation commons-logging sends these messages to is either A. configured in commons logging explicitly or B. found dynamically There is no way for the underlying logging implementation to "tell" commons-logging anything. So if the underlying logging implementation cannot configure itself correctly, as I understand is your situation here, commons-logging can't do much about it. It is the job of log4j, in this case, to tell you that it cannot load its configuration and from my experience it usually does.

            People

            • Assignee:
              Dennis Lundberg
              Reporter:
              Malcolm Cleaton
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development