welcome to xlongwei.com

欢迎大家一起学习、交流、分享


QQ:9167702333 邮箱:admin@xlongwei.com

AopLogger使用AOP记录接口调用日志


分类 Java   关键字 分享   标签 java   algorithm   spring   发布 hongwei  1428158731687
注意 转载须保留原文链接,译文链接,作者译者等信息。  
AOP面向切面编程,可以切入已有代码的执行过程,例如给接口调用加上日志、给注册用户奖励积分等,对原有代码无侵入。
/**
 * 使用AOP记日志并捕获异常
 * @author hongwei
 * @date 2014-11-12
 */
@Aspect
@Component
public class AopLogger {
	private String targetPackage = "com.itecheast.ite";
	private String aopLoggerClassName = getClass().getName();
	private Boolean hasCallerInfo = null;
	
	@Around(value="execution(* com.itecheast.ite.*.service.*.*(..))")
	public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
		String targetName = joinPoint.getSignature().getDeclaringTypeName();
        String methodName = joinPoint.getSignature().getName();
        Object[] arguments = joinPoint.getArgs();
        Logger logger = LoggerFactory.getLogger(targetName);
        
        String requestInfo = methodName+Arrays.toString(arguments);
        		
        Logger callerLogger = null;
        if(hasCallerInfo==null || hasCallerInfo) {
        StringBuilder caller = new StringBuilder();
        StackTraceElement[] stackTraceElements = new Throwable().getStackTrace();//尝试打印调用者信息
        if (stackTraceElements != null) {
        	for(int i=0;i<stackTraceElements.length;i++) {
        	StackTraceElement stackTraceElement = stackTraceElements[i];
        	String className = stackTraceElement.getClassName();
        	int lastDot = className.lastIndexOf('.');
        	String packageName = className.substring(0, lastDot);
        	if(!packageName.startsWith(targetPackage) || className.equals(aopLoggerClassName) || className.contains("$") || className.contains("proxy")) continue;
        	
        	String simpleClassName = className.substring(lastDot+1);
        	caller.append(' ');
        	caller.append(simpleClassName);
        	caller.append('.');
        	caller.append(stackTraceElement.getMethodName());
        	caller.append(':');
        	caller.append(stackTraceElement.getLineNumber());
        	
        	callerLogger = LoggerFactory.getLogger(stackTraceElement.getClassName());
        	if(hasCallerInfo==null) hasCallerInfo = true;
        	break;
        	}
        }
        if(hasCallerInfo==null) hasCallerInfo = false;
        else requestInfo += caller.toString();
        }
        
        String callerRequestInfo = targetName.substring(targetName.lastIndexOf('.')+1)+"."+requestInfo;
        try {
        	long s = System.currentTimeMillis();
			Object proceed = joinPoint.proceed();
			long e = System.currentTimeMillis();
			if(proceed instanceof Result) {
				Result<?> result = (Result<?>)proceed;
				String responseInfo = proceed.toString()+" in "+(e-s)+" ms";
				if(result.success()) {
					logger.info(requestInfo);
					logger.info(responseInfo);
					if(callerLogger!=null) {
						callerLogger.info(callerRequestInfo);
						callerLogger.info(responseInfo);
					}
				}else {
					logger.warn(requestInfo);
					logger.warn(responseInfo);
					if(callerLogger!=null) {
						callerLogger.warn(callerRequestInfo);
						callerLogger.warn(responseInfo);
					}
				}
			}else {
				String responseInfo = (proceed!=null ? proceed.toString() : "no result")+" in "+(e-s)+" ms";
				logger.info(requestInfo);
				logger.info(responseInfo);
				if(callerLogger!=null) {
					callerLogger.info(callerRequestInfo);
					callerLogger.info(responseInfo);
				}
			}
			return proceed;
        }catch (Exception e) {
			Result<Object> result = Result.newException(e);
			String responseInfo = result.toString();
			result.setMessage(e.getMessage());
			logger.warn(requestInfo);
			logger.warn(responseInfo);
			if(callerLogger!=null) {
				callerLogger.warn(callerRequestInfo);
				callerLogger.warn(responseInfo);
			}
			return result;
		}
	}
}
日志输出样例:ArticleController的63行调用了ArticleServiceImpl的category方法,参数30,耗时0ms,返回值Category@30,通常情况下ArticleServiceImpl和ArticleController的日志时分开的,方便独立查看日志输出。
2015-04-04 22:40:14.017 INFO  [catalina-exec-1] ArticleServiceImpl:73 category[30] ArticleController.article:63
2015-04-04 22:40:14.018 INFO  [catalina-exec-1] ArticleServiceImpl:74 Result<Category>: {code=0, object=Category@30 } in 0 ms
2015-04-04 22:40:14.018 INFO  [catalina-exec-1] ArticleController:76 ArticleServiceImpl.category[30] ArticleController.article:63
2015-04-04 22:40:14.018 INFO  [catalina-exec-1] ArticleController:77 Result<Category>: {code=0, object=Category@30 } in 0 ms

dubbo分布式运行时日志:
consumer端:proxy0是<dubbo:reference />引用代理,IdServiceTester.next:12是调用者及方法行,两处都会打印日志,运行时日志配置分开即可
2015-09-04 15:15:27.440 INFO  [main] proxy0:73-- next[] IdServiceTester.next:12
2015-09-04 15:15:27.440 INFO  [main] proxy0:74-- Result<Long>: {code=0, object=20150904151527437 } in 8 ms
2015-09-04 15:15:27.440 INFO  [main] IdServiceTester:76-- proxy0.next[] IdServiceTester.next:12
2015-09-04 15:15:27.440 INFO  [main] IdServiceTester:77-- Result<Long>: {code=0, object=20150904151527437 } in 8 ms
provider端:IdServiceImpl是实际被调用的bean实例,这里已经找不到调用者的相关信息了,全部是dubbo管理的远程调用
2015-09-04 15:15:27.437 INFO  [DubboServerHandler-192.168.11.149:20880-thread-41] IdServiceImpl:73-- next[]
2015-09-04 15:15:27.437 INFO  [DubboServerHandler-192.168.11.149:20880-thread-41] IdServiceImpl:74-- Result<Long>: {code=0, object=20150904151527437 } in 0 ms