[Thesis] Logging und Exception-Handling: Konzept erstellen und umsetzen

[AMatutat]

Das Konzept zum Loggen muss ausgearbeitet und dokumentiert werden.
Ziel ist ein klares Konzept, das a) Lognachrichten strukturiert und deren Inhalt definiert, b) klar definierte Log-Level hat und c) einfach im Einsatz ist.

Es muss definiert werden

1. WAS wird geloggt
2. WIE wird geloggt
3. WARUM wird geloggt
4. Wo wird das Logging KONFIGURIERT

Mögliche Sichtweisen:

• Entwicklung: Das Loggen ist quasi Teil des Debuggings - man kann anhand der Ausgaben detailliert den Programmablauf nachvollziehen
• Produktiv-Code: Das Loggen dient zur Ausgabe von Fehlern, von denen sich das Programm nicht selbst erholen kann; dabei sollte die Ausgabe hilfreicher sein als ein einfacher Stack-Trace

Das Logging-Konzept sollte mit dem Exception-Handling-Konzept abgestimmt sein. Aktuell wird das Logging hart kodiert konfiguriert - das sollte besser in der Gradle-Konfiguration passieren, um die unterschiedlichen Blickwinkel abzubilden. Auch sollte dabei berücksichtigt werden, ob man das Spiel direkt aus der Code-Basis startet oder aus dem JAR-File. Analog beim Exception-Handling: Im Moment wird ausgiebig mit (teilweise echt sperrigen) Exceptions geworfen, nur um die dann einen Moment später zu fangen und als RunTimeException neu verpackt erneut zu werfen(?!) und dann in Game einen zentralen Catch-All drin zu haben. Hier sollte man klar unterscheiden: Kann ich revovern - dann sollte ich das melden (loggen) und weiter machen. Kann ich nicht recovern - dann sollte ich eine Exception werfen; die sollte dann aber nicht einfach gefangen und rebranded werden! Hier sollte man auch nochmal überlegen, ob man statt der vielen custom Exceptions nicht einfach direkt eine RunTimeException wirft, damit man das Zerklütern der Signaturen vermeidet.

[cagix]

@AMatutat Das Konzept müsstet aber schon ihr WMs bauen.

[AHeinisch]

Damit es nicht verloren geht. aus #702 discusion zu run Vielleicht ist es sinnvoll ab und zu auf einen niedrigeren Level zu loggen z.b. wenn es zu keinen Änderungen an Werten kommt. Da z.b. core.System.run() immer loggt "System is running" auch wenn es davor nicht gestoppt wurde. Wenn nun ein Fehler mit dem pausieren bzw. starten von Systemen existiert, ist der log nicht hilfreich, da z.b. eine Suche nach einem speziellen System massiven Spam enthalten kann.

[AMatutat]

Ja. Neben Error/Warning brauchen wir gute Abstufungen;

• High-Level: Nur das wichtigste (z.B neues Level wird geladen, Monster stirbt, Held kriegt ein Level-up etc.)
• Medium-Level: Hier würde ich sowas wie "Entity erstellt/entfernt, System verwaltet entity" etc System erstellt
• Low-Level: Components eingefügt/gelöscht etc,
• Debug-Level: (Hilfs)-Methodenaufrufe etc, System-pausiert,

[AMatutat]

Ich bin mit meinem "Konzept" irgendwie wirklich noch nicht glücklich. Ich kriege keinen roten Faden rein.

Was

• Alles, was in jedem Frame passiert, eignet sich nicht zum Loggen. Das betrifft vor allem die System#execute-Methoden. Hier sollten wir nur im Sonderfall loggen. Diese Methoden werden 30+ Mal pro Sekunde aufgerufen, das verstopft die Log-Nachrichten.
• Immer wenn eine Exception geworfen wird, sollte ein Warning geloggt werden. Führt die Exception zu einem Absturz, wird ein Error geloggt.
• Auf Info-Ebene möchte ich wirklich nur fundamentale Geschichten loggen: Programmstart, Programmende, Spielstart, Erstellen und Entfernen der Systeme, Erstellen von Entitäten, Löschen von Entitäten, Laden von neuen Levels, Pausen/Unpausen der Systeme.
• Auf Debug-Ebene sollten Dinge wie das Konfigurieren der Builder-Methoden, das Registrieren/Deregistrieren der Entitäten bei den Systemen und beim Game, das Erstellen und Hinzufügen von Components geloggt werden.

Wie

Klar ist, die Lognachrichten sollen a) aussagekräftig. und b) einheitlich sein.

Für a) Die wichtigsten Informationen sind in meinen Augen, was wurde wo (und warum) gemacht. Je nach Situation kann noch ein Ergebnis oder eine Anmerkung sinnvoll sein.

Um b) zu erfüllen, sollten wir, wo möglich, auf Lognachrichten-Factory-Methoden setzen. Dort kann dann das Was, Wo (Warum) einheitlich generiert werden.

Wichtig ist halt wirklich, dass ich durch das Lesen des Logbuchs (und dem grundlegenden Verständnis, wie das Framework funktioniert) verstehe, was passiert und es vermieden wird, dass das Logbuch mit Loop-Informationen vollgepumpt wird.

@Lena241, kannst du damit was anfangen? Ich hatte irgendwann mal naiv gesagt, mehr ist besser, aber das sehe ich jetzt deutlich anders.

