這么香的日志動態級別與輸出，你確定不進來看看？——生產環境動態輸入日志級別、文件

本文是一個系列，歡迎關注更新

本文全篇高能，請做好心理准備后再食用，讀完請記得點贊。

前言

上一篇我們討論了日志的性能以及日志的優缺點，有朋友說我沒有干貨，痛定思痛，決定來一篇干貨，讓小伙伴們見識一下員外真正的實力💪，討論一下生產環境如何動態按一次請求、一個用戶來調整日志級別，甚至輸出獨立文件。本文代碼較多，建議讀者運行一下。

設想一個需求：客服妹妹反饋有用戶線上發現了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