一个优秀的日志应该是什么样的-优快云博客

本文链接：https://blog.youkuaiyun.com/randavy/article/details/146768004

在上一篇"一个合格的日志应该是什么样的"，我们打印的日志已经基本可用了。在线上接口行为和预期的不一致时，INFO日志又不够详细，看不出问题，我们希望临时将日志级别修改为DEBUG，要怎么做呢？

1. 修改日志级别

1. 集成actuator

基于spring-boot-starter的应用，可以通过actuator修改日志级别。首先要添加actuator的依赖。

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>

在application.properties中暴露端点

management.endpoints.web.exposure.include=*

2. 查看日志级别

1. 获取所有端点

首先通过actuator获取可用的端点列表，确认logger的端点存在

curl -s http://192.168.31.52:8080/actuator | jq "."

响应格式如下

{
  "_links": {
    "self": {
      "href": "http://192.168.31.52:8080/actuator",
      "templated": false
    },
    "loggers": {
      "href": "http://192.168.31.52:8080/actuator/loggers",
      "templated": false
    },
    "loggers-name": {
      "href": "http://192.168.31.52:8080/actuator/loggers/{name}",
      "templated": true
    }
  }
}

2. 查看日志级别

查看当前系统的所有Logger的级别

 curl -s http://192.168.31.52:8080/actuator/loggers | jq "."

响应格式如下

{
  "levels": [
    "OFF",
    "ERROR",
    "WARN",
    "INFO",
    "DEBUG",
    "TRACE"
  ],
  "loggers": {
    "ROOT": {
      "configuredLevel": "INFO",
      "effectiveLevel": "INFO"
    },
    "com.keyniu": {
      "effectiveLevel": "INFO"
    },
    "com.keyniu.dis": {
      "effectiveLevel": "INFO"
    }
  }
}

你也可以指定查看某个包的日志级别，比如com.keyniu的

curl -s http://192.168.31.52:8080/actuator/loggers/com.keyniu | jq "."

响应格式如下

{
  "effectiveLevel": "INFO"
}

3. 设置日志级别

通过POST请求修改日志级别

curl -X POST http://192.168.31.52:8080/actuator/loggers/com.keyniu  -H "Content-Type: application/json"  -d '{"configuredLevel": "DEBUG"}'

再次查询日志级别后可以发现，级别已经更新为DEBUG

4. 基于代码修改

一般的公司是不允许在线上暴露actuator端点的，所以我们经常会自定义修改日志级别的逻辑。代码修改的逻辑在不同的日志框架下是不同的，我们以logback为例

    public static void setLogLevel(String loggerName, String level) {
        Logger logger = (Logger) LoggerFactory.getLogger(loggerName);
        logger.setLevel(Level.toLevel(level)); // 支持 OFF/ERROR/WARN/INFO/DEBUG/TRACE
    }

Spring对此做了封装，屏蔽了不同日志框架的差异，我们可以通过LoggingSystem来完成日志级别修改。

    public static void setLogLevel(String loggerName, LogLevel level) {
        LoggingSystem loggingSystem = LoggingSystem.get(ClassLoader.getSystemClassLoader());
        loggingSystem.setLogLevel(loggerName, level);
    }

2. 指定用户修改

通过修改日志级别确实解决了问题，不过日志级别的修改是全局的，所有用户都受到影响，而且也不可能在线上长期开启。所以往往我们会想要给特定的用户打印DEBUG日志，比如内部人员、反馈问题的用户。通过logback本身提供的MDC，我们能将指定请求标为要求打印DEBUG日志，这段逻辑可以放在HandlerInterceptor中实现。

1. 设置MDC标志

public class DebugHandlerInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String uid = request.getHeader("user-id");
        boolean xdebug = debugUid.contains(uid) || "1".equals(request.getParameter("xdebug")) ;
        MDC.put("xdebug", xdebug);
        return true;
    }
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        MDC.clear();
    }
}

2. 实现DEBUG日志

再定义一个工具类，用来判断是否要打印DEBUG日志

public class DebugHelper {
    public static boolean isDebugEnabled(Logger logger) {
        return "1".equals(MDC.get("debug")) || logger.isDebugEnabled();
    }
}

打印日志的时候，需要自行判断DebugHelper.isDebugEnabled

if(DebugHelper.isDebugEnabled(log)) {
	log.info("debug info goes here");
}

这个方案简单直观，不过对用户来说不太友好

必须自己调用DebugHelper.isDebugEnabled的判断
需要通过log.info来打印DEBUG日志

3. slf4j的内部实现

我们使用slf4j的时候时候都是从这一行代码开始的，基于lombok的@Slf4j只是帮我们生成了这一行代码

