mysql_escape_string导致的数据回滚

2013年08月22日，一个关于用户数据的血案导致两位开发人员，一位DBA，一位业务运维通宵加班恢复用户数据，史称822血案；
此血案由一个名叫mysql_escape_string的函数导致；
下面将此血案的发现、初步解决、定位以及最终解决的过程记录如下，涉及到相关的知识点也顺便记录。

【血案出现】
8.22上午9点，开发接到数单用户投诉，用户投诉的具体内容为：半小时前登录XX游戏，自己的荣誉、成就、任务全部被清空；
由于是同一时间段接到数单投诉，引起开发重视，于是立即登录Server查看原因。
涉及到此业务的Server架构如下（为了简化说明问题，只把涉及此业务的架构剥离出来）：



1、迅速ssh到业务AServer，发现AServer正在狂刷某类型Log；(有同事会疑惑Svr没部署监控告警吗？实际是此类型Log在某些情况下是正常的Log，所以没有监控此类型Log)；
2、ssh到DBSvr，DBSvr写失败的比较少，但存在。
疑惑点是：在AServer没做任何发布的情况下，什么原因导致用户的数据出错？
初步查看，发现DBSvr在今早8点左右有升级操作，于是怀疑是此DBSvr导致；
【血案临时处理--先止血】
1、回滚一台DBSvr，观察3分钟，发现AServer某类型Log变少。
2、确定是DBSvr的发布导致；
3、立即全部回滚DBSvr；
4、观察业务，恢复OK；
5、确认影响的用户数量：由于早晨8-10点属于用户活跃期，经过统计发现，影响用户数量在5KW量级；
【血案定位过程】
俗语说，蛇打七寸。DBSvr的发布导致用户数据出错，那问题基本是出在DBSvr的升级上，从DBSvr的变更入手是确定问题成因的最快办法。
不得不说的是，由于AServer最近有个需求，需要后端DBServer将DB的blob字段大小由原来仅仅支持4K改到能够支持24K。此次的DBServer版本升级就是针对这个需求的。
1、从业务Server定位原因：
用户的成就之类数据是使用blob存放，AServer在进行读取、更新的时候会做响应的编解码操作。用户数据出错，可能于此相关；
在AServer中，对blob进行编解码之前，会校验此blob是否有效。
A、更新DBServer之前，会生成一个key，一起编码到blob数据区中；如下所示：



B、查询DBServer的响应回来之后，会进行如下的校验



C、校验失败，则认为用户数据不合法，重新初始化用户的数据，如下所示：



经过ABC步骤，基本确定是AServer像DBServer发送消息，在DBServer上面的编解码出错；

2、从DBServer定位原因：
GDB断点到DBServer，一直追踪到对blob字段进行编解码的地方；
最后，一路跟踪到以下的代码：



此段代码的宏定义在旧版本的数值是：MAX_BLOB_LENGTH = 8*1024；
新的升级将其修改为：MAX_BLOB_LENGTH = 24*1024；
在此代码之后，既是写DB的操作。
很明显，AServer传递过来的数据只有在此地方会被修改；
3、确定问题原因以及解决方法
google此函数mysql_escape_string，发现了如下的说明：



很明显，由于字节编码问题（each character may need to be encoded as using two bytes），mysql官方建议输出字符串长度最好设定为输入字符串的length*2+1长度。
额外发现一个问题，即：The return value is the length of the encoded string,
not including the terminating null character.
之前为什么没问题?
至此，原因很明白了：
8*1024 = 4*1024
24*1024 = 24*1024 < 24*1024*2
【血案解决方法】
1、恢复用户数据；
在DBSvr回滚之后，即联系DBA从DB备机和binlog恢复数据；恢复完毕数据约在晚上7点；
由于AServer有cache，故无法在不停机的情况下将数据导入DB。因此，为了降低对用户的影响，决定在凌晨3-4点停服导数据；
2、修复由升级DBServer升级导致的bug，重新测试、发布版本。
【血泪总结】
虽然每次总是在总结，但是每次都被忽略。

灰度原则：版本的发布一定要采用灰度发布方式；

外网验证：在系统灰度发布的情况下，一定要联系相关系统的负责人，进行适当的观察、验证。
【相关文章】
mysql_escape_string ：
http://dev.mysql.com/doc/refman/5.6/en/mysql-escape-string.html