这么香的日志动态级别与输出，你确定不进来看看？——生产环境动态输入日志级别、文件

本文是一个系列，欢迎关注更新

本文全篇高能，请做好心理准备后再食用，读完请记得点赞。

前言

上一篇我们讨论了日志的性能以及日志的优缺点，有朋友说我没有干货，痛定思痛，决定来一篇干货，让小伙伴们见识一下员外真正的实力💪，讨论一下生产环境如何动态按一次请求、一个用户来调整日志级别，甚至输出独立文件。本文代码较多，建议读者运行一下。

设想一个需求：客服妹妹反馈有用户线上发现了BUG，你拿来日志分析，一个 200M 的日志文件看的头大，最后还是没找到有用的信息，你终于决定开启 DEBUG 日志，重启了项目，让用户再次操作一下，结果开了两分钟线上磁盘就告警了，于是你被运维人员痛批一顿，因为停生产环境又被 BOSS 大批一顿。

试着给自己当一下产品经理，提些需求：

先定一个小目标，我们能不能不停机就动态调整级别？
我们能不能将某一个用户甚至一次请求动态调整日志级别？
让我们进入强者的世界，不仅仅要按照用户动态级别，是否能按照用户、请求临时输出一个文件？

整理了以上需求，我们来尝试逐一解决。

实战一动态调整日志级别（小目标实现）

这个需求很简单，想必大家也都会，Logback 和 Log4j2 都原生实现了日志监控日志文件热加载，使用起来也特别简单，只需要在配置文件中修改，当然，框架作者为了混（e）淆（xin）使用者，使用了不一样的配置方式：

<!-- logback 配置 -->
<configuration scan="true" scanPeriod="30 seconds" > 
  ...
</configuration> 

<!-- log4j2 配置 -->
<Configuration monitorInterval="30">
...
</Configuration>

实战二更厉害的动态调整日志输出级别

如此简单的实现，不能很好满足我们的需求，我们决定再接再厉，毕竟我们是有追求的人。

我们来分解一下问题：

想要根据用户来动态级别，我们肯定要区分出用户；
想要根据请求来区分日志级别，我们需要识别请求；
想要动态调整日志级别，我们需要分析日志框架的实现；

我们来逐一解决问题：

区分用户，还需要分解问题，主流 Web 项目有两种，老项目会使用 Session，新项目多使用 Token：
Session ：Session 比较方便，放入 Session 一个日志级别即可。
Token ： Token 也不复杂，提供一种解决方案，可以将 Token 放入到缓存，比如 Redis、数据库来存储（不推荐存数据库）。
区分请求：
给用户提供按钮，配合单页面应用，将所有 HTTP 请求附带一个参数，此方法危险，不适合互联网项目。
特殊需求，在开发过程中编码写入代码中。

区分用户最佳实践，给管理员开放功能，列出在线用户，点击用户即可选择用户输出的日志级别。

动态调整日志级别，这个是我们最棘手的地方，分析Logback API 会发现 ch.qos.logback.classic.Logger已经提供了#setLevel方法，这个方法看似能够在运行过程中改变日志的输出级别，但是读过我之前文章的小伙伴肯定知道，Logger 实例建议static final，所以Logger实例是多线程共享的，如果我们修改了Logger的级别，肯定会污染其他请求乃至其他用户，看来这样是行不通了，如何解决？

没办法时只有两条路线，阅读源码以及翻阅文档，我们先从源码入手，我们先来分析一下Logback是如何决定是否输出一条日志的：

我们随便输出一条日志log.debug("A debug Log");，断点跟进去，发现真正的判断逻辑在filterAndLog_0_Or3Plus，源码如下：

private void filterAndLog_0_Or3Plus(final String localFQCN, 
                                  final Marker marker, 
                                  final Level level, 
                                  final String msg, 
                                  final Object[] params,
                                  final Throwable t) {
// 神奇的方法
final FilterReply decision = loggerContext
  .getTurboFilterChainDecision_0_3OrMore(marker, this, level, 
                                         msg, params, t);
// 如果上面神奇的方法返回 NEUTRAL 才判断日志级别
if (decision == FilterReply.NEUTRAL) {
  if (effectiveLevelInt > level.levelInt) {
    return;
  }
  // 返回 DENY 根本就不判断日志级别了
} else if (decision == FilterReply.DENY) {
  return;
}
// 如果能够执行到这里，则输出日志
buildLoggingEventAndAppend(localFQCN, marker, 
                           level, msg, params, t);
}

