日誌
日誌是什麼?
日誌,維基百科的定義是記錄服務器等電腦設備或軟件的運作。
日誌文件提供精確的系統記錄,根據日誌最終定位到錯誤詳情和根源。日誌的特點是,它描述一些離散的(不連續的)事件。 例如:應用通過一個滾動的文件輸出 INFO 或 ERROR 信息,並通過日誌收集系統,存儲到一些存儲引擎(Elasticsearch)中方便查詢。
日誌有什麼用?
- 在上文中我們解釋了日誌的作用是提供精準的系統記錄方便根因分析。那麼具體在哪些具體方面它可以發揮作用?
- 打印調試:即可以用日誌來記錄變量或者某一段邏輯。記錄程序運行的流程,即程序運行了哪些代碼,方便排查邏輯問題。
- 問題定位:程序出異常或者出故障時快速的定位問題,方便後期解決問題。因為線上生產環境無法 debug,在測試環境去模擬一套生產環境,費時費力。所以依靠日誌記錄的信息定位問題,這點非常重要。還可以記錄流量,後期可以通過 ELK(包括 EFK 進行流量統計)。
- 用戶行為日誌:記錄用戶的操作行為,用於大數據分析,比如監控、風控、推薦等等。這種日誌,一般是給其他團隊分析使用,而且可能是多個團隊,因此一般會有一定的格式要求,開發者應該按照這個格式來記錄,便於其他團隊的使用。當然,要記錄哪些行為、操作,一般也是約定好的,因此,開發者主要是執行的角色。
- 根因分析(甩鍋必備):即在關鍵地方記錄日誌。方便在和各個終端定位問題時,別人說時你的程序問題,你可以理直氣壯的拿出你的日誌說,看,我這裡運行了,狀態也是對的。這樣,對方就會乖乖去定位他的代碼,而不是互相推脫。
什麼時候記錄日誌?
上文說了日誌的重要性,那麼什麼時候需要記錄日誌。
- 系統初始化:系統或者服務的啟動參數。核心模塊或者組件初始化過程中往往依賴一些關鍵配置,根據參數不同會提供不一樣的服務。務必在這裡記錄 INFO 日誌,打印出參數以及啟動完成態服務表述。
- 編程語言提示異常:如今各類主流的編程語言都包括異常機制,業務相關的流行框架有完整的異常模塊。這類捕獲的異常是系統告知開發人員需要加以關注的,是質量非常高的報錯。應當適當記錄日誌,根據實際結合業務的情況使用 WARN 或者 ERROR 級別。
- 業務流程預期不符:除開平臺以及編程語言異常之外,項目代碼中結果與期望不符時也是日誌場景之一,簡單來說所有流程分支都可以加入考慮。取決於開發人員判斷能否容忍情形發生。常見的合適場景包括外部參數不正確,數據處理問題導致返回碼不在合理範圍內等等。
- 系統核心角色,組件關鍵動作:系統中核心角色觸發的業務動作是需要多加關注的,是衡量系統正常運行的重要指標,建議記錄 INFO 級別日誌,比如電商系統用戶從登錄到下單的整個流程;微服務各服務節點交互;核心數據表增刪改;核心組件運行等等,如果日誌頻度高或者打印量特別大,可以提煉關鍵點 INFO 記錄,其餘酌情考慮 DEBUG 級別。
- 第三方服務遠程調用:微服務架構體系中有一個重要的點就是第三方永遠不可信,對於第三方服務遠程調用建議打印請求和響應的參數,方便在和各個終端定位問題,不會因為第三方服務日誌的缺失變得手足無措。
日誌打印
Slf4j & Logback
Slf4j 英文全稱為 “ Simple Logging Facade for Java ”,為 Java 提供的簡單日誌門面。Facade 門面,更底層一點說就是接口。它允許用戶以自己的喜好,在工程中通過 Slf4j 接入不同的日誌系統。
Logback 是 Slf4j 的原生實現框架,同樣也是出自 Log4j 一個人之手,但擁有比 Log4j 更多的優點、特性和更做強的性能,Logback 相對於 Log4j 擁有更快的執行速度。基於我們先前在 Log4j 上的工作,Logback 重寫了內部的實現,在某些特定的場景上面,甚至可以比之前的速度快上 10 倍。在保證 Logback 的組件更加快速的同時,同時所需的內存更加少。
日誌文件
日誌文件放置於固定的目錄中,按照一定的模板進行命名,推薦的日誌文件名稱:
<code>當前正在寫入的日誌文件名:[-]
.log
如:example-server-book-service-access
.log
已經滾入歷史的日誌文件名:[-]
.yyyy-MM-dd-hh
.[滾動號]
.log
/<code>
如:
example-server-book-service-access.2019-12-01-10.1.log
日誌變量定義
推薦使用 lombok(代碼生成器) 註解 @lombok.extern.slf4j.Slf4j 來生成日誌變量實例。
<code><
dependency
><
groupId
>org.projectlombokgroupId
><
artifactId
>lombokartifactId
><
version
>1.18.10version
><
scope
>providedscope
>dependency
>/<code>
代碼示例
<code>import
lombok.extern
.slf4j.Slf4j; @Slf4jpublic
class
LogTest
{public
static
void
main
(String[] args)
{log
.info("this is log test"
); } }/<code>
日誌配置
日誌記錄採用分級記錄,級別與日誌文件名相對應,不同級別的日誌信息記錄到不同的日誌文件中。如有特殊格式日誌,如 access log,單獨使用一個文件,請注意避免重複打印(可使用 additivity**="false"** 避免 )。
參數佔位格式
使用參數化形式 {} 佔位,[] 進行參數隔離,這樣的好處是可讀性更高,而且只有真正準備打印的時候才會處理參數。
<code>log
.debug("order is paying with userId:[{}] and orderId : [{}]"
,userId, orderId);log
.debug("order is paying with userId: "
+ userId +" and orderId: "
+ orderId);/<code>
日誌的基本格式
日誌時間
作為日誌產生的日期和時間,這個數據非常重要,一般精確到毫秒。
<code>yyyy-MM-dd
HH
:mm
:ss.SSS
/<code>
日誌級別
日誌的輸出都是分級別的,不同的設置不同的場合打印不同的日誌。
主要使用如下的四個級別:
- DEBUG:DEUBG 級別的主要輸出調試性質的內容,該級別日誌主要用於在開發、測試階段輸出。該級別的日誌應儘可能地詳盡,開發人員可以將各類詳細信息記錄到 DEBUG 裡,起到調試的作用,包括參數信息,調試細節信息,返回值信息等等,便於在開發、測試階段出現問題或者異常時,對其進行分析。
- INFO:INFO 級別的主要記錄系統關鍵信息,旨在保留系統正常工作期間關鍵運行指標,開發人員可以將初始化系統配置、業務狀態變化信息,或者用戶業務流程中的核心處理記錄到INFO日誌中,方便日常運維工作以及錯誤回溯時上下文場景復現。建議在項目完成後,在測試環境將日誌級別調成 INFO,然後通過 INFO 級別的信息看看是否能瞭解這個應用的運用情況,如果出現問題後是否這些日誌能否提供有用的排查問題的信息。
- WARN:WARN 級別的主要輸出警告性質的內容,這些內容是可以預知且是有規劃的,比如,某個方法入參為空或者該參數的值不滿足運行該方法的條件時。在 WARN 級別的時應輸出較為詳盡的信息,以便於事後對日誌進行分析。
- ERROR:ERROR 級別主要針對於一些不可預知的信息,諸如:錯誤、異常等,比如,在 catch 塊中抓獲的網絡通信、數據庫連接等異常,若異常對系統的整個流程影響不大,可以使用 WARN 級別日誌輸出。在輸出 ERROR 級別的日誌時,儘量多地輸出方法入參數、方法執行過程中產生的對象等數據,在帶有錯誤、異常對象的數據時,需要將該對象一併輸出。
DEBUG / INFO 的選擇
DEBUG 級別比 INFO 低,包含調試時更詳細的瞭解系統運行狀態的東西,比如變量的值等等,都可以輸出到 DEBUG 日誌裡。 INFO 是在線日誌默認的輸出級別,反饋系統的當前狀態給最終用戶看的。輸出的信息,應該對最終用戶具有實際意義的。從功能角度上說,INFO 輸出的信息可以看作是軟件產品的一部分,所以需要謹慎對待,不可隨便輸出。如果這條日誌會被頻繁打印或者大部分時間對於糾錯起不到作用,就應當考慮下調為 DEBUG 級別。
- 由於 DEBUG 日誌打印量遠大於 INFO,出於前文日誌性能的考慮,如果代碼為核心代碼,執行頻率非常高,務必推敲日誌設計是否合理,是否需要下調為 DEBUG 級別日誌。
- 注意日誌的可讀性,不妨在寫完代碼 review 這條日誌是否通順,能否提供真正有意義的信息。
- 日誌輸出是多線程公用的,如果有另外一個線程正在輸出日誌,上面的記錄就會被打斷,最終顯示輸出和預想的就會不一致。
WARN / ERROR 的選擇
當方法或者功能處理過程中產生不符合預期結果或者有框架報錯時可以考慮使用,常見問題處理方法包括:
- 增加判斷處理邏輯,嘗試本地解決:增加邏輯判斷吞掉報警永遠是最優選擇拋出異常,交給上層邏輯解決
- 拋出異常,交給上層邏輯解決
- 記錄日誌,報警提醒
- 使用返回碼包裝錯誤做返回
一般來說,WARN 級別不會短信報警,ERROR 級別則會短信報警甚至電話報警,ERROR 級別的日誌意味著系統中發生了非常嚴重的問題,必須有人馬上處理,比如數據庫不可用,系統的關鍵業務流程走不下去等等。錯誤的使用反而帶來嚴重的後果,不區分問題的重要程度,只要有問題就error記錄下來,其實這樣是非常不負責任的,因為對於成熟的系統,都會有一套完整的報錯機制,那這個錯誤信息什麼時候需要發出來,很多都是依據單位時間內 ERROR 日誌的數量來確定的。
強調ERROR報警
- ERROR 級別的日誌打印通常伴隨報警通知。ERROR的報出應該伴隨著業務功能受損,即上面提到的系統中發生了非常嚴重的問題,必須有人馬上處理。
ERROR日誌目標
- 給處理者直接準確的信息:ERROR 信息形成自身閉環。
問題定位:
- 發生了什麼問題,哪些功能受到影響
- 獲取幫助信息:直接幫助信息或幫助信息的存儲位置
- 通過報警知道解決方案或者找何人解決
線程名稱
輸出該日誌的線程名稱,一般在一個應用中一個同步請求由同一線程完成,輸出線程名稱可以在各個請求產生的日誌中進行分類,便於分清當前請求上下文的日誌。
opentracing 標識
在分佈式應用中,用戶的一個請求會調用若干個服務完成,這些服務可能還是嵌套調用的,因此完成一個請求的日誌並不在一個應用的日誌文件,而是分散在不同服務器上不同應用節點的日誌文件中。該標識是為了串聯一個請求在整個系統中的調用日誌。
- 唯一字符串(trace id)
- 調用層級(span id)
通過搜索 trace id 就可以查到這個 trace id 標識的請求在整個系統中流轉(處理)過程中產生的所有日誌。
biz 標識
在業務開發中,我們的日誌都是和業務相關聯的,有時候是需要根據用戶或者業務做聚類的,因此一次請求如果可以通過某項標識做聚類的時候,可以將聚類標識打印到日誌中。
- 用戶標識(user id)
- 業務標識(biz id)
日誌記錄器名稱
日誌記錄器名稱一般使用類名,日誌文件中可以輸出簡單的類名即可,看實際情況是否需要使用包名和行號等信息。主要用於看到日誌後到哪個類中去找這個日誌輸出,便於定位問題所在。
日誌內容
禁用 System.out.println 和 System.err.println
變參替換日誌拼接
輸出日誌的對象,應在其類中實現快速的 toString 方法,以便於在日誌輸出時僅輸出這個對象類名和 hashCode
預防空指針:不要在日誌中調用對象的方法獲取值,除非確保該對象肯定不為 null,否則很有可能會因為日誌的問題而導致應用產生空指針異常。
異常堆棧
異常堆棧一般會出現在 ERROR 或者 WARN 級別的日誌中,異常堆棧含有方法調用鏈的系統,以及異常產生的根源。異常堆棧的日誌屬於上一行日誌的,在日誌收集時需要將其劃至上一行中。
最佳實踐
日誌格式
<code>2019
-12
-01
00
:00
:00.000
|pid|log
-level|[svc-name,trace-id,span-id,user-id,biz-id]|thread-name|package-name.
class
-name
:log
message/<code>
- 時間
- pid,pid
- log-level,日誌級別
- svc-name,應用名稱
- trace-id,調用鏈標識
- span-id,調用層級標識
- user-id,用戶標識
- biz-id,業務標識
- thread-name,線程名稱
- package-name.class-name,日誌記錄器名稱
- log message,日誌消息體
日誌模塊擴展
日誌模塊是基於以下技術點做擴展的。
- Slf4j MDC 實現原理(暫不開展詳解,如有興趣私下溝通)
- Opentracing Scope 原理(暫不開展詳解,如有興趣私下溝通)
在每個 tracing 鏈路中,將 Opentracing Scope 中的上下文信息放置 MDC 中,根據 Spring Boot Logging 擴展接口擴展的取值邏輯 **logging.pattern.level **的取值邏輯。
相關源碼參考
Spring Cloud Sleuth
[Spring Cloud Sleuth]github.com/spring-clou…
修改 logback 配置文件中每個 appender 的 pattern 為以下默認值即可實現標準化。
<code>%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}|${PID:- }|%level|${LOG_LEVEL_PATTERN:-%5p}|%t|%-40.40
logger{39}
: %msg%n /<code>
logback.xml 節選
<code><
configuration
><
property
name
="LOG_PATH"
value
="${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}"
/><
springProperty
scope
="context"
name
="APP_NAME"
source
="spring.application.name"
defaultValue
="spring-boot-fusion"
/><
property
name
="LOG_PATTERN"
value
="%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}|${PID:- }|%level|${LOG_LEVEL_PATTERN:-%5p}|%t|%-40.40logger{39}: %msg%n"
/><
appender
name
="fileInfo"
class
="ch.qos.logback.core.rolling.RollingFileAppender"
><
file
>${LOG_PATH}/${APP_NAME}-info.logfile
><
rollingPolicy
class
="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"
><
FileNamePattern
>${LOG_PATH}/${APP_NAME}-info.%d{yyyy-MM-dd-HH}.%i.logFileNamePattern
><
MaxHistory
>48MaxHistory
><
maxFileSize
>1GBmaxFileSize
><
totalSizeCap
>20GBtotalSizeCap
>rollingPolicy
><
layout
class
="ch.qos.logback.classic.PatternLayout"
><
pattern
>${LOG_PATTERN}pattern
>layout
><
filter
class
="ch.qos.logback.classic.filter.LevelFilter"
><
level
>INFOlevel
><
onMatch
>ACCEPTonMatch
><
onMismatch
>DENYonMismatch
>filter
>appender
>
configuration
>/<code>
代碼使用示例:
<code>public
Result> page( (value ="page-num"
, defaultValue ="1"
)int
pageNum, (value ="page-size"
, defaultValue ="10"
)int
pageSize) { LogStandardUtils.putUserId("userId123"
); LogStandardUtils.putBizId("bizId321"
); producerService.sendMsg("xxx"
); simpleClient.page(pageNum, pageSize);return
new
Result<>(simpleService.page(pageNum, pageSize)); }/<code>
日誌記錄
<code>2019
-12
-04
16
:29:08.223|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.n.u.concurrent.ShutdownEnabledTimer
:
Shutdown hook installed for:
NFLoadBalancer-PingTimer-example-server-order-service
2019
-12
-04
16
:29:08.224|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.netflix.loadbalancer.BaseLoadBalancer
:
Client: example-server-order-service instantiated a LoadBalancer:
DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current
list
of
Servers=[],Load
balancer
stats=Zone
stats:
{},Server
stats:
[]}ServerList:null
2019
-12
-04
16
:29:08.234|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.n.l.DynamicServerListLoadBalancer
:
Using
serverListUpdater
PollingServerListUpdater
2019
-12
-04
16
:29:08.247|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.n.l.DynamicServerListLoadBalancer
:
DynamicServerListLoadBalancer for client example-server-order-service initialized:
DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current
list
of
Servers=[],Load
balancer
stats=Zone
stats:
{},Server
stats:
[]}ServerList:ConsulServerList{serviceId='example-server-order-service',
tag=null}
2019
-12
-04
16
:29:08.329|43546|WARN|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.p.f.l.ctl.common.rule.StrategyRule
:
No up servers available from load balancer:
DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current
list
of
Servers=[],Load
balancer
stats=Zone
stats:
{},Server
stats:
[]}ServerList:ConsulServerList{serviceId='example-server-order-service',
tag=null}
2019
-12
-04
16
:29:08.334|43546|WARN|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.p.f.l.ctl.common.rule.StrategyRule
:
No up servers available from load balancer:
DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current
list
of
Servers=[],Load
balancer
stats=Zone
stats:
{},Server
stats:
[]}ServerList:ConsulServerList{serviceId='example-server-order-service',
tag=null}
2019
-12
-04
16
:29:08.342|43546|ERROR|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1
task-4|c.p.f.w.c.advice.ExceptionHandlerAdvice
:
當前程序進入到異常捕獲器,出錯的
url
為:[
http://127.0.0.1:10011/simples
],出錯的參數為:[
{"querystring":"{}","payload":""}
]
java.lang.RuntimeException: com.netflix.client.ClientException: Load balancer does not have available server for client:
example-server-order-service
/<code>
日誌服務
SLS日誌服務
日誌服務(簡稱 SLS)是針對日誌類數據的一站式服務,在阿里巴巴集團經歷大量大數據場景錘鍊而成。您無需開發就能快捷完成日誌數據採集、消費、投遞以及查詢分析等功能,提升運維、運營效率,建立 DT 時代海量日誌處理能力。
project
項目、管理日誌基礎單元,服務日誌建議一個環境建為一個 Project,這樣日誌記錄是整體一個閉環,日誌記錄隨整個環境內的服務調用產生。
logstore
日誌庫,日誌庫建議按照日誌類型分為不同的,如特定格式的 access 日誌,以及 info / warn / error 日誌,特定格式可以配置更為方面的索引以及告警設置。
注意:請勿按照應用服務區分為不同的 logstore,在微服務架構中,一次請求交叉了多個應用服務,日誌是散落在各個應用服務中的,按照服務區分 logstore,需要開發同學十分了解應用運行狀況和調用拓撲圖,這點往往是不具備的。
實時採集與消費
功能:
- 通過ECS、容器、移動端、開源軟件、JS等接入實時日誌數據(例如Metric、Event、BinLog、TextLog、Click等)。
- 提供實時消費接口,與實時計算及服務對接。
用途:數據清洗(ETL)、流計算(Stream Compute)、監控與報警、 機器學習與迭代計算。
查詢分析
實時索引、查詢分析數據。
- 查詢:關鍵詞、模糊、上下文、範圍。
- 統計:SQL聚合等豐富查詢手段。
- 可視化:Dashboard + 報表功能。
- 對接:Grafana、JDBC/SQL92。
用途:DevOps / 線上運維,日誌實時數據分析,安全診斷與分析,運營與客服系統。
消費投遞
穩定可靠的日誌投遞。將日誌中樞數據投遞至存儲類服務進行存儲。支持壓縮、自定義Partition、以及行列等各種存儲方式。
用途:數據倉庫 + 數據分析、審計、推薦系統與用戶畫像。
告警
日誌服務的告警功能基於儀表盤中的查詢圖表實現。在日誌服務控制檯查詢頁面或儀表盤頁面設置告警規則,並指定告警規則的配置、檢查條件和通知方式。設置告警後,日誌服務定期對儀表盤的查詢結果進行檢查,檢查結果滿足預設條件時發送告警通知,實現實時的服務狀態監控。
最佳實踐
日誌服務功能相當強大,想用好日誌服務可以參看:
help.aliyun.com/document_de…
ELK 通用日誌解決方案
ELK 是 Elasticsearch、Logstash、Kibana 三大開源框架首字母大寫簡稱。市面上也被成為 Elastic Stack。其中 Elasticsearch 是一個基於 Lucene、分佈式、通過 Restful 方式進行交互的近實時搜索平臺框架。像類似百度、谷歌這種大數據全文搜索引擎的場景都可以使用 Elasticsearch 作為底層支持框架,可見 Elasticsearch 提供的搜索能力確實強大,市面上很多時候我們簡稱 Elasticsearch 為 es。Logstash 是 ELK 的中央數據流引擎,用於從不同目標(文件/數據存儲/MQ)收集的不同格式數據,經過過濾後支持輸出到不同目的地(文件/ MQ / Redis / Elasticsearch / Kafka 等)。Kibana 可以將 Elasticsearch 的數據通過友好的頁面展示出來,提供實時分析的功能。
實踐說明
普通格式日誌
<code>2019
-11
-26
15
:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1
task-42]|c.p.f.w.pay.PayServiceImpl
:
order is paying with userId: 105 and orderId:
45982043
/<code>
普通日誌前綴是固定的,可以固定分詞索引,方便更快的查詢分析。
特定格式日誌
以 access 日誌為例
<code>2019
-11
-26
15
:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1
task-42]|c.p.f.w.logging.AccessLoggingFilter
:
>
url:
http://liweichao.com:10011/actuator/health
>
http-method:
GET
>
request-header:
[Accept:"text/plain,
text/*,
*/*",
Connection:"close",
User-Agent:"Consul
Health
Check",
Host:"liweichao.com:10011",
Accept-Encoding:"gzip"]
>
request-time:
2019
-11
-26
15
:01:03.309
>
querystring:
-
>
payload:
-
>
extra-param:
-
<
response-time:
2019
-11
-26
15
:01:03.332
<
take-time:
23
<
http-status:
200
<
response-header:
[content-type:"application/vnd.spring-boot.actuator.v2+json;charset=UTF-8",
content-size:"15"]
<
response-data:
{"status":"UP"}
/<code>
特定格式日誌可按格式創建索引更方便聚焦查詢分析和告警,如根據 take-time,http-status,biz-code 等值。