如何解決微服務化中日誌收集不全的問題？
背景
隨著酒店業務的高速發展，我們為用戶、商家提供的服務越來越精細，系統服務化程度、複雜度也逐漸上升。微服務化雖然能夠很好地解決問題，但也有副作用，比如，問題定位。
每次問題定位都需要從源頭開始找同事幫我人肉查日誌，舉一個簡單的例子：
「這個詳情頁的價格是怎麼算出來的?」
一次用戶酒店可訂空房頁（POI詳情頁）訪問，流量最多需要經過73個服務節點。查問題的時候需要先後找4~5個關鍵節點的同學幫我們登錄十多個不同節點的機器，查詢具體的日誌，溝通成本極大，效率很低。
為了解決這個問題，基礎架構的同學提供了MTrace（詳情可以參考技術博客：《分散式會話跟蹤系統架構設計與實踐》）協助業務方排查長鏈路問題。
但是與此同時，還有許多不確定性因素，使問題排查過程更加艱難，甚至無果而終：
- 各服務化節點存儲日誌的時間長度不一致；
- 有的服務節點，因為QPS過高，只能不打或者隨機列印日誌，會導致最終查問題的時候，線索因為沒日誌斷掉；
- 有的服務節點，使用了非同步邏輯（線程池、Hystrix、非同步RPC等）導致日誌中缺失Trace ID，無法關聯在一起；
- 各服務節點的採樣率不一樣，鏈路數據的上報率也是隨機性的，線索容易斷掉；
- MTrace上只有鏈路信息，沒有關聯各服務節點的日誌信息；
- 動態擴容節點上的日誌，縮容後無法找到。
總結起來如圖所示：
目標
我們的核心訴求有兩個：
- 根據用戶行為快速定位到具體的Trace ID，繼而查詢到這次服務調用鏈路上所有節點的日誌；
- 查詢的實時性要能做到准實時（秒級輸出），相關鏈路日誌要在獨立外部存儲系統中保存半年以上。
然後我們對訴求做了進一步的拆分：
- 全量打日誌不現實，需要選擇性打，打價值最高部分的日誌；
- 鏈路數據需要全服務節點都上傳，避免因為非同步化等原因造成鏈路數據中斷不上傳；
- 接入方式盡量簡單，避免所有服務節點都需要修改具體業務代碼來接入。最好是能通過日誌攔截的方式，其它保持透明；
- 日誌格式化，該有的欄位（AppKey、hostname、IP、timestamp等）不需要業務RD反覆輸入，自動補齊；
- 在不阻塞原有業務操作的情況下，做到准實時展示鏈路、日誌；
- 鏈路數據和日誌數據存儲，不依賴各服務節點，需要在獨立的存儲系統上存儲半年以上。
系統
搞清了核心訴求後，我們針對性地做了許多調研，最終定了一個系統的整體設計方案，這就是目前已經上線並實踐已久的美團點評酒店「衛星系統」。
下面，我們就來對系統做詳細介紹，包括一些核心細節點。
架構
如下圖所示，衛星系統從橫向分為鏈路和日誌兩個部分。
圖2 全鏈路日誌系統整體架構
鏈路部分是以MTrace為基礎，用支持超時fallback下Trace信息傳遞的Hystrix-Trace插件來覆蓋全部場景，保證鏈路被完整採集。
日誌部分在接入端有三大核心步驟，首先是依託於日誌攔截組件實現對業務代碼零侵入的情況下收集系統中所有日誌內容，然後根據統一日誌規範對日誌進行格式化處理，最後通過基於logcenter日誌傳輸機制實現日誌到Kafka的傳輸。
從縱向又分為：
- 業務接入層，根據策略採集Trace與業務日誌；
- 數據處理層，通過storm流式處理日誌信息；
- 數據存儲層，用於支持實時查詢的Squirrel（美團點評Redis集群）與持久存儲的ES（ElasticSearch），以及面向用戶的展示層。
日誌採樣方案
接入端是所有數據之源，所以方案設計極為關鍵。要解決的問題有：採集策略、鏈路完整性保障、日誌攔截、日誌格式化、日誌傳輸。
有的業務單台機器每天日誌總量就有百G以上，更有不少業務因為QPS過高而選擇平時不列印日誌，只在排查問題時通過動態日誌級別調整來臨時輸出。所以，我們在最初收集日誌時必須做出取捨。經過分析，發現在排查問題的時候，絕大多數情況下發起人都是自己人（RD、PM、運營），如果我們只將這些人發起的鏈路日誌記下來，那麼目標日誌量將會極大減少，由日誌量過大而造成的存儲時間短、查詢時效性差等問題自然得到解決。
所以我們制定了這樣的採集策略：
通過在鏈路入口服務判斷發起人是否滿足特定人群（住宿事業部員工）來決定是否進行日誌採集，將採集標誌通過MTrace進行全鏈路傳遞。這樣就能保證鏈路上所有節點都能行為一致地去選擇是否進行日誌上報，保證鏈路上日誌的完整性。
日誌攔截
作為核心要素的日誌，如何進行收集是一個比較棘手的問題。讓業務方強制使用我們的介面進行日誌輸出會帶來許多麻煩，一方面會影響業務方原有的日誌輸出策略；另一方面，系統原有的日誌輸出點眾多，涉及的業務也五花八門，改動一個點很簡單，但是全面進行改動難保不會出現未知影響。所以，需要儘可能降低對接入方代碼的侵入。
由於目前酒店核心業務已全面接入log4j2，通過研究，發現我們可以註冊全局Filter來遍歷系統所有日誌，這一發現，使我們實現了代碼零改動的情況下收集到系統所有日誌。
圖3 基於log4j2 filter機制的日誌收集策略
日誌格式化
業務系統輸出的日誌格式不一，比如有的沒有列印TraceID信息，有的沒有列印日誌位置信息從而很難進行定位。這主要帶來兩方面的問題，一方面不利於由人主導的排查分析工作，另一方面也不利於後續的系統優化升級，比如對日誌的自動化分析報警等等。
針對這些問題，我們設計了統一日誌規範，並由框架完成缺失內容的填充，同時給業務方提供了標準化的日誌介面，業務方可以通過該介面定義日誌的元數據，為後續支持自動化分析打下基礎。
由框架填充統一日誌信息這一過程利用到了log4j2的Plugins機制，通過Properties、Lookups、ContextMap實現業務無感知的操作。
圖4 通過Plugins機制支持格式化日誌屬性傳遞
日誌處理
我們在最終的日誌傳輸環節利用了日誌中心的傳輸機制，使用日誌中心的ScribeAppender實現日誌傳輸至本地agent，然後上報到遠端Kafka，這樣設計有幾點好處：
- 依賴公司成熟的基礎服務相對而言更可靠、更穩定，同時也省去了自己搭建服務、保證服務安全這一過程；
- 可以將日誌直接轉存至日誌中心ES做持久化存儲，同時支持快速靈活的數據檢索；
- 可以通過Storm對日誌進行流式處理，支持靈活的系統擴展，比如：實時檢索、基於日誌的實時業務檢查、報警等等，為後續系統擴展升級打下基礎。
我們的數據處理邏輯全部在Storm進行處理，主要包含日誌存儲Squirrel（美團點評內部基於Redis Cluster研發的純內存存儲）、實時檢索與Trace同步。
目前日誌中心ES能保證分鐘級別實時性，但是對於RD排查問題還是不夠，必須支持秒級別實時性。所以我們選擇將特定目標用戶的日誌直接存入Squirrel，失效時間只有半小時，查詢日誌時結合ES與Squirrel，這樣既滿足了秒級別實時性，又保證了日誌量不會太大，對Squirrel的壓力可以忽略不計。
我們的系統核心數據有鏈路與日誌，鏈路信息的獲取是通過MTrace服務獲得，但是MTrace服務對鏈路數據的保存時間有限，無法滿足我們的需求。所以，我們通過延時隊列從MTrace獲取近期的鏈路信息進行落地存儲，這樣就實現了數據的閉環，保證了數據完整性。
鏈路完整性保障
MTrace組件的Trace傳遞功能基於ThreadLocal，而酒店業務大量使用非同步化邏輯（線程池、Hystrix），這樣會造成傳遞信息的損失，破壞鏈路完整性。
一方面，通過Sonar檢查和梳理關鍵鏈路，來確保業務方使用類似transmittable-thread-local中的ExecutorServiceTtlWrapper.java、ExecutorTtlWrapper.java的封裝，來將ThreadLocal里的Trace信息，也傳遞到非同步線程中（前文提到的MTrace也提供這樣的封裝）。
另一方面，Hystrix的線程池模式會造成線程變數丟失。為了解決這個問題，MTrace提供了Mtrace Hystrix Support Plugin插件實現跨線程調用時的線程變數傳遞，但是由於Hystrix有專門的timer線程池來進行超時fallback調用，使得在超時情況下進入fallback邏輯以後的鏈路信息丟失。
針對這個問題，我們深入研究了Hystrix機制，最終結合Hystrix Command Execution Hook、Hystrix ConcurrencyStrategy、Hystrix Request Context實現了覆蓋全場景的Hystrix-Trace插件，保障了鏈路的完整性。
HystrixPlugins.getInstance().registerCommandExecutionHook(new HystrixCommandExecutionHook() {n @Overriden public <T> void onStart(HystrixInvokable<T> commandInstance) {n // 執行command之前將trace信息保存至hystrix上下文，實現超時子線程的trace傳遞n if (!HystrixRequestContext.isCurrentThreadInitialized()) {n HystrixRequestContext.initializeContext();n }n spanVariable.set(Tracer.getServerSpan());n }nn @Overriden public <T> Exception onError(HystrixInvokable<T> commandInstance, HystrixRuntimeException.FailureType failureType, Exception e) {n // 執行結束後清空hystrix上下文信息n HystrixRequestContext context = HystrixRequestContext.getContextForCurrentThread();n if (context != null) {n context.shutdown();n }n return e;n }nn @Overriden public <T> void onSuccess(HystrixInvokable<T> commandInstance) {n // 執行結束後清空hystrix上下文信息n HystrixRequestContext context = HystrixRequestContext.getContextForCurrentThread();n if (context != null) {n context.shutdown();n }n }n});nnHystrixPlugins.getInstance().registerConcurrencyStrategy(new HystrixConcurrencyStrategy() {n @Overriden public <T> Callable<T> wrapCallable(Callable<T> callable) {n // 通過自定義callable保存trace信息n return WithTraceCallable.get(callable);n }n});n
效果展示
比如以排查一次用戶點擊某POI詳情頁的TraceID為例子：
我們可以看到他在MTrace中的調用鏈路是這樣的：
在衛星系統中，展示為如下效果：
可見，在保留了鏈路數據的基礎上，系統還將全鏈路節點日誌聚合到了一起，提升了排查效率。
後續規劃
目前，系統還處於初級階段，主要用來解決RD在排查問題時的兩大痛點：日誌信息的不完整與太分散，現在已經滿足了這一需求。但是，全鏈路日誌系統能做的不止這些，後續的主要規劃有如下幾方面：
- 支持多鏈路日誌關聯搜索，比如一次列表頁刷新與後續的詳情頁展示，雖然鏈路是多個但是實際處在一個關聯的場景中。支持關聯搜索就可以可以將日誌排查目標從單個動作維度擴展到多動作組成的場景維度。
- 支持業務方自定義策略規則進行基於日誌的自動化業務正確性檢查，如果檢查出問題可以直接將詳細信息通知相關人員，實現實時監測日誌、實時發現問題、實時通知到位，免去人工費時費力的低效勞動。
作者簡介
亞輝，2015年加入美團點評，就職於美團點評酒旅事業群技術研發部酒店後台研發組。
曾鋆，2013年加入美團點評，就職於美團點評酒旅事業群技術研發部酒店後台研發組。
最後發個廣告，美團點評酒旅事業群技術研發部酒店後台研發組長期招聘Java後台、架構方面的人才，有興趣的同學可以發送簡歷到xuguanfei#http://meituan.com。
推薦閱讀：