Analizar los Archivos de Registro (Logs)

Los archivos de registro (log files) son una de nuestras mayores herramientas de diagnóstico. Siempre que algo va mal o tal vez cuando va bien necesitamos averiguar el por qué en detalle, pero para hacerlo necesitamos analizar, reducir y extraer varios gigabytes de datos de los archivos de registro. En este artículo doy consejos y comandos para ayudaros a analizar los archivos de registro a través del archivo access.log de Apache.

El archivo access.log por sí mismo es un poderoso recurso analítico. A través de él se pueden ver referencias, detectar hotlinks a contenido profundo y patrones de tráfico.

Apache puede registrar cada visitante y cada petición hecha en el archivo access.log. La ubicación y el nombre del archivo de registro de Apache variarán según la plataforma *nix, así que aquí está el formato access.log que uso para este artículo:

LogFormat "%h %l %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i"" combined

1. %h – Dirección IP.
2. %l – Nombre de usuario remoto. Desactivado por defecto a menos que IdentityCheck On esté activado. Será dash si está desactivado.
3. %u – Nombre de usuario remoto. Como arriba.
4. %t – Timestamp, formato inglés.
5. % r – Primera línea de petición. Si la solicitud es POST o GET, el archivo de destino en el dominio y el protocolo.
6. %s – Número de código de respuesta HTTP.
7. %0 – Número de bytes enviados.
8. %{Referer]i – La URL de referencia. Se hizo clic en un enlace o se alojó contenido en esta página.
9. %{User-Agent]i – Cadena del agente de usuario del visitante.

Hay salidas frecuentes de entradas de archivos de registro en este artículo, pero para mayor claridad he truncado cada ejemplo a un archivo cada uno.

1. Ver las entradas más recientes

El archivo access.log es demasiado grande para leerlo de un vistazo. No estoy bromeando, mi propio sitio web no recibo más de 1000 visitas en un día determinado, y sin embargo tengo estas dimensiones de ficheros:

$ du -hs access.log
5024M    access.log
$ wc -l access.log
23218662 access.log

5024 MB en disco y con 23.218.662 líneas de entradas. Lo guardo todo porque a menudo reviso el registro para estudiar ataques y prestaciones, du devuelve el tamaño del archivo en el disco duro en cualquier formato que usted le diga, mientras que wc cuenta el número de líneas, palabras o caracteres en la entrada.

head y tail son dos grandes comandos para empezar a extraer datos del archivo de registro, volcan las líneas X superior o inferior de un archivo a la salida. En este caso le pido a la cola que escoja la línea inferior del access.log

$ tail -n 1 access.log
23.20.9.23 - - [06/Jul/2015:11:21:48 +0000] "GET /archives/2374 HTTP/1.0" 200 4613 "-" "CCBot/2.0 (http://commoncrawl.org/faq/)"

2. Ver líneas específicas con sed

Los comandos generan sobre todo una corriente de texto: tail y head, mientras que du y wc cuentan las cosas. sed(recursear) es el programa que hace las cosas con las cosas.

sed puede modificar el flujo usando expresiones regulares. Una cosa que hago todo el tiempo es sustituir los espacios en los nombres de archivo con guiones bajos más amigables:

$ a=”this has spaces”
$ sed ‘s/s/_/g’ <<< $a
this_has_spaces

A lo largo del resto de este artículo utilizo sed tanto para la sustitución como para imprimir líneas específicas de un archivo. Imprimir línea 15:

span>$ sed -n 15p access.log
Print lines 3 to 100 (inclusive):
$ sed -n 3,100p access.log

3. Más acciones con sed

sed puede imprimir líneas basándose en casi todos los criterios: puede preguntar por cualquier otra línea; o especificar líneas en las que el noveno carácter sea «f».

Imprimir una de cada cuatro líneas, empezando por 0:

span>$ sed -n 0-4p access.log

O busca líneas con el agente de usuarios de Facebook. Facebook tiene un rastreador que utilizan para añadir sitios a un índice como el de Google, de modo que si compartes un enlace a una página, la información de la página estará lista:

$ tail -n 300 access.log | sed -n  '/facebook/'
2a03:2880:3010:9ff6:face:b00c:0:1 - - [07/Jul/2015:20:39:01 +0000] "GET /archives/13544804758 HTTP/1.1" 206 9857 "-" "facebookexternalhit/1.1 (+http://www.facebook.com/externalhit_uatext.php)"

4. Encontrar anti-patrones

sed puede imprimir una línea en casi cualquier criterio. Incluso puede imprimir líneas que no coinciden con un patrón. Un uso divertido es encontrar agentes de usuario interesantes, ya que cada navegador es Mozilla:

