syslog-ng und MySQL

Wir haben einen Kunden, der auf einem seiner Systeme die anfallenden Log-Nachrichten nicht nur in die üblichen Logfiles schreiben läßt, sondern auch in seine MySQL-Datenbank. Das sah in der Config dann so aus (Liebe Kinder, bitte nicht nachmachen!):

destination d_mysql {
program(
"/usr/bin/mysql -uSOMEUSER -pSOMEPASSWORD SOMEDATABASE"
template("INSERT INTO logs (host, facility, priority, level, tag, datetime, program, msg) VALUES ( '$HOST', '$FACILITY', '$PRIORITY', '$LEVEL', '$TAG','$YEAR-$MONTH-$DAY $HOUR:$MIN:$SEC','$PROGRAM', '$MSG' ); ")
template-escape(yes)
);
};
filter f_no_debug { not level(debug); };
log { source(s_all); filter(f_no_debug); destination(d_mysql); };


Kurz zur Erläuterung: Hier wird syslog-ng letztlich angewiesen, für jede einzelne Log-Nachricht einen Programmaufruf von mysql zu konstruieren und eine Zeile an eine bestimmte Tabelle (logs) in einer bestimmten Datenbank anzufügen.

Man kann dem Kunden hier auch gar keinen Vorwurf machen, erstens entspricht diese Vorgehensweise einer alten Anleitung, die man an vielen Stellen im Internet findet (offenbar schreiben die Autoren diverser Anleitungen alle voneinander ab), zweitens unterstützte syslog-ng früher kein Logging in Datenbanken. So der so: diese Vorgehensweise ist nicht gerade optimal. Die Probleme im einzelnen sind:
ul>

Auf einem gut beschäftigten System sind Log-Nachrichten keine gelegentlich auftretenden Ereignisse, sondern meist eher ein fast kontinuierlicher Strom von Daten. Deswegen neigen die meisten Logging-Lösung (so auch syslog-ng) dazu die anfallenden Nachrichten immer ein kleines bißchen zu puffern und dann erst in die Dateien zu schreiben, weil man sonst dem System viel Arbeit aufbürdet, etwa dann wenn man etwa 200 mal pro Sekunde eine Datei öffnet, eine Zeile hinten anfügt und sie wieder schließt und das am besten mit mehreren Dateien gleichzeitig tut. Das oben gezeigte Beispiel macht mit MySQL ziemlich genau das: es konstruiert wirklich für jede Log-Nachricht einen Befehlsaufruf von mysql.

Man muß sich einfach mal vergegenwärtigen was bei einem Programmaufruf so alles passiert: Zunächst muß das Programm von der Festplatte geholt werden (zugegebenermaßen wird Linux dies natürlich bei häufigen Aufrufen cachen, es sei hier trotzdem mal erwähnt), dann müssen die dynamisch zu ladenen Bibliotheken die dieses Programm verwendet geholt werden (auch hier wird später gecachet), dann muß für das Programm Speicher alloziert werden und bei jedem halbwegs modernen Linux-Kernel heißt das auch, daß der Kernel Memory Layout Randomization machen muß, d.h. er muß die einzelnen Programmteile im Speicher zufällig verteilen, damit Angriffe gegen das Programm nicht zuverlässig zu ausnutzbaren Funktionen springen können. Das Erzeugen von Zufall ist für den Kernel auf x86er Hardware nicht einfach (weil die Plattform — wie die allermeisten Computer-Plattformen — nicht vorsieht, daß zwingend eine gute Entropiequelle Teil der Hardware sein muß) und kann Zeit kosten. Wer schonmal mit GnuPG oder OpenSSL große Schlüssel generiert hat, wird das Problem „not enough entropy“ kennen. Wenn dem Kernel die Entropie ausgeht, dann kann das auch andere Programme in Mitleidenschaft ziehen, dann kann es z.B. zu Verzögerungen kommen, wenn der Apache HTTPS-Aufrufe bedienen soll, denn neue SSL-Verbindungen brauchen auch immer eine Prise frische Entropie.

