最近碰到一个bug, 约7天发生一次，历时3周才找到问题并修复。

在找到bug并修复后，我仔细反思了一下。

我发现不仅这个bug是并发bug的一个典型，修复bug的过程也是直击我的弱点。

下面记录一下整个过程。

最近突然想对我的网络框架做一次RPC浸泡测试。

写了一段代码，开了6000个客户端，去并发RPC请求，服务端收到RPC之后会随机10~2500ms 延时之后再返回。 丢到我的VPS上之后，也没在意，过了两天就忘记这回事了。

过了大概一周，我突然想起来我还有一个浸泡测试在跑着呢，就上去看了一下log.

令我意外的是，网络和rpc没有出现bug，定时器出现Bug了。

就这样一边加log等重现，一边看代码，在历时3周后终于靠看代码修掉了。

定时器相关代码大概如下：

--core.lua（run in thread1)
function core.timeout(ms, func)
    local co = cocreate(func)
    local session = silly_timeout(ms)         --silly_timeout 等价于 silly_timer_timeout
    sleep_session_co[session] = co
    sleep_co_session[co] = session
    return session
end

local MSG = {}
function MSG.expire(session, _, _)
    local co = sleep_session_co[session]
    assert(sleep_co_session[co] == session)
    sleep_session_co[session] = nil
    sleep_co_session[co] = nil
    wakeup_co_queue[#wakeup_co_queue + 1] = co
end

//silly_timer.c
uint32_t
silly_timer_timeout(uint32_t expire)
{
    struct node *n = newnode();
    if (unlikely(n == NULL)) {
        silly_log("silly timer alloc node failed\n");
        return -1;
    }
    lock(T);
    n->expire = expire / TIMER_RESOLUTION + T->ticktime;
    assert((int32_t)(n->expire - T->expire) >= 0);
    add_node(T, n);
    unlock(T);
    return n->session;
}

// run thread2
void
silly_timer_update()
{
//检查所有struct node, 是否超时,
//如果超时，则向lua层抛出expire消息，然后将node结点Free掉
//在Lua层收到expire消息后，会调用MSG.expire函数
}

发现bug时，是发现在MSG.expire函数的第二行assert失败了。

这时我就告诉自己，柯南君的名言“排除一切不可能，剩下的再不可能也是真相”。

即然assert失败了，那只有三种可能。

A1. co 为 nil, 这时sleep_co_session[co]为nil
A2. co 不为nil 且sleep_co_session[co] 为nil
A3. co 不为nil 且 sleep_co_session[co]不等于session

我检查了一下代码，发现sleep_session_co 和sleep_co_session都是一起操作的，因此我将A2排除了。

为了进一步排除A1和A3, 我在MSG.expire加了点log，当assert失败时，打印一下session和co的值。

过了几天后确定是A1.

而导致A1产生的可能情况有以下几种可能：

B1. silly_timer_timeout返回了两个相同的session
B2. silly_timer_update 对同一个session返回了2次
B3. silly_timer_update 返回了一个陌生的session

我查了一下rpc client端的log,我发现在相同的时间确实有一次rpc请求失败了，排除了B2.

如果是情况3, 那就代表silly_timer_update时返回的是脏数据，我查看了silly_timer.c中的代码，发现node->session只有在newnode时被赋值，其他情况并没有被改动过。因此我将B3排除了。

现在就剩下B1，出现B1 有两种可能。

C1. session回绕了
C2. 在++session时有并发问题出现了某种竞争

于是，我在session回绕和session每增加1000时，分别打印了一行log。以期望可以在下次重现时，获得一些有用的信息。

再次出现之后，我发现session并没有回绕，而session每增加1000打印的log似乎对我并没有什么帮助。

我开始把矛头对准C2分析。但是我反复检查，以我现有的知识来讲，session都不可能存在并发问题。

线突然断了，我知道一定是我哪里弄错了，但是我思维已经造成了定式。反复思考也没看到哪里有问题。

之后，每天打开电脑第一件事，就是去看一遍之前发生过的log和代码，以便突然有点灵感。

在过了大约7天之后，我突然发现，session每增加1000时的log L1和assert失败时的log L2发生在同一秒，而出错的session比L1中打印出来的session要小。

这也意味在有一个session在timeout之后立即就收到了expire消息。

于是我重新去看了一下silly_timer_timeout函数，我终于发现问题所在了。

在silly_timer_timeout时由于超时时间非常短的情况下。如果有以下步骤，就是必现的。

1. silly_timer_timeout加入node N1, 在执行完unlock之后，silly_timer_timeout所在的线程T1突然被切换而暂停执行了。
2. 这时silly_timer_update在线程T2执行了，它检查到N1已经达到了超时标准，于是将其关联的session用expire消息推送到lua线程并将N1释放(free)。
3. 其他代码调用malloc重新分配到了刚刚释放N1的内存，并写入数据
4. T1 重新唤醒被执行。silly_timer_timeout返回了错误的session, 但是silly_timer_update却推送了正确的session.

我在unlock之后加入了usleep(5000)之后，不一会，bug就重现了。

我复盘了一下整个bug分析流程，我发现整个思路都没有什么大问题。

惟一有问题的是，我做了一个错误的假设B1。

B1 应该被修改为，返回了一个无效的session（重复的session同样是无效的session）。

之所以我做了错误的B1假设，是因为潜意识告诉我，silly_timer_timeout返回的session不可能问题了。我在一个错误的假设上做了各种推理。

这次经历告诉我，当相关代码出bug时，一定要忘记所有背景知识，仅对出问题的相关代码进假设（一切皆有可能）。

然后再根据相关信息进行逐个排查。

即使如此，打破思维定式，真的很难 ^_^!