年后负责一个比较老的服务,报警不少,今天排查的这个问题也只有在老版本MyBatis下才有机会复现,值此宝贵的线上问题机会,记录一番。

低版本MyBatis中,在高并发情况下,有概率遇到解析private内部类集合解析抛错的情况。

我通过分析异常栈+搜索+分析源码的方式解决了此问题。

背景

直接上我们的异常栈:

2024-03-01 18:45:28.503 [38728506_441_358] [TID: N/A] ERROR c.l.c.c.t.TestController.batisConcurrentBug$4:1076 - {"bltag":"log_error","errmsg":"selectByOrderIdsAndContractTypesAndContractStatus::class org.mybatis.spring.MyBatisSystemException:nested exception is org.apache.ibatis.builder.BuilderException: Error evaluating expression 'orderIds != null and orderIds.size() > 0'. Cause: org.apache.ibatis.ognl.MethodFailedException: Method \"size\" failed for object [690] [java.lang.IllegalAccessException: Class org.apache.ibatis.ognl.OgnlRuntime can not access a member of class java.util.Arrays$ArrayList with modifiers \"public\"]\norg.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:75)\norg.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:371)\ncom.sun.proxy.$Proxy69.selectList(Unknown Source)\norg.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:198)\norg.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:119)\norg.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63)\norg.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52)\ncom.sun.proxy.$Proxy135.selectByOrderIdsAndContractTypesAndContractStatus(Unknown Source)\nsun.reflect.GeneratedMethodAccessor361.invoke(Unknown Source)\nsun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\njava.lang.reflect.Method.invoke(Method.java:498)\norg.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)\norg.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)\norg.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)\ncom.company.fn.mybatis.encrypt.DaoEncryptAspect.invoke(DaoEncryptAspect.java:47)\norg.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)\norg.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)\ncom.sun.proxy.$Proxy136.selectByOrderIdsAndContractTypesAndContractStatus(Unknown Source)\ncom.company.contract.controller.test.TestController.lambda$testMybatisConcurrentBug$4(TestController.java:1073)\njava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\njava.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)\njava.util.concurrent.FutureTask.run(FutureTask.java)\njava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\njava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\njava.lang.Thread.run(Thread.java:750)\n","host":"10.33.74.11","port":"8080","segmentid":"","line":0}
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.builder.BuilderException: Error evaluating expression 'orderIds != null and orderIds.size() > 0'. Cause: org.apache.ibatis.ognl.MethodFailedException: Method "size" failed for object [690] [java.lang.IllegalAccessException: Class org.apache.ibatis.ognl.OgnlRuntime can not access a member of class java.util.Arrays$ArrayList with modifiers "public"]
    at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:75) ~[mybatis-spring-1.2.2.jar:1.2.2]
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:371) ~[mybatis-spring-1.2.2.jar:1.2.2]
    at com.sun.proxy.$Proxy69.selectList(Unknown Source) ~[?:?]
    at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:198) ~[mybatis-spring-1.2.2.jar:1.2.2]
    at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:119) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52) ~[mybatis-3.2.8.jar:3.2.8]
    at com.sun.proxy.$Proxy135.selectByOrderIdsAndContractTypesAndContractStatus(Unknown Source) ~[?:?]
    at sun.reflect.GeneratedMethodAccessor361.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_362]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_362]
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at com.company.fn.mybatis.encrypt.DaoEncryptAspect.invoke(DaoEncryptAspect.java:47) ~[fn-commons-utils-1.4.4-SNAPSHOT.jar:?]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at com.sun.proxy.$Proxy136.selectByOrderIdsAndContractTypesAndContractStatus(Unknown Source) ~[?:?]
    at com.company.contract.controller.test.TestController.lambda$testMybatisConcurrentBug$4(TestController.java:1073) ~[classes/:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_362]
    at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) [?:1.8.0_362]
    at java.util.concurrent.FutureTask.run(FutureTask.java) [?:1.8.0_362]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_362]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_362]
    at java.lang.Thread.run(Thread.java:750) [?:1.8.0_362]