private Logger log = LoggerFactory.getLogger(HelloWorldController.class);

LoggerFactory的实现流程如下:

当我们调用LoggerFactory时，LoggerFactory会用两种方式寻找ILoggerFacotry的实现
1. 通过环境变量，slf4j.provider获取配置
2. 通过ServiceLoader读取provider
调用ILoggerFacotry.getLogger获取对应的日志实现
1. 返回一个实现了 org.slf4j.Logger 实现

在原理清晰的前提下，扩展的方案基本也明确了，就是提供ILoggerFacotry的实现，返回我们自己的org.slf4j.Logger的实现，这个类的debug方法要包含我们的MDC里的xdebug的判断。
我尝试了两种方案

自定义SLF4JServiceProvider，KeyniuSLF4jServiceProvider，配置-Dslf4j.provider=com.keyniu.dis.logger.KeyniuSLF4jServiceProvider
修改logback的实现，修改Logger的isDebugEnabled和debug方法

4. 扩展SLF4jServiceProvider

1. 实现KeyniuSLF4jServiceProvider

代码和LogbackServiceProvider一致，只是修改ILoggerFacotry的实现


public class KeyniuSLF4jServiceProvider implements SLF4JServiceProvider {
    static final String NULL_CS_URL = "http://logback.qos.ch/codes.html#null_CS";
    public static String REQUESTED_API_VERSION = "2.0.99";
    private LoggerContext defaultLoggerContext;
    private IMarkerFactory markerFactory;
    private LogbackMDCAdapter mdcAdapter;
	...
    public ILoggerFactory getLoggerFactory() {
        return new KeyniuLoggerFactory(this.defaultLoggerContext);
    }
	...
}

2. 实现ILoggerFactory

实现ILoggerFactory返回自己的Logger对象

public class KeyniuLoggerFactory implements ILoggerFactory {
    private LoggerContext loggerContext;
    public KeyniuLoggerFactory(LoggerContext loggerContext) {
        this.loggerContext = loggerContext;
    }
    @Override
    public Logger getLogger(String s) {
        return new KeyniuLogger(this.loggerContext.getLogger(s));
    }
}

3. 修改Logger的实现

修改所有的debug和isDebugEnabled，判断MDC的xdebug的值

public class KeyniuLogger implements org.slf4j.Logger {
    private ch.qos.logback.classic.Logger back;
    public KeyniuLogger(ch.qos.logback.classic.Logger back) {
        this.back = back;
    }
    @Override
    public boolean isDebugEnabled() {
        return back.isDebugEnabled() || "1".equals(MDC.get("xdebug"));
    }
    @Override
    public void debug(String s) {
        if ("1".equals(MDC.get("xdebug"))) {
            back.info(s);
        } else {
            back.debug(s);
        }
    }
}

4. 修改启动参数

java -Dslf4j.provider=com.keyniu.dis.logger.KeyniuSLF4jServiceProvider   com.keyniu.dis.DiveInMain

5. 最终失败

SLF4J(I): Attempting to load provider "com.keyniu.dis.logger.KeyniuSLF4jServiceProvider" specified via "slf4j.provider" system property
Exception in thread "main" java.lang.IllegalArgumentException: LoggerFactory is not a Logback LoggerContext but Logback is on the classpath. Either remove Logback or the competing implementation (class com.keyniu.dis.logger.KeyniuLoggerFactory loaded from file:/target/classes/). If you are using WebLogic you will need to add 'org.slf4j' to prefer-application-packages in WEB-INF/weblogic.xml: com.keyniu.dis.logger.KeyniuLoggerFactory
	at org.springframework.util.Assert.instanceCheckFailed(Assert.java:592)
	at org.springframework.util.Assert.isInstanceOf(Assert.java:511)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.getLoggerContext(LogbackLoggingSystem.java:401)
	at org.springframework.boot.logging.logback.LogbackLoggingSystem.beforeInitialize(LogbackLoggingSystem.java:128)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationStartingEvent(LoggingApplicationListener.java:238)

原因是spring的LogbackLoggingSystem要求ILoggerFactory返回的LoggerFactory对象必须实现LoggerContext，而LoggerContext.getLog是一个final方法、返回的类是final类，这条路走不通。
在这里插入图片描述

5. 修改logback实现

    public final Logger getLogger(Class<?> clazz) {
        return this.getLogger(clazz.getName());
    }

修改logback的ch.qos.logback.classic.LoggerContext的getLogger实现，返回KeyniuLogger，虽然可用，但是修改第三方包并不是好的想法。暂时采用第2步的方案。