© destinacigdem / 123RF.com

Der Linux-Kernel unterstützt pfiffig sowohl Admins beim Umgang mit Kernel-Nachrichten als auch Entwicklerinnen und Entwickler bei deren Generierung.

Programmierkarrieren beginnen typischerweise mit einem “hello, world”. Dessen Ursprung geht auf die beiden AT&T-Mitarbeiter Brian Kernighan und Dennis Ritchie zurück, die die Programmiersprache C erfunden haben. Mit »printf(“hello, world”);« gaben sie 1974 als Erste den berühmt gewordenen String auf die Konsole aus. Dabei ist »printf()« nicht einmal Teil der Programmiersprache C selbst, sondern Teil der C-Standardbibliothek.

Auch ein Linux-Kernel hat Mitteilungsdrang, und da der Betriebssystemkern keinen Zugriff auf die Standardfunktionen der C-Bibliothek hat, spendierte ihm sein Vater Linus Torvalds konsequenterweise eine korrespondierende Funktion »printk()«. In den ersten Versionen war dieses Sprachrohr des Kernels im Vergleich zu »printf()« deutlich abgespeckt und unterstützte nur wenige, ausgewählte Umsetzungssequenzen. Heute ist die Funktion stark ausgeweitet und vor allem auch auf spezifische Belange eines Betriebssystemkerns hin ausgerichtet. Dadurch ist der Umgang mit der Funktion teilweise etwas kniffelig geworden.

Geplagte Admins

Per »printk()« publizierte Kernel-Nachrichten werden nicht einfach blind auf die armen Admin-Profis losgelassen. Vielmehr bietet der Kernel der geplagten Systemverwaltung die Möglichkeit, die Flut an Ausgaben aus dem Inneren des Betriebssystemkerns per Konfiguration einzudämmen. Dazu dienen der System Call »syslog()«, den die Standard-C-Bibliothek auf die Funktion »klogctl()« abbildet, sowie der im Userland laufende Syslog-Daemon (»rsyslogd()«) (Abbildung 1). Hinzu kommen eine Reihe von virtuellen Dateien im Verzeichnis »proc/«.

Abbildung 1: Die Architektur des Kernel-Log-Systems im Überblick.

Insbesondere konfiguriert man mit dem System Call »syslog()« den Konsolen-Level. Dazu sollte man wissen, dass alle Nachrichten eines Betriebssystemkerns klassischerweise auf der sogenannten Konsole landen. In den Anfangstagen von Unix hatte jeder Rechner ein über ein serielles Interface angeschlossenes Terminal, die Konsole. Heute, in Zeiten grafischer Displays, ist die Konsole zumeist virtuell. Am ehesten bekommt man sie beim Booten zu Gesicht; insbesondere, wenn man während des Boot-Vorgangs durch einen Druck auf [Esc] das grafische Boot-Logo gegen die Konsolennachrichten tauscht.

Um die Konsole während des Betriebs nicht vollzuspammen, kennzeichnet der Kernel alle seine Nachrichten mit einem Log-Level zwischen 0 und 7 (siehe Tabelle “Log-Level und deren Abbildung im Kernel”). Diese Log-Level entsprechen denen des Syslog-Systems. Per System Call lässt sich die Schwelle konfigurieren, ab der die Mitteilungen ausgegeben werden. Dabei entspricht eine niedrige Zahl einer hohen Priorität.

Plappermäuler stopfen

Bei Bedarf stellen Sie die Schwelle über das Proc-Filesystem beziehungsweise mithilfe von »sysctl« und der zugehörigen Konfigurationsdatei »/etc/sysctl.conf« ein (Abbildung 2). Auf die Proc-Datei »/proc/sys/kernel/printk« setzen Sie durch vier Ganzzahlen vier Attribute. Die erste Ganzzahl repräsentiert die erwähnte Schwelle. Nur höher als die Schwelle priorisierte Nachrichten, also solche mit einem kleineren Log-Level, werden protokolliert. Die zweite Ganzzahl spezifiziert den Default-Log-Level, falls eine Nachricht keine Priorisierung mitbringt.

Abbildung 2: Per »sysctl« lässt sich das Log-System konfigurieren.

Als Nächstes folgt der »minimum_console_loglevel«. Dieser Wert sichert die Konfiguration des Default-Log-Levels ab, indem er eine Untergrenze dafür angibt. Damit lassen sich Bösewichter ausbremsen, die durch geschickte Änderung des Log-Levels ihr Tun verbergen wollen. Der vierte Wert schließlich gibt den Standard für den Log-Level vor. Auf dieser Priorisierungsebene werden Nachrichten verarbeitet, die keine Log-Level-Markierung aufweisen.

