Débugger un WordPress multisites en mode bourrin
Cet article a été publié il y a 7 ans 5 mois 2 jours, il est donc possible qu’il ne soit plus à jour. Les informations proposées sont donc peut-être expirées.Récemment, je suis tombé sur un bug étrange : le site, basé sur WordPress est correctement installé, la connexion à la base de données fonctionne (testée en ligne de commandes, puis avec un script maison), et pourtant, il affiche une erreur de connexion à la base de données. Il aura fallu beaucoup de patience, d’essais, et de bidouille de barbu pour avoir la solution. C’est vicieux.
Posons le décor : il s’agit de créer une version de pré-production d’un site en production. Il a donc simplement été « cloné » (base + fichiers), dans un VirtualHost à part avec une configuration FPM dédiée. Le WordPress est un multisites, et il est configuré de manière habituelle, avec dans le fichier wp-config.php les paramètres suivants :
|
1 2 3 4 5 6 7 |
define('MULTISITE', true); define('WP_ALLOW_MULTISITE', true); define('SUBDOMAIN_INSTALL', false); define('DOMAIN_CURRENT_SITE', 'preprod.site.com'); define('PATH_CURRENT_SITE', '/'); define('SITE_ID_CURRENT_SITE', 1); define('BLOG_ID_CURRENT_SITE', 1); |
Dans la base, le siteurl (et le home) est également sur le bon domaine :
|
1 2 3 4 5 6 |
mysql> select option_name, option_value from wp_options where option_name = 'siteurl'; +-------------+---------------------------+ | option_name | option_value | +-------------+---------------------------+ | siteurl | http://preprod.site.com | +-------------+---------------------------+ |
Après avoir vu fonctionner l’accès à la base dans le même environnement que le site en question, j’ai cherché dans les erreurs PHP. Rien, nada, que dalle, nib. Même en mode debug.
L’étape suivante, le truc de barbu, capturer une trace de l’exécution des threads FPM (le pool est appelé « preprod ») lors de l’appel au site. C’est assez violent, j’avoue, mais ça fonctionne pas mal :
|
1 |
strace $(ps fauxw | egrep "fpm" | egrep "preprod" | awk '{print"-p " $2 " -v -vv -f -ff -o /tmp/strace_fpm.log"}' | tr "\n" " ") |
Je remercie Djerfy qui s’était attelé à résoudre un problème sur lequel nous pauvres petits admins butions, et qui a donc lancé cette routine sur un serveur que nous infogérons. Cette commande va donc vous créer un fichier de trace de chaque process FPM lancé (le pid du process est en suffixe, le filtre « preprod » permettant d’isoler le bon pool). J’ai ensuite filtré le fichier récupéré grâce à grep sur le mot-clé « sql » :
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_m"..., 64, MSG_DONTWAIT, NULL, NULL) = 64 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_EN"..., 50, MSG_DONTWAIT, NULL, 0) = 50 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 |
Erf, je n’ai pas les messages en entier, mais ceux-ci ressemblent tout de même à des requêtes SQL. On affine un peu, on ajoute une ou deux options par-ci par-là (on filtre notamment les sendto et les recvfrom qui concernent le SQL), la commande devient maintenant :
|
1 |
strace $(ps fauxw | egrep "fpm" | egrep "preprod" | awk '{print"-p " $2 " -e sendto,recvfrom -v -vv -f -ff -t -tt -T -s 512 -o /tmp/strace_fpm.log"}' | tr "\n" " ") |
Là, on voit quelque chose d’un peu plus parlant :
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 |
1460038240.515568 recvfrom(5, "N\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000032> 1460038240.515746 recvfrom(5, "\n5.6.29-log\0D\0\0\0{o9j/GYi\0\377\367\10\2\0\177\200\25\0\0\0\0\0\0\0\0\0\0$r7W1.3V6IN+\0mysql_native_password\0", 82, MSG_DONTWAIT, NULL, NULL) = 78 <0.000031> 1460038240.515847 sendto(5, "q\0\0\1\r\242\n\0\0\0\0\300\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0preprod_site\0\24\24\206\244\2722Q\351+\315\255\257?t4h\266#\3430\"\0mysql_native_password\0\25\f_client_name\7mysqlnd", 117, MSG_DONTWAIT, NULL, 0) = 117 <0.000034> 1460038240.515965 recvfrom(5, "\7\0\0\2", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000029> 1460038240.516087 recvfrom(5, "\0\0\0\2\0\0\0", 82, MSG_DONTWAIT, NULL, NULL) = 7 <0.000027> 1460038240.516214 sendto(5, "\17\0\0\0\3SET NAMES utf8", 19, MSG_DONTWAIT, NULL, 0) = 19 <0.000033> 1460038240.516351 recvfrom(5, "\7\0\0\1\0\0\0\2\0\0\0", 75, MSG_DONTWAIT, NULL, NULL) = 11 <0.000029> 1460038240.516434 sendto(5, "\32\0\0\0\3SELECT @@SESSION.sql_mode", 30, MSG_DONTWAIT, NULL, 0) = 30 <0.000031> 1460038240.516589 recvfrom(5, "\1\0\0\1\1(\0\0\2\3def\0\0\0\22@@SESSION.sql_mode\0\f!\0B\0\0\0\375\0\0\37\0\0\5\0\0\3\376\0\0\2\0\27\0\0\4\26N", 64, MSG_DONTWAIT, NULL, NULL) = 64 <0.000028> 1460038240.516726 recvfrom(5, "O_ENGINE_SUBSTITUTION\5\0\0\5\376\0\0\2\0", 82, MSG_DONTWAIT, NULL, NULL) = 30 <0.000028> 1460038240.516840 sendto(5, ".\0\0\0\3SET SESSION sql_mode='NO_ENGINE_SUBSTITUTION'", 50, MSG_DONTWAIT, NULL, 0) = 50 <0.000032> 1460038240.516961 recvfrom(5, "\7\0\0\1\0\0\0\2\0\0\0", 52, MSG_DONTWAIT, NULL, NULL) = 11 <0.000023> 1460038240.517037 sendto(5, "\17\0\0\0\2preprod_site", 19, MSG_DONTWAIT, NULL, 0) = 19 <0.000028> 1460038240.517143 recvfrom(5, "\7\0\0\1\0\0\0\2\0\0\0", 41, MSG_DONTWAIT, NULL, NULL) = 11 <0.000023> 1460038240.520407 sendto(5, "J\0\0\0\3SELECT * FROM wp_blogs WHERE domain = 'preprod.site.com' AND path = '/'", 78, MSG_DONTWAIT, NULL, 0) = 78 <0.000034> 1460038240.520690 recvfrom(5, "\1\0\0\1\fB\0\0\2\3def\16preprod_site\10w", 30, MSG_DONTWAIT, NULL, NULL) = 30 <0.000024> 1460038240.520799 recvfrom(5, "p_blogs\10wp_blogs\7blog_id\7blog_id\f?\0\24\0\0\0\10\3B\0\0\0B\0\0\3\3def\16preprod_site\10wp_blogs\10wp_b", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000023> 1460038240.520907 recvfrom(5, "logs\7site_id\7site_id\f?\0\24\0\0\0\10\1\0\0\0\0@\0\0\4\3def\16preprod_site\10wp_blogs\10wp_blogs\6domain\6", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000028> 1460038240.521032 recvfrom(5, "domain\f!\0X\2\0\0\375\t@\0\0\0<\0\0\5\3def\16preprod_site\10wp_blogs\10wp_blogs\4path\4path\f!\0,\1\0\0\375\1@\0\0", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000028> 1460038240.521152 recvfrom(5, "\0H\0\0\6\3def\16preprod_site\10wp_blogs\10wp_blogs\nregistered\nregistered\f?\0\23\0\0\0\f\201\0\0\0\0L\0\0\7\3", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000028> 1460038240.521271 recvfrom(5, "def\16preprod_site\10wp_blogs\10wp_blogs\flast_updated\flast_updated\f?\0\23\0\0\0\f\201\0\0\0\0@\0\0\10\3de", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000033> 1460038240.521392 recvfrom(5, "f\16preprod_site\10wp_blogs\10wp_blogs\6public\6public\f?\0\2\0\0\0\1\1\0\0\0\0D\0\0\t\3def\16preprod_site", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000027> 1460038240.521508 recvfrom(5, "\10wp_blogs\10wp_blogs\10archived\10archived\f?\0\2\0\0\0\1\1\0\0\0\0@\0\0\n\3def\16preprod_site\10wp_blog", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000027> 1460038240.521625 recvfrom(5, "s\10wp_blogs\6mature\6mature\f?\0\2\0\0\0\1\1\0\0\0\0<\0\0\v\3def\16preprod_site\10wp_blogs\10wp_blogs\4spa", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000027> 1460038240.521742 recvfrom(5, "m\4spam\f?\0\2\0\0\0\1\1\0\0\0\0B\0\0\f\3def\16preprod_site\10wp_blogs\10wp_blogs\7deleted\7deleted\f?\0\2\0\0", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000028> 1460038240.521865 recvfrom(5, "\0\1\1\0\0\0\0B\0\0\r\3def\16preprod_site\10wp_blogs\10wp_blogs\7lang_id\7lang_id\f?\0\v\0\0\0\3\t@\0\0\0\5\0\0\16\376", 82, MSG_DONTWAIT, NULL, NULL) = 82 <0.000028> 1460038240.521986 recvfrom(5, "\0\0\2\0\5\0\0\17\376\0\0\2\0", 82, MSG_DONTWAIT, NULL, NULL) = 13 <0.000029> 1460038240.541916 sendto(5, "\1\0\0\0\1", 5, MSG_DONTWAIT, NULL, 0) = 5 <0.000043> |
Donc il en exécute des requêtes, et pourtant il affiche l’erreur de connexion, mais que se passe-t-il ? On découvre dans ce fatras une requête sur une table wp_blogs, par curiosité, je la lance à la main sur la base :
|
1 2 |
mysql> select * from wp_blogs where domain = 'preprod.site.com' and path = '/'; Empty set (0.00 sec) |
Ah, étrange, mais que pourrait-il donc y avoir dans cette table ?
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 |
mysql> select * from wp_blogs\G *************************** 1. row *************************** blog_id: 1 site_id: 1 domain: www.site.com path: / registered: 2014-12-09 09:25:58 last_updated: 2016-03-30 13:53:57 public: 1 archived: 0 mature: 0 spam: 0 deleted: 0 lang_id: 0 *************************** 2. row *************************** blog_id: 3 site_id: 1 domain: www.site.com path: /actualites/ registered: 2015-02-19 10:17:30 last_updated: 2016-03-25 14:44:33 public: 1 archived: 0 mature: 0 spam: 0 deleted: 0 lang_id: 0 2 rows in set (0.01 sec) |
Oh, le joli champ domain qui ne correspond pas du tout. On a déjà une copie de la base, on va donc se permettre de modifier les domain en direct :
|
1 2 |
mysql> update wp_blogs set domain = "preprod.site.com" where blog_id = '1' or blog_id = '3'; Query OK, 2 rows affected (0.00 sec) |
Devinez quoi ? Le site s’affiche instantanément.
Je ne sais pas pourquoi il persiste à afficher l’erreur de connexion à la base de données alors que la connexion fonctionne parfaitement, et qu’il ne trouve simplement pas de site correspondant au domaine à afficher. Mais voilà, si jamais vous devez manipuler un WordPress multisites, vous êtes prévenus.
La commande strace utilisée plus haut va m’être très utile. En effet, je n’ai toujours pas réussi à corriger le tir sur l’article 1 de la série de la sécurisation de serveur, qui fait planter FPM. Souhaitez-moi bonne chance.
PS : l’après-midi après avoir planifié l’article, j’ai trouvé la solution au problème. Compte-rendu de l’enquête très bientôt.
Si tu veux je dois avoir une commande (qui traine quelque part) pour afficher correctement une requête à partir d’un strace, disons que c’est plus lisible. J’te donnerais ça dans la semaine (le temps de chercher)…
Côté WordPress tu peux aussi regarder pour optimiser le fichier wp-config avec l’ajout des paramètres tel que WP_HOME et WP_SITEURL. Ces paramètres vont surcharger ce que tu as justement en base et éviter ces dysfonctionnements entre environnements 🙂