今天线上使用Mycat的业务突然反馈通过golang MySQL客户端执行SQL报异常:

Error 3344: StringIndexOutOfBoundsException: String index out of range: 237

查看Mycat日志也只有异常堆栈信息, 没有打出错误SQL和参数. 业务方很快定位到问题: 通过prepare binary协议执行一条INSERT语句时, 某个VARCHAR字段传入的数据长度超过600K而报出的错误. 通过源码调试找到了问题原因, 是mycat的一个bug, 该bug在1.6分支依然存在. 本文会详细分析该问题.

背景

业务方使用的是golang的github.com/go-sql-driver/mysql这个官方mysql客户端访问的Mycat代理服务器, 涉及到的数据表结构如下 (结构类似, 字段脱敏):

CREATE TABLE `tbl_test` (
    `id` bigint(20),
    `name` varchar(32),
    `password` varchar(32),
    `group` varchar(32),
    `data` longtext,
    `create_time` int(11),
    PRIMARY KEY (`id`)
) ENGINE=InnoDB

采用prepare binary协议执行INSERT SQL语句:

package main

import (
   "database/sql"
   "fmt"

   _ "github.com/go-sql-driver/mysql"
)

var data="abcdefg"

func main() {
   db, err := sql.Open("mysql", "test:test@tcp(127.0.0.1:8066)/test?charset=utf8")
   if err != nil {
      fmt.Printf("open error: %v\n", err)
      return
   }
   defer db.Close()
   sql := "INSERT INTO tbl_test (id,name,password,group,data,create_time) VALUES (?,?,?,?,?,?)"
   stmt, err := db.Prepare(sql)
   if err != nil {
      fmt.Printf("prepare error: %v\n", err)
      return
   }
   defer stmt.Close()
   args := []interface{}{1,"doggy","catty","animal",data,0}
   result, err := stmt.Exec(args...)
   if err != nil {
      fmt.Printf("execute error: %v\n", err)
      return
   }
   rowAffected, err := result.RowsAffected()
   if err != nil {
      fmt.Printf("get rowAffected error: %v\n", err)
      return
   }
   fmt.Printf("rowAffected: %d\n", rowAffected)
}

mycat启动端口为8066, 直连后端mysql, tbl_test没有配置分表. 当data变量长度超过600K时, 执行这段代码就会报Error 3344: StringIndexOutOfBoundsException.

MySQL prepare binary协议

由于采用了prepare binary协议执行SQL, 我们先来分析一下prepare binary执行流程. 具体内容可参考MySQL Internal Manual

prepare binary协议包含5种命令:

COM_STMT_PREPARE
COM_STMT_EXECUTE
COM_STMT_CLOSE
COM_STMT_RESET
COM_STMT_SEND_LONG_DATA

MySQL处理一个prepare binary请求的流程如下:

客户端向MySQL发送COM_STMT_PREPARE命令发送SQL语句, 从而在MySQL中创建一个PrepareStmt, 客户端从响应中获取StmtId.
客户端向MySQL发送COM_STMT_EXECUTE命令传入参数, 并将上一步获得的StmtId一并传入, 执行PrepareStmt, 从响应中获取执行结果.
客户端向MySQL发送COM_STMT_RESET命令清除PrepareStmt中绑定的参数.
客户端向MySQL发送COM_STMT_CLOSE命令关闭PrepareStmt.

注意以上每一步都会收到MySQL的响应. 另外一个COM_STMT_SEND_LONG_DATA命令, 是用来发送某一列的参数值的. 该命令没有返回值.

问题剖析

以上是针对MySQL而言的. Mycat作为MySQL的代理中间件, 处理prepare binary的方式与上述类似, 但是因为处理COM_STMT_SEND_LONG_DATA和COM_STMT_EXECUTE命令的方式不对, 导致了这个bug. 直接上代码:

public class ExecutePacket extends MySQLPacket {
    public void read(byte[] data, String charset) throws UnsupportedEncodingException {
        ...
        // 设置参数类型和读取参数值
        byte[] nullBitMap = this.nullBitMap;
        for (int i = 0; i < parameterCount; i++) {
            BindValue bv = new BindValue();
            bv.type = pstmt.getParametersType()[i];
            if ((nullBitMap[i / 8] & (1 << (i & 7))) != 0) {
                bv.isNull = true;
            } else {
                BindValueUtil.read(mm, bv, charset);
                if(bv.isLongData) {
                    bv.value = pstmt.getLongData(i);
                }
            }
            values[i] = bv;
        }
        ...
    }
}

