前言:
Thrift作為Facebook開源的RPC框架, 通過IDL中間語言, 並借助代碼生成引擎生成各種主流語言的rpc框架服務端/客戶端代碼. 不過Thrift的實現, 簡單使用離實際生產環境還是有一定距離, 本系列將對Thrift作代碼解讀和框架擴充, 使得它更加貼近生產環境. 本文講述RPC服務框架中, 日志的重要性, 以及logid的引入. 日志不僅包含豐富的數據(就看是否會挖掘), 而且還是線上服務問題追蹤和排查錯誤最好的方式.
日志級別
采用大家喜聞樂見的log4j作為該RPC服務框架首選的日志庫. 其對日志的級別有如下幾種:
1). TRACE 最細粒度級別日志級別
2). DEBUG 對調試應用程序有幫助的日志級別
3). INFO 粗粒度級別突出強調應用程序的運行
4). WARN 表明潛在錯誤的情形
5). ERROR 明確發生錯誤, 但不影響系統繼續運行
6). FATAL 嚴重的錯誤, 會導致應用工作不正常
日志級別等級順序如下: TRACE < DEBUG < INFO < WARN < ERROR < FATAL
而應用具體的輸出取決於日志級別的設置(包含及以上才會輸出), 往往項目該上線采用DEBUG級別(日志量大, 容易寫滿磁盤), 等系統穩定后采用INFO級別
RPC服務日志需求
上述的日志需求雖然能定位問題, 但往往存在如下問題:
1). 很多日志只是簡單了記錄該點(代碼行)運行過, 或是運行到該點的數據快照.
2). 服務由多種模塊(每個模塊由有多個節點構成)組成, 之間的日志串聯不起來.
而好的日志設計, 必須能滿足
1). 以完整的一次RPC調用作為單位(不是某個執行點快照, 而是完整的RPC callback過程), 並輸出完整的一行日志記錄, 包括(時間點, 來源, 輸入參數, 輸出參數, 中間經歷的子過程, 消耗時間).
2). 引入logid, 作為多個模塊之間串聯的依據.
RPC級別的日志解決方案
嘗試如下navie的方式去實現
public String echo(String msg) {
StringBuilder sb = new StringBuilder();
// *) 記錄輸入參數
sb.append("[request: {msg: msg}]");
// *) 訪問緩存服務
sb.append("[action: access redis, consume 100ms]");
// *). 訪問后端數據庫
sb.append("[action: dao, consume 100ms]");
// *). 記錄返回結果
sb.append("[response: {msg}]");
logger.info(sb.toString());
return msg;
}
評注: 這邊的echo函數代表了一個rpc服務調用接口, 且簡化了各個組件的交互. 同時引入StringBuilder, 記錄各個交互的過程和時間消耗, 最后統一由函數出口前使用logger進行日志的統一輸入.
但是這種方式弊端非常的明顯:
1. 假設該rpc服務的函數, 存在多個出口
2. 函數存在嵌套調用, 需要嵌套子函數的過程信息
如下面的代碼片段, 可參考:
public boolean verifySession() {
// ***********我要記錄日志(*^__^*) ***************
}
public String echo(String msg) {
StringBuilder sb = new StringBuilder();
// *) 調用子過程
verifySession();
// *) 記錄輸入參數
sb.append("[request: {msg: msg}]");
// *) 訪問緩存服務
if ( KeyValueEngine Access Fail ) {
// *********日志記錄在那里***********
throw new Exception();
}
sb.append("[action: access redis, consume 100ms]");
// *). 訪問后端數據庫
if ( Database Access Fail ) {
// *********日志記錄在那里***********
throw new Exception();
}
sb.append("[action: dao, consume 100ms]");
// *). 記錄返回結果
sb.append("[response: {msg}]");
logger.info(sb.toString());
return msg;
}
評注: 子函數verifySession的調用, 需要把StringBuilder對象往里傳, 才能記錄相關的信息, 而多個異常出口, 需要把日志輸入往里添加(這個繁瑣且容易忘記). 這種方案只能說容易想到, 但不是最佳的方案.
有一點不可否認, rpc調用始終在同一個線程中. 聰明的讀者是否猜到了最佳的解決方案.
對, 就是大殺器ThreadLocal,其能解決子函數調用的問題, 那多出口問題呢? 讓rpc服務框架去處理, 其作為具體rpc調用的最外層.
采用動態代理類, 去攔截rpc的handler接口調用.
public class LogProxyHandler<T> implements InvocationHandler {
private T instance;
public LogProxyHandler(T instance) {
this.instance = instance;
}
public Object createProxy() {
return Proxy.newProxyInstance(instance.getClass().getClassLoader(),
instance.getClass().getInterfaces(), this);
}
@Override
public Object invoke(Object proxy, Method method, Object[] args)
throws Throwable {
// *) 函數調用前, 攔截處理, 作ThreadLocal的初始化工作
LoggerUtility.beforeInvoke(); // -----(1)
try {
Object res = method.invoke(instance, args);
// *) 函數成功返回后, 攔截處理, 進行日志的集中輸出
LoggerUtility.returnInvoke(); // -----(2)
return res;
} catch (Throwable e) {
// *) 出現異常后, 攔截處理, 進行日志集中輸入 // -----(3)
LoggerUtility.throwableInvode("[result = exception: {%s}]", e.getMessage());
throw e;
}
}
}
代碼評注:
(1). 攔截點beforeInvoke用於ThreadLocal的初始話工作, 日志緩存的清空
(2). 攔截點returnInvoke用於函數成功返回后, 進行日志集中輸出
(3). 攔截點throwableInvoke用於出現異常后, 進行日志的集中輸出
同時在rpc服務調用中, 才用LoggerUtility的noticeLog靜態函數(簡單緩存中間日志過程)代替之前的StringBuilder.append來記錄中間子過程
LoggerUtility的代碼如下所示:
public class LoggerUtility {
private static final Logger rpcLogger = LoggerFactory.getLogger("rpc");
public static final ThreadLocal<StringBuilder> threadLocals = new ThreadLocal<StringBuilder>();
public static void beforeInvoke() {
StringBuilder sb = threadLocals.get();
if ( sb == null ) {
sb = new StringBuilder();
threadLocals.set(sb);
}
sb.delete(0, sb.length());
}
public static void returnInvoke() {
StringBuilder sb = threadLocals.get();
if ( sb != null ) {
rpcLogger.info(sb.toString());
}
}
public static void throwableInvode(String fmt, Object... args) {
StringBuilder sb = threadLocals.get();
if ( sb != null ) {
rpcLogger.info(sb.toString() + " " + String.format(fmt, args));
}
}
public static void noticeLog(String fmt, Object... args) {
StringBuilder sb = threadLocals.get();
if ( sb != null ) {
sb.append(String.format(fmt, args));
}
}
}
兩者的結合完美的解決了上述RPC的日志問題, 是不是很贊.
Logid的日志解決方案
Thrift框架本身是沒有logid的概念的, 我們很難去改動thrift的rpc協議, 去添加它(比如大百度的做法是把logid作為rpc協議本身一部分). 這邊的解決方案是基於約定. 我們采用如下約定, 所有的rpc請求參數都封裝為一個具體Request對象, 所有的返回結構都封裝為一個具體的Response對象, 而每個Request對象首個屬性是logid.
比如如下的結構定義:
struct EchoRequest {
1: required i64 logid = 1001,
2: required string msg
}
struct EchoResponse {
1: required i32 status,
2: optional string msg
}
service EchoService {
EchoResponse echo(1: EchoRequest req);
}
評注: Request結構中logid, 就是約定的需要加到rpc的請求結構里去的.
我一直覺得: 約定優於配置, 約定優於框架.
后續
中間插入日志處理這塊, 后續講述之前計划的服務發布/訂閱化, 借助zookeeper來構建一個簡單的系統, 敬請期待.