前言:
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来构建一个简单的系统, 敬请期待.