Crear sistema de Log para el Engine

[adrigm]

Sería bueno crear un archivo de Log que registre la actividad del engine, pero sin hacer uso de librerías externas y sin complicarlo demasiado.

[RdlP]

Yo puedo encargarme de eso si todo el mundo está de acuerdo

[adrigm]

@RdlP Claro, pero comenta primero como tienes pensado abordarlo para llegar a un consenso.

[adrigm]

Por si sirve, yo tenía pensado algo así: http://razonartificial.com/2011/09/creando-un-archivo-de-log-en-cpp/

Pero podemos ver propuestas e ideas.

[RdlP]

Pues había pensado en crear una clase LOG con distintos niveles de logging (Debug, Info y Error), y cada vez que se quiera registrar algo llamar a los métodos de dicha clase para realizarlo. Internamente se escribiría en un fichero de log.

P.D ahhh y permitir etiquetas a cada entrada que se guarde en el log

[adrigm]

@RdlP, de acuerdo, lo único a tener en cuenta es mantenerlo simple. Por lo demás vía libre,

[adrigm]

@RdlP, genial la clase log. Un par de cuestiones únicamente.

• Los mensajes de ERROR se pegaban a la fecha, faltaba un espacio (ya está arreglado ;))
• Quizás podríamos que hacer que init reciba un parámetro std::string con el nombre del archivo, no sería más versátil?

[adrigm]

También se me ocurre añadir un separador visual entre secciones, ¿Quizás alguna forma de añadir una línea en blanco?

[RdlP]

Si, se puede hacer que reciba el nombre del fichero por parámetro y quedaría más versátil, la verdad que no he caído.

En cuanto a "separador visual entre secciones" te refieres a que si por ejemplo tenemos esto:

INFO: Prueba: Prueba1 INFO: Prueba: Prueba2 INFO: Prueba: Prueba3 ERROR: Prueba: error

Haya una separación entre los 3 primeros y el último?

[adrigm]

No, me refiero a entre sesiones. Yo ejecuto mi engine y se empieza a escribir el log con los mensajes que vaya generando, cierro la aplicación y vuelvo abrirla. Los mensajes de la nueva sesión se generan justo a continuación. Aquí hay dos opciones o limpiar el log entre sesiones de ejecución o hacer una separación visual entre sesiones.

[RdlP]

Vale, como habías dicho entre secciones me había liado, pues mañana por la tarde lo hago.

Yo opino que sea mejor una separación visual, para que el usuario pueda ver el log de sesiones anteriores, puede ser interesante si quiere buscar algo en concreto de una sesión anterior.

[adrigm]

@RdlP opino lo mismo, si en algún momento se necesita "limpiar" basta con que borre el fichero.

Otra cuestión: Esto para más adelante, pero habrá que tenerlo en cuenta. Quizás en modo Release convendría no generar el archivo ya que se supone que es para depurarlo el usario de la biblioteca (programador) no para que lo vea el usuario final. O se puede dejar a modo de que el usuario pueda ver si fallo algo.

[RdlP]

En ese caso yo creo que puede ser interesante mantener el log porque si alguien usa el engine y da fallo, bastaría decirle que abriese el log y nos mostrase la información, sino fuese así podría llegar a ser bastante difícil solucionar problemas que le ocurran al usuario final. Aunque sería bueno que opinasen los demás para ver sus puntos de vista.

[adrigm]

@RdlP, Esta línea:

strftime(buffer,20,"%D %T ",timeinfo);

Falla en tiempo de ejecución en Visual Studio. Voy a tratar de mirar que la pasa creo que es el formato.

[RdlP]

Aquí hay gente donde le da fallo el strftime:

http://connect.microsoft.com/VisualStudio/feedback/details/759720/vs2012-strftime-crash-with-z-formatting-code

Yo uso linux y no puedo comprobar el fallo que da. Con GCC funciona perfecto.

Edito: En vez de poner 20, tanto en buffer como en strftime prueba a poner un número mayor. 40 por ejemplo.

[adrigm]

Ya está corregido, el tema era que el compilador no usaba las cadenas de formato más modernas (bravo Microsoft ¬¬).

Las que están en amarillo de esta lista no son compatibles: http://www.cplusplus.com/reference/ctime/strftime/