分析源码我们得出结论，神奇的方法返回值优先级要高于日志级别判断，这样就有意思了，我们能不能定制那个神奇方法呢，继续跟进去发现，TurboFilterList继承了CopyOnWriteArrayList<TurboFilter>，其本身就是一个List，其中的TurboFilterList#getTurboFilterChainDecision里面逻辑就是循环自己获取FilterReply然后返回，一起看一下代码：

public FilterReply getTurboFilterChainDecision(final Marker marker, 
                                             final Logger logger, 
                                             final Level level, 
                                             final String format, 
                                             final Object[] params,
                                             final Throwable t) {

final int size = size();
// 如果只有一个，直接返回结果，期间如果异常直接返回 NEUTRAL
// size不可能是0，因为调用者已经判断了，这里不再展示
if (size == 1) {
  try {
    TurboFilter tf = get(0);
    return tf.decide(marker, logger, level, 
                     format, params, t);
  } catch (IndexOutOfBoundsException iobe) {
    return FilterReply.NEUTRAL;
  }
}
// 如果有多个，循环获取第一个不是 NEUTRAL 的结果返回，其他不再判断
Object[] tfa = toArray();
final int len = tfa.length;
for (int i = 0; i < len; i++) {
  // for (TurboFilter tf : this) {
  final TurboFilter tf = (TurboFilter) tfa[i];
  final FilterReply r = tf
    .decide(marker, logger, level, format, params, t);
  if (r == FilterReply.DENY || r == FilterReply.ACCEPT) {
    return r;
  }
}
return FilterReply.NEUTRAL;
}

为什么作者要把一个TurboFilter时的逻辑与多个TurboFilter时的逻辑分开写？关注公众号回复TurboFilter获取答案（额外有一段解析，作为微信粉丝福利）。

梳理一下思路，每一条日志，无论级别，最终都会进入filterAndLog_0_Or3Plus方法进行判断是否输出，而其判断又会优先判断TurboFilterList#getTurboFilterChainDecision的返回值，getTurboFilterChainDecision中使用了TurboFilter，跟进源码我们发现TurboFilterList是空的，我们几乎可以断言，作者不会平白无故搞一个空的List，一定是用来给我们扩展的，我们去翻翻文档，肯定找得到扩展方法，翻看文档中关于TurboFilters的部分，我们找到如下描述：

TurboFilters

TurboFilter objects all extend the TurboFilter abstract class. Like the regular filters, they use ternary logic to return their evaluation of the logging event.

Overall, they work much like the previously mentioned filters. However, there are two main differences between Filter and TurboFilter objects.

TurboFilter objects are tied to the logging context. Hence, they are called not only when a given appender is used, but each and every time a logging request is issued. Their scope is wider than appender-attached filters.

More importantly, they are called before the LoggingEvent object creation. TurboFilter objects do not require the instantiation of a logging event to filter a logging request. As such, turbo filters are intended for high performance filtering of logging events, even before the events are created.

大概意思和我们分析的也差不多，TurboFilter也可以控制日志是否能够输出，而且优先级要高于普通的Filter，这不奇怪，毕竟Turbo嘛。

文档中给出了实例，接下来我们来定义一个自己TurboFilter吧。

/**
 * DynamicLoggingFilter
 *
 * @author jiyanwai
 * @date 2020-01-15 16:09:16
 */
@Slf4j
public class DynamicLoggingFilter extends TurboFilter {

  public static final String DEBUG_HEADER_NAME = "X-Debug";
  public static final String DEBUG_SESSION_KEY = DEBUG_HEADER_NAME;

