如何優雅地爲Struts2的action加監控日誌

時間 2019-12-23

標籤如何優雅 struts2 struts action 監控日誌欄目 Struts 简体版

原文原文鏈接

很久沒寫博客啦，一晃竟已有5個月了，實在是慚愧的很，待整理的checklist仍是挺多的，努力一一補上！今天這篇博文源於工做中的一個case：爲Struts2中的特定action添加監控日誌。對Struts2熟悉的童鞋可能會說，這個不就是常規的aop功能嗎，直接利用其自帶的攔截器（Interceptor）機制就可輕易實現，so easy！但最終筆者並無這麼幹，爲什麼呢？後面會說。這期間，筆者也走了好幾條彎路，皆以失敗了結，其中牽涉到aop代理的好一些細節知識點，以及一些常見的aop誤區，若是沒有這些彎路的嘗試，可能都不會注意到它，故記錄於此，引覺得鑑。java

問題背景

　　最近拿到一個需求：對指定的部分請求增長日誌監控，即在方法調用前，作一些統一的業務邏輯判斷，對於符合條件的則打印方法名、參數等上下文信息，便於後續統計分析。因爲歷史緣由，當前工程較老，其MVC框架仍是基於Struts2的！固然，因爲忍受不了Struts2的各類安全漏洞、笨重不堪等問題，該工程的MVC框架也正在向spring MVC遷移。目前的狀況是，Struts2和spring MVC並存，而這次所要攔截的請求都屬於老的接口，問題就變成如何爲Struts2中的action增長日誌監控。git

解決方案

1、初體驗

　　背景中已提到，項目的MVC框架最終會去掉Struts2並徹底切換到spring MVC，所以，爲了不與Struts2過渡耦合，一開始我就避開了其自帶的Interceptor機制，試圖用spring aop來解決它，這樣就跟MVC框架無關了，後面即使切換到spring MVC，這塊也不用再改動。github

　　首先想到了spring中的自動代理建立器，爲了與現有的代碼保持一致，選用了基於Bean名稱匹配的BeanNameAutoProxyCreator，爲了講解的方便，筆者寫了個簡單的demo，相關類定義以下：web

/**
 * @author sherlockyb
 * @2017年12月9日
 */
public class HelloAction extends ActionSupport implements ServletRequestAware, ServletResponseAware {
  ......
  public void helloA() {
    System.out.println("say: hello A");
  }
  public void helloB() {
    System.out.println("say: hello B");
  }
  public void helloC() {
    System.out.println("say: hello C");
  }
  ......
}

/**
 * @author sherlockyb
 * @2017年12月10日
 */
public class GreetingMethodInterceptor implements MethodInterceptor {
  private final Logger log = LoggerFactory.getLogger(getClass());
  @Override
  public Object invoke(MethodInvocation invocation) throws Throwable {
    log.info("greeting before invocation...");
    Object result = invocation.proceed();
    log.info("greeting after invocation");
	return result;
  }
}

　　數據庫的聲明式事務配置appContext-struts2-db.xml以下，之因此要把這個配置專門列出來，由於它與後面的一次報錯息息相關，咱們暫且往下走。spring

<bean id="txAdvice" class="org.sherlockyb.blogdemos.struts2.aop.TransactionManagerAdvice"></bean>
<aop:config>
  <aop:pointcut id="helloPointcut" expression="execution(* org.sherlockyb..*HelloService*.*(..))" />
  <aop:advisor advice-ref="txAdvice" pointcut-ref="helloPointcut" order="1" />
</aop:config>

　　如今須要對helloA和helloB加日誌監控，配置以下：數據庫

<bean name="greetingInterceptor" class="org.sherlockyb.blogdemos.struts2.aop.GreetingMethodInterceptor" />
<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
  <property name="beanNames">
    <list>
      <value>helloAction</value>
    </list>
  </property>
  <property name="interceptorNames">
    <list>
      <value>greetingAdvisor</value>
    </list>
  </property>
