© ratoca / 123RF.vom

Eine Protokollierung braucht man auch in vielen Bash-Skripten. Daher bietet es sich an, das Logging mit einem eigenen Modul für den Anwender einfach handhabbar und einheitlich zu gestalten.

In dieser Serie ist bisher ein Modulsystem für die Bash entstanden [1], und wir haben ein Array-Modul implementiert [2], das mit Unit-Tests geprüft wurde [3]. Damit haben wir zwar schon eine ordentliche Grundlage geschaffen, aber um nützliche Skripte schreiben zu können – geschweige denn verteilte Systeme – fehlen uns in unserer Bibliothek noch wichtige Komponenten. In diesem Teil programmieren wir ein Modul, das wir in jedem folgenden Skript brauchen werden: Es generiert schöne Logs und Debug-Ausgaben.

Überlegen wir uns zuerst, was wir erreichen wollen: Was zeichnet gutes Logging aus? In verteilten Systemen interagieren mehrere Prozesse, weshalb Protokollausgaben oft korrelieren. Deshalb soll sich der Zeitpunkt eines Ereignisses an der Ausgabe ablesen lassen. Um Anfragen parallel abzuarbeiten, läuft von manchen Skripten mehr als eine Instanz zur selben Zeit. Hilfreich wäre es also, wenn wir erkennen können, von welcher Instanz eine Ausgabe erzeugt wurde.

Zudem sind nicht alle Ausgaben gleich wichtig. Ein Kürzel, an dem sich erkennen lässt, ob es sich bei einer Meldung um einen kritischen Fehler, eine Warnung oder nur eine Information handelt, erlaubt dem Nutzer einzuschätzen, ob Handlungsbedarf besteht. Wie hilfreich eine Meldung ist, hängt aber nicht zuletzt auch davon ab, wer sie liest. Debug-Ausgaben helfen Entwicklern dabei, Fehler im Code zu lokalisieren, aber aus Sicht eines Anwenders, der die Sprache der Shell nicht spricht, beanspruchen sie nur unnötig die SSD. Wir brauchen also auch eine Stellschraube zum Filtern von Ausgaben.

Mehrlagig

Wir geben dem Modul den naheliegenden Namen »log« und planen die vier Ausgabefunktionen »log_error()«, »log_warning()«, »log_info()« und »log_debug()«, mit denen der Aufrufer Fehler, Warnungen, informative Meldungen und Debug-Ausgaben erzeugt. Um die Ausgaben zu filtern, definieren wir für jede der vier Funktionen ein Log-Level und ermöglichen dem Aufrufer, mit den Funktionen »log_get_verbosity()« und »log_set_verbosity()« das Log-Level auszulesen beziehungsweise zu setzen.

Wir beginnen also mit der Definition der vier Log-Levels, wozu wir globale Variablen verwenden. Gemäß der Konventionen aus dem zweiten Teil der Serie deklarieren wir die Log-Levels im Konstruktor des Moduls (Listing 1) mit den Variablen »__log_debug«, »__log_info«, »__log_warning« und »__log_error«, die wir mit »-ri« als konstante Integer deklarieren. Das aktuelle Log-Level speichern wir in »__log_verbosity« und legen »__log_warning« als Default fest. Standardmäßig werden also nur Warnungen und Fehler ausgegeben.

Da die meisten Prozesse unseres verteilten Systems im Hintergrund laufen, wollen wir Ausgaben nicht nur auf die Standardfehlerausgabe, sondern auch in eine Log-Datei schreiben, die wir im Home-Verzeichnis des Nutzers unter ».bms/log« ablegen. Daher deklarieren wir im Konstruktor auch die Variablen »__log_path« und »__log_file«, in denen das Verzeichnis beziehungsweise der komplette Pfad der Log-Datei gespeichert ist.

Zuletzt soll der Konstruktor auch dafür sorgen, dass das Log-Verzeichnis existiert. Mit der Option »–parents« erzeugt »mkdir« die komplette Verzeichnisstruktur und gibt auch dann Erfolg zurück, falls das Verzeichnis bereits existiert.

__init() {
  local script_name
  script_name="${0##*/}"
  declare -xgri __log_debug=3
  declare -xgri __log_info=2
  declare -xgri __log_warning=1
  declare -xgri __log_error=0
  declare -xgi __log_verbosity="$__log_warning"
  declare -xgr __log_path="$HOME/.bms/log"
  declare -xgr __log_file="$HOME/.bms/log/$script_name.log"
  if ! mkdir --parents "$__log_path"; then
    return 1
  fi
  return 0
}

