备注：对于一个优秀的工程师来说，定位问题和处理问题的良好的心态和思路是必备的技能。一个优秀的工程师在以下三点上持续精进：首先，面对问题能够追根问底，不气馁；同时，找到原因后能够举一反，并不断完善自己的知识体系；第三， 总结输出经验，给团队同伴赋能。
起因
线上服务突然报警，异常信息关键词是：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.daojia.dop.*****.CheckConfigServiceImpl.updateCheckResult(CheckConfigServiceImpl.java:240)
at com.daojia.dop.*****.CheckConfigServiceImpl$$FastClassBySpringCGLIB$$fd3a9057.invoke()
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.daojia.*****.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
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 = ?
### 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.daojia.dop.*****.CheckConfigServiceImpl.updateCheckResult(CheckConfigServiceImpl.java:240)
at com.daojia.dop.*****.CheckConfigServiceImpl$$FastClassBySpringCGLIB$$fd3a9057.invoke()
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.daojia.*****.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这种 SQL 语法错的【where 前多了个逗号】也会报 NPE
update check_result SET fix_operator = ?, fix_comment = ? , where id = ?业务场景
按 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
看到空指针，直觉就是先检查一下参数有无 null 经排查，三个参数都有。下面是线下复现的 SQL：
update check_result SET fix_operator = 'xiaoyisdfsdfsdfsdffffgfhghhhgggfdgdgdfgdfgdfgfdgfdg', fix_comment = '备注' where id = 37714232434通过本地执行 SQL 语句，直接使用命令执行和通过 DbVisualizer 客户端执行，都是报 data to long。fix_operator 表中设置的长度是 32，实际参数长度已经超出了 32。但是使用 Navicat 客户端执行的时候成功了，去表里查看修改的记录，发现是只取了前 32 个字节入库了，后面的都丢弃了。所以使用此客户端的要多加注意。个人感觉这种处理方式太暴力了，这就相当于埋了个定时炸弹。按说到此就可以宣布错误原因找到了，但细想还有很多疑问没解开。到底是执行之前对参数长度做了校验直接返回失败？还是请求发给了数据库，执行后返回的错误？为什么参数过长，到日志里就变成了空指针了呢？接下来就继续排查，寻找答案。
2、继续追查
是在 SQL 执行前校验报错？还是执行后返回的错？还需要继续追查下去，以便找到根本原因。
通过 debug，一直跟到给数据库发送 SQL 命令前都没有报错，也没有发现对参数长度校验的逻辑，这个疑问就可以排除掉了，看来刚才是想多了。
直到接收到数据库返回的信息解析后才发现错误，这才是真实的错误：
3、步步逼近真相
步步跟进，“Data to long”的异常输出到哪里了？继续追查：
原来异常是在这里被吞了，肯定输出不到日志了：
下面是此部分的代码 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 连接，把要执行的命令、数据按协议打包成数据发送给客户端，还是阻塞等待返回结果的（这也印证了为什么有慢查询的时候连接池很快就会被耗尽）。
- 6、com.mysql.jdbc.MysqlIO 这个类值得好好研究一下。
