[Gelöst] Welche log-/verbose-level bzw. Meldungen gehören nach stdout oder stderr?

[buhtz]

Gibt es im unixoiden Universum, oder auch darüber hinaus klare Konventionen oder gar deutliche Regeln, welche Art von "Nachrichten" auf stdout oder stderr ausgegeben werden sollen?

In Python unterscheidet man

1. DEBUG
2. INFO
3. WARNING
4. ERROR
5. CRITICAL

Laut Doku und meinen eigenen Experimenten scheint hier immer alles auf stderr zu landen. Das überrascht mich.
Ich hätte debug und info (und evtl. auch warning) eher auf stdout erwartet.

[Meillo]

Bei Filter-Programmen muessen alle Meldungen auf Stderr rauskommen, da sie sonst ja in mitten des normalen Programmoutputs in der Pipe bzw. Ausgabedatei verschwinden. Dann wuerde z.B. ein `wc' am Ende falsch zaehlen.

Stdout ist fuer die normale Programmausgabe gedacht. Stderr ist fuer Meldungen, die beim menschlichen Bediener ankommen sollen.

[buhtz]

Bei Filter-Programmen muessen alle Meldungen auf Stderr rauskommen, da sie sonst ja in mitten des normalen Programmoutputs in der Pipe bzw. Ausgabedatei verschwinden. Dann wuerde z.B. ein `wc' am Ende falsch zaehlen.

Stdout ist fuer die normale Programmausgabe gedacht. Stderr ist fuer Meldungen, die beim menschlichen Bediener ankommen sollen.

Ich wollte zuerst einen neuen Thread aufmachen, aber dachte mir, dass passt hier doch ganz gut.

Als Programmierer fällt es mir nun schwer zu entscheiden, wohin (stderr per logging oder stdout per print()) die "Meldungen" nun gehen sollen. Ich bin ziemlich verwirrt, ehrlich gesagt, je mehr ich darüber nachdenken muss. Hier wurden die Begriffe "normale Programmausgabe" und "Meldungen, (für) menschliche Bediener" unterschieden. Ist das nicht das Selbe?

logging.info() geht ja auch "nur" auf stderr. Ist das also eine Art schwächerer Debug Output?

Eine GUI Anwendung "kommuniziert" mit dem Anwender ja über Strings und Symbole, die sich u.a. auf Buttons oder Statuszeilen befinden. In der Kommandozeile habe ich bisher für solche Dinge das INFO Level des logging Moduls in Python verwendet. Da es aber auf stderr rauskommt, scheint das doch nicht der Weg zu sein und ich müsste eigentlich ein klassisches print() einsetzen.

So ganz klar und eindeutig, kann ich "meine Strings" nicht zwischen "INFO auf stderr" oder "print()" einteilen.

Puh! Was habt ihr denn da so für Regeln und Gepflogenheiten?

[Meillo]

Wenn es sich um eine GUI-Anwendung handelt, dann sind alle Konsolenausgaben nur fuer's Logging und Debuggen. (Bei CLI-Anwendungen ist das voellig anders.) Alles was ein GUI-Programm nach stderr und stdout schreibt sollte vernachlaessigbar sein, da man das nicht zu sehen bekommt, wenn man das Programm aus einem Menu heraus startet. Zudem sollten standardmaessig nur schwerwiegende Dinge ausgegeben werden, weil es sonst die Konsole flutet, wenn man das Programm aus der Shell startet. Eine Debug- oder Verbose-Option kann mehr Ausgaben aktivieren.


Ich denke, es waere einfacher, anhand von konkreten Beispielen zu ueberlegen. Kannst du vielleicht mal die Ausgaben deines Programms posten und wir sagen dir, wie wir diese klassifizieren wuerden?

[buhtz]

Ich denke, es waere einfacher, anhand von konkreten Beispielen zu ueberlegen. Kannst du vielleicht mal die Ausgaben deines Programms posten und wir sagen dir, wie wir diese klassifizieren wuerden?

OK, dann habe ich jetzt mal ein konkretes Beispiel. Hyperorg ist eine CLI Anwendung, die Org-Dateien (ein markup-Format aus dem Emacs Umfeld) aus einem Verzeichnis liest, in HTML-Dateien konvertiert und in ein neues Verzeichnis schreibt.

Hier mal "version" und "usage" output