Caused by: org.apache.ibatis.builder.BuilderException: Error evaluating expression 'orderIds != null and orderIds.size() > 0'. Cause: org.apache.ibatis.ognl.MethodFailedException: Method "size" failed for object [690] [java.lang.IllegalAccessException: Class org.apache.ibatis.ognl.OgnlRuntime can not access a member of class java.util.Arrays$ArrayList with modifiers "public"]
    at org.apache.ibatis.scripting.xmltags.OgnlCache.getValue(OgnlCache.java:47) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.ExpressionEvaluator.evaluateBoolean(ExpressionEvaluator.java:32) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.IfSqlNode.apply(IfSqlNode.java:33) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.MixedSqlNode.apply(MixedSqlNode.java:32) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:40) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:278) ~[mybatis-3.2.8.jar:3.2.8]
    at com.company.hawkeye.client.mybitis.CatMybatisPlugin.intercept(CatMybatisPlugin.java:70) ~[hawk-client-1.5.6.jar:?]
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:60) ~[mybatis-3.2.8.jar:3.2.8]
    at com.sun.proxy.$Proxy296.query(Unknown Source) ~[?:?]
    at sun.reflect.GeneratedMethodAccessor475.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_362]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_362]
    at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49) ~[mybatis-3.2.8.jar:3.2.8]
    at com.company.ctt.metrics.core.instrument.mybatis.MyBatisMetricsInterceptor.recordRequest(MyBatisMetricsInterceptor.java:55) ~[metrics-dog-core-2.1.9.31.jar:2.1.9.31]
    at com.company.ctt.metrics.core.instrument.mybatis.MyBatisMetricsInterceptor.intercept(MyBatisMetricsInterceptor.java:33) ~[metrics-dog-core-2.1.9.31.jar:2.1.9.31]
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:60) ~[mybatis-3.2.8.jar:3.2.8]
    at com.sun.proxy.$Proxy296.query(Unknown Source) ~[?:?]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:108) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:102) ~[mybatis-3.2.8.jar:3.2.8]
    at sun.reflect.GeneratedMethodAccessor405.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_362]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_362]
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358) ~[mybatis-spring-1.2.2.jar:1.2.2]
    ... 23 more
Caused by: org.apache.ibatis.ognl.MethodFailedException: Method "size" failed for object [690]
    at org.apache.ibatis.ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:837) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:61) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.OgnlRuntime.callMethod(OgnlRuntime.java:860) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.ASTMethod.getValueBody(ASTMethod.java:73) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.ASTChain.getValueBody(ASTChain.java:109) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.ASTGreater.getValueBody(ASTGreater.java:49) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.ASTAnd.getValueBody(ASTAnd.java:56) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:333) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:310) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.OgnlCache.getValue(OgnlCache.java:45) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.ExpressionEvaluator.evaluateBoolean(ExpressionEvaluator.java:32) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.IfSqlNode.apply(IfSqlNode.java:33) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.MixedSqlNode.apply(MixedSqlNode.java:32) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.scripting.xmltags.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:40) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:278) ~[mybatis-3.2.8.jar:3.2.8]
    at com.company.hawkeye.client.mybitis.CatMybatisPlugin.intercept(CatMybatisPlugin.java:70) ~[hawk-client-1.5.6.jar:?]
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:60) ~[mybatis-3.2.8.jar:3.2.8]
    at com.sun.proxy.$Proxy296.query(Unknown Source) ~[?:?]
    at sun.reflect.GeneratedMethodAccessor475.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_362]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_362]
    at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49) ~[mybatis-3.2.8.jar:3.2.8]
    at com.company.ctt.metrics.core.instrument.mybatis.MyBatisMetricsInterceptor.recordRequest(MyBatisMetricsInterceptor.java:55) ~[metrics-dog-core-2.1.9.31.jar:2.1.9.31]
    at com.company.ctt.metrics.core.instrument.mybatis.MyBatisMetricsInterceptor.intercept(MyBatisMetricsInterceptor.java:33) ~[metrics-dog-core-2.1.9.31.jar:2.1.9.31]
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:60) ~[mybatis-3.2.8.jar:3.2.8]
    at com.sun.proxy.$Proxy296.query(Unknown Source) ~[?:?]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:108) ~[mybatis-3.2.8.jar:3.2.8]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:102) ~[mybatis-3.2.8.jar:3.2.8]
    at sun.reflect.GeneratedMethodAccessor405.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_362]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_362]
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358) ~[mybatis-spring-1.2.2.jar:1.2.2]
    ... 23 more
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358)
    ... 23 more
Caused by: org.apache.ibatis.ognl.MethodFailedException: Method "size" failed for object [690] [java.lang.IllegalAccessException: Class org.apache.ibatis.ognl.OgnlRuntime can not access a member of class java.util.Arrays$ArrayList with modifiers "public"]
    at org.apache.ibatis.ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:837)
    at org.apache.ibatis.ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:61)
    at org.apache.ibatis.ognl.OgnlRuntime.callMethod(OgnlRuntime.java:860)
    at org.apache.ibatis.ognl.ASTMethod.getValueBody(ASTMethod.java:73)
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
    at org.apache.ibatis.ognl.ASTChain.getValueBody(ASTChain.java:109)
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
    at org.apache.ibatis.ognl.ASTGreater.getValueBody(ASTGreater.java:49)
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
    at org.apache.ibatis.ognl.ASTAnd.getValueBody(ASTAnd.java:56)
    at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
    at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
    at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:333)
    at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:310)
    at org.apache.ibatis.scripting.xmltags.OgnlCache.getValue(OgnlCache.java:45)
    ... 45 more

分析

通过异常栈,可以快速定位到报异常的源码。加以搜索报错关键字,不难定位到MyBatis官方issue: https://github.com/mybatis/mybatis-3/pull/384

stackoverflow中已经有人给出了解法: https://stackoverflow.com/questions/36961953/mybatis-error-org-apache-ibatis-ognl-ognlruntime

简要概括下问题: 此bugOGNL 2.7 + MyBatis 3.2.X 版本的问题,当给Mapper传入private内部类型的集合时,调用private内部类中的方法由于并发,会出现反射调用方法的问题。

详细的解释有一位网友写的不错:MyBatis居然也有并发问题,我这里就不再赘述细节。

针对问题,我也做了一版分析,画图说明下问题发生的过程: 图中标示了核心的类以及调用链路,更详细的类大家可以参考异常栈。

在第三个流程中,OgnlRuntime用来实现反射调用入参类型的属性方法。由于传入的MethodOgnlRuntime中是内部缓存中的同一个引用,当多个线程并发执行时,会出现多线程同时修改同一Method同一属性的时序问题,如图:

对应源码:

问题复现

分析清楚原因,我尝试在本地复现了一下这种线上低频出现的并发问题:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
@RequestMapping("testMybatisConcurrentBug")
@ResponseBody
public Object testMybatisConcurrentBug() {
    ExecutorService executor = new ThreadPoolExecutor(10, 10, 100L, TimeUnit.MILLISECONDS, new SynchronousQueue<>(), new ThreadPoolExecutor.AbortPolicy());
 
    for (int j = 0; j < 100; j++) {
        executor.submit(() -> {
            try {
                // 此处传入 Arrays.asList Collections.singletonList 这类`private`内部类式的容器映射均可
                List<DO> retList = yourMapper.selectBylist(Arrays.asList(690L), Arrays.asList(ContractTypeEnum.HT.getValue()), Arrays.asList(ContractStatusEnum.GZ.getValue()));
                System.out.println(retList);
            } catch (Exception e) {
                logger.error("selectBylist::", e);
                e.printStackTrace();
            }
        });
    }
    return "testMybatisConcurrentBug 启动";
}

还可以本地确认一下反射类的修饰符、方法访问性:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
public static void main(String[] args) throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
 
        // 创建一个Arrays.asList返回的List实例
        List<Long> list = Arrays.asList(666L);
 
        // 获取ArrayList实例的Class对象
        Class<?> clazz = list.getClass();
 
        // 获取size()方法
        Method method = clazz.getMethod("size");
 
        // 检查这个方法确实是存在于ArrayList或者其超类中的
        if (List.class.isAssignableFrom(clazz)) {
 
            if (!Modifier.isPublic(method.getDeclaringClass().getModifiers())) {
                System.out.println("目标类的修饰符不是public!!!");
            }
 
            if (!method.isAccessible()) {
                System.out.println("目标方法不可直接访问!!!");
                method.setAccessible(true);
            }
            // 调用size()方法
            int size = (Integer) method.invoke(list);
            System.out.println("The size of the list is: " + size);
 
            method.setAccessible(false);
        } else {
            System.out.println("The provided object is not a List.");
        }
 
    }

使用如上测试脚本可以稳定复现,佐证了我们前面的分析正确性。

解决

问题只要分析、复现清楚,解决方案就很简单:

  • 可以将项目MyBatis版本升级到3.3.X;
    • 由此引入依赖的问题,可考虑多环境灰度观察进行平稳上线;
  • 也可以将涉及到报错的Mapper处入参,修改为java.util.ArrayList类型;
    • 梳理了下,光这一个mapper方法就涉及20+调用处;

经过沟通权衡,我们选择了升级MyBatis版本(改动小、版本差异不大)。升级后的OgnlRuntime 可以看到修改method的可访问性增加了synchronized,保证其多线程操作下的原子性、结果一致性。