Als Nächstes kommen wir zu den Ausgabefunktionen. Alle vier Funktionen tun im Wesentlichen dasselbe, weshalb sie sich in der Handhabung nicht unterscheiden sollten. Doch wie wollen wir sie eigentlich einsetzen? Ein strategisch platzierter Aufruf von »log_info()« wie etwa »log_info “Synchronisiere mit $server”« macht so manchen Kommentar im Code überflüssig. Es soll also möglich sein, eine oder mehrere Meldungen als Parameter an die Log-Funktionen zu übergeben.

Um Ausgaben als Argument zu übergeben, müssen sie aber erst einer Variablen zugewiesen werden. Die Ausgabe kann daher erst dann erfolgen, wenn der Befehl abgeschlossen ist, der sie erzeugt. Wenn wir die Ausgabe eines Befehls, der mehrere Minuten läuft, auf diese Weise protokollieren, wird die Ausgabe also erst mit mehreren Minuten Verzögerung sichtbar. Besser wäre es, wenn wir unsere Log-Funktionen wie im Befehl »apt-get install -y toolbox | log_info« an das Ende einer Pipe hängen könnten, um Ausgaben in Echtzeit zu protokollieren. Wenn unseren Log-Funktionen keine Argumente übergeben wurden, sollen sie folglich Daten von der Standardeingabe lesen.

Wir schreiben darum zunächst eine Hilfsfunktion »_log_write()«, der wir das Log-Level, das Log-Tag sowie die zu protokollierenden Daten übergeben. Die Funktion soll also die Struktur haben, die Listing 2 zeigt.

