Spring Boot & Apache CXF – Logging & Monitoring mit Logback, Elasticsearch, Logstash & Kibana

SOAP-Endpoints auf Basis von Microservice-Technologien mit Spring Boot? Cool! Aber wie findet man bei den ganzen „Micro-Servern“ Fehler? Wie sehen die SOAP-Nachrichten aus und wie logge ich eigentlich generell? Und: wie viele Produkte haben wir eigentlich verkauft? Das klingt so, als bräuchten wir einen Blogartikel zum Thema Logging und Monitoring mit Spring Boot und Apache CXF!

Spring Boot & Apache CXF – Tutorial

Part 1: Spring Boot & Apache CXF – SOAP ohne XML?
Part 2: Spring Boot & Apache CXF – SOAP Webservices testen
Part 3: Spring Boot & Apache CXF – XML-Validierung und Custom SOAP Faults
Part 4: Spring Boot & Apache CXF – Logging & Monitoring mit Logback, Elasticsearch, Logstash & Kibana
Part 5: Spring Boot & Apache CXF – Von 0 auf SOAP mit dem cxf-spring-boot-starter

Nach nunmehr drei Artikeln geht uns die Arbeit mit Spring Boot & Apache CXF schon leicht von der Hand. Wir ziehen munter neue SOAP-Endpoints hoch, testen diese vernünftig mit Unit- & Integrationstests und geben bei Verstößen gegen gute XML-Sitten Alarm – natürlich XML-Schema-konform. Doch noch bevor der erste SOAP-Endpoint produktiv geht, wollen wir wissen, welche SOAP-Messages da im Detail über die Leitung gehen. Allein für eine vernünftige Zusammenarbeit mit Service-Consumern im Test ist es unerlässlich, dass unsere SOAP-Endpoints alle ein- und ausgehenden Messages loggen.

Und spätestens auf dem Weg in die Produktion werden auch noch erste Stimmen aus der Fachabteilung laut, die die genauen Aufrufzahlen unserer Services haben wollen – vielleicht sogar detailliert, wie viele Produkte verkauft wurden etc. Außerdem haben wir unsere schlanke Architektur intern so gut verkauft, dass jedes neue Projekt mit SOAP-Endpoints unserer Vorgehensweise folgt – die Anzahl der Endpoints im Unternehmen steigt und wir können nicht mehr auf jedem einzelnen Server nachschauen, was der gerade für Messages verarbeitet.

Transparenz über die SOAP-Messages muss her. Aber wie loggen wir überhaupt mit Apache CXF? Welches Logging-Framework sollten wir einsetzen? Und wie beantworten wir die Fragen der Fachabteilung und müssen gleichzeitig nicht auf jedem einzelnen Server in Logfiles wühlen? Wir werden versuchen hier alles zu beantworten, Schritt für Schritt. Kurz durchatmen – und los!

Ein einheitliches Logging-Framework: slf4j und Logback

Wie immer kann man alle Schritte selbst nachvollziehen – das GitHub Repository tutorial-soap-spring-boot-cxf wartet schon auf Besuch. Der folgende Schritt findet sich komplett im Projekt step6_soap_message_logging und baut diesmal auf dem vorletzten Step aus dem zweiten Teil der Blogserie SOAP-Webservices testen auf (step4_test ), da nicht jeder Custom SOAP Faults benötigen wird.

Zu Beginn kann man sich die Frage stellen, welches Loggingframework denn zum Einsatz kommen soll. Gesetzt sollte hier die Simple Logging Facade for Java (slf4j) sein, eine naheliegende Wahl für die Loggingimplementierung wäre Logback . Die führende Stellung von slf4j und Logback hat auch die Spring Boot Entwickler dazu bewogen, beide als Standard in Spring zu nutzen. Leider tut das Apache CXF erstmal nicht und nutzt das Java SE Logging aus java.util.logging . Zum Glück gibt es hier aber Abhilfe um Spring Boot, Apache CXF und unsere eigene fachliche Implementierung auf einen gemeinsamen Nenner zu bekommen: Das Logging Framework für den gesamten Apache CXF Stack lässt sich seid Version 2.2.8 konfigurieren. Das nutzen wir natürlich sofort und konfigurieren slf4j. Dazu erstellen wir in src/main/resources einen Ordner META-INF und darin einen weiteren namens cxf. Darin erstellen wir eine Datei org.apache.cxf.Logger deren einzige Zeile folgendes enthält:

1org.apache.cxf.common.logging.Slf4jLogger

Fertig. Beim nächsten Start unseres Endpoints läuft das gesamte Logging über slf4j und Logback. Konfigurieren können wir das Logging somit ganz bequem über eine logback-spring.xml (eine detaillierte Einführung zur Konfiguration von Logback bietet die Dokumentation ):

1<?xml version="1.0" encoding="UTF-8"?>
2<configuration>
3    <include resource="org/springframework/boot/logging/logback/base.xml"/>
4    <logger name="org.springframework" level="WARN"/>
5    <logger name="org.apache.cxf" level="INFO"/>
6    <logger name="de.jonashackt.tutorial" level="DEBUG"/>
7 
8  <appender name="file" class="ch.qos.logback.core.FileAppender">
9      <file> weather-service.log </file>
10      <append>true</append>
11      <encoder>
12         <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
13      </encoder>
14   </appender>
15 
16  <root level="INFO">
17      <appender-ref ref="file" />
18  </root>
19</configuration>