public class BindValueUtil {
    public static final void read(MySQLMessage mm, BindValue bv, String charset) throws UnsupportedEncodingException {
        switch (bv.type & 0xff) {
            ...
        case Fields.FIELD_TYPE_VAR_STRING:
        case Fields.FIELD_TYPE_STRING:
        case Fields.FIELD_TYPE_VARCHAR:
            bv.value = mm.readStringWithLength(charset);
//            if (bv.value == null) {
//                bv.isNull = true;
//            }
            break;
            ...
        case Fields.FIELD_TYPE_BLOB:
            bv.isLongData = true;
            break;
        }
    }
}

可以看到, 在处理VARCHAR类型时, 直接读取packet中的数据, 而当是FIELD_TYPE_BLOB类型时, 会做一个标记, 不读取packet中的数据. 这种实现方式的背后逻辑是: 对FIELD_TYPE_BLOB类型, 客户端会使用COM_STMT_SEND_LONG_DATA命令发送数据, 而在COM_STMT_EXECUTE会忽略对应列, 不再发送该列数据.

然而, Mycat的实现方式忽略了一种情况: 对于VARCHAR, TEXT等类型, 客户端同样可以用COM_STMT_SEND_LONG_DATA命令发送数据. 考虑这种情况: 客户端对VARCHAR类型的列的数据, 使用COM_STMT_SEND_LONG_DATA命令发送, 而其他类型仍使用COM_STMT_EXECUTE发送, 按照Mycat的这种实现方式, 会按照SQL中参数绑定的顺序, 处理那些本应忽略的列, 而一旦用错误的类型处理数据, 相当于协议解析错误, 就肯定会导致StringIndexOutOfBoundsException等问题了.

那么, 为什么VARCHAR字段长度超过600K会触发这个bug呢? 原来是golang mysql客户端在执行prepare binary SQL时, 如果一个字符串数据的长度超过了longDataSize的值, 就会把该数据通过COM_STMT_SEND_LONG_DATA发送. 相关代码在这个文件中, 简要给出相关内容:

// Execute Prepared Statement
// http://dev.mysql.com/doc/internals/en/com-stmt-execute.html
func (stmt *mysqlStmt) writeExecutePacket(args []driver.Value) error {
    ...
    // Determine threshold dynamically to avoid packet size shortage.
    longDataSize := mc.maxAllowedPacket / (stmt.paramCount + 1)
    if longDataSize < 64 {
        longDataSize = 64
    }
    ...
    if len(args) > 0 {
        ...
        for i, arg := range args {
            ...
            switch v := arg.(type) {
            case []byte: // 与string类似
                ...
            case string:
                paramTypes[i+i] = byte(fieldTypeString)
                paramTypes[i+i+1] = 0x00

                if len(v) < longDataSize {
                    paramValues = appendLengthEncodedInteger(paramValues,
                        uint64(len(v)),
                    )
                    paramValues = append(paramValues, v...)
                } else {
                    if err := stmt.writeCommandLongData(i, []byte(v)); err != nil {
                        return err
                    }
                }
                ...
            }
            ...
        }
        ...
    }
    ...
}

可以看到, longDataSize := mc.maxAllowedPacket / (stmt.paramCount + 1)

其中paramCount为prepare语句中绑定的参数个数. maxAllowedPacket与MySQL系统参数max_allowed_packet有关. 这个文档给出了客户端maxAllowedPacket的设置方式. 如果不设置, 默认值是4194304, 如果设置为0, 则通过SELECT @@max_allowed_packet从MySQL获取, 如果设置值超过1<<24-1, 则设置为1<<24-1.

到此, 问题原因终于明晰了: golang mysql客户端使用了maxAllowedPacket的默认值4194304, 并且在执行prepare binary语句时, 遇到了长度超过longDataSize的数据, 执行COM_STMT_SEND_LONG_DATA发送给Mycat后, 再执行COM_STMT_EXECUTE时未发送该字段数据, 而Mycat仍在COM_STMT_EXECUTE时处理该数据, 导致协议解析错误. 至于600K触发这个bug, 执行的SQL中有6个绑定参数, 则longDataSize = 4194304 / (6 + 1) = 599186, 约等于600K.

解决方案

我们已经跟业务同学协商, 由他们优化该字段, 减小字段长度. 至于Mycat如何修复这个bug, 也非常简单: 在执行COM_STMT_SEND_LONG_DATA后, 把对应字段做一个标记, 在后续执行COM_STMT_EXECUTE遍历绑定参数时, 跳过该字段即可.

Mycat处理prepare binary协议的bug

Mycat处理prepare binary协议的bug

背景

MySQL prepare binary协议

问题剖析

解决方案