The line number printed by slf4j, logback and log4j is incorrect

environmental information

SpringBoot 2.1.15.RELEASE

slf4j:1.7.25

logback:1.2.3

explain

         The system uses the slf4j+logback log combination, and encapsulates its own log operation class Log.java for the personalized needs of the system, instead of directly using slf4j's API:

private static Logger logger = LoggerFactory.getLogger(xxx.class);

configuration information

  logback configuration:

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<property resource="configs-xml-logback.properties" />
	<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
		<layout class="ch.qos.logback.classic.PatternLayout">
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %msg [%t][%logger{0}:%L]%n</pattern>
		</layout>
	</appender>

	<appender name="bizLog"
		class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>${log.root.path}/${app.name}/${app.name}.log</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>${log.root.path}/${app.name}/${app.name}.%d{yyyy-MM-dd}.log
			</fileNamePattern>
			<maxHistory>3</maxHistory>
		</rollingPolicy>
		<encoder>
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %msg [%t][%logger{0}:%L]%n</pattern>
		</encoder>
	</appender>

	<!-- Asynchronous output -->
	<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
		<!-- Do not lose logs.default,If 80 of the queue%already expired,Will be discarded TRACT,DEBUG,INFO Level log -->
		<discardingThreshold>0</discardingThreshold>
		<!-- Change the depth of the default queue,This value affects performance.The default value is 256 -->
		<queueSize>256</queueSize>
		<!-- Add additional appender,At most one can be added -->
		<appender-ref ref="bizLog" />
	</appender>

	<logger name="java.sql.Connection" level="${sql.log.level}" />
	<logger name="java.sql.Statement" level="${sql.log.level}" />
	<logger name="java.sql.PreparedStatement" level="${sql.log.level}" />
	
	<logger name="com.eternalinfo" level="${log.dev.level}" />
	
	<root level="${log.level}">
		<appender-ref ref="stdout" />
		<appender-ref ref="ASYNC" />
	</root>
	<jmxConfigurator />
</configuration>  

configs-xml-logback.properties

app.name=myApp
log.root.path=/home/myApp-logs
log.level=INFO
log.dev.level=DEBUG
sql.log.level=INFO

Problem description

The configuration of logback is effective,% L is the print line number, and the line number can also be displayed in the log.

The problem is that there are many wrong line numbers, and they are repeated lines, such as 51, 117 and 149.

2021-09-22 14:06:49.238 INFO   Load the 7th sub configuration file: file [D:\xxx.xml] [main] [resourcelookup: 117]
2021-09-22 14:06:49.248 INFO   Load the 8th sub configuration file: file [D:\yyy.xml] [main] [resourcelookup: 117]
2021-09-22 14:06:49.256 DEBUG loaded a total of 9 configuration files [main] [resourcelookup: 51]
2021-09-22 14:06:49.256 DEBUG starts processing the loaded 0-th sub configuration file: xxx.xml [main] [XmlConfigDeserializer:51]
2021-09-22 14:38:27.517 WARN   Cannot get HttpServletRequest object [pool-14-thread-1] [HttpHolderUtil:149]

Cause analysis

         After the problem occurred, I first guessed that these line numbers were the line numbers in the agent class, but it was quickly eliminated: some classes did not use the agent, and the printed log line numbers were still wrong.

        After carefully looking at the line number of the log, I found a rule:

The line number of the DEBUG level log is 51

The line number of the INFO level log is 117

The line number of the WARN level log is 149

Therefore, the problem is likely to lie in the Log operation class Log.java. These line numbers are the line numbers in the Log operation class Log. After opening the Log class, I found that it is indeed like this:

Log.java   There are omitted codes

import org.slf4j.Logger;

import ch.qos.logback.classic.LoggerContext;

public class Log
{
	public static final String LOG_LEVEL_KEY="log.level";
	public static final String OUT_LOG_CLASS_REGEX_KEY="out.log.class.regex";
	
	private Logger logger;
	private static final String PLACE_HODER_STR="\\{\\}";
	
	Log(Class<?> clz,LoggerContext loggerContext)
	{
//		logger=LoggerFactory.getLogger(clz); 
//		if(this.loggerContext==null) {
//			loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
//		}
		logger=loggerContext.getLogger(clz);
	}
	
	private Logger getCurrentLog()
	{
		return logger;
	}
	
	private String getLogId(Object message) {
		String logId = LogIdUtil.getLogId()==null ?"":LogIdUtil.getLogId()+"||";
		return logId+message;
	}
	
	/**
	 * debug record
	 * @param message
	 * @param e
	 */
	public void debug(Object message,Throwable e)
	{
		message = getLogId(message);
		getCurrentLog().debug(((String)message).replace("{}", ""),e);
	}
	
	
	/**
	 * message record
	 * @param message
	 * @param e
	 */
	public void info(Object message,Throwable e)
	{
		message = getLogId(message);
		getCurrentLog().info(((String)message).replace("{}", ""),e);
	}
	
	
	
	public void warn(Object message,Throwable e)
	{
		message = getLogId(message);
		getCurrentLog().warn(((String)message).replace("{}", ""),e);
	}

...
	
}

The reason is that the Log operation class Log is used to print the Log, and the place where the debug, info and warn of slf4j are really called is the Log class, so the printed line number is the line number in the Log class, not the line number of the place where the Log class is called (hereinafter referred to as the caller class)

getCurrentLog().debug(((String)message).replace("{}", ""),e);