  /**
   * 返回值 FilterReply.DENY，FilterReply.NEUTRAL或FilterReply.ACCEPT
   * 如果是 DENY，则不会再输出
   * 如果是 ACCEPT，则直接输出
   * 如果是 NEUTRAL，走来日志输出判断逻辑
   *
   * @return FilterReply.DENY，FilterReply.NEUTRAL或FilterReply.ACCEPT
   */
  @Override
  public FilterReply decide(Marker marker, Logger logger, Level level,
                            String format, Object[] params, Throwable t) {

    // 这里可以过滤我们自己的logger
    boolean isMyLogger = logger.getName().startsWith("com.jiyuanwai");
    if (!isMyLogger) {
      return FilterReply.NEUTRAL;
    }

    RequestAttributes requestAttributes = RequestContextHolder
        .getRequestAttributes();

    // 项目启动或者运行定时器时，可能没有 RequestAttributes
    if (requestAttributes == null) {
      return FilterReply.NEUTRAL;
    }

    // 先判断 RequestHeader，用于区分线程
    ServletRequestAttributes servletRequestAttributes =
        (ServletRequestAttributes) requestAttributes;
    // 按照请求参数判断，实际生产环境可以开发功能给管理人员功能，将用户唯一标示放入缓存或者session
    HttpServletRequest request = servletRequestAttributes.getRequest();
    String debug = request.getHeader(DEBUG_HEADER_NAME);
    boolean debugBoolean = Boolean.parseBoolean(debug);
    if (debugBoolean) {
      return FilterReply.ACCEPT;
    }

    // 再判断 Session
    HttpSession session = request.getSession(false);
    if (session == null) {
      return FilterReply.NEUTRAL;
    }
    Object attribute = session.getAttribute(DEBUG_SESSION_KEY);
    debugBoolean = Boolean.parseBoolean((String) attribute);
    if (debugBoolean) {
      return FilterReply.ACCEPT;
    }

    return FilterReply.NEUTRAL;
  }

}

日志配置文件调整如下：

<configuration scan="false" debug="false">
    <turboFilter class="com.jiyuanwai.logging.extend.dynamic.DynamicLoggingFilter" />
    ...
    <root level="error">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

写一个方法测试一下

@GetMapping
public void debugLevel() {
  log.debug("A debug Log");
}

这里推荐大家使用Idea内置的 HTTP Request：

HTTP Request

# 测试 RequestHeader 使用
GET http://localhost:8082/log/level
Accept: */*
# 通过Header，避免污染请求参数（否则文件上传会有问题）
X-Debug: true
Cache-Control: no-cache

###

执行之后，可以在控制台看到：

22:50:19.816 DEBUG [082-exec-5] c.j.l.e.c.LogController       (  35) - A debug Log


我们完成了按照请求来动态调整日志。

继续测试一下Session，这里我就简单处理，仅仅在 Controller 增加一下作为测试，线上可以配合在线用户管理功能实现，小伙伴们可以按需扩展，如果有困难可以留言，我收集大家的困难统一解决。

@PutMapping
public void startDebugBySession(HttpSession session) {
  // 仅供测试，线上需要开发功能，获取对对应用户 session，然后放入属性
  session.setAttribute(DynamicLoggingFilter.DEBUG_SESSION_KEY, "true");
}

开启 Session 级别 debug 请求如下

# 以 Session 开启当前用户 DEBUG 模式
PUT http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache

###

# 去掉自定义Header，再次测试
GET http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache

###

结果如下

09:28:16.662 DEBUG [082-exec-1] c.j.l.e.c.LogController       (  40) - A debug Log

Tocken 与 Session 几乎没有差别，这里就不再展示了。

至此，我们已经很优雅的实现了按照请求、按照用户来动态输出日志，可以自豪一下了。

实战三强者的世界

让我们来实现最后一个需求，动态输出日志文件。

强者的世界

我们先分析一下需求，想要按照用户临时输出文件，区分用户可以使用之前的方法，我们需要解决的问题是，我们如何将特定的用户输出到特定的文件？

读过员外以前文章的朋友都知道，真正负责输出日志的是 Appender，我们优先去翻翻文档看看官方有没有解决方案，经过一番硬啃文档，我们发现了 SiftingAppender配合discriminator再配合MDC 似乎能解决我们的需求，SiftingAppender可以根据用户会话分离日志事件，这样不同用户生成的日志就可以进入不同的日志文件，甚至可以每个用户一个日志文件。discriminator很好理解按照字面意思就是鉴别器可以用来鉴别，但MDC是什么？

"Mapped Diagnostic Context" is essentially a map maintained by the logging framework where the application code provides key-value pairs which can then be inserted by the logging framework in log messages. MDC data can also be highly helpful in filtering messages or triggering certain actions.

简单翻译一下，MDC 就是日志框架维护的一个Map，可以用来过滤和触发操作，员外总结了两个最佳实践：

读过以前文章的小伙伴（没读过的赶快关注公众号，点击往期回顾-日志系列即可查看）肯定还记得我提过的超级 SessionId 与RequestId，如何实现？当然是MDC，见下文。
另外就是discriminator配合MDC可以动态输出文件了，我们来试一下。

实现思路，使用Filter并且第一个执行，直接来看代码

/**
 * LogFilter 用于处理动态日志
 *
 * @author jiyanwai
 * @date 2020-01-16 06:05:19
 */
