title: std::cerr doesn't wait for std::cout (when running CTest)
body: <h2>The context</h2>
  
  <p>I wrote a logger printing messages for the user. Messages with level "debug", "info" or "warning" are printed in <code>std::cout</code> and messages with level "error" or "system_error" are printed in <code>std::cerr</code>. My program is not multi-threaded. I work under Linux openSUSE 12.3 with gcc 4.7.2 and CMake 3.1.0.</p>
  
  <h2>My problem</h2>
  
  <p>I discovered that sometimes, when an error message (printed in <code>std::cerr</code>) follows a long information message (printed in <code>std::cout</code>) and when the output is redirected to the file <code>LastTest.log</code> 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 <code>std::cout</code>, then the code continues and another writing thread is lauched for <code>std::cerr</code> without waiting the first one is terminated.</p>
  
  <p><strong>Is it possible to avoid that without using only <code>std::cout</code> ?</strong></p>
  
  <p>I don't have the problem in the terminal. It only happens when CTest redirect the output to the <code>LastTest.log</code> file.</p>
  
  <p><em>Note that my buffer is flushed. It's not a problem of <code>std::endl</code> coming after the call to <code>std::cerr</code> !</em></p>
  
  <h2>Example</h2>
  
  <h3>Expected behaviour :</h3>
  
  <pre><code>[ 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
  </code></pre>
  
  <h3>What happens :</h3>
  
  <pre><code>[ 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
  </code></pre>
  
  <h2>How I call my logger</h2>
  
  <p>Here is an example of how I call <code>std::cout</code> or <code>std::cerr</code> with my logger.
  I call the logger with maccros like that :</p>
  
  <pre><code>#define LOG_DEBUG(X) {if(Log::debug_is_active()){std::ostringstream o;o&lt;&lt;X;Log::debug(o.str());}}
  #define LOG_ERROR(X) {if(Log::error_is_active()){std::ostringstream o;o&lt;&lt;X;Log::error(o.str());}}
  //...
  LOG_DEBUG("This" &lt;&lt; std::endl &lt;&lt; "is" &lt;&lt; std::endl &lt;&lt; "a message");
  LOG_ERROR("at line " &lt;&lt; __LINE__ &lt;&lt; " : " &lt;&lt; err_id);
  </code></pre>
  
  <p>with</p>
  
  <pre><code>void Log::debug(const std::string&amp; msg)
  {
      Log::write_if_active(Log::DEBUG, msg);
  }
  void Log::error(const std::string&amp; msg)
  {
      Log::write_if_active(Log::ERROR, msg);
  }
  //...
  void Log::write_if_active(unsigned short int state, const std::string&amp; msg)
  {
      Instant now;
      now.setCurrentTime();
      std::vector&lt;std::string&gt; lines;
      for(std::size_t k = 0; k &lt; 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 &lt; Log::chanels.size(); ++i)
          if(Log::chanels[i])
              if(Log::chanels[i]-&gt;flags &amp; state)
                  Log::chanels[i]-&gt;write(state, now, lines);
  }
  </code></pre>
  
  <p>Here, the log chanel is the object dedicated to terminal output, the write function is :</p>
  
  <pre><code>void Log::StdOut::write(unsigned short int state, const Instant&amp; t, const std::vector&lt;std::string&gt;&amp; lines)
  {
      assert(lines.size() &gt; 0 &amp;&amp; "PRE: empty lines");
      std::string prefix =  "[ ";
      if(this-&gt;withDate || this-&gt;withTime)
      {
          std::string pattern = "";
          if(this-&gt;withDate)
              pattern += "%Y-%m-%d ";
          if(this-&gt;withTime)
              pattern += "%H:%M:%S.%Z ";
          prefix += t.toString(pattern);
      }
      std::ostream* out = 0;
      if(state == Log::TRACE)
      {
          prefix += "  TRACE";
          out = &amp;std::cout;
      }
      else if(state == Log::DEBUG)
      {
          prefix += "  DEBUG";
          out = &amp;std::cout;
      }
      else if(state == Log::INFO)
      {
          prefix += "   INFO";
          out = &amp;std::cout;
      }
      else if(state == Log::WARNING)
      {
          prefix += "WARNING";
          out = &amp;std::cout;
      }
      else if(state == Log::ERROR)
      {
          prefix += "  ERROR";
          out = &amp;std::cerr;
      }
      else if(state == Log::SYS_ERROR)
      {
          prefix += "SYERROR";
          out = &amp;std::cerr;
      }
      else
          assert(false &amp;&amp; "PRE: Invalid Log state");
      prefix += " ] ";
      (*out) &lt;&lt; prefix &lt;&lt; lines[0] &lt;&lt; "\n";
      prefix = std::string(prefix.size(), ' ');
      for(unsigned long int i = 1; i &lt; lines.size(); ++i)
          (*out) &lt;&lt; prefix &lt;&lt; lines[i] &lt;&lt; "\n";
      out-&gt;flush();
  }
  </code></pre>
  
  <p>You can see that my buffer is flushed when the log instruction is executed.</p>