Auf der Suche nach dem Prozess-Killer

Kurzvortrag auf den Linuxwochen 2010

Seit längerem bekam ich auf einem bestimmten Server immer wieder Mails wie die folgende:

Date: Tue, 21 Sep 2010 21:46:01 +0200 (CEST)
From: Cron Daemon <root@wsr.ac.at>
To: hjp@wsr.ac.at
Subject: Cron <hjp@wotan2> ~/bin/get_samples; ~/bin/aggregate; ~/bin/expire
Return-Path: <hjp@wsr.ac.at>
Message-Id: <20100921194657.C88C5808A@wotan2.wsr.ac.at>

/bin/sh: line 1: 26880 Killed                  ~/bin/get_samples

Das war einigermaßen beunruhigend. Irgendwas killt da Cronjobs. Und dieses irgendwas läuft offensichtlich mit root-Rechten, sonst könnte es nicht Cronjobs verschiedener User killen.

Wie findet man sowas? Zunächst fiel mir auf, dass die gekillten Prozesse immer die gleiche PID (oder eine von wenigen PIDs hatten) und ein kleines Testprogramm, das einfach so lange forkt, bis es die richtige PID hat und dann darauf wartet, gekillt zu werden, zeigte, dass das das sehr häufig auftritt:

% ./findpid 26880
got pid 26880
1285245175.121462: child 26880 exited with status 0009
got pid 26880
1285245181.129473: child 26880 exited with status 0009
got pid 26880
1285245187.137956: child 26880 exited with status 0009
got pid 26880
1285245193.145998: child 26880 exited with status 0009

Ein Prozess mit der „richtigen“ PID lebt also jeweils nur wenige Sekunden. Da sollte sich der Killer doch finden lassen. Allerdings war ich zunächst wenig erfolgreich.

Mit dem Upgrade des Servers auf Debian Lenny (ja, gerade rechtzeitig vor dem Freeze für Squeeze :-)) bekam ich ein neues Werkzeug in die Hand:

Das Linux Auditing System

Eingeführt mit Kernel 2.6.20, kann das Linux Auditing System systemweit Systemcalls (gefiltert nach bestimmten Kriterien) aufzeichnen. Also für diesen Zweck genau das richtige.

Mehrere Leute im Publikum waren der Meinung, das Auditing System gäbe es schon länger. Auch ich habe vage in Erinnerung, dass es schon früher etwas ähnliches gab, bin mir aber ziemlich sicher, dass Debian Etch (Kernel 2.6.18) kein entsprechendes Tool hatte. Hinweise zur Historie werden gerne angenommen.

Außer der Kernel-Komponente besteht das Auditing System aus mehreren User-Space-Programmen:

auditd
Der auditd zeichnet die vom Kernel gemeldeten Events auf und schreibt sie in ein Logfile. Der auditd muss vor den zu auditierenden Prozessen gestartet werden. Ist das nicht möglich, gibt es auch einen Kernel-Parameter, der auditing bereits vor dem Start von init aktiviert.
auditctl
Mit diesem Tool können Filterkriterien festgelegt und Auditing auch ganz abgeschaltet bzw. (bis zum nächsten reboot) irreversibel aktiviert werden.
ausearch
Durchsucht die von auditd geschriebenen Logs und gibt die Records in einigermaßen menschenlesbarer Form aus.
aureport
Fasst die Logs zu Reports zusammen.

Die Filterkriterien sind recht flexibel, in meinem Fall war es aber einfach:

auditctl -a exit,always -S kill

Das heißt, ich möchte nur den Systemcall kill mitloggen, und zwar zum exit-Zeitpunkt, damit ich auch den Returncode sehe. always heißt, dass ich das loggen will (es gibt nur die Alternative never, die nicht loggt).

Lassen wir das ein paar Sekunden laufen und suchen wir dann nach kill(26880, 9). ausearch gibt die Parameter hexadezimal aus, und dezimal 26880 ist hexadezimal 6900, also:

wotan2:/usr/local/roxen 14:59 :-) 125# ausearch -sc kill | grep ' a0=6900 a1=9 ' | head
type=SYSCALL msg=audit(1285245427.433:22): arch=40000003 syscall=37 per=400000 success=yes exit=0 a0=6900 a1=9 a2=a0a95e0 a3=0 items=0 ppid=4274 pid=4299 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="roxen" exe="/usr/local/roxen/server-4.5.241/pike/bin/pike" key=(null)
type=SYSCALL msg=audit(1285245427.433:23): arch=40000003 syscall=37 per=400000 success=yes exit=0 a0=6900 a1=9 a2=a0a95e0 a3=0 items=0 ppid=4274 pid=4299 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="roxen" exe="/usr/local/roxen/server-4.5.241/pike/bin/pike" key=(null)
type=SYSCALL msg=audit(1285245430.434:34): arch=40000003 syscall=37 per=400000 success=no exit=-3 a0=6900 a1=9 a2=a0a95e0 a3=0 items=0 ppid=4274 pid=4299 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="roxen" exe="/usr/local/roxen/server-4.5.241/pike/bin/pike" key=(null)

Aha! Der Bösewicht hat die PID 4299, heißt "roxen" und führt das Executable "/usr/local/roxen/server-4.5.241/pike/bin/pike" aus.

Roxen ist ein Webserver, der als Root läuft, damit er z.B. CGI-Scripts unter verschiedenen uids starten kann. Ich vermute, dass er manchmal den Tod eines CGI-Scripts nicht mitbekommt und dann versucht, dieses Script zu killen, bis ihm mit waitpid mitteilt, dass es tot ist, was natürlich nie passiert.

Ein Restart des Webservers behebt das Problem (für ein paar Wochen), ein Upgrade auf die neueste Version (und wenn das nicht hilft, Debugging) wäre aber angesagt.

Zum Schluss hier noch ein vollständiger Record:

----
time->Thu Sep 23 14:37:07 2010
type=OBJ_PID msg=audit(1285245427.433:22): opid=26880 oauid=-1 ouid=1010 oses=-1 obj=(none) ocomm="findpid"
type=SYSCALL msg=audit(1285245427.433:22): arch=40000003 syscall=37 per=400000 success=yes exit=0 a0=6900 a1=9 a2=a0a95e0 a3=0 items=0 ppid=4274 pid=4299 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="roxen" exe="/usr/local/roxen/server-4.5.241/pike/bin/pike" key=(null)
----

Er enthält auch die Zeit, und — da an einem kill(2) zwei Prozesse beteiligt sind — auch Informationen über den anderen Prozess, in dem Fall mein findpid Programm.