Kapitel 4. Rezepte protokollieren

Diese Arbeit wurde mithilfe von KI übersetzt. Wir freuen uns über dein Feedback und deine Kommentare: translation-feedback@oreilly.com

4.0 Einleitung

Unter Logging versteht man die Aufzeichnung von Ereignissen, die während der Ausführung eines Programms auftreten. Diese Tätigkeit wird beim Programmieren oft unterschätzt, weil sie zusätzliche Arbeit bedeutet, die sich für den Programmierer nicht sofort auszahlt.

Während des normalen Betriebs eines Programms ist die Protokollierung ein Overhead, der Verarbeitungszyklen in Anspruch nimmt, um in eine Datei, eine Datenbank oder sogar auf den Bildschirm zu schreiben. Darüber hinaus können nicht verwaltete Logs Probleme verursachen. Der klassische Fall, dass die Logdateien so groß werden, dass sie den gesamten verfügbaren Speicherplatz belegen und den Server zum Absturz bringen, ist nur zu real und passiert zu oft.

Wenn jedoch etwas passiert und du die Abfolge der Ereignisse herausfinden willst, die dazu geführt haben, werden die Protokolle zu einer unschätzbaren diagnostischen Ressource. Logs können auch in Echtzeit überwacht werden und bei Bedarf können Warnmeldungen verschickt werden.

4.1 In Protokolle schreiben

Problem

Du möchtest Ereignisse protokollieren, die während der Ausführung deines Codes passieren.

Lösung

Verwende das log Paket in der Standardbibliothek, um Ereignisse zu protokollieren.

Diskussion

Go stellt in der Standardbibliothek das Paket log zur Verfügung, mit dem du Ereignisse protokollieren kannst, während das Programm läuft. Es hat eine Standardimplementierung, die in den Standardfehler schreibt und einen Zeitstempel hinzufügt. Das bedeutet, dass du es sofort für die Protokollierung verwenden kannst, ohne es konfigurieren oder einrichten zu müssen, wenn du in den Standardfehler schreiben willst.

Das Paket log bietet mehrere Funktionen, mit denen du Logs schreiben kannst. Es gibt vor allem drei Gruppen von Funktionen:

Drucken

Druckt die Protokolle an den Logger

Tödlich

Druckt in den Logger und ruft os.Exit mit einem Exit-Code von 1 auf

Panik

Druckt in den Logger und ruft panic

Jedes Set besteht aus drei Funktionen; Print hat zum Beispiel Print und Printf, die eine Formatierung ermöglichen, und Println fügt nach dem Drucken einen Zeilenumbruch hinzu.

Hier ist ein Beispiel mit Print:

func main() {
	str := "abcdefghi"
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Println("Cannot parse string:", err)
	}
	fmt.Println("Number is", num)
}

Wenn in diesem Beispiel ein Fehler auftritt, rufst du die Funktion Println auf, die in den Standard-Logger ausgibt. Das siehst du in der Befehlszeile, wenn du das Programm ausführst:

% go run main.go
2022/01/23 18:39:06 Cannot parse string: strconv.ParseInt: parsing "abcdefghi":
 invalid syntax
Number is 0

Du wirst auch sehen, dass das Programm nicht anhält und bis zur letzten Anweisung des Programms weiterläuft. Mit anderen Worten: Println protokolliert einfach und macht weiter. Was ist der Unterschied zu fmt.Println? Eigentlich gar nicht - das Einzige, was in der Zeile hinzugefügt wird, ist das Datum.

Als Nächstes wirf einen Blick auf Fatal . Du änderst nur eine Zeile des Codes, um Fatalln zu verwenden:

func main() {
	str := "abcdefghi"
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Fatalln("Cannot parse string", err)
	}
	fmt.Println("Number is", num)
}

Wenn du es ausführst, solltest du Folgendes sehen:

% go run main.go
2022/01/23 18:42:10 Cannot parse string strconv.ParseInt: parsing "abcdefghi":
invalid syntax
exit status 1