Dann muß man sich klar machen, daß auch im Programmablauf einiges passiert, hier sei einmal das wichtigste erwähnt: Unter anderem muß hier jedesmal eine neue Verbindung zur MySQL-Datenbank aufgebaut werden (in diesem Fall verfolgt das glücklicherweise wenigstens über den Socket, die Verbindung muß nicht auch noch zweimal durch den TCP/IP-Stack wandern, wie sie es etwa bei einem Zugriff über das Loopback-Interface müßte). Das heißt aber schonmal mindestens ein SELECT FROM mysql.users pro Verbindung.

Ein weiterer, nicht zu vernachlässigender Faktor ist, daß das Kommandozeilenprogramm mysql ein sehr komplexes, mächtiges Programm ist. Es wäre viel sinnvoller, hier ein schmales mysql-insert-Programm zu verwenden, das einen kleineren Memory-Footprint hat und auf diese Aufgabe optimiert ist. (Nein, ich kenne kein solches Programm.)

Schließlich und endlich muß man schauen, was in der MySQL-Datenbank dann passiert: An eine nach kurzer Zeit gigantisch große Tabelle muß eine Zeile angefügt werden, diese Operation muß ggf. für eine MySQL-Replikation noch in ein Binlog geschrieben werden (und auf allen Slaves wiederholt werden) und natürlich müssen sämtliche Indizes dieser Tabelle aktualisiert werden. Alle internen Mechanismen zur Optimierung, die MySQL möglicherweise haben könnte um einen Haufen von Inserts in eine große Tabelle effizient abzuarbeiten werden ausgehebelt, weil die Inserts alle einzeln auf das Datenbanksystem einprasseln.

Und das alles für jede einzelne Log-Nachricht. Auf einem gut beschäftigten Server also locker viele, viele Male pro Sekunde. Moderne Prozessoren können zwar viele Milliarden Instruktionen pro Sekunde verarbeiten, aber natürlich setzen sich so komplexe Vorgänge wie oben beschrieben aus sehr vielen Instruktionen zusammen und außerdem findet ja längst nicht alles auf dem Prozessor statt, RAM und Festplatten sind aber um einiges langsamer als der Prozessor selbst.

Als letztes Bonmot sei erwähnt, daß bei dieser Vorgehensweise natürlich ständig in der Prozessliste des Linux-Kernels die Aufrufe von mysql mit den Zugangsdaten zur Datenbank im Klartext auftauchen. Wenn man auf dem System alleine ist (oder zu sein glaubt), mag das vielleicht noch gehen, ist aber trotzdem nicht empfehlenswert, denn die Prozessliste ist auch Usern mit nur wenigen Rechten auf dem System zugänglich. (Immerhin: Bei diesem Kunden war der Datenbankuser nicht ‚root‘ und hatte auch nicht maximale Rechte auf dem Datenbanksystem. Es kommt also nicht immer gleich ganz dicke.)

Wenn man ein bißchen länger zu dem Thema googelt, findet man noch andere Lösungen, die schon ein bißchen besser sind. Einige Leute schreiben die Log-Nachrichten einfach in eine extra Datei und lassen sie dann von einem anderen Programm alle paar Minuten im Block einlesen und in die MySQL-Datenbank stopfen. Das klingt zwar deutlich holpriger, kann aber bei guter Implementation deutlich besser funktionieren. Wieder andere verwenden eine Named Pipe um die MySQL-Datenbank zu füttern und nicht ständig neue MySQL-Verbindungen aufbauen zu müssen. Auch das ist deutlich besser als das oben gegebene Beispiel. Aber leider schreiben offenbar erschreckend viele Leute ausgerechnet von den Anleitungen ab, die auch das obrige Beispiel hervorgebracht hat.

Mittlerweile gibt es einen nochmal deutlich eleganteren Weg, denn inzwischen bringt syslog-ng nativen Support für das Logging in Datenbanken mit. Als ich vor ein paar Tagen für unseren Kunden das Logging auf diese neue Methode umstellen wollte, ging es mir nach einem längeren Blick in die Dokumentation von syslog-ng allerdings erstmal wie dem sprichwörtlichen Schwein vorm Uhrwerk. Zwar liefert die Dokumentation ein Beispiel für PostGreSQL mit, aber das läßt leider Fragen offen, die auch von der detailierteren Dokumentation im Anhang nicht zufriedenstellend beantwortet werden (jedenfalls hab ich die Antworten nicht gefunden). So stellte sich mir etwa die Frage, ob ich über ein Socket gehen kann oder durch das Loopback-Interface gehen muß und ob ich ggf. den Pfad zum Socket angeben muß. Auch fragte ich mich, welche Variablen oder Macros ich denn aufrufen könnte und wie gut oder schlecht die Zugangsdaten zur Datenbank denn geschützt werden (wobei diese Frage schon eher unter Kür denn unter Pflicht fällt, solange die Daten nicht in der Prozessliste auftauchen, ist schonmal etwas gewonnen). Ich sage nicht, daß längeres Suchen in der Dokumentation diese Fragen nicht beantwortet, ich will nur mal ein bißchen darüber jammern, daß ich in der Dokumentation von syslog-ng bei jedem Thema immer ein bißchen länger suchen muß um meine Fragen zu beantworten.

