五年Java經驗,面試還是說不出日誌該怎麼寫更好?

java識堂 發佈 2020-01-23T07:16:45+00:00

複製代碼可以看得出log4j2 與 logback 配置文件書寫大同小異,甚至同樣需要注意additivity="true"時導致的日誌重複輸出問題,畢竟 log4j1 與 logback 都是 Ceki大神都作品。

概覽

各位小夥伴大家好,我又回來更新了,上一篇我們討論了為什麼要使用日誌框架,這次我們深入問題的根源,為什麼我們需要日誌,日誌具體如何使用?

大多數開發人員會糾結日誌該怎麼輸出,什麼時候輸出,輸出了會不會有人看等問題,讓我們跳出開發人員的局限來考慮這個問題:誰需要日誌?日誌有幾種?日誌都需要輸出什麼?如何輸出日誌?

誰需要日誌?

  • 開發者 開發人員在開發過程中需要輸出一些變量方便調試,正確的做法是使用日誌來輸出(使用 System.out來輸出,一不小心發布到線上,會被項目經理痛批);其次線上問題很難重放,用戶的表述一般都會失真,況且很多用戶發現 bug 就刪 app 關網頁走人了
  • 運維人員 整個系統大部分時間都是運維人員來維護,日誌可以幫助運維人員來了解系統狀態(很多運維繫統接入的也是日誌),運維人員發現日誌有異常信息也可以及時通知開發來排查
  • 運營人員 沒錯,就是運營人員,比如電商的轉化率、視頻網站的完播率、普通PV數據等都可以通過日誌進行統計,隨著大數據技術的普及,這部分日誌占比也越來越高
  • 安全人員 雖然大多數企業不重視安全,但是安全也可以通過日誌來進行預警,比如某個用戶突然大額轉帳、再比如資料庫突然出現大量無條件分頁查庫(拖庫)等等

日誌有幾種?

  • 調試日誌 用於開發人員開發或者線上回溯問題。
  • 診斷日誌 一般用於運維人員監控系統與安全人員分析預警。
  • 埋點日誌 一般用於運營決策分析,也有用作微服務調用鏈路追蹤的(運維、調試)。
  • 審計日誌 與診斷日誌類似,診斷日誌偏向運維,審計日誌偏向安全。

日誌都需要輸出什麼?

註:日誌級別會在下面講解

  • 調試日誌 DEBUG 或者 TRACE 級別,比如方法調用參數,網絡連接具體信息,一般是開發者調試程序使用,線上非特殊情況關閉這些日誌 INFO 級別,一般是比較重要卻沒有風險的信息,如初始化環境、參數,清理環境,定時任務執行,遠程調用第一次連接成功 WARN 級別,有可能有風險又不影響系統繼續執行的錯誤,比如系統參數配置不正確,用戶請求的參數不正確(要輸出具體參數方便排查),或者某些耗性能的場景,比如一次請求執行太久、一條 SQL 執行超過兩秒,某些第三方調用失敗,不太可能被運行的if分支等 ERROR 級別,用於程序出錯列印堆棧信息,不應該用於輸出程序問題之外的其他信息,需要注意列印了日誌異常(Exception)就不應該拋(throw)了
  • 診斷日誌 一般輸出 INFO 級別,請求響應時間,內存占用等等,線上接入監控系統時打開,建議輸出到獨立的文件,可以考慮 JSON 格式方便外部工具分析
  • 埋點日誌 業務按需定製,比如上文提到的轉化率可以在用戶付款時輸出日誌,完播率可以在用戶播放完成後請求一次後台輸出日誌,一般可輸出 INFO 級別,建議輸出到獨立的文件,可以考慮JSON格式方便外部工具分析
  • 審計日誌 大多 WARN 級別或者 INFO 級別,一般是敏感操作即可輸出,登陸、轉帳付款、授權消權、刪除等等,建議輸出到獨立的文件,可以考慮JSON格式方便外部工具分析

一般調試日誌由開發者自定義輸出,其他三種應該根據實際業務需求來定製。

