blog · git · desktop · images · music · contact & privacy · gopher


Vom plötzlichen Tod eines Daemons

2020-07-22

Ab und zu hat sich einer unserer Daemons unerwartet beendet. Geloggt hat er nichts. Das einzige, was ich gesehen habe, war in systemd ein Log-Eintrag der Art: „Process exited with status code 143.“ Davon abgesehen war der Daemon einfach weg. Manchmal. Manchmal jeden zweiten Tag, manchmal einen Monat nicht. Spaß.

Die erste Frage, die sich da stellt: Hat sich der Prozess halt mit Exitcode 143 beendet oder liegt das an der Konvention, dass Codes über 128 auf ein Signal zurückzuführen sind? Falls zweiteres zutrifft, dann wäre es SIGTERM gewesen, denn 128 + 15 = 143.

Theoretisch kann man das unterscheiden:

#include <stdio.h>
#include <string.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>

int
main(int argc, char **argv)
{
    pid_t child;
    int wstatus;

    child = fork();
    if (child == 0)
    {
        if (argc >= 2 && strcmp(argv[1], "--loop") == 0)
        {
            printf("Please kill %d\n", getpid());
            for (;;)
                /* noop */ ;
        }
        else
        {
            return 143;
        }
    }
    else if (child == -1)
    {
        perror("fork");
        return 1;
    }

    if (waitpid(child, &wstatus, 0) != -1)
    {
        if (WIFEXITED(wstatus))
            printf("Exited: %d\n", WEXITSTATUS(wstatus));
        else if (WIFSIGNALED(wstatus))
            printf("Signal: %d\n", WTERMSIG(wstatus));
    }

    return 0;
}

Über systemd bin ich aber an diese Information nicht rangekommen. Um ehrlich zu sein, hätte es auch nicht viel genutzt, denn die nächste Frage ist ja: Welcher andere Prozess hat das Signal geschickt?

Also sehe ich einfach nur „Exitcode 143“. Und jetzt?

Nach einer Weile habe ich quasi aufgegeben und folgenden kleinen Wrapper geschrieben:

/* Call as:
 *
 * ./tracer /usr/bin/my-real-daemon --foo --bar -Dbaz=1
 */

#define _POSIX_C_SOURCE 1

#include <signal.h>
#include <stdio.h>
#include <stdlib.h>
#include <syslog.h>
#include <sys/signalfd.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>

void
die(char *msg)
{
    perror(msg);
    exit(EXIT_FAILURE);
}

int
main(int argc, char **argv)
{
    sigset_t mask;
    int sfd, wstatus;
    struct signalfd_siginfo fdsi;
    ssize_t s;
    pid_t child;

    child = fork();
    if (child == -1)
        die("fork");
    else if (child == 0)
    {
        argc--;
        argv++;
        execv(argv[0], argv);
        die("exec");
    }

    sigemptyset(&mask);
    sigaddset(&mask, SIGTERM);
    sigaddset(&mask, SIGCHLD);

    if (sigprocmask(SIG_BLOCK, &mask, NULL) == -1)
        die("sigprocmask");

    sfd = signalfd(-1, &mask, 0);
    if (sfd == -1)
        die("signalfd");

    syslog(LOG_DAEMON | LOG_ERR, "Me: %u Child: %u\n", getpid(), child);

    for (;;)
    {
        s = read(sfd, &fdsi, sizeof(struct signalfd_siginfo));
        if (s != sizeof(struct signalfd_siginfo))
            die("read");

        syslog(LOG_DAEMON | LOG_ERR, "Got %u: code %d, pid %u, uid %u, status %d\n",
               fdsi.ssi_signo,
               fdsi.ssi_code,
               fdsi.ssi_pid,
               fdsi.ssi_uid,
               fdsi.ssi_status);

        switch (fdsi.ssi_signo)
        {
            case SIGCHLD:
                waitpid(child, &wstatus, 0);
                if (WIFEXITED(wstatus))
                {
                    syslog(LOG_DAEMON | LOG_ERR, "Child exited normally: %d\n",
                           WEXITSTATUS(wstatus));
                    return WEXITSTATUS(wstatus);
                }
                else if (WIFSIGNALED(wstatus))
                {
                    syslog(LOG_DAEMON | LOG_ERR, "Child exited with signal: %d\n",
                           WTERMSIG(wstatus));
                    return 128 + WTERMSIG(wstatus);
                }
                else
                {
                    syslog(LOG_DAEMON | LOG_ERR, "Child exited for unknown reason\n");
                    exit(EXIT_FAILURE);
                }
            case SIGTERM:
                syslog(LOG_DAEMON | LOG_ERR, "Relaying signal to %u\n", child);
                kill(child, SIGTERM);
                break;
            default:
                syslog(LOG_DAEMON | LOG_ERR, "Unexpected signal\n");
        }
    }
}

(Hätte stattdessen auch strace benutzen können, das macht aber häufig alles äußerst langsam.)

Alles auf dem System inklusive systemd geht dann davon aus, dass mein Programm der echte Daemon ist. Wer auch immer dann das Signal schickt, schickt es zuerst zu mir, und ich kann dann sehen, wer es war.

Hat nicht funktioniert.

Weiterhin nur „Exitcode 143“. Aus der Sicht meines Wrappers hat sich das Programm einfach beendet.

Eine Kollegin fragte dann letztlich: „Ist das vielleicht eine stale PID-File?“ Nein, kann nicht sein. Das hatte ich schon geprüft, weil, ja, dieser Daemon benutzt in der Tat PID-Files. Es hätte auch nicht ganz gepasst, denn der Daemon lief einige Zeit ordentlich und hat sich erst später spontan verabschiedet. Und zu alledem enthielt die PID-File ja nun die PID meines Wrappers, mit dem ich das genauer hätte sehen können müssen.

Muss wahrscheinlich nicht dazusagen, dass sie trotzdem recht hatte.

Ich hatte vergessen, dass dieser Daemon irgendwann einen zweiten Daemon startet. Und natürlich benutzt auch der zweite Daemon eine PID-File. Ein schneller Test hat die Theorie bestätigt: Der zweite Daemon schießt den ersten wegen einer stale PID-File ab. Glückwunsch.

Aber … warum hat mein Wrapper mir das nicht gesagt?

Die einzige Erklärung: Die zweite PID-File hat schlichtweg die echte PID des ersten Daemons enthalten. Ja, natürlich. Ich nahm an, dass irgendwas den ersten Daemon absichtlich abschießt, aber das war einfach nicht der Fall. Nur rein zufällig hat jemand die echte PID des ersten Daemons erwischt.

Aber wie wahrscheinlich ist denn das, dass das regelmäßig passiert? Ja, manchmal war einen Monat lang Ruhe, aber öfter ist es eben auch jeden zweiten Tag passiert. Seltsam.

Die Antwort ist überraschend einfach: Threads.

Wenn der Daemon normal läuft, startet er einen großen Haufen Threads:

systemd(1)-+-java(684)-+-java(762)
           |            |-{java}(731)
           |            |-{java}(732)
           |            |-{java}(733)
           |            |-{java}(734)
           |            |-... viele weitere ...
           |            `-{java}(958)

Jeder Thread bekommt eine „PID“, was ein potentielles Ziel für ein kill() ist (man 7 signal):

The signal disposition is a per-process attribute: in a  multi‐
threaded application, the disposition of a particular signal is
the same for all threads.

Dadurch steigt die Wahrscheinlichkeit für eine Kollision in einer stale PID-File dramatisch an.

Die finale Zutat für das Desaster: Dieses System wurde täglich neugestartet (absichtlich – das Ding ist nur zu Geschäftszeiten an, um Geld zu sparen). Mit anderen Worten gab es eine hohe Chance dafür, dass all diese PIDs etwa im selben Bereich liegen, weil natürlich alles beim Booten gestartet wird.

Ein besserer Ansatz: auditd

Etwas beschämt muss ich zugeben, dass ich bisher nicht viel über das Audit-Subsystem wusste. Damit hätte ich das Problem viel schneller lösen können.

Ich hätte eine einfache Regel hinzufügen können, die alle kill()-Aufrufe überwacht:

# auditctl -a always,exit -F arch=b64 -S kill -k mykill

Damit fallen Logeinträge dieser Art heraus:

Jul 22 15:30:35 arch audit[996]: SYSCALL arch=c000003e syscall=62 success=yes exit=0 a0=3d6 a1=f a2=0 a3=560e1039942a items=0 ppid=858 pid=996 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts1 ses=1 comm="bla" exe="/root/bla" key="mykill"

Und ich hätte alles gewusst:

Damit wäre ich dann sehr schnell beim Verursacher herausgekommen. Ohne einen eigenen Wrapper schreiben zu müssen und was sonst noch.

Und natürlich war es auch naiv von mir, in meinem eigenen Wrapper nur die PID des Senders zu loggen. Ein Äquivalent zu exe hätte ich gebraucht.

Der „Bitte“-Abschnitt

Wenn du einen neuen Daemon schreibst, benutze bitte keine PID-Files mehr. Einfach sein lassen. Heutige Init-Systeme brauchen das nicht mehr, auch nicht für sowas wie „sende ein SIGHUP zum Reloaden“ (siehe zum Beispiel systemds $MAINPID).

Wenn du einen neuen Daemon schreibst, starte bitte nicht einfach so selbständig neue Daemons. Einfach sein lassen. Das ist furchtbar beim Debuggen. Erwähne in der Doku, dass der Sysadmin zwei Daemons zu starten hat, und dann machen wir das.

Comments?