std.log — Logging

→ Zurück zur Unit-Übersicht

Logging mit fünf Leveln (DEBUG, INFO, WARN, ERROR, FATAL), umschaltbarem Ausgabeziel (stdout oder Datei), optionalem Zeitstempel, ANSI-Farben und einem Callback zum Weiterleiten an externe Systeme. Zusätzlich eine einfache JSON-Zeilenausgabe (log_info_kv) für maschinelle Auswertung.

Einsatzbereiche: Serverdienste, Hintergrundjobs, CLI-Werkzeuge, Produktions-Diagnose.

Autor: Andreas Röne
Copyright: 2024–2025 Andreas Röne
Quelle: std/log.lyx

<WRAP alert> Zwei Ausgabewege — nur einer respektiert die Konfiguration.
log_emit ist der konfigurierbare Weg: Level-Filter, Datei-Sink, Zeitstempel. Die Kurzfunktionen log_info/log_debug/log_warn/log_error/log_fatal schreiben dagegen immer und immer nach stdout — sie ignorieren set_log_level und log_set_file. Details unter Fallstricke. Für alles außer Wegwerf-Skripten: log_emit verwenden. </WRAP>

import std.log;

Die Zahlenwerte sind geordnet: log_emit verwirft alles unterhalb des gesetzten Levels. set_log_level(LOG_LEVEL_WARN) lässt also WARN, ERROR und FATAL durch.

Der Handler wird von den Kurzfunktionen gerufen, nicht von log_emit.

import std.log;

fn main(): int64 {
    set_log_level(LOG_LEVEL_INFO);

    log_emit(LOG_LEVEL_DEBUG, "Verbindungspool initialisiert");   // gefiltert
    log_emit(LOG_LEVEL_INFO,  "Server lauscht auf Port 8080");
    log_emit(LOG_LEVEL_WARN,  "Zertifikat laeuft in 14 Tagen ab");
    log_emit(LOG_LEVEL_ERROR, "Datenbank nicht erreichbar");

    PrintLn("aktives Level: ", log_level_to_string(get_log_level()));
    return 0;
}

Ausgabe:

[INFO] Server lauscht auf Port 8080
[WARN] Zertifikat laeuft in 14 Tagen ab
[ERROR] Datenbank nicht erreichbar
aktives Level: INFO

import std.log;

fn main(): int64 {
    set_log_level(LOG_LEVEL_INFO);

    if (log_set_file("dienst.log")) {
        log_set_timestamp(true);
        log_emit(LOG_LEVEL_INFO, "Dienst gestartet");
        log_infof("aktive Verbindungen: ", 17);
        log_info_kv("request", "pfad", "/api/v1/status");
        log_emit(LOG_LEVEL_ERROR, "Upstream-Timeout");
        log_set_timestamp(false);
        log_set_file("");                       // zurueck auf stdout
        PrintLn("geschrieben nach dienst.log");
    } else {
        PrintLn("Log-Datei nicht schreibbar");
    }
    return 0;
}

Inhalt von dienst.log:

[1786640183] [INFO] Dienst gestartet
[1786640183] [INFO] aktive Verbindungen: 17
{"level":"info","event":"request","pfad":"/api/v1/status"}
[1786640183] [ERROR] Upstream-Timeout

Zwei Beobachtungen an dieser echten Ausgabe: Der Zeitstempel sind rohe Unix-Sekunden, kein formatiertes Datum — für lesbare Zeiten die Zeile selbst mit std.datetime bauen. Und die log_info_kv-Zeile trägt keinen Zeitstempel, weil sie am Präfix-Aufbau von log_emit vorbei direkt schreibt.

import std.log;

var _fehler: int64 := 0;

fn zaehleUndSpiegle(msg: pchar): void {
    _fehler := _fehler + 1;
    PrintLn("  [audit] ", msg);
}

fn main(): int64 {
    PrintLn("Handler registriert? ", IntToStr(has_log_callback() as int64));
    register_log_callback(zaehleUndSpiegle as int64);
    PrintLn("Handler registriert? ", IntToStr(has_log_callback() as int64));

    log_warn("Plattenplatz unter 10 %");
    log_error("Schreibvorgang fehlgeschlagen");

    unregister_log_callback();
    log_warn("nach unregister — kein audit mehr");

    PrintLn("vom Handler gesehen: ", IntToStr(_fehler));
    return 0;
}

Ausgabe:

Handler registriert? 0
Handler registriert? 1
[WARN] Plattenplatz unter 10 %
  [audit] Plattenplatz unter 10 %
[ERROR] Schreibvorgang fehlgeschlagen
  [audit] Schreibvorgang fehlgeschlagen
[WARN] nach unregister — kein audit mehr
vom Handler gesehen: 2

Der Handler wird als Funktionszeiger übergeben (as int64) und muss die Signatur fn(pchar): void haben. Er bekommt die nackte Nachricht ohne Level-Präfix — das Level ist im Handler also nicht mehr erkennbar.

Alle Punkte hier sind mit lyxc 1.0.17K nachgestellt; jeder hat ein offenes Issue.

import std.log;

fn main(): int64 {
    set_log_level(LOG_LEVEL_ERROR);

    log_info("log_info: erscheint trotz Level ERROR");
    log_debug("log_debug: erscheint ebenfalls");

    log_emit(LOG_LEVEL_INFO,  "log_emit INFO: korrekt unterdrueckt");
    log_emit(LOG_LEVEL_ERROR, "log_emit ERROR: erscheint");
    return 0;
}

[INFO] log_info: erscheint trotz Level ERROR
[DEBUG] log_debug: erscheint ebenfalls
[ERROR] log_emit ERROR: erscheint

Ursache: log_debug & Co. rufen direkt PrintLn statt log_emit. Damit greift weder der Filter noch der Datei-Sink noch der Zeitstempel. Ein Dienst, der log_set_file aufruft und dann log_info benutzt, schreibt seine Logs weiter nach stdout — die Datei bleibt leer.

log_set_color(true) erzeugt kein einziges ANSI-Byte. Grund ist der Escape in _log_color_code: die Farbcodes sind als „\033[36m“ geschrieben, aber Lyx kennt keine oktalen Escapes. \0 wird als NUL gelesen, der String hat damit Länge 0:

fn main(): int64 {
    PrintLn("StrLen(\\033[36m) = ", IntToStr(StrLen("\033[36m")));
    PrintLn("StrLen(\\x1b[36m) = ", IntToStr(StrLen("\x1b[36m")));
    return 0;
}

StrLen(\033[36m) = 0
StrLen(\x1b[36m) = 5

Im eigenen Code deshalb \x1b verwenden, nie \033.

Anführungszeichen im Wert zerstören das JSON:

log_info_kv("cfg", "pfad", "C:\"tmp\"x");

{"level":"info","event":"cfg","pfad":"C:"tmp"x"}

Das ist kein gültiges JSON mehr. Vor der Übergabe selbst maskieren (Backslash, Anführungszeichen, Steuerzeichen) oder std.json verwenden. log_info_kv ignoriert außerdem den Level-Filter und schreibt auch bei Level FATAL.

log_section_enter(„migration“) und log_section_exit(„migration“) erzeugen dieselbe Zeile [INFO] migration — im Log ist Anfang und Ende nicht zu unterscheiden. log_app_start(name) ignoriert den übergebenen Namen und druckt ein festes Banner. Wer Abschnitte auswerten will, formuliert die Zeile selbst:

log_emit(LOG_LEVEL_INFO, "-> migration");
log_emit(LOG_LEVEL_INFO, "<- migration");

log_debugf/log_infof/log_warnf/log_errorf allokieren pro Aufruf einen 22-Byte-Zahlenpuffer und einen Kombinationspuffer, geben aber beides nie frei. In einer Schleife mit vielen Log-Zeilen wächst der Heap monoton. Bis zum Fix in Dauerschleifen log_emit mit selbst gebauter Nachricht verwenden:

log_emit(LOG_LEVEL_INFO, StrConcat("aktive Verbindungen: ", IntToStr(n)));

• Ausgabe grundsätzlich über log_emit — nur dieser Weg respektiert Level und Ziel.
• Level einmal beim Programmstart setzen, danach nicht mehr ändern.
• Datei-Sink früh setzen, damit keine Zeilen vorher nach stdout entkommen.
• Farben derzeit nicht einplanen (Fallstrick 2).
• Für maschinell auswertbare Logs eigene JSON-Zeilen mit std.json bauen statt log_info_kv.

• std.datetime — lesbare Zeitstempel statt Unix-Sekunden
• std.json — korrekt maskierte strukturierte Ausgabe
• std.io — direkte Dateiausgabe
• std.os — open/write/close, unix_time