【问题标题】:std::cerr doesn't wait for std::cout (when running CTest)std::cerr 不等待 std::cout (运行 CTest 时)
【发布时间】:2015-08-16 01:58:19
【问题描述】:

上下文

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

我的问题

我发现有时,当一条长信息消息(以std::cout 打印)之后出现错误消息(以std::cerr 打印)并且当输出被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::coutstd::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);
}

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

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

你可以看到我的缓冲区在执行日志指令的时候被刷新了。

【问题讨论】:

  • 是的,但是在 std::cerr 中打印错误消息的 C++ 指令位于在 std::cout 中打印最后一个 std::endl 的指令之后。
  • 如果您在程序开始时发出std::ios_base::sync_with_stdio(false);,有什么变化吗?
  • @Hurkyl: sync_with_stdio 完全不同。
  • @Nawaz:可能。但是很难找到的错误通常发生在您确信自己不可能找到错误的地方,这是一件容易测试的事情。 (此外,它使语句“cout 被缓冲”实际上是正确的;在我看到的实现中,cout 通常在同步开启时根本不被缓冲;缓冲被委托给stdio 库)
  • @Nawaz:实际上,我目前的赌注是在 Linux 中的重定向做一些令人惊讶的事情,我评论的重点是消除 Linux 之间的交互以及如何设置 stdio 库。 (还有……有时库中确实存在错误)

标签: c++ output io-redirection ctest


【解决方案1】:

我以前曾以几种形式看到过这种行为。中心思想是要记住 std::coutstd::cerr 写入两个完全独立的流,所以任何时候你在同一个地方看到这两个流的输出,这是因为你之外的一些机制合并两个流的程序。

有时,我看到这只是由于一个错误,例如

myprogram > logfile &
tail -f logfile

它正在观察日志文件的写入,但也忘记将stderr 重定向到日志文件,因此写入stdout 在显示之前至少经过tail 内的两个额外缓冲层,但写入stderr直接去tty,这样就可以混进去了。

我见过的其他示例涉及合并流的外部进程。我对CTest 一无所知,但也许它正在这样做。此类进程没有义务按照您最初将它们写入流的确切时间对行进行排序,并且即使它们愿意也可能无法访问该信息!


你真的只有两个选择:

  • 将两个日志写入同一个流 - 例如使用std::clog 代替std::coutstd::cout 代替std::cerr;或使用myprogram 2&gt;&amp;1 或类似名称启动程序
  • 确保合并是由一个真正知道要合并什么的进程完成的,并注意适当地进行。如果您通过传递包含日志事件的数据包而不是自己编写格式化的日志消息来进行通信,这会更好。

【讨论】:

  • 实际上,我无法控制 CTest 如何启动可执行文件并重定向输出。我会尝试使用std::clog,我从未使用过它,它可能是一个很好的解决方案。
【解决方案2】:

回答我自己的问题

最后,它来自bug in CMake

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

它将在 CMake >= 3.4 中解决。

【讨论】:

    【解决方案3】:

    我不是 C++ 专家,但这可能会有所帮助...

    我相信您在重定向到文件时在这里看到的问题是由于 cstdio 库试图变得聪明造成的。我的理解是,在 Linux 上,C++ iostream 最终会将其输出发送到 cstdio 库。

    在启动时,cstdio 库会检测您是将输出发送到终端还是文件。如果输出到终端,则 stdio 是行缓冲的。如果输出到文件,则 stdio 变为块缓冲。

    stderr 的输出从不缓冲,因此会立即发送。

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

    【讨论】:

    • 仅供参考,std::ios_base::sync_with_stdio(false); 将关闭对标准流(如 cout)的操作必须像您对 stdio 库进行相应调用一样的行为。
    猜你喜欢
    • 2013-02-08
    • 1970-01-01
    • 2010-10-12
    • 2011-10-29
    • 2013-03-12
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    相关资源
    最近更新 更多