@cagix, ich denke, wir werden auf externe Log-Bibliotheken verzichten wollen, oder? Die können teilweise wirklich schöne Sachen, aber a) ist das wieder eine externe Abhängigkeit und b) müsste man sich dann erstmal für eine entscheiden und sich dort einarbeiten.

[cagix]

@AMatutat Log-Bibliotheken: Es gibt ja ein paar große Namen, und am Ende kommt es darauf an ;) ... Natürlich zögere ich, weitere externe Abhängigkeiten ins Spiel zu bringen. Und grad bei den Logging-Bibliotheken ist es leider so, dass jedes Projekt seine eigenen Vorlieben hat und man schnell zig solcher Libs im Einsatz hat und damit herumjongliert.

Was genau fehlt Dir denn bei java.util.logging? Wie sehr fehlt es Dir? Könnte man das mit halbwegs vernünftigem Aufwand selbst bauen?

[cagix]

Ich stimme zu, dass etwas in jedem Frame zu loggen tödlich sein kann. Die Frage ist, ob es dennoch Dinge gibt, die man hier evtl. sehen will?

Die vorgeschlagene Unterscheidung finde ich ad hoc nachvollziehbar. Die Default-Log-Level sind aber SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST (Error gibt es nicht, Debug auch nicht).

Wie weit würden wir mit Log-Nachrichten-Factories kommen? Ich finde den Gedanken spannend, fürchte aber, dass die Meldungen doch recht unterschiedlich sind und wir dann bei mehr als fünf Factory-Methods enden?

Ein weiterer Gedanke: Brauchen/wollen wir eigene Formatter und/oder eigene Handler?

Noch ein weiterer Gedanke: Wir nutzen die Logger basierend auf dem qualifizierten Klassennamen. Das ist etabliert, aber auch auf Dauer zermürbend und irgendwie auch zerbrechlich: Ich muss in jeder Klasse einen private final Logger LOGGER = Logger.getLogger(this.getClass().getName()); deklarieren - das ist literally exakt überall der selbe Code ... Wenn wir tatsächlich eine Log-Nachrichten-Factory etablieren, könnte man dann darüber nachdenken, dass dort die Logger "erzeugt" werden und in den Klassen beim Aufruf halt der Klassenname oder das Package oder was mit übergeben werden muss (d.h. in den Klassen entfällt die Deklaration der individuellen Logger). Oder dass man dann statt qualifiziertem Klassennamen eine eher funktionsbasierte Namensgebung nutzt ("Game", "System", ...)?

[cagix]

Ich hatte irgendwann mal naiv gesagt, mehr ist besser, aber das sehe ich jetzt deutlich anders.

@AMatutat @Lena241 Weiss nicht. Ich finde schon, dass man auf niedrigem Level relativ viel loggen sollte. Aber diese Level wird man vermutlich nie aktivieren, d.h. das verpufft dann. Aber für Debug-Fälle o.ä. könnten die Informationen schon wertvoll sein. Es müsste halt nur durchgängig passieren: Erstellen, Ändern, Löschen, ... also im gesamten Lebenszyklus der unterschiedlichen Bausteine. Müsste also nochmal je Package genau analysiert werden (Entitäten sind anders als Components oder Systeme).

[cagix]

@AMatutat @Lena241 Wie weit seid ihr denn hier? Könnt ihr das morgen oder nächste Woche im Meeting mal als Konzept vorstellen mit Bewertung und möglichen Handlungsalternativen? Dann sollte noch das https://github.com/Programmiermethoden/Dungeon/labels/meeting Label mit dran.

[cagix]

Damit es nicht verloren geht. aus #702 discusion zu run Vielleicht ist es sinnvoll ab und zu auf einen niedrigeren Level zu loggen z.b. wenn es zu keinen Änderungen an Werten kommt. Da z.b. core.System.run() immer loggt "System is running" auch wenn es davor nicht gestoppt wurde. Wenn nun ein Fehler mit dem pausieren bzw. starten von Systemen existiert, ist der log nicht hilfreich, da z.b. eine Suche nach einem speziellen System massiven Spam enthalten kann.

@AMatutat An der Stelle macht vielleicht ein "großes" Logging-Framework Sinn - die speichern die Logs nach verschiedenen Kanälen sortiert bzw. bringen teilweise eine Art Viewer mit. Vielleicht hat einer der Tutoren mal Lust, sich log4j (Apache), SLF4J oder Logback anzuschauen? (um mal nur ein paar Namen zu nennen)

[AMatutat]

Morgen wird knapp, nächste Woche gerne.
Ich schieb das Issue eh die ganze Zeit (@Lena241 sorry dafür, du kannst ja ohne richtiges konzept nicht wirklich was machen) und dann hätte ich jetzt mal etwas Feuer unterm Hintern was das Ding angeht.

[tgrothe]

Ich habe eine Idee, im Laufe der Diskussion in #1532. Wir definieren in Game eine "globale" "Ausstiegsmethode": public static void exitDungeon(String cause) {}, diese könnte dann von allen Codestellen aufgerufen werden, die eine Exception hochreichen würden, und diese könnte dann eine Fehlermeldung ausgeben (bzw. loggen), und dann das Spiel (geordnet) mit exit System beenden.

Ggf. könnte ihr auch ein Stacktrace übergeben werden können ...