Code: Alles auswählen

$ hyperorg --version
hyperorg 0.0.0a1

$ hyperorg
usage: hyperorg [-h] [-v] [-d] [--version] inputdir outputdir
hyperorg: error: the following arguments are required: inputdir, outputdir

Hier der Output, wenn es das tut, was es tun soll: die oben beschriebene Konvertierung. Es gibt in dem Fall keinen Output. Früher hätte ich hier standardmäßig noch über das in- und output Verzeichnis berichtet. Das würde vermutlich ggf. auf stdout (per print()) gehen?

Code: Alles auswählen

$ hyperorg my.org-roam my.html-roam

Hier das selbe im "verbose" Modus. Wie ich gerade wahrnehme, ist der inhaltlich in der Formulierung auch noch verbesserungsbedürftig.

Code: Alles auswählen

$ hyperorg my.org-roam my.html-roam -v
INFO  : Using my.org-roam as input directory.
INFO  : Done. 414 nodes loaded.
INFO  : Using my.html-roam as output directory.
INFO  : Delete all files and folders in the output directory.
INFO  : Done. See you next time.

Und hier der Debug output (was im Grunde doppeltes verbose bedeutet), allerdings in der Mitte gekürzt, weil es sonst zu viel ist.

Code: Alles auswählen

$ hyperorg my.org-roam my.html-roam -d
[2023-01-03 12:14:41,331] [INFO] reader.py:__init__() => Using my.org-roam as input directory.
[2023-01-03 12:14:41,577] [INFO] reader.py:read_org_files() => Done. 414 nodes loaded.
[2023-01-03 12:14:41,578] [INFO] exporter.py:__init__() => Using my.html-roam as output directory.
[2023-01-03 12:14:41,578] [DEBUG] exporter.py:_set_css_content() => Re-use CSS-file "my.html-roam/style.css".
[2023-01-03 12:14:41,578] [INFO] exporter.py:_clean_output_dir() => Delete all files and folders in the output directory.
[2023-01-03 12:14:41,593] [DEBUG] exporter.py:export_to_html() => Node: Identification of Seniors at Risk (ISAR) Screening
[2023-01-03 12:14:41,597] [DEBUG] exporter.py:export_to_html() => Node: Raumstrukturierung bei Sekundärdaten-Analysen
[2023-01-03 12:14:41,597] [DEBUG] exporter.py:export_to_html() => Node: Venkatesh; Morris; Davis; Davis (2003) User Acceptance of Information Technology
[2023-01-03 12:14:41,598] [DEBUG] exporter.py:export_to_html() => Node: EUROSTAT Nutzung
[2023-01-03 12:14:41,598] [DEBUG] exporter.py:export_to_html() => Node: Python import structure for package testing from itself and its prject
[...SNIPPED...]
[2023-01-03 12:14:41,822] [DEBUG] exporter.py:export_to_html() => Node: Qualitätsindikatoren
[2023-01-03 12:14:41,822] [DEBUG] exporter.py:export_to_html() => Node: ProcessPoolExecutor
[2023-01-03 12:14:41,824] [INFO] __main__.py:main() => Done. See you next time.

[Meillo]

Das Programm gibt ja keine Arbeitsergebnisse ins Terminal aus. Alle Ausgaben sind nur fuer den User bestimmt.

Ich wuerde alle vom User angeforderten Ausgaben nach Stdout schreiben, also die Versionsmeldung und die Verbose- und Debug-Ausgaben. Wenn irgendetwas passiert, das so nicht erwartet ist, also z.B. eine Fehlermeldung weil eine Datei nicht geschrieben werden kann, oder wenn die Kommandozeilenoptionen falsch sind (also auch den Fall wenn es ohne Argumente aufgerufen wird), die wuerde ich nach Stderr schreiben (und dann auch mit einem Exitcode != 0 beenden).

Diese Regel -- Was der User anfordert nach Stdout und was unerwartet ist nach Stderr. -- passt meistens.


Ich ueberlege mir halt, wie ich das nutzen wuerde. Die Verbose- oder Debugausgabe wuerde ich vielleicht in eine Datei umleiten, damit ich spaeter nachschauen kann. Eine Meldung, dass eine Datei nicht geschrieben oder geoeffnet werden kann, wuerde ich aber trotz Umleitung im Terminal sehen wollen. Ebenso sollte dann der Exit-Code passen. Ich wuerde das beispielsweise so verwenden:

Code: Alles auswählen

hyperorg -d my.org-roam my.html-roam >hyperorg.debug && echo success

Ich hoffe, das hilft dir weiter.

[buhtz]

Ich wuerde alle vom User angeforderten Ausgaben nach Stdout schreiben, also die Versionsmeldung und die Verbose- und Debug-Ausgaben.

So verstehe ich das eigentlich auch.

Aber das logging Modul von Python schreibt wirklich alles nach stderr, auch INFO und DEBUG. Als kleiner Nixblicker denke ich mir immer, dass sich das die Python-Hasen schon gut überlegt haben.

Nach deiner Regel wäre es ja einfach, alle logging-Meldung von WARNING und "schlimmer" (also ERROR und CRITICAL) nach stderr und INFO und DEBUG nach stdout. Ist aber nicht so voreingstellt bei Python. Umbiegen kann man das dort natürlich, aber vermutlich ist es so nicht gedacht.

Ich werde da noch mal auf der Python Liste nachfragen.

EDIT: Beim usage von argparse ist es differenziert. Ruf man hyperorg ohne Argumente auf, ist das eigentlich ein Fehler, woraufhin argparse eine verkürzte Version des usage ausgibt; tatsächlich auf stderr. Fordert man explizit die usage infos an per -h werden diese auf stdout ausgeben. Aha.

[Meillo]

Aber das logging Modul von Python schreibt wirklich alles nach stderr, auch INFO und DEBUG. Als kleiner Nixblicker denke ich mir immer, dass sich das die Python-Hasen schon gut überlegt haben.

Nach deiner Regel wäre es ja einfach, alle logging-Meldung von WARNING und "schlimmer" (also ERROR und CRITICAL) nach stderr und INFO und DEBUG nach stdout. Ist aber nicht so voreingstellt bei Python. Umbiegen kann man das dort natürlich, aber vermutlich ist es so nicht gedacht.

Das passt fuer mich eigentlich schon wie es ist. Logging ist das was einheitlich ins Logging-Backend geht, sei es direkt in eine Textdatei oder zu Syslog oder ins Terminal oder sonstwo hin. Dort waere es falsch, Teile davon woanders hin zu schicken.

Logging und Fehlerausgaben sind fuer mich aber separate Dinge. Ein Serverprozess (Daemon) hat nur Logging, aber ein Kommandozeilentool wuerde bei Fehlern direkt Fehlermeldungen nach Stderr schreiben, separat und ggf. zusaetzlich zum Logging, weil beides verschiedenen Zwecken dient.

EDIT: Beim usage von argparse ist es differenziert. Ruf man hyperorg ohne Argumente auf, ist das eigentlich ein Fehler, woraufhin argparse eine verkürzte Version des usage ausgibt; tatsächlich auf stderr. Fordert man explizit die usage infos an per -h werden diese auf stdout ausgeben. Aha.

So sollte es auch sein. Im einen Fall hat man den Befehl ja richtig aufgerufen, um die Usage-Meldung ausgeben zu lassen. Im anderen Fall hat man den Befehl falsch aufgerufen, naemlich ohne Argumente, obwohl er welche benoetigt.

[buhtz]

Hier die Diskussion auf der Python-Liste: https://mail.python.org/pipermail/pytho ... 08709.html

[Meillo]

Hier die Diskussion auf der Python-Liste: https://mail.python.org/pipermail/pytho ... 08709.html

Danke fuer den Hinweis. Die Meinungen dort decken sich mit meinen Aussagen.

Ich habe den Eindruck, dass du das Konzept von Logging nicht so verstanden hast, wie es die meisten verstehen. Du solltest dich von den Detailfragen (Was so hin geht.) loesen und nochmal an der Idee von Logging an sich ansetzen, wozu man es nutzt, was es von Programmausgaben unterscheidet. Vielleicht ist Python hier auch ein schlechtes Beispiel, denn normalerweise schreibt ein Logger nicht nach Stderr. Das scheint mir eine Python-Besonderheit zu sein. Normalerweise uebergibt der Logger seine Eintraege an Syslog und das kuemmert sich dann um alles weitere, oder falls man kein Syslog verwendet, dann wuerde ein Logger normalerweise direkt in eine Datei schreiben. In dem Fall ist Logging als Konzept viel einfacher zu verstehen, als unter dem Sonderfall, dass das Logging ins Terminal ausgegeben wird.

