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!
lunes, 20 de enero de 2014
Syslog Royale cómo escribir un Syslog en C - pt.1
Al escribir software siempre se debe intentar ser profesionales, independientemente del uso del software que estamos escribiendo. Por ejemplo, no se puede olvidar de prever un buen sistema de log (hay, también, algunos profesionales de la programación que ni siquiera saben lo que es un buen sistema de log... pero esta es otra historia.)
Para agregar un log al nuestro software podemos ayudarnos con el sistema operativo, por ejemplo en UNIX y Linux tenemos Syslog que es muy flexible y que nos hace la vida más fácil. En el caso de no poder (o no querer) utilizar los recursos proporcionados por el OS podemos pensar de escribir nuestro propio sistema de log, como veremos más adelante en este post. Vamos a tratar de emular , más o menos, la sintaxis y la función de Syslog, tratando de hacer un producto sencillo pero de calidad, o sea un producto profesional, porque siempre tratamos de ser profesionales, tal vez sin llegar a los excesos de profesionalidad del protagonista del título.
Sea porque no quiero hacer un post muy largo (se convertiría en aburrido), que por seguir una especie de enfoque específica+implementación (adaptado a un C -Blog ), he dividido el post en dos partes: en la primera describiré, a modo de especifica funcional, el header file (mylog.h) y un ejemplo de uso (main.c). En la segunda entrega describiré la implementación real .
Vemos el header file, mylog.h:
Veamos ahora el ejemplo de uso, main.c:
Para hoy terminamos. Los mas trabajadores podrán, esperando la segunda parte, escribir su propia implementación, y luego compararla con la mía, pero la mía será seguramente mejor... (se aleja riendo).
¡Hasta el próximo post!
Para agregar un log al nuestro software podemos ayudarnos con el sistema operativo, por ejemplo en UNIX y Linux tenemos Syslog que es muy flexible y que nos hace la vida más fácil. En el caso de no poder (o no querer) utilizar los recursos proporcionados por el OS podemos pensar de escribir nuestro propio sistema de log, como veremos más adelante en este post. Vamos a tratar de emular , más o menos, la sintaxis y la función de Syslog, tratando de hacer un producto sencillo pero de calidad, o sea un producto profesional, porque siempre tratamos de ser profesionales, tal vez sin llegar a los excesos de profesionalidad del protagonista del título.
 |
| Me llamo Log, James Log |
Vemos el header file, mylog.h:
Simple y que se explica por sí mismo, ¿no? Nuestro producto se compone de tres funciones canónicas (abre, usa, cierra), y trabaja en niveles de gravedad (actualmente cuatro). Casi no hace falta explicar que, estableciendo un nivel, en el logfile aparecerán todos los mensajes de nivel de gravedad igual o mayor del nivel seleccionado. El nivel de NOLOG, luego, es básicamente una flag de inhabilitación que nos permite iniciar la aplicación sin logfile, para aligerar la ejecución: se supone que debe ser una inhabilitación real, es decir, la CPU y el sistema de I/O deben realimente trabajar menos sin el log habilitado.// niveles de mylog #define MYLOG_NOLOG -1 // ningún mensaje de log #define MYLOG_ERROR 0 // condición de errore #define MYLOG_WARNING 1 // condición de warning #define MYLOG_DEBUG 2 // mensaje de debug // prototipos globales void myOpenLog(const char *fname, int level); void myLog(int level, const char *format, ...); void myCloseLog();
Veamos ahora el ejemplo de uso, main.c:
Sencillo, ¿no? Ejecuto un test de argumentos con ejemplo de uso (usage...), y luego abro, uso, cierro, salgo. Mediante una línea de comandos como "mylog log.log 1", ¿como será el resultado? Creará un file "log.log" que contendrá las siguientes dos líneas:#include <stdio.h> #include <stdlib.h> #include "mylog.h" int main(int argc, char* argv[]) { // test argumentos if (argc != 3) { printf("mylog: wrong arguments counts\n"); printf("usage: mylog logfile loglevel [e.g.: mylog log.txt 1]\n"); return EXIT_FAILURE; } // open log: set logfname y loglevel (0=error/1=warning/2=debug; -1=nolog) myOpenLog(argv[1], atoi(argv[2])); // test mylog() myLog(MYLOG_ERROR, "esto es un msg de tipo %d (el nivel impostado es %d)", MYLOG_ERROR, atoi(argv[2])); myLog(MYLOG_WARNING, "esto es un msg de tipo %d (el nivel impostado es %d)", MYLOG_WARNING, atoi(argv[2])); myLog(MYLOG_DEBUG, "esto es un msg de tipo %d (el nivel impostado es %d)", MYLOG_DEBUG, atoi(argv[2])); // close log myCloseLog(); // exit return EXIT_SUCCESS; }
Añadimos detalles a la específica: usos sucesivos de la aplicación deben colgar líneas al logfile, ya que una clave fundamental de un log es mantener información de lo que pasa (y si cada vez reiniciamos el file la vamos a perder). Y si queremos empezar desde cero, podemos utilizar un otro filename, o borrar el viejo logfile antes de ejecutar. Otro detalle que llama la atención es que necesitamos, además de nuestros textos de traza, también informaciones horarias, tal vez muy precisas (en el ejemplo hay los microsegundos: en el próximo episodio explicaré por qué).2014-01-18 18:39:33.890271 - esto es un msg de tipo 0 (el nivel impostado es 1) 2014-01-18 18:39:33.890407 - esto es un msg de tipo 1 (el nivel impostado es 1)
Para hoy terminamos. Los mas trabajadores podrán, esperando la segunda parte, escribir su propia implementación, y luego compararla con la mía, pero la mía será seguramente mejor... (se aleja riendo).
¡Hasta el próximo post!
Suscribirse a:
Entradas (Atom)