====== 实现log4j打日志带uuid(同一个请求线程同一个uuid) ======
===== 实现思路 =====
- [目标前提]:尽量不改变原有的写法Logger logger = Logger.getLogger(A.class);
- 新建Logger子类BaseUuidLogger,重写debug,info等方法;在ThreadLocal中获取同一个uuid;打印日志前带上这个uuid
- spring能管理到的类(@controller,@service),使用aop切面,扫描Logger变量强制设置成BaseUuidLogger
- spring管理不到的类,比如util工具类,使用BaseUuidLoggerUtils.getBaseUuidLogger()赋值给Logger变量
===== 具体步骤 =====
==== BaseUuidLogger.java ====
由于使用BaseUuidLogger重写debug,info后的方法打印日志,log4j打印出来的类和行号都是BaseUuidLogger类的信息,而我们希望log4j打印出调用BaseUuidLogger的堆栈前面一个类的类名和行号信息。
所以,修改log4j配置文件把log4j捕获的类型和行号删除,然后,在BaseUuidLogger中重写的debug,info等方法打印日志前带上ThreadLocal中获取的同一个uuid之前再带上调用BaseUuidLogger的堆栈前面一个类的类名和行号信息。
package com.shhxzq.fin.lifeapp.model.base;
import java.util.UUID;
import org.apache.commons.lang.StringUtils;
import org.apache.log4j.Logger;
/**
* 基础日志操作类-同一个线程的uuid是一样的
*
* @author Gxx
*/
public class BaseUuidLogger extends Logger {
/**
* 通过匿名内部类覆盖ThreadLocal的initialValue()方法,指定初始值
* 使得同一个线程的uuid是一样的
*/
private static ThreadLocal uuid = new ThreadLocal() {
/**
* 初始值
*/
public String initialValue() {
return "[uuid:" + UUID.randomUUID().toString() + "] : ";
}
};
/**
* 空参数构造函数
*/
public BaseUuidLogger() {
super(StringUtils.EMPTY);
}
/**
* 构造方法
*
* @param name
*/
protected BaseUuidLogger(String name) {
super(name);
}
@Override
public void trace(Object message) {
message = getStackString() + uuid.get() + message;
super.trace(message);
}
@Override
public void debug(Object message) {
message = getStackString() + uuid.get() + message;
super.debug(message);
}
@Override
public void error(Object message) {
message = getStackString() + uuid.get() + message;
super.error(message);
}
@Override
public void error(Object message, Throwable t) {
message = getStackString() + uuid.get() + message;
super.error(message, t);
}
@Override
public void fatal(Object message) {
message = getStackString() + uuid.get() + message;
super.fatal(message);
}
@Override
public void fatal(Object message, Throwable t) {
message = getStackString() + uuid.get() + message;
super.fatal(message, t);
}
@Override
public void info(Object message) {
message = getStackString() + uuid.get() + message;
super.info(message);
}
@Override
public void warn(Object message) {
message = getStackString() + uuid.get() + message;
super.warn(message);
}
/**
* 获取堆栈信息
* @param stackElements
* @return
*/
private String getStackString() {
StackTraceElement[] stackElements = new Throwable().getStackTrace();
if (stackElements != null && stackElements.length > 2) {
return "[" + stackElements[2].getClassName()+ ".java:"
+ stackElements[2].getMethodName() + "():"
+ stackElements[2].getLineNumber() + "]";
}
return StringUtils.EMPTY;
}
}
==== log4j.xml ====
[%C:%L]指的是[类名:行号],因为同一个线程请求打印出同一个uuid,所以把%t(指的是线程名)也去掉了。
==
修改前<->修改后
==
==
修改前<->修改后
==
==== application-context.xml ====
配置AOP切面,可以扫描到指定路径下所有@Service注解的服务类
==== spring-mvc.xml ====
要让AOP扫描到@Controller注解的控制器类(虽然是spring管理,但是AOP默认扫描不到),必须加一行配置
==== ServiceAop.java ====
扫面到切面指向的类和方法时候,程序会进入切面类的实现逻辑:通过反射扫描当前执行对象的Logger类型成员变量,new一个BaseUuidLogger子类对象,把这个Logger类型成员变量的所有属性拷贝赋值给BaseUuidLogger,再反射强制set给这个Logger类型成员变量。
package com.shhxzq.fin.lifeapp.biz.utils;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.text.MessageFormat;
import org.apache.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.reflect.MethodSignature;
import com.shhxzq.fin.lifeapp.model.base.BaseUuidLogger;
import com.shhxzq.fin.lifeapp.model.base.BusinessException;
import com.shhxzq.fin.lifeapp.model.base.Log;
import com.shhxzq.fin.lifeapp.model.base.LogMethodTime;
/**
* 服务层AOP
* @author Gxx
*/
public class ServiceAop {
/**
* 日志记录器
*/
Logger logger = BaseUuidLoggerUtils.getBaseUuidLogger();
/**
* 方法前后操作
* @param pjp
* @return
* @throws Exception
*/
public Object around(ProceedingJoinPoint pjp) throws Throwable {
/**
* 获取切面方法
*/
Signature sig = pjp.getSignature();
MethodSignature msig = null;
if (!(sig instanceof MethodSignature)) {
throw new IllegalArgumentException("该注解只能用于方法");
}
msig = (MethodSignature) sig;
Object target = pjp.getTarget();
Method currentMethod = target.getClass().getMethod(msig.getName(), msig.getParameterTypes());
/**
* 判断是否有Logger对象,有则强制设置为BaseUuidLogger
*/
Field[] files = target.getClass().getDeclaredFields();
for(Field field : files) {
if(field.getType() == Logger.class) {
/**
* 私有变量必须先设置Accessible为true
*/
field.setAccessible(true);
/**
* 判断是否第一次赋值
*/
if(!(field.get(target) instanceof BaseUuidLogger)) {
/**
* 创建基础日志操作实体-同一个线程的uuid是一样的
*/
BaseUuidLogger uuidLogger = new BaseUuidLogger();
/**
* 拷贝属性-父类向子类拷贝(两层父类)
*/
BeanUtils.copyPropertiesLevel2(uuidLogger, field.get(target));
/**
* 覆盖设置Logger对象
*/
field.set(target, uuidLogger);
}
}
}
/**
* 判断是否加注解@Log和@LogMethodTime
*/
boolean isLog = currentMethod.isAnnotationPresent(Log.class);
boolean isLogMethodTime = currentMethod.isAnnotationPresent(LogMethodTime.class);
/**
* 类.方法 名字
*/
String targetName = pjp.getTarget().getClass().getName() + "." + pjp.getSignature().getName();
/**
* 注解@Log或@LogMethodTime,只要配置一个就打日志
*/
if(isLog || isLogMethodTime) {
String request = BeAopUtil.getStringFromRequest(pjp.getArgs());
String requestMsg = "log - {0} request - {1}";
logger.info(MessageFormat.format(requestMsg, new Object[] { targetName, request }));
}
/**
* 开始时间
*/
long begin = DateUtils.getNow().getTime();
Object result = null;
try {
/**
* 执行方法
*/
result = pjp.proceed();
} catch (BusinessException t) {
logger.error(targetName + " exception occure!reason:" + t.getMessage());
throw t;
} catch (Throwable t) {
logger.error(targetName + " exception occure!", t);
throw t;
} finally {
/**
* 注解@LogMethodTime才计算计算时间
*/
if(isLogMethodTime) {
long end = DateUtils.getNow().getTime();
logger.info(targetName + " use time : " + (end - begin) / 1000.0 + "s");
}
}
/**
* 注解@Log或@LogMethodTime,只要配置一个就打日志
*/
if(isLog || isLogMethodTime) {
Object response = BeAopUtil.getStringFromResponse(result);
String responseMsg = "log - {0} response - {1}";
logger.info(MessageFormat.format(responseMsg, new Object[] { targetName, response }));
}
return result;
}
}
==== BeanUtils.java ====
一般采用org.apache.commons.beanutils.BeanUtils.java:copyProperties(Object dest, Object orig)来拷贝两个对象的相同属性,但是这个类不能拷贝private,protected以及父类的所有属性,所以这里使用反射机制新写一个Bean工具类。
package com.shhxzq.fin.lifeapp.biz.utils;
import java.lang.reflect.Field;
import java.lang.reflect.Modifier;
/**
* Bean工具类
* @author Gxx
*/
public class BeanUtils {
/**
* 拷贝属性-父类向子类拷贝(一层父类)
* @param dest
* @param origin
* @throws Exception
*/
public static void copyPropertiesLevel1(Object dest, Object origin) throws Exception {
if (!(dest.getClass().getSuperclass() == origin.getClass())) {
throw new Exception("dest不是origin的子类");
}
/**
* 第一层父类
*/
Class fatherClass = origin.getClass();
Field ff[] = fatherClass.getDeclaredFields();
for (int i = 0; i < ff.length; i++) {
Field f = ff[i];
// 私有变量必须先设置Accessible为true
f.setAccessible(true);
// 修改final属性
Field modifiersField = Field.class.getDeclaredField("modifiers");
modifiersField.setAccessible(true);
modifiersField.setInt(f, f.getModifiers() & ~Modifier.FINAL);
f.set(dest, f.get(origin));
}
}
/**
* 拷贝属性-父类向子类拷贝(两层父类)
* @param dest
* @param origin
* @throws Exception
*/
public static void copyPropertiesLevel2(Object dest, Object origin) throws Exception {
if (!(dest.getClass().getSuperclass() == origin.getClass())) {
throw new Exception("dest不是origin的子类");
}
/**
* 第一层父类
*/
Class fatherClass = origin.getClass();
Field ff[] = fatherClass.getDeclaredFields();
for (int i = 0; i < ff.length; i++) {
Field f = ff[i];
// 私有变量必须先设置Accessible为true
f.setAccessible(true);
// 修改final属性
Field modifiersField = Field.class.getDeclaredField("modifiers");
modifiersField.setAccessible(true);
modifiersField.setInt(f, f.getModifiers() & ~Modifier.FINAL);
f.set(dest, f.get(origin));
}
/**
* 第二层父类
*/
fatherClass = origin.getClass().getSuperclass();
ff = fatherClass.getDeclaredFields();
for (int i = 0; i < ff.length; i++) {
Field f = ff[i];
// 私有变量必须先设置Accessible为true
f.setAccessible(true);
// 修改final属性
Field modifiersField = Field.class.getDeclaredField("modifiers");
modifiersField.setAccessible(true);
modifiersField.setInt(f, f.getModifiers() & ~Modifier.FINAL);
f.set(dest, f.get(origin));
}
}
}
==== BaseUuidLoggerUtils.java ====
前面配置AOP,那么AOP扫描到的@Service和@Controller自动Logger类型成员变量会变成BaseUuidLogger对象;那脱离了spring管理的其它类就只能还一种方法,使用这个工具类手动获取BaseUuidLogger对象。
package com.shhxzq.fin.lifeapp.biz.utils;
import org.apache.log4j.Logger;
import com.shhxzq.fin.lifeapp.model.base.BaseUuidLogger;
/**
* 基础日志输出工具类-同一个线程的uuid是一样的
* @author Gxx
*/
public class BaseUuidLoggerUtils {
/**
* 日志记录器
*/
static Logger logger = Logger.getLogger(BaseUuidLoggerUtils.class);
/**
* 或者基础日志操作实体-同一个线程的uuid是一样的
* @return
*/
public static BaseUuidLogger getBaseUuidLogger() {
BaseUuidLogger baseUuidLogger = new BaseUuidLogger();
try {
BeanUtils.copyPropertiesLevel2(baseUuidLogger, Logger.getLogger(BaseUuidLoggerUtils.class));
} catch (Exception e) {
logger.error("拷贝属性异常", e);
}
return baseUuidLogger;
}
}
==== 用法1 ====
spring能管理到的类(@controller,@service),使用aop切面,扫描Logger变量强制设置成BaseUuidLogger
/**
* 信用卡服务接口实现类
*
* @author Gxx
*/
@Service("laCreditService")
public class LaCreditServiceImpl implements LaCreditService {
/**
* 日志处理器
*/
private Logger logger = Logger.getLogger(LaCreditServiceImpl.class);
...
}
/**
* 信用卡相关接口
* @author Gxx
*/
@Controller
@RequestMapping("/lifeapp/credit/")
public class CreditController {
/**
* 日志处理器
*/
private final Logger logger = Logger.getLogger(CreditController.class);
...
}
==== 用法2 ====
spring管理不到的类,比如util工具类,使用BaseUuidLoggerUtils.getBaseUuidLogger()赋值给Logger变量
/**
* 监控工具类
*
* @author Gxx
* @since 2016/12/2
*/
public class HawkeyeUtil {
/**
* 日志处理器
*/
private static Logger logger = BaseUuidLoggerUtils.getBaseUuidLogger();
...
}
===== 打印效果 =====
2016-12-24 09:28:46,503 INFO [com.shhxzq.fin.lifeapp.biz.utils.ServiceAop.java:around():93][uuid:f9ca7f9e-3d01-4fb3-be1e-30866c598f35] : log - com.shhxzq.fin.lifeapp.biz.impl.credit.LaCreditServiceImpl.queryShowCreditMenu request - {"acceptMode":"Mobile","custNo":"0000045412","deviceId":"BiHo7J4ppFXL8vAmQ3WZ7M"}
2016-12-24 09:28:46,503 INFO [com.shhxzq.fin.lifeapp.remote.impl.SafeCenterServiceImpl.java:checkShowCreditMenu():63][uuid:f9ca7f9e-3d01-4fb3-be1e-30866c598f35] : 判断用户是否可见信用卡服务请求:BeidouRiskQueryDO{appName='LIFEAPP', dataMap={}, moduleType=101, isMeetBreak=true, memberId='0000045412', deviceId='BiHo7J4ppFXL8vAmQ3WZ7M', ip='null', weixin='null'}
2016-12-24 09:28:46,505 INFO [com.shhxzq.fin.lifeapp.remote.impl.SafeCenterServiceImpl.java:checkShowCreditMenu():78][uuid:f9ca7f9e-3d01-4fb3-be1e-30866c598f35] : 判断用户能否还款返回:AccessStatus=[0],Reason=[null]
2016-12-24 09:28:46,506 INFO [com.shhxzq.fin.lifeapp.biz.utils.ServiceAop.java:around():120][uuid:f9ca7f9e-3d01-4fb3-be1e-30866c598f35] : com.shhxzq.fin.lifeapp.biz.impl.credit.LaCreditServiceImpl.queryShowCreditMenu use time : 0.003s
2016-12-24 09:28:46,506 INFO [com.shhxzq.fin.lifeapp.biz.utils.ServiceAop.java:around():130][uuid:f9ca7f9e-3d01-4fb3-be1e-30866c598f35] : log - com.shhxzq.fin.lifeapp.biz.impl.credit.LaCreditServiceImpl.queryShowCreditMenu response - true
根据uuid
grep 'f9ca7f9e-3d01-4fb3-be1e-30866c598f35' lifeapp.log --color
可以查到日志中同一次请求的所有日志
===== [待探讨方式1]ASM字节码技术 =====
lifeapp项目运行,自动解压log4j.jar,拿到Logger.class(或者父类),使用ASM字节码技术框架,修改debug,info等方法(或者修改这些方法统一调后面的某个方法),在打印信息之前带上uuid(在ThreadLocal中获取同一个uuid)。使用新实现的ClassLoader类重新加载新的Logger.class创建新对象。
==== 用法 ====
和原始的Logger对象用法一样
/**
* 监控工具类
*
* @author Gxx
* @since 2016/12/2
*/
public class HawkeyeUtil {
/**
* 日志处理器
*/
private static Logger logger = Logger.getLogger(HawkeyeUtil.class);
...
}
===== [待探讨方式2]修改Log4j源码 =====
拿出Log4j源码,修改debug,info等方法(或者修改这些方法统一调后面的某个方法),在打印信息之前带上uuid(在ThreadLocal中获取同一个uuid)。重新编译,放到src/main/java/目录下Logger对应的包路径下。
==== 用法 ====
和原始的Logger对象用法一样
/**
* 监控工具类
*
* @author Gxx
* @since 2016/12/2
*/
public class HawkeyeUtil {
/**
* 日志处理器
*/
private static Logger logger = Logger.getLogger(HawkeyeUtil.class);
...
}