Solution

Solution ideas

        When slf4j is used, the org.slf4j.Logger interface of slf4j is referenced by default (the implementation class depends on what the real logging framework is, for example, ch.qos.logback.classic.Logger of logback), and this Logger interface also has a sub interface org.slf4j.spi.LocationAwareLogger. The implementation class of ch.qos.logback.classic.Logger of logback also implements this interface:

LocationAwareLogger.java

package org.slf4j.spi;

import org.slf4j.Logger;
import org.slf4j.Marker;

/**
 * An <b>optional</b> interface helping integration with logging systems capable of 
 * extracting location information. This interface is mainly used by SLF4J bridges 
 * such as jcl-over-slf4j, jul-to-slf4j and log4j-over-slf4j or {@link Logger} wrappers
 * which need to provide hints so that the underlying logging system can extract
 * the correct location information (method name, line number).
 *
 * @author Ceki Gulcu
 * @since 1.3
 */
public interface LocationAwareLogger extends Logger {

    // these constants should be in EventContants. However, in order to preserve binary backward compatibility
    // we keep these constants here
    final public int TRACE_INT = 00;
    final public int DEBUG_INT = 10;
    final public int INFO_INT = 20;
    final public int WARN_INT = 30;
    final public int ERROR_INT = 40;

    /**
     * Printing method with support for location information. 
     * 
     * @param marker The marker to be used for this event, may be null.
     * @param fqcn The fully qualified class name of the <b>logger instance</b>,
     * typically the logger class, logger bridge or a logger wrapper.
     * @param level One of the level integers defined in this interface
     * @param message The message for the log event
     * @param t Throwable associated with the log event, may be null.
     */
    public void log(Marker marker, String fqcn, int level, String message, Object[] argArray, Throwable t);

}

ch.qos.logback.classic.Logger.java

public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {

    private static final long serialVersionUID = 5454405123156820674L; // 8745934908040027998L;

    /**
     * The fully qualified name of this class. Used in gathering caller
     * information.
     */
    public static final String FQCN = ch.qos.logback.classic.Logger.class.getName();

    public void log(Marker marker, String fqcn, int levelInt, String message, Object[] argArray, Throwable t) {
        Level level = Level.fromLocationAwareLoggerInteger(levelInt);
        filterAndLog_0_Or3Plus(fqcn, marker, level, message, argArray, t);
    }
...
}

The description of the LocationAwareLogger interface reads:

This optional interface can help the log system to output the correct reference location information (method name and line number), and can be used for slf4j bridging, such as jcl-over-slf4j, jul-to-slf4j and log4j-over-slf4j or Logger wrappers (or Logger decoration mode)

Here, the Log operation class Log is equivalent to the decorator of Logger.

 

resolvent

Modify the debug, info, warn and other methods in the log operation class log to the log method in LocationAwareLogger

You can refer to org.apache.commons.logging.impl.SLF4JLocationAwareLog in the jcl-over-slf4j package

Log.java

import org.slf4j.Logger;

import ch.qos.logback.classic.LoggerContext;

public class Log
{
	public static final String LOG_LEVEL_KEY="log.level";
	public static final String OUT_LOG_CLASS_REGEX_KEY="out.log.class.regex";
	
	private Logger logger;
	private static final String PLACE_HODER_STR="\\{\\}";
	
	Log(Class<?> clz,LoggerContext loggerContext)
	{
//		logger=LoggerFactory.getLogger(clz); 
//		if(this.loggerContext==null) {
//			loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
//		}
		logger=loggerContext.getLogger(clz);
	}
	
	private Logger getCurrentLog()
	{
		return logger;
	}
	
	private String getLogId(Object message) {
		String logId = LogIdUtil.getLogId()==null ?"":LogIdUtil.getLogId()+"||";
		return logId+message;
	}
	
	/**
	 * debug record
	 * @param message
	 * @param e
	 */
    public void debug(Object message, Throwable e) {
        message = getLogId(message);
        // Make a judgment to prevent the logger from implementing the LocationAwareLogger interface after changing the log implementation framework. If only logback is used, it is not required
        if (this.logger instanceof LocationAwareLogger) {
            ((LocationAwareLogger) this.logger).log(null, FQCN, LocationAwareLogger.DEBUG_INT, (String) message, null, e);
            return;
        }
        this.logger.debug(((String) message).replace("{}", ""), e);
    }
	
	
	/**
	 * message record
	 * @param message
	 * @param e
	 */
    public void info(Object message, Throwable e) {
        message = getLogId(message);
        if (this.logger instanceof LocationAwareLogger) {
            ((LocationAwareLogger) this.logger).log(null, FQCN, LocationAwareLogger.INFO_INT, (String) message, null, e);
            return;
        }
        getCurrentLog().info(((String) message).replace("{}", ""), e);
    }
	
	
    public void warn(Object message, Throwable e) {
        message = getLogId(message);
        if (this.logger instanceof LocationAwareLogger) {
            ((LocationAwareLogger) this.logger).log(null, FQCN, LocationAwareLogger.WARN_INT, (String) message, null, e);
            return;
        }
        getCurrentLog().warn(((String) message).replace("{}", ""), e);
    }

...
	
}

reference resources:

Slf4j+logback implements log printing - obtain the number of rows of caller classes and methods_ Wang 37444's column 

Tags: Java Logback slf4j

Posted on Wed, 22 Sep 2021 12:48:58 -0400 by charliez