動態調整日誌級別

背景

隨着外賣業務的快速發展，業務複雜度不斷增長，線上系統環境有任何細小波動，對整個外賣業務均可能產生巨大的影響，甚至造成災難性的雪崩效應，形成巨大的經濟損失。每一次客訴、系統抖動等都是對技術人員的重大考驗，咱們必須當即響應，快速解決問題。

如何提升排查問題的效率呢？最有效的方式是經過分析系統日誌。若是系統日誌全面，會爲咱們排查解決線上問題帶來絕大的幫助，可是要想保證系統日誌全面，就必須打印出全部的系統或業務日誌。這樣就會帶來另外一個問題，那就是日誌量的暴漲，過多的日誌除了可以幫助咱們解決問題外，同時會直接形成系統性能降低，極端狀況下，甚至致使系統宕機。在這種背景下，爲了兼顧性能和快速響應線上問題，咱們設計開發了日誌級別動態調整組件。經過使用該組件，能夠在須要解決線上問題時，實時調整線上日誌輸出級別，獲取全面的Debug日誌，幫助工程師提升定位問題的效率。

簡介

使用場景

場景一

業務依賴複雜。某一時刻，依賴的下游服務故障，致使請求大量超時，尤爲是像外賣這種集中性特別明顯的業務，平均每秒QPS在8000以上，1分鐘的故障就會集中產生大量的錯誤日誌，致使磁盤IO急劇提升，耗費大量CPU，進而致使整個服務癱瘓。若是該業務不能當即降級，怎麼辦？

從代碼級別解決問題到發版上線，暫且不說流程長、操做麻煩，同時還存在引入其它故障的高風險。若是系統剛好使用Log4j版本，在極短期內打印出了海量錯誤日誌，會快速耗盡Buffer區內存，從而拖慢主線程，形成服務性能總體降低，甚至尚未來得及修復問題，海量日誌已經拖垮服務，形成服務宕機，損失慘重。

場景二

大量的訂單、結算等客訴問題反饋過來，一線工程師大量精力埋沒於排查問題中，而排查定位問題的最終手段仍然是依賴線上日誌。因爲鏈路較長，任一日誌的缺失，都給問題的排查帶來極大的障礙，面對運營的催促，怎麼辦？

工程師爲了之後排查問題的方便，在任一可能出現異常的地方，都會打印出關鍵日誌，而後發版上線。但好不容易解決了本次問題，還沒來得及收穫喜悅，就又面臨着一個新問題，那就是場景三。

場景三

因爲線上業務系統默認日誌打印級別是INFO級別，爲了排查問題方便，調試型日誌都以該級別打印出來。這樣的話給系統帶來了額外的負擔，在高峯期大量調試日誌時會拖慢系統性能，增大出故障的風險，怎麼辦？

一方面要快速響應業務，另外一方面要兼顧系統性能，能不能兩方面兼顧？咱們的動態調整日誌級別工具正是爲了解決這種痛點。

能解決哪些問題

1. 日誌降級。 兼容Log4j、Log4j2和Logback主流日誌框架，若是遇到場景一，能夠經過咱們的日誌工具，快速調整日誌輸出級別，下降系統日誌的輸出，從而達到日誌降級的效果，同時可以給RD爭取充裕的排查問題時間。
2. 規範日誌級別濫用，幫助工程師快速定位解決線上問題。 使用日誌級別動態調整組件，能夠實時動態調整線上服務的日誌打印級別，調試型日誌可使用低級別打印出，減輕線上服務的負載壓力。遇到排查問題時，能夠臨時將日誌級別調低，快速獲得精準化的日誌信息，排查解決問題。

系統基礎架構

日誌級別動態調整組件定位爲中間件，在設計之初重點考慮瞭如下幾點：

1. 低侵入性

   • 接入服務僅須要引入JAR包和XML配置文件便可，不存在額外編碼工做，業務耦合低、接入成本小。

2. 安全可靠

   • 更改接入服務的日誌輸出級別，只能經過咱們提供的管理系統，全部的操做記錄有跡可查。
   • 引入權限認證，確保工程師只能操做本身負責的服務或系統，同時會把操做內容實時周知給系統的全部相關責任人，避免誤傷。

3. 可視化操做

   • 操做者能夠經過咱們提供的管理頁面，定向修改一個或一批服務節點。
   • 提供可視化的操控開關，能夠隨時關閉或開啓服務。

具體實現

調用組件

本組件採用工廠模式實現，保障其高可擴展性。目前已實現日誌級別動態調整和方法調用處理單元，下面主要介紹日誌級別動態調整處理單元的實現。

