jdbc连接参数noAccessToProcedureBodie
2021-06-07 本文已影响0人
晚歌歌
背景
测试在生产以下的测试、预生产环境发现某个使用MYSQL存储过程查询的报表500异常，错误日志如下：
2021-06-03 10:41:41,489 [http-bio-8080-exec-71] DEBUG o.m.s.t.SpringManagedTransaction - JDBC Connection [jdbc:mysql://xxx:3306/center_report?useUnicode=true&characterEncoding=UTF8&rewriteBatchedStatements=true&noAccessToProcedureBodies=true&allowMultiQueries=true&useHostsInPrivileges=false&useLocalSessionState=true, UserName=root, @MYSQL_CJ_DISPLAY_PROD_NAME@] will not be managed by Spring
2021-06-03 10:41:41,490 [http-bio-8080-exec-71] DEBUG c.n.e.r.b.d.A.listUserExtraLog - ==> Preparing: call sp_list_user_extra_log( ?, ?, ?, 0, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2021-06-03 10:41:41,557 [http-bio-8080-exec-71] DEBUG c.n.e.r.b.d.A.listUserExtraLog - ==> Parameters: 3(Long), (String), (String), 1(Integer), (String), 2000-01-01 00:00:00.0(Timestamp), 2021-06-02 23:59:59.999(Timestamp), (String), (String), (String), 1(Integer), 10(Integer)
2021-06-03 10:41:41,557 [http-bio-8080-exec-71] DEBUG c.n.core.log.LogExceptionHandler - Resolving exception from handler [public com.x.elearning.common.page.vo.PageQueryResp<com.x.elearning.report.behavior.vo.AccountExtraLogWebVo> com.x.elearning.report.behavior.controller.ReportGoldExpController.list(com.x.elearning.report.behavior.vo.GoldExpListRequest)]: org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: java.lang.ArrayIndexOutOfBoundsException: 13
### The error may exist in com/nexdragon/elearning/report/behavior/dao/AccountExtraLogReportDao.java (best guess)
### The error may involve com.x.elearning.report.behavior.dao.AccountExtraLogReportDao.listUserExtraLog-Inline
### The error occurred while setting parameters
### SQL: call sp_list_user_extra_log( ?, ?, ?, 0, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
### Cause: java.lang.ArrayIndexOutOfBoundsException: 13
2021-06-03 10:41:41,559 [http-bio-8080-exec-71] ERROR c.n.core.log.LogExceptionHandler - exception trace
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: java.lang.ArrayIndexOutOfBoundsException: 13
### The error may exist in com/x/elearning/report/behavior/dao/AccountExtraLogReportDao.java (best guess)
### The error may involve com.x.elearning.report.behavior.dao.AccountExtraLogReportDao.listUserExtraLog-Inline
### The error occurred while setting parameters
### SQL: call sp_list_user_extra_log( ?, ?, ?, 0, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
### Cause: java.lang.ArrayIndexOutOfBoundsException: 13
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.$Proxy77.selectList(Unknown Source) ~[na:na]
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.7.jar:3.2.7]
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52) ~[mybatis-3.2.7.jar:3.2.7]
at com.x.core.framework.monitor.performance.mybatis.MonitoredMapperProxy.invoke(MonitoredMapperProxy.java:47) ~[core-1.3.4-SNAPSHOT.jar:na]
at com.sun.proxy.$Proxy121.listUserExtraLog(Unknown Source) ~[na:na]
at com.x.elearning.report.behavior.service.ReportGoldExpService.list(ReportGoldExpService.java:75) ~[classes/:na]
at com.x.elearning.report.behavior.controller.ReportGoldExpController.list(ReportGoldExpController.java:65) ~[classes/:na]
at com.x.elearning.report.behavior.controller.ReportGoldExpController$$FastClassBySpringCGLIB$$162baacb.invoke(<generated>) ~[classes/:na]
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:56) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.aspectj.AspectJAfterAdvice.invoke(AspectJAfterAdvice.java:47) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:62) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
at com.x.elearning.report.behavior.controller.ReportGoldExpController$$EnhancerBySpringCGLIB$$8e2ebce5.list(<generated>) ~[classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_131]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_131]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221) ~[spring-web-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137) ~[spring-web-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104) ~[spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:747) ~[spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:676) ~[spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:938) [spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:870) [spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:961) [spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:863) [spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:650) [servlet-api.jar:na]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:837) [spring-webmvc-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) [servlet-api.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.85]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.85]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.85]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.85]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.85]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) [spring-web-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.85]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.85]
at com.x.core.framework.GlobalFilter.doFilterInternal(GlobalFilter.java:35) [core-1.3.4-SNAPSHOT.jar:na]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.0.9.RELEASE.jar:4.0.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.85]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.85]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:7.0.85]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110) [catalina.jar:7.0.85]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169) [catalina.jar:7.0.85]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.85]
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:962) [catalina.jar:7.0.85]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.85]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445) [catalina.jar:7.0.85]
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1115) [tomcat-coyote.jar:7.0.85]
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637) [tomcat-coyote.jar:7.0.85]
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.85]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.85]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: java.lang.ArrayIndexOutOfBoundsException: 13
### The error may exist in com/x/elearning/report/behavior/dao/AccountExtraLogReportDao.java (best guess)
### The error may involve com.x.elearning.report.behavior.dao.AccountExtraLogReportDao.listUserExtraLog-Inline
### The error occurred while setting parameters
### SQL: call sp_list_user_extra_log( ?, ?, ?, 0, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
### Cause: java.lang.ArrayIndexOutOfBoundsException: 13
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:26) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:111) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:102) ~[mybatis-3.2.7.jar:3.2.7]
at sun.reflect.GeneratedMethodAccessor204.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358) ~[mybatis-spring-1.2.2.jar:1.2.2]
... 67 common frames omitted
Caused by: java.lang.ArrayIndexOutOfBoundsException: 13
at com.mysql.jdbc.CallableStatement.setInOutParamsOnServer(CallableStatement.java:2275) ~[mysql-connector-java-5.1.30.nd.1.14.jar:na]
at com.mysql.jdbc.CallableStatement.execute(CallableStatement.java:922) ~[mysql-connector-java-5.1.30.nd.1.14.jar:na]
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172) ~[commons-dbcp-1.4.jar:1.4]
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172) ~[commons-dbcp-1.4.jar:1.4]
at sun.reflect.GeneratedMethodAccessor152.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:62) ~[mybatis-3.2.7.jar:3.2.7]
at com.sun.proxy.$Proxy231.execute(Unknown Source) ~[na:na]
at org.apache.ibatis.executor.statement.CallableStatementHandler.query(CallableStatementHandler.java:66) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:73) ~[mybatis-3.2.7.jar:3.2.7]
at sun.reflect.GeneratedMethodAccessor149.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:62) ~[mybatis-3.2.7.jar:3.2.7]
at com.sun.proxy.$Proxy229.query(Unknown Source) ~[na:na]
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:60) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:267) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:137) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:96) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:77) ~[mybatis-3.2.7.jar:3.2.7]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:108) ~[mybatis-3.2.7.jar:3.2.7]
... 72 common frames omitted
排查
- 首先大致可以先排查是否只是某些数据异常导致参数设置异常：发现是整个列表展示不出来，排除
- 排查是否测试和预生产存储过程存在问题：与生产环境的存储过程对比，一致，排除
- 排查是否测试和预生产相关代码：与主干分支对比，一致，排除
- 排查是否报错的地方引用jar包有升级：排查MySQL jdbc jar包版本没有变化
此时排查陷入困难，目前已有测试环境错误日志，继续拉取生产环境的正常日志进行对比：
发现了jdbc连接参数不一致：
测试：jdbc:mysql://xxx:3306/center_report?useUnicode=true&characterEncoding=UTF8&rewriteBatchedStatements=true&noAccessToProcedureBodies=true&allowMultiQueries=true&useHostsInPrivileges=false&useLocalSessionState=true
生产：jdbc:mysql://xxx:3306/center_report?useUnicode=true&rewriteBatchedStatements=TRUE
发现其中某个参数可能跟存储过程有关：noAccessToProcedureBodies
网上仅能搜到的信息如下，但是与参数设置有关那一定就是这个问题：
问了相关开发人员确实这个参数是这周加上去的，生产环境还没有发布，去掉该参数后接口调用正常
