Details
-
Bug
-
Resolution: Fixed
-
None
-
None
-
None
-
Operating System: All
Platform: All
-
blocker
-
P1
-
23
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. ...