Über die Proc-Datei »/proc/sys/kernel/printk_delay« lassen sich Kernel-Meldungen um die dort konfigurierte Zeit verzögern. Erlaubt sind Werte zwischen 0 Millisekunden (keine Verzögerung) und 10 000 Millisekunden, also 10 Sekunden.

Ein häufiges Problem stellen wiederholt auftretende, identische Meldungen dar. Den zeitlichen Abstand zwischen zwei Meldungen stellen Sie über »printk_ratelimit« ein (in Sekunden) beziehungsweise lesen ihn aus. Über »printk_ratelimit_burst« legen Sie eine Anzahl von Wiederholungen fest, bevor die Zeitbedingung greift. Standardmäßig sind zehn Wiederholungen konfiguriert.

Als Letztes können Sie über die Proc-Datei »printk_devkmsg« konfigurieren, ob Applikationen über die Gerätedatei »/dev/kmsg« eigene Meldungen in das Kernel-Logging einpflegen dürfen. Standardmäßig ist das erlaubt, paranoide Admins stellen den Wert aus Sicherheitsgründen aber gern auf »off«.

Grundsätzlich sollten Sie im Hinterkopf behalten, dass der Kernel bei Aufruf von »printk()« die Nachrichten mit einem Zeitstempel versehen in einen Ringpuffer ablegt. Dessen Größe lässt sich konfigurieren, unter Ubuntu liegt sie bei 256 MByte. Diese Größe sowie die Frequenz, mit der neue Nachrichten auftreten und Nachrichten aus dem Ringpuffer gelesen werden, entscheiden darüber, ob Informationen verloren gehen oder nicht.

Die im Ringpuffer abgelegten Nachrichten lassen sich über den System Call »syslog« respektive via »klogctl« auslesen und als wieder überschreibbar markieren (siehe Tabelle “Kommandos der Funktion »klogctl()« (Auswahl)”). Alternativ kann der Zugriff über die Gerätedatei »/dev/kmsg« erfolgen. Zudem existiert ein Zugang über »/proc/kmsg«, der nur die neu hinzugekommenen Einträge liest.

Das den meisten Anwendern wohlvertraute Kommando »dmesg« greift übrigens auf »/dev/kmsg« zurück, um den Inhalt des Ringpuffers auszulesen und auf dem Terminal zu publizieren. Der schreibende Zugriff auf »/dev/kmsg« ermöglicht es, eigene Einträge in den Ringpuffer abzulegen.

Kernel-Lektüre

Das regelmäßige Auslesen gewährleistet auf den meisten Linux-Systemen der Rsyslog-Daemon (oder Alternativen wie »syslog-ng«). Der Dienst ist grundsätzlich für das Event-Management eines Linux-Systems zuständig. Dank der umfangreichen Konfigurationsmöglichkeiten leitet Rsyslogd die Nachrichten nicht nur in Log-Dateien um, sondern protokolliert auch gern per Netzwerk auf andere Server.

Die Filtermöglichkeiten für jedes Log-Level müssen sich im Kernel im Aufruf von »printk()« widerspiegeln. Linus Torvalds hat sich dazu eine Lösung ausgedacht, die weitgehend kompatibel zu »printf()« arbeitet. Statt einen zusätzlichen Parameter für den Log-Level einzuführen, lässt sich dieser optional mit einer Ganzzahl am Anfang des sogenannten Format-Strings durch Setzen in spitzen Klammern spezifizieren.

Um den Code etwas lesbarer zu gestalten, spaltet der Linux-Kernel den Format-String in diesen Anfangsteil und die eigentliche Ausgabe auf. Für den Anfangsteil, also die Priorität als Ganzzahl in spitzen Klammern, hat Torvalds Defines festgelegt. Das führt zu einem Aussehen, das beispielsweise in Zeile 11 in Listing 1 zu sehen ist. Man beachte, dass zwischen dem Define und dem restlichen Format-String kein Komma stehen darf.

