PrestaShop en 502 pendant un crawl de facettes : le serveur allait bien, la file d’attente a lâché

Une boutique PrestaShop 1.7.8 en 502 Bad Gateway sur toutes les pages. Sur un échantillon de 5 000 requêtes : 2 453 réponses en 502, 1 384 en 504, et 4 en 200. Côté serveur, rien d’anormal : disque rempli à 42 %, 13 Go de RAM libre sur 16, MariaDB et nginx démarrés. Pourtant, dès qu’on a bloqué le trafic abusif en amont, la boutique est repassée en 200 dans la journée. Ce 502 tenait en trois éléments empilés : un robot qui explorait des milliers de combinaisons de filtres, une table de module sans index, et un pool PHP-FPM de 5 workers partagé avec cinq autres boutiques. Aucun des trois ne produisait d’erreur applicative.

La supervision a alerté, mais sur la mauvaise question

Notre sonde d’uptime avait bien sonné, cinq fois dans la journée, sur le chat de l’équipe et par e-mail. Mais la boutique se dégradait depuis minuit, en alternant timeouts et réponses normales. Trois cycles « panne, rétablissement » dans la nuit, indiscernables d’un flapping ordinaire, puis un vrai 502 en fin de matinée, celui qui a déclenché l’intervention.

Le vrai défaut était ailleurs. Sur la journée, 388 contrôles ont réussi avec 2,8 secondes de moyenne et des pointes à 7,7 secondes, sans rien déclencher, puisque le code était 200. Une sonde d’uptime ne connaît que « up » et « down ». Une boutique qui répond en 7 secondes n’est ni l’un ni l’autre, et c’est exactement là qu’elle a passé la nuit.

Au passage, la sonde interrogeait le domaine sans www, qui répondait en 302 : elle ne mesurait même pas le vrai hôte.

Les fausses pistes : disque, RAM et « il suffit d’ajouter des workers »

df -h, free -m, l’état des services : tout était correct. Le diagnostic est venu des logs nginx et PHP-FPM, de la processlist MariaDB et de la volumétrie des tables.

L’autre réflexe courant, augmenter pm.max_children, on l’a prévu, mais en dernier. Tant qu’on ne sait pas pourquoi chaque worker reste occupé plusieurs secondes, plus de workers qui attendent la même requête SQL lente, c’est surtout plus de connexions MariaDB et plus de mémoire consommée, sur un serveur partagé.

Pourquoi PrestaShop renvoie des 502 alors que rien n’est en panne : le calcul

Les ordres de grandeur relevés : jusqu’à 8 000 requêtes par heure sur les URLs à facettes, des pages à 5 à 10 secondes, et un pool PHP-FPM limité à 5 workers, tous occupés en continu.

Avec 5 workers et une page à 5 secondes, le pool traite au mieux une requête par seconde, soit 3 600 par heure, pour toutes les boutiques du pool réunies. À 10 secondes par page, on tombe à 1 800. Un crawler à 8 000 requêtes par heure sur une seule boutique dépasse la capacité totale. Les requêtes suivantes s’empilent : nginx renvoie d’abord un 502 quand le socket FPM refuse la connexion, puis un 504 quand l’attente dépasse son timeout de 60 secondes. Aucun composant n’est en panne : c’est une file d’attente qui déborde.

Pourquoi des pages aussi lentes ? Deux couches.

Chaque combinaison de filtres est un cache miss

Le crawler, deux User-Agents déguisés en Chrome et sans referer, parcourait des URLs du type (exemple fictif) /12-categorie?q=Couleur-Bleu/Taille-M/Prix-€-20-50. Le paramètre q= est celui que ps_facetedsearch construit pour encoder les filtres actifs. La clé du cache du bloc de filtres est calculée ainsi (v4.0.1 enregistrée en base sur la boutique, fichiers en v4.0.4 sur le disque, code identique) :

