A menudo cuando una centralita tiene alta carga, ver la consola o los logs que genera Asterisk en /var/log/asterisk/messages no es suficiente. Porque se genera gran cantidad de información, porque al tener muchas llamadas concurrentes seguir una llamada en concreto a través de saltos en un fichero es complicado, porque a medida que integramos más y más herramientas con Asterisk las llamadas ya no se controlan o se localizan en un único punto…

Lo que vamos a intentar es tener controlado el log de todo el sistema, incluyendo Asterisk, su dialplan, los agis y cualesquira herramientas que usemos. Los objetivos son claros:

• Tener todos los logs relevantes en un lugar unificado de tal forma que podamos seguir la pista a las llamadas o a los errores sin tener que hacer merges mentales de múltiples fuentes.
• Tener los logs marcados y clasificados de tal forma que podamos encontrar de forma cómoda y sencilla cualquier información puntual que necesitemos.
• Loguear todo lo que ocurre en la plataforma remotamente relacionado con el flujo de las llamadas y el correcto funcionamiento de las mismas.

En este post vamos a ver un ejemplo de cómo hacer esto con un criterio arbitrario. Se pretende que cualquira pueda adaptar este ejemplo a sus necesidades. En este ejemplo vamos a querer:

1. Los logs generales del sistema para ver que todo es correcto. Esto es, el syslog. Deberemos filtrar cúales de los servicios del sistema que loguean al syslog queremos ver y cuáles no.
2. Los logs relacionados con el flujo de una llamada. En este caso vamos a suponer que dialplan y agis.

Todo esto lo vamos a hacer a través del syslog del sistema y las opciones que nos brinda para filtrar y etiquetar los logs.  ¡Manos a la obra!

Logger de Asterisk

Asterisk tiene una herramienta para configurar los logs que genera. Se configura en el fichero logger.conf. En el fichero podemos configurar los niveles de log que queremos que asterisk muestre en consola, en el fichero messages y en el syslog. Independientemente de lo que habilitemos para consola y para el fichero messages -nunca hay suficientes logs- vamos a activar y configurar el logging a syslog de tal forma que asterisk loguee ahí los errores y los warnigs. No nos interesa más información porque el log de los flujos de llamada lo vamos a gestionar de forma manual a fin de tener la información que nosotros deseamos de una forma más limpia.

Como se puede ver, las dos primeras líneas hacen referencia al CLI y al log normal de Asterisk. La última línea, que es la que usaremos, indica a Asterisk que loguee los mensajes de severidad Error y Warning a syslog con la facility Local5. De esta forma ya podremos ver en el syslog errores de parseo, de los channels, si no hemos cerrado un paréntesis y demás. Pero no podremos seguir el flujo de las llamadas ya que no tenemos ni verbose ni debug.

Este sería un ejemplo de lo que aparece en syslog cuando se hace un dialplan reload de Asterisk:

Oct 16 09:51:35 callcenter asterisk[15238]: WARNING[15309]: pbx_config.c:2276 in pbx_load_config: No closing parenthesis found? 'Macro(setgroup-in'

En vez de ver todo el reload en la consola con todas las extensiones, veo que me he dejado un paréntesis sin cerrar en el dialplan. Lo mismo pasaría para el resto de errores y warnings comunes durante las llamadas.

Log de los Agis

Cada vez más, a medida que desarrollamos nuestro Asterisk para darle más funcionalidades, debemos ejecutar más Agis. Los Agis son parte normal del flujo de una llamada y por tanto es de esperar que si queremos seguir la pista a cuanto ocurre en las llamadas de la centralita, sepamos lo que pasa dentro de esos Agi.

Todos los leguajes de programación tienen sus funciones para loguear a syslog. En este ejemplo vamos a usar Agis escritos en PHP. Generamos una pequeña clase que gestione los logs tal y como queremos que aparezcan en nuestros ficheros:

Tenemos una función doLog a la que podremos llamar para que loguee lo que nosotros le pasemos como parámetro al Syslog. Además, enviará un correo por todo mensaje que no sea de tipo DEBUG para avisar de que algo no funciona como debería. Sólo queda ver hacer llamadas de log en los Agi para tener el flujo controlado y logueado. Por ejemplo:

Este sencillo Agi, comprueba si un usuario dado como parámetro existe en la tabla tablausuarios y setea la variable de canal EXISTE_USUARIO a “SI” o “NO”. Como podemos ver, se hacen múltiples llamadas a la clase de log a lo largo del Agi para poder seguir el flujo de la llamada en el mismo y no hacer que éste sea una caja negra desde que se le llama en el Dialplan hasta que termina y devuelve el control. Las llamadas a la función de log reciben como parámetros:

• Uniqueid de la llamada para poder discriminar fácilmente entre las mismas. Ya samos que no es único pero también sabemos que es lo bastante único.
• Nombre del fichero Agi.
• Línea en el fichero Agi en el que se encuentra el log.
• Severidad del mensaje. Cuando no hay un problema ponemos LOG_DEBUG ya que en nuestro caso cualquier otro causa además del log, un envío de correo avisando de que algo ha ido mal. Existen diferentes niveles de severidad que vienen dados por las funciones de llamada a syslog del lenguaje en particular.
• Mensaje que queremos que se grabe.

Una vez tenemos los Agi bien comentados y las llamadas al log bien pensadas, podemos ver cuanto pasa en un Agi mirando el Syslog:

Como podemos ver, hemos llamado al Agi y le hemos preguntado por un usuario que no existe. En el log podemos ver:

• Fecha del log.
• Nombre del host.
• SyslogTag, una marca para poder clasificar los logs, en este caso “ivozlog”.
• Uniqueid de la llamada, para poder trackear una llamada en concreto.
• Nombre del fichero de Agi que ha generado este log.
• Línea dentro del Agi donde estaba el mensaje de log, muy útil en Agis grandes.
• Mensaje informativo.

Como podemos ver, tenemos toda la información necesaria para poder ver el flujo que ha seguido una llamada en concreto en los Agi por los que ha pasado. Sin embargo, no hemos terminado con los Agi ya que sólo hemos controlado errores de programación y de conexión. Tenemos controlados los errores y los flujos pero no estamos aún preparados para los errores incontrolados tales como excepciones.

La librería de Agi más popular es sin duda phpagi. Esta librería permite además avisar de errores incontrolados y fallos en la comunicación con Asterisk mediante un correo electrónico. Es muy sencillo modificar la función de manejo de errores de phpagi.php para que loguee a syslog con el tag y el facility que nosotros queramos:

Y por fin lo único que quedaría sería decir al propio PHP que loguease los errores propios del lenguaje en syslog para de esta forma terminar de controlar todo lo que puede pasar en un AGI. Esto ya es propio de cada instalación de php en cada distribución así que símplemente lo dejamos como comentario.

Log del dialplan de Asterisk

Como hemos comentado, sólo tenemos de Asterisk los errores y los warnings. No tenemos información detallada de lo que pasa con una llamada ya que en alta carga el log de Asterisk y la consola se vuelven a efectos prácticos, inusables. Casi todos hemos usado la aplicación NoOp para ir poniendo mensajes que más tarde nos ayuden a debuguear visualmente el flujo de las llamadas. En este caso y dado que lo que queremos es unificar los logs en el syslog, vamos a reemplazar Noop por una aplicación que loguee a Syslog.
Asterisk dispone de la aplicación Log, que usa el logger de Asterisk para hacer sus cosas. Sin embargo, esta función nos deja poco control y es poco flexible para nuestras necesidades. En su lugar vamos a usar una aplicación  que aunque no es oficial de asterisk,  es fácilmente integrable en cualquier asterisk 1.4 y además ya viene se serie en asterisk-es-rsp: app_syslog.
La función app_syslog se pensó para poder loguear al Syslog directamente desde dialplan. Acepta gran cantidad de parámetros y al llamar directamente a Syslog y no usar el log de asterisk es enormemente rápida, ligera y flexible. Para instalarla símplemente hay que copiar el app_syslog.c a la carpeta apps de Asterisk (a no ser que tengamos las últimas versiones del branch principal de asterisk-es-rsp) y escoger su compilación al hacer “make menuconfig”, ya que al no ser una aplicación oficial de asterisk se decidió que no se compilase por defecto.

El uso de la aplicación es bastante sencilla:

En este caso, no vamos a cambiar de facility, ni de tag… por lo que los parámetros los guardaremos en variables globales y haremos las llamadas a Syslog desde nuestro dialplan de forma sencilla:

Y El resultado en el Syslog sería tal que:

De tal forma que ahora sí que podemos seguir un flujo de llamada de forma ordenada desde el Syslog del sistema.

Poniendo orden en el Syslog

Hemos hecho que nuestra centralita loguee todo al Syslog del sistema. Tenemos enormes cantidades de información en el fichero /var/log/syslog, pero esa información únicamente está marcada. Aún nos queda poder filtrarla (sin greps por favor), y tenerla en tamaños manejables ya que la inspección del fichero de syslog va a ser un caos mucho mayor que mirar la consola de asterisk, cosa que queríamos evitar desde un inicio.
Como herramienta de Syslog vamos a usar rsyslog, el programa de viene por defecto en Debian. Vamos a repartir los logs entre diferentes ficheros de tal forma que tengamos todo un poco más repartido. ¿Repartido? ¿No queríamos unificar todo?
En estos momentos tenemos los siguientes logs marcados de la siguiente manera:

• Log de errores de Asterisk con facility Local5, tag “asterisk”.
• Log de los agis con facility Local6, tag “ivozlog”.
• Log de errores de phpagi con facility Local6 y tag “phpagi”
• Log del dialplan de Asterisk con facility Local5 y tag “asterisk”
• Todos los demás logs del sistema con sus facilitys, y sus tags

Vamos a hacer que los errores (Local6) vayan a un fichero y los mensajes de flujo de llamadas (Local5) vayan a otro fichero. De esta forma tendremos más separado lo que es el error incontrolado de lo que es un debug o error controlado (que por otra parte ya se nos notifica por correo).

En el fichero /etc/rsyslog.conf tenemos la configuración por defecto de un syslog. No vamos a comentar todo lo que hace el sistema ya que el manejo de syslog es algo que todos los administradores de sistemas conocen a la perfección. Símplemente modificaremos las líneas necesarias para que los logs con determinada facility sean desviados a otros ficheros y no aparezcan en el log principal mezclados con todo lo demás.
Localizamos la línea

Y la reemplazamos por

De esta forma hacemos que todos los logs con facility Local5, Local6, Local0 no aparezcan en el fichero de syslog y cada uno se escriba en su propio fichero. Tenemos las cosas más separadas pero aún así podemos ver el flujo de llamadas y errores de forma ordenada y cada uno en su sitio.
¡No hemos acabado! Tenemos ingentes cantidades de información que van a generar ficheros enormes que van a acabar por hacerse demasiado pesados amén de llenarnos el disco duro. Los logs hay que rotarlos. Nada más sencillo que crear unas rotaciones con el fichero /etc/logrotate.d/asterisk :

Esto ya va tomando forma
Del mismo modo que hemos marcado y desviado los logs de Asterisk y de nuestra programación, podemos hacer lo propio con otros servicios de tal forma que la ingente cantidad de información -nunca hay demasiada- pueda ser más manejable y tratable. Podemos quedarnos aquí o podemos ir a hacerlo mejor:

Syslog a Mysql

¿No sería mucho más manejable disponer de todos los logs en una base de datos? De esta forma podríamos integrar visores y filtros en webs de gestión de una forma mucho más sencilla, amén de hacer todas las tareas de mantenimiento más sencillas al pobre administrador que no va a tener que lidiar con docenas de ficheros o dar acceso a los logs a gente que no debe tener acceso al sistema.
Rsyslog hace esto sencillo. Lo que vamos a necesitar es:

