cancel a deadline_timer, callback triggered anyway

Question

I was suprised not to find a clock component in boost::asio (our any widely used library) so it tried making a simple, minimalistic, implementation for testing some of my code.

Using boost::asio::deadline_timer I made the following class

class Clock
{
    public:
        using callback_t = std::function<void(int, Clock&)>;
        using duration_t = boost::posix_time::time_duration;

    public:
        Clock(boost::asio::io_service& io,
              callback_t               callback = nullptr,
              duration_t               duration = boost::posix_time::seconds(1),
              bool                     enable   = true)
            : m_timer(io)
            , m_duration(duration)
            , m_callback(callback)
            , m_enabled(false)
            , m_count(0ul)
        {
            if (enable) start();
        }

        void start()
        {
            if (!m_enabled)
            {
                m_enabled = true;
                m_timer.expires_from_now(m_duration);
                m_timer.async_wait(boost::bind(&Clock::tick, this, _1)); // std::bind _1 issue ?
            }
        }

        void stop()
        {
            if (m_enabled)
            {
                m_enabled = false;
                size_t c_cnt = m_timer.cancel();
                #ifdef DEBUG
                printf("[DEBUG@%p] timer::stop : %lu ops cancelled\n", this, c_cnt);
                #endif
            }
        }

        void tick(const boost::system::error_code& ec)
        {
            if(!ec)
            {
                m_timer.expires_at(m_timer.expires_at() + m_duration);
                m_timer.async_wait(boost::bind(&Clock::tick, this, _1)); // std::bind _1 issue ?
                if (m_callback) m_callback(++m_count, *this);
            }
        }

        void              reset_count()                            { m_count = 0ul;         }
        size_t            get_count()                        const { return m_count;        }
        void              set_duration(duration_t duration)        { m_duration = duration; }
        const duration_t& get_duration()                     const { return m_duration;     }
        void              set_callback(callback_t callback)        { m_callback = callback; }
        const callback_t& get_callback()                     const { return m_callback;     }

    private:
        boost::asio::deadline_timer m_timer;
        duration_t                  m_duration;
        callback_t                  m_callback;
        bool                        m_enabled;
        size_t                      m_count;
};

Yet it looks like the stop method doesn't work. If I ask a Clock c2 to stop another Clock c1

boost::asio::io_service ios;
Clock c1(ios, [&](int i, Clock& self){
        printf("[C1 - fast] tick %d\n", i);
    }, boost::posix_time::millisec(100)
);
Clock c2(ios, [&](int i, Clock& self){
        printf("[C2 - slow] tick %d\n", i);
        if (i%2==0) c1.start(); else c1.stop(); // Stop and start
    }, boost::posix_time::millisec(1000)
);
ios.run();

I see both clocks ticking as expected expect sometimes c1 doesn't stop for one second, while it should.

It looks like calling m_timer.cancel() doesn't always work because of some sync issue. Did I got somethign wrong ?

Answer 1

First, let's show the problem reproduced:

Live On Coliru (code below)

As you can see I run it as

./a.out | grep -C5 false

This filters the output for records that print from C1's completion handler when really c1_active is false (and the completion handler wasn't expected to run)

The problem, in a nutshell, is a "logical" race condition.

It's a bit of mind bender because there's only a single thread (visible on the surface). But it's actually not too complicated.

What happens is this:

• when Clock C1 expires, it will post its completion handler onto the io_service's task queue. Which implies that it might not run immediately.

• imagine that C2 expired too, and it's completion handler now gets scheduled and executes before the one that C1 just pushed. Imagine that by some high coincidence this time, C2 decides to call stop() on C1.

• After C2's completion handler returns, C1's completion handler gets invoked.

  OOPS

  It still has ec saying "no error"... Hence the deadline timer for C1 gets rescheduled. Oops.

Background

