项目现状:
1.logback配置了9种appender,在LogUtil中对日志做开关控制。
(1)优点:这样分散了日志压力,毕竟全打在一个文件,会给排查带来很多麻烦。
(2)缺点:但是带来问题也很明显,在打日志的时候,要给每一条日志加开关,这个重复工作量较大,也会影响代码整洁性。
解决思路:
2.所以在调研了AOP的功能之后,决定从两方面下手来做日志管理:
(1)日志收敛,统一加开关。
(2)trace调用链路,方便排查。
解决方式:
1.切面配置方式的选择:
目前要么是注解,要么是bean文件配置。
显然注解的方式更适合我们,bean配置起来会繁琐一点。而且我们的bean文件已经很大了,个人觉得还是尽量保证bean的轻量化,毕竟项目还要走很远。
2.切点的配置表达式选择:
切点配置方式五花八门,有“包路径”execution方式,@within注解,@annotation注解,@args等等。
由于我们项目中的日志打得很分散,用包路径的方式改造成本太大,要把整个项目都梳理一遍,把打一类日志的类放到一起。另外,包路径管理也是一个坑,观察过其他项目里的切面,大部分是埋点使用,只是针对特定的一些类。所以决定采用注解的方式。
@annotation注解只能针对特定的类,所以采用@within注解,打在类上,类中所有的方法都可以被拦截掉。
3.方案落地
首先是一个改造思路。可以从稳定的一些类入手,这些类基本稳定,大多数情况下,只关注初入参和返回值。然后就想之前的日志改造一样,慢慢转掉。
具体代码:
(1)自定义注解:
package com.cainiao.arrow.myannotation;
import java.lang.annotation.Documented;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
import static java.lang.annotation.ElementType.METHOD;
import static java.lang.annotation.ElementType.TYPE;
/**
* @author nhq
* 自定义注解
*/
@Retention(RetentionPolicy.RUNTIME)
@Target(value={ METHOD, TYPE})
@Documented
public @interface GlobalLog {
/**
* 扩展字段
*/
//String[] key() default {};
}
target设置为方法和类,在方法和类上都可以打上注解。
1、RetentionPolicy.SOURCE:注解只保留在源文件,当Java文件编译成class文件的时候,注解被遗弃;
2、RetentionPolicy.CLASS:注解被保留到class文件,但jvm加载class文件时候被遗弃,这是默认的生命周期;
3、RetentionPolicy.RUNTIME:注解不仅被保存到class文件中,jvm加载class文件之后,仍然存在;
一般在运行时去动态获取注解信息,就用 RUNTIME 注解,比如一些反射操作。如果要在编译时进行一些预处理操作,比如生成一些辅助代码,就用 CLASS注解。如果只是做一些检查性的操作,比如 @Override,则可选用 SOURCE 注解。暂时先用RUNTIME注解。
@Documented:将自定义注解设置为文档说明信息。
针对每一类日志,编写各自的切面类,下面以GlobalLogAspect为例:
package com.cainiao.arrow.aspect;
import com.alibaba.fastjson.JSON;
import com.cainiao.arrow.diamond.SuperManDiamondKey;
import com.cainiao.arrow.util.LogUtil;
import com.cainiao.arrow.util.execute.ExeLogUtil;
import com.taobao.hsf.annotation.Order;
import org.apache.commons.lang.StringUtils;
import org.apache.commons.lang.exception.ExceptionUtils;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import java.lang.reflect.Method;
/**
* @author nhq
* 基础日志类切面,优先执行,order默认设置为1
*/
@Component
@Aspect
@Order(1)
public class GlobalLogAspect {
private static final Logger log = LogUtil.globalLog;
//private static final Logger log = LoggerFactory.getLogger(GlobalLogAspect.class);
/**
* 切点:国际日志注解
* 1、包路径方式不适合当前项目环境,管理也更麻烦。
* 2、采用注解方式,按需加注解(有的类不再关注细节,只关注出入参,可以先用这种方式)
* 3、用within注解,可以拦截注解所标注类的所有方法。
*/
@Pointcut("@within(com.cainiao.arrow.myannotation.GlobalLog)")
public void globalLog(){ }
/**
* 涉及到插入、修改db的服务,请不要用切面方式做加标、去标的操作
*/
@Before("globalLog()")
public void before(JoinPoint joinPoint){
}
@Around("globalLog()")
public Object around(JoinPoint joinPoint){
long start = System.currentTimeMillis();
try {
String aspectSwitch = SuperManDiamondKey.getInstance().getCustomTestParam().get( "aspect_switch");
//开关关闭,直接返回
if(StringUtils.isEmpty(aspectSwitch)&&aspectSwitch.equals("N")){
return ((ProceedingJoinPoint) joinPoint).proceed();
}
//获取相关信息
Object [] args = joinPoint.getArgs();
LogTracer.newParamNode();
MethodSignature methodSignature = (MethodSignature)joinPoint.getSignature();
Method method = methodSignature.getMethod();
String methodName = method.getName();
String clazzname = joinPoint.getTarget().getClass().getName();
LogTracer.setMethod(methodName);
LogTracer.setClazz(clazzname);
String[] parameterNames = methodSignature.getParameterNames();
if(parameterNames!=null && parameterNames.length>0){
for(int i=0;i<parameterNames.length;i++){
if(!parameterNames[i].equals("request")){
LogTracer.setParams(parameterNames[i],args[i]);
}
}
}
//直接执行,会执行错误。必须return
Object returnVal = ((ProceedingJoinPoint) joinPoint).proceed();
LogTracer.setReturnValue(returnVal);
long end = System.currentTimeMillis();
LogTracer.setConsumeTime(end-start);
return returnVal;
} catch (Throwable e) {
long end = System.currentTimeMillis();
LogTracer.setParams("Exception",ExceptionUtils.getFullStackTrace(e));
LogTracer.setConsumeTime(end-start);
}finally {
//统一打日志,一个开关解决
if(LogUtil.isPrint(log)){
log.info(LogTracer.getParamNodeLinkedList());
}
}
return null;
}
@After("globalLog()")
public void after(JoinPoint joinPoint){
}
//配置后置返回通知,使用在方法aspect()上注册的切入点
@AfterReturning("globalLog()")
public void afterReturn(JoinPoint joinPoint){
}
//配置抛出异常后通知,使用在方法aspect()上注册的切入点
@AfterThrowing(pointcut="globalLog()", throwing="ex")
public void afterThrow(JoinPoint joinPoint, Exception ex){
LogTracer.setParams("Exception",ExceptionUtils.getFullStackTrace(ex));
}
}
在finally里统一打日志,一个开关解决。
另外为了方便排查的收集器:
package com.cainiao.arrow.aspect;
import com.alibaba.fastjson.JSON;
import lombok.Data;
import org.apache.commons.collections.CollectionUtils;
import java.util.HashMap;
import java.util.LinkedList;
import java.util.Map;
public class LogTracer {
private final static ThreadLocal<LinkedList<ParamNode>> traceLog = new ThreadLocal<>();
static {
traceLog.remove();
}
public static void start(){
traceLog.remove();
}
public static void newParamNode(){
ParamNode paramNode = new ParamNode();
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
paramNodeLinkedList.add(paramNode);
}
public static void setMethod(String method){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
//最后一个是最新的
ParamNode paramNode = paramNodeLinkedList.getLast();
paramNode.setMethod(method);
}
public static void setClazz(String clazz){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
//最后一个是最新的
ParamNode paramNode = paramNodeLinkedList.getLast();
paramNode.setClazz(clazz);
}
public static void setParams(String key,Object value){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
//最后一个是最新的
ParamNode paramNode = paramNodeLinkedList.getLast();
paramNode.addParam(key,value);
}
public static void setReturnValue(Object value){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
//最后一个是最新的
ParamNode paramNode = paramNodeLinkedList.getLast();
paramNode.setReturnValue(value);
}
public static void setConsumeTime(long consumeTime){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
//最后一个是最新的
ParamNode paramNode = paramNodeLinkedList.getLast();
paramNode.setConsumeTime(consumeTime);
}
//public static void add(ParamNode paramNode) {
// LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
// paramNodeLinkedList.add(paramNode);
//}
public static LinkedList<ParamNode> getParamNode() {
LinkedList<ParamNode> paramNodeLinkedList = traceLog.get();
if (paramNodeLinkedList == null) {
paramNodeLinkedList = new LinkedList<ParamNode>();
traceLog.set(paramNodeLinkedList);
}
return paramNodeLinkedList;
}
public static String getParamNodeLinkedList(){
LinkedList<ParamNode> paramNodeLinkedList = getParamNode();
if(CollectionUtils.isNotEmpty(paramNodeLinkedList)){
return JSON.toJSONString(paramNodeLinkedList);
}
return "null";
}
@Data
private static class ParamNode{
private String clazz;
private String method;
private Object returnValue;
private long consumeTime;
private Map<String,Object> params;
public void addParam(String name,Object param){
if(params== null){
params = new HashMap<>();
}
params.put(name,param);
}
}
}
那么现在想要切入这种方式,其实就很简单了,对现有代码毫无侵入:
(1)自己写一个注解和日志切面。
(2)在需要拦截的类上加一个注解。
遇到的坑:
(1)HttpServletRequest类,在收集在trace中,toJSONString的时候报错。
(2) @Order的执行顺序。首先按照order标注的数字依次执行。对于同一个切面的多个同级别advice,是按方法名称的字母排序。
private static final Comparator<Method> METHOD_COMPARATOR;
static {
CompoundComparator<Method> comparator = new CompoundComparator<Method>();
comparator.addComparator(new ConvertingComparator<Method, Annotation>(
new InstanceComparator<Annotation>(
Around.class, Before.class, After.class, AfterReturning.class, AfterThrowing.class),
new Converter<Method, Annotation>() {
@Override
public Annotation convert(Method method) {
AspectJAnnotation<?> annotation = AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(method);
return (annotation != null ? annotation.getAnnotation() : null);
}
}));
comparator.addComparator(new ConvertingComparator<Method, String>(
new Converter<Method, String>() {
@Override
public String convert(Method method) {
return method.getName();
}
}));
METHOD_COMPARATOR = comparator;
}
public List<Advisor> getAdvisors(MetadataAwareAspectInstanceFactory aspectInstanceFactory) {
Class<?> aspectClass = aspectInstanceFactory.getAspectMetadata().getAspectClass();
String aspectName = aspectInstanceFactory.getAspectMetadata().getAspectName();
validate(aspectClass);
// We need to wrap the MetadataAwareAspectInstanceFactory with a decorator
// so that it will only instantiate once.
MetadataAwareAspectInstanceFactory lazySingletonAspectInstanceFactory =
new LazySingletonAspectInstanceFactoryDecorator(aspectInstanceFactory);
List<Advisor> advisors = new LinkedList<Advisor>();
for (Method method : getAdvisorMethods(aspectClass)) {
Advisor advisor = getAdvisor(method, lazySingletonAspectInstanceFactory, advisors.size(), aspectName);
if (advisor != null) {
advisors.add(advisor);
}
}
(3)Caused by: org.springframework.beans.factory.BeanNotOfRequiredTypeException: Bean named '****' is expected to be of type '****' but was actually of type 'com.sun.proxy.$Proxy**' 。
Spring aop代理混用的问题,
(a)、如果目标对象实现了接口,默认情况下会采用JDK的动态代理实现AOP
(b)、如果目标对象实现了接口,可以强制使用CGLIB实现AOP
(c)、如果目标对象没有实现了接口,必须采用CGLIB库,spring会自动在JDK动态代理和CGLIB之间转换
JDK动态代理要比cglib代理执行速度快,但性能不如cglib好.
解决就是把<aop:aspectj-autoproxy>改为<aop:aspectj-autoproxy proxy-target-class="true"/>,如果参数为false表示spring按照上面原则去选择,参数为true表示使用CGLIB动态代理。
(4)其他坑待踩。