Hace unos días en mi trabajo tuvimos un pequeño inconveniente con un proveedor, mas bien el problema fue del proveedor y nosotros sufrimos daño colateral, pero al principio nosotros no lo sabíamos que pasaba, solo teníamos un servidor caído, logs inmensos, bastante trafico pero tampoco era un DDOS, ¿cual era el origen?.
Para poner un poco de contexto, nosotros enviamos y publicamos avisos en varios servicios para nuestros clientes, independiente del método que usemos, sea api o xml, los proveedores tienen que pasar a levantar las imágenes.
La pregunta que nos hacíamos era ¿El trafico son ips diferentes o desde un grupo de varias ip pero mas reducido?
#Primer comando usado es cat registro.log
Supongamos que tenemos registro.log, solo como ejemplo pongo un trozo a modo de ejemplo, ademas remplace las ip por XXX.XXX.XXX.XXX para proteger al proveedor.
El log original no estaba tan ordenado como este, porque habían cientos de miles de lineas solicitando diferentes recursos intercaladas, no siempre mostraba al mismo archivo como en este caso, pero para el ejemplo sirve.
XXX.XXX.XXX.001 - - [14/Nov/2017:23:01:09 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.XXX - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.002 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.003 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo2.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.004 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo5.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.005 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo3.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.006 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo5.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.007 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.008 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo9.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.009 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.010 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo3.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.011 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.012 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo2.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.013 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo7.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.014 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.015 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.016 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo8.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.017 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.018 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo7.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34
Lo que si destacaba entre todos era una imagen en particular que era el logo de un cliente que insertamos en los aviso, que parecía haber sido pedida mas veces, que el resto, por eso sobresalía, se notaba mas, supongamos que se llamaba /imagenes/ejemplo1.jpg asi que nos concentramos en intentar averiguar cuantas veces se pido esa imagen.
Usamos es cat combinado con grep
cat registro.log | grep /imagenes/ejemplo1.jpg #Eso nos deja un log mucho mas chico quitando todas las llamadas que no sean a nuestra imagen XXX.XXX.XXX.001 - - [14/Nov/2017:23:01:09 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.XXX - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.002 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.007 - - [14/Nov/2017:23:01:10 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.009 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.011 - - [14/Nov/2017:23:01:11 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.014 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.015 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 XXX.XXX.XXX.017 - - [14/Nov/2017:23:01:12 +0000] GET /imagenes/ejemplo1.jpg HTTP/1.1 200 26055 - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/534.34 (KHTML, like Gecko) wkhtmltoimage Safari/534.34 #Ahora repetimos los 2 comandos anteriores y le agregamos cut cat registro.log | grep /imagenes/ejemplo1.jpg | cut -d " " -f 1 #Con cut nos quedamos con la primera columna XXX.XXX.XXX.001 XXX.XXX.XXX.002 XXX.XXX.XXX.007 XXX.XXX.XXX.009 XXX.XXX.XXX.011 XXX.XXX.XXX.014 XXX.XXX.XXX.015 XXX.XXX.XXX.017 #En este log todas las ip parecen ser diferentes, #pero recuerden que solo estoy mostrando un trozo, el log #original tenia cientos de miles de lineas con ips
Ahora le agregamos sort
#Todo en la misma linea cat registro.log | grep /imagenes/ejemplo1.jpg | cut -d " " -f 1 | sort #Quedaria algo asi XXX.XXX.XXX.001 XXX.XXX.XXX.001 XXX.XXX.XXX.001 XXX.XXX.XXX.001 XXX.XXX.XXX.002 XXX.XXX.XXX.002 XXX.XXX.XXX.002 XXX.XXX.XXX.007 XXX.XXX.XXX.007 XXX.XXX.XXX.007 XXX.XXX.XXX.007 XXX.XXX.XXX.007 XXX.XXX.XXX.009 XXX.XXX.XXX.009 XXX.XXX.XXX.009 XXX.XXX.XXX.009 XXX.XXX.XXX.011 XXX.XXX.XXX.011 XXX.XXX.XXX.014 XXX.XXX.XXX.015 XXX.XXX.XXX.015 XXX.XXX.XXX.017 XXX.XXX.XXX.017
Ahora agregamos el comando uniq -c
#Ahora agregamos el comando uniq -c #con esto nos quedaremos con una lista de ips sin repetir y sumara las repeticiones #El numero antes de la ip es la cantidad veces que aparecio esa ip #Todo en la misma linea cat registro.log | grep /imagenes/ejemplo1.jpg | cut -d " " -f 1 | sort | uniq -c #Quedaria algo asi 453 XXX.XXX.XXX.001 323 XXX.XXX.XXX.002 515 XXX.XXX.XXX.007 406 XXX.XXX.XXX.009 253 XXX.XXX.XXX.011 112 XXX.XXX.XXX.014 241 XXX.XXX.XXX.015 225 XXX.XXX.XXX.017
#Para ordenarlo cat registro.log | grep /imagenes/ejemplo1.jpg | cut -d " " -f 1 | sort | uniq -c | sort -k1,1nr -k2,2 #Nos quedaria algo asi 515 XXX.XXX.XXX.007 453 XXX.XXX.XXX.001 406 XXX.XXX.XXX.009 323 XXX.XXX.XXX.002 253 XXX.XXX.XXX.011 241 XXX.XXX.XXX.015 225 XXX.XXX.XXX.017 112 XXX.XXX.XXX.014
Hasta aquí logramos saber desde cuantas ip se pidió este archivo y cuantas veces por ip, pero todavía no sabemos algo importante ¿Todas estas ip están relacionadas?. Para eso vamos a geolocalizar todos y cada una de las ip
#Ahora vamos a necesitar GeoIp apt-get install geoip-bin geoip-database
Desde Aqui nos descargamos la base de datos de GeoIP, yo use la db de ciudades.
Ahora vamos a ejecutar una versión mas simple del comando, solo nos interesa una lista de ip y no la cantidad de peticiones ademas mandamos todo a un archivo.
mkdir /tmp/geoip/ #Todo en la misma linea cat registro.log | grep "/imagenes/ejemplo1.jpg" | cut -d " " -f 1 | sort | uniq /tmp/geoip/solicitudes.log cd /tmp/geoip #Por si no lo descargamos antes wget http://geolite.maxmind.com/download/geoip/database/GeoLiteCity.dat.gz gzip -d GeoLiteCity.dat.gz ls -l total 17436 -rw-r--r-- 1 alvaro alvaro 17852821 nov 6 15:05 GeoLiteCity.dat
Ahora con nano,vi o lo que sea creamos el archivo /tmp/geoip/geoip.php
<?php
$solicitudes = file('solicitudes.log');
foreach ($solicitudes as $solicitud) {
$solicitud = trim($solicitud);
$explode = explode(" ",$solicitud);
$list[$explode[1]] = $explode[0];
}
foreach ($list as $ip => $hits) {
exec('geoiplookup -f GeoLiteCity.dat '.$ip,$output);
$output = substr($output[0],25);
echo $hits . ' ' . $ip . " - " . $output . PHP_EOL;
}
?>
Ahora guardamos y salimos
#Ejecutamos php /tmp/geoip/geoip.php #Esto nos dara algo similar a esto 515 XXX.XXX.XXX.007 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 453 XXX.XXX.XXX.001 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 406 XXX.XXX.XXX.009 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 323 XXX.XXX.XXX.002 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 253 XXX.XXX.XXX.011 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 241 XXX.XXX.XXX.015 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 225 XXX.XXX.XXX.017 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703 112 XXX.XXX.XXX.014 - : US, VA, Virginia, Ashburn, 20149, 39.048100, -77.472801, 511, 703
¿Que significa esto? Pues que todas, o casi todas las solicitudes, al menos las que provocaban problemas por la cantidad de peticiones por ip, provenían desde el mismo datacenter ubicando en Amazon, el origen era el mismo por lo que si, estaban relacionadas y eso contestaba nuestra pregunta.
En nuestro caso cada ip tenia un promedio de 250 peticiones a esta imagen y eran casi 150 ips, solo esa imagen tuvo mas de 30.000 solicitudes en muy poco rato, repito solo esa imagen, después estaban todas las demás cientos de miles de peticiones mas.
El asunto era que este proveedor muy pero muy conocido y muy, muy grande, tuvo un problema interno, la base de datos que esta alojada en cientos de servidores aceptaba cambios pero demoraban en mostrase, como dije mas arriba el proveedor tenia que pasar a levantar fotos y entre ellos el logo que fue lo que rastreamos y nos permitió analizar y entender la situación.
Y el asunto era este, mandábamos el aviso por un json a un api, el proveedor pasaba a levantar las imágenes, digamos con un cron, las marcaba como realizadas pero como el sistema de ellos demoraba en mostrar confirmación interna de que se levantaron, el cron que corre detrás del anterior pasa de nuevo a levantaras nuevamente, y asi un promedio de 30 veces por aviso y publicamos miles de avisos, se imaginan el problema.
El log y el buen uso de la consola de linux para parsear el log nos permitió entender desde donde venia la avalancha de solicitudes, espero que les sirva.
Administrador de Sistemas, Programador, Docente y ahora resulta que también Blogger (peor es ser tictoker). Más de 20 años de experiencia en computación atendiendo nabos y resolviendo problemas que sino fuera por estos nabos no habrían ocurrido en primer lugar. Escribo más que nada sobre tecnología y herramientas en general además de algunos artículos con opiniones tan subjetivas como irrelevantes, así que si no te gustan mejor madura.