问题描述
收到error日志告警,出现多条下列错误日志
[2021-02-03 16:55:32.469][ERROR][http-nio-8249-exec-44][com.jiu.common.online.exception.GlobalExceptionHandler][127.0.0.1][[]请求异常：/merchant/cashierArea/listCashiierAreaorg.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException: ### Error querying database.
Cause: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0 ### The error may exist in class path resource [mapper/zx_business_machine/HsyCashierAreaMapper.xml] ### The error may involve defaultParameterMap ### The error occurred while setting parameters ### SQL: select F_id, F_cashier_area_no, F_cashier_area_name, F_merchant_id, F_create_time, F_update_time from t_hsy_cashier_area where f_merchant_id = ? order by f_create_time desc limit ?,? ###
Cause: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:77)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
at com.sun.proxy.$Proxy142.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:144)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:77)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:58)
at com.sun.proxy.$Proxy173.listCashierAreaByMerchantId(Unknown Source)
at com.jiu.online.machine.hsy.service.impl.CashierAreaServiceImpl.listCashierArea(CashierAreaServiceImpl.java:310)
at com.jiu.online.machine.hsy.service.impl.CashierAreaServiceImpl$$FastClassBySpringCGLIB$$4cc36c10.invoke()
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:684)
at com.jiu.online.machine.hsy.service.impl.CashierAreaServiceImpl$$EnhancerBySpringCGLIB$$f7bc53d8.listCashierArea()
at com.jiu.online.machine.hsy.controller.CashierAreaController.listCashierArea(CashierAreaController.java:114)
at sun.reflect.GeneratedMethodAccessor513.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:877)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at com.jiu.online.machine.hsy.filter.SessionFilter.doFilter(SessionFilter.java:49)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:90)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
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:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.cloud.sleuth.instrument.web.ExceptionLoggingFilter.doFilter(ExceptionLoggingFilter.java:48)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at brave.servlet.TracingFilter.doFilter(TracingFilter.java:86)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at com.jiu.common.online.filter.MonitorFilter.doFilter(MonitorFilter.java:54)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.ibatis.exceptions.PersistenceException: ### Error querying database.
Cause: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0 ### The error may exist in class path resource [mapper/zx_business_machine/HsyCashierAreaMapper.xml] ### The error may involve defaultParameterMap ### The error occurred while setting parameters ### SQL: select F_id, F_cashier_area_no, F_cashier_area_name, F_merchant_id, F_create_time, F_update_time from t_hsy_cashier_area where f_merchant_id = ? order by f_create_time desc limit ?,? ###
Cause: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:150)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at sun.reflect.GeneratedMethodAccessor373.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433) ... 87 common frames omitted
Caused by: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0
at java.util.ArrayList.rangeCheck(ArrayList.java:653)
at java.util.ArrayList.get(ArrayList.java:429)
at com.dangdang.ddframe.rdb.sharding.jdbc.util.ParameterList.set(ParameterList.java:82)
at com.dangdang.ddframe.rdb.sharding.parser.result.merger.Limit.replaceParameters(Limit.java:71)
at com.dangdang.ddframe.rdb.sharding.router.SQLRouteEngine.routeSQL(SQLRouteEngine.java:105)
at com.dangdang.ddframe.rdb.sharding.router.PreparedSQLRouter.route(PreparedSQLRouter.java:56)
at com.dangdang.ddframe.rdb.sharding.jdbc.ShardingPreparedStatement.routeSQL(ShardingPreparedStatement.java:162)
at com.dangdang.ddframe.rdb.sharding.jdbc.ShardingPreparedStatement.execute(ShardingPreparedStatement.java:112)
at sun.reflect.GeneratedMethodAccessor242.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59)
at com.sun.proxy.$Proxy256.execute(Unknown Source)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
at sun.reflect.GeneratedMethodAccessor241.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
at com.jiu.online.machine.hsy.filter.SqlExecuteTimeCountInterceptor.intercept(SqlExecuteTimeCountInterceptor.java:53)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy254.query(Unknown Source)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:136)
at sun.reflect.GeneratedMethodAccessor236.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
at com.jiu.common.core.persistence.interceptor.PaginationInterceptor.intercept(PaginationInterceptor.java:74)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy253.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148) ... 92 common frames omitted ]
原因分析
根据异常栈信息,初步定为是sharding框架代码抛的下标越界异常
image.png
Cause: java.lang.IndexOutOfBoundsException: Index: 1, Size: 0
说明此时jdbcMethodInvocations这个list为空,但参数index传了1
初步判断是由于并发导致的
经过一番折腾,最终确定是由于并发情况下,框架出现了线程安全问题.且复现出现概率也蛮高的
复现演示图如下:
sharding1bug.gif
原因分析:
testThread-0线程和testThread-1线程对应的jdbcMethodInvocations对象竟然是同一个(但未定位到该原因,初步判断是由于本地缓存的原因)
-
在执行完语句后,有个clearRouteContext的方法会clear这个list
image.png 在并发情况下,由于ArrayList非线程安全,可能导致上述问题
解决方案
- 目前由于历史原因,用了sharding-jdbc1.3.3这一早期的版本,框架出现了问题,优先考虑升级,考虑升级至4.0.0-RC3版本
- 经过测试以及查阅资料,该版本未出现问题
- 线上采取灰度升级版本.逐步将部门所有项目的sharding-jdbc框架进行了升级
另外,sharding-jdbc 1.x这一古老版本和4.x版本存在很多不同,包括包名,分片接口,命名空间方式对应的标签等,着实也折腾得够呛(估计和被apache收购有关).具体的一些不同也可以参考我的另一篇文档
https://www.jianshu.com/p/39830e1ccf9b
总结
对于技术选型以及版本的选择真的要重视,一定是经过相关调研才敲定.像项目中竟然采用这么古老的版本实在不应该
