[slf4j-dev] [Bug 23] New: bogus jcl-over-slf4j impl - %F, %L etc. off by one

[bugzilla-daemon at gil.qos.ch]

http://bugzilla.slf4j.org/show_bug.cgi?id=23

           Summary: bogus jcl-over-slf4j impl - %F, %L etc. off by one
           Product: SLF4J
           Version: 1.0rc1
          Platform: All
        OS/Version: All
            Status: NEW
          Severity: blocker
          Priority: P1
         Component: Implementations
        AssignedTo: dev at slf4j.org
        ReportedBy: elkner at linofee.org


Since jcl-over-slf4j implementation uses wrt. log4j internally
org.apache.log4j.Logger, this leads to an off by one situation wrt.
determination of the source line and thus always reports the SLF4JLog as source
of the event
because LoggingEvent#FQCN is set to org.apache.log4j.Category and not to
org.apache.commons.logging.impl.SLF4JLog.

E.g.:
private static final Log log = LogFactory.getLog(JCLTest.class);

executed like:

org.apache.commons.logging.LogFactory#getLog(clazz)
-->org.apache.commons.logging.impl.SLF4FLogFactory#getInstance(clazz)
   -->org.slf4j.LoggerFactory.getLogger(clazzName)
      -->org.slf4j.impl.NLOG4JLoggerFactory#getLogger(clazzName)
         -->org.apache.log4j.LogManager#getLogger(clazzName)
            -->org.apache.log4j.Hierarchy#getLogger(clazzName)
              
-->org.apache.log4.DefaultCategoryFactory#makeNewLoggerInstance(clazzName)
   <--------------org.apache.log4j.Logger(clazzName)
<--org.apache.commons.logging.impl.SLF4JLog(logger)

logger.FCQN == org.apache.log4j.Category

log.info("test");
-->org.apache.commons.logging.impl.SLF4JLog.logger#info(String)
   -->org.apache.log4j.Category#info(String)
      -->org.apache.log4j.Category#forcedLog(FQCN, Level.INFO, message, null);
         -->event = new LoggingEvent(FQCN, this, level, message, t);
         -->#callAppenders(event);
         ...-->event.LocationInfo(new Throwable(), FQCN);
               ...-->s="stackTraceOfThrowableAsString(t)"
                     #ibegin = s.lastIndexOf(FQCN);
                     #ibegin += "charsTilnextLine()"
                     #return "lineFrom(ibegin, tilEOL)

So obviously, this is an error aka off by one situation, since SLF4JLog
is actually the FQCN which should be used and not Category ...

A stacktrace used to determine %F:%L, which makes the problem better visible:

java.lang.Throwable
    at
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:182)
    at
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:475)
    at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:56)
    at org.apache.log4j.PatternLayout.format(PatternLayout.java:495)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
    at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
    at org.apache.log4j.Category.callAppenders(Category.java:198)
    at org.apache.log4j.Category.forcedLog(Category.java:510)
    at org.apache.log4j.Category.info(Category.java:738)
    at org.apache.commons.logging.impl.SLF4JLog.info(SLF4JLog.java:120)
    at JCLTest.<init>(JCLTest.java:21)
    at JCLTest.main(JCLTest.java:25)

Thus the result:

04:30:46,334 [main] INFO  (SLF4JLog.java:120) - test

But should be:
04:30:46,334 [main] INFO  (JCLTest.java:21) - test


So, at least if one wanna use e.g. nlog4j as its slf4j impl., logging is almost
completely unusable wrt. debugging, which makes it hard to troubleshoot AS like
jboss etc. ...

-- 
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.