前言:

　　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
     
       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
     
       threadLocals = new ThreadLocal
      
       ();　　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来构建一个简单的系统, 敬请期待.