[buhtz]

...

Ich habe den Eindruck, dass du das Konzept von Logging nicht so verstanden hast, wie es die meisten verstehen.
...
nochmal an der Idee von Logging an sich ansetzen, wozu man es nutzt, was es von Programmausgaben unterscheidet.

Da dürftest du recht haben.

Nun frage ich mich, wie ich in Python technisch zwischen Standard-Meldungen für den Nutzer (auf stdout) und Verbose-Meldungen für den Nutzer (auch stdout, aber nur wenn --verbose gesetzt ist) unterscheiden soll. Ich kann ja nicht vor fast jede print() Zeile ein if verbose: setzen. Ich bin es in Python gewöhnt, dass es für solche Basic-Dinge eine Lösung in der Standard-Bib gibt. Ich finde einige "Workarounds": https://stackoverflow.com/q/5980042/4865723 Und auch hier taucht immer wieder mal das logging Modul auf. Scheinbar bin ich nicht der einzige, der das initial missverstanden hat. Die scheinbare konzeptuelle Verbindung zwischen verbosity level und log level hatte mich fehlgeleitet.

[Meillo]

Du solltest mit der Annahme beginnen, dass das Logging *nicht* auf das Terminal ausgegeben wird. Damit kannst du es nicht fuer Ausgaben ins Terminal nutzen.

Ich schreibe mir meist eine kleine Hilfsfunktion, der ich einen Loglevel und einen Text uebergeben kann und die gibt ihn dann mit fprintf() aus, falls Verbose aktiviert ist bzw. der eingestellte Loglevel hoch genug ist. Das sieht dann etwa so aus:

Code: Alles auswählen

debugprint(3, "foo bar");

Alternativ schiebst du alle Debugmeldungen ins Logging und schreibst dieses entweder in eine Datei oder laesst es so wie bisher auf Stderr ausgeben.

Alle Fehlermeldungen, die auch angezeigt werden sollen, wenn kein Verbose oder Debug gesetzt sind, gibst du direkt mit print() nach Stderr aus -- parallel und zusaetzlich zum Logging.

Als C-Programmierer mache ich so Zeug von Hand; von Python habe ich keine Ahnung.

[buhtz]

Mhm... Eigentlich ist es in den Python-Docs ganz gut beschrieben, in welchen Situationen man welche Mechanismen (logging, print, warning) nutzen sollte/könnte.

https://docs.python.org/howto/logging.h ... se-logging

[Meillo]

Mhm... Eigentlich ist es in den Python-Docs ganz gut beschrieben, in welchen Situationen man welche Mechanismen (logging, print, warning) nutzen sollte/könnte.

https://docs.python.org/howto/logging.h ... se-logging

Na dann!

Wobei das alles nur Sandkastenbeispiele sind.

Bei einem Programmfehler muesstest du dann beides machen:

Code: Alles auswählen

print("Error: foo fails", file=sys.stderr)
logging.error("foo fails")

Die erste Zeile geht ins Terminal und zwar immer. Die zweite Zeile geht dorthin wohin das Logging nun eben geht und abhaengig vom jeweils eingestellten Debug-/Verbosity-Level.

[JTH]

Will doch auch noch was zu dem Thema einwerfen

Das logging-Modul ist denk ich mehr als Grundlage fürs Logging zu verstehen. Das soll keine fertige Lösung für alle Ansprüche bereithalten. Man kann damit aber auch, mit ein bisschen Setup, sehr vieles leicht lösen. Zumindest all die Fälle, die ihr beiden hier angesprochen habt. Die Python-Doku hat da noch eine Latte an Beispielen: Logging HOWTO und Logging Cookbook.

Und hier noch ein paar Beispiele von mir. Beim zweiten Überfliegen des Threads sind die vielleicht etwas am Thema vorbei oder zu trivial, aber nun hab ich schon rumgebastelt. Vielleicht hilfts dir ja noch weiter, buhtz:

Umbiegen kann man das dort natürlich, aber vermutlich ist es so nicht gedacht.

Von stderr nach stdout verschieben lassen sich die Meldungen ganz leicht:

Code: Alles auswählen

import logging
import sys

