环境信息

SpringBoot?2.1.15.RELEASE

slf4j:1.7.25

logback:1.2.3

说明

????????系统使用的是slf4j+logback日志组合，而且为了系统的个性化需求，封装了自己的日志操作类Log.java，不是直接使用slf4j的API：

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

配置信息

?logback配置：

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>

	<!-- 异步输出 -->
	<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
		<!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
		<discardingThreshold>0</discardingThreshold>
		<!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
		<queueSize>256</queueSize>
		<!-- 添加附加的appender,最多只能添加一个 -->
		<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

问题描述

logback的配置是生效的，%L是打印行号，在日志里也能显示出行号出来。

问题在于有很多行号的值不对，而且都是些重复的行数，比如51、117、149。

2021-09-22 14:06:49.238 INFO ?加载第7个子配置文件:file [D:\xxx.xml] 【main】【ResourceLookuper:117】
2021-09-22 14:06:49.248 INFO ?加载第8个子配置文件:file [D:\yyy.xml] 【main】【ResourceLookuper:117】
2021-09-22 14:06:49.256 DEBUG 总共加载了9配置文件【main】【ResourceLookuper:51】
2021-09-22 14:06:49.256 DEBUG 开始处理已加载的第0个子配置文件:xxx.xml 【main】【XmlConfigDeserializer:51】
2021-09-22 14:38:27.517 WARN ?获取不到HttpServletRequest对象【pool-14-thread-1】【HttpHolderUtil:149】

原因分析

????????问题出现以后，最开始是猜想这些行号是代理类里的行号，不过很快排除了：有些类并没有使用代理，打印出的日志行号还是不对。

? ? ? ? 仔细看了下日志的行号，发现了一个规律：

DEBUG级别的日志的行号是51

INFO级别的日志的行号是117

WARN级别的日志的行号是149

所以问题很可能出在日志操作类Log.java上，这些行号是日志操作类Log里的行号。打开Log类看了下，发现确实是这样：

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记录
	 * @param message
	 * @param e
	 */
	public void debug(Object message,Throwable e)
	{
		message = getLogId(message);
		getCurrentLog().debug(((String)message).replace("{}", ""),e);
	}
	
	
	/**
	 * message记录
	 * @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);
	}

...
	
}

原因在于打印日志是使用的日志操作类Log，真正调用slf4j的debug、info、warn的地方是Log类，所以打印出的行号是Log类里的行号，而不是调用Log类的地方（以下称为调用者类）的行号

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

解决方案

解决思路

? ? ? ? 在使用slf4j的时候，默认引用的是slf4j的org.slf4j.Logger接口（实现类看真正的日志框架是什么，比如这里是logback的ch.qos.logback.classic.Logger），而这个Logger接口还有一个子接口org.slf4j.spi.LocationAwareLogger，logback的ch.qos.logback.classic.Logger实现类也实现了这个接口：

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);
    }
...
}

LocationAwareLogger这个接口的说明里写了：

这个可选接口可以帮助日志系统来输出正确的引用位置信息（方法名、行号），可以用于slf4j的桥连，比如jcl-over-slf4j, jul-to-slf4j and log4j-over-slf4j or Logger wrappers （或者Logger的装饰模式）

在这里，日志操作类Log相当于Logger的装饰器。

解决方法

修改日志操作类Log里的debug、info、warn等方法，改成LocationAwareLogger里的log方法

可以参考jcl-over-slf4j包里的org.apache.commons.logging.impl.SLF4JLocationAwareLog

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记录
	 * @param message
	 * @param e
	 */
    public void debug(Object message, Throwable e) {
        message = getLogId(message);
        // 做判断是以防更改了日志实现框架之后，logger未实现LocationAwareLogger接口。如果只是logback使用，不需要
        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记录
	 * @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);
    }

...
	
}

参考：

Slf4j+logback实现日志打印-获取调用者类及方法行数信息_wang37444的专栏