1. 程式人生 > >spring 在有事務的方法上配置自定義日誌切面,事務會失效解決方法

spring 在有事務的方法上配置自定義日誌切面,事務會失效解決方法

問題描述,在servic事務方法中記錄日誌時候,在方法上加上自定義日誌註解橫切面,日誌切面使用Around環繞通知記錄日誌

事務配置都是正確配置,當去除@MethodLog日誌註解時候,事務是可以正常回滾的

如果加上日誌註解@MethodLog事務會失效,不回滾。

自定義註解

@Target({ElementType.METHOD, ElementType.TYPE })  
@Retention(RetentionPolicy.RUNTIME)  
@Documented
public @interface MethodLog {
	String module();
	String funtion();
}


service類

@Service
public class UserServiceImpl implements UserService{

	@Autowired
	private UserMapper userMapper;
	
	@MethodLog(module="使用者",funtion="新增使用者")
	@Transactional
	@Override
	public void insert123(User user) throws Exception {
		// TODO Auto-generated method stub
		userMapper.insert(user);
		throw new NullPointerException("nullpoint exception!!!!!");
		
	}
	}

切面實現類

package com.kerry.aop;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.lang.reflect.Method;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Map;
import java.util.UUID;

import javax.servlet.http.HttpServletRequest;

import org.apache.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.core.NamedThreadLocal;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import com.kerry.model.AppLog;
import com.kerry.service.AppLogService;



/**
 * 使用者操作日誌管理
 * @author lenovo
 */
@Component
@Aspect
public class AppLogAdvice {
	private Logger log=Logger.getLogger(AppLogAdvice.class);
	
	@Autowired
	private AppLogService logService;

	
	private NamedThreadLocal<Long>  startTimeThreadLocal =new NamedThreadLocal<Long>("StopWatch-StartTime");
	
	@Pointcut("@annotation(com.kerry.aop.MethodLog)")
	private void pointcut() {}
	
	
	@Around("pointcut()")
    public Object around(ProceedingJoinPoint point) throws Throwable {
		AppLog logEntity=new AppLog();
		long beginTime = System.currentTimeMillis();//1、開始時間
        startTimeThreadLocal.set(beginTime);//執行緒繫結變數(該資料只有當前請求的執行緒可見)
		logEntity.setId(UUID.randomUUID().toString().replace("-", ""));
		ServletRequestAttributes attributes=(ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
		HttpServletRequest request=attributes.getRequest();
		
		StringBuffer paramStr=new StringBuffer();
		Enumeration<String> nameList=request.getParameterNames();
		while(nameList.hasMoreElements()){
			String name = nameList.nextElement();
			paramStr.append(name).append("=").append(request.getParameter(name)).append("&");
		}
		Map<String, String> map = getMethodLog(point);  
        logEntity.setPath(request.getRequestURI());
        if(paramStr.length()>0){
        	logEntity.setParam(paramStr.substring(0,paramStr.length()-1));
        }
        logEntity.setModule(map.get("module"));
        logEntity.setFunction(map.get("function"));
        Object object = null;
        try{
        	object=point.proceed();
        	logEntity.setStatus("0");
        	logEntity.setRemark("成功");
        	return object;
        }catch(Exception e){
        	e.printStackTrace();
        	logEntity.setStatus("1");
        	logEntity.setRemark("程式出異常");
        	if(e!=null){
        		logEntity.setException(getExceptionTrace(e));
        	}
        }finally{
        	long endTime = System.currentTimeMillis();//1結束時間
    		long time=endTime-startTimeThreadLocal.get();
    		logEntity.setConsumeTime(String.valueOf(time));
    		log.info("Msg:開始寫入日誌...");
    		logService.addAppLog(logEntity);
    		log.info("Msg:日誌寫入結束");
		}
        return object;
	}
	
	/**
	 * 獲取日誌註解標註資訊  
	 * @param joinPoint
	 * @return
	 * @throws Exception
	 */
    public static Map<String, String> getMethodLog(ProceedingJoinPoint joinPoint)  
            throws Exception {
    	Map<String, String> map=new HashMap<String, String>();
        String targetName = joinPoint.getTarget().getClass().getName();  
        String methodName = joinPoint.getSignature().getName();  
        
        @SuppressWarnings("rawtypes")
		Class targetClass = Class.forName(targetName);  
        Method[] method = targetClass.getMethods();  
        for (Method m : method) {  
            if (m.getName().equals(methodName)) {  
                MethodLog methodCache = m.getAnnotation(MethodLog.class);  
                if (methodCache != null) {  
                	map.put("module", methodCache.module());  
                	map.put("function", methodCache.funtion());
                }  
                break;  
            }  
        }  
        return map;  
    }  
    /**
     * 獲取異常資訊
     * @param e
     * @return
     */
    public static String getExceptionTrace(Throwable e){
	    StringWriter sw = new StringWriter();
	    PrintWriter pw = new PrintWriter(sw);
	    e.printStackTrace(pw);
	    pw.flush();
	    pw.close();
	    return sw.toString();
	}
}



當呼叫userServiceImpl中事務方法 insert123(User user)時候,,方法中丟擲異常按照spring事務管理會回滾事務

但是,事務方法上也註解自定義的日誌註解,此時會發現 方法中insert語句成功插入資料庫,而且切面中的日誌也成功插入資料庫,

而我們要的是 當事務方法異常時候,應該會回滾事務, 日誌切面不管事務方法是否異常都要記錄日誌

思考:一個事務方法上有多個切面橫切,會導致事務失效?? 自定義切面影響了spring事務的切面?

解決思路: 是不是自定義切面中try catch了事務方法的exception, 刪除 AppLogAdvice 的around方法的try catch 語句試試

註釋掉try  catch finally 語句塊

