Std:: cerr не ждет std:: cout (при запуске CTest)

Контекст

Я написал для пользователя сообщения для печати журнала. Сообщения с уровнем "debug", "info" или "warning" печатаются в std::cout, а сообщения с уровнем "error" или "system_error" печатаются в std::cerr. Моя программа не многопоточная. Я работаю под Linux openSUSE 12.3 с gcc 4.7.2 и CMake 3.1.0.

Моя проблема

Я обнаружил, что иногда, когда сообщение об ошибке (напечатанное в std::cerr) следует за длинным информационным сообщением (напечатано в std::cout), а когда выход перенаправляется в файл LastTest.log от CTest, появляется сообщение об ошибке в информационном сообщении (см. пример ниже). Я не очень хорошо понимаю это поведение, но я полагаю, что для std::cout запускается поток писем, затем код продолжается, а другой поток писем выделяется для std::cerr, не дожидаясь завершения первого.

Можно ли избежать этого, не используя только std::cout?

У меня нет проблемы в терминале. Это происходит только тогда, когда CTest перенаправляет вывод в файл LastTest.log.

Обратите внимание, что мой буфер очищен. Это не проблема std::endl после вызова std::cerr!

Пример

Ожидаемое поведение:

[ 12:06:51.497   TRACE ] Start test
[ 12:06:52.837 WARNING ] This
                         is
                         a
                         very
                         long
                         warning
                         message...
[ 12:06:52.837   ERROR ] AT LINE 49 : 7
[ 12:06:52.841   ERROR ] AT LINE 71 : 506
[ 12:06:52.841   TRACE ] End of test

Что происходит:

[ 12:06:51.497   TRACE ] Start test
[ 12:06:52.837 WARNING ] This
                         is
                         a
                         very
                         long
[ 12:06:52.837   ERROR ] AT LINE 49 : 7
                         warning
                         message...
[ 12:06:52.841   ERROR ] AT LINE 71 : 506
[ 12:06:52.841   TRACE ] End of test

Как я называю свой регистратор

Вот пример того, как я вызываю std::cout или std::cerr с помощью моего регистратора. Я вызываю logger с такими макросами:

#define LOG_DEBUG(X) {if(Log::debug_is_active()){std::ostringstream o;o<<X;Log::debug(o.str());}}
#define LOG_ERROR(X) {if(Log::error_is_active()){std::ostringstream o;o<<X;Log::error(o.str());}}
//...
LOG_DEBUG("This" << std::endl << "is" << std::endl << "a message");
LOG_ERROR("at line " << __LINE__ << " : " << err_id);

с

void Log::debug(const std::string& msg)
{
    Log::write_if_active(Log::DEBUG, msg);
}
void Log::error(const std::string& msg)
{
    Log::write_if_active(Log::ERROR, msg);
}
//...
void Log::write_if_active(unsigned short int state, const std::string& msg)
{
    Instant now;
    now.setCurrentTime();
    std::vector<std::string> lines;
    for(std::size_t k = 0; k < msg.size();)
    {
        std::size_t next_endl = msg.find('\n', k);
        if(next_endl == std::string::npos)
            next_endl = msg.size();
        lines.push_back(msg.substr(k, next_endl - k));
        k = next_endl + 1;
    }
    boost::mutex::scoped_lock lock(Log::mutex);
    for(unsigned long int i = 0; i < Log::chanels.size(); ++i)
        if(Log::chanels[i])
            if(Log::chanels[i]->flags & state)
                Log::chanels[i]->write(state, now, lines);
}

Здесь журнал-канал - это объект, выделенный для вывода терминала, функция записи:

void Log::StdOut::write(unsigned short int state, const Instant& t, const std::vector<std::string>& lines)
{
    assert(lines.size() > 0 && "PRE: empty lines");
    std::string prefix =  "[ ";
    if(this->withDate || this->withTime)
    {
        std::string pattern = "";
        if(this->withDate)
            pattern += "%Y-%m-%d ";
        if(this->withTime)
            pattern += "%H:%M:%S.%Z ";
        prefix += t.toString(pattern);
    }
    std::ostream* out = 0;
    if(state == Log::TRACE)
    {
        prefix += "  TRACE";
        out = &std::cout;
    }
    else if(state == Log::DEBUG)
    {
        prefix += "  DEBUG";
        out = &std::cout;
    }
    else if(state == Log::INFO)
    {
        prefix += "   INFO";
        out = &std::cout;
    }
    else if(state == Log::WARNING)
    {
        prefix += "WARNING";
        out = &std::cout;
    }
    else if(state == Log::ERROR)
    {
        prefix += "  ERROR";
        out = &std::cerr;
    }
    else if(state == Log::SYS_ERROR)
    {
        prefix += "SYERROR";
        out = &std::cerr;
    }
    else
        assert(false && "PRE: Invalid Log state");
    prefix += " ] ";
    (*out) << prefix << lines[0] << "\n";
    prefix = std::string(prefix.size(), ' ');
    for(unsigned long int i = 1; i < lines.size(); ++i)
        (*out) << prefix << lines[i] << "\n";
    out->flush();
}

Вы можете видеть, что мой буфер сбрасывается при выполнении инструкции журнала.

Ответы

myprogram > logfile &
tail -f logfile