Encontrar al culpable del alto uso de la CPU en nuestro servidor de WordPress

Hace unos días recibimos un correo electrónico de nuestro proveedor de alojamiento (SiteGround) informándonos que nuestro sitio ya tenía "90% del uso mensual permitido de CPU" y que, una vez superado el 100%, el "servicio web sería limitado" y es posible que tengamos "problemas para acceder a él". Bastante aterrador, ¿verdad? Definitivamente era una situación totalmente indeseable que teníamos que arreglar lo antes posible. Pero… ¿por dónde empezar?

Hoy queríamos compartir con vosotros nuestra experiencia ante un problema bastante común en las webs, explicando qué hicimos para identificar al culpable y cómo solucionamos el problema. De esta forma, si te enfrentas a un problema similar, tendrás algunas ideas sobre cómo empezar...

Razones por las que puede tener un uso elevado de la CPU

WordPress es un sistema de gestión de contenidos escrito en PHP. Esto significa que el contenido que sirve es generado dinámicamente por un conjunto de scripts PHP: cada vez que un visitante llega a su sitio web, WordPress procesa la solicitud (que es algo así como "por favor envíeme su página de inicio") y genera una respuesta (en este caso, envía la página de inicio). Claramente, responder a una solicitud implica un cierto uso de los recursos del servidor: uno tiene que ver la solicitud en sí, determinar a qué quiere acceder el visitante, obtenerlo de la base de datos, generar la respuesta HTML, etc.

Una de las razones por las que un sistema de caché acelera el tiempo de carga de su sitio web debería ser bastante obvia ahora: básicamente ahorra este tiempo de procesamiento. Cuando llega una solicitud específica por primera vez ("envíame tu página de inicio"), WordPress se inicia y genera la respuesta. Si hay un caché, almacena dicha respuesta antes de que se envíe al visitante. De esta manera, futuras solicitudes a ese mismo recurso (en nuestro ejemplo, una página de inicio) ya no requerirán que WordPress procese nada; el caché puede devolver la copia que guardó antes, ahorrando así tiempo y recursos.

Con este rendimiento en mente, no es difícil imaginar cuáles son las razones por las que podemos ver un uso elevado de la CPU en nuestro servidor:

• Recibes demasiadas solicitudes. Si muchos usuarios llegan a tu sitio web al mismo tiempo, o si recibes muchas solicitudes ilegítimas (probablemente alguien esté atacando tu servidor), WordPress tendrá que procesar todas esas solicitudes y, por lo tanto, el uso de los recursos del servidor aumentará.
• Las solicitudes tardan en resolverse. Si tiene muchos complementos instalados o algunos de sus complementos son ineficientes por cualquier motivo, todas las solicitudes que reciba tardarán más de lo necesario, porque WordPress ejecutará una gran cantidad de código ineficiente.

Entonces parece que un caché es una buena protección contra estos problemas, ¿verdad? Y de hecho lo es. Sin embargo, tenga en cuenta que el caché no "soluciona" el problema; simplemente lo “oculta”. Y es importante recordar esto porque hay funcionalidades de WordPress que no se pueden almacenar en caché y, por lo tanto, siempre requerirán la ejecución de WordPress:

• Tareas programadas usando WP-Cron. WP-Cron es un mecanismo de WordPress para programar tareas que se ejecutarán en el futuro. Por ejemplo, WordPress lo usa para publicar publicaciones programadas.
• API REST de WordPress. La API REST es una interfaz que se puede usar desde aplicaciones de terceros para interactuar con un sitio de WordPress enviando y recibiendo objetos JSON. Algunas solicitudes de API REST pueden almacenarse en caché (es decir, solicitudes GET), pero otras no (POST y PUT). Por lo tanto, es algo que generalmente no se puede almacenar en caché...
• Solicitudes AJAX en WordPress. Antes de que tuviéramos la API REST en WordPress, teníamos que usar su API AJAX para crear sitios web dinámicos. Esta API es bastante similar a la API REST, porque también podemos usarla para enviar y recibir información del servidor. Es un sistema diferente, pero está sujeto a las mismas limitaciones que la API REST.

Analizando el problema

Primero tenemos que identificar por qué ha aumentado el uso de la CPU en nuestro sitio web. ¿Ha aumentado el número de solicitudes a nuestro sitio web? ¿Es ahora más lento atender solicitudes individuales? Para responder a estas preguntas contamos con una herramienta muy útil en nuestro servidor: el registro de acceso .

El registro de acceso es un archivo de texto en el que el servidor registra todas y cada una de las solicitudes que recibe junto con información útil sobre ellas. Específicamente, el registro de acceso nos dice cuándo se recibió una solicitud (fecha y hora), quién la hizo (una IP), qué recurso solicitó (una URL), si la solicitud fue exitosa, etc. Aquí hay un ejemplo de nuestro servidor :

 66.249.83.82 - - [22/Apr/2020:14:04:59 +0200] "GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0" 200 22325 "-" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" 66.249.83.84 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/aziz-acharki-549137-unsplash-540x350.jpg HTTP/1.0" 200 10566 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" 66.249.83.82 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/Screenshot-of-Unsplah-website-768x520.png HTTP/1.0" 200 399577 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19" ... 188.79.17.218 - - [22/Apr/2020:14:06:14 +0200] "GET /es/blog/problemas-mas-comunes-de-wordpress/ HTTP/1.0" 200 110741 "https://www.google.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" 188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-content/plugins/nelio-ab-testing/assets/dist/js/alternative-loader.js?version=52b0ff65c68ab39896d47d6ff673fd59 HTTP/1.0" 200 2763 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" 188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-includes/css/dist/block-library/style.min.css?ver=5.4 HTTP/1.0" 200 7627 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15" ...

Echémosle un vistazo más de cerca:

• 66.249.83.82 . Esta es la IP del dispositivo que realizó la solicitud.
• 22/Apr/2020:14:04:59 +0200 . Esta es la fecha y hora exactas de la solicitud.
• GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0 . Luego vemos que el visitante solicitó ( GET ) una publicación de nuestro blog (en español).
• Mozilla/5.0 (Linux; Android ... Este es el User-Agent del navegador y nos brinda cierta información sobre el dispositivo y el sistema operativo que realizó la solicitud.

Observe cómo nuestro servidor recibió varias solicitudes de la misma IP ( 66.249.83.82 ) después de la primera. Esto puede parecer un ataque, pero en realidad no lo es: las páginas web suelen incluir varios activos (imágenes, secuencias de comandos, estilos) y es completamente normal que un visitante que acceda a una determinada página web de su sitio realice varias solicitudes para recuperarlos todos. .

Pues bien, en nuestro caso pudimos comprobar que, efectivamente, teníamos un número de solicitudes inusualmente alto. Extremadamente alto, en realidad. Y lo sabíamos porque el archivo de registro era mucho más grande de lo habitual.

Una posible explicación sería que hubo un pico de visitas por alguna razón… pero según Google Analytics, no fue así. Así que algo diferente estaba sucediendo.

Un análisis más detallado del registro de acceso nos permitió identificar el siguiente hecho: más del 15% de todas las solicitudes que estábamos recibiendo provenían de la misma IP. ¡Y (redoble de tambores) esa IP era nuestro propio servidor web!

Identificando al culpable

En este punto finalmente supimos que era nuestro propio servidor el que hacía tantas solicitudes que generaba un pico en su uso de CPU. ¿Pero por qué? ¿Por qué estaba pasando esto? ¿Quién generaba esas solicitudes? Estas son preguntas más difíciles de responder.

Primero volvimos a mirar nuestros registros, filtrando por IP e intentando identificar un patrón que pudiera arrojar algo de luz sobre el problema en cuestión:

 35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:06:18 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:07:21 +0200] "GET /es?..." "php-requests/1.7-3470169" 35.214.244.124 - - [22/Apr/2020:14:07:24 +0200] "GET /es?..." "php-requests/1.7-3470169" ...

y encontramos uno: el User-Agent de todas estas solicitudes anormales fue php-requests/1.7-3470169 . ¡Interesante!

WordPress tiene varias funciones con las que activar solicitudes: wp_remote_request . Si observa el código fuente de estas funciones, verá que básicamente envuelven algunos métodos de una clase llamada WP_Http . Esta clase es interesante porque, por defecto, todas las solicitudes que realiza configuran el User-Agent en "WordPress/version", por lo que es posible que esto tenga algo que ver con nuestro problema. Pero no lo hizo... todavía.

Si seguimos inspeccionando el código fuente de WordPress, vemos que WP_Http usa otra clase de WordPress internamente para realizar las solicitudes: Requests . Y chico, esta clase es interesante: al principio de su definición vemos que define una constante llamada VERSION cuyo valor es 1.7-3470169 . Y un poco más tarde, usa esta constante para construir el User-Agent que encontramos en nuestros registros: php-requests/1.7-3470169 .

¡Brillante! Ahora hemos confirmado que todas estas extrañas solicitudes que recibimos provienen de nuestro sitio de WordPress. Esto probablemente significa que el culpable es un complemento... pero ¿cuál?

La idea que teníamos para resolver esto era bastante simple: si modificamos el User-Agent para que incluya el nombre del complemento que usa la clase Requests , veremos el nombre del complemento en el registro de acceso de nuestro servidor. Y esto es bastante fácil de lograr. Todo lo que hicimos fue editar la función Requests ' get_default_options con el siguiente fragmento:

 $trace = debug_backtrace(); $files = []; foreach ( $trace as $log ) { if ( false !== strpos( $log['file'], '/wp-content/plugins/' ) ) { $files[] = $log['file']; } } if ( empty( $files ) ) { $debug = 'no-plugin'; } else { $plugins = array_map( function( $x ) { return preg_replace( '/.*\/wp-content\/plugins\/([^\/]+)\/.*/', '$1', $x ); }, $files ); $plugins = array_unique( $plugins ); $debug = implode( ' ', $plugins ); } $defaults['useragent'] .= " (NelioDebug {$debug})";

Veamos qué hace paso a paso:

• Primero obtenemos la pila de ejecución con debug_backtrace . Esta es una función PHP que genera un backtrace, revelando todas las funciones que han sido llamadas para llegar a la actual.
• Para cada elemento de la pila de ejecución tenemos información como la función que ha sido invocada, el archivo y la línea en la que está definida, los argumentos con los que ha sido llamada, etc. Sin embargo, en lo que queremos centrarnos es en la archivo donde se definió la función: si está en wp-content/plugins , sabemos con certeza que es una función definida en un complemento.
• Una vez que hayamos procesado todos los elementos en la pila, simplemente necesitamos obtener los nombres (si los hay) de todos los complementos que hemos encontrado e incluirlos en la variable useragent .

Después de extender WordPress como se describe, rápidamente comenzamos a ver quién era el culpable :

 35.214.244.124 - - [23/Apr/2020:10:59:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:20 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:36 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:00:01 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:05:21 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" ...

Resolviendo el problema

Una vez que supimos el nombre del complemento ofensivo, simplemente contactamos a su desarrollador y le pedimos ayuda. Respondieron y nos dijeron cómo superar el problema mientras trabajaban en una solución adecuada. Afortunadamente para nosotros, las cosas mejoraron rápidamente:

Como puedes ver, una de las grandes cosas del software libre es que podemos explorar el código fuente de las aplicaciones que usamos y adaptarlo a nuestras necesidades. En este caso, pudimos modificar el propio WordPress para que pudiera revelar cierta información que necesitábamos.

Espero que les haya gustado el truco de usar debug_backtrace para averiguar quién ejecuta una determinada función. Claro, no es un método ortodoxo, pero es rápido de implementar y, hasta ahora, siempre ha demostrado ser extremadamente útil.

Imagen destacada de Michal Mancewicz en Unsplash.