std :: cerr不等待std :: cout(运行CTest时)

Question

上下文

我为用户写了一个记录器打印消息.打印带有"debug","info"或"warning" std::cout级别的消息,并打印带有"error"或"system_error"级别的消息std::cerr.我的程序不是多线程的.我使用gcc 4.7.2和CMake 3.1.0在Linux openSUSE 12.3下工作.

我的问题

我发现有时,当一条错误消息(打印在std::cerr)后面跟着一条长信息消息(打印出来std::cout),当输出被LastTest.logCTest 重定向到文件时,信息消息中会出现错误信息(请看下面的例子).我不太了解这种行为,但我想是一个写入线程被启动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使用记录器的示例.我用这样的maccros调用记录器:

#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);
}

这里,log chanel是专用于终端输出的对象,write函数是:

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();
}

您可以看到执行日志指令时刷新了我的缓冲区.

Answer 1

我之前以一些形式看过这种行为.中心思想是记住std::cout并std::cerr写入两个完全独立的流,因此每当你在同一个地方看到两者的输出时,都是因为程序之外的某些机制合并了两个流.

有时,我只是因为一个错误而看到这一点,例如

myprogram > logfile &
tail -f logfile

这是在写日志文件,但忘记重定向stderr到日志文件,所以写入在显示之前stdout至少经过两个额外的缓冲层tail,但写入stderr直接转到tty,因此可以混合使用.

我见过的其他例子涉及合并流的外部流程.我什么都不知道,CTest但也许它正在这样做.这些进程没有义务按照您最初将它们写入流的确切时间对行进行排序,并且即使他们想要也可能无法访问该信息!

你真的只有两个选择:

• 将两个日志写入同一个流 - 例如使用std::clog而不是代替std::cout或std::cout代替std::cerr; 或者用myprogram 2>&1或类似的方式启动程序
• 确保合并是由一个实际意识到它正在合并的过程完成的,并且要注意适当地进行合并.如果您通过传递包含日志记录事件的数据包进行通信而不是自己编写格式化的日志消息,则可以更好地工作.

Answer 2

回答我自己的问题

最后,它来自CMake中的一个错误.

CTest无法管理两个缓冲区的顺序,因此不关心输出的确切顺序.

它将在CMake> = 3.4中解决.