Author: skitching Date: Sun May 22 03:43:06 2005 New Revision: 171300 URL: http://svn.apache.org/viewcvs?rev=171300&view=rev Log: Added internal diagnostics
Modified: jakarta/commons/proper/logging/trunk/src/java/org/apache/commons/logging/LogFactory.java Modified: jakarta/commons/proper/logging/trunk/src/java/org/apache/commons/logging/LogFactory.java URL: http://svn.apache.org/viewcvs/jakarta/commons/proper/logging/trunk/src/java/org/apache/commons/logging/LogFactory.java?rev=171300&r1=171299&r2=171300&view=diff ============================================================================== --- jakarta/commons/proper/logging/trunk/src/java/org/apache/commons/logging/LogFactory.java (original) +++ jakarta/commons/proper/logging/trunk/src/java/org/apache/commons/logging/LogFactory.java Sun May 22 03:43:06 2005 @@ -21,6 +21,8 @@ import java.io.IOException; import java.io.InputStream; import java.io.InputStreamReader; +import java.io.PrintStream; +import java.io.FileOutputStream; import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; import java.security.AccessController; @@ -80,6 +82,34 @@ "META-INF/services/org.apache.commons.logging.LogFactory"; /** + * The name of the property used to enable internal commons-logging + * diagnostic output, in order to get information on what logging + * implementations are being discovered, what classloaders they + * are loaded through, etc. + * <p> + * If a system property of this name is set then the value is + * assumed to be the name of a file. The special strings + * STDOUT or STDERR (case-sensitive) indicate output to + * System.out and System.err respectively. + */ + public static final String DIAGNOSTICS_DEST_PROPERTY = + "org.apache.commons.logging.diagnostics.dest"; + + /** + * When null (the usual case), no diagnostic output will be + * generated by LogFactory or LogFactoryImpl. When non-null, + * interesting events will be written to the specified object. + */ + private static PrintStream diagnosticsStream = null; + + /** + * A string that gets prefixed to every message output by the + * logDiagnostic method, so that users can clearly see which + * LogFactory class is generating the output. + */ + private static String diagnosticPrefix; + + /** * <p>Setting this system property value allows the <code>Hashtable</code> used to store * classloaders to be substituted by an alternative implementation. * </p> @@ -133,10 +163,9 @@ /** * Protected constructor that is not available for public use. */ - protected LogFactory() { + protected LogFactory() { } - - + // --------------------------------------------------------- Public Methods @@ -247,6 +276,21 @@ */ protected static LogFactory nullClassLoaderFactory = null; + /** + * Create the hashtable which will be used to store a map of + * (context-classloader -> logfactory-object). Version 1.2+ of Java + * supports "weak references", allowing a custom Hashtable class + * to be used which uses only weak references to its keys. Using weak + * references can fix memory leaks on webapp unload in some cases (though + * not all). Version 1.1 of Java does not support weak references, so we + * must dynamically determine which we are using. And just for fun, this + * code also supports the ability for a system property to specify an + * arbitrary Hashtable implementation name. + * <p> + * Note that the correct way to ensure no memory leaks occur is to ensure + * that LogFactory.release(contextClassLoader) is called whenever a + * webapp is undeployed. + */ private static final Hashtable createFactoryStore() { Hashtable result = null; String storeImplementationClass @@ -260,9 +304,16 @@ } catch (Throwable t) { // ignore - if (!WEAK_HASHTABLE_CLASSNAME.equals(storeImplementationClass)) { - // if the user's trying to set up a custom implementation, give a clue - System.err.println("[ERROR] LogFactory: Load of custom hashtable failed"); + if (!WEAK_HASHTABLE_CLASSNAME.equals(storeImplementationClass)) { + // if the user's trying to set up a custom implementation, give a clue + if (isDiagnosticsEnabled()) { + // use internal logging to issue the warning + logDiagnostic("[ERROR] LogFactory: Load of custom hashtable failed"); + } else { + // we *really* want this output, even if diagnostics weren't + // explicitly enabled by the user. + System.err.println("[ERROR] LogFactory: Load of custom hashtable failed"); + } } } if (result == null) { @@ -305,13 +356,32 @@ // Identify the class loader we will be using ClassLoader contextClassLoader = getContextClassLoader(); + if (contextClassLoader == null) { + // This is an odd enough situation to report about. This + // output will be a nuisance on JDK1.1, as the system + // classloader is null in that environment. + logDiagnostic("Context classloader is null."); + } + // Return any previously registered factory for this class loader LogFactory factory = getCachedFactory(contextClassLoader); - if (factory != null) + if (factory != null) { return factory; + } + + logDiagnostic( + "LogFactory requested for the first time for context classloader " + + objectId(contextClassLoader)); // Load properties file. - // Will be used one way or another in the end. + // + // If the properties file exists, then its contents are used as + // "attributes" on the LogFactory implementation class. One particular + // property may also control which LogFactory concrete subclass is + // used, but only if other discovery mechanisms fail.. + // + // As the properties file (if it exists) will be used one way or + // another in the end we may as well look for it first. Properties props=null; try { @@ -324,28 +394,47 @@ stream.close(); } } catch (IOException e) { + ; // ignore } catch (SecurityException e) { + ; // ignore } - // First, try the system property + // First, try a global system property + logDiagnostic( + "Looking for system property [" + FACTORY_PROPERTY + + "] to define the LogFactory subclass to use.."); + try { String factoryClass = System.getProperty(FACTORY_PROPERTY); if (factoryClass != null) { - factory = newFactory(factoryClass, contextClassLoader); + logDiagnostic( + "Creating an instance of LogFactory class " + factoryClass + + " as specified by system property " + FACTORY_PROPERTY); + + factory = newFactory(factoryClass, contextClassLoader, contextClassLoader); } } catch (SecurityException e) { + logDiagnostic( + "A security exception occurred while trying to create an" + + " instance of the custom factory class" + + ": [" + e.getMessage().trim() + + "]. Trying alternative implementations.."); ; // ignore } - // Second, try to find a service by using the JDK1.3 jar - // discovery mechanism. This will allow users to plug a logger - // by just placing it in the lib/ directory of the webapp ( or in - // CLASSPATH or equivalent ). This is similar to the second - // step, except that it uses the (standard?) jdk1.3 location in the jar. + // Second, try to find a service by using the JDK1.3 class + // discovery mechanism, which involves putting a file with the name + // of an interface class in the META-INF/services directory, where the + // contents of the file is a single line specifying a concrete class + // that implements the desired interface. if (factory == null) { + logDiagnostic( + "Looking for a resource file of name [" + SERVICE_ID + + "] to define the LogFactory subclass to use.."); + try { InputStream is = getResourceAsStream(contextClassLoader, SERVICE_ID); @@ -366,11 +455,23 @@ if (factoryClassName != null && ! "".equals(factoryClassName)) { - factory= newFactory( factoryClassName, contextClassLoader ); + logDiagnostic( + "Creating an instance of LogFactory class " + factoryClassName + + " as specified by file " + SERVICE_ID + + " which was present in the path of the context" + + " classloader."); + + factory = newFactory( factoryClassName, contextClassLoader, contextClassLoader ); } } } catch( Exception ex ) { - ; + logDiagnostic( + "A security exception occurred while trying to create an" + + " instance of the custom factory class" + + ": [" + ex.getMessage().trim() + + "]. Trying alternative implementations.."); + + ; // ignore } } @@ -383,10 +484,23 @@ // the webapp, even if a default logger is set at JVM level by a // system property ) - if (factory == null && props != null) { - String factoryClass = props.getProperty(FACTORY_PROPERTY); - if (factoryClass != null) { - factory = newFactory(factoryClass, contextClassLoader); + if (factory == null) { + logDiagnostic( + "Looking for a properties file of name " + FACTORY_PROPERTIES + + " to define the LogFactory subclass to use.."); + + if (props != null) { + logDiagnostic( + "Properties file found. Looking for property " + + FACTORY_PROPERTY + + " to define the LogFactory subclass to use.."); + + String factoryClass = props.getProperty(FACTORY_PROPERTY); + if (factoryClass != null) { + factory = newFactory(factoryClass, contextClassLoader, contextClassLoader); + + // what about handling an exception from newFactory?? + } } } @@ -394,8 +508,21 @@ // Fourth, try the fallback implementation class if (factory == null) { + logDiagnostic( + "Loading the default LogFactory implementation " + FACTORY_DEFAULT + + " via the same classloader that loaded this LogFactory" + + " class (ie not looking in the context classloader)."); + + // Note: we don't try to load the LogFactory implementation + // via the context classloader here because: + // * that can cause problems (see comments in newFactory method) + // * no-one should be customising the code of the default class + // Yes, we do give up the ability for the child to ship a newer + // version of the LogFactoryImpl class and have it used dynamically + // by an old LogFactory class in the parent, but that isn't + // necessarily a good idea anyway. ClassLoader logFactoryClassLoader = getClassLoader(LogFactory.class); - factory = newFactory(FACTORY_DEFAULT, logFactoryClassLoader); + factory = newFactory(FACTORY_DEFAULT, logFactoryClassLoader, contextClassLoader); } if (factory != null) { @@ -464,6 +591,7 @@ */ public static void release(ClassLoader classLoader) { + logDiagnostic("Releasing factory for classloader " + objectId(classLoader)); synchronized (factories) { if (classLoader == null) { if (nullClassLoaderFactory != null) { @@ -492,6 +620,7 @@ */ public static void releaseAll() { + logDiagnostic("Releasing factory for all classloaders."); synchronized (factories) { Enumeration elements = factories.elements(); while (elements.hasMoreElements()) { @@ -511,19 +640,16 @@ // ------------------------------------------------------ Protected Methods - /** * Safely get access to the classloader for the specified class. * <p> - * Theoretically, calling Class.getClassLoader can throw a security - * exception, and so should be done under an AccessController in order - * to provide maximum flexibility. - * <p> - * However in practice people don't appear to use security policies that - * forbid getClassLoader calls, so for the moment this method doesn't - * bother to actually do that. As all code is written to call this - * method rather than Class.getClassLoader, AccessController stuff could - * be put in this method without any disruption later if needed. + * Theoretically, calling getClassLoader can throw a security exception, + * and so should be done under an AccessController in order to provide + * maximum flexibility. However in practice people don't appear to use + * security policies that forbid getClassLoader calls. So for the moment + * all code is written to call this method rather than Class.getClassLoader, + * so that we could put AccessController stuff in this method without any + * disruption later if we need to. * <p> * Even when using an AccessController, however, this method can still * throw SecurityException. Commons-logging basically relies on the @@ -539,10 +665,13 @@ try { return clazz.getClassLoader(); } catch(SecurityException ex) { + logDiagnostic( + "Unable to get classloader for class " + clazz + + " due to security restrictions."); throw ex; } } - + /** * Calls LogFactory.directGetContextClassLoader under the control of an * AccessController class. This means that java code running under a @@ -637,6 +766,19 @@ } catch (NoSuchMethodException e) { // Assume we are running on JDK 1.1 classLoader = getClassLoader(LogFactory.class); + + // We deliberately don't log a message here to outputStream; + // this message would be output for every call to LogFactory.getLog() + // when running on JDK1.1 + // + // if (outputStream != null) { + // outputStream.println( + // "Method Thread.getContextClassLoader does not exist;" + // + " assuming this is JDK 1.1, and that the context" + // + " classloader is the same as the class that loaded" + // + " the concrete LogFactory class."); + // } + } // Return the selected class loader @@ -646,6 +788,13 @@ /** * Check cached factories (keyed by contextClassLoader) * + * @param contextClassLoader is the context classloader associated + * with the current thread. This allows separate LogFactory objects + * per component within a container, provided each component has + * a distinct context classloader set. This parameter may be null + * in JDK1.1, and in embedded systems where jcl-using code is + * placed in the bootclasspath. + * * @return the factory associated with the specified classloader if * one has previously been created, or null if this is the first time * we have seen this particular classloader. @@ -655,6 +804,9 @@ LogFactory factory = null; if (contextClassLoader == null) { + // We have to handle this specially, as factories is a Hashtable + // and those don't accept null as a key value. + // // nb: nullClassLoaderFactory might be null. That's ok. factory = nullClassLoaderFactory; } else { @@ -693,7 +845,36 @@ * implementation class, loaded by the specified class loader. * If that fails, try the class loader used to load this * (abstract) LogFactory. - * + * <p> + * <h2>ClassLoader conflicts</h2> + * Note that there can be problems if the specified ClassLoader is not the + * same as the classloader that loaded this class, ie when loading a + * concrete LogFactory subclass via a context classloader. + * <p> + * The problem is the same one that can occur when loading a concrete Log + * subclass via a context classloader. + * <p> + * The problem occurs when code running in the context classloader calls + * class X which was loaded via a parent classloader, and class X then calls + * LogFactory.getFactory (either directly or via LogFactory.getLog). Because + * class X was loaded via the parent, it binds to LogFactory loaded via + * the parent. When the code in this method finds some LogFactoryYYYY + * class in the child (context) classloader, and there also happens to be a + * LogFactory class defined in the child classloader, then LogFactoryYYYY + * will be bound to [EMAIL PROTECTED] It cannot be cast to + * [EMAIL PROTECTED], ie this method cannot return the object as + * the desired type. Note that it doesn't matter if the LogFactory class + * in the child classloader is identical to the LogFactory class in the + * parent classloader, they are not compatible. + * <p> + * The solution taken here is to simply print out an error message when + * this occurs then throw an exception. The deployer of the application + * must ensure they remove all occurrences of the LogFactory class from + * the child classloader in order to resolve the issue. Note that they + * do not have to move the custom LogFactory subclass; that is ok as + * long as the only LogFactory class it can find to bind to is in the + * parent classloader. + * <p> * @param factoryClass Fully qualified name of the <code>LogFactory</code> * implementation class * @param classLoader ClassLoader from which to load this class @@ -702,7 +883,8 @@ * cannot be created */ protected static LogFactory newFactory(final String factoryClass, - final ClassLoader classLoader) + final ClassLoader classLoader, + final ClassLoader contextClassLoader) throws LogConfigurationException { Object result = AccessController.doPrivileged( @@ -712,8 +894,17 @@ } }); - if (result instanceof LogConfigurationException) - throw (LogConfigurationException)result; + if (result instanceof LogConfigurationException) { + LogConfigurationException ex = (LogConfigurationException) result; + logDiagnostic( + "An error occurred while loading the factory class:" + + ex.getMessage()); + throw ex; + } + + logDiagnostic( + "Created object " + objectId(result) + + " to manage classloader " + objectId(contextClassLoader)); return (LogFactory)result; } @@ -739,47 +930,80 @@ // Warning: must typecast here & allow exception // to be generated/caught & recast properly. logFactoryClass = classLoader.loadClass(factoryClass); + if (LogFactory.class.isAssignableFrom(logFactoryClass)) { + logDiagnostic( + "loaded class " + logFactoryClass.getName() + + " from classloader " + objectId(classLoader)); + } else { + logDiagnostic( + "Factory class " + logFactoryClass.getName() + + " loaded from classloader " + objectId(classLoader) + + " does not extend " + LogFactory.class.getName() + + " as loaded by this classloader."); + } + return (LogFactory) logFactoryClass.newInstance(); } catch (ClassNotFoundException ex) { if (classLoader == thisClassLoader) { // Nothing more to try, onwards. + logDiagnostic( + "Unable to locate any class called " + factoryClass + + " via classloader " + objectId(classLoader)); throw ex; } // ignore exception, continue } catch (NoClassDefFoundError e) { if (classLoader == thisClassLoader) { // Nothing more to try, onwards. + logDiagnostic( + "Class " + factoryClass + " cannot be loaded" + + " via classloader " + objectId(classLoader) + + ": it depends on some other class that cannot" + + " be found."); throw e; } - - } catch(ClassCastException e){ - - if (classLoader == thisClassLoader) { - // Nothing more to try, onwards (bug in loader implementation). + // ignore exception, continue + } catch(ClassCastException e) { + if (classLoader == thisClassLoader) { + // This cast exception is not due to classloader issues; + // the specified class *really* doesn't extend the + // required LogFactory base class. + logDiagnostic( + "Class " + factoryClass + " really does not extend " + + LogFactory.class.getName()); throw e; - } + } + // Ignore exception, continue } - // Ignore exception, continue } /* At this point, either classLoader == null, OR * classLoader was unable to load factoryClass. - * Try the class loader that loaded this class: - * LogFactory.getClassLoader(). + * + * In either case, we call Class.forName, which is equivalent + * to LogFactory.class.getClassLoader.load(name), ie we ignore + * the classloader parameter the caller passed, and fall back + * to trying the classloader associated with this class. See the + * javadoc for the newFactory method for more info on the + * consequences of this. * * Notes: - * a) LogFactory.class.getClassLoader() may return 'null' - * if LogFactory is loaded by the bootstrap classloader. - * b) The Java endorsed library mechanism is instead - * Class.forName(factoryClass); + * * LogFactory.class.getClassLoader() may return 'null' + * if LogFactory is loaded by the bootstrap classloader. */ // Warning: must typecast here & allow exception // to be generated/caught & recast properly. + + logDiagnostic( + "Unable to load factory class via classloader " + + objectId(classLoader) + + ": trying the classloader associated with this LogFactory."); logFactoryClass = Class.forName(factoryClass); return (LogFactory) logFactoryClass.newInstance(); } catch (Exception e) { // Check to see if we've got a bad configuration + logDiagnostic("Unable to create logfactory instance."); if (logFactoryClass != null && !LogFactory.class.isAssignableFrom(logFactoryClass)) { return new LogConfigurationException( @@ -805,6 +1029,202 @@ } }); } + + /** + * Determines whether the user wants internal diagnostic output. If so, + * returns an appropriate writer object. Users can enable diagnostic + * output by setting the system property named OUTPUT_PROPERTY to + * a filename, or the special values STDOUT or STDERR. + */ + private static void initDiagnostics() { + String dest; + try { + dest = System.getProperty(DIAGNOSTICS_DEST_PROPERTY); + if (dest == null) { + return; + } + } catch(SecurityException ex) { + // We must be running in some very secure environment. + // We just have to assume output is not wanted.. + return; + } + + if (dest.equals("STDOUT")) { + diagnosticsStream = System.out; + } else if (dest.equals("STDERR")) { + diagnosticsStream = System.err; + } else { + try { + // open the file in append mode + FileOutputStream fos = new FileOutputStream(dest, true); + diagnosticsStream = new PrintStream(fos); + } catch(IOException ex) { + // We should report this to the user - but how? + return; + } + } + + // In order to avoid confusion where multiple instances of JCL are + // being used via different classloaders within the same app, we + // ensure each logged message has a prefix of form + // [EMAIL PROTECTED]: + Class clazz = LogFactory.class; + String classLoaderName; + try { + ClassLoader classLoader = thisClassLoader; + if (thisClassLoader == null) { + classLoaderName = "BOOTLOADER"; + } else { + classLoaderName = String.valueOf(System.identityHashCode(classLoader)); + } + } catch(SecurityException e) { + classLoaderName = "UNKNOWN"; + } + diagnosticPrefix = + clazz.getName() + "@" + classLoaderName + ": "; + } + + /** + * Indicates true if the user has enabled internal logging. + * <p> + * By the way, sorry for the incorrect grammar, but calling this method + * areDiagnosticsEnabled just isn't java beans style. + * + * @return true if calls to logDiagnostic will have any effect. + */ + protected static boolean isDiagnosticsEnabled() { + return diagnosticsStream != null; + } + + /** + * Write the specified message to the internal logging destination. + * <p> + * Note that this method is private; concrete subclasses of this class + * should not call it because the diagnosticPrefix string this + * method puts in front of all its messages is [EMAIL PROTECTED], + * while subclasses should put [EMAIL PROTECTED] + * <p> + * Subclasses should instead compute their own prefix, then call + * logRawDiagnostic. Note that calling isDiagnosticsEnabled is + * fine for subclasses. + * <p> + * Note that it is safe to call this method before initDiagnostics + * is called; any output will just be ignored (as isDiagnosticsEnabled + * will return false). + * + * @param msg is the diagnostic message to be output. + */ + private static final void logDiagnostic(String msg) { + if (diagnosticsStream != null) { + diagnosticsStream.print(diagnosticPrefix); + diagnosticsStream.println(msg); + diagnosticsStream.flush(); + } + } + + /** + * Write the specified message to the internal logging destination. + * + * @param msg is the diagnostic message to be output. + */ + protected static final void logRawDiagnostic(String msg) { + if (diagnosticsStream != null) { + diagnosticsStream.println(msg); + diagnosticsStream.flush(); + } + } + + /** + * Generate useful diagnostics regarding the classloader tree for + * the specified class. + * <p> + * As an example, if the specified class was loaded via a webapp's + * classloader, then you may get the following output: + * <pre> + * Class com.acme.Foo was loaded via classloader 11111 + * ClassLoader tree: 11111 -> 22222 (SYSTEM) -> 33333 -> BOOT + * </pre> + * <p> + * This method returns immediately if isDiagnosticsEnabled() + * returns false. + * + * @param clazz is the class whose classloader + tree are to be + * output. + */ + private static void logClassLoaderTree(Class clazz) { + if (!isDiagnosticsEnabled()) { + return; + } + + String className = clazz.getName(); + ClassLoader classLoader; + ClassLoader systemClassLoader; + + try { + classLoader = getClassLoader(clazz); + } catch(SecurityException ex) { + // not much useful diagnostics we can print here! + logDiagnostic( + "Security forbids determining the classloader for " + className); + return; + } + + logDiagnostic( + "Class " + className + " was loaded via classloader " + + objectId(classLoader)); + + try { + systemClassLoader = ClassLoader.getSystemClassLoader(); + } catch(SecurityException ex) { + logDiagnostic( + "Security forbids determining the system classloader."); + return; + } + + if (classLoader != null) { + StringBuffer buf = new StringBuffer("ClassLoader tree:"); + for(;;) { + buf.append(objectId(classLoader)); + if (classLoader == systemClassLoader) { + buf.append(" (SYSTEM) "); + } + + try { + classLoader = classLoader.getParent(); + } catch(SecurityException ex) { + buf.append(" --> SECRET"); + break; + } + + buf.append(" --> "); + if (classLoader == null) { + buf.append("BOOT"); + break; + } + } + logDiagnostic(buf.toString()); + } + } + + /** + * Returns a string that uniquely identifies the specified object, including + * its class. + * <p> + * The returned string is of form "[EMAIL PROTECTED]", ie is the same as + * the return value of the Object.toString() method, but works even when + * the specified object's class has overidden the toString method. + * + * @param o may be null. + * @return + */ + public static String objectId(Object o) { + if (o == null) { + return "null"; + } else { + return o.getClass().getName() + "@" + System.identityHashCode(o); + } + } + // ---------------------------------------------------------------------- // Static initialiser block to perform initialisation at class load time. // @@ -825,8 +1245,11 @@ // ---------------------------------------------------------------------- static { + // note: it's safe to call methods before initInternalLogging.. thisClassLoader = getClassLoader(LogFactory.class); + initDiagnostics(); + logClassLoaderTree(LogFactory.class); factories = createFactoryStore(); - } + } } --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]