$ tail -n 30 access.log | sed -n '/Mozilla/!p' 
199.16.186.106 - - [07/Jul/2015:20:18:53 +0000] "GET /feed HTTP/1.1" 301 652 "-" "BoardReader Blog Indexer(http://boardreader.com)"

'/Mozilla/!p' coincide con cualquier línea que no contenga «Mozilla». Este es un uso no convencional para sed, pero sirve como un gran ejemplo de la fuerza del programa.

5. Salida dividida con tee

tee es un método para dividir la salida de un comando:

Una secuencia se redirige a un archivo.
La otra corriente va a STDOUT y continúa el flujo.
Aquí, canalizo la última línea del archivo hacia tee. Redirijo la salida a la sustitución de procesos en lugar de a un archivo. De esta manera puedo realizar varias tareas en paralelo sin tener que iterar. El orden de salida de tee puede ser impredecible porque los resultados se emiten tan pronto como se completan. Para explicar el orden:

• STDOUT imprime toda la línea.
• awk imprime la primera columna de la línea.
• wc imprime el número de caracteres.
• wc imprime el número de palabras.

$ tail -n 1 access.log | tee >(wc -w) >(wc -c) >(awk '{ print $1 }')
66.249.67.95 - - [07/Jul/2015:20:41:29 +0000] "GET /archives/98 HTTP/1.1" 200 13906 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"
66.249.67.95
163
15

6. Visualizar las líneas circundantes con grep

grep – que cubro extensamente en mi artículo sobre grep y regex – es una de las primeras y aún poderosas utilidades de búsqueda. grep usa expresiones regulares para encontrar texto coincidente. Aquí busqué instancias de un rastreador Baidu que accedía a una parte oscura del sistema de archivos de WordPress:

grep -C 1 -m 1 ‘jquery’ access.log
79.97.253.56 - - [03/Nov/2014:14:42:22 +0000] "GET /style.css HTTP/1.1" 200 1704 "http://www.bhalash.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.19 Safari/537.36"
79.97.253.56 - - [03/Nov/2014:14:42:22 +0000] "GET /jquery-2.1.0.min.js HTTP/1.1" 200 29653 "http://www.bhalash.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.19 Safari/537.36"
79.97.253.56 - - [03/Nov/2014:14:42:23 +0000] "GET /functions.js HTTP/1.1" 200 607 "http://www.bhalash.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.19 Safari/537.36"usi

grep -C 1 proporciona un contexto de una línea a cada lado del partido, y -m 1 restringe el grep al primer partido encontrado.

7. Formatear la salida con AWK

• grep encuentra las cosas.
• sed hace cosas con las cosas.
• awk hace que las cosas sean bonitas.

AWK es una utilidad que forma la tercera parte de nuestro trípode de herramientas. grep encuentra las líneas que queremos usar; sed realiza sustituciones para hacerlo más accesible; y AWK formatea la salida como sea que especifiquemos A pesar de que AWK puede ser programado, AWK es un lenguaje de programación completo por sí mismo. – se supone que debe tomar información de STDIN.

El uso más común es imprimir una columna dada (palabras separadas por espacios) desde la entrada. Aquí quiero la dirección IP en la primera columna de access.log:

$ awk '{ print $1 '} access.log
66.249.64.76

Aquí inserto "IP:" antes de cada dirección como una forma de añadir más orden:

$ awk '{ print "IP: " $1 }’ < access.log
IP: 66.49.64.76

8. Más formato con AWK

AWK es lo suficientemente poderoso como para analizar cualquier entrada en bruto en una tabla sin ningún esfuerzo extra de mi parte. Este ejemplo imprime la IP y la marca de tiempo de una visita después de eliminar los caracteres adicionales como estos: [ y ] con sed:

$ awk 'END{ print "IP: " $1; print "Date: " $4$5 }' < access.log | sed 's/[//g;s/]//g' 
IP: 157.55.39.30
Date: 30/Jul/2015:19:24:10+0000

END imprime la línea final sólo de entrada. Hay una nueva línea implícita entre los comandos de impresión.

9. Salida de B-AWK hacia el exterior

AWK puede imprimir el texto de la última columna con la variable $NF

$ awk 'END{print $NF}' < access.log
Safari/537.36"

10. Ver a los visitantes en tiempo real

tail -f dice a tail que tiene que monitorizar el archivo especificado en busca de cambios añadidos y mostrar nuevas líneas en STDOUT. Esta es una herramienta de desarrollo fantástica. Cuando trabajo en un sitio mantendré abiertos varios logs de debug en cola y podré vigilarlos mientras hago cambios.

