std::cerr doesn't wait for std::cout (when running CTest)

Question

The context

I wrote a logger printing messages for the user. Messages with level "debug", "info" or "warning" are printed in std::cout and messages with level "error" or "system_error" are printed in std::cerr. My program is not multi-threaded. I work under Linux openSUSE 12.3 with gcc 4.7.2 and CMake 3.1.0.

My problem

I discovered that sometimes, when an error message (printed in std::cerr) follows a long information message (printed in std::cout) and when the output is redirected to the file LastTest.log by CTest, the error message appears in the information message (look at the example below). I don't well understand this behaviour but I suppose a writing thread is launched for std::cout, then the code continues and another writing thread is lauched for std::cerr without waiting the first one is terminated.

Is it possible to avoid that without using only std::cout ?

I don't have the problem in the terminal. It only happens when CTest redirect the output to the LastTest.log file.

Note that my buffer is flushed. It's not a problem of std::endl coming after the call to std::cerr !

Example

Expected behaviour :

[ 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

What happens :

[ 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

How I call my logger

Here is an example of how I call std::cout or std::cerr with my logger. I call the logger with maccros like that :

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

with

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

Here, the log chanel is the object dedicated to terminal output, the write function is :

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

You can see that my buffer is flushed when the log instruction is executed.

Torment

Yes, but the C++ instruction printing the error message in std::cerr come after the instruction printing the last std::endl in std::cout. – Torment

Does anything change if you issue std::ios_base::sync_with_stdio(false); at the beginning of your program? – Occasional

@Hurkyl: sync_with_stdio is completely a different thing. – Bora

@Nawaz: Probably. But hard-to-find bugs usually occur in places where you've convinced yourself there can't be a bug to find, and this is an easy thing to test. (also, it makes the statement "cout is buffered" actually correct; in the implementations I've seen, cout usually isn't buffered at all with synchronization on; buffering is delegated to the stdio library) – Occasional

@Hurkyl: In that case, the bug would be in the library itself. – Bora

@caduchon please post your code, then we wouldn't all have to be guessing here – Angulate

@Nawaz: Actually, my bet is currently on redirection in Linux doing something surprising, and the main point of my comment is to eliminate interactions between Linux and how the stdio library gets set up. (also... sometimes there really are bugs in the library) – Occasional

I posted my code as an edit. – Torment

Can you show how you are having CTest redirect cout and cerr both to the file? Can you make the problem happen without using CTest? – Bismuth

CTest produces a log file with the std outputs of each executable test. I can't say more about that. I can't reproduce without CTest, even by calling the same test with > Test.log 2>&1. – Torment

So the problem is with CTest, and your title is misleading. I missed the two references to CTest completely on my first skim read, so it might be worth making them more prominent. – Deirdre

You're right. It wasn't clearly identified when I wrote my question. Correction done. – Torment

Answer 1

Answering my own question

Finally, it comes from a bug in CMake.

CTest is not able to manage the order of the two buffers, and then doesn't care about the exact order of the output.

It will be resolved in CMake >= 3.4.

Torment

Answer 2

I've seen this behavior before in a few forms. The central idea is to remember that std::cout and std::cerr write to two completely separate streams, so any time you see the output from both in the same place, it's because of some mechanism outside of your program that merges the two streams.

Sometimes, I see this simply due to a mistake, such as

myprogram > logfile &
tail -f logfile

which is watching the logfile as it's written, but forgot to redirect stderr to the logfile too, so writes to stdout go through at least two additional layers of buffering inside tail before getting displayed, but writes to stderr go directly to the tty, and so can get mixed in.

Other examples I've seen involve an external process merging streams. I don't know anything about CTest but maybe it's doing this. Such processes are under no obligation to sort lines by the exact time at which you originally wrote them to the stream, and probably don't have access to that information even if they wanted to!

---

You really only have two choices here:

• Write both logs to the same stream — e.g. use std::clog instead of std::cout or std::cout instead of std::cerr; or launch the program with myprogram 2>&1 or similar
• Make sure the merging is done by a process that is actually aware of what it's merging, and takes care to do it appropriately. This works better if you're communicating by passing around packets containing logging events rather than writing the formatted log messages themselves.

Occasional

Actually, I have no control on how CTest launch the executable and redirect the output. I will try with std::clog, I never used it, it could be a good solution. – Torment

Answer 3

I'm not a C++ expert, but this might help...

I believe that the issue you are seeing here, when redirecting to a file, is caused by the cstdio library trying to be smart. My understanding is that on Linux, the C++ iostreams ultimately send their output to the cstdio library.

At startup, the cstdio library detects if you are sending the output to a terminal or to a file. If the output is going to the terminal then stdio is line buffered. If output is going to a file then stdio becomes block buffered.

Output to stderr is never buffered, so will be sent immediately.

For solutions you could possibly try using fflush on stdout, or you could look into using the setvbuf function on stdout to force line buffered output (or even unbuffered output if you like). Something like this should force stdout to be line buffered setvbuf(stdout, NULL, _IOLBF, 0).

Matthieu

FYI, std::ios_base::sync_with_stdio(false); will turn off the behavior where operations on the standard streams (like cout) must behave as if you made the corresponding calls to the stdio library. – Occasional