boost log库_记录一个使用 boost::asio::deadline_timer 的 bug

最近几天在 debug 一个模块，这个模块使用了 boost::asio ，主要就是跑一个 io_service.run() ，有几个 deadline_timer 注册在 io_service 里面。模块退出的时候把 timer 都 deadline_timer.cancel() 掉。

这个模块用 deadline_timer 现了周期性的 timer ，实现大概如下（网上有很多周期性的 timer 都是这样实现的）：

void inner(deadline_timer& timer, function<void(void)> callback) {
    callback();
    timer.expires_from_now(expiry_time);
    timer.async_wait(bind(
        inner, ref(timer), callback));   
}

void register(deadline_timer& timer, function<void(void)> callback) {
    timer.expires_from_now(expiry_time);
    timer.async_wait(bind(inner, ref(timer), callback));
}

这个模块其中一个 bug 的表现是：在模块退出的时候，其中一个 deadline_timer 会继续周期性的运行打日志，而其他的 deadline_timer 没什么问题，正常 cancel 了。最终导致 io_service.run() 一直在等待。跑一天能复现一次。

我开始想用 boost 的一个宏 BOOST_ASIO_ENABLE_HANDLER_TRACKING 看一看 io_service 里的 epoll 都有啥在 wait ，后来发现在 cmake 里 add define 这个宏会出 core ， gdb 看了一下发现 core 在了模块使用的 log 库的初始化上面，估计是 log 库魔改了什么，于是放弃。

经过了一系列挣扎，翻了翻 boost 的文档，发现 deadline_timer::cancel() 的文档里面有这样一句话：

If the timer has already expired when cancel() is called, then the handlers for asynchronous wait operations will:
* have already been invoked; or
* have been queued for invocation in the near future.

这才明白，原来 deadline_timer 如果恰好在 cancel 之前到期，那么 inner 立即运行或者加入到 io_service 的 epoll 里，等着 io_service 调度。于是，如果采用这种递归的周期性的定时器，就会有这种 case ：

1. 当前 timer 已经到期了；
2. 这时 cancel 掉这个 timer ，这个 timer 的 inner 会加入到 epoll 里；
3. cancel 掉的 timer 不会再执行了，然而已经加入到 epoll 里的 inner 会继续执行；
4. 由于 inner 是递归的，会产生新的 inner ，也就是说，这个 timer 并没有被真正的 cancel ，而是复活了。

问题发现了，原因就是在 cancel 的时候，如果正好 timer 过期，这时 inner 会加入到 epoll 中，这个 inner 会递归复活。

如何解决呢？

实在想不出啥好办法，后来在 stack overflow （ https://stackoverflow.com/questions/43168199/cancelling-boost-asio-deadline-timer-safely ）上面查询到了 tricky 的解决方法，也是 boost::deadline_timer 实现周期性 timer 如何退出的唯一正解：

1. 不用 cancel 函数，而是在原来调用 cancel 的地方设置 timer 的一个特殊的过期时间（ magic number ）；
2. 修改 inner 函数，首先判断过期时间是不是这个 magic number ，如果是，那就直接退出，不递归了。

这样，即使想退出的时候，已经有 inner 在 epoll 里了也没关系， inner 跑的时候会检查 magic number 的，不会继续递归了，最多多执行一次而已。

代码大概是这样：

// 原来 timer.cancel(); 的地方
io_service.post([&] { timer.expires_at(114514); });

// inner 应该这么写
void inner(deadline_timer& timer, function<void(void)> callback) {
    if (timer.expires_at() == 114514) {
        return;
    } else {
        callback();
        timer.expires_from_now(expiry_time);
        timer.async_wait(bind(
            inner, ref(timer), callback));  
    }
}

最后一个问题，模块里有很多个周期性的 timer ，为啥只有这个会 cancel 失败呢？因为只有这个 timer 周期比较小， cancel 的时候正好容易碰上过期时间（容易：指跑一天能复现一次）。