MySQL表加字段可为null导致ArrayIndexOutOfBoundsException报错问题记录
问题爆出
企微群告警爆了，立即去看ELK报错日志，报错日志非常莫名其妙：java.lang.ArrayIndexOutOfBoundsException: 16
原因分析
事后发现共有18257次报错日志，时间跨度 19:09:24.331 - 19:19:20.332，如下截图所示：
这个时间点正好是让DBA操作执行DDL语句，表加字段：ALTER TABLE channel_advertiser_id ADD COLUMN stop_time timestamp default NULL COMMENT '账户关停时间' after status;
执行时间为19点9分21秒，执行耗时不过3秒，19点9分24秒就执行完成。
看到数据越界，思维会习惯性以为查询出重复的数据。于是查询表的总记录数为3235条，没有重复的数据。
可知，表的数据量非常少，但是是一个非常核心的业务主表。0.17s就有194次报错日志：
ELK最早一条报错日志：
19:09:24.331 [SchedulerFactory_Worker-17] ERROR c.p.c.b.j.t.PutAdCreativeMaterialJob - PutAdCreativeMaterialJob error:org.springframework.dao.TransientDataAccessResourceException:
### Error querying database. Cause: java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
### The error may exist in URL [jar:file:/opt/app/octopus-backend.jar!/BOOT-INF/classes!/mybatisKraken/ChannelAdvertiserIdMapper.xml]
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select * from channel_advertiser_id where isactive = 1 and advertiser_id = ?
### Cause: java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
; SQL []; java.lang.ArrayIndexOutOfBoundsException: 16; nested exception is java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
至此还是莫名其妙，毫无头绪。
不过大体上的思路还是有的，无非是2个：
- 找日志
谛听（内部应用，类似于开源的SkyWalking）报错日志：
java.lang.ArrayIndexOutOfBoundsException: 16<MSG>16
java.sql.SQLException
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73)
at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:441)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute$original$HSVORnno(ClientPreparedStatement.java:370)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute$original$HSVORnno$accessor$gSEmEInd(ClientPreparedStatement.java)
at com.mysql.cj.jdbc.ClientPreparedStatement$auxiliary$ksqk50q8.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java)
at com.mysql.cj.jdbc.ServerPreparedStatement.execute$accessor$mLgNCD2S(ServerPreparedStatement.java)
at com.mysql.cj.jdbc.ServerPreparedStatement$auxiliary$3DrEHQTx.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at com.mysql.cj.jdbc.ServerPreparedStatement.execute(ServerPreparedStatement.java)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
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.CachingExecutor.query(CachingExecutor.java:109)
at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:108)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy437.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
at sun.reflect.GeneratedMethodAccessor169.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)
at com.sun.proxy.$Proxy138.selectOne(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy152.selectAdvertiserIdById(Unknown Source)
at sun.reflect.GeneratedMethodAccessor168.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
at org.springframework.aop.framework.ReflectiveMethodInvocation
同时也找到类似（不完全一样）的几个ArrayIndexOutOfBoundsException报错记录帖子，见参考。
看源码com.mysql.cj.jdbc.ServerPreparedStatement（有删减），简单分析：
protected <M extends Message> com.mysql.cj.jdbc.result.ResultSetInternalMethods executeInternal(int maxRowsToRetrieve, M sendPacket,
boolean createStreamingResultSet, boolean queryIsSelectOnly, ColumnDefinition metadata, boolean isBatch) throws SQLException {
synchronized (checkClosed().getConnectionMutex()) {
((PreparedQuery<?>) this.query).getQueryBindings()
.setNumberOfExecutions(((PreparedQuery<?>) this.query).getQueryBindings().getNumberOfExecutions() + 1);
// We defer to server-side execution
try {
return serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata);
} catch (Exception ex) {
if (this.session.getPropertySet().getBooleanProperty(PropertyKey.enablePacketDebug).getValue()) {
this.session.dumpPacketRingBuffer();
}
// 报错441行
SQLException sqlEx = SQLError.createSQLException(ex.toString(), MysqlErrorNumbers.SQL_STATE_GENERAL_ERROR, ex, this.exceptionInterceptor);
if (this.dumpQueriesOnException.getValue()) {
String extractedSql = toString();
StringBuilder messageBuf = new StringBuilder(extractedSql.length() + 32);
messageBuf.append("\n\nQuery being executed when exception was thrown:\n");
messageBuf.append(extractedSql);
messageBuf.append("\n\n");
sqlEx = appendMessageToException(sqlEx, messageBuf.toString(), this.exceptionInterceptor);
}
throw sqlEx;
}
}
}
执行return serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata);时抛错，ServerPreparedStatement.serverExecute方法
protected ResultSetInternalMethods serverExecute(int maxRowsToRetrieve, boolean createStreamingResultSet, ColumnDefinition metadata) throws SQLException {
synchronized (checkClosed().getConnectionMutex()) {
this.results = ((ServerPreparedQuery) this.query).serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata, this.resultSetFactory);
return this.results;
}
}
ServerPreparedQuery.serverExecute方法
public <T extends Resultset> T serverExecute(int maxRowsToRetrieve, boolean createStreamingResultSet, ColumnDefinition metadata,
ProtocolEntityFactory<T, NativePacketPayload> resultSetFactory) {
if (this.session.shouldIntercept()) {
T interceptedResults = this.session.invokeQueryInterceptorsPre(() -> {
return getOriginalSql();
}, this, true);
if (interceptedResults != null) {
return interceptedResults;
}
}
String queryAsString = this.profileSQL || this.logSlowQueries || this.gatherPerfMetrics ? asSql(true) : "";
NativePacketPayload packet = prepareExecutePacket();
NativePacketPayload resPacket = sendExecutePacket(packet, queryAsString);
T rs = readExecuteResult(resPacket, maxRowsToRetrieve, createStreamingResultSet, metadata, resultSetFactory, queryAsString);
return rs;
}
执行查询时，需要使用到session。而加字段后，session信息发生变更？
另外从源码搜索反向分析，找到ArrayIndexOutOfBoundsException可能出现在NativeServerSession类里面：
能力有限，只能分析到这个地步。
另外，报错的数据越界的数字也是有讲究的，看一下表的定义（注释省去，字段名字母有删减）：
create table channel_advertiser_id (
id int auto_increment primary key,
adv_id varchar(100) null,
aer_name varchar(100) null comment '',
adve_name varchar(100) null comment '',
cha_id text null comment '',
cor_id int null comment '',
use_id int null comment '',
isactive tinyint(1) not null,
insert_time timestamp default CURRENT_TIMESTAMP not null,
update_time timestamp default CURRENT_TIMESTAMP not null on update CURRENT_TIMESTAMP,
updateby varchar(100) null comment '',
isot int(5) default 2 not null comment '',
status int(5) default 1 not null comment '',
stop_time timestamp null comment '账户关停时间',
advd_id varchar(50) null comment '',
is_ew tinyint(1) default 0 null comment '',
cony varchar(100) null
) charset = utf8;
发布前16个字段，发布后17个字段。
注：mysql-connector-java版本为8.0.22，
反思
假使按照规范，DBA是21点（整点）执行DDL语句。虽然DBA不一定会卡整点执行。但是生产上很多跑批任务大多数都是整点或者半点执行的。19点10分有1.8w次报错。那21点多执行，虽然不是业务使用高峰期，那还是会有这个问题？？？
