sábado, 27 de diciembre de 2014
domingo, 22 de junio de 2014
Skylog cómo escribir un Syslog en C - pt.3
Estamos de vuelta aquí. Espero que no hayáis contenido el aliento esperando este post, como os había recomendado aquí. En caso de que lo hayáis hecho dudo que estéis en condición de seguir leyendo... ¿dónde nos habíamos quedado? (Uh, ha pasado mucho tiempo)... Ah, sí, ésta es la secuela de Quantum of Solace (¿o era Quantum of Syslog?), Así que para aquellos que no lo han visto, el título es Skyfall (¿o Skylog?).
En el primer y segundo episodio vimos el header mylog.h, el utilizador main.c y el file de implementación mylog.c. Para completar este ultimo, sólo faltaba escribir la función local getDateUsec(), que es exactamente lo que vamos a hacer.
De hecho, una versión simplificada de nuestro Syslog podría contener una función como esta:
El primer ejemplo que me viene a la mente, sin necesidad de recurrir al Software para sistemas hard-realtime, es el siguiente: imaginaros haber escrito un socket-server y un client de prueba y probarlos en la misma máquina (éste es un escenario real en el que se aprovecha el echo de contar con una base de tiempo común para servidor y cliente). Durante la etapa de depuración os dais cuenta de que en una fase operativa (típicamente la inicial) algún mensaje se pierde en el camino. Analizáis los dos log disponibles (servidor y cliente) y no conseguís averiguar cuál es el primer par de mensajes que no se sincroniza, ya que muchos mensajes parecen empezar en el mismo segundo. Ahí está: con la precisión del microsegundo podréis entender mejor lo que está pasando (este es un caso real que me ha pasado en el trabajo, ¡no me estoy inventando nada!).
Uff, por fin podemos dar por acabada la trilogía de Syslog. Espero que algo del Software descrito os pueda ser útil en el futuro. Ah, se me olvidaba: "Me llamo Log, James Log".
¡Hasta el próximo post!
 |
| Pero, ¿dónde estamos? ¿Esto no era un Blog de programación? |
De hecho, una versión simplificada de nuestro Syslog podría contener una función como esta:
Una función así es, en la mayoría de los casos, más que suficiente para añadir la hora a nuestras lineas de log. El resultado final en el file log.log (descrito aquí) sería así:/* getDate() * Genera un string con fecha y hora. */ static char *getDate(char *dest, size_t size) { // get time time_t t = time(NULL); struct tm *tmp = localtime(&t); // format cadena de destino dest (alocada por el que llama la función) strftime(dest, size, "%Y-%m-%d %H:%M:%S", tmp); // return cadena de destino dest return dest; }
Pero nosotros somos como nuestro amigo Bond, necesitamos medios más sofisticados, por lo que vamos a utilizar una función como esta:2014-06-22 00:16:48 - esto es un msg de tipo 0 (el nivel impostado es 2) 2014-06-22 00:16:48 - esto es un msg de tipo 1 (el nivel impostado es 2) 2014-06-22 00:16:48 - esto es un msg de tipo 2 (el nivel impostado es 2)
que es muy similar a la anterior, pero también nos proporciona los microsegundos (como se describe justamente en los comentarios dentro de la función). La salida del file de log será de este tipo:/* getDateUsec() * Genera un string con fecha y hora (usa los microsegundos). */ static char *getDateUsec(char *dest, size_t size) { // get time (con gettimeofday()+localtime() en lugar de time()+localtime() para obtener los usec) struct timeval tv; gettimeofday(&tv, NULL); struct tm *tmp = localtime(&tv.tv_sec); // format cadena de destino dest (alocada por el que llama la función) y añade usec char fmt[128]; strftime(fmt, sizeof(fmt), "%Y-%m-%d %H:%M:%S.%%06u", tmp); snprintf(dest, size, fmt, tv.tv_usec); // return cadena de destino dest return dest; }
Vale, ya puedo oír los murmullos: "que exagerado, ¡hasta los microsegundos!" Repito: la versión simple es más que suficiente en la mayoría de los casos, pero, esforzándonos un poco, algún ejemplo en el que no puede ser útil una mayor precisión se encuentra.2014-06-22 00:17:16.921026 - esto es un msg de tipo 0 (el nivel impostado es 2) 2014-06-22 00:17:16.921150 - esto es un msg de tipo 1 (el nivel impostado es 2) 2014-06-22 00:17:16.921170 - esto es un msg de tipo 2 (el nivel impostado es 2)
El primer ejemplo que me viene a la mente, sin necesidad de recurrir al Software para sistemas hard-realtime, es el siguiente: imaginaros haber escrito un socket-server y un client de prueba y probarlos en la misma máquina (éste es un escenario real en el que se aprovecha el echo de contar con una base de tiempo común para servidor y cliente). Durante la etapa de depuración os dais cuenta de que en una fase operativa (típicamente la inicial) algún mensaje se pierde en el camino. Analizáis los dos log disponibles (servidor y cliente) y no conseguís averiguar cuál es el primer par de mensajes que no se sincroniza, ya que muchos mensajes parecen empezar en el mismo segundo. Ahí está: con la precisión del microsegundo podréis entender mejor lo que está pasando (este es un caso real que me ha pasado en el trabajo, ¡no me estoy inventando nada!).
Uff, por fin podemos dar por acabada la trilogía de Syslog. Espero que algo del Software descrito os pueda ser útil en el futuro. Ah, se me olvidaba: "Me llamo Log, James Log".
¡Hasta el próximo post!
domingo, 23 de febrero de 2014
Quantum of Syslog cómo escribir un Syslog en C - pt.2
Ok , a gran petición, publicamos una secuela de Casino Royale (¡oops! .. Syslog Royale ), donde el juego se hace muy difícil. Habíamos acabado con una pseudo-especificación de un sistema syslog-like, con, además, la anticipación de los datos que se quieren obtener. Ahora es el momento de la implementación real, y espero que alguien haya cogido mi invitación a escribir una versión suya esperando para este post (y no podeis decir que no os he dejado el tiempo...).
En el post anterior vimos el header mylog.h y el utilizador main.c, por tanto, con gran originalidad , el file de implementación lo llamaremos mylog.c. Vamos a verlo y analizarlo en secciones:
La segunda sección que encontramos es la de los "prototipos locales", que describe las funciones estáticas de este archivo, las que no deben ser exportadas a los utilizadores de mylog. En este caso, hay getDateUsec(), que describiremos mas adelante.
Luego tenemos la sección "variables locales", que son, globales al file. Sé que las globales son una maldición (como se describe aquí ), pero en algunos casos (como éste ) es difícil prescindir. Y, además, son estáticas al file, entonces nos vamos a sentir menos culpables. Las variables locales son dos: uno es un FILE* que describe el file de log (mylog_fp) , mientras que la otra (mylog_level) es un int que se utiliza para gestionar el nivel de log (que, como se ha visto en el post introductorio se establece en cuatro valores ).
Después nos trasladamos a la implementación real, y nos encontramos con las dos primeras de las tres funciones de nuestra librería, myOpenLog() y myCloseLog():
La otra función, myCloseLog() , se limita simplemente a liberar con fclose() el descriptor obtenido myOpenLog().
Y ahora llegamos al corazón del sistema di log: la función mylog():
Luego, utilizando la función de la familia stdarg, podemos manejar el mensaje que se mostrará (ver después de el comentario "compone logstr con argumentos múltiples") que utiliza un formato printf () (tal como se utiliza en main.c) . No voy a explicar cómo funcionan printf() y stdarg() (no es el tema de este post), sin embargo, se podría volver a ellas en el futuro ... por el momento, os remito a la larguísima documentación encontrable con San Google.
En este punto, la función termina escribiendo en el file de log (véase después del comentario “escribe logstr con la fecha+hora y flush datos") utilizando fprintf().
La última declaración es fflush(): ¿por qué? Ok , añade un overhead de I/O, pero un buen sistema de log debe garantizar la escritura inmediata del mensaje que acaba de componer, si no, en caso de crash del programa, o, más simplemente, en aplicaciones multi-proceso, es posible que, por extraño que parezca, lo mensajes tengan una orden temporal equivocada, que en fase de debug, pruebas o análisis de los resultados podría confundirnos.
¿Qué pensáis de la implementación? No está mal, ¿verdad? Bueno, obviamente, he hecho algunas simplificaciones, porque la idea básica es la de proponer ejemplos que tengan estilo y funcionalidad, y que, a continuación, se puedan mejorar añadiendo los controles que faltan (tipo verificar si el descriptor FILE* es válido antes de usarlo, etc.) . Lo importante es que la idea básica sea correcta y se puede utilizar como pista para productos reales. Probar en copiar y compilar todo, os aseguro que funciona (¡al igual que todos los ejemplos que propongo en el blog, eh!) .
En un futuro episodio hablaremos de la función local getDateUsec(), para terminar con broche de oro el tema. Como siempre, les invito a no contener la respiración esperando...
¡Hasta el próximo post!
 |
| Nuestra implementación es mejor que la tuya... |
#include <time.h> #include <sys/time.h> #include <stdarg.h> #include <stdio.h> #include "mylog.h" // prototipos locales static char *getDateUsec(char *dest, size_t size); // variables locales static FILE *mylog_fp; static int mylog_level;No voy a describir los include-files, que son , ni más ni menos, sólo lo que se necesitan. Parece obvio, pero es normal encontrar sources con muchos más include de lo necesario: no hacer daño, pero complican la interpretación visual del código. Acordaros de poner sólo lo que se necesitan.
La segunda sección que encontramos es la de los "prototipos locales", que describe las funciones estáticas de este archivo, las que no deben ser exportadas a los utilizadores de mylog. En este caso, hay getDateUsec(), que describiremos mas adelante.
Luego tenemos la sección "variables locales", que son, globales al file. Sé que las globales son una maldición (como se describe aquí ), pero en algunos casos (como éste ) es difícil prescindir. Y, además, son estáticas al file, entonces nos vamos a sentir menos culpables. Las variables locales son dos: uno es un FILE* que describe el file de log (mylog_fp) , mientras que la otra (mylog_level) es un int que se utiliza para gestionar el nivel de log (que, como se ha visto en el post introductorio se establece en cuatro valores ).
Después nos trasladamos a la implementación real, y nos encontramos con las dos primeras de las tres funciones de nuestra librería, myOpenLog() y myCloseLog():
Como se puede ver son muy simples: myOpenLog() abre con fopen() el file que se pasa en el argumento (la cadena fname), y establece el nivel de log con el valor que se pasa con el segundo argumento (int level). El file lo abriremos en modo append, ya que queremos un archivo de registro incremental, reservándonos de resetearlo cuando nos necesite./* myOpenLog() * Abre una conexión al logger myLog para un programa. */ void myOpenLog(const char *fname, int level) { // abre el logfile y set level mylog_fp = fopen(fname, "a"); mylog_level = level; } /* myCloseLog() * Cierra el descriptor usado para escribir al logger myLog. */ void myCloseLog() { // cierra el logfile fclose(mylog_fp); }
La otra función, myCloseLog() , se limita simplemente a liberar con fclose() el descriptor obtenido myOpenLog().
Y ahora llegamos al corazón del sistema di log: la función mylog():
La primera operación que realiza mylog() es testear el nivel de log: esto es crucial, ya que nos permite generar sólo los mensajes de nivel inferior o igual al fijado por myOpenLog(), lo cual también incluye la no generación de mensajes si mylog_level es MYLOG_NOLOG. Y en este último caso, la única operación que se realiza es el test en el if, por lo que, si decidimos no utilizar el sistema de log, la carga de CPU y sistema de I/O es prácticamente cero (¡estaba en las especificaciones del proyecto!) ./* myLog() * Genera un mensaje de log para el logger myLog. */ void myLog(int level, const char *format, ...) { // test nivel de log if (level <= mylog_level) { // compone logstr con argumentos múltiples va_list arglist; va_start(arglist, format); char logstr[128]; vsnprintf(logstr, sizeof(logstr), format, arglist); va_end(arglist); // escribe logstr con fecha+hora y flush datos char date[128]; fprintf(mylog_fp, "%s - %s\n", getDateUsec(date, sizeof(date)), logstr); fflush(mylog_fp); } }
Luego, utilizando la función de la familia stdarg, podemos manejar el mensaje que se mostrará (ver después de el comentario "compone logstr con argumentos múltiples") que utiliza un formato printf () (tal como se utiliza en main.c) . No voy a explicar cómo funcionan printf() y stdarg() (no es el tema de este post), sin embargo, se podría volver a ellas en el futuro ... por el momento, os remito a la larguísima documentación encontrable con San Google.
En este punto, la función termina escribiendo en el file de log (véase después del comentario “escribe logstr con la fecha+hora y flush datos") utilizando fprintf().
La última declaración es fflush(): ¿por qué? Ok , añade un overhead de I/O, pero un buen sistema de log debe garantizar la escritura inmediata del mensaje que acaba de componer, si no, en caso de crash del programa, o, más simplemente, en aplicaciones multi-proceso, es posible que, por extraño que parezca, lo mensajes tengan una orden temporal equivocada, que en fase de debug, pruebas o análisis de los resultados podría confundirnos.
¿Qué pensáis de la implementación? No está mal, ¿verdad? Bueno, obviamente, he hecho algunas simplificaciones, porque la idea básica es la de proponer ejemplos que tengan estilo y funcionalidad, y que, a continuación, se puedan mejorar añadiendo los controles que faltan (tipo verificar si el descriptor FILE* es válido antes de usarlo, etc.) . Lo importante es que la idea básica sea correcta y se puede utilizar como pista para productos reales. Probar en copiar y compilar todo, os aseguro que funciona (¡al igual que todos los ejemplos que propongo en el blog, eh!) .
En un futuro episodio hablaremos de la función local getDateUsec(), para terminar con broche de oro el tema. Como siempre, les invito a no contener la respiración esperando...
¡Hasta el próximo post!
Suscribirse a:
Entradas (Atom)