Résumé : quand elle est chaînée à un head -n 1
, la commande rabbitmqctl
affiche ce qu'on attend d'elle mais aussi une erreur « Error: Terminated ». Oui, head
termine son exécution dès qu'elle a affiché le nombre de ligne qu'on lui a demandé. Se faisant, elle n'écoute plus ce qui se raconte dans le pipe. L'écriture dans un pipe sans lecteur déclenche l'envoi d'un signal SIGPIPE à l'écrivain (rabbitmqctl
dans le cas présent).
Ce signal peut fermer le programme (traitement par défaut), déclencher un bout de code maison ou être ignoré (c'est le cas de rabbitmqctl
) et/ou déclencher un comportement pas vraiment prévu (c'est le cas de rabbitmqctl
).
On profite de l'occasion pour réviser l'utilisation de strace
(« -f » et « -e » et la différenciation entre une fonction de la libc et un appel système ‒ fork()
versus clone()
‒ sont les pièges habituels), les signaux Linux (leur héritage, leur traitement avec signal
/ sigaction
, la structure de données siginfo_t
, etc.), l'appel système write()
(qui permet d'écrire dans un fichier, comme la console), les compétitions entre processus (si rabbitmqctl
va assez vite, il peut terminer avant que head
termine, donc aucune erreur s'affiche), et les limites des outils de diagnostic (un signal émit durant un appel système est annoncé comme venant du processus qui a effectué cet appel, pas du noyau, strace -f
fait disparaître l'erreur donc impossible de la tracer…).
J'utilise RabbitMQ.
Pour regarder les entrailles de mon installation, j'utilise l'outil rabbitmqctl
. Exemple : rabbitmqctl -p <virtual_host> list_queues | head -n 3
.
Une fois sur deux, cette commande me retourne le résultat (la liste des files d'attente) ainsi que l'erreur « Error: Terminated ».
Aucune erreur est affichée si j'utilise grep
à la place de head
. Si je n'utilise pas la commande head
, je n'ai pas de problème.
La réponse est évidente : head
se termine (exit()
) dès qu'elle a affiché le nombre de lignes qu'on lui demande, donc le fichier « stdin » est fermé… Sauf que ce fichier est toujours le « stdout » de rabbitmqctl
. Si rabbitmqctl
tente d'écrire dedans avec l'appel système write()
, celui-ci lui enverra le signal SIGPIPE qui signifie, en gros "hého, il y a plus personne qui t'écoute !". rabbitmqctl
peut intercepter ce signal et afficher un message d'erreur.
Il n'y a pas de problème avec | grep
car grep
attend la fin du fichier (qu'il reconnaît car read()
retourne alors 0, voir man open
).
J'en parle à Johndescs qui, évidemment, doute : "ça ferait pareil avec d'autres programmes, genre dmesg
, ce qui n'est pas le cas".
Sortons strace
afin de tracer les appels système et leurs erreurs.
Évidemment, rabbitmqctl
se fork()
(et pas qu'un peu…), donc, la première fois, on voit rien. Relançons en demandant de tracer également les appels système des processus enfant : strace -f
.
Évidemment, les appels système sont très nombreux, donc on veut les filtrer avec « -e », mais, comme toujours, on ne filtre pas ce qu'il faut : rabbitmqctl
utilise writev()
, pas write()
…
Cette fois, on est bon :
# strace -f -e writev rabbitmqctl -p <virtual_host> list_queues | head -n 1
strace: Process 23884 attached
[…]
strace: Process 23982 attached
[…]
strace: Process 23990 attached
[…]
[pid 23990] writev(45, [{iov_base="\0\0\0+", iov_len=4}, {iov_base="\203D\2\1\0008\204h\4a\23gR\0\0\0\0A\0\0\0\0\1R\1r\0\3R\0\1\0"..., iov_len=43}], 2 <unfinished ...>
[pid 23982] writev(1, [{iov_base="Listing queues ...\n", iov_len=19}], 1 <unfinished ...>
[pid 23990] <... writev resumed> ) = 47
[pid 23982] <... writev resumed> ) = 19
Listing queues ...
[…]
[pid 23990] writev(45, [{iov_base="\0\0\0+", iov_len=4}, {iov_base="\203D\2\1\0008\204h\4a\24gR\0\0\0\0A\0\0\0\0\1R\1r\0\3R\0\1\0"..., iov_len=43}], 2) = 47
[pid 23982] writev(1, [{iov_base="celeryev.42165f0d-b15c-4667-8b57"..., iov_len=51}], 1) = -1 EPIPE (Broken pipe)
[pid 23982] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=23899, si_uid=114} ---
[…]
[pid 23982] +++ exited with 0 +++
Le processus numéro 23990 interroge le processus 23982 via un pipe (« writev(45,[…] » => fichier numéro 45 ;) ). Ce dernier réagit à l'ordre en écrivant directement sa réponse sur stdout (writev(1, [{iov_base="Listing queues … » => fichier numéro 1 = stdout, c'est la norme). Et il se mange bien un SIGPIPE.
Même chose pour dmesg | head -n 1
: dmesg
reçoit bien un SIGPIPE et se termine (ce qui est le traitement par défaut de la plupart des signaux).
Dans la trace strace
ci-dessous, notons que la structure de données « siginfo_t » associée à un signal nous informe que le signal SIGPIPE a été envoyé par un processus (« si_code=SI_USER ») dont le PID est « si_pid=23899 » et que ce dernier tourne avec les droits de l'utilisateur dont l'ID est « si_uid=114 ». 114 = UID de l'utilisateur rabbitmq sur mon système. 23899 = PID de la machine virtuelle Erlang (BEAM/erl, car RabbitMQ est codé en Erlang) qui fait tourner rabbitmqctl
, qui, d'ailleurs demande à ignorer le signal SIGPIPE (on verra ça plus bas).
Avec dmesg
, on constate que l'UID est celui de root et que le PID est celui du processus dmesg
lui-même. Même chose avec un simple programme C qui se fork()
et execvp()
seq
: le PID annoncé dans « si_pid » est celui du processus enfant.
Dans le cas d'Erlang, ce n'est pas étonnant que la machine virtuelle re-émette le signal à l'un de ses enfants, car elle est un intermédiaire entre lui et le noyau.
Dans le cas du programme C, on pourrait s'attendre à ce que le code du signal soit SI_KERNEL vu que write() est un appel système, donc normalement exécuté côté kernel, mais ce n'est pas le cas… C'est un peu comme la structure de données d'un SIGCHLD qui contient le PID du processus enfant qui a pris fin : ce n'est pas directement l'enfant qui envoie le signal (et « si_code » est cohérent puisqu'il vaut « CLD_EXITED »).
Mais, du coup, qui écrit le message d'erreur « Error: Terminated » ?
Impossible de le savoir : dès que j'utilise le paramètre « -f » de strace
, il ne s'affiche plus :
rabbitmqctl
pour lancer la machinerie Erlang, se termine avec un code retour 70. On le voit car son père (Bash, execvp()
par strace
afin d'exécuter rabbitmqctl
qui s'avère être un script) reçoit un signal SIGCHLD (ton enfant a terminé) avec « si_status=70 » dans la structure de données « siginfo_t »). Bash, le père, conserve ce code retour et termine avec un code retour 70.L'observation avec strace
n'est pas si neutre que cela ? Je suis très surpris…
Peut-être que le signal SIGPIPE est traité par rabbitmqctl
? D'ailleurs, si l'on regarde le journal strace
ci-dessus, on constate que le processus numéro 23982, qui s'est pourtant mangé le SIGPIPE, termine avec un code retour 0, ce qui n'est pas normal : essaye un kill -13
(SIGPIPE a le numéro de signal 13, voir man 7 signal
) sur un cat
ou un grep
: le code retour est 141. De même, quand un processus termine à cause d'un signal, non-traité strace
affiche « killed by
Pour traiter un signal, c'est-à-dire soit l'ignorer, soit déclencher une fonction, un développeur doit utiliser les appels système signal()
ou sigaction
. Avec un strace -f -e writev,signal rabbitmqctl […] | head -n 1
, on constate que plusieurs processus demandent à ignorer SIGPIPE. Mais pas le processus qui écrit sur stdout.
Peu importe : la gestion des signaux s'hérite : si un processus parent a ignoré un signal ou enregistré une fonction pour le gérer, alors toute sa descendance en bénéficie. L'héritage de la fonction de traitement s'arrête uniquement si le code est écrasé avec une fonction de la libc membre de la famille exec
(c'est logique : la fonction de traitement ne sera plus disponible puisque le code du programme est écrasé par un autre programme). Un signal ignoré cesse jamais implicitement de l'être. Là encore, c'est le manuel de signal()
qui nous le confirme : « A child created via fork(2) inherits a copy of its parent's signal dispositions. During an execve(2), the dispositions of handled signals are reset to the default; the dispositions of ignored signals are left unchanged. »
Comment visualiser la parenté avec strace
? Avec « -f », on a bien le PID qui s'affiche à gauche, mais on ne sait pas quel processus l'a enfanté. On pense à utiliser « -e fork », mais ça produit aucun résultat. Un lutin du web nous rappelle que fork()
n'est pas un appel système, mais aussi une fonction de la glibc qui, ces temps-ci, encapsule l'appel système clone()
. Debian utilise la glibc. Ça explique pourquoi strace
ne voit pas les fork()
. Hop, « -e writev,clone,signal » et l'on voit bien que le processus parent de celui qui écrit sur stdout ignore (« SIG_IGN ») le signal SIGPIPE, donc son enfant (celui qui écrit sur stdout et reçoit le SIGPIPE) l'ignorera aussi :
[pid 6686] rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8a98c2b0e0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[…]
[pid 6686] clone(child_stack=0x7f8a561b7ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f8a561b89d0, tls=0x7f8a561b8700, child_tidptr=0x7f8a561b89d0) = 6767
[…]
[pid 6767] writev(1, [{iov_base="celeryev.42165f0d-b15c-4667-8b57"..., iov_len=51}], 1) = -1 EPIPE (Broken pipe)
Je précise, même si c'est inutile, que le processus enfant n'a pas fait appel à l'appel système execve
(ni autre membre de la famille exec).
Donc le processus n'a pas de routine définie lorsqu'il se prend un SIGPIPE, donc ce n'est pas lui qui affiche « Error: Terminated ». Mais cela peut être son parent, la machine virtuelle Erlang ou un autre processus qui discute avec lui et qui se rend compte qu'il n'a pas fait son boulot.
dmesg
n'enregistre pas non plus de fonction pour traiter SIGPIPE et ne l'ignore pas non plus, d'où il est donc normal qu'il se termine sans rien afficher quand il se mange un SIGPIPE, car c'est le traitement par défaut de SIGPIPE.
On notera également qu'il y a une notion de vitesse : si rabbitmqctl
a le temps d'écrire ce qu'il veut avant que head
ne termine, alors aucun signal SIGPIPE est envoyé et donc aucune erreur est affichée.
On vérifie ça avec rabbitmqctl -p <virtual_host> list_queues | (sleep 2 && head -n 1)
: aucune erreur, jamais. En revanche, sleep 1
= erreur.
On peut aussi vérifier avec strace -e writev rabbitmqctl -p <virtual_host> list_queues | strace head -n 1
: on verra que head
close()
stdin avant que rabbitmqctl
termine ses writev()
.
On peut aussi reproduire ça avec seq 1 1040 | head -n 1
: aucune erreur. En revanche, seq 1 1041
, vlam, SIGPIPE. Normal : seq
écrit les nombres 1 à 1040 ainsi que le retour à la ligne entre chaque nombre dans un buffer. Ce qu'il faut écrire occupe 4093 octets au total, donc write()
écrit ça d'un coup d'après sa page de manuel, donc head
a encore rien reçu, donc il n'a pas pu fermer stdin et se terminer. En revanche, il faut plus que 4096 octets pour écrire les nombres de 1 à 1041, donc cela se fait en deux appels à write()
. Entre les deux appels, head
a fermé le fichier et s'est arrêté, donc le deuxième write()
déclenche un SIGPIPE.
Cela explique le côté aléatoire de mon problème (tantôt le message s'affiche, tantôt non). rabbitmqctl
affiche 4 lignes au total. Avec un head -n 4
, le message d'erreur apparaît jamais car rabbitmqctl
a toujours le temps d'effectuer ses opérations (demander à son enfant de bosser, l'enfant consulte ses registres et écrit sur stdout, etc.). Avec head -n 3
, il y a une race condition : parfois rabbitmqctl
arrive à être assez rapide, parfois non. Avec head -n 1
, rabbitmqctl
a aucune chance de gagner la compétition : il y a trop de boulot et de communication inter-processus à entreprendre.
Cela est confirmé par le manuel de write()
qui expose : « If write() is interrupted by a signal before it writes any data, it shall return −1 with errno set to [EINTR] ». Dans la discussion que j'ai déjà mentionnée, on lit également « EPIPE An attempt is made to write to a pipe or FIFO that is not open for reading by any process, or that only has one end open. […] ». Tout correspond : write()
n'est pas interrompu, il arrive trop tard.
Au final, c'est très probablement rabbitmqctl
(ou la machinerie Erlang) qui affiche le message d'erreur « Error: Terminated » quand l'un des processus enfant ne se termine pas de manière attendue.
Difficile d'aller plus loin (j'aurais voulu savoir quoi, précisément, écrit le message d'erreur) :
su
(le script shell rabbitmqctl
l'appelle afin de lancer la machinerie Erlang). Sur une machine de bureau Debian 10, si l'on fait un su -s /bin/sh -c cat
(comme le fait rabbitmqctl
sauf que la commande n'est pas cat
, évidemment) et que l'on envoie un signal à cat
avec kill
, on constate que su
consulte /usr/share/locale/<LOCALE>/LC_MESSAGE/libc.mo
et write()
un message d'erreur qui varie en fonction du signal envoyé. Mais, sur le serveur RabbitMQ Debian 9, ce n'est pas le cas : su
write()
rien, ni quand on le charge de lancer cat
, ni quand on le charge de lancer rabbitmqctl
;gdb
permet de jouer avec les signaux, mais on est face à un empilement de scripts shell (sur lesquels gdb
est incompétent) qui lancent, in fine, du Erlang, qui, lui, a besoin que des variables d'environnement soient définies (par les scripts) et dont des sous-processus discutent entre eux pour accomplir le boulot…, bref, un joli merdier ;signal()
et sigaction()
sont des appels système, pas des fonctions de la libc, y'a-t-il moyen d'intercepter ?) ou de faire des dégâts collatéraux (comportement inattendu lié à des signaux qui auraient du être ignorés ou traités et qui ne le sont pas à cause de la surcharge, par exemple) ;