1. Dar soporte mysql a rsyslog.
2. Crear la base de datos y hacer que rsyslog escriba en ella lo que nosotros queramos.
3. Hacer que la base de datos sea manejable.

Lo primero no puede ser más sencillo:
apt-get install rsyslog-mysql

Durante la instalación de rsyslog-mysql nos saldra un “ncurses” donde nos preguntará si queremos configurar una bases de datos … le decimos que no, que lo haremos manualmente ya que nos vamos a crear una tabla normal sino una tabla del tipo merge. Esto lo explicamos más adelante.

Vamos a crear digamos 28 tablas se1-se28 idénticas en todo excepto en el nombre, en una base de datos llamada log y creada para este propósito:

Después creamos la tabla SystemEvents que es una tabla merge de las 28 anteriores:

¿Qué hemos hecho? Hemos creado una tabla que es una unión de otras 28 tablas. Cuando hagamos un SELECT de la tabla SystemEvents, estaremos buscando en las 28 tablas y cuando hagamos un INSERT en la tabla estremos escribiendo en la tabla se1 (la primera).
Ya tenemos la tabla, ahora toca hacer que rsyslog escriba en ella los logs del sistema que nosotros queremos. Para ello vamos a crear un fichero de configuración aparte /etc/rsyslog.d/mysql.conf. Lo primero de todo es decirle a rsyslog que incluya la configuración de ese fichero. Vamos al final del fichero /etc/rsyslog.conf y añadimos (si no la tenemos ya) la línea
$IncludeConfig /etc/rsyslog.d/*.conf
En el nuevo fichero le diremos a rsyslog que cargue el módulo mysql y que loguee ciertas cosas a la base de datos log, tabla SystemEvents:

Este fichero loguea todo lo que iría al fichero normal de syslog más los facility 5 y 6 a la base de datos. Se podría haber hecho todo en una sola línea y el uso del template no es en realidad necesario (ya que usamos el esquema estandar para las tablas, el que rsyslog usa por defecto) pero de esta forma se puede tocar después de una forma más cómoda. En la web de rsyslog hay mucha documentación acerca de cómo configurar este comportamiento.
Sólo nos queda dar permisos al usuario “rsysloguser” con contraseña “rsyslogpass” en la base de datos “log” para poder reiniciar rsyslog y ver los logs en la base de datos.
¡Tampoco hemos terminado!
Por lo que hemos visto, los INSERT de Mysql se hacen en la tabla se1, por lo que las otras 27 tablas están vacías y no sirven de nada. Además, a medida que pasa el tiempo y los logs se acumulan, la tabla SystemEvents se va haciendo más y más grande y el rendimiento empieza a degradarse. Para eso hemos hecho 28 tablas: Al igual que rotamos los ficheros de log vamos a rotar las tablas de log de tal forma que todos los días vamos a:

• Eliminar la tabla se28
• Rotar todas las tablas una posición a la derecha
• Volver a crear la tabla se1

De esta forma consevaremos en base de datos los logs de las últimas 4 semanas siempre, una tabla por cada día. Además borrar una tabla es mucho más eficiente que borrar sus registros. Un pequeño script puesto en cron nos va a permitir hacer esto de forma automática:

Nota: El usuario rsyslog ha de tener el privilegio global RELOAD para que esta rotación funcione correctamente.

¿Hemos acabado ya? Realmente… sí.
Ya sólo nos quedaría usar una aplicación que nos permita ver y filtrar los logs de una forma sencilla. Podemos usar nuestra propia aplicación o usar alguna ya hecha a tal efecto como phplogcon. Este programa, no vamos a meternos en su instalación ya que es bastante sencilla y sería repetir lo que ya está explicado en su web, dispone de una potente interfaz para ver y gestionar los logs. Cada uno que use el que más le guste

phplogcon

Posted by Jon Bonilla in Asterisk, General, Howto