Für unsere Zwecke reicht diese recht simple Konfiguration. Zuerst inkludieren wir die Logback Basiskonfiguration von Spring Boot und bauen somit auf dieser auf. Dann setzen wir für´s Erste Spring auf „WARN“, Apache CXF auf „INFO“ und unsere eigene Implementierung auf „DEBUG“. Die Level sind hier natürlich nur exemplarisch und können nach Lust und Laune angepasst und erweitert werden. Danach konfigurieren wir einen einfachen Logfile-Appender inkl. Namen und entsprechendem Pattern.

In unserem Code initialisieren wir uns übrigens immer einen org.slf4j.Logger und nutzen die Methode getLogger(Class clazz) der Klasse org.slf4j.LoggerFactory , um unseren Logger inital anzulegen:

1private static final Logger LOG = LoggerFactory.getLogger(ClassWhereWeUseThisLoggerInside.class);

Danach steht uns die ganze Bandbreite an logging-Methoden (.info(), .debug(), usw.) zur Verfügung.

SOAP Message Logging: Konfiguration des Apache CXF Endpoints

Um Apache CXF dazu zu bringen SOAP-Messages zu loggen, reicht die Konfiguration eines LoggingFeatures in unserer WebServiceConfiguration . Dieses kann man z.B. global direkt auf dem SpringBus konfigurieren:

1@Bean(name = Bus.DEFAULT_BUS_ID)
2public SpringBus springBus() {
3    SpringBus springBus = new SpringBus();
4    LoggingFeature logFeature = new LoggingFeature();
5    logFeature.setPrettyLogging(true);
6    logFeature.initialize(springBus);
7    springBus.getFeatures().add(logFeature);
8    return springBus;
9}

Dabei wird fortan jeder Endpoint dieses SOAP-Servers alle ein- und ausgehenden Nachrichten loggen. Eine zweite Möglichkeit besteht darin, die Konfiguration des Loggings pro Endpunkt vorzunehmen. Die Konfiguration funktioniert sehr ähnlich:

1@Bean
2public Endpoint endpoint() {
3    EndpointImpl endpoint = new EndpointImpl(springBus(), weatherService());        
4    endpoint.setServiceName(weather().getServiceName());
5    endpoint.setWsdlLocation(weather().getWSDLDocumentLocation().toString());
6    endpoint.publish(SERVICE_URL);
7 
8    LoggingFeature logFeature = new LoggingFeature();
9    logFeature.setPrettyLogging(true);
10    logFeature.initialize(springBus());
11    endpoint.getFeatures().add(logFeature);
12 
13    return endpoint;
14}

Haben wir mit Hilfe einer der beiden Varianten das SOAP-Message-Logging konfiguriert, können wir einen unserer Integrationstests ausführen, um die SOAP Messages im Logfile zu finden – am besten unseren WeatherServiceSystemTest , der fährt alles notwendige innerhalb des Tests hoch. In unserer Console sollte sich u.a. die eingehende SOAP-Nachricht finden, wie sie Apache CXF standardmäßig logged (also inkl. Adresse, Encoding, HTTP-Headern usw.):

