Contando mis logs

Tanto tiempo ciertoo??? Esta vez vengo con un problema mas operativo que otra cosa! El problema es el siguiente: me tocó implementar un servidor de logs centralizado donde escriben logs unos mmm, 150-200 hosts, entre servidores, equipos de red, ups etc.

Hay momentos en el día en que la cantidad de logs se puede poner un pooco densa, y por las noches extrañamente el rsyslog colapsa. En principio activé el monitoreo propio de rsyslog, pero este solamente me dice la cantidad de logs en la cola actual, la cantidad encolados desde que inició el servidor, y el máximo de logs que hubo en algún momento en la cola.

##Estadisticas de rsyslog
$ModLoad impstats.so
$PStatInterval 20
$PStatSeverity 7


Aca una salida del monitoreo con impstats.so

Jun 10 20:50:25 bb rsyslogd-pstats: imuxsock: submitted=141 ratelimit.discarded=0 ratelimit.numratelimiters=72
Jun 10 20:50:25 bb rsyslogd-pstats: action 30 queue: size=0 enqueued=213694 full=0 maxqsize=159
Jun 10 20:50:25 bb rsyslogd-pstats: action 31 queue: size=0 enqueued=76427 full=0 maxqsize=18
Jun 10 20:50:25 bb rsyslogd-pstats: main Q: size=3 enqueued=636410 full=0 maxqsize=238

Tengo 3 colas, la principal y dos mas, una para escribir en un rsyslog secundario remoto y otra para escribir en una BD en otro servidor remoto.

Por las noches sucedía que la mainQ colapsaba y perdía logs. Un par de veces el servidor colapsó.

El tamaño default de la cola de mensajes principal es de 10k mensajes, por lo tanto como me sobraba memoria agrandé la cola considerablemente a unos 100k mensajes. Y por las dudas implementé unas mediciones extras para ver qué cantidad de logs están llegando y de qué dispositivos en particular.

Asumciones:
-Que los logs vienen por UDP (recuerdo que algunos servidores están configurador con TCP, pero son minoría).
-Que cada paquete UDP representa un mensaje, es lo mas probable.

La solución fue el siguiente script en perl:

#!/usr/bin/perl -w

open STDIN,"tcpdump -n -s 1024 -tt dst host HOST_IP and dst port 514 2>/dev/null |" or die "Oops";
open STDOUT,">>/dev/null";
open STDERR,">>/dev/null";

$t1=time();
$t2=$t1+300;

#Imprime en "valores" un historico con el siguiente formato
#fecha y hora
#mensajes -> host
#mensajes -> host
#...
#Ademas escribe en total_logs, el valor logs.value mensajes
#este archivo es levantado por munin para graficar la cantidad
#de mensajes recibidos en los ultimos 5 minutos
sub ver_valores
{
        my $i;
        my $s="";
        my $x=0;
        foreach $i (sort (keys %LOGS))
        {
                $x=$x+$LOGS{$i};
                $s=$s."$LOGS{$i} -> $i\n";
        }
        open(F,">>valores");
        print F localtime()."\n$s\n\n";
        close(F);
        open(F,">total_logs");
        print F "logs.value $x";
        close(F);
}


#Pone en 0 todos los valores del hash
sub reiniciar
{
        foreach $i (keys %LOGS)
        {
                $LOGS{$i}=0;
        }
}

while()
{
        my @a=split(' ',$_);
        my @b=split('\.',$a[2]);
        my $c="$b[0].$b[1].$b[2].$b[3]";
        if(defined $LOGS{$c})
        {
                $LOGS{$c}=$LOGS{$c}+1;
        }
        else
        {
                $LOGS{$c}=1;
        }
        $t1=time();
        if($t1 > $t2)#pasaron al menos 300 segundos
        {
                $t2=$t1+300;
                ver_valores();
                reiniciar();
        }
}

El script es bastante sencillo, toma la salida de tcpdump (un tanto filtrada para reducir la carga al script), y por cada linea (mensaje syslog) carga un nuevo valor en el hash o incrementa en 1 el valor si el host ya fue ingresado. Pasados los 300 segundos se llama a la función ver_valores(), que imprime datos en dos archivos diferentes. Luego la función reiniciar, que pone a cero la cantidad de mensajes de todos los hosts de hash, era mas sencillo reiniciar el hash completamente? SI, pero me interesa que el hash crezca a medida que un nuevo host comienza a mandar logs, y si deja de enviar que marque cero.

Filtrado del tcpdump:

-n: sin resolución de nombres.
-s 1024: reducir el tamaño máximo de captura por paquete, para no sobrecargar en vano, con 1024 bytes sobra para reconocer el tipo de paquete (UDP o TCP).
-tt: para que la hora se imprima como timestamp.
dst host HOST_IP and dst port 514: solamente captura los paquetes destinados a a la IP HOST_IP y al puerto 514 (UDP o TCP).

Si bien falta un pequeño detalle (a tratar en otro post, que es hacer de este script un demonio, de momento lo lanzo con screen), con esto logré saber el número de mensajes recibidos en los últimos 5 minutos y tener un historial que muestra la cantidad de logs que envió cada host.

En la imagen podemos ver como si bien hay una tendencia a los 2k mensajes cada 5 minutos, hubo unos picos muy interesantes que pasaron los 20k mensajes!!!

UPDATE: hice un cambio en la función ver_valores(), básicamente simplifiqué la obtención de la hora, ahora es mas simple la función.