@Slf4j
@Component
@Order(Integer.MIN_VALUE)
@WebFilter("/*")
public class LogFilter implements Filter {

  public static final String REQUEST_ID_MDC_KEY = "requestId";
  public static final String SESSION_ID_MDC_KEY = "sessionId";
  public static final String STAND_ALONE_HEADER_KEY = "X-StandAlone-File";
  public static final String STAND_ALONE_SESSION_KEY = STAND_ALONE_HEADER_KEY;

  @Override
  public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain)
      throws IOException, ServletException {

    try {
      try {
        HttpServletRequest request = (HttpServletRequest) servletRequest;
        // requestId 与超级 SessionId，可以根据需求自行定制
        String requestId = CommonUtils.generateRequestId();
        MDC.put(REQUEST_ID_MDC_KEY, requestId);
        String sessionId = request.getRequestedSessionId();
        MDC.put(SESSION_ID_MDC_KEY, sessionId);

        // 只有开启了独立文件输出，才放入MDC
        String standAlone = request.getHeader(STAND_ALONE_HEADER_KEY);
        if (standAlone == null) {
          standAlone = (String) request.getSession().getAttribute(STAND_ALONE_SESSION_KEY);
        }
        if (standAlone != null) {
          // 此处可以任意定制不同路径，sessionId会被拼接到文件名，参考下文修改后的xml
          MDC.put(STAND_ALONE_SESSION_KEY, sessionId);
        }

      } catch (Exception e) {
        // 此处处理异常，不影响业务
        log.error("Error handler dynamic log", e);
      }
      // 继续执行，不处理其他Filter异常
      filterChain.doFilter(servletRequest, servletResponse);
    } finally {
      // 切记要清理环境
      MDC.clear();
    }
  }
}

配置文件增加SiftAppender

<appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
  <discriminator>
    <key>X-StandAlone-File</key>
    <!-- MDC取不到，默认“all” -->
    <defaultValue>all</defaultValue>
  </discriminator>
  <sift>
    <!-- Appender Name需要独立 -->
    <appender name="FILE-${X-StandAlone-File}" class="ch.qos.logback.core.FileAppender">
      <!-- 正在记录的日志文件的路径及文件名 -->
      <!-- 输出位置，${X-StandAlone-File}取MDC -->
      <file>${LOG_PATH}/${X-StandAlone-File}.log</file>
      <!-- 日志记录器的滚动策略，按日期，按大小记录 -->
      <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <!-- 按日滚动 -->
        <fileNamePattern>${LOG_PATH}/%d{yyyy-MM}/log-%d{yyyy-MM-dd-HH}-%i.${X-StandAlone-File}.gz</fileNamePattern>
        <!-- 单个文件最大50M -->
        <maxFileSize>50MB</maxFileSize>
        <!--  最多占用5G磁盘空间，500个文件（总共不能超过该5G） -->
        <maxHistory>500</maxHistory>
        <totalSizeCap>5GB</totalSizeCap>
      </rollingPolicy>
      <!-- 追加方式记录日志 -->
      <append>true</append>
      <!-- 日志文件的格式 -->
      <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>${FILE_LOG_PATTERN}</pattern>
        <charset>utf-8</charset>
      </encoder>
    </appender>
  </sift>
  <root level="error">
    <!-- 为了方便测试，同时输出到控制台 -->
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="SIFT"/>
  </root>
</appender>

调整Controller增加方法

/**
    * 为当前用户开启debug，测试使用，生产环境请配合在线用户管理相关功能来实现
    *
    * @param session session
    */
