切记，中间件一定不能吞没下游的异常，更不能掩盖异常

1024个为什么

已于 2023-04-08 11:58:57 修改

阅读量297

点赞数 1

文章标签： java mysql spring bug mybatis

于 2019-12-23 22:37:32 首次发布

本文链接：https://blog.csdn.net/JiuQianWan/article/details/126118259

版权

一、起因

线上服务报警 NullPointerException

2019-12-22 13:13:19.715 [] [http-nio-80-exec-6] ERROR c.d.d.c.c.s.CheckConfigServiceImpl - error
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException: 
### Error updating database.  Cause: java.lang.NullPointerException
### The error may involve com.daojia.dop.checkcenter.configcheck.dao.CheckResultDao.updateByPrimaryKeySelective-Inline
### The error occurred while setting parameters
### SQL: update check_result SET fix_operator = ?, fix_comment = ? where id = ?
// 这种SQL语法错的【where前多了个逗号】也会报NPE ### SQL: update check_result SET fix_operator = ?, fix_comment = ?  , where id = ?
### Cause: java.lang.NullPointerException
  at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:77)
  at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
  at com.sun.proxy.$Proxy79.update(Unknown Source)
  at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294)
  at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:62)
  at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
  at com.sun.proxy.$Proxy84.updateByPrimaryKeySelective(Unknown Source)
  at com.*****.CheckConfigServiceImpl.updateCheckResult(CheckConfigServiceImpl.java:240)
  at com.*****.CheckConfigServiceImpl$$FastClassBySpringCGLIB$$fd3a9057.invoke(<generated>)
  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
  at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)
  at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
  at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88)
   ........此处省略n行
  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 updating database.  Cause: java.lang.NullPointerException
### The error may involve com.*****.CheckResultDao.updateByPrimaryKeySelective-Inline
### The error occurred while setting parameters
### SQL: update check_result          SET fix_operator = ?,                                           fix_comment = ?          where id = ?
### Cause: java.lang.NullPointerException
  at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
  at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:200)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  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.NullPointerException: null
  at com.sun.proxy.$Proxy97.update(Unknown Source)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
  at com.sun.proxy.$Proxy97.update(Unknown Source)
  at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
  ... 92 common frames omitted

二、业务场景

按id更新一条记录的处理人、备注信息

环境：springboot2.0.6 + mybatis3.4.4 + pagehelper插件+cat监控插件（大众点评开源的），数据库是 mysql5.7

<dependency>
  <groupId>org.mybatis.spring.boot</groupId>
  <artifactId>mybatis-spring-boot-starter</artifactId>
  <version>1.3.0</version>
</dependency>
<dependency>
  <groupId>mysql</groupId>
  <artifactId>mysql-connector-java</artifactId>
  <version>5.1.40</version>
</dependency>
<dependency>
  <groupId>com.daojia.openfire</groupId>
  <artifactId>openfire-cat-mybatis</artifactId>
  <version>2.0.0-SNAPSHOT</version>
</dependency>
<dependency>
  <groupId>com.github.pagehelper</groupId>
  <artifactId>pagehelper</artifactId>
  <version>5.1.9</version>
</dependency>

三、排查过程

1、看到空指针，直觉就是先检查一下参数有无null

经排查，三个参数都有。下面是线下复现的SQL

update check_result  SET fix_operator = 'xiaoyiHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH',  fix_comment = '备注'   where id = 37714

通过本地执行SQL语句，直接使用命令执行和通过DbVisualizer客户端执行，都是报 data to long。fix_operator 表中设置的长度是32，实际参数长度已经超出了32。但是使用Navicat客户端执行的时候成功了，去表里查看修改的记录，发现是只取了前32个字节入库了，后面的都丢弃了。所以使用此客户端的要多加注意。个人感觉这种处理方式太暴力了，这就相当于埋了个定时炸弹。

按说到此就可以宣布错误原因找到了，但细想还有很多疑问没解开。到底是执行之前对参数长度做了校验直接返回失败？还是请求发给了数据库，执行后返回的错误？为什么参数过长，到日志里就变成了空指针了呢？接下来就继续排查，寻找答案。

2、是在SQL执行前校验报错？还是执行后返回的错？

通过debug，一直跟到给数据库发送SQL命令前都没有报错，也没有发现对参数长度校验的逻辑，这个疑问就可以排除掉了，刚才想多了。

直到接收到数据库返回的信息解析后才发现错误，这才是真实的错误。

3、步步跟进，“Data to lang”的异常输出到哪里了？

