Commons Logging
  1. Commons Logging
  2. LOGGING-132

Jdk14Logger wrapper does not respect logger name

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: Nightly Builds, 1.0, 1.0.1, 1.0.2, 1.0.3, 1.0.4, 1.1.0, 1.1.1, 1.1.2
    • Fix Version/s: 1.1.2
    • Labels:
      None

      Description

      The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

      Example:
      I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

      With the other log wrappers, if I log a message I always get something like:

      Oct 21, 2009 5:03:26 PM
      [INFO] SubSystemA start - My log message

      With the JDK log wrapper, I get something like:

      Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
      INFO: My log message

      Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

      Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
      0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
      0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
      00000000000000000000000000000000000000000000000000000000
      INFO: My log message

      The fix:

      In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.

          private void log( Level level, String msg, Throwable ex ) {
      
              Logger logger = getLogger();
              if (logger.isLoggable(level)) {
                  // Hack (?) to get the stack trace.
                  Throwable dummyException=new Throwable();
                  StackTraceElement locations[]=dummyException.getStackTrace();
                  // Caller will be the third element
                  String cname="unknown";
                  String method="unknown";
                  if( locations!=null && locations.length >2 ) {
                      StackTraceElement caller=locations[2];
                      cname=caller.getClassName();
                      method=caller.getMethodName();
                  }
                  if( ex==null ) {
                      logger.logp( level, cname, method, msg );
                  } else {
                      logger.logp( level, cname, method, msg, ex );
                  }
              }
      
          }
      

        Activity

        Nathan Niesen created issue -
        Nathan Niesen made changes -
        Field Original Value New Value
        Description The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. It is also problematic for obfuscated code and private parts of an application or library.

        Example:
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message

        With the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message


        The fix:

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.


            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

        <b>Example:</b>
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

        <blockquote>
            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message
        </blockquote>

        With the JDK log wrapper, I get something like:

        <blockquote>
            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message
        </blockquote>

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

        </blockquote>
            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message
        </blockquote>

        <b>The fix:</b>

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.


            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        Nathan Niesen made changes -
        Description The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

        <b>Example:</b>
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

        <blockquote>
            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message
        </blockquote>

        With the JDK log wrapper, I get something like:

        <blockquote>
            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message
        </blockquote>

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

        </blockquote>
            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message
        </blockquote>

        <b>The fix:</b>

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.


            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

        Example:
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message

        With the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message

        The fix:

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.


            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        Dennis Lundberg made changes -
        Affects Version/s 2.0 [ 12312250 ]
        Description The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

        Example:
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message

        With the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message

        The fix:

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.


            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        The JDK14 wrapper implementation logs using the callers class name instead of the configured logger name. This prevents the ability to use named loggers for applications and subsystems. Also, the log message name does not match the JDK logger name so user don't know what name to use to configure the logger. It is also problematic for obfuscated code and private parts of an application or library.

        Example:
        I have a class named com.myco.product.subsysa.ClassX.InnerClassY and I create logger LogFactory.getLog("SubSystemA").

        With the other log wrappers, if I log a message I always get something like:

            Oct 21, 2009 5:03:26 PM
            [INFO] SubSystemA start - My log message

        With the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$InnerClassY start
            INFO: My log message

        Or worse yet with obfuscated code and the JDK log wrapper, I get something like:

            Oct 21, 2009 5:03:26 PM com.myco.product.subsysa.ClassX$_oOOO.o00000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        0000000000000000000000000000000000000000000000000000000000000000000000000000000000000
        00000000000000000000000000000000000000000000000000000000
            INFO: My log message

        The fix:

        In the calls to logger.logp(...), replace cname with this.name. Loggers created with the class name will still get the class name.

        {code}
            private void log( Level level, String msg, Throwable ex ) {

                Logger logger = getLogger();
                if (logger.isLoggable(level)) {
                    // Hack (?) to get the stack trace.
                    Throwable dummyException=new Throwable();
                    StackTraceElement locations[]=dummyException.getStackTrace();
                    // Caller will be the third element
                    String cname="unknown";
                    String method="unknown";
                    if( locations!=null && locations.length >2 ) {
                        StackTraceElement caller=locations[2];
                        cname=caller.getClassName();
                        method=caller.getMethodName();
                    }
                    if( ex==null ) {
                        logger.logp( level, cname, method, msg );
                    } else {
                        logger.logp( level, cname, method, msg, ex );
                    }
                }

            }
        {code}
        Hide
        Dennis Lundberg added a comment -

        I tried your suggestion, but there were a lots of test failures.
        So changing this will have a larger impact than you thought.

        Show
        Dennis Lundberg added a comment - I tried your suggestion, but there were a lots of test failures. So changing this will have a larger impact than you thought.
        Hide
        Nathan Niesen added a comment - - edited

        If there is a major impact, it's because there are a lot of bad tests.

        The real impact will be that the logger implementation adheres to the contract set forth in the JDK and Commons logging documentation. The logger is created with a specified string name (not a class name), configured using the specified name, and logs using the specified name. Nothing in the LogFactory uses an object instances class name to retrieve a logger or change its configuration.

        I should also note that the Jdk13LumberjackLogger appears to have a similar defect. The implementation of its log method is different but it creates a LogRecord and never calls setLoggerName(this.name).

        The Avalon and Log4J loggers use the Logger class and which correctly sets the logger name on the log record. SimpleLog also correctly uses the log name.

        Show
        Nathan Niesen added a comment - - edited If there is a major impact, it's because there are a lot of bad tests. The real impact will be that the logger implementation adheres to the contract set forth in the JDK and Commons logging documentation. The logger is created with a specified string name (not a class name), configured using the specified name, and logs using the specified name. Nothing in the LogFactory uses an object instances class name to retrieve a logger or change its configuration. I should also note that the Jdk13LumberjackLogger appears to have a similar defect. The implementation of its log method is different but it creates a LogRecord and never calls setLoggerName(this.name). The Avalon and Log4J loggers use the Logger class and which correctly sets the logger name on the log record. SimpleLog also correctly uses the log name.
        Nathan Niesen made changes -
        Affects Version/s 1.0.2 [ 12314497 ]
        Affects Version/s 1.1.2 [ 12314498 ]
        Affects Version/s 2.0 [ 12312250 ]
        Hide
        Dennis Lundberg added a comment -

        Removing 2.0 as "Affects version/s" again. That is only a placeholder for ideas at this time, so this issue can't have an effect that version.

        Show
        Dennis Lundberg added a comment - Removing 2.0 as "Affects version/s" again. That is only a placeholder for ideas at this time, so this issue can't have an effect that version.
        Dennis Lundberg made changes -
        Affects Version/s 2.0 [ 12312250 ]
        Hide
        Thomas Neidhart added a comment -

        Applied change in r1448063 for the Jdk14Logger.

        Show
        Thomas Neidhart added a comment - Applied change in r1448063 for the Jdk14Logger.
        Thomas Neidhart made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 1.1.2 [ 12314498 ]
        Resolution Fixed [ 1 ]
        Thomas Neidhart made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        1216d 15h 45m 1 Thomas Neidhart 20/Feb/13 10:02
        Resolved Resolved Closed Closed
        28d 10h 9m 1 Thomas Neidhart 20/Mar/13 20:11

          People

          • Assignee:
            Unassigned
            Reporter:
            Nathan Niesen
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development