For a more in-depth background on the guarantees that Asio (doesn't) make(s) for the order in which completion handlers get executed, see

• When do handlers for cancelled boost::asio handlers get to run?

Solutions?

The simplest solution is to realize that m_enabled could be false. Let's just add the check:

void tick(const boost::system::error_code &ec) {
    if (!ec && m_enabled) {
        m_timer.expires_at(m_timer.expires_at() + m_duration);
        m_timer.async_wait(boost::bind(&Clock::tick, this, _1));

        if (m_callback)
            m_callback(++m_count, *this);
    }
}

On my system it doesn't reproduce the problem any more :)

Reproducer

Live On Coliru

#include <boost/asio.hpp>
#include <boost/bind.hpp>
#include <boost/date_time/posix_time/posix_time_io.hpp>

static boost::posix_time::time_duration elapsed() {
    using namespace boost::posix_time;
    static ptime const t0 = microsec_clock::local_time();
    return (microsec_clock::local_time() - t0);
}

class Clock {
  public:
    using callback_t = std::function<void(int, Clock &)>;
    using duration_t = boost::posix_time::time_duration;

  public:
    Clock(boost::asio::io_service &io, callback_t callback = nullptr,
          duration_t duration = boost::posix_time::seconds(1), bool enable = true)
            : m_timer(io), m_duration(duration), m_callback(callback), m_enabled(false), m_count(0ul) 
    {
        if (enable)
            start();
    }

    void start() {
        if (!m_enabled) {
            m_enabled = true;
            m_timer.expires_from_now(m_duration);
            m_timer.async_wait(boost::bind(&Clock::tick, this, _1)); // std::bind _1 issue ?
        }
    }

    void stop() {
        if (m_enabled) {
            m_enabled = false;
            size_t c_cnt = m_timer.cancel();
#ifdef DEBUG
            printf("[DEBUG@%p] timer::stop : %lu ops cancelled\n", this, c_cnt);
#endif
        }
    }

    void tick(const boost::system::error_code &ec) {
        if (ec != boost::asio::error::operation_aborted) {
            m_timer.expires_at(m_timer.expires_at() + m_duration);
            m_timer.async_wait(boost::bind(&Clock::tick, this, _1));
            if (m_callback)
                m_callback(++m_count, *this);
        }
    }

    void reset_count()                     { m_count = 0ul;         } 
    size_t get_count() const               { return m_count;        } 

    void set_duration(duration_t duration) { m_duration = duration; } 
    const duration_t &get_duration() const { return m_duration;     } 

    void set_callback(callback_t callback) { m_callback = callback; } 
    const callback_t &get_callback() const { return m_callback;     } 

  private:
    boost::asio::deadline_timer m_timer;
    duration_t m_duration;
    callback_t m_callback;
    bool m_enabled;
    size_t m_count;
};

#include <iostream>

int main() {
    boost::asio::io_service ios;

    bool c1_active = true;

    Clock c1(ios, [&](int i, Clock& self)
            { 
                std::cout << elapsed() << "\t[C1 - fast] tick" << i << " (c1 active? " << std::boolalpha << c1_active << ")\n";
            },
            boost::posix_time::millisec(1)
            );

#if 1
    Clock c2(ios, [&](int i, Clock& self)
            {
                std::cout << elapsed() << "\t[C2 - slow] tick" << i << "\n";
                c1_active = (i % 2 == 0);

                if (c1_active)
                    c1.start();
                else
                    c1.stop();
            },
            boost::posix_time::millisec(10)
        );
#endif

    ios.run();
}

Answer 2

From the boost documentation:

If the timer has already expired when cancel() is called, then the handlers for asynchronous wait operations will:

1. have already been invoked;
2. or have been queued for invocation in the near future.

These handlers can no longer be cancelled, and therefore are passed an error code that indicates the successful completion of the wait operation.

Your application on such successful completions (when timer already expired) restart the timer again, and another interesting thing that on Start function call you again implicitly cancelling the timer in case when it is not expired yet.

expires_at function sets the expiry time. Any pending asynchronous wait operations will be cancelled. The handler for each cancelled operation will be invoked with the boost::asio::error::operation_aborted error code.

Probably you could reuse your m_enabled variable or just have another flag for detecting timer cancellation.

Another solution is possible: timer example