12016-07-14 17:52:50.988  INFO 42064 --- [nio-8090-exec-1] o.a.c.s.W.WeatherService.WeatherService  : Inbound Message
2----------------------------
3ID: 1
4Address: http://localhost:8090/soap-api/WeatherSoapService_1.0
5Encoding: UTF-8
6Http-Method: POST
7Content-Type: text/xml; charset=UTF-8
8Headers: {Accept=[*/*], cache-control=[no-cache], connection=[keep-alive], Content-Length=[662], content-type=[text/xml; charset=UTF-8], host=[localhost:8090], pragma=[no-cache], SOAPAction=["http://www.codecentric.de/namespace/weatherservice/GetCityForecastByZIP"], user-agent=[Apache CXF 3.1.6]}
9Payload: <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
10  <soap:Body>
11    <GetCityForecastByZIP xmlns="http://www.codecentric.de/namespace/weatherservice/general" xmlns:ns2="http://www.codecentric.de/namespace/weatherservice/exception" xmlns:ns3="http://www.codecentric.de/namespace/weatherservice/datatypes" xmlns:xmime="http://www.w3.org/2005/05/xmlmime">
12      <ForecastRequest>
13        <ZIP>99425</ZIP>
14        <flagcolor>blackblue</flagcolor>
15        <productName>ForecastBasic</productName>
16        <ForecastCustomer>
17          <Age>67</Age>
18          <Contribution>500</Contribution>
19          <MethodOfPayment>Bitcoin</MethodOfPayment>
20        </ForecastCustomer>
21      </ForecastRequest>
22    </GetCityForecastByZIP>
23  </soap:Body>
24</soap:Envelope>

Um zu erfahren, welche SOAP-Nachrichten über die Leitung gehen, reicht das im ersten Schritt meist schon völlig aus.

Die Logausgabe der SOAP Messages anpassen

Das ging wirklich schnell bis hier. Aber eigentlich wollen wir selbst bestimmen, wie die Logausgabe aussieht. Man könnte z.B. nur den Payload, also die SOAP-Message selbst sehen wollen. Mit dem Wissen über die Apache CXF Interceptor Chains aus dem letzten Teil , ist das kein Problem. Wir schauen uns dazu die CXF-Klasse org.apache.cxf.interceptor.LoggingInInterceptor an. Die Methode protected void logging(Logger logger, Message message) befüllt darin ein Objekt der Klasse org.apache.cxf.interceptor.LoggingMessage mit allen notwendigen Informationen für die Standard-Logausgabe, die wir eben schon selbst in unserem Logfile bewundern durften. Neben Encoding, Http-Method und all dem anderen wird hier auch der Payload gespeichert. Die letzte Anweisung der Methode ruft die Methode formatLoggingMessage(LoggingMessage loggingMessage) auf. Diese ist sehr simpel und nur dazu da, die toString()-Methode auf das befüllte LoggingMessage-Objekt auszuführen. Genau hier setzen wir an. Denn wir können einfach unsere eigene Klasse von org.apache.cxf.interceptor.LoggingInInterceptor ableiten und formatLoggingMessage(LoggingMessage loggingMessage) überschreiben – schon bestimmen wir, wie Apache CXF unsere SOAP-Message loggt.

Für die folgenden Schritte gibt es wie gewohnt ein GitHub Beispielprojekt step7_soap_message_logging_payload_only . Und los geht´s: Wir erstellen eine Klasse LoggingInInterceptorXmlOnly.java und überschreiben formatLoggingMessage(LoggingMessage loggingMessage) z.B. so:

1import org.apache.cxf.interceptor.LoggingInInterceptor;
2import org.apache.cxf.interceptor.LoggingMessage;
3 
4public class LoggingInInterceptorXmlOnly extends LoggingInInterceptor {
5 
6  @Override
7    protected String formatLoggingMessage(LoggingMessage loggingMessage) {
8        StringBuilder buffer = new StringBuilder();
9        buffer.append("Inbound Message:\n");
10 
11        // Only write the Payload (SOAP-Xml) to Logger
12        if (loggingMessage.getPayload().length() > 0) {
13            buffer.append(loggingMessage.getPayload());
14        }        
15        return buffer.toString();
16    }
17}

Damit Apache CXF unseren eigenen LoggingInInterceptor auch nutzt, müssen wir ihn noch als Spring-Bean konfigurieren und in die Incoming Interceptor Chain hängen. Dazu erweitern wir unsere WebServiceConfiguration :

1@Bean
2public AbstractLoggingInterceptor logInInterceptor() {
3    LoggingInInterceptor logInInterceptor = new LoggingInInterceptorXmlOnly();
4    // The In-Messages are pretty without setting it - when setting it Apache CXF throws empty lines into the In-Messages
5    return logInInterceptor;
6}

Wichtig ist hier, dass unsere Bean vom Typ org.apache.cxf.interceptor.AbstractLoggingInterceptor ist und dass wir die naheliegende Methode setPrettyLogging(true) nicht benutzen – sie sorgt leider dafür, dass unschöne Leerzeilen unsere SOAP-Messages im Log verunstalten (einzige Ausnahme: führt man den Test in Intellij aus, sieht die Logausgabe trotzdem gut aus).

Natürlich haben wir das „In“ unseres LoggingInInterceptors nicht überlesen – wir müssen das gleiche Prozedere auch für die Responses durchführen. Dazu erstellen wir schnell eine Klasse LoggingOutInterceptorXmlOnly.java und leiten sie von org.apache.cxf.interceptor.LoggingOutInterceptor ab. Bis auf die Logmessage „Outbound“ ist der Rest identisch mit dem Inbound Inteceptor. Die entsprechende Bean in der WebServiceConfiguration gibt auch wieder einen AbstractLoggingInterceptor zurück, darf nun aber die Methode setPrettyLogging(true) bedenkenlos nutzen – die Apache CXF Implementierung ist hier komischer Weise eine komplett andere für die ausgehenden Messages:

1@Bean
2public AbstractLoggingInterceptor logOutInterceptor() {
3    LoggingOutInterceptor logOutInterceptor = new LoggingOutInterceptorXmlOnly();
4    logOutInterceptor.setPrettyLogging(true);
5    return logOutInterceptor;
6}

Abschließend packen wir unsere Logging-Interceptors noch in die Apache CXF Interceptor Chains – und damit uns keine Nachricht entgeht, tun wir das auch in den Fault-Chains für den Fehlerfall. Dazu nutzen wir die Konfigurationsmöglichkeiten direkt am SpringBus in unserer WebServiceConfiguration :

1@Bean(name = Bus.DEFAULT_BUS_ID)
2public SpringBus springBus() {
3    SpringBus springBus = new SpringBus();
4    springBus.getInInterceptors().add(logInInterceptor());
5    springBus.getInFaultInterceptors().add(logInInterceptor());
6    springBus.getOutInterceptors().add(logOutInterceptor());
7    springBus.getOutFaultInterceptors().add(logOutInterceptor());
8    return springBus;
9}

12016-07-15 08:35:05.522  INFO 45895 --- [nio-8090-exec-1] o.a.c.s.W.WeatherService.WeatherService  : Inbound Message:
2<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
3  <soap:Body>
4    <GetCityForecastByZIP xmlns="http://www.codecentric.de/namespace/weatherservice/general" xmlns:ns2="http://www.codecentric.de/namespace/weatherservice/exception" xmlns:ns3="http://www.codecentric.de/namespace/weatherservice/datatypes" xmlns:xmime="http://www.w3.org/2005/05/xmlmime">
5      <ForecastRequest>
6        <ZIP>99425</ZIP>
7        <flagcolor>blackblue</flagcolor>
8        <productName>ForecastBasic</productName>
9        <ForecastCustomer>
10          <Age>67</Age>
11          <Contribution>500</Contribution>
12          <MethodOfPayment>Bitcoin</MethodOfPayment>
13        </ForecastCustomer>
14      </ForecastRequest>
15    </GetCityForecastByZIP>
16  </soap:Body>
17</soap:Envelope>

Elasticsearch, Logstash, Kibana – So loggt man SOAP-Messages in 2016

Als ich das erste Mal über die Möglichkeiten des ELK-Stacks (oder aktueller „Elastic-Stack“ ) der Firma elastic las, war ich sofort total begeistert. Und auch die zahlreichen Blogartikel zum Thema im codecentric Blog zeigen, dass ich damit nicht allein bin.

Eine Idee meines Kollegen Dennis Schulte brachte mich dann dazu, die Anforderungen an ein Monitoring von SOAP-Messages mit den Möglichkeiten des ELK-Stacks abbilden zu wollen. Denn wir hatten ja Eingangs schon festgestellt, dass das ausschließliche Logging in ein Logfile auf einem speziellen Server einer Serverfarm nicht das Gelbe vom Ei ist. Vor allem, wenn wir wirklich viele Server aufsetzen und zusätzlich auch noch einige Stages bestücken und betreuen müssen, bevor unsere SOAP-Endpoints dann produktiv gehen. Außerdem brauchen wir Auswertungsmechanismen, die uns das Bilden von Kennzahlen erlauben – idealerweise aufbereitet in hübschen Dashboards, die nicht nur Vollblutnerds verstehen. Außerdem wollen wir im Fehlerfall von dort aus auch mal bis auf die einzelne SOAP-Anfrage hinuntergehen können, um genau analysieren zu können, was vielleicht schief gelaufen ist.

Und natürlich gab es auch einen Treiber, der mir erst im Laufe des Schreibens dieses Artikels so richtig bewusst wurde. Viele Lösungen im Integrationsumfeld buhlen eben gerade mit ihren Auswertungsmöglichkeiten und Dashboards meist um Käufer teurer Suiten – versprechen dabei aber meiner Erfahrung nach meist Dinge, die sie in der Praxis nicht liefern können. Z.B. hat eine wirkliche Transparenz über alle ein- und ausgehenden Nachrichten meist massive Auswirkungen auf die Performance der Integrationsanwendungen – etwas, das wir auf jeden Fall vermeiden wollen. Oder die Freischaltung der hübschen Dashboards ist so teuer, dass unser ganzes Integrationsprojekt zu kippen droht. Als hätte man in solchen Projekten nicht schon genug Probleme… Der Einsatz einer Open-Source-Lösung hilft uns hier, sehr schnell im Projekt voran zu kommen. Haben wir den geplanten Erfolg, können wir immer noch auf Einkaufstour gehen – und uns automatische Benachrichtigungen, Security-Features, Support u.v.m. hinzukaufen.

Und zu guter Letzt hatte ich den Einsatz des Elastic-Stacks schon im ersten Teil der Serie angekündigt – nun will ich also mein Versprechen einlösen :). Und los geht´s.

Initiale ELK-Architektur

Es gibt unzählige Möglichkeiten, einen Elastic-Stack aufzusetzen. Der Suchserver Elasticsearch ist beispielweise voll auf Skalierung getrimmt – zieht man mehrere Instanzen im gleichen Netz hoch, finden und verbinden sich die Elasticsearch-Instanzen automatisch. Genauso kann die teilweise recht aufwändige Anlieferung von Logs nochmals über Queuing-Mechanismen gepuffert werden usw. Diese Möglichkeiten stehen für große ELK-Installationen bereit und wappnen uns gegen riesige Datenmengen.

Für unseren Use Case wollen wir allerdings mit einer möglichst schlanken ELK-Variante starten. Sie soll uns alles bieten, was wir benötigen und bei Bedarf erweiterbar sein. Wie man grundsätzlich Spring Boot Anwendungen und ELK zusammenbringt, haben meine Kollegen schon im blog oder im Softwerker Spezial zu Elasticsearch beschrieben. Wir nehmen dabei die für uns passende Variante und erweitern sie für die Anforderungen an eine SOAP-Message-Monitoring. Hier kommen wir auch um ein kleines Architekturbild nicht drum rum:

Unsere SOAP-Endpoints, die wir mit Hilfe eines embedded Webserver per Spring Boot und Apache CXF verfügbar machen, loggen nach den ersten Abschnitten dieses Artikels ihre SOAP-Messages (und auch alles andere) per slf4j und Logback. Eine einfache, aber effektive und mächtige Methode, um unsere Logs mundgerecht für unseren Elastic-Server aufzubereiten, ist die Verwendung des logstash-logback-encoders . Denn so ersparen wir uns die Installation und das Management von sogenannten Logshippern auf unseren SOAP-Servern.

Die Appender des logstash-logback-encoders liefern die als JSON aufbereiteten Logs an Logstash , das diese indiziert und in Elasticsearch „pumpt“. Sobald alle Logs in Elasticsearch liegen, können wir sie nach Belieben über die Web-GUI Kibana durchsuchen und die Ergebnisse visualisieren. Optional biegt ein Nginx den Port von Kibana auf die Enterprise-Firewall-freundliche Zahl 80 um.

Ok. Das klingt nach Raketentechnik?! Ist aber keine, wir machen das jetzt einfach mal anhand unseres Beispielprojektes. Dazu gibt es wie gewohnt ein neues Projekt step8_logging_into_elasticstack in unserem GitHub-Repository .

Konfiguration des logstash-logback-encoders

Beginnen wir mit der Konfiguration des logstash-logback-encoders. Dieser enthält Encoder, die die Logs aufbereiten und ihre Bestandteile in Fields innerhalb von Logevents füllen (also Key-Value bzw. JSON). Die Standard Fields enthalten schon ein gutes „Startpaket“ für die spätere Loganalyse in unserem ELK-Server.

Bevor wir jedoch an die Konfiguration gehen, sollten wir in unserer Anwendung die pom.xml um die Abhängigkeit zum logstash-logback-encoder erweitern:

1<!-- Logging with ELK -->
2<dependency>
3  <groupId>net.logstash.logback</groupId>
4  <artifactId>logstash-logback-encoder</artifactId>
5  <version>4.6</version>
6  <!-- Exclude older version of logback-core for conflicting with newer in spring-boot,
7  see https://github.com/logstash/logstash-logback-encoder/issues/153 -->
8  <exclusions>
9    <exclusion>
10      <artifactId>logback-core</artifactId>
11      <groupId>ch.qos.logback</groupId>
12    </exclusion>
13  </exclusions>
14</dependency>

Dabei empfiehlt es sich, die inkludierte Abhängigkeit zu Logback herauszunehmen, da Spring Boot eine eigene Version mitbringt. Leider gibt es an dieser Stelle neben dem Issue 153 noch ein paar weitere Probleme im Zusammenspiel zwischen Spring Boot, logstash-logback-endocder und Logback zu beachten. Der Einfachheit halber würde ich empfehlen, vorerst bei der Spring-Boot-Version 1.3.3.RELEASE zu bleiben. Sonst läuft man in das Issue 160 , dass eigentlich auf einen Fehler in Logback 1.1.7 zurückzuführen ist, der allerdings erst in Version 1.1.8 behoben ist – die leider zum Zeitpunkt des Schreibens dieses Artikels noch nicht released und somit auch noch nicht in Spring Boot eingebunden ist. Hoffentlich passen die Releases von Spring Boot 1.4.0 und Logback 1.1.8 terminlich zusammen, dann löst sich das Problem in Luft auf. Wer es gar nicht abwarten will, kann versuchen, die Spring-Boot-Logback-Version im Maven tag properties zu überschreiben (empfehlen würde ich es aber nicht):

1<logback.version>1.1.6</logback.version>

1<?xml version="1.0" encoding="UTF-8"?>
2<configuration>
3    <include resource="org/springframework/boot/logging/logback/base.xml"/>
4    <logger name="org.springframework" level="WARN"/>
5    <logger name="de.jonashackt.tutorial" level="DEBUG"/>
6    <logger name="org.apache.cxf" level="INFO"/>
7 
8    <!-- Logstash-Configuration -->
9    <appender name="logstash" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
10        <destination>192.168.99.100:5000</destination>
11        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
12            <customFields>{"service_name":"WeatherService 1.0"}</customFields>
13            <fieldNames>
14                <message>log_msg</message>
15            </fieldNames>
16        </encoder>
17        <keepAliveDuration>5 minutes</keepAliveDuration>
18    </appender>
19 
20  <root level="INFO">
21        <appender-ref ref="logstash" />
22  </root>
23</configuration>

In unserem Beispiel setzen wir auf den LogstashTcpSocketAppender – einen der vielen möglichen Appender-Varianten . Als nächster Schritt ist hier z.B. der alternative Einsatz eines Async Appenders denkbar – eine Möglichkeit, um das Schreiben der Logs noch weiter von unseren produktiven Webservice-Calls zu entkoppeln. Einen ähnlichen Effekt würde man mit einer zwischengeschalteten Redis erreichen.

Doch in den meisten Fällen wird unser LogstashTcpSocketAppender ausreichen, denn auch er wird niemals einen loggenden Thread blockieren. Intern arbeiten die TcpAppender nämlich schon asynchron und nutzen dabei den LMAX Disruptor RingBuffer . Im unwahrscheinlichen Fall, dass dieser RingBuffer überläuft, werden die Logevents einfach verworfen, um einen Systemcrash zu vermeiden. Aber für solche Extremsituationen bieten sich dann die genannten alternativen Varianten an. In jedem Fall vermeiden wir, dass unser Logging Auswirkungen auf die Performance unserer SOAP-Endpoints hat und erreichen trotzdem vollständige Transparenz über alle ein- und ausgehenden Nachrichten. Somit sind wir sogar den teuren Integrationssuiten einen Schritt voraus.

Dem LogstashTcpSocketAppender übergeben wir in unseren logback-spring.xml in der destination die IP unseres Elastic-Servers und den Port unserer Logstash-Instanz darauf. Dem LogstashEncoder bringen wir zwei Field-Definitionen bei. Zuerst konfigurieren wir ein Custom Field mit dem Namen unseres SOAP-Webservices. Dieses Field ist später in Kibana auswertbar. Außerdem biegen wir das Standard Field mit dem Namen message auf log_msg um – das muss man nicht machen, erleichtert aber später die Identifikation in Kibana.

Zuletzt konfigurieren wir noch einen keepAlive alle 5 Minuten, um die Verbindung zwischen unseren SOAP-Servern und dem Elastic-Server noch ein wenig zusätzliche Haltbarkeit zu spendieren.

Aufsetzen unseres ELK-Servers & Konfiguration von logstash

Wie gesagt gibt es sehr viele Möglichkeiten, einen Elastic-Server aufzusetzen. Wir bedienen uns auch hier eines möglichst einfachen Setups. Und noch einfacher, als ein GitHub Repository zu klonen und im root-Verzeichnis docker-compose up aufzurufen, geht es wohl nicht. Einzige Voraussetzung ist eine lauffähige Docker-Installation nebst Docker Compose . Auf dem Mac hat brew beides verfügbar. Vielen Dank an dieser Stelle an deviantony für das genial einfache ELK-Setup.

Bevor wir jedoch der Versuchung nachgeben, unseren Elastic-Server sofort hochzufahren, sollten wir noch Logstash konfigurieren. Ein Beispiel liegt in besagtem Github Repository im Ordner logstash/config/logstash.conf. Der im Repository verwendete mutate-Filter kann hier erstmal ignoriert werden:

1input {
2  tcp {
3    port => 5000
4  }
5}
6 
7filter {
8  ### getting all fields that where extracted from logstash-logback-plugin
9  json {
10    source => "message"
11  }
12  ### filter out keep-alive-messages, that have no valid JSON-format and produce _jsonparsefailure in tags
13  if "_jsonparsefailure" in [tags] {
14      drop { }
15  }
16}
17 
18output {
19  elasticsearch {
20      hosts => "elasticsearch:9200"
21  }
22}

Logstash-Konfigurationen bestehen immer aus den gleichen drei Blöcken – input, filter und output (eine schöne Analogie zum EVA-Prinzip 🙂 ). Im input-Block konfigurieren wir unseren Eingangskanal. Im konkreten Fall also das Input-Plugin tcp – eines von vielen möglichen Input-Plugins .

Im filter-Block verwenden wir eines der ebenfalls zahlreichen Filter-Plugins . Das json Filter-Plugin extrahiert die vom logstash-logback-encoder gefüllten Fields in Logstash-Datenstrukturen, so wie sie danach in Elasticsearch landen. Da wir keepAlive im logstash-logback-encoder konfiguriert haben, sollten wir im zweiten Schritt innerhalb unseres filter-Blocks die keep-alive-Messages wieder ausfiltern, sonst landen hässliche Events mit „_jsonparsefailure“ in unserer Kibana-Auswertung.

Zuletzt konfigurieren wir im output-Block das Ziel – unseren Suchserver Elasticsearch – und übergeben dessen Port innerhalb unseres Elastic-Servers. Nun sind wir endlich soweit und erwecken unseren Elastic-Server per docker-compose up zum Leben.

Loslegen mit der Loganalyse in Kibana

Nach allerhand Bildschirm-Aktivität in unserer Console ist unser Elastic-Server irgendwann komplett hochgefahren und die Komponenten Logstash, Elasticsearch und Kibana laufen. Je nach dem, welche IP der eigene Docker-Host hat und ob man diese evtl. elegant hinter einem Alias versteckt hat, sieht die URL für den Zugriff auf Kibana unterschiedlich aus. Wir gehen hier wieder von einem ganz simplen Szenario aus: Unser Docker-Host hat die IP 192.168.99.100 und damit ergibt sich für unser Kibana in etwa folgende URL: http://192.168.99.100:5601/app/kibana . Der Port wird in der docker-compose.yml unseres ELK-Setups festgelegt. Rufen wir die URL das erste Mal auf, sehen wir in etwa Folgendes in unserem Browser:

Damit läuft unser Elastic-Server. Als nächstes sollten wir unter Settings/Indices ein Index-Pattern anlegen – die praktische Vorbelegung mit logstash-* nehmen wir gerne mit und klicken direkt auf Create – daraufhin zeigt Kibana eine ganze Reihe von Fields an:

Nun wollen wir endlich ein paar Einträge produzieren und damit evaluieren, ob unsere „Initiale ELK-Architektur“ auch praktisch funktioniert. Dazu starten wir am besten einen Single System Integration Test (siehe Part 2 des Tutorials ) wie den WeatherServiceSystemTest – der nimmt uns alle Denkarbeit ab und wir können uns auf die Analyse in Kibana stürzen. Und siehe da – gehen wir zurück auf Discover, sehen wir unsere Logeinträge:

Über die add Buttons neben den indizierten Fields können wir die Fields als Spaltenüberschriften in der Discovery-Ansicht konfigurieren. Beispielsweise ist unser Custom-Field service_name und der Output des jeweiligen Logevents in log_msg interessant. Die Zeit führt die Spalte als Time sowieso immer an:

Und voilá. Schon loggt unser SOAP-Server auf Basis von Spring Boot und Apache CXF in einen Elastic-Server. Spätestens jetzt wird wohl bei einigen Lesern der Spieltrieb geweckt worden sein, denn man kann jetzt richtig viel mit den Daten mit Hilfe von Auswertungen und Visualisierungen anstellen. Außerdem kann man alles in für das eigene Projekt Marketing-reife Dashboards packen.

Und wenn man es ausreizen will, kann man die Daten, die in unseren Elastic-Server hineinlaufen, natürlich nochmals verbessern. Zum Beispiel könnte man die SOAP-Messages in eigene Fields packen, um sie später besser auswerten zu können. Außerdem wollen wir wissen, welche Logeinträge zu einem bestimmten SOAP-Request gehören (Log-Korrelation).

Eigentlich könnten wir das auch noch schnell bauen – jetzt kommt auch beim Autor der Spieltrieb durch 🙂

SOAP Messages in eigene Elasticsearch Fields loggen

Für die Beantwortung all der Fragen aus der Fachabteilung lohnt sich das Anlegen eigener Custom Fields für die Inbound- und die Outbound SOAP-Messages. Denn eine Auswertung gezielt auf ein Elasticsearch Field geht später in Kibana viel leichter von der Hand bzw. wird überhaupt erst vernünftig möglich. Dazu brauchen wir ein Konzept, wie wir die SOAP-Messages, die Apache CXF für uns loggt, irgendwie Richtung Elasticsearch bekommen.

Hier gibt es natürlich wieder eine große Anzahl an möglichen Herangehensweisen. Aber es gibt eine einfach anzuwendende, gleichzeitig aber äußerst mächtige Lösung. Und die Eleganz des Konzepts löst schon mal Begeisterung aus: Wir verwenden den Mapped Diagnostics Context – kurz MDC. Als Teil der slf4j-API wird er von Logback implementiert und geht auf das Buch Patterns for Logging Diagnostic Messages in Pattern Languages of Program Design von R. Martin, D. Riehle und F. Buschmann zurück. Doch das müssen wir nicht unbedingt komplett lesen. Denn im Grunde ist der Logback MDC eine Art Map, in die wir zum Zeitpunkt der Log-Schreibung unsere Log-Message mitsamt einem passendem Key packen. Der logstash-logback-encoder macht praktischer Weise am Ende aus jedem MDC-Eintrag ein Field im Logevent. Und diese Fields landen dann durch alle Zwischenstationen hindurch 1:1 in einem Elasticsearch Field. Und das auch noch dazu passend für mehrere parallele SOAP-Requests, die über entsprechende Threads abgearbeitet werden. Unsere einzige Sorge bleibt also, wie man die SOAP-Messages in ein MDC-Field schreibt. Denn wie wir in das Logging der SOAP-Messages von Apache CXF eingreifen, haben wir ja schon im Abschnitt Die Logausgabe der SOAP Messages anpassen gelernt.

Also Ärmel hoch und los! Wieder findet sich alles in einem eigenen Projekt in unserem GitHub Repository . Wir passen die Interceptors aus dem step7_soap_message_logging_payload_only an und benennen sie zuerst einmal passend um: SoapMsgToMdcExtractionLoggingInInterceptor.java und SoapMsgToMdcExtractionLoggingOutInterceptor.java . Statt die SOAP-Messages direkt zu loggen, schreiben wir sie mit Hilfe der Methode net.logstash.logback.marker.Markers.append des logstash-logback-encoders direkt in den MDC. Dazu müssen wir uns freilich vorher einen org.slf4j.Logger initialisieren:

1import org.apache.cxf.interceptor.LoggingInInterceptor;
2import org.apache.cxf.interceptor.LoggingMessage;
3import org.slf4j.Logger;
4import org.slf4j.LoggerFactory;
5import static net.logstash.logback.marker.Markers.append;
6 
7public class SoapMsgToMdcExtractionLoggingInInterceptor extends LoggingInInterceptor {
8 
9    private static final Logger LOG = LoggerFactory.getLogger(SoapMsgToMdcExtractionLoggingInInterceptor.class);
10    private static final String SOAP_MESSAGE_INBOUND = "soap-message-inbound";
11 
12    @Override
13    protected void log(java.util.logging.Logger logger, String message) {
14        // just do nothing, because we don´t want CXF-Implementation to log,
15        // we just want to Push the SOAP-Message to Logback -> Logstash -> Elasticsearch -> Kibana
16    }
17 
18    @Override
19    protected String formatLoggingMessage(LoggingMessage loggingMessage) {
20        if (loggingMessage.getPayload().length() > 0) {
21            LOG.info(append(SOAP_MESSAGE_INBOUND, loggingMessage.getPayload().toString()), "Log Inbound-SoapMessage to Elasticseach");
22        }
23        return "";
24    }
25}

1soap-message-inbound: "*<MethodOfPayment>Bitcoin</MethodOfPayment>*"

Auf diese Art würden wir alle eingehenden SOAP-Messages finden, die die Zahlungsmethode Bitcoin verwenden. Und auf diesem Ergebnis lässt sich dann wieder aufbauen. Man könnte z.B. zählen und in Relation zur Zeit setzen… Oder, oder, oder. Hier sind einem kaum Grenzen gesetzt. Aufpassen sollte man in diesem Zusammenhang nur mit SOAP-Nachrichten, die sehr groß werden – z.B. weil sie mehrere PDFs base64-kodiert enthalten. Dann kann es sinnvoll sein, die Nachrichten vor der Übergabe in Elasticsearch zu kürzen – z.B. per grok-filter .

Korrelation aller Log-Events eines SOAP-Requests

Bleibt eine zweite wichtige Frage: Welche Logmessages gehören eigentlich zu einem bestimmten SOAP-Request? In unserem Beispielprojekt sind es ja doch meist wir selbst, die einfach einen Test starten und damit einen Request innerhalb einer überschaubaren Zeitspanne absetzen. Dadurch sind die in Kibana sichtbaren Logeinträge meist noch chronologisch geordnet. Die Situation wird aber spätestens eine andere sein, wenn unser SOAP-Endpoint produktiv deployed ist und genutzt wird. Denn dann schicken mehrere User oder Systeme parallel ihre Requests ab und wir können nicht mehr zweifelsfrei sagen, welche Logeinträge eigentlich zusammengehören. Und wenn dann auch noch mehrere SOAP Server in unseren Elastic-Server loggen, ist die chronologische Reihenfolge auf jeden Fall dahin.

Wir bräuchten eine Art Request-Id, auf die wir in Kibana filtern könnten. Auch hier hilft uns das Konzept des MDC wieder enorm. Denn neben den genannten Vorteilen, hält er seine Informationen pro Thread – und zwar pro Request-Thread. Ein UUID wäre hier ein geeigneter Kandidat. Wichtig ist für unseren Use Case bei der Nutzung des MDCs nur eines: Wir müssen zum Start eines Requests immer einen neuen UUID generieren und ihn zum Ende wieder aus dem MDC entfernen, sodass sichergestellt ist, dass er nie wieder verwendet wird. Denn wenn ein Thread stirbt, erlaubt der MDC das Wiederverwenden von Feldinhalten in anderen Threads.

Da wir gleichzeitig jedes erdenkliche Logevent mitbekommen wollen – egal, ob es in unserer fachlichen Implementierung oder in Apache CXF auftritt – müssen wir natürlich mit dem Schreiben in den MDC so früh wie möglich ansetzen. Hier hilft es sich klar zu machen, dass Apache CXF ein Servlet nach der Servlet Specification nutzt. Ein Servlet Filter hängt sich dabei direkt vor und direkt nach jeden Request, der von einem Servlet abgearbeitet wird.

Das passt für unseren Fall ideal. Ein Servlet Filter bekommt wirklich jeden SOAP-Request mit und die (korrekte) Nutzung des MDCs garantiert die Eindeutigkeit der IDs sowie die korrekte Weitergabe an Elasticsearch. Sozusagen ein Dream Team. Und das wollen wir jetzt auch implementieren. Unser Projekt step9_soap_message_logging_into_custom_elasticsearch_field enthält bereits eine Implementierung :

1import org.slf4j.MDC;
2import javax.servlet.*;
3import java.io.IOException;
4import java.util.UUID;
5 
6public class LogCorrelationFilter implements Filter {
7    private static final String SERVICE_CALL_ID_KEY = "service-call-id";
8 
9    @Override
10    public void init(FilterConfig filterConfig) throws ServletException {}
11 
12    @Override
13    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
14        MDC.put(SERVICE_CALL_ID_KEY, UUID.randomUUID().toString());
15        try {
16            chain.doFilter(request, response);
17        } finally {
18            MDC.remove(SERVICE_CALL_ID_KEY);
19        }       
20    }
21 
22    @Override
23    public void destroy() {}
24}

Wir leiten unsere Klasse von javax.servlet.Filter ab und überschreiben alle notwendigen Methoden. Dabei interessiert uns aber nur die doFilter(ServletRequest request, ServletResponse response, FilterChain chain). In ihr generieren wir ein UUID und packen diesen mit samt dem Key service-call-id in den org.slf4j.MDC. Danach folgt per chain.doFilter(request, response) der Aufruf des Apache CXF Servlets, in dem die gesamte Verarbeitung unseres SOAP-Requests abläuft. Schließlich entfernen wir im finally Block wieder den UUID aus dem MDC, um eine Wiederverwendung zu vermeiden. Fertig ist unser Servlet Filter. Nun muss er nur noch konfiguriert werden. Dazu initialisieren wir eine neue Spring Bean in unserer WebServiceConfiguration.java :

1@Bean
2public Filter filter() {
3    return new LogCorrelationFilter();
4}

Das sollte es auch schon gewesen sein. Wir starten also wieder unseren WeatherServiceSystemTest und das neue Elasticsearch Field service-call-id taucht danach in unserer Discorvery-Ansicht in Kibana auf. Für Testzwecke starten wir unseren Test einfach gleich ein paar mal mehr oder starten unsere SimpleBootCxfApplication.java und beschießen unseren Endpunkt mit einem Load Test mit mehreren parallelen Threads in SoapUI . So können wir ein paar mehr valide Testdaten erzeugen und nach Belieben auf eine bestimmte service-call-id eines Logeintrags filtern. Dazu einen Logeintrag in der Discovery-Ansicht aufklappen und auf das kleine Lupen-Symbol mit dem Plus-Zeichen hinter dem Field service-call-id klicken:

Das Ergebnis lässt sich sehen. Alle zu einem SOAP-Request gehörenden Logeinträge werden uns angezeigt – egal, mit wie vielen parallelen Requests unser SOAP-Endpoint traktiert wurde:

Nun haben wir praktisch alle initialen Anforderungen an Logging & Monitoring unserer SOAP-Endpoints erfüllt. Alle genutzen Frameworks verwenden slf4j und Logback fürs Logging. Wir wissen ab jetzt genau, welche SOAP-Messages über die Leitung gehen und können unseren Service-Consumern im Projekt vernünftig bei der Implementierung helfen. Nebenbei erkennen wir eigene Fehler in unserer Implementierung wesentlich schneller – und das natürlich alles für eine nahezu unbegrenzte Anzahl von SOAP-Servern auf Basis von Spring Boot und Apache CXF. Also müssen wir uns nicht mehr mühsehlig durch einzelne Logfiles auf unseren Microservice-artigen SOAP-Endpoints quälen und verkürzen damit die Zeit massiv, bis wir einen Fehler gefunden haben.

Zusätzlich wissen wir auch bei vielen parallelen Requests noch, welche Logeinträge zu einem bestimmten SOAP-Request gehören. Und durch Bestücken dedizierter Elasticsearch Fields mit den SOAP-Messages sind wir super auf die Fragen aus der Fachabteilung vorbereitet. Für jede Anfrage können wir eine passende Visualisierung konfigurieren und daraus am Ende wunderschöne Dashboards zusammenstellen – dazu gibt es eine Vielzahl an Tutorials im Netz, wie z.B. auf elastic.co .

Und schließlich stechen wir die Anbieter der großen Integrationssuiten aus – wir loggen alles ohne Performanceeinbußen und verpassen trotzdem keine Nachrichten. Da wir dann noch nahezu jede Frage mit einer eigenen Visualisierung abbilden können, haben wir eine nahezu perfekte Monitoring-Lösung für SOAP-Webservices auf Basis aktuellster Technologien.

Mit diesem Artikel haben wir viele Fragen aus dem ersten Teil der Blogserie beantworten können. Trotzdem wird es sicher noch eine Fortsetzung geben. Mindestens ein Thema steht dabei schon in den Startlöchern: Wir können alle Ideen jedes bisherigen Artikels nochmals bündeln und für alle unsere SOAP-Endpoints verfügbar machen… Aber ich will noch nicht zu viel verraten.