python访问memchache的诡异bug

一、背景

最近用python的tornado框架+nginx反向代理做了套服务，通过supervisord进程管理工具来管理服务的多个进程，由于python里面没有实际意义上的线程，所以采用了本地memcache数据库作为了共享缓存。但是在服务上线后出现了一系列诡异的问题。

二、异常

1、服务访问过程中，时不时的会出现某个进程卡死的情况，单个进程的cpu利用率卡死到100%
2、服务时不时的崩溃，通过tornado日志可以看到如下的异常信息
*** glibc detected *** /opt/rh/python27/root/usr/bin/python2.7: double free or corruption (!prev): 0
3、通过strace工具查看某个卡死的进程pid，等待几分钟后又重新可以运行而cpu利用率也降下来了
4、通过dmesg工具查看出现了很多段错误：

python2.7[199367]: segfault at 3c ip 0000003310c79753 sp 00007fff1fb8e160 error 4 in libc-2.12.so [3310c00000+18a000]

python2.7[199725]: segfault at 10 ip 0000003310c790ac sp 00007fff35fdcfd0 error 4 in libc-2.12.so [3310c00000+18a000]

python2.7[199373]: segfault at 2b ip 0000003310c79753 sp 00007fff255188b0 error 4 in libc-2.12.so [3310c00000+18a000]

三、异常排查和处理

通过strace -p [进程id] 跟踪某个进程，直到其出现cpu卡死的情况，如下是异常出现前的strace信息。

{EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLHUP|EPOLLONESHOT|EPOLLET|0x3fa09000, {u32=32538, u64=17264586486200696602}}) = 0
recvfrom(15, "*122\r\n$16\r\n4082054637388644\r\n$19"..., 65536, 0, NULL, NULL) = 5242
sendto(14, "set WB:IV:feed:p:cry 1 300 2231\r"..., 2266, MSG_NOSIGNAL, NULL, 0) = 2266
recvfrom(14, "VALUE WB:IV:feed:p:86 1 2920\r\n(l"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 5229
recvfrom(14, 0x12752f8, 8196, 16384, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=14, events=POLLIN}], 1, 2000) = 0 (Timeout)
shutdown(14, 2 /* send and receive */)  = 0
close(14)                               = 0

通过分析strace信息基本定位到程序出问题的基本位置是在往memcache写数据的时候，而在tornado的异常信息中也出现了再访问pylibmc.so库的时候出现了异常，所以把代码中所有涉及到memcache访问的地方都加上了try…catch并打印了堆栈信息，出现如下的异常信息

_pylibmc.SocketCreateError: error 11 from memcached_set: SUCCESS

剩下就是google了，issuse

把出问题的地方重试了几次发现果然是key中包含了空格，bug只要可以复现解决起来就easy了。

再一次验证了“越是诡异的问题，越是小bug”