Antes de comenzar vale aclarar que este tipo de análisis forense sobre archivos de log de gran volumen conviene hacerlo fuera del servidor (por ejemplo, descargar el access.log a una máquina local) para no castigar en uso de CPU, memoria y E/S en el VPC o instancia EC2.

En este caso de estudio, se trata de un servidor Web Apache donde más de la mitad de los clientes terminan generando una respuesta 408 en algún momento:

root@debian:/var/log/apache2# cat access.log | cut -d' ' -f1 | sort | uniq | wc -l
1079
root@debian:/var/log/apache2# grep ' 408 ' access.log | cut -d' ' -f1 | sort | uniq | wc -l
587

Apache utiliza el módulo mod_reqtimeout. La configuración del módulo reqtimeout utilizada es el ejemplo del manual de Apache:

RequestReadTimeout header=20-40,minrate=500
RequestReadTimeout body=10,minrate=500

Este módulo genera una respuesta 408 cuando ocurre alguno de los timeouts definidos.

Para analizar cómo y por qué un cliente termina generando una respuesta HTTP 408 desde el servidor Apache, es conveniente separar el log de Apache por IP. Es decir, guardar en un archivo todas las respuestas pertenecientes a una misma IP. Para ello, crear un script que filtre el log de Apache por IP:

emi@vaio:/tmp$ nano 408s-users.sh

Código del script:

grep ' 408 ' access.log | cut -d' ' -f1 | sort | uniq > 408s.borrar
while read ip; do
  grep $ip access.log > "access-${ip}.log"
done < 408s.borrar

Correr el script para generar archivos de log separados por IP:

emi@vaio:/tmp$ ./408s-users.sh

Esto permite analizar sesiones individuales.

Una mirada rápida da la pauta de que hay dos tipos de respuestas 408:

  1. Aisladas: único request para un cliente. Podría ser ocasionado por los mecanismos de prefetching/preloading de ciertos browsers al iniciar.
  2. Transcurridos 20 segundos luego de la última solicitud válida.

Ejemplo del caso 2, una seguidilla de 3 respuestas 408:

192.168.45.55 - - [04/Jan/2021:08:24:22 -0300] "GET /logout HTTP/1.1" 200 70317 "https://www.linuxito.com/perfil" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36"
192.168.45.55 - - [04/Jan/2021:08:24:42 -0300] "-" 408 5895 "-" "-"
192.168.45.55 - - [04/Jan/2021:08:24:56 -0300] "GET / HTTP/1.1" 200 25823 "https://www.linuxito.com/checkout?id=3461" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36"
192.168.45.55 - - [04/Jan/2021:08:25:16 -0300] "-" 408 5895 "-" "-"
192.168.45.55 - - [04/Jan/2021:08:25:19 -0300] "GET /descargas/pdf/manual.pdf HTTP/1.1" 302 7138 "https://www.linuxito.com/blog/inicio.html" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36"
192.168.45.55 - - [04/Jan/2021:08:25:39 -0300] "-" 408 5895 "-" "-"

Ahora es posible volcar todas las respuestas 408, junto con la solicitud inmediata anterior realizada por el mismo usuario:

emi@vaio:/tmp$ grep ' 408 ' -B 1 access-*.log > 408s.log

Analizando todas estas entradas, se concluye que ocurre una respuesta 408 transcurridos 20 segundos luego de la última solicitud válida de una sesión de un usuario (independientemente del recurso solicitado en la última solicitud de la sesión). Esta situación ocurre para una parte importante de más de la mitad de los usuarios del sitio.

La sospecha es que se trata de una cuestión específica de cada navegador.

Pruebas con Chrome

Prueba accediendo a al sitio con el navegador Google Chrome desde mi IP (10.60.3.127). Luego de loguearse, y pasados 20 segundos, aparece el 408:

10.60.3.127 - - [04/Jan/2021:11:28:28 -0300] "POST /login HTTP/1.1" 302 1408 "https://www.linuxito.com/login" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36"
10.60.3.127 - - [04/Jan/2021:11:28:28 -0300] "GET /home HTTP/1.1" 302 733 "https://www.linuxito.com/login" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36"
10.60.3.127 - - [04/Jan/2021:11:28:49 -0300] "-" 408 579 "-" "-"

Pruebas con Firefox

La misma prueba, pero con Firefox, no provoca la respuesta 408.

10.60.3.127 - - [04/Jan/2021:11:29:59 -0300] "POST /login HTTP/1.1" 302 4650 "https://www.linuxito.com/login" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"
10.60.3.127 - - [04/Jan/2021:11:30:00 -0300] "GET /home HTTP/1.1" 302 733 "https://www.linuxito.com/login" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"


La conclusión es que determinados navegadores pre-abren una conexión con el servidor luego de cada solicitud para acelerar los tiempos de acceso. Situación que genera una respuesta 408 (timeout) de Apache si el usuario no genera ningún acceso dentro del período de tiempo configurado. Como admin uno podría verse tentado a aumentar el timeout para minimizar las respuestas 408. Sin embargo, mantener conexiones abiertas que no serán usadas puede terminar provocando una saturación del servidor Web o el sistema operativo subyacente en sitios con un gran número de clientes.

Compartí este artículo