#include <linux/module.h>
#include <linux/cdev.h>
static int __init mod_init(void) {
  char *ptr = NULL;
  char field[64];
  __be32 ipv4addr = 0x2a2aa8c0;
  printk("mod_init called\n");
  ptr = (char *)-0x1;
  printk( KERN_INFO "Pointer (gehasht und orginal)): %p - %px\n", field, field );
  pr_info("Pointer (Fehlertext und Wert): %pe - %p\n", ptr, ptr );
  pr_debug("Pointer (symbolisch): %pS - %pS\n", mod_init, cdev_add );
  pr_err("Pointer (symbolisch, Modul): %pSb - %pSb\n", mod_init, cdev_add);
  printk("Feld (8 Elemente): %8ph\n", field );
  printk("IPv4-Adresse: %pI4\n", &ipv4addr );
  print_hex_dump( KERN_INFO, "Linux-Mag: ", DUMP_PREFIX_NONE,16,1,field,sizeof(field),1);
  // WARN( ptr==(char*)(-1), "Uppps, just for fun");
  return -1;
}
static void __exit mod_exit(void)
{
    printk("mod_exit called\n");
}
module_init( mod_init );
module_exit( mod_exit );
MODULE_LICENSE( "GPL" );

Zusätzlich gibt es noch Makros wie »pr_info()« (Zeile 12) oder »pr_debug()« (Zeile 13). Die mit »pr_« beginnenden Makros ergänzen den Format-String um den zugehörigen Log-Level sowie zusätzlich um den Modulnamen. In Abgrenzung zu »pr_info()« wird »pr_debug()« nur dann mitkompiliert, wenn das Define »KERN_DEBUG« gesetzt ist. In einem Gerätetreiber empfehlen sich im Übrigen Varianten, die mit »dev_« beginnen: Sie ergänzen über einen zusätzlichen Parameter die Ausgabe um das Gerät (Device).

Apropos Debug: In der Trickkiste von Linux befinden sich noch die Makros »bug()«, »bug_on()«, »warn()«, »warn_on()« und »warn_once«. Allen diesen Makros übergeben Sie als ersten Parameter eine Bedingung. Trifft sie zu, geben die Routinen den Stacktrace aus. Aus ihm lässt sich die Aufrufkaskade ablesen, was sehr nützlich zur Fehleranalyse ist.

Die »warn()«-Makros begnügen sich mit einer umfangreichen Ausgabe, die »bug()«-Routinen lösen hingegen eine Kernel Panic und das Beenden des aktiven Kernel-Codes aus. Während die einfachen Spielarten mit dem Stacktrace den Namen des Quellcodemoduls und die Zeilennummer ausgeben, bekommen die »_on«-Varianten einen Format-String samt potenziellen Parametern überreicht. Das Makro »warn_once« stellt sicher, dass die Meldung nur ein einziges Mal ausgegeben wird und nicht gleich das ganze System mit wiederholten Meldungen flutet.

Tückisches <C>printk()<C>

Nicht nur seine Syslog-Anbindung zeichnet »printk()« aus, sondern auch die umfangreichen Formatierungsmöglichkeiten.

Jedes Prozentzeichen im Format-String leitet eine sogenannte Umsetzungssequenz ein. Sie wird bei der Ausgabe durch einen Wert oder Text ersetzt, den »printk()« als weiteren Parameter übergeben bekommt. Die durch das Prozentzeichen eingeleitete Umsetzungssequenz bestimmt durch zusätzliche, angehängte Zeichen, wie es den Wert zu formatieren gilt. Ein »%d« beispielsweise sorgt für eine dezimale Ausgabe des übergebenen Werts, ein »%x« präsentiert ihn in seiner hexadezimalen Form.

Die Umsetzungssequenzen für die Standarddatentypen sind mit denen von »printf()« identisch. Umsetzungssequenzen für Fließkommazahlen fehlen jedoch, da es die im Kernel nicht gibt. Auch das sicherheitsgefährdende »%n« wurde glücklicherweise aus dem Betriebssystemkern verbannt.

Exotisch und manchmal tückisch wird es bei der Ausgabe von Adressen, also Pointern. Das klassische »%p« existiert zwar, doch wer erwartet, die richtige Adresse zu sehen, wird enttäuscht (Abbildung 3). Tatsächlich gibt Linux standardmäßig nur gehashte Adressen zurück, damit potenzielle Angreifer keine Rückschlüsse über Adresslagen des Kernels ziehen können. Wenn Sie die unmodifizierte Adresse sehen möchten, verwenden Sie ein »px«.

Abbildung 3: Diverse »printk()«-Varianten erhöhen die Lesbarkeit.

Generell lässt sich also die Umsetzungssequenz »%p« erweitern. Ein »%pe« beispielsweise gibt den zu einem Fehler gehörenden String aus, falls der Pointer einen solchen Fehler repräsentiert (Listing 1, Zeile 13). Bei »%pS« gibt »printk()« anstelle der Adresse den symbolischen Namen einer Variablen oder Funktion aus, soweit der Kernel auf die Symbole und deren Adressen Zugriff hat. Bei einem weiter angehängtem »b«, also »%pSb«, erscheint zusätzlich der Modulname.