日誌的其他注意點

  1. 線上日誌應儘量謹慎,要思考:這個位置輸出日誌能幫助排除問題嗎?輸出的信息與排查問題相關嗎?輸出的信息足夠排除問題嗎?做到不少輸出必要信息,不多輸出無用信息(拖慢系統,淹沒有用信息)
  2. 超級 SessionId 與 RequestId,無論是單體應用還是微服務架構,應該為每個用戶每次登陸生成一個超級 SessionId,方便跟蹤區分一個用戶;RequestId,每次請求生成一個 RequestId,用於跟蹤一次請求,微服務也可以用於鏈路追蹤
  3. 日誌要儘量單行輸出,一條日誌輸出一行,否則不方便閱讀以及其他第三方系統或者工具分析
  4. 公司內部應該制定一套通用的日誌規範,包括日誌的格式,變量名(駝峰、下劃線),分隔符(「=」或「:」等),何時輸出(比如規定調用第三方前後輸出INFO日誌),公司的日誌規範應該不斷優化、調整,找到適合公司業務的最佳規範

OK,理論就聊到這裡,接下來讓我們回到技術層面。

使用概念

如果要想要學會使用日誌框架,先要理解幾個簡單概念,LoggerAppendersLayout日誌級別級別繼承(Level Inheritance)

Logger(日誌實例)

用於輸出日誌,調用一次org.slf4j.LoggerFactory#getLogger(java.lang.Class<?>)或org.slf4j.LoggerFactory#getLogger(java.lang.String)就會產生一個日誌實例,相同參數會共用同一個實例。

Appenders

日誌輸出器,logback 預定義了輸出到控制台、文件、Socket 伺服器、MySQL、PostgreSQL、Oracle 和其他資料庫、JMS 和 UNIX Syslog 系統調用等實現,通過配置文件配置即可使用,當然我們常用的只有控制台和文件兩種。

Layout

用於控制日誌輸出格式,前文所說的」自動輸出日誌相關信息,如:日期、線程、方法名稱等等「就可以用 Layout 來控制,實際使用很簡單,寫一個 Layout 格式定義表達式(pattern)即可,使用方法類似於Java 的SimpleDateFomat。

日誌級別

RFC 5424 (page 11)規定了 8 種日誌級別,但是SLF4j 只定義了 5 種日誌級別,分別是 ERROR、WARN、INFO、DEBUG、TRACE 這五個級別從高到低,配置級別越高日誌輸出就越少,如下圖



我們看到滑動條上五個點正好對應五個級別,滑動指示器可以左右移動,指示器作為分界點,指示器左側都可以輸出,右側都不能輸出,左右調整指示器就可以調整日誌的輸出,滑倒右側就可以全部輸出,滑倒左側就可以減少輸出,那麼是否能夠徹底關閉輸出呢?答案是可以的,配置文件中還可以配置為 ALL 與 OFF,分別對應所有(等價於TRACE)與關閉。

級別繼承

理解了日誌級別,讓我們來考慮如下場景:

  • 某些重要業務輸出 INFO 級別,其他業務輸出WARN級別的日誌,同時關閉所有庫、框架的日誌

有需求就會有解決方案,其實很簡單,logback 與 log4j 都支持按照日誌實例來配置,現在問題解決了,但是新的問題又來了,如果線上所有日誌都輸出 INFO 級別,難道要一個一個配置嗎?這時候就就要請出我們上面所提到的級別繼承,如果 Java 一樣,logback 與 log4j 中也都是單根繼承模型,Java 中是 Object,日誌中是 ROOT,如下圖:



有了繼承機制,我們只需要將 ROOT 調整到 INFO 級別,再按照需求細化調整我們業務對應的 logger 實例級別即可滿足絕大多數場景。

Codding 實戰

問:把大象裝冰箱分幾步?分三步:1、引入依賴,2、編碼輸出日誌,3、調整配置文件。前文已經講過步驟一,如果沒有看過的讀者請移步公眾號查看往期回顧,這裡直接進入步驟二。

步驟二

如果項目中使用了Lombok,那麼可以直接在類上面加@Slf4j註解既可獲得日誌實例,否則可以使用static final org.slf4j.Logger logger = LoggerFactory.getLogger(TestLog.class);來獲取日誌實例

具體日誌輸出方法如下:

logger.trace("A TRACE Message");
logger.debug("A DEBUG Message");
logger.info("An INFO Message");
logger.warn("A WARN Message");
logger.error("An ERROR Message");
複製代碼

這裡有個注意點,儘量使用參數占位而不要手動拼接字符串,如下

String level = "Trace";
// 反例
logger.trace("A " + level + " Message");
// 正確的做法
logger.trace("A {} Message", level);
複製代碼