Beachte, dass die letzte Anweisung nicht ausgeführt wird und das Programm mit dem Exit-Code 1 endet. Der Exit-Code 1 ist ein Sammelbegriff für allgemeine Fehler, d.h. irgendetwas ist mit dem Programm schief gelaufen, und deshalb muss es beendet werden.

Schließlich kannst du Panic verwenden. Wenn du die eingebaute Funktion panic aufrufst, hält sie die aktuelle Goroutine an, führt den aufgeschobenen Code aus und kehrt zur aufrufenden Funktion zurück, wodurch eine weitere panic ausgelöst wird, die schließlich zu main aufsteigt und schließlich beendet wird. Mehr über die eingebaute Funktion panic erfährst du in Rezept 3.7:

func main() {
	str := "abcdefghi"
	num := conv(str)
	fmt.Println("Number is", num)
}

func conv(str string) (num int64) {
	defer fmt.Println("deferred code in function conv")
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Panicln("Cannot parse string", err)
	}
	fmt.Println("end of function conv")
	return
}

Die Funktion Panicln druckt in den Standard-Logger und gerät in Panik. Wenn du den Code ausführst, siehst du Folgendes:

% go run main.go
2022/01/23 18:48:20 Cannot parse string strconv.ParseInt: parsing "abcdefghi":
invalid syntax
deferred code in function conv
panic: Cannot parse string strconv.ParseInt: parsing "abcdefghi": invalid syntax
...
exit status 2

Der verzögerte Code in der Funktion conv läuft, aber die letzte Anweisung im Programm nicht. Interessanterweise siehst du den Exit Code 2, was technisch nicht korrekt ist, denn traditionell bedeutet Exit Code 2 so etwas wie "falsche Argumente". Seit Go Version 1.17.6 ist dieser kleine Fehler immer noch in der Warteschlange und wartet darauf, behoben zu werden.

4.2 Ändern, was vom Standard-Logger aufgezeichnet wird

Problem

Du möchtest ändern, was der Standard-Logger protokolliert.

Lösung

Verwende die Funktion SetFlags , um Flags zu setzen und Felder zu jeder Protokollzeile hinzuzufügen.

Diskussion

Das Standardverhalten des Standard-Loggers fügt die Felder für Datum und Uhrzeit zu jeder Zeile des Protokolls hinzu. Zum Beispiel mit dieser Codezeile:

log.Println("Some event happened")

wirst du dies auf dem Bildschirm sehen:

2022/01/24 10:46:44 Some event happened

Mit dem Paket log kannst du zusätzlich zu den Standardfeldern für Datum und Uhrzeit weitere Informationen hinzufügen. Du kannst diese Felder mit der Funktion SetFlag hinzufügen. Zu den zur Verfügung stehenden Feldern gehören:

Datum

Das Datum in der lokalen Zeitzone

Zeit

Die Zeit in der lokalen Zeitzone

Mikrosekunden

Die Mikrosekunde Auflösung des Zeitfeldes

UTC

Verwende die Zeitzone UTC anstelle der lokalen Zeitzone, wenn Datums- oder Zeitfelder gesetzt sind

Lange Datei

Der vollständige Dateiname und die Zeilennummer

Kurze Datei

Der Dateiname und die Zeilennummer

Position des Nachrichtenpräfixes

Verschiebe das Präfix (von SetPrefix) vom Anfang der Zeile vor den Anfang der Nachricht

Hier sind einige Beispiele. Du beginnst damit, dass du nur das Datumsfeld im Protokoll einstellst:

log.SetFlags(log.Ldate)
log.Println("Some event happened")

Das ergibt:

2022/01/24 Some event happened

Wenn du die Zeit mit Mikrosekundenangaben hinzufügen möchtest, tust du dies:

log.SetFlags(log.Ldate | log.Lmicroseconds)
log.Println("Some event happened")

Mit dem or Operator für die Flags richtest du die verschiedenen Felder ein, die mit dem Log verwendet werden sollen. Hier ist das Ergebnis von vorher:

2022/01/24 20:43:54.595365 Some event happened

Die Dateifelder sind interessant, weil du mit ihnen anhand der Logs feststellen kannst, wo dieProbleme im Code liegen:

log.SetFlags(log.Ldate | log.Lshortfile)
log.Println("Some event happened")

Er gibt dir zusätzliche Informationen über den Dateinamen und die Zeile, in der dasProblem aufgetreten ist:

2022/01/24 20:51:02 logging.go:20: Some event happened

4.3 Protokollierung in Datei

Problem

Du möchtest Ereignisse in einer Logdatei statt in der Standardfehlerdatei protokollieren.

Lösung

Verwende die Funktion SetOutput , um das Protokoll in eine Datei zu schreiben.

Diskussion

Bisher hast du gelernt, wie man die Logs in den Standardfehler schreibt, vor allem auf den Bildschirm, wenn du sie in der Kommandozeile ausführst. Was ist, wenn du sie in eine Logdatei schreiben willst, was in den meisten Fällen der Fall ist?

Die Antwort ist ziemlich einfach. Du benutzt SetOutput, um die Ausgabe in eine Datei umzuleiten.

Schau dir zuerst das Logfile an. Du willst eine neue Datei zum Erstellen oder Anhängen öffnen, und sie ist nur zum Schreiben gedacht:

file, err := os.OpenFile("app.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
if err != nil {
    log.Fatal(err)
}
defer file.Close()

Du rufst SetOutput mit der Datei als Parameter auf und fährst dann mit der Protokollierung fort:

log.SetOutput(file)
log.Println("Some event happened")

Die Ausgabe wird unter in die app.log-Datei statt auf den Bildschirm geschrieben.

Wie du wahrscheinlich aus dem Code entnommen hast, sollte das Einrichten der Logs, die in eine Datei geschrieben werden sollen, nur einmal gemacht werden. Was ist, wenn du gleichzeitig auf den Bildschirm und in die Datei schreiben willst? Du könntest die Protokollausgabe jedes Mal zurücksetzen (tue das nicht) oder vielleicht zwei Logger erstellen, einen für Standardfehler und einen für eine Datei, und die Logger dann in separatenAnweisungen aufrufen.

Oder du kannst Go's MultiWriter Funktion im io Paket verwenden, die einen Writer erstellt, der seine Schreibvorgänge auf alle bereitgestellten Writer dupliziert:

file, err := os.OpenFile("app.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
if err != nil {
    log.Fatal(err)
}
defer file.Close()
writer := io.MultiWriter(os.Stderr, file)
log.SetOutput(writer)
log.Println("Some event happened")
log.Println("Another event happened")

Auf diese Weise schreibst du gleichzeitig auf den Bildschirm und in die Datei. Du kannst sogar in mehr als zwei Writer schreiben!

4.4 Log-Ebenen verwenden

Problem

Du möchtest Log-Ereignisse nach Log-Ebenen einordnen.

Lösung

Verwende die Funktion New , um einen Logger zu erstellen, einen für jede Log-Ebene, und verwende dieseLogger dannentsprechend.

Diskussion

Logdaten sind in der Regel ziemlich groß. Mit Hilfe von Log-Ebenen kannst du sie überschaubarer machen und die Priorität der Ereignisse bestimmen. Die Log-Levels geben den Schweregrad eines Ereignisses an und damit seine Bedeutung. Es ist ein einfacher Mechanismus: Du schaust dir zuerst die Log-Levels mit dem höchsten Schweregrad an, filterst die Logs mit dem niedrigsten Schweregrad heraus und verringerst so die Ermüdung durch Alarme. Beispiele für Protokollstufen von hoch bis niedrig sind:

  • Tödlich

  • Fehler

  • Warnen

  • Info

  • Debuggen

Um Loglevel für deine Logs einzurichten, kannst du den Level zu jeder Zeile des Logs hinzufügen. Am einfachsten ist es, die Funktion SetPrefix zu verwenden:

log.SetPrefix("INFO ")
log.Println("Some event happened")

Wenn du die Funktion SetPrefix mit dem Loglevel als Präfix aufrufst, setzt du den Loglevel an den Anfang der Zeile:

INFO 2022/01/26 00:48:15 Some event happened

Das Problem ist natürlich, dass du jedes Mal, wenn du eine Log-Zeile mit einer anderen Log-Ebene als die vorherige Zeile hinzufügen willst, SetPrefix erneut aufrufen musst. Das ist keine praktikable Lösung.

Eine andere Methode besteht darin, neue Logger im Voraus zu erstellen, wobei jeder Logger eine einzelne Log-Ebene darstellt:

var (
	info  *log.Logger
	debug *log.Logger
)

func init() {
	info = log.New(os.Stderr, "INFO\t", log.LstdFlags)
	debug = log.New(os.Stderr, "DEBUG\t", log.LstdFlags)
}

Dazu verwendest du die Funktion New, die einen Logger zurückgibt, aber du kannst auch das Präfix und die Felder festlegen, die dem Log hinzugefügt werden sollen.

Um Ereignisse mit verschiedenen Protokollierungsstufen zu protokollieren, musst du nur die entsprechenden Logger verwenden:

info.Println("Some informational event happened")
debug.Println("Some debugging event happened")

Das wird auf dem Bildschirm angezeigt:

INFO	2022/01/26 00:53:03 Some informational event happened
DEBUG	2022/01/26 00:53:03 Some debugging event happened

Du kannst auch die Protokollierung für bestimmte Log-Ebenen ausschalten, um die Größe der Logdatei zu verringern. Wenn du zum Beispiel ein Programm entwickelst, kannst du Debug-Ereignisse protokollieren, aber sobald du es in der Produktion einsetzt, möchtest du das nicht mehr tun. Eine gängige Praxis ist es, Umgebungsvariablen zu verwenden, um anzugeben, ob du in der Entwicklung oder in der Produktion arbeitest.

Umgebungsvariablen sind benannte Werte, die Teil der Umgebung sind, in der Programme laufen. Umgebungsvariablen werden in der Befehlszeile gesetzt, und Programme können während der Laufzeit auf diese Variablen zugreifen.

Für Unix-basierte Systeme wie Linux und macOS kannst du zum Beispiel eine Umgebungsvariable ENV wie folgt setzen:

$ export ENV=development

Um die Umgebungsvariable in der Kommandozeile abzurufen, kannst du echo verwenden und ein $ vor den Variablennamen setzen:

$ echo $ENV

Auch in Windows-Systemen kannst du die Umgebungsvariable auf diese Weise setzen:

$ set ENV=development

Um die Umgebungsvariable in Windows zu erhalten, kannst du echo verwenden und ein % vor und nach dem Variablennamen hinzufügen:

$ echo %ENV%

Das Abrufen der Umgebungsvariablen in Go ist einfach. Du kannst die Funktion os.Getenv verwenden, der du den Namen der Umgebungsvariablen übergibst, und du erhältst den Wert der Umgebungsvariablen. Wie im vorherigen Beispiel setzen wir dieUmgebungsvariable ENV auf production:

$ export ENV=production

Wenn du diesen Code ausführst, wirst du sehen, dass das Debug-Ereignis nicht gedruckt wird:

info.Println("Some informational event happened")
if os.Getenv("ENV") != "production" {
	debug.Println("Some debugging event happened")
}

Wenn du in die Entwicklungsumgebung wechselst, wird das Debug-Ereignis erneut gedruckt.

Auf hast du zu Beginn dieses Rezepts gelernt, dass einer der Gründe für die Verwendung von Log-Ebenen darin besteht, bestimmte Log-Ebenen zu priorisieren und herauszufiltern. Auf einem Unix-basierten System kannst du dies ganz einfach mit dem Befehl grep tun.

Angenommen, du hast eine Datei namens logfile.log mit den folgenden Einträgen:

INFO	2023/01/06 00:21:32 Some informational event happened
DEBUG	2023/01/06 00:21:32 Some debugging event happened
INFO	2023/01/06 00:21:35 Another informational event happened
WARN	2023/01/06 00:23:35 A warning event happened
WARN	2023/01/06 00:33:11 Another warning event happened
ERROR	2023/01/06 00:33:11 An error event happened

Du willst dir zuerst alle Fehlerereignisse ansehen, damit du mit grep nur Fehlerereignisse herausfiltern kannst:

$ grep "^ERROR" logfile.log

Auf siehst du nur das Fehlerereignis. Das ^ vor grep bedeutet, dass du nur die Zeilen sehen willst, die mit ERROR beginnen:

ERROR	2023/01/06 00:33:11 An error event happened

Was, wenn du alle Log-Ereignisse außer den Debug-Ereignissen sehen willst? Du kannst die Debug-Ereignisse einfach mit dem v Flag in grep ausschließen:

$ grep -v "^DEBUG" logfile.log

Dies führt dazu, dass alle Ereignisse außer den Debug-Ereignissen angezeigt werden:

INFO	2023/01/06 00:21:32 Some informational event happened
INFO	2023/01/06 00:21:35 Another informational event happened
WARN	2023/01/06 00:23:35 A warning event happened
WARN	2023/01/06 00:33:11 Another warning event happened
ERROR	2023/01/06 00:33:11 An error event happened

Die Verwendung von grep ist nur der Anfang. grep ist ein mächtiges Werkzeug, aber es gibt noch viele andere Tools zur Loganalyse, die du verwenden kannst.

4.5 Protokollierung mit dem System Log Service

Problem

Du möchtest dich unter in das Systemprotokoll einloggen, anstatt in deine Logdateien.

Lösung

Verwende das log/syslog Paket, um ins Syslog zu schreiben.

Diskussion

Syslog ist ein standardisiertes netzwerkbasiertes Logging-Protokoll. Es ist seit langem der De-facto-Standard für die Protokollierung von Systemereignissen und wurde in den 1980er Jahren von Eric Allman im Rahmen des Sendmail-Projekts entwickelt. Das Protokoll wurde in RFC 3164 von der Internet Engineering Task Force (IETF) dokumentiert. Später standardisierte die IETF es in RFC 5424.

Eine Syslog-Nachricht (wie in RFC 3164) besteht aus drei Teilen:

Priorität

Beinhaltet die Anlage und den Schweregrad

Kopfzeile

Enthält den Zeitstempel und den Hostnamen oder die IP-Adresse des Rechners

Nachricht

Beinhaltet den Tag und den Inhalt

Die Einrichtung beschreibt den Typ des Systems, das die Logmeldung sendet. Sie ermöglicht es, dass Log-Meldungen von verschiedenen Einrichtungen unterschiedlich behandelt werden. In den RFCs sind 24 Einrichtungen definiert; hier sind einige davon:

  • 0 (Kernel)

  • 1 (Benutzerebene)

  • 2 (Post)

  • 3 (System-Daemons)

  • 4 (Sicherheits-/Autorisierungsmeldungen)

Der Schweregrad ist ähnlich wie der Log-Level. Syslog definiert acht verschiedene Stufen, wobei 0 die höchste und 7 die niedrigste ist:

  • 0 (Notfall)

  • 1 (Warnung)

  • 2 (Kritisch)

  • 3 (Fehler)

  • 4 (Warnung)

  • 5 (Hinweis)

  • 6 (informativ)

  • 7 (Debug)

Der Zeitstempel und der Hostname oder die IP-Adresse sind selbsterklärend. Der Tag ist der Name des Programms, das die Meldung erzeugt hat, während der Inhalt die Details der Logmeldung enthält.

Syslog ist nicht einheitlich in verschiedenen Betriebssystemen implementiert. Eine beliebte Implementierung von Syslog ist rsyslog, die Standard-Syslog-Implementierung in vielen Linux-Varianten wie Debian, Ubuntu, openSUSE und anderen.

Go bietet ein log/syslog Paket als Teil der Standardbibliothek, um eine Schnittstelle zu Syslog zu schaffen. Allerdings funktioniert es nicht auf allen Systemen. Zum Beispiel funktioniert es nicht mit Windows, weil es nicht in Windows implementiert ist.

Das Beispiel in diesem Rezept basiert auf der Ausführung gegen rsyslog auf Ubuntu 20.04 und sollte auf Systemen mit rsyslog funktionieren. Ich habe es jedoch nicht auf allen Systemen und Implementierungen ausprobiert.

Bevor wir mit dem Go-Code beginnen, musst du rsyslog so einrichten, dass die Priorität, die Kopfzeile und die Nachrichtenteile angezeigt werden. In rsyslog wird dies mithilfe eines Templates in der rsyslog-Konfigurationsdatei erledigt.

Beginne mit der Bearbeitung der Konfigurationsdatei /etc/rsyslog.conf:

$ sudo vi /etc/rsyslog.conf

Füge die Templating-Konfiguration nach dieser Zeile $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat in die Konfigurationsdatei ein:

$template gosyslogs,"%syslogseverity-text% %syslogfacility-text% %hostname%
%timegenerated% %syslogtag% %msg%\n"
$ActionFileDefaultTemplate gosyslogs

In dieser Konfiguration nennst du die Vorlage gosyslogs. Du stellst sie so ein, dass zuerst der Schweregrad angezeigt wird, gefolgt von der Einrichtung, dann der Hostname und der Zeitstempel und schließlich der Tag und die Nachricht.

Sobald du diese Datei gespeichert hast, starte rsyslog neu:

sudo service rsyslog restart

Jetzt, wo du rsyslog eingerichtet hast, kannst du dir den Code ansehen. Das Senden von Logmeldungen an syslog mit dem Paket syslog ist relativ einfach:

var logger *log.Logger

func init() {
	var err error
	logger, err = syslog.NewLogger(syslog.LOG_USER|syslog.LOG_NOTICE, 0)
	if err != nil {
		log.Fatal("cannot write to syslog: ", err)
	}
}

func main() {
	logger.Print("hello syslog!")
}

Mit der Funktion NewLogger erstellst du einen Logger und übergibst die Syslog-Prioritätsflags, die du setzen willst. Das Paket syslog bietet Flags für den Facility und den Severity Level. Du kannst sie miteinander kombinieren, um den Facility Code und den Schweregrad zu senden. Im Fall des vorangegangenen Codes sendest du syslog.LOG_USER, um den Facility Code des Benutzers anzugeben, und syslog.LOG_NOTICE, um den Schweregrad der Meldung anzugeben.

Führe den Code zuerst in der Datei main.go aus:

$ go run main.go

Überprüfe nun die Syslogs. Führe dies in der Kommandozeile aus:

$ sudo tail /var/log/syslog

Du solltest eine Reihe von Logmeldungen sehen, aber irgendwo am Ende sollte etwas wie das hier stehen:

notice user myhostname Jan 26 15:30:08 /tmp/go-build2223050573/b001/exe/
main[163995]:
  hello syslog!

Das erste Feld ist notice, der Schweregrad , gefolgt von user, dem Code der Einrichtung. Das nächste Feld ist myhostname, das ist der Hostname, gefolgt vom Zeitstempel.

Das nächste Feld ist das Tag, das Feld /tmp/go-build2223050573/b001/exe/main[163995] in der Logmeldung. Warum wird angezeigt, dass es sich im Verzeichnis /tmp befindet? Das liegt daran, dass du go run verwendest. Wenn du den Code kompilierst und die Binärdatei ausführst, sieht es anders aus. Das letzte Feld in der Logmeldung sind die Details des Logs, die du mit logger ausdruckst.

Get Go Kochbuch now with the O’Reilly learning platform.

O’Reilly members experience books, live events, courses curated by job role, and more from O’Reilly and nearly 200 top publishers.

Start your free trial