$ tail -n 1 -f access.log
67.196.50.63 - - [06/Jul/2015:16:16:09 +0000] "GET /archives/13544804736 HTTP/1.1" 200 11361 "-" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.66 Safari/537.36"
# Recargo la web y una nueva fila se añade al output
62.210.215.119 - - [06/Jul/2015:16:16:08 +0000] "GET /feed HTTP/1.1" 200 15568 "-" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.66 Safari/537.36"

11. Clasificar y filtrar

grep permite el soporte del potente regex. En este caso quería examinar las olas de robots que atacan el inicio de sesión de WordPress de mi propio sitio web:

$ grep -P '(wp-login|regist)' access.log | grep GET
91.188.72.170 - - [02/Jul/2015:20:25:07 +0000] "GET /wp-login.php HTTP/1.0" 301 631 "-" "-"

Abordo esto en gran profundidad en mi artículo sobre regex, pero (foo|bar) encontrará foo OR bar en una línea. Lo meto en un segundo comando que busca el comando GET, es decir, cuando el bot solicita las páginas de inicio de sesión, porque cada petición genera al menos dos líneas:

AWK puede imprimir texto de la última columna con la variable $NF:

$ awk 'END{print $NF}' < access.log
Safari/537.36"

1. La solicitud de la página de inicio de sesión.
   
2. La redirección a la pantalla de «contraseña incorrecta».

12. Diseccionar información de DNS e IP

Los cómodos comandos dig y nslookup buscan en Internet información sobre dominios y direcciones IP por igual:

Tomamos dig: interroga a los servidores de nombres sobre una dirección IP o un dominio, y devuelve todo lo que encuentra. Dependiendo de la configuración del servidor, es posible que vea información sobre los dominios relacionados. He truncado la salida completa del comando ya que se ejecuta en más de 30 líneas.

$ dig $(awk ‘END{ print $1 }’ access.log)
; <<>> DiG 9.9.5-3ubuntu0.2-Ubuntu <<>>
;; global options: +cmd
;; Got answer:
...
;; Query time: 1 msec
;; SERVER: 109.74.192.20#53(109.74.192.20)
;; WHEN: Mon Jul 06 21:45:46 UTC 2015
…

nslookup consultará cualquier dominio que se conecte a la IP.

$ nslookup $(awk 'END{print $1 }' access.log)
[INSERT]
Server:  109.74.192.20
Address: 109.74.192.20#53
** server can't find 251.251.185.146.in-addr.arpa: NXDOMAIN

nslookup y dig hacen su mejor trabajo cuando empiezas con un dominio y lo rastreas hasta la dirección IP, pero a veces descubres su dominio.

13. Leer ficheros log archivados

cronjobs comprime, poda y archiva los archivos access.log de forma regular antes de que su tamaño se convierta en un problema. Un trabajo cron regular crea una copia gzip del archivo access.log de ese día y luego vacía el archivo original.

zcatlee el contenido de un archivo gzip en STDOUT:

$ zcat access.log.tar.gz | head -n 1
79.97.253.56 - - [03/Nov/2014:14:38:26 +0000] "GET /icons/blank.gif HTTP/1.1" 200 430 "http://www.bhalash.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.19 Safari/537.36"

Puedes unir esta salida archivada con la salida grep o cat del archivo original access.log:

awk { print “IP: “ $1 }’ < <({zcat access.log*gz & cat access.log}
IP: 66.49.64.76

14. Acelerar el grep

Puedes forzar a grep a ejecutarse cientos de veces más rápido si reinicias la localización del sistema antes de su búsqueda. Los emuladores de terminal modernos utilizan el conjunto de caracteres Unicode de 110.000 caracteres. Cuando grep busca a través de Unicode, incluye todos esos miles de glifos adicionales. Si reinicias la localización del sistema para usar ASCII, grep sólo tiene que incluir 128.

Aquí hay un pequeño script llamado lc_grep que resetea el locale de la terminal para usar el conjunto de caracteres ASCII. La localización del ordenador representa:

• El conjunto de caracteres (UTF8 o ASCII o lo que sea).
  Marca de tiempo (UTC + u – horas).
  Lenguaje que utiliza.
  

La desventaja es que grep funcionará de una manera más difusa. Un buen ejemplo es la ü alemana frente a la u. grep inglesa que interpretará la primera como la segunda, por lo que una búsqueda de caracteres no ingleses puede dar resultados extraños.

#!/bin/zsh
OLD_LC=$LC_TIME
LC_TIME=C
grep "$@"
LC_TIME=$OLD_LC

Después de reiniciar el locale, los argumentos de grep pasan a ser normales a través de $@, que es una lista de todos los argumentos dados al script.

$ lc_grep -P '(wp-login.php|regist)' access.log

15. Geolocaliza a los visitantes

La utilidad geoiplookup y sus bases de datos se envían como parte de varias distribuciones. La utilidad consulta las direcciones IP suministradas y, dependiendo de la calidad de la base de datos, devuelve información sobre el país y la región. Aquí hay un pequeño script de envoltura que toma cualquier dominio o IP y elimina la edición de una geoiplookupy el código de país:

#!/bin/zsh
ip=$(dig $1 | grep -A 1 'ANSWER SECTION') | awk 'END{ print $NF }')
echo geoiplookup $ip | sed -e 's/^.*: //g'

$ ./get_country serversaustralia.com.au

AU, Australia

16. Dominar las expresiones regulares

Ya he mencionado que las expresiones regulares son mi herramienta más poderosa cuando analizo archivos. Vale la pena que le dediques tiempo a revisar mi otro artículo y presentarte a regex en grep. Aunque AWK puede imprimir cualquier número de columnas, cada cadena de agente de usuario es diferente y única en longitud. Es más fácil eliminar la línea anterior con regex:

$ tail -n 1 access.log | sed 's/^.*-" "//g;s/"//g'
Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)

La línea antes de la cadena del agente de usuario termina literalmente con -" ", así que primero quito eso. Hay una comilla final después del agente de usuario que luego quito

17. Búsqueda de visitantes

Este es un script típico que uso para investigar a los visitantes de mi sitio. En este caso, utilizo la búsqueda de un bot de raspado de Google:

#!/bin/zsh
matches=$(grep $@)
last_visit=$(echo $matches | tail -n 1)
echo "IP: $(echo $last_visit | awk '{print $1 }')"
echo "Total visits: $(echo $matches | wc -l)"
echo "User Agent: $(echo $last_visit | sed -e 's/^.*-" "//g' | tr -d '"')"
echo "Last visit: $(echo $last_visit | tr -d '[]' | awk '{ print $4$5 }')"

Le pasas el script una dirección IP y el archivo de registro de destino, y desde allí devuelve el total de visitas y la fecha y hora de la última visita.

$ ./visitors.sh 66.249.78.54 access.log
IP: 66.249.78.54
Total visits: 3856
User Agent: Mozilla/5.0 (compatible; Googlebot/2.1;+http://www.google.com/bot.html)
Last visit: 07/Jul/2015:21:51:35+0000

18. Colorear la salida con multitail

Las líneas rectas de blanco sobre negro se mezclan de una línea a otra cuando se mira lo suficiente durante cuatro horas a la vez. Por otra parte, grc, «el colorante genérico», añadirá color a cualquier comando.

multitail es un sustituto directo de tail:

$ multitail -f access.log

Primero llamas a grc y luego pasas por el resto de tu comando como argumentos:

$ grc tail -f -n 50 access.log

19. Ver archivos perdidos

awk tiene habilidades como awk y sed, ya que puede igualar patrones y realizar sustituciones:

awk 'END{($9 ~ /404/)}' < access.log | awk '{print $9": " $7}'
404: /apple-touch-icon.png

En el comando anterior ($9 ~ /404/) sólo se imprimen líneas donde el código de estado devuelto es «404», el cual es reenviado a otro comando AWK para formatear.

20. Informe sobre los códigos de acceso

Esta práctica línea ordena el registro, cuenta las ocurrencias de una cadena y ordena la salida en orden descendente:

$ awk '{ print $9 }' access.log | sort | uniq -c | sort -rn
1999022 200
 188287 301
  65430 302

La posición del código de retorno en la línea varía según la distribución. Compruebe su propio archivo access.log y encuentre el código de retorno antes de empezar!

21. Informe sobre archivos perdidos

Esta última línea combina las dos últimas para mostrar los 10 archivos perdidos más importantes encontrados por los visitantes. sort y uniq deberían ser autoexplicativos: sort reorganiza el archivo, ya sea por letra o por número mientras que uniq elimina líneas adyacentes idénticas.
Este flujo agrega entradas duplicadas, ordena las ocurrencias en orden numérico y produce los archivos que faltan más. En este caso el mayor culpable fue un archivo que aún no había subido mientras probaba el sitio durante el desarrollo.

$ awk '($9 ~ /404/)' access.log | awk '{ print $7 }' | sort | uniq -c | sort -nr
   5343 /our-wp-content/themes/rmwb/assets/images/fallback.jpg
   3199 /our-wp-content/themes/rmwb/images/favicon.png
 1471 /our-wp-content/themes/sheepie/assets/images/fallback.jpg

Fuente