	@Around("pointcut()")
    public Object around(ProceedingJoinPoint point) throws Throwable {
		AppLog logEntity=new AppLog();
		long beginTime = System.currentTimeMillis();//1、開始時間
        startTimeThreadLocal.set(beginTime);//執行緒繫結變數(該資料只有當前請求的執行緒可見)
		logEntity.setId(UUID.randomUUID().toString().replace("-", ""));
		ServletRequestAttributes attributes=(ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
		HttpServletRequest request=attributes.getRequest();
		
		StringBuffer paramStr=new StringBuffer();
		Enumeration<String> nameList=request.getParameterNames();
		while(nameList.hasMoreElements()){
			String name = nameList.nextElement();
			paramStr.append(name).append("=").append(request.getParameter(name)).append("&");
		}
		Map<String, String> map = getMethodLog(point);  
        logEntity.setPath(request.getRequestURI());
        if(paramStr.length()>0){
        	logEntity.setParam(paramStr.substring(0,paramStr.length()-1));
        }
        logEntity.setModule(map.get("module"));
        logEntity.setFunction(map.get("function"));
        Object object = null;
//        try{
        	object=point.proceed();
        	logEntity.setStatus("0");
        	logEntity.setRemark("成功");
//        	return object;
//        }catch(Exception e){
//        	e.printStackTrace();
//        	logEntity.setStatus("1");
//        	logEntity.setRemark("程式出異常");
//        	if(e!=null){
//        		logEntity.setException(getExceptionTrace(e));
//        	}
//        }finally{
        	long endTime = System.currentTimeMillis();//1結束時間
    		long time=endTime-startTimeThreadLocal.get();
    		logEntity.setConsumeTime(String.valueOf(time));
    		log.info("Msg:開始寫入日誌...");
    		logService.addAppLog(logEntity);
    		log.info("Msg:日誌寫入結束");
//		}
        return object;
	}

執行結果:   user,和log 資料都被回滾了? 

為什麼都被回滾了? 難道是spring事務傳播 導致的, 而我們logService方法並沒有開啟事務 為何?

@Service
public class AppLogServiceImpl implements AppLogService{
	private Logger log=Logger.getLogger(AppLogServiceImpl.class);
	
	@Autowired
	private AppLogDao dao;

	public void addAppLog(AppLog logEntity) {
		log.info("寫入日誌");
		dao.addAppLog(logEntity);
	}
}

實驗試試,在addApplog上加入不支援事務或者強制新啟一個事務
@Transactional(propagation=Propagation.REQUIRES_NEW)
	public void addAppLog(AppLog logEntity) {

@Transactional(propagation=Propagation.NOT_SUPPORTED)
	public void addAppLog(AppLog logEntity) {

結果,user,log資料還是都會被回滾, 但是我們想要的是log日誌不要被回滾。

為啥log日誌也被回滾

統計下以上測試結果,, 如果around通知中,有try   catch掉service 的執行方法,會發現 事務失效不會回滾, 去掉try catch  事務會回滾,但是日誌記錄也被回滾了

發現不對為啥日誌會被回滾,也不是事務傳播屬性導致的,到底是啥的,,接著看了下控制檯日誌,發現原來當去除 try catch 塊時候,切面中執行到  object=point.proceed(); 這裡的時候,就會丟擲異常, 這句程式碼下面的日誌記錄不會被執行的,所以日誌程式碼那壓根就沒執行,所以沒記錄入庫。

綜合統計以上:去除自定義日誌的try catch事務會回滾, 也就是在自定義切面的時候,不能try  catch  執行的事務方法,

問題:業務中就要這麼幹啊,不管事務方法是否異常都要執行日誌記錄。

回到上面,在日誌切面實現類中放開around方法中的try catch 語句塊,尋找為啥事務沒生效,沒回滾原因。

猜想:是不是切面執行順序問題,一個類被多個切面橫切,那個先執行,那個後執行或者是交替執行?

繼續測試

around環繞通知, 此時通知又try catch掉service執行程式碼 ,控制檯記錄:

2017-08-25 14:08:40.160  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : AppLogAdvice Exception...... 
2017-08-25 14:08:40.161  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : Msg:開始寫入日誌...
2017-08-25 14:08:40.171  INFO 4068 --- [nio-8080-exec-1] c.kerry.service.impl.AppLogServiceImpl   : 寫入日誌
2017-08-25 14:08:40.174  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : Msg:日誌寫入結束
應該執行的service內的方法後在執行切面類的 ,所以順序是先執行的事務切面,再是自定義日誌切面

此時我們手動改變下順序, 使用@order註解日誌切面 

@Component
@Aspect
@Order(0)
public class AppLogAdvice {

測試日誌 
2017-08-25 14:17:04.595  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : AppLogAdvice Exception...... 
2017-08-25 14:17:04.596  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : Msg:開始寫入日誌...
2017-08-25 14:17:04.604  INFO 4068 --- [nio-8080-exec-1] c.kerry.service.impl.AppLogServiceImpl   : 寫入日誌
2017-08-25 14:17:04.606  INFO 4068 --- [nio-8080-exec-1] com.kerry.aop.AppLogAdvice               : Msg:日誌寫入結束
null
org.springframework.transaction.UnexpectedRollbackException: Transaction rolled back because it has been marked as rollback-only
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:724)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:487)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy235.insert123(Unknown Source)
	at com.kerry.web.UserController.save(UserController.java:43)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Transaction rolled back because it has been marked as rollback-only
2017-08-25 14:17:04.694  WARN 4068 --- [nio-8080-exec-1] .m.m.a.ExceptionHandlerExceptionResolver : Resolved exception caused by Handler execution: org.springframework.transaction.UnexpectedRollbackException: Transaction rolled back because it has been marked as rollback-only
通過以上日誌我們發現先執行的日誌切面,再執行的service方法。
檢視資料庫發現  user 和 log 都被回滾了,日誌顯示事務會回滾了, 但是為毛把log也回滾了? 事務傳播搞的鬼?

為了驗證猜想,那就繼續更改spring事務傳播屬性,更改日誌記錄的service方法

@Transactional(propagation=Propagation.NOT_SUPPORTED)
	public void addAppLog(AppLog logEntity) {
		log.info("寫入日誌");
		dao.addAppLog(logEntity);
	}

設定為不支援事務

測試結果 通過, user插入失敗,日誌插入成功 ,

接著測試,寫入日誌不使用上面的service ,新起一個thread類,插入日誌

public class LogThread extends Thread {
	
	
	private AppLogService logService;
	private AppLog log;

	public LogThread(AppLogService logService,AppLog log) {
		this.logService = logService;
		this.log = log;
	}

	@Override
	public void run() {
		logService.addAppLog(log);
	}

切面類插入日誌更改成新啟執行緒插入,同時去除logService.addAppLog方法上設定的事務
    }finally{
        	long endTime = System.currentTimeMillis();//1結束時間
    		long time=endTime-startTimeThreadLocal.get();
    		logEntity.setConsumeTime(String.valueOf(time));
    		log.info("Msg:開始寫入日誌...");
//    		logService.addAppLog(logEntity);
    		new LogThread(logService, logEntity).start();
    		log.info("Msg:日誌寫入結束");
		}

測試結果發現, user插入失敗, log插入成功 符合預期結果

此時可以確定應該是事務傳播引起的導致user,和log都回滾了。 當分來開不同事務執行緒 就可以得到正確答案。

綜上所述: 在使用事務切面的方法上使用自定義切面 並且使用around環繞通知時候, 當try   catch掉被執行事務方法時候,事務會失效,

解決方法

方法1 : 不要try  catch 被執行事務方法

方法2 : springmvc 中使用try   catch,但是設定自定義切面執行順序更 高優先順序

如: spring mvc中  被切面類

@Component
@Aspect
@Order(0)
public class AppLogAdvice {

註解事務設定 order(2)

<!-- 配置 Annotation 驅動,掃描@Transactional註解的類定義事務  -->
	<tx:annotation-driven transaction-manager="transactionManager" proxy-target-class="true" order="2"/>


方法3 springboot中,使用try catch  的  around方法時候 ,除了要設定自定義切面的優選順序高還得設定 日誌插入的方法不支援事務或者自己強制新啟一個事務

@Component
@Aspect
@Order(0)
public class AppLogAdvice {

//@Transactional(propagation=Propagation.NOT_SUPPORTED)
	@Transactional(propagation=Propagation.REQUIRES_NEW)
	public void addAppLog(AppLog logEntity) {
		log.info("寫入日誌");
		dao.addAppLog(logEntity);
	}

或者  使用新建Thread類處理插入日誌
   		log.info("Msg:開始寫入日誌...");
//    		logService.addAppLog(logEntity);
    		new LogThread(logService, logEntity).start();
    		log.info("Msg:日誌寫入結束");