Eine kleine Geschichte über File Descriptors und ihre Flags

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.

Comments?