Log-Korrelation mit TracEE

Logging in verteilten Systemen: Das neue Logging-Framework TracEE stellt sich vor

Sven Bunge

©Shutterstock.com/Bildagentur Zoonar GmbH

Überspitzt gesagt hat ein Entwickler in zwei Belangen Kontakt mit dem Fachbereich: neue Anforderungen und neue Bugs. Selten ist ein Bug einfach zu reproduzieren, viel mehr muss eine genaue Abfolge eingehalten werden. Doch oft wird gerade diese nicht richtig beschrieben. Das hier gezeigte Framework TracEE stellt Merkmale für die Korrelation und Suche von Log-Meldungen bereit und vereinfacht die Fehlersuche in großen, verteilten Systemen.

Logging in verteilten Systemen – Log-Korrelation mit TracEE

Eine monolithische Software-Architektur eignet sich nur bedingt für hohe Skalierung, Hochverfügbarkeit und agile Entwicklung mit mehreren Teams. Vor diesem Hintergrund begannen wir vor vier Jahren die Entwicklung einer E-Commerce-Plattform für digitale Produkte im Auftrag eines Kunden und setzen auf eine Mischung aus SOA und vielen kleinen Web-Anwendungen für die Darstellung. Wir hielten nicht alle Prinzipien von Twelve Factors ein, waren aber schon damals nah dran. Das System skalierte gut in der Breite, was auch vom Kunden genutzt wurde. Die Komponenten des produktiven Teilsystems wurden auf mehr als 50 Servern installiert und klassisch via BigBang live geschaltet. Alles lief soweit gut, es gab aber natürlich kleinere Bugs oder fachliche Inkonsistenzen, von denen einzelne Endkunden betroffen waren und sich dann via E-Mail oder Telefon beschwerten. Wir standen vor der Herausforderung, den genauen Sachverhalt mit der Aussage der Kunden abzugleichen und die Verarbeitung im Backend nachzuvollziehen. Hierzu analysierten wir primär die Logstatements.

Ist es bei wenigen Servern schon eine Herausforderung, die Logdateien zu durchsuchen, so ist dies bei mehr als 50 Servern mit jeweils mehreren Komponenten nahezu unmöglich. Wir ließen daher alle Logdateien via Logstash einsammeln, lieferten diese an Elasticsearch und nutzten Kibana für die Suche. Mit diesem ELK-Stack konnten wir die Log Statements zwar durchsuchen, aber es war immer noch sehr schwierig, die einzelnen Events zu korrelieren. Die Verwendung der Thread ID schloss sich aus, da an jeder Kundenanfrage viele verschiedene Server und Threads beteiligt waren. Die Analyse konnte bis dahin nur von erfahrenen Entwicklern vorgenommen werden, da diese neben dem technischen Einblick in alle betroffenen Komponenten auch die fachliche Sicht kannten. Man musste wissen, wo der nächste Schritt im Code langläuft. Die Analyse einer Customer Journey in dieser Form dauerte schlichtweg zu lange.

Log-Statements korrelieren, aber was?

Etwas Abstand zum Problem bringt oft die Lösung: Wir begannen, über Korrelations- IDs nachzudenken und darüber, diese transparent über die Systemgrenzen zu übertragen. Erst dachten wir nur an diese eine correlationId. Aber wir wollten nicht nur einzelne Requests eines Nutzers verfolgen, wir wollten die Conversation, die Session oder auch wiederkehrende Jobs verfolgen können. Auch wollten wir je nach Einsatzgebiet den Logstatements weitere Meta-Informationen mitgeben, sodass die Korrelation nicht beim Schreiben, sondern erst beim Durchsuchen wieder gebildet wird.

Korrelierte_Logstatements_in_Kibana

Logstatements mehrerer Komponenten und Server via HTTP-Session korreliert

So begannen wir mit der Entwicklung des Frameworks TracEE. Die Idee: Wir nutzen den Mapped Diagnostic Context (siehe Logback-MDC ), der von SLF4J weitestgehend abstrahiert und mittlerweile von fast jedem Logging Framework bereitgestellt wird. Mittels MDC können im Scope des gerade aktiven Java Threads Metadaten abgelegt und dann mittels Log Framework bei jedem Statement ausgegeben werden. Hier können wir beliebige IDs ablegen und diese je nach verwendeter Logging-Implementierung im Logstatement einfügen oder mittels JSON neben dem Statement als Metadaten direkt an Logstash senden. Mittlerweile gibt es Umsetzungen des MDC auch für PHP und Ruby.

Ähnlich wie auf dem Classpath geht es auf dem MDC mitunter sehr bunt zu: Viele weitere Frameworks wie z.B. Apache Camel legen dort ebenfalls Logging-Informationen ab. Nach der Verarbeitung muss auch noch jede Komponente dafür sorgen, dass der MDC wieder aufgeräumt wird. Hier darf TracEE nur die Einträge entfernen, die auch über das Framework hinzugefügt wurden. Auch sollen andere MDC-Werte nicht automatisch auf andere Komponenten übertragen werden. Aus diesem Grund merkt sich TracEE die hinzugefügten Keys auch noch selbst. Das heißt im Umkehrschluss, dass alle Werte über TracEE selbst in den MDC geschrieben werden müssen:

Tracee.getBackend().put(„conversationId“, „XYZ1234“);

Den Invocation Context an andere Komponenten propagieren

Unser System kommunizierte intern fast ausschließlich über Protokolle auf der Basis von HTTP (z.B. REST). An dieser Stelle bieten sich die HTTP-Header für die transparente Übertragung der Daten an. Um im HTTP-Standard zu bleiben, mussten wir Key und Value via URL-Encode umformen und konnten diese dann mittels Gleichheitszeichen verbinden. Mehrere Key-Value-Paare werden mittels Komma separiert. Es ist so einfach, dass auch Implementierungen außerhalb von Java denkbar sind.

Als Namen des HTTP-Headers wählten wir TPIC: TracEE Propagated Invocation Context. Und um genau das handelt es sich: Es wird der Kontext des Aufrufs übertragen. Hierbei wird der Kontext nicht nur vom Aufrufer an den Dienst im Request übertragen, der Kontext wird auch im Response an den Aufrufer zurückpropagiert. Werden dem Context in der aufgerufenen Komponente weitere Informationen hinzugefügt, so werden diese im Response ebenfalls zurückübertragen.

TPIC: in+Request=yes,TPIC.invocationId=ABC4711

In älteren Teilen der Anwendung geschieht der Datenaustausch hingegen via SOAP. Da die Requests durch ein paar XML-Proxies wandern und damit die HTTP-Header verloren gehen, mussten wir an dieser Stelle die Strategie ändern. Bei der Übertragung via SOAP wird stattdessen der SOAP Header für die Meta-Informationen verwendet. Auch hier geschieht dies in beide Richtungen. Ein entsprechender SOAP Envelope mit Header ist dem Listing zu entnehmen.

<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
  <soap:Header>
    <TPIC xmlns="http://tracee.io/tpic/1.0">
      <entry key="in Request">yes</entry>
      <entry key="TPIC.invocationId">ABC4711</entry>
    </TPIC>
</soap:Header>
...
</soap:Envelope>

Mit Bindings TracEE an verwendete Technologie binden

Soweit die Theorie der Übertragung selbst. Diese muss nun für diverse Technologien gut und einfach bereitgestellt werden und es müssen alle Standards eingehalten werden. Aus diesem Grund gliederten wir TracEE in diverse Module. Neben API und Core gibt es für viele Java-Technologien bereits Bindings, um mit wenig Aufwand die Header entsprechend zu übertragen.

Neben Implementierungen für den Servlet-, JaxWS- und JaxRS-Standard werden auch diverse HTTP Clients von Apache sowie SpringMVC, SpringWS, Spring AMQP, Apache CXF oder auch Quartz unterstützt. Um für möglichst viele Leute nutzbar zu sein, setzt TracEE nur auf ältere Framework-Versionen als Mindestvoraussetzung und gibt sich mit Java-Version 6 zufrieden. Alle Bindings funktionieren aber (Stand heute) auch mit der aktuellen Version der entsprechenden Technologie.

Die Grundlagen sind soweit geschaffen: Meta-Informationen werden bei jedem Logstatement an unseren ELK Stack übermittelt, werden als Propagated Invocation Context an andere Services übertragen, so dass nur noch die entsprechenden IDs für Korrelation fehlen.

Korrelation mit der Hilfe von mehreren IDs