Las he sustituido por cadenas equivalentes, me he permitido de paso cambiar el formato de la fecha para que salga al modo español, es decir, el día antes que el mes.

[RdlP]

joder, hay que tener buen ojo para ver el amarillo ahí, lo que me ha costado verlo... Bueno pues un error solucionado entonces.

[angelnavarro]

Buenas tardes,

No tengo experiencia en C++ y por tanto no sé cuanto de costoso sería hacerlo, pero en Java tenemos la librería Log4j para generar logs. Lo comento en relación a poner Logs en tiempo de Desarrollo, Release.

Esta librería tiene, como ha comentado @RdlP, varios métodos de log en función de la prioridad (debug, info, warn, error) y tú desde tu código llamas evidentemente al que consideres necesario. Externo al código tienes la configuración del logging, donde le dices que mensajes se pintaran. Por ejemplo, en este proyecto se podría poner que para Desarrollo se imprimiese todo y para Release sólo los mensajes Error o Warn. La configuración podría ser tan simple como un parámetro en el archivo .ini.

Saludos,

[danigomez]

@angelnavarro Yo creo que es posbile de hacer, directamente en el constructor de la clase Log cargar los valores de inicialización y luego obviamos aquellos tipos de log que no se encuentran en la configuración.

[RdlP]

Eso implicaría que cualquier persona pueda modificar el archivo .ini y elegir que nivel de logging quiere. Estoy de acuerdo en que la idea es buena, pero quizá no tanto la realización de la misma.

Por mi parte voto por poner una constante que indique si estamos en modo release o en modo debug y dependiendo de donde nos encontremos actuar en consecuencia.

Una cosa que no se es si hay alguna macro interna que nos indique si estamos en modo Release o Debug, en ese caso no haría falta usar una constante/variable podríamos usar la macro que nos ofrece el Debug mode

[danigomez]

@RdlP Si me parece que es más conveniente usar una constante interna para evitar que cualquiera lo modifique, luego se puede indicar también, a partir de si estamos en Debug o Release que tipo de log se quiere mostrar como dijo @angelnavarro, no simplemente loggear en Debug y no loggear en Release.

[angelnavarro]

Bueno, no sé exactamente como se llama (me tengo que poner las pilas con C y C++), pero sé que en C se pueden definir "constantes" en tiempo de compilación, ¿verdad?. Disculpad que no sepa exactamente como se llaman pero creo que se podían consultar con las directivas del preprocesador, con #IFDEF, etc. Eso podría resolverlo si compilamos Debug con un valor y Release con otro. ...... Edito: Acabo de recordar que esto se hacía pasando parámetros a GCC, por lo que entiendo que podría ser algo exclusivo de este compilador

Saludos,

[adrigm]

La constante de debug es GDE_DEBUG para usarla hay que hacer lo siguiente:

#ifdef GDE_DEBUG
// algo en modo debug solamente
#endif

Está definida en el fichero config.hpp

[RdlP]

Se podría usar algo como lo siguiente

define DEBUG TRUE

y luego a la hora de que mensajes loggear usar

if DEBUG == TRUE

Imprimir todo

else

imprimir errores solo

Lo que yo vengo a decir es que no se si el proyecto define alguna macro DEBUG ya, en ese caso sería muy simple.

Edito: Vale, perfecto adrian, pues mañana veré que puedo hacer con eso

[ficion]

Noté que en src/GDE/Core/Log.cpp, el código en las funciones para loguear es básicamente el mismo:

std::ofstream logFile(Log::logFileName.c_str(), std::ofstream::app);
time (&rawtime);
char buffer [20];
struct tm * timeinfo;
timeinfo = localtime (&rawtime);
strftime (buffer,20,"%d/%m/%y %X ",timeinfo);
logFile << buffer << "ERROR: " << tag << ": " << text << std::endl;
logFile.close();

Ahora, no he programado nunca en C++ (por ahora no, que me trato de concentrar en C solamente), pero, por lo que sé, los programadores de C++ tienden a ser muy quisquillosos con el uso de macros, por alguna razón. Yo pienso que en ciertos casos ayuda mucho a la legibilidad y este sería un caso. Se usa el mismo código, cambiando solamente un término. Quizá se puede definir un macro así:

#define LOGSTEP(qry) do \
{ \
std::ofstream logFile(Log::logFileName.c_str(), std::ofstream::app); \
time (&rawtime); \
char buffer [20]; \
struct tm * timeinfo; \
timeinfo = localtime (&rawtime); \
strftime (buffer,20,"%d/%m/%y %X ",timeinfo); \
logFile << buffer << qry ": " << tag << ": " << text << std::endl; \
logFile.close(); \
} while(0)

(Importante notar que no se trata de un macro que deba salir del archivo Log.hpp o Log.cpp; se debe hacer un #undef LOGSTEP al final del archivo Log.cpp.) Entonces en los tres casos se puede usar (cada uno en la correspondiente función, por supuesto):

LOGSTEP("INFO");
LOGSTEP("DEBUG");
LOGSTEP("ERROR");

No sé qué les parece, para mí eso quedaría bien... Quizá hasta sirva como un ejemplo claro para los todavía más nuevos, sobre uso de macros. :wink: (Por favor no me flameen)

---

Quizá una pequeña cosa que me gustaría proponer (pequeño detalle), que al principio de cada entrada del log, en vez de INFO, DEBUG y ERROR, se usaran INF, DBG y ERR. Esto porque los tres primeros términos tienen 4, 5 y 5 letras, mientras que los últimos tres, tienen 3 (lo cual los deja uniforme), que de paso es más corto. Ojo, que incluso pienso que sería mejor usar algo como I, D y E, simplemente porque se repetirán mucho en el log. Bueno, cosa pequeña.

[RdlP]

No logro entender tu planteamiento de las macros (que tiene un problema intrínseco que luego comentaré). Dices de usar una macro parecida a la que has puesto y llamarla de la siguiente forma:

LOGSTEP("INFO");
LOGSTEP("DEBUG");
LOGSTEP("ERROR");

Supongo que habría que pasarle también el tag y el text ¿no?

El problema que yo veo con las macros es que allá donde llames a la macro lo que se hace es sustituir el nombre de la macro por toda la macro, si se va a llamar muchas veces a las funciones de Log aumentará considerablemente el tamaño del fichero resultante (hablo del GDE no del log). Las macros se suelen usar con tareas más cortas y si son largas que no sean llamadas con tanta frecuencia.

Por otra parte veo bien lo de reducir Error, Debug e Info a tres caracteres, pero no a uno ya que para la gente que use el motor un carácter podría ser poco explicativo.

[danigomez]

@ficion No estoy entendiendo por qué has usado un bucle en la macro, no terminaria nunca de ejecutarse... En lo que si estoy de acuerdo es en utilizar un método común para hacer el log, ya que como has dicho los tres métodos son básicamente iguales, tan solo cambia el encabezado del log , es decir el string ERROR, DEBUG e INFO, por lo que bien podria hacerse un método que reciba los valores que están hardcodeados para poder llamarlo desde los otros

 void Log::log(std::string tag, std::string text, std::string logType)
    {
         if (!initialized)
        {
            std::cout << "El sistema de log no ha sido inicializado, por favor, inicielo mediante GDE::Log::init()" << std::endl;
            return;
        }
        std::ofstream logFile(Log::logFileName.c_str(), std::ofstream::app);
        time (&rawtime);
        char buffer [20];
        struct tm * timeinfo;
        timeinfo = localtime (&rawtime);
        strftime (buffer,20,"%d/%m/%y %X ",timeinfo);
        logFile << buffer << logType << ": " << tag << ": " << text << std::endl;
        logFile.close();

    }

luego en cada método hacer :

void Log::error(std::string tag, std::string text)
{
    Log::log(tag, text, ERRH);
}

[RdlP]

Estoy de acuerdo en lo que ha dicho @LeonardoJegigzem

[ficion]

@RdlP La idea del macro es simplemente para ayudar un poco a la legibilidad (quizá), porque se repite el mismo código cambiando solamente una cadena y para mí eso es algo redundante. Quizá no sea tan bueno usarlo, porque el macro sólo será usado tres veces, y sólo en ese archivo, pero me gusta probar...

Y no, el macro no es como una función, el macro simplemente es reemplazo de texto en la misma linea. Aún cuando parece una función, es más limitada (a veces). Ojo, que los macros se expanden una vez: antes de empezar el proceso de compilación, el preprocesador actúa sobre el archivo y expande todos los macros, es casi como si hubiésemos escrito todas esas instrucciones ahí mismo (de hecho, cuando termine de actuar el preprocesador, será así). Lo que ayuda esto, es que, cuando se hace lo de llamar una función dentro de otra, dentro de otra, dentro de otra, puede pasar algo llamado function overhead, que reduce el rendimiento. Para esto a veces se propone que se use la keyword inline, pero esta función no es candidata para eso.

En todo caso, el function overhead no es lo que me preocupa; llamar a otra función, como @LeonardoJegigzem dice, quizá sea mucho mejor, porque no afectará en nada el rendimiento en este caso.

@LeonardoJegigzem Pareciera como si fuera un bucle infinito (yo igual lo pensé la primera vez que vi uno), pero pone while(0), osea que todo eso se ejecuta una sola vez. :) La razón de esto, es que si se pone en un condicional if else que no use {} ni do {...} while(0), el macro se expande así (si no tuviera el bucle):

if (x < 4)
    LOGSTEP("INF");
else
    [...]
    ==>
        if (x < 4)
            std::ofstream logFile(Log::logFileName.c_str(), std::ofstream::app);
            time (&rawtime);
            char buffer [20];
            struct tm * timeinfo;
            timeinfo = localtime (&rawtime);
            strftime (buffer,20,"%d/%m/%y %X ",timeinfo);
            logFile << buffer << "INF: " << tag << ": " << text << std::endl;
            logFile.close();
        else
            [...]    

Como ves, lo que parecía una inocente función hace que ese else quede inválido. Ahora, esto claramente se puede solucionar siendo cautos (colocando {} antes del nombre del macro, o definir el macro encerrado en un bloque {}; encerrar en bloques el contenido de los if else; etc), pero queda mejor así. La razón de que sea ese bucle, es que a muchos también les tienta colocar el ; final (si te fijas, si se usan {}, el ; no es necesario y se toma como una expresión nula, lo cual también rompe los condicionales ìf else sin bloque).

Perdón por escribir tanto (aún creo que no sé hacerme explicar bien, pero bueno...).

[danigomez]

@ficion uups, por alguna razón mi cerebro que me dijo que 0 == true jaja, claro, ahora que planteas el caso de que no se usen las llaves tiene sentido!

[RdlP]

@ficion vale, ya se lo que querías decir, ahora si que le veo sentido, aún así creo que es complicar bastante el fichero para la gente novata, a la cual el preprocesador le resulta lejano, lejos de usarlo para alguna tarea simple. Eso no quiere decir que el mecanismo sea complejo, pero pienso que a la gente nueva le puede costar entenderlo.

Yo creo que sería mejor como comenta @LeonardoJegigzem pero bueno, que opine más gente y según se vea se hace una cosa u otra.

[ficion]

@RdlP En eso tienes razón; ni hablar de cómo se definen los macros, que queda horrible y a veces no se ve qué hace.

@LeonardoJegigzem Ese método lo usan en el kernel de Linux también. Deberías proponer un commit con tu idea aplicada, ¿no crees?

[adrigm]

Creo que el uso de macros con el preprocesador se debe limitar al máximo, he hecho algunos cambios para usar un enumerado de logs definido en el archivo CoreTypes.hpp. Si se necesitan más niveles se pueden añadir fácilmente.

[RdlP]

Volviendo al tema del Log, como han comentado @LeonardoJegigzem y @angelnavarro sería interesante limitar los log tipo DBG que aparezcan en el fichero, ya que eso sería información de depuración para nosotros.

Como se ha comentado se podría hacer que en modo debug imprimiese todos los log y en modo release solo los log info y error, la forma de hacer esto podría ser con la macro GDE_DEBUG. ¿Qué opináis?

[adrigm]

Borrado comentario fuera de lugar.

Sí, yo me encargo de adaptar para que si impriman solo los mensajes de debug en el modo Debug.

[danigomez]

@adrigm Podriamos agregar un array con los encabezados del log para no tener que estar modificando constantemente el método log al agregar un nuevo tipo,

