Automatisiertes Testen mit Lognachrichten

Matthias Putz

Testen mit Logmeldungen

Die Idee hinter “Automatisiertes Testen mit Lognachrichten” ist es, sich zu Nutze zu machen, dass jedes einzelne System Lognachrichten produziert. Oft liest der Entwickler beim Programmieren diese Nachrichten oder analysiert die Loghistorie, um einen Bug aufzuspüren.

Lognachrichten nehmen bei dem vorgestellten Ansatz eine weitere, sehr entscheidende Rolle ein: Alle Lognachrichten aller Systeme werden zentral gesammelt und stehen dem Testsystem zur Verfügung. Sie dienen dem Nachvollziehen, in welchem Zustand sich die einzelnen Systeme befinden und ob bestimmte Aktionen ausgelöst wurden. Daraufhin kann der Test dann die externen Schnittstellen des Systems nutzen, um das System in einen anderen Zustand zu bringen und um anschließend wieder auf die entsprechende Reaktion in den Logmeldungen zu hören.

Löst eine Aktion nicht oder nicht innerhalb eines Zeitrahmens eine bestimmte Logmeldung aus, ist der Test fehlgeschlagen. Das beschreibt die relativ simple Kernidee des Ansatz, welche jedoch große Mächtigkeit besitzt:

• Lognachrichten bieten einen beliebig tiefen und detaillierten Einblick in ein System. Entscheidend ist die Qualität der Logmeldungen (siehe Abschnitt “Positive Seiteneffekte”).
• Die einzige Anpassung an einem System, um es für die Integrationstests verwenden zu können, ist das Weiterleiten der Lognachrichten an eine zentrale Instanz (bereits weit verbreitet ist z.B. der Elk Stack [1]). Meist muss für das Weiterleiten nur die Konfigurationsdatei des verwendeten Logging-Frameworks angepasst werden und somit hält sich der Aufwand durchaus im Rahmen.
• Das Gesamtsystem kann für den Test als Blackbox betrachtet werden. Insbesondere müssen keine Datenbanken ausgelesen werden und interne Schnittstellen nach außen und somit über Sicherheitsbarrieren hinaus, verfügbar gemacht werden. Natürlich stellen auch Lognachrichten schützenswerte Informationen dar. Beachtet man jedoch die Vorgabe, dass keine sensiblen Daten im Klartext geloggt werden dürfen (siehe Abschnitt “Probleme und Lösungen”), so kann ein Angreifer auf ein Produktivsystem, bei dem vergessen wurde das Testsetup zu deaktivieren, lediglich die Lognachrichten mitlesen.

Abbildung 1 zeigt das Testsystem und die für den Test wichtigen Interaktionen im Überblick: Systeme senden ihre Lognachrichten an eine zentrale Instanz (1) und sendet diese somit an den Test weiter (2). Durch die Lognachrichten steuert das Testsystem den Ablauf des Tests indem es auf Lognachrichten hört (3) und das Gesamtsystem durch die externen Schnittstellen stimuliert (4).

Das Testsystem

Ein Integrationstest könnte wie folgt aussehen:

try {
  startSystem()
  waitFor(DEBUG, "UserManagement", "Starting user controller", TIMEOUT_10S)

  createUser(name="Hans", password="1234") // Aufruf einer Remote API
  waitFor(DEBUG, "UserController", "Creating user: id=1, name=Hans", TIMEOUT_10S)
  assumeNot(DEBUG, "UserController", "Failed to create user: name=Hans, error=Name invalid", TIMEOUT_10S)
} finally {
  stopSystem()
}

Dies beinhaltet alle notwendigen Primitiven:

• startSystem() - Fährt das System hoch. Z.B. kann hier ein Testsystem mit docker-compose oder ein Kubernetes Cluster mit kubectl kontrolliert werden. Wichtig ist hierbei, dass aus Sicht des Tests beim Hochfahren ein sauberes, wohl definiertes System mit gegebenenfalls bekannten Testdaten, vorliegt.
• stopSystem() - Versucht das System nach dem Test zu stoppen.
• waitFor(level, logger, message, timeout) - Wartet auf die Lognachricht message mit Level level von logger. Nach timeout Sekunden tritt der Timeout auf und die Nachricht gilt als nicht empfangen. waitFor durchsucht dabei zuerst die bereits eingegangenen Lognachrichten und, falls nicht vorhanden, prüft alle neu ankommenden Nachrichten ob sie auf die Nachricht, sprich die Attribute level, logger und message, matchen. Abbildung 2 zeigt das Ablaufdiagramm von waitFor für eine Nachricht m und Timeout t.