</bean>
<bean id="greetingAdvisor" class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
  <property name="advice">
    <ref bean="greetingInterceptor" />
  </property>
  <property name="patterns">
    <list>
      <value>org.sherlockyb.blogdemos.struts2.web.action.HelloAction.helloA</value>
      <value>org.sherlockyb.blogdemos.struts2.web.action.HelloAction.helloB</value>
    </list>
  </property>
</bean>

　　而後用postman測試action請求http://localhost/hello/helloA.action，直接報錯：express

java.lang.NoSuchMethodException: com.sun.proxy.$Proxy39.helloA()
	at ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1247)
	at ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:68)
	at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethodWithDebugInfo(XWorkMethodAccessor.java:117)
	at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethod(XWorkMethodAccessor.java:108)
	at ognl.OgnlRuntime.callMethod(OgnlRuntime.java:1370)
	at ognl.ASTMethod.getValueBody(ASTMethod.java:91)
	at ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)
	at ognl.SimpleNode.getValue(SimpleNode.java:258)
	at ognl.Ognl.getValue(Ognl.java:467)
	at ognl.Ognl.getValue(Ognl.java:431)
	at com.opensymphony.xwork2.ognl.OgnlUtil$3.execute(OgnlUtil.java:352)
	at com.opensymphony.xwork2.ognl.OgnlUtil.compileAndExecuteMethod(OgnlUtil.java:404)
	at com.opensymphony.xwork2.ognl.OgnlUtil.callMethod(OgnlUtil.java:350)
	at com.opensymphony.xwork2.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:430)
	at com.opensymphony.xwork2.DefaultActionInvocation.invokeActionOnly(DefaultActionInvocation.java:290)
	at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:251)
  ...

　　NoSuchMethodException？奇了怪了，TestAction中明明有helloA方法，而且patterns配置中也加了org.sherlockyb.blogdemos.struts2.web.action.helloA的配置，爲啥最終生成的代理類卻沒有這個方法呢？究竟是哪裏出了問題？帶着這個疑問，咱們直接從異常信息着手：既然它報的是$Proxy39這個類沒有helloA方法，那咱們就來debug看一下$Proxy39究竟有哪些內容。apache

　　由於OgnlRuntime粒度太細了，太多地方調用，若在這裏面打斷點還得根據條件斷點才能定位到TestAction的調用，比較麻煩，故筆者選擇了在調用棧中所處位置較爲上層的DefaultActionInvocation。定位到異常信息DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:430)對應的源碼，斷點打在了源碼的第430行，以下：安全

而後debug模式運行應用，截獲的debug信息以下：app

　　從1處能夠看出，原來$Proxy39是JDK動態代理生成的代理類，至於爲啥是JDK代理，能夠注意到變量proxyTargetClass默認是false的，也就是說spring aop 默認採用JDK動態代理。咱們知道，JDK動態代理是面向接口的，只會爲目標類所實現的接口生成代理方法，查看2處interface的內容以下：

[interface org.apache.struts2.interceptor.ServletRequestAware, interface org.apache.struts2.interceptor.ServletResponseAware, interface com.opensymphony.xwork2.Action, interface com.opensymphony.xwork2.Validateable, interface com.opensymphony.xwork2.ValidationAware, interface com.opensymphony.xwork2.TextProvider, interface com.opensymphony.xwork2.LocaleProvider, interface java.io.Serializable]

這些不正是TestAction直接（ServletRequestAware等）或間接（Action等）實現的接口嘛，而helloA和helloB是TestAction自定義的方法，並不在這些接口的方法中，那麼最終的代理類$Proxy39天然不會含有這倆方法，調用時就會報上述錯誤。

2、改進

　　咱們的目的是爲TestAction中的helloA和helloB方法進行動態代理，但它們不屬於TestAction所實現接口中的任何一個方法，顯然JDK動態代理知足不了需求，轉向CGLib代理，因而將proxyTargetClass參數改成true，強制其走CGLib代理。配置以下：

<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
  ......
  <property name="proxyTargetClass">
    <value>true</value>
  </property>
  ......
</bean>
……

依舊用postman測試，依舊報錯了：

[ERROR] 2017-12-12 23:17:49,450 [resin-port-80-48] struts2.dispatcher.DefaultDispatcherErrorHandler (CommonsLogger.java:42) -Exception occurred during processing request: Unable to instantiate Action, helloAction,  defined for 'helloA' in namespace '/hello'Error creating bean with name 'helloAction' defined in class path resource [appContext-struts2-action.xml]: Initialization of bean failed; nested exception is org.springframework.aop.framework.AopConfigException: Could not generate CGLIB subclass of class [class com.sun.proxy.$Proxy40]: Common causes of this problem include using a final class or a non-visible class; nested exception is java.lang.IllegalArgumentException: Cannot subclass final class class com.sun.proxy.$Proxy40
Unable to instantiate Action, helloAction,  defined for 'helloA' in namespace '/hello'Error creating bean with name 'helloAction' defined in class path resource [appContext-struts2-action.xml]: Initialization of bean failed; nested exception is org.springframework.aop.framework.AopConfigException: Could not generate CGLIB subclass of class [class com.sun.proxy.$Proxy40]: Common causes of this problem include using a final class or a non-visible class; nested exception is java.lang.IllegalArgumentException: Cannot subclass final class class com.sun.proxy.$Proxy40 - action - file:/D:/DevCode/workspace/blog-demos/struts2/target/classes/org/sherlockyb/blogdemos/struts2/web/action/conf/struts-hello.xml:9:61
	at com.opensymphony.xwork2.DefaultActionInvocation.createAction(DefaultActionInvocation.java:317)
	at com.opensymphony.xwork2.DefaultActionInvocation.init(DefaultActionInvocation.java:398)
	at com.opensymphony.xwork2.DefaultActionProxy.prepare(DefaultActionProxy.java:194)
	at org.apache.struts2.impl.StrutsActionProxy.prepare(StrutsActionProxy.java:63)
	at org.apache.struts2.impl.StrutsActionProxyFactory.createActionProxy(StrutsActionProxyFactory.java:37)
	at com.opensymphony.xwork2.DefaultActionProxyFactory.createActionProxy(DefaultActionProxyFactory.java:58)
	at org.apache.struts2.dispatcher.Dispatcher.serviceAction(Dispatcher.java:565)
	at org.apache.struts2.dispatcher.ng.ExecuteOperations.executeAction(ExecuteOperations.java:81)
	at org.apache.struts2.dispatcher.ng.filter.StrutsPrepareAndExecuteFilter.doFilter(StrutsPrepareAndExecuteFilter.java:99)

　　咱們能夠注意到異常棧中最底層的一條錯誤信息：Cannot subclass final class class com.sun.proxy.$Proxy40，這條錯誤是致使上述報錯的最根本緣由（root cause），其對應的調用鏈詳情以下：

Caused by: java.lang.IllegalArgumentException: Cannot subclass final class class com.sun.proxy.$Proxy40
	at net.sf.cglib.proxy.Enhancer.generateClass(Enhancer.java:446)
	at net.sf.cglib.transform.TransformingClassGenerator.generateClass(TransformingClassGenerator.java:33)
	at net.sf.cglib.core.DefaultGeneratorStrategy.generate(DefaultGeneratorStrategy.java:25)
	at net.sf.cglib.core.AbstractClassGenerator.create(AbstractClassGenerator.java:216)
	at net.sf.cglib.proxy.Enhancer.createHelper(Enhancer.java:377)
	at net.sf.cglib.proxy.Enhancer.create(Enhancer.java:285)
	at org.springframework.aop.framework.Cglib2AopProxy.getProxy(Cglib2AopProxy.java:201)

　　也就是說，當前面配置的BeanNameAutoProxyCreator嘗試爲目標類com.sun.proxy.$Proxy40生成CGLib代理時，卻發現這貨是final的！也就是說JDK動態代理生成的代理類是final的，大家知道這個知識點嘛？反正在此以前我是沒留意過這個，知道的童鞋可舉個爪，那說明你走的比我遠，要繼續保持這樣的好奇心。咱們言歸正傳，上述錯誤代表，在BeanNameAutoProxyCreator生效前，已經有第三者爲TestAction以JDK動態代理的方式生成了代理類，致使沒法再進行CGLib代理。這個第三者究竟是誰呢？

　　起初我想到了Struts2的Interceptor機制，會不會是Struts2事先採用JDK動態代理的方式爲TestAction生成了代理，以便加上各類Interceptor加強邏輯？很快，我經過debug跟蹤Struts2源碼否決了這個猜想：

一、action是交給spring管理的，即StrutsSpringObjectFactory，咱們知道action的做用域是prototype的，即每來一個請求，Struts2都會經過DefaultActionFactory來buildAction，而實際的建立則是委託給StrutsSpringObjectFactory來處理，也就說Struts2是拿到spring容器構建好的action以後，才作後續的Interceptor過程；

二、經過仔細閱讀DefaultActionInvocation的invoke源碼可知，Struts2的Interceptor機制既不是經過JDK動態代理來實現，也沒有采納CGLib代理，而是巧用責任鏈和迭代等代碼技巧來實現的，具體細節等後面單獨一篇博文細說。

　　那究竟是何方神聖偷偷作了這個事兒呢？謎底盡在源碼中！經過源碼來跟蹤下action的建立過程：

一、DefaultActionInvocation——action的建立（每次請求必走邏輯）

protected void createAction(Map<String, Object> contextMap) {
  // load action
  String timerKey = "actionCreate: " + proxy.getActionName();
  try {
    UtilTimerStack.push(timerKey);
    action = objectFactory.buildAction(proxy.getActionName(), proxy.getNamespace(), proxy.getConfig(), contextMap);
  } catch (InstantiationException e) {
    throw new XWorkException("Unable to intantiate Action!", e, proxy.getConfig());
  }
  ......
}

二、StrutsSpringObjectFactory——spring容器層面的，bean的建立

@Override
public Object buildBean(String beanName, Map<String, Object> extraContext, boolean injectInternal) throws Exception {
  Object o;
  if (appContext.containsBean(beanName)) {
    o = appContext.getBean(beanName);	//action從spring容器中獲取
  } else {
    Class beanClazz = getClassInstance(beanName);
    o = buildBean(beanClazz, extraContext);
  }
  if (injectInternal) {
    injectInternalBeans(o);
  }
  return o;
}

三、AbstractAutowireCapableBeanFactory——spring容器中，bean的初始化以及以後的postProcess過程

protected Object initializeBean(final String beanName, final Object bean, RootBeanDefinition mbd) {
  ......
  if (mbd == null || !mbd.isSynthetic()) {
    wrappedBean = applyBeanPostProcessorsBeforeInitialization(wrappedBean, beanName);
  }
  try {
    invokeInitMethods(beanName, wrappedBean, mbd);
  }
  catch (Throwable ex) {
    throw new BeanCreationException((mbd != null ? mbd.getResourceDescription() : null),
					beanName, "Invocation of init method failed", ex);
  }
  //Bean初始化以後，postProcess處理，如一系列的AutoProxyCreator
  if (mbd == null || !mbd.isSynthetic()) { 
    wrappedBean = applyBeanPostProcessorsAfterInitialization(wrappedBean, beanName);
  }
  return wrappedBean;
}

　　最終定位到AspectJAwareAdvisorAutoProxyCreator，直接看debug調用棧：

　　首先，咱們先看下wrapIfNecessary的核心代碼片斷以下，其大體功能就是爲目標bean建立代理類：先看下bean有沒有相關的advice，若是有，則經過createProxy爲其建立代理類；不然直接返回原始bean！

protected Object wrapIfNecessary(Object bean, String beanName, Object cacheKey) {
		......
		// Create proxy if we have advice.
		Object[] specificInterceptors = getAdvicesAndAdvisorsForBean(bean.getClass(), beanName, null);
		if (specificInterceptors != DO_NOT_PROXY) {
			this.advisedBeans.add(cacheKey);
			Object proxy = createProxy(bean.getClass(), beanName, specificInterceptors, new SingletonTargetSource(bean));
			this.proxyTypes.put(cacheKey, proxy.getClass());
			return proxy;
		}
		this.nonAdvisedBeans.add(cacheKey);
		return bean;
	}

這裏bean的debug信息以下：

HelloAction@3d696299，這正是咱們在xml中定義的原始bean實例！也就說，AspectJAwareAdvisorAutoProxyCreator就是傳說中的第三者。那麼問題來了：AspectJAwareAdvisorAutoProxyCreator是在什麼狀況下又是什麼時候被建立的呢？咱們並無顯式地在哪裏指定，要讓它爲HelloAction建立代理，這兩者是如何關聯的起來的呢？

　　在eclipse中，定位到AspectJAwareAdvisorAutoProxyCreator類的源碼，選中其類名，直接Ctrl+Shift+G查看其在workspace中的全部引用（reference）以下：

　　進一步跟進registerAspectJAutoProxyCreatorIfNecessary方法，直接Ctrl+Shift+H查看該方法的上層調用鏈：

　　到這裏第一個問題就比較清晰了：因爲appContext-struts2-db.xml中經過<aop:config>爲數據庫操做配置了聲明式事務，致使AspectJAwareAdvisorAutoProxyCreator實例的構建。咱們再來看第二個問題，即這個AutoProxyCreator是如何與HelloAction關聯的，回顧下前面的wrapIfNecessary的源碼片斷，其中有一個getAdvicesAndAdvisorsForBean方法，它是定義在抽象類AbstractAutoProxyCreator中的抽象方法，其功能以下方的官方註釋所說：判斷當前目標bean是否須要代理，若是是則返回對應的加強（advice）或切面（advisor）集。具體實現則交給各具體的子類，典型的模板方法設計。

/**
  * Return whether the given bean is to be proxied, what additional
  * advices (e.g. AOP Alliance interceptors) and advisors to apply.
  */
  protected abstract Object[] getAdvicesAndAdvisorsForBean(Class<?> beanClass, String beanName, TargetSource customTargetSource) throws BeansException;

AbstractAutoProxyCreator類的繼承結構以下：

其中的AbstractAdvisorAutoProxyCreator很關鍵，它是第三者AspectJAwareAdvisorAutoProxyCreator的直接父類，並實現抽象方法getAdvicesAndAdvisorsForBean，邏輯以下：

@Override
protected Object[] getAdvicesAndAdvisorsForBean(Class beanClass, String beanName, TargetSource targetSource) {
	List advisors = findEligibleAdvisors(beanClass, beanName);	//找出bean相關的advisors
	if (advisors.isEmpty()) {
      return DO_NOT_PROXY;	//若是沒有advisor，則直接返回約定的DO_NOT_PROXY，表示無需代理
	}
	return advisors.toArray();
}

再看下findEligibleAdvisors具體作了什麼：

protected List<Advisor> findEligibleAdvisors(Class beanClass, String beanName) {
  //獲取當前spring容器中全部的Advisor，除了FactoryBean類型的和目前已構建過的
  List<Advisor> candidateAdvisors = findCandidateAdvisors();
  List<Advisor> eligibleAdvisors = findAdvisorsThatCanApply(candidateAdvisors, beanClass, beanName);	//從中篩選出能夠應用在bean上的advisor
  extendAdvisors(eligibleAdvisors);
  if (!eligibleAdvisors.isEmpty()) {
    eligibleAdvisors = sortAdvisors(eligibleAdvisors);
  }
  return eligibleAdvisors;
}

最終經過層層代碼跳轉，咱們來到了AopUtils中斷定advisor與bean是否匹配的關鍵邏輯：

public static boolean canApply(Pointcut pc, Class<?> targetClass, boolean hasIntroductions) {
  if (!pc.getClassFilter().matches(targetClass)) {	//先看類級別是否匹配，不匹配就直接返回false
    return false;
  }
  //方法匹配器：切點的一部分，斷定目標方法是否與切點表達式匹配
  MethodMatcher methodMatcher = pc.getMethodMatcher();
  IntroductionAwareMethodMatcher introductionAwareMethodMatcher = null;
  if (methodMatcher instanceof IntroductionAwareMethodMatcher) {
    introductionAwareMethodMatcher = (IntroductionAwareMethodMatcher) methodMatcher;
  }
  Set<Class> classes = new HashSet<Class>(ClassUtils.getAllInterfacesForClassAsSet(targetClass));
  classes.add(targetClass);
  /**這裏的classes由兩部分組成：一個是目標類所實現的全部接口；一個是目標類自己(targetClass)。結合下面的循環掃描Methods的邏輯，也就是說，它會掃描目標類所實現的全部接口中定義的方法和目標類自身定義的方法
  */
  for (Class<?> clazz : classes) {
    Method[] methods = clazz.getMethods();
    for (Method method : methods) {
      if ((introductionAwareMethodMatcher != null && 
           introductionAwareMethodMatcher.matches(method, targetClass, hasIntroductions)) ||
           methodMatcher.matches(method, targetClass)) {
        return true;
      }
    }
  }
  return false;
}

　　看到這兒整個流程就清晰了：因爲咱們配置了greetingAdvisor，而且patterns與HelloAction中的helloA和helloB匹配，致使相應的advisor與目標bean（HelloAction）關聯了，即getAdvicesAndAdvisorsForBean返回的Interceptors不爲DO_NOT_PROXY，因而走了下面的createProxy邏輯，又由於AspectJAwareAdvisorAutoProxyCreator的配置項proxyTargetClass默認是false的，進而爲HelloAction建立了JDK動態代理。

3、最終版

　　通過上述兩次錯誤分析，咱們得知如下幾點：

一、首先使用CGLib的方式爲HelloAction建立代理是必須的，由於咱們所要代理的方法是HelloAction自定義的，且不在其所實現接口的方法列表中，面向接口的JDK動態代理行不通；

二、只要當前應用中別的地方事先配置了<aop:config>（好比最經常使用的聲明式事務），就沒法使用BeanNameAutoProxyCreator的方式爲HelloAction建立CGLib代理！由於要爲目標類的部分方法生成代理，其配置項interceptorNames就只能用Advisor而非普通的bean名稱，而Advisor又會被AspectJAwareAdvisorAutoProxyCreator掃描到，最終致使上述二次代理的問題。

　　最終去掉了BeanNameAutoProxyCreator和greetingAdvisor，改成<aop:config>經過指定proxy-target-class爲true強制AspectJAwareAdvisorAutoProxyCreator走CGLib代理，配置以下：

<aop:config proxy-target-class="true"> <aop:pointcut id="pt-greet" expression="( execution(* org.sherlockyb.blogdemos.struts2.web.action.HelloAction.helloA(..)) or execution(* org.sherlockyb.blogdemos.struts2.web.action.HelloAction.helloB(..)) )"/>
  <aop:advisor id="ad-greet" advice-ref="greetingInterceptor" pointcut-ref="pt-greet"/> 
</aop:config>

　　最後的攔截效果以下：

[INFO] 2017-12-14 23:44:03,972 [resin-port-80-51] struts2.aop.GreetingMethodInterceptor (GreetingMethodInterceptor.java:33) -greeting before invocation...
say: hello A
[INFO] 2017-12-14 23:44:08,234 [resin-port-80-51] struts2.aop.GreetingMethodInterceptor (GreetingMethodInterceptor.java:35) -greeting after invocation

總結

1、JDK與CGLib動態代理的本質區別

1.1 JDK動態代理

　　JDK動態代理是面向接口的，即被代理的目標類必須實現接口，且最終只會爲目標類所實現的全部接口中的方法生成代理方法，對於目標類中包含的可是非接口中的方法，是不會生成對應的代理方法，methodA和methodB就是例子，這是由JDK代理的實現機制所決定了的：經過繼承自Proxy類，實現目標類所實現的接口來生成代理類。

　　JDK動態代理生成的代理類，以$Proxy開頭，後面的計數數字表示當前生成的是第幾個代理類。且代理類是final的，不可被繼承。