目前美團外賣業務系統基本統一採用的SLF4J日誌框架，在應用初始化時，SLF4J會綁定具體的日誌框架，如Log4j、Logback或Log4j2等。具體源碼以下(slf4j-api-1.7.7)：

private final static void bind() {
  try {
    // 查找classpath下全部的StaticLoggerBinder類。
    Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet(); 
    reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
    // 每個slf4j橋接包中都有一個org.slf4j.impl.StaticLoggerBinder類，該類實現了LoggerFactoryBinder接口。
    // the next line does the binding
    StaticLoggerBinder.getSingleton();
    INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
    reportActualBinding(staticLoggerBinderPathSet);
    fixSubstitutedLoggers();
    ...
}

findPossibleStaticLoggerBinderPathSet方法用來查找當前classpath下全部的org.slf4j.impl.StaticLoggerBinder類。每個slf4j橋接包中都有一個StaticLoggerBinder類，該類實現了LoggerFactoryBinder接口。具體綁定到哪個日誌框架則取決於類加載順序。

接下來，我們分三部分，來講說ChangeLogLevelProcessUnit類：

1. 初始化：肯定所使用的日誌框架，獲取配置文件中全部的Logger內存實例，並將它們的引用緩存到Map容器中。

   String type = StaticLoggerBinder.getSingleton().getLoggerFactoryClassStr();
   if (LogConstant.LOG4J_LOGGER_FACTORY.equals(type)) {
    logFrameworkType = LogFrameworkType.LOG4J;
    Enumeration enumeration = org.apache.log4j.LogManager.getCurrentLoggers();
    while (enumeration.hasMoreElements()) {
        org.apache.log4j.Logger logger = (org.apache.log4j.Logger) enumeration.nextElement();
        if (logger.getLevel() != null) {
            loggerMap.put(logger.getName(), logger);
        }
    }
    org.apache.log4j.Logger rootLogger = org.apache.log4j.LogManager.getRootLogger();
    loggerMap.put(rootLogger.getName(), rootLogger);
   } else if (LogConstant.LOGBACK_LOGGER_FACTORY.equals(type)) {
    logFrameworkType = LogFrameworkType.LOGBACK;
    ch.qos.logback.classic.LoggerContext loggerContext = (ch.qos.logback.classic.LoggerContext) LoggerFactory.getILoggerFactory();
    for (ch.qos.logback.classic.Logger logger : loggerContext.getLoggerList()) {
        if (logger.getLevel() != null) {
            loggerMap.put(logger.getName(), logger);
        }
    }
    ch.qos.logback.classic.Logger rootLogger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
    loggerMap.put(rootLogger.getName(), rootLogger);
   } else if (LogConstant.LOG4J2_LOGGER_FACTORY.equals(type)) {
    logFrameworkType = LogFrameworkType.LOG4J2;
    org.apache.logging.log4j.core.LoggerContext loggerContext = (org.apache.logging.log4j.core.LoggerContext) org.apache.logging.log4j.LogManager.getContext(false);
    Map<String, org.apache.logging.log4j.core.config.LoggerConfig> map = loggerContext.getConfiguration().getLoggers();
    for (org.apache.logging.log4j.core.config.LoggerConfig loggerConfig : map.values()) {
        String key = loggerConfig.getName();
        if (StringUtils.isBlank(key)) {
            key = "root";
        }
        loggerMap.put(key, loggerConfig);
    }
   } else {
    logFrameworkType = LogFrameworkType.UNKNOWN;
    LOG.error("Log框架沒法識別: type={}", type);
   }

2. 獲取Logger列表：從本地Map容器取出。

   private String getLoggerList() {
    JSONObject result = new JSONObject();
    result.put("logFramework", logFrameworkType);
    JSONArray loggerList = new JSONArray();
    for (ConcurrentMap.Entry<String, Object> entry : loggerMap.entrySet()) {
        JSONObject loggerJSON = new JSONObject();
        loggerJSON.put("loggerName", entry.getKey());
        if (logFrameworkType == LogFrameworkType.LOG4J) {
            org.apache.log4j.Logger targetLogger = (org.apache.log4j.Logger) entry.getValue();
            loggerJSON.put("logLevel", targetLogger.getLevel().toString());
        } else if (logFrameworkType == LogFrameworkType.LOGBACK) {
            ch.qos.logback.classic.Logger targetLogger = (ch.qos.logback.classic.Logger) entry.getValue();
            loggerJSON.put("logLevel", targetLogger.getLevel().toString());
        } else if (logFrameworkType == LogFrameworkType.LOG4J2) {
            org.apache.logging.log4j.core.config.LoggerConfig targetLogger = (org.apache.logging.log4j.core.config.LoggerConfig) entry.getValue();
            loggerJSON.put("logLevel", targetLogger.getLevel().toString());
        } else {
            loggerJSON.put("logLevel", "Logger的類型未知,沒法處理!");
        }
        loggerList.add(loggerJSON);
    }
    result.put("loggerList", loggerList);
    LOG.info("getLoggerList: result={}", result.toString());
    return result.toString();
   }

3. 修改Logger的級別。

   private String setLogLevel(JSONArray data) {
    LOG.info("setLogLevel: data={}", data);
    List<LoggerBean> loggerList = parseJsonData(data);
    if (CollectionUtils.isEmpty(loggerList)) {
        return "";
    }
    for (LoggerBean loggerbean : loggerList) {
        Object logger = loggerMap.get(loggerbean.getName());
        if (logger == null) {
            throw new RuntimeException("須要修改日誌級別的Logger不存在");
        }
        if (logFrameworkType == LogFrameworkType.LOG4J) {
            org.apache.log4j.Logger targetLogger = (org.apache.log4j.Logger) logger;
            org.apache.log4j.Level targetLevel = org.apache.log4j.Level.toLevel(loggerbean.getLevel());
            targetLogger.setLevel(targetLevel);
        } else if (logFrameworkType == LogFrameworkType.LOGBACK) {
            ch.qos.logback.classic.Logger targetLogger = (ch.qos.logback.classic.Logger) logger;
            ch.qos.logback.classic.Level targetLevel = ch.qos.logback.classic.Level.toLevel(loggerbean.getLevel());
            targetLogger.setLevel(targetLevel);
        } else if (logFrameworkType == LogFrameworkType.LOG4J2) {
            org.apache.logging.log4j.core.config.LoggerConfig loggerConfig = (org.apache.logging.log4j.core.config.LoggerConfig) logger;
            org.apache.logging.log4j.Level targetLevel = org.apache.logging.log4j.Level.toLevel(loggerbean.getLevel());
            loggerConfig.setLevel(targetLevel);
            org.apache.logging.log4j.core.LoggerContext ctx = (org.apache.logging.log4j.core.LoggerContext) org.apache.logging.log4j.LogManager.getContext(false);
            ctx.updateLoggers(); // This causes all Loggers to refetch information from their LoggerConfig.
        } else {
            throw new RuntimeException("Logger的類型未知,沒法處理!");
        }
    }
    return "success";
   }

上面介紹瞭如何拿到日誌配置文件中的Logger，以及修改Logger的級別。

通訊方式

咱們根據Web項目和純粹RPC項目，分別提供HTTP和Thrift兩種通訊協議。

場景1、Thrift服務

全部的請求信息都包含在JSON String的數據結構裏面，其中包含有簽名信息，請求時簽名驗證失敗將直接拋出異常。

引入組件提供的dynamic-invoker.xml配置，將會在系統中自動注入開啓一個專爲日誌級別調整的接口服務，該接口是一個單純的Thrift服務，可以經過ZooKeeper實現服務註冊與發現，而且有可視化的開啓與關閉管理後臺，簡單明瞭，操做方便。

場景2、HTTP服務

對於一些Web項目，暴露一個RPC服務至關不安全。爲此，咱們提供了HTTP協議接口，接入流程徹底同樣，在真正修改日誌輸出級別時，會根據系統類型自主判斷使用哪一種協議，有獨立實現的簽名認證，安全可靠。

結束語

從2016年9月V1.0版本上線以來，陸續接入外賣配送的20多個核心應用，覆蓋推送、接單、配送調度、斑馬配送、活動等核心交易服務。

舉例：

• 問題描述：發配送服務化項目因爲間接依賴，引入了Logback日誌框架。在項目啓動加載時，SLF4J動態綁定到Logback框架上，可是因爲發配送項目使用的Log4j，並未配置Logback.xml文件，致使在打印日誌時，SLF4J沒法匹配到具體的日誌配置，從而爲項目自動建立了一個日誌級別爲Debug的ROOT節點，全部的日誌以該級別打印輸出，致使發配送服務化項目在中午11：30左右高峯期，短期內打印過多的系統日誌，引發Load飆高，從新修改發版上線已經來不及，若是不能當即解決，勢必形成服務化宕機，損失很是嚴重。

• 處理結果：使用咱們這個日誌工具，批量將服務化項目全部的日誌輸出級別調整爲ERROR級別，大大減小了日誌量的輸出，給工程師留出充裕的的時間完美的解決了該問題，避免形成更大的系統故障。

• 後記：更重要的是以該工具組件爲切入點，幫助各業務系統逐漸規範系統日誌使用，取得很好效果。

後續咱們規劃將其推廣成爲公司級別的工具，爲愈來愈多的項目提供便利。

歡迎感興趣的同窗與咱們進一步交流。