TracEE selbst generiert in der Default-Einstellung eine sogenannte invocationId, wenn diese noch nicht existiert bzw. aus dem Request gelesen werden konnte. Im Servlet Binding wird zudem ein Hash der HTTP SessionId generiert und als sessionId mit übertragen. Sollte dies für den eigenen Anwendungsfall nicht ausreichen, so können nach Belieben weitere IDs je nach gewünschter Korrelation generiert und TracEE hinzugefügt werden. So ist z.B. eine conversationId denkbar, die sich via HTTP-Links oder Cookies auf andere Komponenten mit einer Web-GUI überträgt. Auch könnten weitere Nutzer-IDs des Systems hinzugefügt werden, die dann in Kibana bzw. in den Logfiles als Information zur Verfügung stehen.

Grafische_Darstellung_der_Propagation

Abb. 1 Propagation des Contextes über Systemgrenzen hinweg

Selektive Übertragung / Annahme von Kontext-Informationen

Bei der Übertragung der Informationen auf andere Komponenten ist drauf zu achten, dass evtl. nicht alle Informationen übertragen bzw. angenommen werden sollen. Denkbar ist z.B., dass für die Ansteuerung eines im Internet verfügbaren Services nur die invocationId mitgesendet wird. Die selbst hinzugefügte Kundennummer soll hingegen das System nicht verlassen.

Dies ist mittels Konfigurationsprofil möglich. Dort kann je nach gewünschter Übertragungsrichtung bestimmt werden, welche Keys gelesen bzw. geschrieben werden sollen. Auch Anpassungen der Länge der Standard-IDs sind möglich. Dabei ist es nicht erforderlich, eine vollständige Konfiguration zu hinterlegen — nicht gesetzte Werte werden von der Default-Konfiguration übernommen.

Um ein Profil zu nutzen, bieten viele Bindings die Möglichkeit, dieses bei der Initialisierung anzugeben. Für alle Standard-Profile stehen Konstanten in der Klasse TraceeFilterConfiguration.Profile bereit. Passt keines der Profile auf die Anforderung, z.B. weil via RegularExpression ein Übertragungsparameter ausgeschlossen werden muss, so ist eine Datei META-INF/tracee.properties anzulegen. Dort können dann mehrere Profile definiert werden. Mehr Informationen können der BindingConfiguration auf der Homepage entnommen werden.

Ausblick

Die Entwicklung von TracEE geht auf Github natürlich stetig weiter. Hinsichtlich der Kernfunktionalität und Flexibilität ist TracEE bereits jetzt sehr gut aufgestellt. Gerade denken wir über ein Modul für AngularJS und einen Starter für Spring Boot nach.

Eine Entwicklung ist schon weit fortgeschritten und könnte das Logging von Fehlern verbessern: TracEE ContextLogger. Tritt ein Fehler in der Anwendung auf, werden HTTP-Aufruf sowie Methodenparameter ebenfalls protokolliert. In Verbindung mit TracEE wird damit die Fehlersuche zum Kinderspiel.

Fazit

Mit mehreren IDs können die Logstatements bei der Suche individuell und je nach Fehler bzw. Anwendungsfall korreliert werden. Dies hat die Fehlersuche in unseren Projekten wesentlich vereinfacht. Diese IDs werden mittlerweile auch direkt in Bugtickets zwischen den Teams und angeschlossenen Partnern verwendet.

Bleibt noch zu erwähnen, dass wir uns auf Feedback und Pull-Requests auf Github freuen.

Aufmacherbild: Log output von Shutterstock / Urheberrecht: Bildagentur Zoonar GmbH

DevOpsCon Whitepaper 2018

Free: BRAND NEW DevOps Whitepaper 2018

Learn about Containers,Continuous Delivery, DevOps Culture, Cloud Platforms & Security with articles by experts like Michiel Rook, Christoph Engelbert, Scott Sanders and many more.

Verwandte Themen:

Geschrieben von
Sven Bunge
Sven Bunge
Sven Bunge arbeitet als Senior Consultant bei der Management- und IT-Unternehmensberatung Holisticon AG. Er beschäftigt sich dort mit der Architektur von komplexen verteilten Systemen sowie deren Performanceoptimierung. Die Aspekte von einfacher und qualitativ hochwertiger Software hat er dabei stets im Blick.
Kommentare

Hinterlasse einen Kommentar

Hinterlasse den ersten Kommentar!

avatar
400
  Subscribe  
Benachrichtige mich zu: