年后负责一个比较老的服务,报警不少,今天排查的这个问题也只有在老版本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
简要概括下问题:
此bug
为OGNL 2.7 + MyBatis 3.2.X
版本的问题,当给Mapper
传入private
内部类型的集合时,调用private
内部类中的方法由于并发,会出现反射调用方法的问题。
详细的解释有一位网友写的不错:MyBatis居然也有并发问题,我这里就不再赘述细节。
针对问题,我也做了一版分析,画图说明下问题发生的过程: 图中标示了核心的类以及调用链路,更详细的类大家可以参考异常栈。
在第三个流程中,OgnlRuntime
用来实现反射调用入参类型的属性方法。由于传入的Method
在OgnlRuntime
中是内部缓存中的同一个引用,当多个线程并发执行时,会出现多线程同时修改同一Method
同一属性的时序问题,如图:
对应源码:
问题复现
分析清楚原因,我尝试在本地复现了一下这种线上低频出现的并发问题:
|
|
还可以本地确认一下反射类的修饰符、方法访问性:
|
|
使用如上测试脚本可以稳定复现,佐证了我们前面的分析正确性。
解决
问题只要分析、复现清楚,解决方案就很简单:
- 可以将项目
MyBatis
版本升级到3.3.X;- 由此引入依赖的问题,可考虑多环境灰度观察进行平稳上线;
- 也可以将涉及到报错的
Mapper
处入参,修改为java.util.ArrayList
类型;- 梳理了下,光这一个mapper方法就涉及20+调用处;
经过沟通权衡,我们选择了升级MyBatis
版本(改动小、版本差异不大)。升级后的OgnlRuntime
:
可以看到修改method
的可访问性增加了synchronized
,保证其多线程操作下的原子性、结果一致性。