Uploaded image for project: 'SLF4J'
  1. SLF4J
  2. SLF4J-15

bogus jcl-over-slf4j impl - %F, %L etc. off by one

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • None
    • None
    • Implementations
    • None
    • Operating System: All
      Platform: All

    Description

      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. ...

      Attachments

        Activity

          People

            slf4j-dev SLF4J developers list
            elkner Jens Elkner
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: