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.
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.