本机系统:centos 6.5
本地环境:nginx version: openresty/1.9.15.1
mysql版本:mysql Ver 14.14 Distrib 5.1.73
报错现象:2016/12/13 09:59:01 [error] 10263#0: *15385 lua entry thread aborted: runtime error: xxxx/lualib/resty/mysql.lua:192: bad argument #1 to 'strchar' (invalid value)
stack traceback:
coroutine 0:
[C]: in function 'strchar'
xxxxxx/lualib/resty/mysql.lua:192: in function '_send_packet'
xxxxxx/lualib/resty/mysql.lua:728: in function 'close'
问题过程:(1)、在使用lua操作mysql数据库查询操作的过程中,查询操作完毕后调用close函数关闭数据库时,出现上述报错;
本地数据库拥有762条记录数据,当查询数据大于762条时,就会出现上述错误,具体查询语句如下:
SELECT x,y, modify_time FROM table ORDER BY modify_time DESC LIMIT 0, 800;
使用本地mysql测试数据库操作语句没有任何问题;
(2)、根据错误日志定位到,是mysql.lua 中的 _send_packet() 函数'strchar'报错,添加详细日志输出发现数据越界了:
2016/12/13 12:00:11 [error] 10417#0: *15391 [lua] mysql.lua:191: _send_packet(): packet no: 0, client: 127.0.0.1,
2016/12/13 12:00:11 [error] 10417#0: *15391 [lua] mysql.lua:191: _send_packet(): packet no: 256, client: 127.0.0.1,
在mysql.sql 的192行,如下语句:
local packet = _set_byte3(size) .. strchar(self.packet_no) .. req
strchar(256) 越界导致报上述错误;
(3)、随后定位这个self.packet_no数据的来源, 在mysql.lua的_recv_packet()函数的227行 有赋值操作:
local num = strbyte(data, pos)
--print("recv packet: packet no: ", num)
self.packet_no = num
即 mysql库中_send_packet() 函数中的self.packet_no数值来源于 _recv_packet()函数;
在mysql.lua 接收数据函数中添加日志发现,在接收数据包的过程中,数据项计数器num是从 0~255 间循环计数的;
由于表中总记录为762条, 250 + 256 + 256 =762 ;
其中在接收数据的前6条刚好是指令数据;
因此在接收数据 完成的退出的时候, self.packet_no = num刚好等于255;
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 250, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 251, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 252, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 253, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 254, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 [lua] mysql.lua:228: _recv_packet(): Test packet sequence number : 255, client: 127.0.0.1,
2016/12/13 13:01:01 [error] 10656#0: *15415 lua entry thread aborted: runtime error: xxxx/lualib/resty/mysql.lua:191: bad argument #1 to 'strchar' (invalid value)
最后 _send_packet()函数调用计数器值前加一了,255+1 =256 ,产生越界报错:
self.packet_no = self.packet_no + 1
local packet = _set_byte3(size) .. strchar(self.packet_no) .. req
(4)、验证:
随后将mysql的查询语句Limit限制为 250, 506, 762,均触发了以上bug
SELECT x,y, modify_time FROM table ORDER BY modify_time DESC LIMIT 0, 250;
SELECT x,y, modify_time FROM table ORDER BY modify_time DESC LIMIT 0, 506;
SELECT x,y, modify_time FROM table ORDER BY modify_time DESC LIMIT 0, 762;
求核实确实是否为mysql库函数bug;