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
1
2
3
4
5
6
7
8

至此还是莫名其妙，毫无头绪。

不过大体上的思路还是有的，无非是2个：

1. 找日志
2. Google

谛听（内部应用，类似于开源的SkyWalking）报错日志：

java.lang.ArrayIndexOutOfBoundsException: 1616
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 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 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 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.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 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.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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

同时也找到类似（不完全一样）的几个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;
        }
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

执行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;
    }
}
1
2
3
4
5
6

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;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

执行查询时，需要使用到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;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

发布前16个字段，发布后17个字段。与报错提到的java.lang.ArrayIndexOutOfBoundsException: 16完全吻合。

注：mysql-connector-java版本为8.0.22。

反思

假使按照规范，DBA是21点（整点）执行DDL语句。虽然DBA不一定会卡整点执行。但是生产上很多跑批任务大多数都是整点或者半点执行的。19点10分有1.8w次报错。那21点多执行，虽然不是业务使用高峰期，那还是会有这个问题？？？

参考

• 数据库最后一个字段Null导致mybatis抛出异常ArrayIndexOutOfBoundsException
• SQLite + Mybatis-guice throw ArrayIndexOutOfBoundsException
• mybatis+ojdbc6.jar的一个奇怪问题记录