_log_write() {
  local -i level="$1"
  local tag="$2"
  local lines=("${@:3}")
  if (( ${#lines[@]} == 0 )); then
    # Standardeingabe protokollieren
  else
    # Parameter protokollieren
  fi
  return 0
}

Der Fall, dass der Funktion keine Parameter übergeben wurden, ist schnell implementiert (Listing 3). Wir müssen lediglich »read()« in einer While-Schleife aufrufen, um die Standardeingabe Zeile für Zeile zu lesen. Wir rufen dann die Funktion erneut auf, diesmal mit der zu protokollierenden Zeile als Parameter. Der Code im Else-Zweig kommt also in beiden Fällen zum Einsatz. Wichtig ist, beim Aufruf von »read()« die Option »-r« zu übergeben, damit die Funktion keine Escape-Sequenzen interpretiert.

Außerdem müssen wir sicherstellen, dass die Umgebungsvariable »IFS« (der Internal Field Separator) leer ist. Letztere definiert die Zeichen, die die Bash als Wortgrenzen betrachtet. IFS enthält standardmäßig vier Zeichen: Leerzeichen, Tabulator, Zeilenumbruch und das Null-Byte. Diese Zeichen werden beim Aufruf von »read()« vom Anfang und Ende der Zeile abgeschnitten. Da die Eingabe möglicherweise Einrückungen enthält, gilt es, sie unverfälscht auszugeben. Dass wir dem Aufruf die Zuweisung »IFS=””« voranstellen, bewirkt, dass sich der Wert von IFS nicht für das gesamte Skript ändert, sondern nur für den Aufruf von »read()«.

while IFS="" read -r line; do
  if ! _log_write "$level" "$tag" "$line"; then
    return 1
  fi
done

In Parametern am »_log_write()« übergebene Daten sollen zeilenweise ausgegeben werden. In diesem Fall müssen wir also ,wie in Listing 4 gezeigt, über die Elemente von »lines« iterieren und jedes Element zusammen mit Datum, Uhrzeit, Prozess-ID und Log-Tag ausgeben. Der Befehl »Tee« erlaubt, Daten gleichzeitig in eine Datei und auf die Standardausgabe zu schreiben. Durch die Umleitung der Standardausgabe auf die Standardfehlerausgabe mit »1>&2« können wir gleichzeitig in die Log-Datei und auf die Standardfehlerausgabe schreiben.

for line in "${lines[@]}"; do
  local timestamp
  if ! timestamp=$(date +"%F %T %z"); then
    echo "Kann Timestamp nicht erzeugen" 1>&2
    return 1
  fi
  if ! echo "$timestamp $$ $tag $line" | tee --append "$__log_file" 1>&2; then
    echo "Kann nicht nach $__log_file schreiben" 1>&2
  fi
done

Unsere »_log_write()«-Funktion ist damit schon recht komplett. Es fehlen nur noch die Prüfung des Log-Levels und die Deklaration der Variablen »line«, die in beiden Verzweigungen verwendet wurde. Listing 5 zeigt die fertige Funktion.

_log_write() {
  local -i level="$1"
  local tag="$2"
  local lines=("${@:3}")
  local line
  if (( __log_verbosity < level )); then
    return 0
  fi
  if (( ${#lines[@]} == 0 )); then
    while IFS="" read -r line; do
      if ! _log_write "$level" "$tag" "$line"; then
        return 1
      fi
    done
  else
    for line in "${lines[@]}"; do
      local timestamp
      if ! timestamp=$(date +"%F %T %z"); then
        echo "Kann Timestamp nicht erzeugen" 1>&2
        return 1
      fi
      if ! echo "$timestamp $$ $tag $line" | tee --append "$__log_file" 1>&2; then
        echo "Kann nicht nach $__log_file schreiben" 1>&2
      fi
    done
  fi
  return 0
}

Wir können nun die anderen Funktionen durch einen einfachen Aufruf von »_log_write()« wie in Listing 6 implementieren. Einzig »log_debug()« weicht vom Muster ab, denn bei Debug-Ausgaben sollte man nachvollziehen können, woher die Ausgabe kommt.

Im ersten Teil der Serie haben wir bereits beiläufig die Variable »FUNCNAME« kennengelernt, die den Namen der aktuellen Funktion enthält. Tatsächlich handelt es sich bei »FUNCNAME« aber nicht um eine einfache Variable, sondern um ein Array. Es enthält nicht nur den Namen der aktuellen Funktion, sondern auch die Namen der aufrufenden Funktionen. Um den Aufrufer von »log_debug()« herauszufinden, müssen wir also lediglich das zweite Element von »FUNCNAME« ausgeben.

Die Bash stellt neben »FUNCNAME« auch die Arrays »BASH_SOURCE« und »BASH_LINENO« bereit, mit denen wir auf dieselbe Weise den Namen des Skripts und die Zeilennummer ermitteln, von der aus »log_debug()« aufgerufen wurde.

log_error() {
  local lines=("$@")
  _log_write "$__log_error" "[ERR]" "${lines[@]}"
}
log_warn() {
  local lines=("$@")
  _log_write "$__log_warning" "[WRN]" "${lines[@]}"
}
log_info() {
  local lines=("$@")
  _log_write "$__log_info" "[INF]" "${lines[@]}"
}
log_debug() {
  local lines=("$@")
  local dbgtag
  dbgtag="${BASH_SOURCE[1]}:${BASH_LINENO[1]} ${FUNCNAME[1]}:"
  _log_write "$__log_debug" "[DBG] $dbgtag" "${lines[@]}"
}

Blick fürs Wesentliche

Die Ausgabefunktionen sind damit komplett, es fehlen aber noch die Funktionen zum Auslesen und Setzen des Log-Levels. Da »log_get_verbosity()« lediglich den Wert von »__log_verbosity« ausliest, genügt ein Einzeiler (Listing 7). Die Funktion »log_set_verbosity()« dagegen fällt ein wenig länger aus, da sie sicherstellen muss, dass das vom Aufrufer übergebene Log-Level nicht zu groß oder zu klein ist.

log_get_verbosity() {
  echo "$__log_verbosity"
}
log_set_verbosity() {
  local -i verb="$1"
  if (( verb < __log_error )); then
    verb="$__log_error"
  elif (( verb > __log_debug )); then
    verb="$__log_debug"
  fi
  __log_verbosity="$verb"
  return 0
}

Die Funktionen legen wir nun unter »/usr/local/share/bms/include/log.sh« ab und schreiben ein kurzes Skript wie das in Listing 8, mit dem wir einige Ausgaben protokollieren. Führen wir das Skript nun aus, erhalten wir die in Abbildung 1 gezeigte Ausgabe. Wie erwartet erscheinen standardmäßig nur Fehler und Warnungen. Erst ein Anpassen des Log-Levels macht andere Ausgaben sichtbar.

Abbildung 1: Sieht gut aus: unser Log-Modul.

#!/bin/bash
main() {
  log_debug "Diese Debugmeldung wird nicht ausgegeben"
  log_info  "Diese Info wird auch nicht ausgegeben"
  log_warn  "Diese Warnung wird ausgegeben"
  log_error "Fehler werden immer ausgegeben"
  log_set_verbosity 10
  log_debug "Diese Debugmeldung wird ausgegeben"
  log_info  "Diese Info wird ausgegeben"
  seq 1 5 | log_error
  log_set_verbosity -1
  log_error "Fehler werden immer ausgegeben"
  return 0
}
{
  if ! . bms.sh; then
    exit 1
  fi
  if ! include "log"; then
    exit 1
  fi
  main "$@"
  exit "$?"
}

Stapellauf

Die von der Bash verwalteten Arrays, die wir für »log_debug()« verwendet haben, enthalten nicht nur Informationen über den direkten Aufrufer, sondern über alle Aufrufer bis hin zur Main-Funktion. Das lässt sich ausnutzen, um einen Stacktrace zu erzeugen, also eine Ausgabe der Aufrufhierarchie. Wir müssen dafür lediglich »FUNCNAME« vom letzten bis zum zweiten Element rückwärts durchlaufen und die Einträge nacheinander ausgeben.

Da »BASH_SOURCE«, »BASH_LINENO« und »FUNCNAME« stets gleich groß sind, ergibt sich die entsprechende Funktion »log_stacktrace()« (Listing 9) fast von selbst. Wir fügen sie in das Log-Modul ein und testen das Konstrukt mit einem kurzen Skript wie dem in Listing 10. Funktioniert alles wie gewünscht, sieht die Ausgabe so aus, wie die in Abbildung 2.

Abbildung 2: Stacktraces mit Einrückung.

log_stacktrace() {
  local -i i
  local indent
  echo "Stacktrace:"
  indent="  "
  for (( i = ${#FUNCNAME[@]} - 1; i > 0; i-- )); do
    echo "$indent${BASH_SOURCE[$i]}:${BASH_LINENO[$i]} ${FUNCNAME[$i]}"
    indent+="  "
  done
  return 0
}

#!/bin/bash
baz() {
  log_stacktrace | log_error
}
bar() {
  baz
}
foo() {
  bar
}
main() {
  foo
}
{
  if ! . bms.sh; then
    exit 1
  fi
  if ! include "log"; then
    exit 1
  fi
  main "$@"
  exit "$?"
}

Im Rampenlicht

Werden mehrere Zeilen auf einmal ausgegeben, sorgt es für mehr Übersicht, wenn man beim Lesen erkennen kann, welche Zeilen zusammengehören. Dazu schreiben wir noch eine Funktion namens »log_highlight()« (Listing 11).

Da wir in Log-Dateien nicht mit Farben arbeiten können, markieren wir den Anfang und das Ende der Ausgabe stattdessen mit Zeichenketten, die ins Auge stechen (Zeile 5, Zeile 14). Mit »= BEGIN Inhalt =« markieren wir den Anfang und mit »= END Inhalt =« das Ende der Ausgabe, wobei Inhalt für die Zeichenkette steht, die der Aufrufer als ersten Parameter an »log_highlight()« übergeben hat.

Wie die anderen Log-Funktionen soll »log_highlight()« Daten entweder über Parameter oder die Standardeingabe entgegennehmen. Ähnlich wie in »_log_write()« bildet daher ein If-Else-Konstrukt den Kern der Funktion. Da wir die einzelnen Zeilen aber nicht verändern, genügt es, die Standardeingabe direkt mit Cat in die Standardausgabe zu schreiben (Zeile 7).

log_highlight() {
  local tag="$1"
  local lines=("${@:2}")
  echo "===== BEGIN $tag ====="
  if (( ${#lines[@]} == 0 )); then
    cat /dev/stdin
  else
    local line
    for line in "${lines[@]}"; do
      printf "%s\n" "$line"
    done
  fi
  echo "===== END $tag ====="
  return 0
}

Zeile 4 aus Listing 10 ändern wir nun so ab, dass sie den Stacktrace mittels »log_highlight()« optisch hervorgehoben ausgibt (Listing 12). Das veränderte Skript erzeugt die in Abbildung 3 gezeigte Ausgabe. Durch die Gleichheitszeichen in den Trennern lassen sich Anfang und Ende der Ausgabe auch in längeren Log-Dateien schnell ausmachen.

log_stacktrace | log_highlight "Aufrufhierarchie" | log_error

Abbildung 3: Mit »log_highlight()« lassen sich Passagen im Log hervorheben.

Ausblick

Jedes der Skripte in unserem verteilten System wird Log-Ausgaben erzeugen. Es zahlt sich daher aus, ein Modul mit einer komfortablen API zu erstellen und nicht ad hoc mit Echo auf die Standardfehlerausgabe zu schreiben. Bevor wir zur Kommunikation zwischen Skripten kommen, gibt es aber noch ein weiteres, ähnlich fundamentales Thema wie das Logging: Im nächsten Teil entwickeln wir einen Parser für die Kommandozeile, der Getopt in den Schatten stellt. (jcb/jlu)