• assumeNot(level, logger, message, timeout) - Die Nachricht m mit den beschriebenen Attributen soll nicht innerhalb des Timeouts timeout auftreten. Abbildung 3 zeigt das Ablaufdiagramm von assumeNot. Da der Test im Gutfall für die Zeit des Timeouts t blockiert, sollte bevorzugt waitFor Tests verwendet werden.

Hinter createUser(..) verbirgt sich kein Primitiv sondern ein Aufruf zu einer Remote API und somit ein anwendungsspezifischer Aufruf. Um den Test lesbar zu machen, ist es ratsam alle externen Aufrufe in Methoden auszulagern.

Ferner hat es sich bewährt, dass die beiden Parameter logger und message in waitFor und assumeNot als reguläre Ausdrücke ausgewertet werden. Dadurch kann der Test z.B. auch Lognachrichten prüfen, bei denen er sich nicht für alle Parameter interessiert. Zum anderen können im regulären Ausdruck Parameter gecaptured und von waitFor bzw. assumeNot zurück gegeben werden. Dies ist z.B. sehr hilfreich, wenn der neu angelegte Benutzer eine zufällig generierte Id zugewiesen bekommt, die fortan für diverse Aktionen mit dem Benutzer notwendig ist:

val groups = waitFor(DEBUG, "UserController", "Creating user: id=(.*), name=Hans", TIMEOUT_10S)

Positive Seiteneffekte

Neben der Möglichkeit Integrationstests einfach zu schreiben, hat der beschriebene Ansatz weitere positive Effekte:

1. Bessere Logmeldungen

Ein positiver Effekt des Ansatzes ist, dass Logmeldungen mit mehr Bedacht geschrieben werden. Wichtig ist auch Logging Guidelines in den Code Style Guidelines festzulegen und einzuhalten. Logging Guidelines beinhalten zum einen das Format von Lognachrichten sowie was wann in welchem Level geloggt werden soll.

Durch die Einhaltung der Guidelines wird ein Logtrace des Gesamtsystems in sich konsistent und folglich steigt die Lesbarkeit fremder Logabschnitte stark an. Ferner haben diese Logmeldungen dann durchaus auch den Anspruch einen fachlichen Wert darzustellen, sprich von Nicht-Entwicklern verstanden und analysiert werden zu können.

Basierend auf den Guidelines von Google [2] und dem Artikel The Art of Logging [3] haben wir unsere eigenen Guidelines entworfen [4]. Diese Guidelines können durchaus sehr projektspezifisch sein. Der Vorschlag soll dazu anregen sich über die Punkte aus dem Kasten „Aspekte für Logging Guidelines“ Gedanken zu machen.

Als Faustregel, ob man die Lognachrichten im korrekten Level ausgibt, kann folgende Regel gelten: Um mit dem Integrationstest zu prüfen ob das Löschen eines Benutzers funktioniert, bringt der Test das Gesamtsystem zuerst in den notwendigen Zustand. Das heißt mit Hilfe von Info-Nachrichten wird geprüft ob alle notwendigen Systeme gestartet sind und, per Remote API, wird ein Benutzer angelegt:

I/UserManagement: Starting User Controller
    I/UserManagement: Creating user: id=123, name=Hans

Anschließend wird mit Hilfe von Info- und Debug-Nachrichten der Testfall überprüft, sprich, es wird geprüft ob alle erwarteten Aktionen ausgelöst werden:

I/UserManagement: Deleting user: id=123
    D/UserManagement: Invalidating user tokens: user id=123
    D/EventPublisher: Publishing user-deleted Event: id=123

Jedoch haben die automatisierten Tests nicht nur einen Qualitätssicherungscharakter, sondern helfen auch bei der Entwicklung.

2. Szenarien für Feature-Implementierung sind reproduzierbar

Sehr hilfreich kann es auch sein, wenn man im Gesamtsystem ein bestimmtes Szenario reproduzieren möchte, um ein gewisses Feature zu entwickeln und zu verifizieren. Zum Beispiel verwendet man einen Test, der das Szenario beinhaltet und setzt einen Breakpoint auf die Zeile, ab der man selbst das System weiter stimulieren möchte. Konkret vermeidet man somit z.B. dass man lokal händisch mehrere User mit diversen Rechten anlegen muss, welche bereits irgendwelche Transaktionen durchgeführt haben - all das macht das System bereits im Test bis zu dem Breakpoint. Zudem lassen sich somit auch Protokolle wie die Authentifizierung über OAuth automatisieren.

3. Teilsysteme sind testbar

Der vorgestellte Ansatz kann noch dahingehend erweitert werden, dass man das Gesamtsystem als “Graybox” betrachtet: Simuliert man bestimmte Teile des Gesamtsystem im Test wie z.B. einen einzelnen Microservice, sofern man Zugriff auf z.B. den Message Bus hat, kann man sein eigenes Feature bereits umsetzen und dessen Auswirkungen betrachten, noch ehe das Team des anderen Microservice seinen Teil des Features umgesetzt hat. Dieser Test kann dann später zu einem vollständigen Integrationstest ausgebaut werden.

