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

Question

上下文

我编写了一个记录器，为用户打印消息。级别为"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中打印)之后，当CTest将输出重定向到文件LastTest.log时，错误消息出现在信息消息中(参见下面的示例)。我不太理解这种行为，但我假设为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的示例。我用这样的宏调用记录器:

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

您可以看到，当执行日志指令时，我的缓冲区被刷新。

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的一个bug。

CTest不能管理两个缓冲区的顺序，因此也不关心输出的确切顺序。

将在CMake>= 3.4中解析

Answer 3

我不是c++专家，但这可能会有所帮助…

我相信你在这里看到的问题，当重定向到一个文件时，是由cstdio库试图变得聪明引起的。我的理解是，在Linux上，c++ io流最终会将它们的输出发送到cstdio库。

在启动时，cstdio库检测您是将输出发送到终端还是发送到文件。如果输出到终端，那么studio是行缓冲的。如果输出到一个文件，那么stdio变成块缓冲。

stderr的输出永远不会被缓冲，所以会立即发送。

对于解决方案，您可以尝试在标准输出上使用fflush，或者您可以考虑在标准输出上使用setvbuf函数来强制行缓冲输出(如果您愿意，甚至可以不缓冲输出)。像这样的代码应该强制标准输出为行缓冲setvbuf(stdout, NULL, _IOLBF, 0)。