Skip to main content

2016年最后一个 bug

00:00/00:00

  • 这篇文章本来叫小黄游记之深圳

元旦前后的小事情

元旦想出去玩

元旦想出去玩一下, 订了12月30号下午6点飞深圳的机票

打个广告, 浦发信用卡每年有3次接送机权益, 终于用到了一次, 告诉司机下午3点来接, 怕路上堵车

白名单空了

中午12点, 刚要去吃午饭, 看了一眼手机, 100多个报警, 又坐了下来, 打开监控, 发现几个业务被拒绝访问了

说个背景, 为了防止来自未经授权的机器操作我们的数据库, 数据库增加了来源 ip 校验(比最近爆出的 MonogDB 被黑的那些 DBA 不知道高到哪里去了~_~), 来自白名单的机器才允许访问, 问题就是, 有几个业务的白名单空了

试图手动更新白名单, 失败了, 然后紧急处理, 去掉了白名单逻辑

这时候是十二点半

查了下更新白名单失败的原因, 在这个函数上, python

def system_with_timeout(cmd, timeout=60*60*24*30):
    from subprocess import Popen, PIPE
    import signal
    import time
    import os

    tstart = time.time()
    p = Popen(cmd, shell=True, bufsize=10240, stdout=PIPE, stderr=PIPE)

    while p.poll() is None: #python2.7 Popen.wait() has no timeout
        time.sleep(min(0.2, time.time() - tstart))
        if time.time() - tstart > timeout:
            try:
                os.kill(p.pid, signal.SIGKILL)
                os.waitpid(-1, os.WNOHANG)
            except:
                return None

    r = p.stdout.read()
    return r

这个方法用来执行系统命令, 带超时, 我们的白名单是通过一个内部的命名空间指定的, 调用系统命令通过名字拿到列表, 出问题的原因在于 PIPE 的大小是有限的, 在 PIPE 满了以后, 调用的命令在等待写入 stdout, poll 一直是 None, 在超时之后, 返回了空值, 上层没做校验, 直接写入了白名单

在 python 2.7 中没有带超时执行系统命令的方法, 需要自己写多线程实现, 修复版本如下:

def system_with_timeout(cmd, timeout=60*60*24*30):
    from subprocess import Popen, PIPE
    import threading
    import thread
    import signal
    import os

    tstart = time.time()
    p = Popen(cmd, shell=True, bufsize=1024, stdout=PIPE, stderr=PIPE)
    res = {}

    def read_stdout(p, res, thread_lock):
        res["stdout"] = p.communicate()[0]
        thread_lock.acquire()
        res["status"] = p.poll()
        thread_lock.release()

    thread_lock = threading.Lock()
    thread.start_new_thread(read_stdout, (p, res, thread_lock,))

    while True:
        if time.time() - tstart > timeout:
            try:
                os.kill(p.pid, signal.SIGKILL)
                os.waitpid(-1, os.WNOHANG)
            except:
                return None

        thread_lock.acquire()
        if "status" in res:
            thread_lock.release()
            break
        thread_lock.release()

        time.sleep(min(0.2, time.time() - tstart))

    return res["stdout"]

确认调用没问题之后, 上线, 修复白名单

服务崩溃

14:50 上线修复白名单, 刚一修复, 就发现请求掉到零了

“呵呵, 统计挂了”, 当时是这样想, 到机器上看了一眼统计状态, 好的, 看了一眼代理服务器状态, 请求日志没了, 只看见一遍一遍在刷拉取元信息的日志

感觉出事了

这时候群里开始报问题

恢复服务

代理服务器从 zookeeper 拉元信息, 从日志来看, 是拉不到, 但是不明白为什么会停止处理请求, 从设计上来讲, 即使 zookeeper 挂掉, 代理服务器的请求处理也是正常的

首先考虑的是元信息太大导致 zookeeper 被打满, 试图恢复之前的元信息, 发现恢复不回去了, zookeeper 响应缓慢

15:00了, 故障已经持续十分钟, 群里已经要炸锅了, 几百万的请求绕过缓存冲向数据库, 产品已经不可用, 内网已经有帖子开始问发生了什么

这时为了止损, 停止按照常规手段恢复服务, 代理服务器设计之初考虑到 zookeeper 服务发生种种异常导致不可用, 有使用本地配置文件启动的应急措施, 不过上线两年来, 这个应急措施从来没用过

我们找到半小时前的备份元信息, 开始向所有代理服务器分发配置, 之后重启

服务开始恢复, 15:10 时产品已经基本可用, 15:20 时线上服务恢复正常

赶飞机

15:40, 确认了一下服务没问题之后, 得去赶飞机了, 航班是联合航班, 东航由南航承运, 不能网上值机, 值机时间在起飞前45分钟, 所以要在17:15之前到机场

路上堵车很厉害, 高速上有事故, 堵了二十分钟, 机场高速车多, 跑得慢, 到机场时差五分钟就不能值机了, 幸好排队的人很少, 办完手续后, 刚好赶上

吃了个饭, 登机了, 小飞机, 没啥可玩的

打个广告, bose 的 qc35 耳机又一次派上了用场, 耳罩式的降噪耳机摘下眼镜效果好很多

赞扬一下神州专车的司机, 约的下午三点的车, 等到快四点也没啥怨言, 没催没抱怨, 比某专车好太多了

到深圳

晚上九点半到深圳, 空气湿润干净, 话说深圳真是个挺好的城市, 容易惹人爱

坐地铁到了西丽, 买了个鸡肉卷, 吃掉

住下后开始找白天出问题的原因

追问题

看代理服务器日志, 没有太大异常, stdout 输出是不断拉取元信息, 同事看了下std err, 之前没注意, 发现已经在不停 core 了