Die Funktion »printk()« kann darüber hinaus Felder bis zu einer Größe von 64 Byte in hexadezimaler Form liefern. Dazu geben Sie nach dem Prozentzeichen die Anzahl auszugebender Bytes an, danach das »p« und schließlich optional noch ein »C«, »D« oder »N«. Ohne ein weiteres Zeichen fügt »printk()« zwischen den Bytes ein Leerzeichen ein. Bei einem »C« (“colon”) verwendet die Funktion stattdessen Doppelpunkte, bei einem »D« (“dash”) Minuszeichen. Bei einem »N« (“nothing”) hängt sie die Bytes direkt aneinander.

Wollen Sie übrigens mehr als 64 Bytes ausgeben, empfiehlt sich dazu die Funktion »print_hex_dump()« (Listing 1, Zeile 17).

Ausgaben leicht gemacht

Die Kernel-Funktion »printk()« kann noch mehr. So gibt es Umsetzungssequenzen für MAC- und IP-Adressen. Dazu dient ein dem »p« angehängtes »M« oder »m«. Ersteres gibt die Adressen inklusive eines Zwischenzeichens aus, Letzteres ohne. Ein zusätzlich angehängtes »R« (“reverse”) stellt die MAC-Adresse in umgekehrter Reihenfolge dar, wie es bei Bluetooth-Adressen häufig üblich ist.

Für die IP-Adressen kombinieren Sie das »p« mit einem »I4« (Zeile 16). Bei einem kleingeschriebenen »i« werden die Adressen dreistellig mit führenden Nullen ausgegeben. Die »4« steht für IPv4-Adressen, die gemäß der Norm aus vier Bytes bestehen. Die »4« lässt sich übrigens noch mit einem »h«, »n«, »b« oder »l« kombinieren, um sie im Host-Format, im Netzformat, als Big-Endian respektive als Little-Endian zu interpretieren.

Es ist nicht schwer zu erraten, dass der Kernel auch IPv6 unterstützt und Sie dazu das »p« mit einem »I6« oder »i6« kombinieren. Das kleine »i« lässt wieder die Zwischenzeichen weg. Ein zusätzlich angehängtes »c« stellt die IPv6-Adresse in Kurzform dar, bei der beispielsweise Folgen von Nullen bei Eindeutigkeit wegfallen dürfen.

Die Tabelle “Ausgewählte Umsetzungssequenzen” listet Umsetzungssequenzen für weitere spezifische Datentypen auf, so etwa 16 Byte breite UUIDs und GUIDs, Dentry-Namen, Blockgerätenamen oder Devicetree-Knoten. Auch Fwnodes und Zeitstempel lassen sich automatisiert und standardisiert ausgeben. Daneben finden sich Clocks und Bitmaps ebenso im Programm wie Flags, die bei Seitentabellen vorkommen. Eine Auflistung finden Sie auf Kernel.org [1].

Sofern der Quellcode aus Listing 1 in der Datei »printktest.c« vorliegt, es ein passendes Makefile gibt und Sie die geeigneten Pakete zur Generierung von Kernel-Code (build-essential, flex, bison) installiert haben, können Sie unser Beispiel durch Aufruf von »make« zum Modul »printktest.ko« generieren lassen. Ein »insmod printktest.ko« lädt das Modul, wobei das »return -1« am Ende der Funktion »mod_init()« ein Einnisten in den Kernel verhindert. Das erklärt auch die (letztlich beabsichtigte) Fehlermeldung beim Laden.

Um sich die Ausgabe anzeigen zu lassen, geben Sie beispielsweise das Kommando »tail -n 10 /var/log/kern.log« auf der Konsole ein. Abbildung 4 zeigt das Makefile, die Generierung, das Laden des Moduls und schließlich die Ausgabe über die Datei »/var/log/kern.log«. Dabei erkennen Sie die unterschiedlichen Formatierungen von Pointern.

Abbildung 4: Mit diesen Kommandos generieren Sie das Testmodul, laden es und sehen sich das Ergebnis an.

Fazit

Bei genauerer Betrachtung entpuppt sich das schlicht aussehende »printk()« als eine sehr mächtige, trickreiche Funktion, die ihre Abstammung vom Urahn »printf()« keineswegs leugnet. Das um die Funktion herum gebaute Kernel-Log-System gibt Admins alle Fäden in die Hand, um Nachrichten aus dem Linux-Inneren ressourcenschonend so zu filtern, dass keine wichtigen Nachrichten verloren gehen. Für alles darüber Hinausgehende bringt das altbewährte Syslog weitere Möglichkeiten mit. Das sind doch gute Nachrichten! (jlu)