Und auf Anhieb findet man im Internet keine guten Beispiele, wie man diesen nativen SQL-Support in syslog-ng denn nun am besten benutzt. (Weil alle nur von dem selben, alten, dämlichen Beispiel abschreiben oder von den paar wenigen, etwas besseren, alten Beispielen.) Nun gut, Probieren geht über Studieren, ich hab’s dann am Ende ausgetüftelt. Damit zu den alten, dämlichen Beispielen sich mit der Zeit dann vielleicht ein paar geringfügig weniger dämliche gesellen, will ich es hier allgemein zugänglich machen:

destination d_mysql {
sql(type(mysql)
username("SOMEUSER")
password("SOMEPASSWORD")
database("SOMEDATABASE")
table("logs")
columns("host", "facility", "priority", "level", "tag", "datetime", "program", "msg")
values("$HOST", "$FACILITY", "$PRIORITY", "$LEVEL", "$TAG","$YEAR-$MONTH-$DAY $HOUR:$MIN:$SEC","$PROGRAM", "$MSG")
indexes("datetime", "host", "program", "pid", "message"));
};
filter f_no_debug { not level(debug); };
log { source(s_src); filter(f_no_debug); destination(d_mysql); };

Und siehe da: die Daten strömen!

Offenbar findet syslog-ng das Socket ohne größere Probleme (ich vermute mal es schaut in die my.cnf). Mit dem Statement host("localhost") könnte man aber auch über das Loopback-Interface (oder das Netzwerk, wenn man einen Hostname angibt) gehen. Bei letzterem bleibt zu beachten, daß MySQL selbst seine Verbindungen nicht verschlüsselt, es sei denn man konfiguriert das explizit. Alternativ bieten sich auch weitere Verschlüsselungsmethoden an, aber das ist ein anderes Thema.

Um nochmal grob einzuordnen wo die Vorteile liegen:

• Das Programm syslog-ng und die dynamischen Bibliotheken werden einmalig beim Programmstart geladen und verbleiben im Speicher. Kein ständiges, erneutes Aufrufen von mysql mehr, kein unnötiger entropy drain.
• Die Verbindung zur MySQL-Datenbank ist persistent. Mag sein, daß syslog-ng sie einmal am Tag schließt und neu initialisiert, aber das fällt nicht weiter ins Gewicht. Meinetwegen kann er sie auch alle fünf Minuten wieder schließen und neu öffnen, solange er dies nicht mehr 200 Mal in der Sekunde tut.
• Zugangsdaten zur DB liegen in der Config für syslog-ng (die nur root lesen kann) und im Speicherbereich von syslog-ng. Ein Angreifer muß also einen Root-Exploit oder Zugriff auf den Speicher von syslog-ng haben. Das sind höhere Hürden als der Zugriff auf die Prozessliste.
• Es ist denkbar, daß syslog-ng intern Puffer verwendet und Log-Nachrichten nicht einzeln an die DB schickt, sondern immer einen Block von Nachrichten durchreicht. Es ist hier zumindest denkbar, daß MySQL selbst da auch intern ein bißchen optimiert, um noch etwas mehr Performance herauszukitzeln. Das war vorher schlicht kaum möglich.

Ein Vergleich der Performance steht noch aus, aber da geht es eher um die Frage wie groß die Verbesserung ausfällt, nicht so sehr ob es eine gibt.

Die wirklich spannende Frage, ob ich mit Programmen wie logger auf dem Host jetzt MySQl-Injections machen kann, werde ich hier in einem Update auch noch beantworten.