golang 的 core 表现为 panic

golang 的错误信息比较详细, panic 时会打印出错误的行

看错误日志, 出现在逻辑中的 zk.Get()这一个调用, 而 Get 取得的是一个字符串, 不应该出 panic

怀疑是驱动有 bug, 追到驱动代码中, 发现一个 cache 设置为1536KB(为什么是1536KB?), 怀疑是 buffer 满以后触发了什么奇怪的 bug

把 buffer 改大, 重启, 服务正常

已经放假了, 没继续追根本原因, 调整 buffer 之后, 测试发版上线, 在 02:30 替换了线上使用静态配置有风险的版本

睡觉

吃的

早上起来, 吃的肠粉, 三份, 鸡蛋, 牛肉还有虾, 好吃

我爱肠粉, 软软滑滑的感觉对我孱弱不堪的胃有好处

老习惯, 上张小黄的图图

wechatimg11524

去图书馆玩了会, 不看书, 给小黄拍照

冒着掉下去的风险拍了张

img_1050

下午吃的食堂, 物美价廉

晚上在路上走了走, 看见几个小黄车

从用户体验和产品设计上, 小黄车比摩拜差得太多, 摩拜的车带 gps, 能看周围的车, 而且扫码开锁, 关锁自动停止计费, 是一个好用的产品, 小黄车只是一个”根据车牌号查开锁密码的数据库服务”, 没有 gps 没有自动计费, 用户查到密码后直接开锁, 用多久也不知道, 周围的车也看不到, 搞不懂为什么这种产品还能跟摩拜撕逼这么久(感觉连收购的价值都没有)

而且因为没有 gps 和自动计费, 车锁也很简单, 破坏成本低, 很容易出现扯掉锁和私装锁的情况, 在路上走了没多久就看到两辆

img_1061

img_1060

摩拜没看到过, 而且, 摩拜的 lite 版比传统版好骑很多, 轻, 舒服也便宜

回去就睡觉啦, 跨年

打麻将

第二天早上起来, 买了件衣服, 红色的, 妹子说过年要穿红色的

下午跟几个同学打麻将, 现学的, 以前也不会, 打了一下午还带了几把德州

晚上去吃的砂锅粥, 挺好吃的

回北京

然后就要回北京了, 两天多点时间, 挺快的

中午的飞机, 是大飞机, 电容屏的 pad, 挺好玩的, 看了个电影, 玩了几把游戏就到了

下来就是雾霾, 空气很差

9001的3M 口罩在路上得戴着, 家里买了352 x80的空气净化器, 效果还可以, 上张图

img_1036

 

img_1037

 

卧室有一个小的小米

晚上约了个按摩, 顺带刮了个痧, 挺舒服的, 有点疼

继续解决问题

上班后, 看之前的问题, 为什么 buffer 小会 panic

看到panic 的报错“, 是因为数组访问超过最大值, 越界

找到 panic 的一行, 在下面

再看相关的 bufsize 相关的逻辑, 在这里:

const (
    bufferSize      = 1536 * 1024
)
func (c *Conn) recvLoop(conn net.Conn) error {
    buf := make([]byte, bufferSize)
    ...
    for {
        ...
        blen := int(binary.BigEndian.Uint32(buf[:4]))
        if cap(buf) < blen {
            buf = make([]byte, blen)
        }
        ...
        _, err = decodePacket(buf[16:16+blen], req.recvStruct)
        ...
    }
}

看 zookeeper 的协议格式, 在16字节之后是数据内容, 所以应该是[16:blen]而不应该是[16:16+blen]

然后看了下库的更新记录, 发现在2016年1月份和3月份有以下的提交:

Alt text

那应该是确认的, 手抖导致的问题

更新驱动, 上线

继续出问题

上线后, 没有异常

我们有一些很大的集群, 上线不久, 有万规模的节点, 三副本, 每天都有任务修复坏掉的节点, 按正常的坏盘率, 不应该出现三副本全挂的情况, 可是在节后两天内, 出现了三个无主节点的情况, 看节点状态, 都是只坏了一个节点就不能选主了

查看负责选主的服务, 持续报错写 zookeeper 失败, 再次怀疑是驱动问题

驱动在Get 值时如果发现长度超过 buffer, 会自动延长, 然而在Set 时, 没有这样的判断逻辑, 导致写入失败

暂时改大 buffer, 上线, 问题解决

后面还得做彻底的bug 修复, 在 Set 时自动增大 buffer

后记

架构师和工程师从不同角度决定了产品的质量, 架构师是设计者, 他的工作决定了产品的质量上限, 工程师是实现者, 他的工作决定了产品的质量下限, 架构师的设计层次要高, 一个糟糕的架构无论如何都不会做成一个好的工程, 工程师的实现要硬, 再好的架构放到不靠谱的人手里, 也会变成一坨屎

然而除此之外, 还有一个依赖模块的可靠性, 比如驱动的使用, 我们一般只会看看 api, 基本没什么人有精力去看他的实现, 所以依赖是一个定时炸弹, 随时可能出问题

然而这个问题可能并没有太好的方法去解决, 毕竟不可能工程上的所有细节都需要自己设计, 我们能做的是让要炸弹尽可能早爆炸并做好相应的准备, 多使用更多人使用过的库, 对于所有依赖库, 应该有专门的人负责追踪更新日志并做必要的更新

开源是使代码变好的通用途径

打赏
微信扫一扫支付
微信logo微信扫一扫, 打赏作者吧~

4 thoughts to “2016年最后一个 bug”

  1. 贝神家挺漂亮啊,话说引入第三方的软件,QA需要完整测试的,当初肯定没测啊…

      1. 这应该是引用的Gravatar的头像, 如果你的邮箱没注册, 就是随机的

评论已关闭