std::string header[] = {"INFO", "DEBUG", "ERROR"};`

Y tomar su valor según el enum que definiste:

logfile << header[logType]

Así solo haria falta modificar el enum y este array y no tocar el código de la clase Log. Si les parece bien, hago el cambio.

[adrigm]

Nos ahorraríamos el switch, sí.

Te encargas?

[danigomez]

Dale, hago el cambio entonces

[ArnauPrat]

Hola chicos, os doy mi opinion. Me he leido los comentarios un poco por encima, así que si discuto algo que ya está solucionado, disculpd. Yo haria lo siguiente. Creari el sistema de Logging, como una clase estática, accessible globalmente. Luego, definiria un conjunto de macros del estilo:

WARNING( texto ) //Aqui para avisos, que puedan darse en situaciones mas o menos graves, pero en las que el motor pueda seguir funcionando
DEBUG( texto ) //Aqui para información de debugging
ASSERT( texto, condicion) //Esta para mi es importantísima. Si salta esta el motor directamente deberia cerrar i dar un informe.
LOG( texto ) //Esta para información de Log, como por ejemplo estado de la inicializaciṕon del engine, recursos cargados etc...

Estas macros llamarian al sistema de logging. Las ventajas son varias. Primero ayuda en la legibilidad. Segundo, te abstrae del sistema de logging usado, y tercero te permite no incluir el código de loging si es necesario. Añadiria una o varias constantes de compilación, para poder activar/desactivar completamente el logging/debug/asserts/warning si es necesario, sin que éste genere ningun tipo de overhead. Luego, en el archivo de configuración del motor, poder configurar el nivel de verbose en el caso de que el motor se haya compilado con el logging activado.

Un Saludo.

[RdlP]

Me parece buena idea lo que comenta @ArnauPrat sobre el hecho de crear las macros que ha comentado, para evitar tener que escribir GDE::Log::info(). También creo que sería interesante añadir un nivel más de logging que en un principio lo pasé por alto, sería el de warning.

En lo que no estoy de acuerdo es en ASSERT( texto, condicion) pues no considero que esto deba formar parte del sistema de log, considero que esto forma más del control de errores del motor.

[adrigm]

Yo también pienso que los assert no deberían estar en el log. Por cierto, tenemos que ponernos las pilas con los assert que faltan en muchos sitios.

[rickyah]

@adrigm yo también opino que los asserts van fuera del log.

Por cierto, podríamos usar la función StringFormat que he creado para permitir mensajes de log con listas argumentos variable sería más potente. https://github.com/genbetadev/Genbeta-Dev-Engine/blob/master/include/GDE/Core/StringsUtil.hpp#L328

Lo ideal hubiera sido implementar streams, pero juntarlo con Macros para eliminar el código de log en builds de producción iba a ser un dolor

[InExtremaRes]

No sé si esto ha sido discutido pero, ¿por qué no se usaron streams y operator<< para hacer los logs? Creo que es una manera más "C++" de hacerse, permite sobrecargar operator<< para escribir nuevos tipos de datos y evita tener que crear muchas de las funciones de conversión a texto que hay en StringUtil.

Se podría hacer algo como lo siguiente:

GDE::Log::info("Etiqueta") << "texto" << 1234 << false;

En vez de:

GDE::Log::info("Etiqueta", "texto" + GDE::convertInt32(1234) + GDE::convertBool(false));

Al menos a mi me parece más claro, y se pueden usar manipuladores para que se deje un espacio automáticamente entre argumentos.

Si les parece bien, podría crear un nuevo issue y ofrecerme para modificar (en realidad re-escribir) la clase de Logs.

[rickyah]

Ojo, la idea del log es poder encapsularlo en una macro y en producción poder eliminar el código de log completamente, por que aunque el lob no escribiera a disco/consola/lo_que_sea las manipulaciones de strings siguen estando ahí (y los strings, que también ocupan) Así que lo que habría que hacer es algo como LOG_INFO("Etiqueta" << "texto" << 1234 << false);

Que se sustituiría por algo como: GDE::Log::info << "Etiqueta" << "texto" << 1234 << false;

Puestos a usar streams, lo mejor en mi opinión es directamente exponer los streams de datos (info, warn) en vez de hacer una llamada.

Sin embargo, lo que hay ahora yo creo que vale de momento. Quiero decir que mejor usar streams porque es más fácil hacer el formato, sin embargo no es lo más prioritario.

[RdlP]

En un principio pensé en hacer la implementación con streams pero tenía una duda. La redefinición del operador << se hace sobre un objeto, pero sin embargo GDE::Log::info es un método de un objeto y por tanto no sabía si la redefinición del oprador << se podría aplicar a métodos.

Además en la propuesta de arriba "Etiqueta" puede ser cualquier cosa y la idea era permitir solo unas determinadas etiquetas (debug, info, warning, error...)

Así que la decisión de hacerlo así y no con streams fue básicamente por ignorancia.

[InExtremaRes]

Hace un tiempo creé una clase de este estilo para otro proyecto, en donde se usaban streams para escribir a algún lado y si se definía una macro del tipo NODEBUG se omitía completamente la generación de logs.

El truco está en no exponer los streams directamente, si no que abstraerlos con una llamada a función tal como mostré en el ejemplo anterior. Básicamente, si una macro de no_depuración está definida, la llamada a la función se reemplaza por un objeto que absorbe todos los argumentos de operator<< sin hacer nada con ellos; ningún manejo de cadena es realizado, solo se mantiene la llamada a la función (que el compilador puede optimizar inline) lo cual es un costo bastante despreciable. Esto es similar a lo que hace Qt con su clase QDebug y sus funciones qDebug() ,qWarning(), etc.

Si bien es cierto lo que comentas @rickyah, que no es la más prioritario, tener una forma sencilla de dar formato a los logs y tener la posibilidad de extenderlo sobrecargando un método me parece un buen paso antes de que luego sea más difícil de cambiar.

[danigomez]

Cómo se implementaria esto de los streams para cada tipo de log?? Con clases anidadas?? , me refiero a còmo harian para manejar la sobrecarga de << para cada tipo de log??

[RdlP]

Cuando pensé inicialmente hacer el log con streams y poder elegir distintos niveles de log pensé en hacer una clase con un método virtual puro y que fuesen las hijas las que implementasen la clase, de esta manera se podrían conseguir distintos niveles de loging (debug, error, warning e info) pero me pareció bastante complejo, así que por eso y por mi comentario de arriba opté por esta opción

[InExtremaRes]

@RdlP, tienes razón que operator<< solo se puede sobrecargar en un objeto y no en un método. El truco que usa Qt es utilizar una función qDebug() que retorna un objeto temporal de tipo QDebug que sí tiene <<. El objeto temporal manipula las cadenas y escribe en el registro en su destructor.

@LeonardoJegigzem, Para cada tipo de log se crean nuevas funciones: info, warning, error, etc, que crean un objeto con un parámetro distinto en el constructor, que indica el nivel. Es el destructor quien se encarga de escribir el stream, muy similar a lo que actualmente hace el método Log::log().

[rickyah]

@RdlP lo que puedes hacer es que info sea una propiedad de la clase GDE::Log. Una propiedad estática en este caso, y eso ya sería un objeto, con lo que puedes sobrecargar lo que quieras

@InExtremaRes Es precisamente el problema que estoy diciendo. Si tienes un objeto stream nulo que no hace nada seguimos teniendo pérdida de rendimiento, ya que se siguen realizando cosas innecesarias, como llamadas a métodos (que es lo que en realidad es un operador), pasando el objeto stream nulo entre esas llamadas. Además indicas que GDE::Log::info() es además otra llamada que devuelve un objeto.

Y como he dicho, los strings y elementos declarados se quedarían en el ejecutable, ocupando espacio innecesariamente, no te digo más si además el compilador le mete un incline, ahorramos la indirección de la llamada a función pero le metemos peso al ejecutable.

A mi me parece que la solución más elegante es una macro que elimine el código totalmente, es lo que he visto en engines.

[rickyah]

Para que nos entendamos, podríamos hacer algo así:

LOG_INFO("hola" << "mundo"); que lo que haría sería sustituir se por esto en debug o build con log activado: GDE::Log::info << "hola" << "mundo";

y por esto en builds sin log:

:)

Si no queréis hardcodear los tipos de log asociados a la macro (info, warn, etc) entonces se podría hacer algo como: LOG(GDE::LogLevel::Info, "hola" << "mundo");

Y se sustituye por

GDE::Log::log(GDE::LogLevel::Info, "hola" << "mundo");