Probleme und Lösungen

Beim Umsetzen des Ansatzes in realen Projekten treten weitere Probleme auf, zu denen wir unsere Erfahrungen vorstellen möchten:

1. Sensible Daten werden nicht geloggt

Sensible Daten wie Passwörter etc. sollten nicht in Logs auftauchen. Um dennoch eine Verbindung herstellen zu können, sollte man z.B. eine kryptographische Hash-Funktion auf die sensiblen Daten anwenden und das Ergebnis als Referenz in den Logs verwenden.

2. Ändern einer Lognachricht lässt Integrationstests fehlschlagen

Dadurch das Lognachrichten nun integraler Bestandteil der Integrationstests sind, kann eine Änderung der Nachricht auch Tests fehlschlagen lassen. Logging Guidelines und Best Practices sollen verhindern, dass sich bereits etablierte und in vielen Tests verwendete Logmeldungen oft ändern. Jedoch ist auch hier beim Entwickler ein Bewusstsein für die Logmeldungen zu schaffen, da sie nicht mehr nur zur eigenen Informationsausgabe dienen.

3. Systeme loggen nicht in die Cloud, wie z.B. Steuergeräte

Zur Speicherung werden meist bei Cloud-Systemen bereits Lösung wie der ELK-Stack [1] zum zentralen Sammeln von Lognachrichten verwendet. Etwas mehr Aufwand muss ggf. bei Steuergeräten investiert werden, da deren Lognachrichten lediglich über USB oder eine serielle Schnittstellen zu einem Host-System übertragen werden. Somit muss auf dem Host-System mit Hilfe eines Adapters dafür gesorgt werden, dass die Lognachrichten weitergeleitet werden. Ein Raspberry Pi [6] eignet sich z.B. sehr gut als Host-System.

4. Externe Services

Oft greift das eigene System auf die API externer Services zu. Um diese externen Schnittstellen in das Testsystem einzubinden, hat es sich bewährt, wie folgt vorzugehen:

• Der Endpunkt der externen Schnittstelle wird im System parametrierbar gemacht.
• Im Testszenario wird der Endpunkt auf einen eigenen, programmierbaren Testserver weitergeleitet.
• Der Testserver wird für den Test konfiguriert: Im einfachsten Fall kann man z.B. für einen bestimmten REST-Endpunkt den Statuscode und den Body setzen.
• Zudem kann der Testserver auch mit Fehlercodes antworten und somit können die Auswirkungen von Fehlerantworten von externen Services getestet werden.

In der Gesamtübersicht ist der Testserver wie in Abbildung 4 wieder zu finden.

5. Libraries, die selbst mit externen Systemen reden

Ein grosses Problem ist, wenn Libraries selbst die Verbindungen nach aussen, zu einem externen Service, aufbauen (über eine hart codierte URL). Als Lösung sollte hier die Verwendung der Library konfigurierbar gemacht werden und beim Testen ein Mock der Library verwendet werden, welcher zum bereits erwähnten Testserver kommuniziert.

6. Aufstart eines sauberen Systems dauert lange

Da in einem Gesamtsystem oft sehr viele Komponenten beteiligt sind, kann der Aufstart eines sauberen Systems durchaus sehr lange dauern. Da man für den Test keinen speziellen Aufstart umsetzen möchte, ist dieses Problem nicht lösbar. Einzig das manuelle, vor jedem Test stattfindende, Resetten der Infrastruktur-Komponenten wie Message-Broker, Datenbanken etc. bei noch nicht gestarteten Applikations-Komponenten kann die Tests beschleunigen.

Fazit

Für die meisten Systeme ist die Notwendigkeit von Integrations- und Systemtests unumstritten. Insbesondere wenn verschiedene Teams Teilsysteme entwickeln und somit die Qualität des Produkts nicht nur durch die Qualität der Teilsystemen sondern auch durch die reibungsfreie Interaktion der Teilsysteme miteinander bestimmt wird.

Wünschenswert ist es dabei - zumindest auf einem Basisniveau – die Integrationstests zu automatisieren. Der hier vorgestellte Ansatz des automatisierten Testens mit Lognachrichten sollte insbesondere durch seine nicht-invasive Möglichkeit der Umsetzung für viele Systeme sehr attraktiv sein. Zudem ergeben sich viele gute Nebeneffekte wie ein verständlicher, einheitlicher Logtrace. Einzig das Erstellen eines sauberen Systems für jeden Test ist aufwendig oder ggf. zeitintensiv.

Neben den bereits erwähnten Vorschlag für Logging Guidelines [4] findet man auf Github auch eine Implementierung des vorgestellten Ansatz [7].

Literatur & Links