// ps_facetedsearch v4.0.1, src/Product/SearchProvider.php, generateCacheKeyForQuery()
$filterHash = md5(
    sprintf(
        '%d-%d-%d-%s-%d-%s',
        (int) $context->shop->id,
        (int) $context->currency->id,
        (int) $context->language->id,
        $filterKey,
        (int) $context->country->id,
        serialize($facetedSearchFilters)
    )
);

Le code est identique en v5.1.0. Les filtres actifs sont sérialisés dans la clé : une nouvelle combinaison, c’est une nouvelle clé, un calcul complet du bloc, et, avec le cache des filtres activé (PS_LAYERED_CACHE_ENABLED = 1), une ligne de plus dans layered_filter_block. Un robot qui suit tous les liens ne réutilise jamais le cache. Résultat : 47 759 combinaisons en cache, 229 Mo, pour un catalogue de 137 produits. Et ce cache n’a ni durée de vie ni éviction : rien dans le module ne l’empêche de grossir.

Une table de module lue en full scan deux à trois fois par page

Seconde couche : un module de popup tiers mémorisait qu’un visiteur avait vu la popup en écrivant une ligne par page vue sans cookie, donc à chaque requête de robot. Plus de 1,7 million de lignes.

Chaque page lisait cette table deux à trois fois par une recherche sur une colonne de hash visiteur. La table n’avait ni clé primaire ni index. Chaque lecture était un scan complet, autour de 2 secondes sous la charge de l’incident (573 ms mesurés au calme le lendemain). Et chaque visite de robot rendait la suivante plus lente.

Le plus beau : en ouvrant la table, 100 % des lignes valaient []. Le module scannait 1,7 million de lignes pour relire un état vide, puis en écrivait une de plus.

C’est le cœur du bug muet : aucune requête n’échoue, aucune exception n’est levée. Le module ne supporte simplement pas qu’on le visite des milliers de fois par heure.

Comment vérifier si votre boutique PrestaShop est concernée

Quatre contrôles, du moins coûteux au plus coûteux. Les noms de table et de colonne du module sont réécrits pour l’article.

1. Le log PHP-FPM, pas le log PHP. Quand le pool est plein, PHP-FPM est le seul à le dire, dans son propre journal. En mode dynamic, le message est :

WARNING: [pool www] server reached pm.max_children setting (5), consider raising it

Il décrit la conséquence, pas la cause. Pendant l’incident, il était bien là, et c’était la seule trace d’erreur de toute la panne : pas une exception PHP, pas une erreur MariaDB, juste cette ligne répétée dans le journal FPM.

2. La part des URLs à facettes dans le trafic. Dans le log d’accès nginx :

grep -cE '[?&]q=' /var/log/nginx/access.log
awk '{print $1}' /var/log/nginx/access.log | sort | uniq -c | sort -rn | head

Réserve : derrière un load balancer, comme ici, nginx ne voit que son IP. Les IP réelles se lisent alors dans les analytics du CDN, Cloudflare dans notre cas.

3. La volumétrie des tables. Lister les plus grosses tables fait souvent apparaître l’intrus :

SELECT table_name, table_rows,
       ROUND((data_length + index_length) / 1024 / 1024) AS size_mb
FROM information_schema.tables
WHERE table_schema = DATABASE()
ORDER BY table_rows DESC
LIMIT 15;

SELECT COUNT(*) FROM ps_module_user;
SELECT COUNT(*) FROM ps_layered_filter_block;

table_rows est une estimation pour InnoDB, le COUNT(*) donne le vrai chiffre. Ici, ps_connections et ps_guest dépassaient aussi 2,9 millions de lignes chacune.

4. Le plan d’exécution.

SHOW INDEX FROM ps_module_user;
EXPLAIN SELECT COUNT(*) FROM ps_module_user WHERE visitor_hash = 'a1b2c3...';

SHOW INDEX ne renvoyait rien, et l’EXPLAIN affichait type = ALL, key = NULL sur environ 1,5 million de lignes estimées.

Le réflexe à retenir

Le correctif, par couches et dans cet ordre

L’ordre compte, parce que le pool est partagé : toute intervention sur PHP-FPM ou MariaDB touche aussi les autres boutiques.

1. Contenir le crawl des facettes en amont

L’action d’urgence a été une règle WAF Cloudflare bloquant les requêtes dont la query string contient q=. Un blocage global gêne aussi les visiteurs qui filtrent réellement. Le lendemain, on l’a transformé en Managed Challenge, avec une exception pour les robots vérifiés des moteurs de recherche. Bilan sur cette règle : 36 300 requêtes challengées, 0 % de résolution. Aucun humain n’était derrière.

L’exception porte sur le statut « robot vérifié » calculé par le CDN, pas sur le User-Agent : notre crawler se présentait comme Chrome, le prochain se dira Googlebot.

Deux pièges :

• sur l’offre gratuite, le rate limiting ne peut pas cibler la query string. On a donc limité les pages HTML (chemins sans extension) à 15 requêtes par 10 secondes et par IP, blocage 10 secondes, sans toucher aux assets. En test, une rafale de 32 pages donne 22 réponses en 200 puis 10 en 429, et un visiteur normal est de nouveau servi 15 secondes après.
• le mode anti-bot global du CDN est resté désactivé : il aurait challengé les webhooks des prestataires de paiement et de livraison.

Googlebot et bingbot passent toujours.

robots.txt, en complément. Ajouté directement dans le fichier en production :

Disallow: /*?q=
Disallow: /*&q=

Il vise les robots vérifiés, exemptés du challenge : après celui-ci, ce sont les seuls qui atteignaient encore les facettes.

Détail vérifié dans le core : PrestaShop 9.0.0 ajoute nativement ?q= et &q= à la liste des paramètres bloqués (Tools::getRobotsContent()), mais ni 1.7.8.11 ni 8.2.1 ne le font. Et Tools::generateRobotsFile() réécrit le fichier entier : un clic sur « Générer robots.txt » dans le back-office efface les lignes ajoutées à la main. On a versionné le fichier pour que l’écrasement se voie dans le diff. Le hook actionAdminMetaBeforeWriteRobotsFile permet de les injecter proprement depuis un module. C’est aussi un des petits gains de la migration de PrestaShop 1.7 vers 8 puis 9.

Enfin, les pages filtrées portent un noindex, follow, posé par le thème dès que q est présent, sans toucher à ps_facetedsearch. Canonical et rel="nofollow" sur les filtres étaient déjà en place.

2. Réduire le coût unitaire d’une page

L’index sur la colonne de hash. Le correctif le plus rentable :

ALTER TABLE ps_module_user
  ADD INDEX idx_visitor_hash (visitor_hash), ALGORITHM=INPLACE, LOCK=NONE;
-- rollback :
-- DROP INDEX idx_visitor_hash ON ps_module_user;

On l’avait estimé entre 20 et 60 secondes. En production, sur 1,72 million de lignes : 6,4 secondes, sans bloquer lectures ni écritures. On l’a appliqué par un script idempotent qui passe par le bootstrap PrestaShop (aucun mot de passe à manipuler), validé d’abord en local sur un dump. Exemple réécrit :

<?php

declare(strict_types=1);

require_once __DIR__ . '/../config/config.inc.php';

$db = Db::getInstance();
$table = _DB_PREFIX_ . 'module_user';

if ([] !== (array) $db->executeS('SHOW INDEX FROM `' . bqSQL($table) . '`')) {
    echo "Index already present\n";
    return;
}

$db->execute(
    'ALTER TABLE `' . bqSQL($table) . '` ADD INDEX idx_visitor_hash (visitor_hash), ALGORITHM=INPLACE, LOCK=NONE'
);

Mesures avant et après :

L’index est aussi déclaré dans le script d’installation du module, pour survivre à une réinstallation.

La purge, et le patch. Comme toutes les lignes valaient [], vider la table ne faisait rien perdre : 88 Mo libérés. Mais vider sans corriger, c’est recommencer. Le module est resté (la popup a servi à Noël et resservira) et on l’a patché : plus aucune lecture ni écriture sur la table pour une page vue par un robot, les écritures légitimes (fermeture de la popup) inchangées. Contrôle : 6 pages vues sans cookie, 0 ligne ajoutée. Pour que le back-office ne propose plus une mise à jour qui écraserait le patch, sa version a été volontairement gonflée, avec une procédure de retour documentée.

Le cache de facettes et les statistiques. layered_filter_block a été vidé (229 Mo rendus, pages filtrées à 0,7 à 0,8 seconde en reconstruisant le cache à la demande). ps_connections et ps_guest ont été purgés à 90 jours, après sauvegarde, en ne supprimant un invité que si plus aucune table ne le référence. Au total, la base est passée de 966 à 441 Mo. Une fois les robots bloqués en amont, les connexions enregistrées sont tombées de 45 000 à 56 000 par jour à moins de 2 000, soit 95 % de moins : c’est l’ordre de grandeur de la part des robots dans ce qu’on appelait « visites ».

3. Dimensionner PHP-FPM et MariaDB, en dernier

La demande à l’infogérant était prête. pm.max_children se calcule depuis la mémoire réelle d’un worker :

ps --no-headers -o rss -C php-fpm7.2 | awk '{ s += $1; n++ } END { printf "%.0f Mo\n", s / n / 1024 }'

Environ 130 Mo par worker ici, sur 16 Go de RAM partagés avec MariaDB : on visait 20 workers. S’y ajoutaient deux directives absentes du pool, request_terminate_timeout = 60s pour couper un worker bloqué, et request_slowlog_timeout = 5s pour tracer toute requête lente. Côté MariaDB 10.3, innodb_buffer_pool_size était resté à la valeur par défaut, 128 Mo sur une machine de 16 Go : on visait 2 Go, avec le slow query log à long_query_time = 2.

Cette demande n’est jamais partie. La boutique a été reprise sur notre cluster Kubernetes, où le dimensionnement PHP-FPM, les timeouts et la limitation de débit sur les pages à facettes font partie du socle. Le raisonnement ne change pas : on dimensionne une fois que chaque page coûte ce qu’elle doit coûter.

Le diagnostic ressemble à celui d’un back-office PrestaShop lent, mais tout part ici du front. Pour la lecture des EXPLAIN, voir optimiser les requêtes SQL sur PrestaShop.

Surveiller la latence, pas seulement la disponibilité

La leçon la moins technique et la plus importante : une alerte binaire a laissé passer une nuit entière de dégradation. On a ajouté à notre outil de supervision un type d’alerte dédié au temps de réponse :

• ouverture après 3 contrôles consécutifs au-dessus de 5 secondes, fermeture après 3 sous 3,5 secondes, pour ne pas osciller ;
• les contrôles en échec sont ignorés, pas comptés comme rapides ;
• canal de l’équipe uniquement, en avertissement : une boutique à 6 secondes n’est pas injoignable, et la confondre avec une panne polluerait les alertes clients.

Un test de non-régression rejoue les temps réels de la journée d’incident et doit ouvrir l’alerte.

On voulait aussi sonder une page catégorie filtrée. Impossible : elle est désormais challengée par le CDN et répondrait 403 à la sonde. On surveille une page catégorie sans filtre, déjà bien plus coûteuse que l’accueil.

Ce qu’on retient de ce 502

Aucun composant n’était en panne : un robot a trouvé un chemin où chaque requête coûtait cher (une combinaison de facettes jamais en cache, plus deux à trois scans complets d’une table qui ne contenait que des []), et 5 workers partagés ont fait le reste. On a traité dans l’ordre : contenir le crawl en amont, rendre chaque page moins chère, puis dimensionner. Si une de vos boutiques alterne 502 et 200 sans autre erreur qu’un warning PHP-FPM, c’est ce genre de diagnostic qu’on fait en TMA.