# Just log to stdout instead of stderr:
logging.basicConfig(stream=sys.stdout)

Bei einem Programmfehler muesstest du dann beides machen:

Mit einem geeigneten logging-Setup muss man das nicht überall im Code von Hand duplizieren. Man kann mehrere Handler benutzen:

Code: Alles auswählen

import logging
import logging.handlers
import sys

# Log everything to syslog (or a file, …) and errors additionally to stderr:
logger = logging.getLogger()

# No fancy formatting for the syslog messages. syslog has better ways to
# e.g. signal the level:
syslog_handler = logging.handlers.SysLogHandler(address="/dev/log")
syslog_handler.setLevel(logging.NOTSET)

stderr_handler = logging.StreamHandler(sys.stderr)
stderr_handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
stderr_handler.setLevel(logging.ERROR)

# Not using basicConfig() here, we want to setup different formatters for
# each handler.
logger.setLevel(logging.NOTSET)
logger.addHandler(syslog_handler)
logger.addHandler(stderr_handler)
# Could add even more log targets here: file(s) (FileHandler), mail
# (SMTPHandler), etc.; each with their own custom level, formatting, and
# more.

Ich kann ja nicht vor fast jede print() Zeile ein if verbose: setzen.

Das ist auch nicht nötig. Dafür gibt es ja Loglevel, mit denen man auch ein --verbose oder --debug umsetzen kann:

Code: Alles auswählen

import argparse
import logging
import sys

# Use levels to handle --debug, --verbose, and --quiet options:
argparser = argparse.ArgumentParser()
argparser.add_argument(
    "--debug", action="store_const", const=logging.DEBUG, dest="log_level"
)
argparser.add_argument(
    "--quiet", action="store_const", const=logging.ERROR, dest="log_level"
)
argparser.add_argument(
    "--verbose", action="store_const", const=logging.INFO, dest="log_level"
)
argparser.set_defaults(log_level=logging.WARNING)
args = argparser.parse_args()

# Don’t use an "INFO: " prefix for info messages.
info_handler = logging.StreamHandler()
info_handler.addFilter(lambda r: r.levelno == logging.INFO)
info_handler.setFormatter(logging.Formatter())

other_handler = logging.StreamHandler()
other_handler.addFilter(lambda r: r.levelno != logging.INFO)
other_handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))

logging.basicConfig(level=args.log_level, handlers=[info_handler, other_handler])

Um bestimmte Level nach stdout, andere nach stderr zu schreiben, kann man zwei StreamHandler mit unterschiedlichen Zielen benutzen – quasi genau so, wie hier drüber mit addFilter() und zwei verschiedenen Formattern schon gelöst.


Für alle obigen Beispiele jeweils z.B. Folgendes zum Ausprobieren anhängen:

Code: Alles auswählen

import socket

# Just use the logging functions later in the code. No further checks for the
# configured verbosity necessary.
try:
    raise Exception("This was a mistake :-(")
except Exception as e:
    logging.exception("There was an exceptional exception!")

logging.critical("BOOM!")
logging.error("Zonk …")
logging.warning("Close call")
logging.info("Hi, log reading user!")

# Using printf formatting so messages don’t get formatted when they would not
# be printed anyway because of the configured level.
logging.debug('Your hostname is "%s"', socket.gethostname())

print(f"\nThe effective level is {logging.getLogger().getEffectiveLevel()}")

Zu der Unterteilung, wann man auf eine Art Logging zurückgreift oder wann man Informationen „einfach“ printet und zu stdout–stderr, schließ ich mich ansonsten Meillos Erklärungen an.

Als Versuch einer anderen Einordnung vielleicht noch: Logging und stderr enthält immer ausschließlich Informationen, die für den grundlegenden Zweck des Programms irrelevant sind (etwas überspitzt). Ein Apache-Server schreibt Fehler- und Zugriffslogs, seine eigentlichen „Ausgaben“ macht er aber anders. cat/grep/find uvw. geben dir als Ergebnis ihrer „Arbeit“ Text aus – das ist kein Logging, sondern die Information, die du haben wolltest, die sollte hier nicht z.B. im syslog landen, sondern per print o.ä. auf stdout.


(Mir ist zu spät aufgefallen, dass deutsche Kommentare im Code hier vielleicht passender gewesen wäre. Gewohnheit )

[Meillo]

@JTH: