blog · git · desktop · images · contact
2021-05-28
Das hier ist ein Repost meines Postings auf nixers.net. Und auf Deutsch.
Liebes UNIX-Tagebuch,
ich hatte heute auf der Arbeit Spaß mit File Descriptors.
Da war ein Python-Skript, das mit EAGAIN
während eines print()
auf
stdout
abbrach. Wie jetzt?
In write(2)
steht geschrieben:
EAGAIN The file descriptor fd refers to a file other than a
socket and has been marked nonblocking (O_NONBLOCK), and
the write would block. See open(2) for further details
on the O_NONBLOCK flag.
EAGAIN or EWOULDBLOCK
The file descriptor fd refers to a socket and has been
marked nonblocking (O_NONBLOCK), and the write would
block. [...]
Den Fehler kann man dann mit folgendem Stückchen C-Code provozieren:
#include <fcntl.h>
#include <stdio.h>
int
main()
{
int i;
if (fcntl(1, F_SETFL, O_NONBLOCK) == -1)
{
perror("fcntl");
return 1;
}
for (i = 0; i < 4 * 8192; i++)
printf("hello world"); /* no trailing \n */
return 0;
}
Einfach am Terminal ausführen, velleicht mit strace
, damit man sieht,
was vor sich geht. Sieht ungefähr so aus:
17:53:50.053752 write(1, "ello worldhello worldhello world"..., 1024) = 1024
17:53:50.053779 write(1, "llo worldhello worldhello worldh"..., 1024) = 1024
17:53:50.053949 write(1, "rldhello worldhello worldhello w"..., 1024) = -1 EAGAIN (Resource temporarily unavailable)
17:53:50.053975 write(1, "hello worldhello worldhello worl"..., 1024) = -1 EAGAIN (Resource temporarily unavailable)
17:53:50.054436 write(1, "hello worldhello worldhello worl"..., 1024) = 1024
17:53:50.054569 write(1, " worldhello worldhello worldhell"..., 1024) = 1024
17:53:50.054596 write(1, "worldhello worldhello worldhello"..., 1024) = -1 EAGAIN (Resource temporarily unavailable)
17:53:50.054620 write(1, "hello worldhello worldhello worl"..., 1024) = -1 EAGAIN (Resource temporarily unavailable)
17:53:50.054645 write(1, "hello worldhello worldhello worl"..., 1024) = -1 EAGAIN (Resource temporarily unavailable)
Die libc buffert erstmal ein bisschen und schreibt dann schließlich
Blöcke von jeweils 1024 Bytes raus. Weil wir den File Descriptor auf
nonblocking gestellt haben, kehrt der Syscall sofort zurück, auch wenn
die Daten vielleicht noch gar nicht an ihrem Ziel angekommen sind. Ich
schätze also, dass es da noch einen zweiten Kernel-internen Buffer gibt.
Wenn der dann voll ist, kriegen wir EAGAIN
.
Mein ursprüngliches Python-Skript hat auch tatsächlich sehr viele Daten
rausgeschrieben. Also wird mein stdout
wohl irgendwie im
nonblock-Modus gelandet sein. Ich habe dann den Code durchforstet, aber
nichts finden können, was dafür verantwortlich sein könnte. Naja, gut,
vielleicht macht Python das intern aus irgendwelchen wirren Gründen?
Also versucht, das isoliert nachzustellen, aber nope, da war kein
fcntl()
von Python zu sehen.
Gut, was macht mein Skript noch? Es forkt und startet ssh. Mhm. Aber ich
habe Pythons check_output()
benutzt, also ist das stdout
von ssh
eine neue Pipe gewesen. Mir war anfangs völlig schleierhaft, wie ssh
auch nur irgendwie in die Nähe meines stdout
hätte kommen sollen?!
Dann eine andere Idee: Das Skript wurde als systemd-Service ausgeführt.
Heißt also, das stdout
meines Skripts ist eigentlich ein Socket,
welches mit dem journald verbunden ist. Vielleicht hat es also systemd
vermasselt und das Socket auf nonblocking gestellt … ? Diese Theorie
konnte ich aber auch nicht verifizieren.
Und dann dämmerte es mir langsam: systemd verbindet dasselbe Socket
mit stdout
und stderr
. Heißt also, wenn ssh etwas an seinem
stderr
macht, könnte das das stdout
meines Python-Skripts
beeinflussen.
Probieren wir das mal:
#include <fcntl.h>
#include <stdio.h>
#include <unistd.h>
int
main()
{
int ret, i, fd;
if (fork() == 0)
{
fd = open("/dev/null", O_WRONLY);
dup2(fd, 1);
close(fd);
execlp("strace", "strace", "-o", "ssh.log",
"ssh", "myserver.example.com", "date",
(char *)0);
return 1;
}
for (i = 0; i < 10; i++)
{
if ((ret = fcntl(1, F_GETFL)) < 0)
{
perror("fcntl");
return 1;
}
if (ret & O_NONBLOCK)
puts("Is NONblocking");
else
puts("Is blocking");
sleep(1);
}
return 0;
}
Und hier der wundervolle Output, stdout
und stderr
sind im
Elternprozess dieselbe Pipe:
$ ./borked 2>&1 | cat
Is blocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Is NONblocking
Der Kindprozess hat sein originales stdout
geschlossen (ist ja neu von
/dev/null
geöffnet worden), aber das stdout
im Elternprozess wurde
trotzdem geändert.
Meine ursprüngliche Umgebung auf der Arbeit hat ssh-Multiplexing verwendet, also habe ich das hier auch gemacht. Am Ende des Postings habe ich das Verhalten aber auch nochmal ohne Multiplexing nachgestellt.
Der von mir gestartete ssh-Prozess überträgt die drei Standard Descriptors an den Multiplexing-Hauptprozess:
19:11:32.186688 sendmsg(4, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[0]}], msg_controllen=24, msg_flags=0}, 0) = 1
19:11:32.186753 sendmsg(4, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[1]}], msg_controllen=24, msg_flags=0}, 0) = 1
19:11:32.186795 sendmsg(4, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[2]}], msg_controllen=24, msg_flags=0}, 0) = 1
Und der wiederum macht das:
19:11:32.186811 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[6]}], msg_controllen=24, msg_flags=0}, 0) = 1
19:11:32.186853 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[7]}], msg_controllen=24, msg_flags=0}, 0) = 1
19:11:32.186903 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[8]}], msg_controllen=24, msg_flags=0}, 0) = 1
19:11:32.186941 ioctl(6, TCGETS, {B38400 opost isig icanon echo ...}) = 0
19:11:32.186976 ioctl(7, TCGETS, 0x7ffdce246db0) = -1 ENOTTY (Inappropriate ioctl for device)
19:11:32.187004 fcntl(7, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
19:11:32.187030 fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
19:11:32.187054 ioctl(8, TCGETS, 0x7ffdce246db0) = -1 ENOTTY (Inappropriate ioctl for device)
19:11:32.187079 fcntl(8, F_GETFL) = 0x1 (flags O_WRONLY)
19:11:32.187104 fcntl(8, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 <-------- TADA
Da hast du’s. Es setzt FD 8, was das empfangene stderr
ist, auf
nonblocking. Weil das dieselbe Pipe ist wie im Elternprozess das
stdout
, wird beides geändert.
Duplizierte Descriptors teilen sich manche Eigenschaften, aber nicht
alle. In dup(2)
steht:
After a successful return, the old and new file descriptors may
be used interchangeably. They refer to the same open file de‐
scription (see open(2)) and thus share file offset and file
status flags; [...]
The two file descriptors do not share file descriptor flags [...]
Diese „file status flags“ sind das, was durch fcntl(..., F_SETFL, ...)
gesetzt wird, aber „file descriptor flags“ sind etwas anderes:
F_SETFL Set the file status flags, defined in <fcntl.h>, [...]
F_SETFD Set the file descriptor flags defined in [...]
Das Lustige ist jetzt natürlich, dass man mir vorwerfen könnte: „Starte
halt nicht irgendwelche Prozesse und lass’ die deine Descriptors erben.
Natürlich können die Unfug treiben.“ Das Ding ist nur, dass das
Absicht war: Mein Python-Skript hat ssh gestartet und dessen stderr
nicht angefasst, damit ssh-Fehler ganz automatisch ohne mein Zutun an
derselben Stelle landen (im systemd-Journal) wie die von Python selbst.
Jetzt hingegen muss ich die manuell einsammeln durch Sonderbehandlung
von sshs stderr
, was mehr Code und fehleranfälliger ist.
Okay, zum Schluss noch der Fall ohne Multiplexing. Zuerst dachte ich,
das träte hier gar nicht auf, aber es ist nur ein kleines bisschen
schwieriger zu bemerken. Ein strace
-Auszug:
20:05:14.074435 dup(0) = 4
20:05:14.074505 dup(1) = 5
20:05:14.074532 dup(2) = 6
...
20:05:14.074674 fcntl(6, F_GETFL) = 0x1 (flags O_WRONLY)
20:05:14.074691 fcntl(6, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
... then at the very end:
20:05:14.167997 close(6) = 0
20:05:14.168232 fcntl(2, F_GETFL) = 0x801 (flags O_WRONLY|O_NONBLOCK)
20:05:14.168249 fcntl(2, F_SETFL, O_WRONLY) = 0
20:05:14.168430 exit_group(0) = ?
Mit anderen Worten, in diesem Fall setzt ssh die Flags zurück. Mein ssh-Befehl war ziemlich schnell fertig, daher hatte ich anfangs keine Zeile mit „NONblocking“ gesehen.
All das hier benutzt ganz viel strace
. Ich liebe dieses Tool. den
Quellcode von ssh habe ich nicht gelesen, das könnte aber sehr
interessant sein. Ist aber was für ein ander’ Mal.