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:日誌寫入結束");