Boost::asio and async_read

Question

I am trying to use Boost::asio and async_read to implement a timeout in protocol which uses the serial port.

I have done a test implementation using synchronous read, which works just find, but my implementation with time out does not work.

void set_result( boost::optional<boost::system::error_code> * a, boost::system::error_code b ) {
    a->reset( b );
}

void receive(boost::asio::io_service & io, boost::asio::serial_port & cctalk_port, boost::asio::streambuf & result){
#if 1
    // Non-working implementation with timeout
    boost::optional<boost::system::error_code> timer_result;
    boost::optional<boost::system::error_code> read_result;

    boost::asio::deadline_timer timer( io );
    LOG(INFO) << "Timer at 5000ms starts here";
    timer.expires_from_now( boost::posix_time::milliseconds(5000) ); // allow up to 50ms of timeout for every char
    timer.async_wait( boost::bind(&set_result, &timer_result, _1) );

    LOG(INFO) << "Async read starts here (result.size() == " << result.size() << ")";
    boost::asio::async_read(
            cctalk_port,
            result,
            boost::asio::transfer_at_least(1),
            boost::bind( &set_result, &read_result, _1 ));
    boost::system::error_code ec;

    while(1) {
        io.poll_one(ec);

        if( ec != 0 || read_result != 0 || timer_result != 0)
            LOG(INFO) << "Error code: " << ec << " read_result: " << read_result << " timer_result: " << timer_result;

        if ( read_result ) {
            timer.cancel();
            LOG(INFO) << "Result ready (" << result.size() << ")";
            return;

        } else if ( timer_result ) {
            LOG(INFO) << "Timeout";
            throw runtime_error("timeout");
        }
    }

    LOG(INFO) << "Not suppose to happen";

#else
    // Working implementation without timeout
    boost::asio::read(cctalk_port, result, boost::asio::transfer_at_least(1));
#endif
}

void receive(boost::asio::io_service & io, boost::asio::serial_port & cctalk_port, size_t size, boost::asio::streambuf & result){
    LOG(INFO) << "Fetch at least " << size << " has allready: " << result.size();
    while( result.size() < size ) {
        receive(io, cctalk_port, result);
        LOG(INFO) << "Buffer size: " << result.size() << "/" << size;
    }
}

When I run this code I got the following outputs:

I0808 17:25:40.809615  3682 ccTalkScan.cxx:137] Fetch at least 5 has allready: 0
I0808 17:25:40.809672  3682 ccTalkScan.cxx:99] Timer at 5000ms starts here
I0808 17:25:40.809686  3682 ccTalkScan.cxx:103] Async read starts here (result.size() == 0)
I0808 17:25:40.809731  3682 ccTalkScan.cxx:115] Error code: system:0 read_result: 1 timer_result: 0
I0808 17:25:40.809738  3682 ccTalkScan.cxx:119] Result ready (12)
I0808 17:25:40.809742  3682 ccTalkScan.cxx:140] Buffer size: 12/5
I0808 17:25:40.809778  3682 ccTalkScan.cxx:137] Fetch at least 5 has allready: 7
I0808 17:25:40.809783  3682 ccTalkScan.cxx:137] Fetch at least 9 has allready: 7
I0808 17:25:40.809788  3682 ccTalkScan.cxx:99] Timer at 5000ms starts here
I0808 17:25:40.809797  3682 ccTalkScan.cxx:103] Async read starts here (result.size() == 7)
I0808 17:25:40.809808  3682 ccTalkScan.cxx:115] Error code: system:0 read_result: 0 timer_result: 1
I0808 17:25:40.809811  3682 ccTalkScan.cxx:123] Timeout

As it appears from the output, the timer is set must faster than 5000ms, in this case less than 1 ms.

Further more, by looking at the actual bytes I does receives it seems like I am missing the first byte.

Nim Nim · Accepted Answer · 2011-08-08T15:56:43

Hmm... The problem here is subtle, basically when you cancel the previous timer - another event is triggered on the io_service (a call to the handler responsible for that timer) to indicate it has been cancelled (with the appropriate error_code). Because you are only calling poll_one, the read is good to go, so you handle the read, then you cancel the timer (which sets up the subsequent event on the io_service - but for this run, it does not get called) - and then when your receive() method is called a second time, and you call poll_one - this event is triggered (and because you don't check for error condition in your set_result method), the state of the optional is good (it contains an error) and you treat this as your timeout...

Follow?

Boost::asio and async_read

1 Answers