@PutMapping
public void startDebugBySession(HttpSession session,
                                @RequestParam(required = false) boolean standAlone) {
  // 仅供测试，线上需要开发功能，获取对对应用户 session，然后放入属性
  session.setAttribute(DynamicLoggingFilter.DEBUG_SESSION_KEY, "true");
  if (standAlone) {
    session.setAttribute(LogFilter.STAND_ALONE_SESSION_KEY, "");
  }
}

先使用Header模式来测试没有开启独立输出会文件结构如何

# 测试 RequestHeader 使用
GET http://localhost:8082/log/level
Accept: */*
# 通过Header，避免污染请求参数（否则文件上传会有问题）
X-Debug: true
Cache-Control: no-cache

###

非独立输出文件

内容如下，可以看到我们的RequestId与超级SessionId都成功的写到日志里面了

2020-01-16 09:54:05.827 DEBUG [http-nio-8082-exec-1] c.j.l.extend.controller.LogController    --- requestId=ee77a879576147bcafdcb745ba5767d3, sessionId=21F4DE2AADBA675F2135601D760BF18E : A debug Log

使用Http Request进行测试开启 debug，并且开启独立文件

# 以 Session 开启当前用户 DEBUG 模式
PUT http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache
Content-Type: application/x-www-form-urlencoded

standAlone=true

###

测试日志输出

# 测试 Session 模式使用
GET http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache

###

独立输出文件

扩展

我们之前采用了日志框架原生解决动态级别，问题在于修改起来不方便，需要连接线上服务器采用vim来修改，上文提到了 Logback 提供了API可以直接热修改，我们来看一下：

/**
    * 修改单个日志级别
    *
    * @param loggerName 日志实例名称
    * @param level      级别
    */
@PostMapping
public void changeLoggingLevel(String loggerName,
                               @RequestParam(required = false, 
                                             defaultValue = "DEBUG") String level) {
  ch.qos.logback.classic.Logger logger =
    (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(loggerName);
  logger.setLevel(Level.toLevel(level));
}

测试一下：

# 测试 调整全局 日志级别
POST http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache
Content-Type: application/x-www-form-urlencoded

loggerName=ROOT

###

如果我们想要还原：

/**
    * 将日志级别重置为配置文件默认
    */
@DeleteMapping
public void restoreLoggingLevel() {
  LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();

  try {
    JoranConfigurator configurator = new JoranConfigurator();
    configurator.setContext(context);
    context.reset();
    configurator.doConfigure(new ClassPathResource("logback.xml").getInputStream());
  } catch (JoranException | IOException ignore) {
    // StatusPrinter will handle this
  }
  StatusPrinter.printInCaseOfErrorsOrWarnings(context);
}

继续测试

# 测试还原日志级别为配置文件级别
DELETE http://localhost:8082/log/level
Accept: */*
Cache-Control: no-cache

###

结束语

这一篇我们实现了按请求、用户级别动态输出级别与文件，现在已经应该能满足 99% 的场景了，员外只用过 Logback，如果读者想使用 Log4j2，可以按照思路尝试自己实现，如果点赞超过 1000，我也可以实现出来给大家用，下一篇我会做一些前文勘误、读者问题反馈，还有少量的最佳实践，欢迎关注更新。

最后给大家贴一张分析过程的思维导图，希望能够帮助大家学会分析、解决问题。

分析问题导图

以上是个人观点，如果有问题或错误，欢迎留言讨论指正，码字不易，如果觉得写的不错，求关注、求点赞、求转发。

扫码关注公众号，第一时间获得更新

扫码关注

代码：https://github.com/jiyuanwai/logging-extend

posted @ 2020-01-16 18:36 鸡员外阅读(2902) 评论(0) 编辑收藏举报

刷新页面返回顶部

一名程序员

这么香的日志动态级别与输出，你确定不进来看看？——生产环境动态输入日志级别、文件

前言

实战一动态调整日志级别（小目标实现）

实战二更厉害的动态调整日志输出级别

TurboFilters

实战三强者的世界

扩展

结束语

公告

一名程序员

这么香的日志动态级别与输出，你确定不进来看看？——生产环境动态输入日志级别、文件

前言

实战一 动态调整日志级别（小目标实现）

实战二 更厉害的动态调整日志输出级别

TurboFilters

实战三 强者的世界

扩展

结束语

公告

实战一动态调整日志级别（小目标实现）

实战二更厉害的动态调整日志输出级别

实战三强者的世界