原来异常是在这里被吞了，肯定输出不到日志了

下面是此部分的代码

com.dianping.cat.message.internal.DefaultMessageProducer#logError(java.lang.String, java.lang.Throwable)


public class DefaultMessageProducer implements MessageProducer {
    /**
    * 其他代码省略
    */
    public void logError(String message, Throwable cause) {
        if (Cat.getManager().isCatEnabled()) {
            if (this.shouldLog(cause)) {
                this.m_manager.getThreadLocalMessageTree().setDiscard(false);
                StringWriter writer = new StringWriter(2048);
                if (message != null) {
                    writer.write(message);
                    writer.write(32);
                }


                cause.printStackTrace(new PrintWriter(writer));
                String detailMessage = writer.toString();
                if (cause instanceof Error) {
                    this.logEvent("Error", cause.getClass().getName(), "ERROR", detailMessage);
                } else if (cause instanceof RuntimeException) {
                    this.logEvent("RuntimeException", cause.getClass().getName(), "ERROR", detailMessage);
                } else {
                    this.logEvent("Exception", cause.getClass().getName(), "ERROR", detailMessage);
                }
            }
        } else {
            // 由于种种原因，上面的条件未能满足，异常在这里被吞了。
            // 这种方式处理异常，不仅不能输出到log文件中，还存在风险
            cause.printStackTrace();
        }
    }

这种处理方式太粗暴了，一点也不优雅。网上有一种说法（是否正确，知识有限，还无法验证），e.printStackTrace()会产生重复的字符串，进入到字符串常量池，会撑爆的，满了之后其他的就会等待，造成死锁。

4、空指针又是怎么冒出来的？

继续往下执行，发现返回了个null，这个null会传给invoke的地方，到InvocationTargetException就变成了java.lang.NullPointerException

public Object intercept(Invocation invocation) throws Throwable {
    MappedStatement mappedStatement = (MappedStatement)invocation.getArgs()[0];
    String[] strArr = mappedStatement.getId().split("\\.");
    String methodName = strArr[strArr.length - 2] + "." + strArr[strArr.length - 1];
    Transaction t = Cat.newTransaction("SQL", methodName);
    Object parameter = null;
    if (invocation.getArgs().length > 1) {
        parameter = invocation.getArgs()[1];
    }


    BoundSql boundSql = mappedStatement.getBoundSql(parameter);
    Configuration configuration = mappedStatement.getConfiguration();
    String sql = this.showSql(configuration, boundSql);
    SqlCommandType sqlCommandType = mappedStatement.getSqlCommandType();
    Cat.logEvent("SQL.Method", sqlCommandType.name().toLowerCase(), "0", sql);
    String s = this.getSQLDatabase();
    Cat.logEvent("SQL.Database", s);
    Object returnObj = null;


    try {
        returnObj = invocation.proceed();
        this.checkResult(returnObj);
        t.setStatus("0");
    } catch (Exception var17) {
        Cat.logError(var17);
    } finally {
        t.complete();
    }
    // 这里会返回null
    return returnObj;
}

而这个异常会被org.apache.ibatis.plugin.Plugin拿到，通过ExceptionUtil处理，就能输出到日志里了。

这就导致了在日志中只看到了java.lang.NullPointerException。

四、总结一下

1、这种场景可能很少遇到，重要的是排查问题的决心和思路。

2、不要觉得开源的插件就没有问题。

3、看到java.lang.NullPointerException，检查参数是否为空是正常的解决思路，如果确认参数没有null（自己不好确认就找同事确认一下，有时候自己看一会儿就看花眼了，尤其参数比较多的SQL语句），就要调整排查思路。

4、MySQL的客户端要充分了解。

5、通过排查有个小收获，原来MySQL客户端和服务端的通信和redis差不多，也是建立一个socket连接，把要执行的命令、数据按协议打包成数据发送给客户端，还是阻塞等待返回结果的（这也印证了为什么有慢查询的时候连接池很快就会被耗尽）。com.mysql.jdbc.MysqlIO这个类值得好好研究一下。

1024个为什么

关注

1
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
切记，中间件一定不能吞没下游的异常，更不能掩盖异常

谁吞了我的异常？一、起因线上服务报警 NullPointerException2019-12-22 13:13:19.715 [] [http-nio-80-exec-6] ERROR c.d.d.c.c.s.CheckConfigServiceImpl - errororg.mybatis.spring.MyBatisSystemException: nested e...
复制链接

扫一扫