這樣做可以提高效率,如果不輸出日誌,第一種情況也會拼接字符串造成性能損耗,第二種就不會有此問題(阿里巴巴Java開發手冊(華山版)這裡表述有問題,占位符效率更高是因為儘量延遲進行字符串處理,如果不需要輸出的日誌就不處理了,下一篇原理分析會展開),另外我們也不需要if (logger.isTraceEnabled())來進行判斷了(性能損耗不高,但是代碼好看多了)。

步驟三

配置文件需要區分 logback 與 log4j2,兩種框架在配置文件上有差別但很相似,來看具體配置文件。

logback 配置文件位置

logback 支持 xml 與 groovy 腳本兩種配置方式,logback 查找配置文件位置規則如下(後續文章會講如何修改位置)

  1. logback 嘗試在類路徑中找到一個名為 logback-test.xml 的文件。
  2. 如果找不到此類文件,則 logback 會嘗試在類路徑中找到名為 logback.groovy 的文件。
  3. 如果找不到這樣的文件,它將在類路徑中檢查文件 logback.xml。
  4. 如果找不到此類文件,則通過查找文件 META-INF\services\ch.qos.logback.classic.spi.Configurator,如果有這個文件且內容是 com.qos.logback.classic.spi.Configurator 實現類的全類名,直接加載這個實現類。
  5. 如果以上方法均不能成功執行,則 logback 會使用 BasicConfigurator 自動進行自我配置,會將日誌輸出到控制台。

這段長長的文字其實不用看,我們就把 logback.xml 放入 Classpath 根目錄就可以了。。

logback 配置文件編寫規則

logback 配置文件主要分為三類,一個或多個 Appender,用於定義輸出位置(不同文件位置,或者網絡又或者資料庫);一個或多個 Logger,用於細化配置不同 logger 的輸出級別以及位置;一個 ROOT,是一個特殊的logger,用於配置根 Logger。



我們一起來看下面的配置文件實例

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false" debug="false">

    <!-- 定義日誌文件的存儲地 -->
    <property name="LOG_PATH" value="/var/log"/>

    <property name="CONSOLE_LOG_PATTERN"
              value="%d{HH:mm:ss.SSS} %-5level [%10.10thread] %-30.30logger{29}\(%4L\\) - %msg%n"/>
    <!-- 控制台輸出 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

    <!-- 文件日誌格式(列印日誌,不列印行號) -->
    <property name="FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%10.10thread] %-30.30logger{29} - %msg%n"/>

    <appender name="FILE_ALL" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在記錄的日誌文件的路徑及文件名 -->
        <file>${LOG_PATH}/log.log</file>
        <!-- 日誌記錄器的滾動策略,按日期,按大小記錄 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!-- yyyy-MM-dd 按日滾動 -->
            <fileNamePattern>${LOG_PATH}/log-%d{yyyy-MM-dd}.%i.log</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>

    <!-- 日誌輸出級別 STDOUT:控制台;FILE_ALL:文件 -->
    <root level="warn">
        <appender-ref ref="STDOUT"/>
    </root>
    <logger name="druid.sql" level="warn" additivity="true"/>
    <logger name="druid.sql.ResultSet" level="warn" additivity="true"/>
    <logger name="com.alibaba.druid.pool.DruidDataSource" level="debug" additivity="true">
        <appender-ref ref="FILE_ALL"/>
    </logger>
</configuration>
複製代碼

上面配置文件定義了兩個 Appender,一個輸出控制台,另一個輸出到文件並且自動滾動。需注意的是property標籤相當於定義一個變量,可以使用${xxx}進行引用,CONSOLE_LOG_PATTERN 與 FILE_LOG_PATTERN 定義了控制台與文件列印格式,具體編寫方式類似於 Java 的SimpleDateFomat就不在此展開了,具體可以參考

  • logback:logback.qos.ch/manual/layo…
  • log4j:logging.apache.org/log4j/2.x/m…

log4j2 配置文件位置

log4j2 支持 XML、JSON、YAML 或者 properties 格式的配置文件,具體查找方式如下:

  1. 檢查「 log4j.configurationFile」系統屬性,如果有,嘗試使用與文件擴展名匹配的ConfigurationFactory加載配置。
  2. 如果未設置系統屬性,則屬性 ConfigurationFactory 將在類路徑中查找 log4j2-test.properties。
  3. 如果找不到此類文件,則 YAML ConfigurationFactory將在類路徑中查找 log4j2-test.yaml或log4j2-test.yml。
  4. 如果找不到此類文件,則 JSON ConfigurationFactory 將在類路徑中查找 log4j2-test.json或log4j2-test.jsn。
  5. 如果找不到這樣的文件,XML ConfigurationFactory 將在類路徑中查找 log4j2-test.xml。
  6. 如果找不到測試文件,則屬性 ConfigurationFactory 將在類路徑上查找 log4j2.properties。
  7. 如果找不到屬性文件,則 YAML ConfigurationFactory 將在類路徑上查找 log4j2.yaml或log4j2.yml。
  8. 如果無法找到 YAML 文件,則 JSON ConfigurationFactory 將在類路徑上查找 log4j2.json或log4j2.jsn。
  9. 如果無法找到 JSON 文件,則 XML ConfigurationFactory 將嘗試在類路徑上找到 log4j2.xml。
  10. 如果找不到配置文件,使用 DefaultConfiguration 自動配置,將日誌輸出到控制台。

這段更長的文字當然也不用看,我們就把 log4j2.xml 放入 Classpath 根目錄就可以了

log4j2 配置文件編寫

log4j 也是 Logger 與 Appender 配置項,也有一個ROOT的特殊 Logger,Appender 比logback支持更多輸出位置,如kafka、Cassandra、Flume等。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" strict="true">
    <!--  定義變量,可以被${xxx}引用  -->
    <Properties>
        <Property name="baseDir">logs</Property>
    </Properties>

    <!--  定義 Appenders 用來指定輸出位置 -->
    <Appenders>
        <!-- 日誌滾動 $${date:yyyy-MM}:按月滾動文件夾 按小時、文件序號滾動,每次滾動都使用gz壓縮 -->
        <RollingFile name="RollingFile" fileName="${baseDir}/log.log"
                     filePattern="${baseDir}/$${date:yyyy-MM}/log-%d{yyyy-MM-dd-HH}-%i.log.gz">
            <!-- 日誌格式 -->
            <PatternLayout pattern="%d %p %c{1.} [%t] %m%n"/>
            <Policies>
                <!-- 時間滾動(按月滾動目錄,按小時滾動文件) -->
                <TimeBasedTriggeringPolicy/>
                <!-- 文件大小滾動(1小時內超過250M,強制滾動一次) -->
                <SizeBasedTriggeringPolicy size="250 MB"/>
            </Policies>
            <!-- 每天最多100個文件 -->
            <DefaultRolloverStrategy max="100">
                <!-- 刪除策略,超過三十天刪除,如果總文件小於100G,文件數量小於10個,則不會被刪除 -->
                <Delete basePath="${baseDir}" maxDepth="2">
                    <IfFileName glob="*/app-*.log.gz">
                        <IfLastModified age="30d">
                            <IfAny>
                                <IfAccumulatedFileSize exceeds="100 GB"/>
                                <IfAccumulatedFileCount exceeds="10"/>
                            </IfAny>
                        </IfLastModified>
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>

    <Loggers>
        <!-- 多個logger -->
        <Logger name="org.apache.logging.log4j.test2" level="debug" additivity="false">
            <AppenderRef ref="RollingFile"/>
        </Logger>

        <!-- 一個ROOT -->
        <Root level="trace">
            <AppenderRef ref="STDOUT"/>
        </Root>
    </Loggers>
</Configuration>
複製代碼

可以看得出 log4j2 與 logback 配置文件書寫大同小異,甚至同樣需要注意additivity="true"時導致的日誌重複輸出問題,畢竟 log4j1 與 logback 都是 Ceki大神都作品。

總結

得益於 Ceki 大佬的努力,日誌使用幾乎沒有有差異(Logback 與 Log4j2,Google 於 2018年4月開源了流式(fluent)日誌框架 Flogger,Slf4j 也將在 2.0 版本支持,而 log4j2 再次落後,不過筆者認為 log4j2 有很多優點,更多內容請關注後續文章)。關於日誌如何輸出本人也是經驗之談,免不了紕漏,歡迎補充指正,另外每個公司都有不同的應用場景,具體應該遵守公司統一規範。

本篇更多傾向基礎使用,接下來的文章將展開對比、原理以及擴展日誌框架,敬請各位小夥伴們期待。



作者:雞員外連結:https://juejin.im/post/5e1472776fb9a047f42e659c

關鍵字: