如何优雅地为Struts2的action加监控日志

很久没写博客啦,一晃竟已有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>

  如今须要对helloAhelloB加日志监控,配置以下:数据库

<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行,以下:安全

debug1.png

而后debug模式运行应用,截获的debug信息以下:app

debug2.png

  从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等)实现的接口嘛,而helloAhelloBTestAction自定义的方法,并不在这些接口的方法中,那么最终的代理类$Proxy39天然不会含有这俩方法,调用时就会报上述错误。

2、改进

  咱们的目的是为TestAction中的helloAhelloB方法进行动态代理,但它们不属于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调用栈:debug3.png

  首先,咱们先看下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信息以下:debug4.png

HelloAction@3d696299,这正是咱们在xml中定义的原始bean实例!也就说,AspectJAwareAdvisorAutoProxyCreator就是传说中的第三者。那么问题来了:AspectJAwareAdvisorAutoProxyCreator是在什么状况下又是什么时候被建立的呢?咱们并无显式地在哪里指定,要让它为HelloAction建立代理,这两者是如何关联的起来的呢?

  在eclipse中,定位到AspectJAwareAdvisorAutoProxyCreator类的源码,选中其类名,直接Ctrl+Shift+G查看其在workspace中的全部引用(reference)以下:debug5.png

  进一步跟进registerAspectJAutoProxyCreatorIfNecessary方法,直接Ctrl+Shift+H查看该方法的上层调用链:debug6.png

  到这里第一个问题就比较清晰了:因为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类的继承结构以下:

debug7.png

其中的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,而且patternsHelloAction中的helloAhelloB匹配,致使相应的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扫描到,最终致使上述二次代理的问题。

  最终去掉了BeanNameAutoProxyCreatorgreetingAdvisor,改成<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的,不可被继承。

1.2 CGLib动态代理

  而CGLib则是经过继承目标类,获得其子类的方式生成代理,而final类是不能被继承的,由于CGLib没法为final类生成代理。

  CGLib代理生成的代理类含有$$,好比HelloAction$$EnhancerByCGLIB$$ff7d443b

2、对aop的不熟练所引起的问题

  对aop的不熟练,使得咱们在用的时候,每每就容易忽视了一些细节,如当前采用的动态代理是JDK的仍是CGLib的,默认选择是什么?都有哪些配置项,配置项的默认值,以及各配置项对最终生成代理结果的影响如何?后续将会针对spring aop单独另开博文详解,尽情期待~

3、Struts2的Interceptor机制原理

  Struts2的Interceptor机制是属于aop功能,按理说用常规的动态代理就可实现。可是由初体验 小节中debug过程可知,它并无基于常规的动态字节码技术如JDK动态代理、CGLib动态代理等,而是经过责任链模式和迭代的巧妙结合,实现了aop的功能,有兴趣的话也可研究一下。

同步更新到此处

相关文章
相关标签/搜索