c++ - plus - iostream doc

std:: cerr no espera a std:: cout(cuando se ejecuta CTest)

Question

El contexto

Escribí un registrador imprimiendo mensajes para el usuario. Los mensajes con nivel "depuración", "información" o "advertencia" se imprimen en std::cout y los mensajes con nivel "error" o "system_error" se imprimen en std::cerr . Mi programa no es multiproceso. Trabajo bajo Linux openSUSE 12.3 con gcc 4.7.2 y CMake 3.1.0.

Mi problema

Descubrí que a veces, cuando un mensaje de error (impreso en std::cerr ) sigue a un mensaje de información largo (impreso en std::cout ) y cuando la salida se redirige al archivo LastTest.log por CTest, el mensaje de error aparece en El mensaje de información (mira el ejemplo de abajo). No entiendo bien este comportamiento, pero supongo que se inicia un hilo de escritura para std::cout , luego el código continúa y otro hilo de escritura se lanza para std::cerr sin esperar a que std::cerr el primero.

¿Es posible evitar eso sin usar solo std::cout ?

No tengo el problema en la terminal. Solo sucede cuando CTest redirige la salida al archivo LastTest.log .

Tenga en cuenta que mi búfer está vaciado. No es un problema de std::endl después de la llamada a std::cerr !

Ejemplo

Comportamiento esperado:

[ 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

Lo que pasa :

[ 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

Como llamo a mi logger

Este es un ejemplo de cómo llamo a std::cout o std::cerr con mi registrador. Llamo al registrador con maccros así:

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

con

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

Aquí, el canal de registro es el objeto dedicado a la salida del terminal, la función de escritura es:

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

Puede ver que mi búfer se vacía cuando se ejecuta la instrucción de registro.

Answer 1

He visto este comportamiento antes en algunas formas. La idea central es recordar que std::cout y std::cerr escriben en dos flujos completamente separados , por lo que cada vez que vea la salida de ambos en el mismo lugar, es debido a algún mecanismo fuera de su programa que combina los dos arroyos

A veces, veo esto simplemente debido a un error, como

myprogram > logfile &
tail -f logfile

que está viendo el archivo de registro como está escrito, pero se olvidó de redirigir stderr al archivo de registro también, así que las escrituras en stdout pasan por al menos dos capas adicionales de almacenamiento en búfer dentro de la tail antes de mostrarse, pero las escrituras en stderr van directamente al tty, y así se puede mezclar en.

Otros ejemplos que he visto involucran un proceso externo que combina flujos. No sé nada acerca de CTest pero tal vez esté haciendo esto. Dichos procesos no tienen la obligación de ordenar las líneas según la hora exacta en que originalmente las escribió en el flujo, y probablemente no tengan acceso a esa información, ¡incluso si lo quisieran!

Realmente solo tienes dos opciones aquí:

• Escriba ambos registros en la misma std::cerr ; por ejemplo, use std::clog lugar de std::cout o std::cout lugar de std::cerr ; o myprogram 2>&1 el programa con myprogram 2>&1 o similar
• Asegúrese de que la fusión se realice mediante un proceso que sea realmente consciente de lo que se está fusionando y que se encargue de hacerlo de manera apropiada. Esto funciona mejor si se está comunicando pasando paquetes que contienen eventos de registro en lugar de escribir los mensajes de registro formateados.

Answer 2

No soy un experto en C ++, pero esto podría ayudar ...

Creo que el problema que está viendo aquí, al redirigir a un archivo, se debe a que la biblioteca cstdio intenta ser inteligente. Mi entendimiento es que en Linux, los iostreams de C ++ finalmente envían su salida a la biblioteca cstdio.

En el inicio, la biblioteca cstdio detecta si está enviando la salida a un terminal o a un archivo. Si la salida va a la terminal, entonces stdio tiene búfer de línea. Si la salida va a un archivo, entonces stdio se convierte en bloque en búfer.

La salida a stderr nunca se almacena en búfer, por lo que se enviará de inmediato.

Para las soluciones, podría intentar usar fflush en la fflush , o podría considerar usar la función setvbuf en la setvbuf para forzar la salida con búfer de línea (o incluso la salida sin búfer si lo desea). Algo así debería hacer que stdout sea setvbuf(stdout, NULL, _IOLBF, 0) búfer de línea setvbuf(stdout, NULL, _IOLBF, 0) .

Answer 3

Respondiendo a mi propia pregunta

Finalmente, viene de un error en CMake .

CTest no puede administrar el orden de los dos búferes, y luego no le importa el orden exacto de la salida.

Se resolverá en CMake> = 3.4.