WSO2 11 minuten

Log4j2 vertelt je wat er zich afspeelt

Rob Blaauboer
Rob Blaauboer
Integration Consultant & WSO2 Trainer
Header LOG4J2
Scroll

Logbestanden vertellen je wat er achter de schermen gebeurt in de software die je runt. WSO2-producten, zoals Enterprise Integrator 6.6.0, maken gebruik van Log4j2 om de informatie die in de logbestanden gezet wordt te controleren. 

Log4j en Log4j2 zijn standaard kaders voor het loggen van applicatieberichten in Java. Als je Java-applicaties ontwikkelt, geef je standaard verschillende statements mee die informatie loggen op het niveau waarop de onderdelen zijn ingesteld. 

Log levels in Log4j2

De ingebouwde log levels voor Log4j2 zijn:

  1. OFF
  2. ALL
  3. FATAL
  4. ERROR
  5. WARN
  6. INFO
  7. DEBUG
  8. TRACE

Door een specifieke class in te stellen op een bepaald log level, zorg je ervoor dat het logging framework voor die specifieke class alle log statements tot dat niveau naar de logbestanden zal schrijven.

Op locaties die van belang zijn voor de system administrator kunnen er in de broncode statements geplaatst worden die informatie voor bepaalde niveaus versturen naar het logbestand. De Log4j2 configuratie controleert dan welke van deze log statements in de broncode daadwerkelijk naar de logbestanden geschreven worden. 

Log levels werken cumulatief, dus als je het instelt op TRACE zul je alle bovenliggende levels (DEBUG,INFO,WARN, …) ook krijgen. Als je het instelt op een ERROR level zul je echter NIET de lagere output-levels krijgen. Hierdoor krijg je een relatief precies instelbaar systeem om output log statements per class in te stellen. 

Het maakt niet uit of je de logs met een tekstverwerker bekijkt of een ELK Stack deployed, de logs vertellen je de waarheid. 

Voor als je niet (zo) bekend bent met logs, een kleine introductie. Bij het opstarten van de Enterprise Integrator via de opdrachtregel of via de terminal met het commando integrator.sh (of bat), komt er op de console een tekst in beeld. Dit is de output die vanuit het logging framework komt en we noemen dat de ‘console logs’. Op de schijf staat een blijvende vorm van de logs die je in console te zien krijgt in het bestand wso2-home/repository/logs/wso2carbon.log, die kun je zelfs inzien als je geen toegang hebt tot de console van waaruit de WSO2 Enterprise Integrator opgestart is.

LOG4J2 1

Zoals je kunt zien krijgen we heel veel INFO-berichten die we kunnen negeren, omdat het ons vertelt wat het programma doet. Maar we mogen niet ieder bericht negeren. ERROR-meldingen geven natuurlijk aan dat we tegen een probleem aangelopen zijn dat we wellicht moeten oplossen.

Log4j2-bestand

Het Log4j2-bestand is te vinden in de [EI-HOME]/conf map. Dit is een zogenaamde ‘hot file’, wat inhoudt dat je het effect van een verandering zult zien. Eerst door een bericht in de console over het feit dat het bestand is aangepast. En op het moment dat de bewuste Java-code uitgevoerd is, een bericht over de log mediators die van toepassing zijn. 

Hoe ziet dat bestand er dan uit?

Het begint met een lijst van ‘appenders’. Een ‘appender’ is verantwoordelijk voor het verzenden van log-berichten naar een bepaalde output bestemming. Deze bestemmingen zijn meestal logbestanden, maar kan ook de Linux syslog facility, een queue of een andere bestemming zijn die informatie kan ontvangen. 

In de Enterprise Integrator kunnen we een aantal van deze appenders zien staan die al ingesteld zijn.

LOG4J2 2

De eerste appender is de console. Zoals je ziet wordt de definitie van het output type voor de carbon console bepaald. Door bijvoorbeeld [%d] uit het layoutpatroon te halen, zal de datum niet meer in de output te zien zijn. Door het weer terug te zetten, zijn we weer terug bij de uitgangssituatie.

Veel appenders ondersteunen syntaxspecificaties in een logregel door patronen te gebruiken. Logs bevatten een aantal verschillende informatie onderdelen, waaronder de tijd waarop het log-statement uitgevoerd is, het log level van de logregel, de class die voor de uitvoer van de logregel zorgde en het bericht dat de class aan de logregel heeft toegevoegd. Door het patroon te gebruiken, kun je zelf bepalen welke elementen en in welke volgorde deze elementen in de log statements naar appender geschreven worden.

LOG4J2 3

Er zijn nog andere soorten appenders naast de ‘rolling file appender’ en de console, maar alleen deze twee worden in de Enterprise Integrator gebruikt. Als we kijken naar de configuratie, zien we een dagelijkse rollover van de carbon log en een beleid op basis van de grootte.

Het is aan te raden om naar deze instellingen te kijken, zodat ze voldoen aan jouw eisen. Als je de rollover parameters te strak zet, heeft dit tot gevolg dat het logbestand redelijk vaak een rollover heeft en daardoor wordt het opzoeken van informatie lastiger en tijdrovender. Als je het daarentegen te groot instelt, kan dit veroorzaken dat je logbestand te groot wordt voor de tools die je gebruikt en je het onhandelbaar voor je wordt.

LOG4J2 4

Iets onder de appenders vind je de loggers die gedefinieerd zijn als een lijst die je ook in de bovenstaande afbeelding kunt te zien. Een logger dient gedefinieerd te worden zoals in het voorbeeld dat je ziet voor org.apache.synapse en vervolgens in de lijst met loggers opgenomen te worden. Als het correct gedefinieerd is, zal de logger geactiveerd worden en kunnen er logberichten verschijnen wanneer die getriggerd worden.

Je eigen loggers toevoegen

Je kunt je eigen loggers aan deze lijst toevoegen door eenvoudig de Java class te specificeren die je wilt loggen. In Java zijn classes deel van een pakket. Een pakket bevat nul of meer classes. Pakketten worden gezien als hiërarchische objecten. Ze hebben dus een boomstructuur.

Je kunt een logger een classname meegeven, om heel specifiek te loggen, of een pakket om algemener te loggen. Vervolgens worden bij het specificeren van een logger de instellingen die voor die logger-configuratie gelden van toepassing op alle classes in hetzelfde pakket (en dus ook voor alle classes in sub-pakketten). Des te hoger de Java classes zijn, dus bijvoorbeeld org.apache.synapse, des te meer lagere classes hierdoor geraakt worden. Er zijn bijvoorbeeld loggers gedefinieerd zoals org.apache.synapse.mediators die alleen de mediators in de synapse triggert en dus niet de org.apache.synapse.transport.http.headers. 

Bij het creëren van een nieuwe logger moet je dus de class of het pakket aangeven dat je zou willen loggen, in dit geval org.yenlo.example. Dat doe je met de volgende drie regels.

logger.org-yenlo-example.name=org.yenlo.example
logger.org-yenlo-example.level=DEBUG
logger.org-yenlo-example.appenderRef.CARBON_LOGFILE.ref = CARBON_LOGFILE

Tot slot voegen we de logger aan de lijst met loggers toe. 

LOG4J2 5

Wanneer deze class nu gebruikt wordt, en ontworpen was met Log4j2 in gedachten, dan krijgen we berichten.

Laten we het log level voor een bepaalde class verhogen.

Spelen met Log4j2

We gaan in deze blog wat spelen met met het loggen. In Enterprise Integrator 6.6.0 wordt het loggen nu gedaan via het bestand Log4j2.properties en niet meer vanuit de Management console.

Waarschuwing: Pas op voor het productiesysteem bij het instellen van de log levels op een stand die gedetailleerder is dan INFO (dus DEBUG of TRACE), omdat de logs daardoor heel veel uitgebreider kunnen worden en dat invloed kan hebben de systeemprestaties. Afhankelijk van de server load zou de grootte van het logbestand op de schijf heel snel kunnen toenemen.

Het bestand Log4j2.properties kun je vinden in de [EI-HOME]/conf map. Gebruik een tekstverwerker om de wijzigingen aan te brengen.

In het algemeen is het handig om de volgende regels in het commentaar te zetten (of eruit te halen) en/of regels toe te voegen die er niet zijn. Stel ze in op INFO, omdat het DEBUG level ervoor zorgt dat ze gedetailleerde informatie gaan loggen over aanvragen en responses die de WSO2 Enterprise Integrator inkomen en uitgaan van en naar andere systemen. 

LOG4J2 6

Voeg nu deze loggers toe:

  • synapse-transport-http-headers
  • synapse-transport-http-wire
  • httpclient-wire-header
  • httpclient-wire-content

aan de logger lijst.

LOG4J2 7

Door deze regels te veranderen, zijn we in staat om ‘turn request’ en ‘response wire logging’ aan en uit te zetten. 

Laten we deze configuratiewijziging van de logger eens testen.

Start de WSO2 Enterprise Integrator als die nog niet runt. Maak een eenvoudige proxy die ‘test’ heet door de Management Console van de Enterprise Integrator te gebruiken met de volgende velden:

LOG4J2 8

Gebruik de ‘Try it’ functie van de Test Proxy om er een bericht naartoe te sturen.

LOG4J2 9

Bekijk de console output of het bestand wso2carbon.log om de informatie te zien die we ingesteld hebben om te laten loggen.

LOG4J2 10

Zet het log level van de logger.synapse-transport-http-wire, de logger.synapse-transport-http-headers en ook de logger.httpclient-wire-header en de logger.httpclient-wire-content terug naar het INFO level. Wacht even, zodat het logging framework de tijd heeft om je wijzigingen te detecteren en stuur dan nog een bericht naar de test-proxy.

Je zult zien dat de logberichten die te maken hebben met de http-transport en wire voor je tweede poging niet meer getoond worden.

Configuratie van het loggen

We veranderen het log level van de mediators om het effect te zien als er een bericht het systeem binnenkomt.

Laten we eerst een hele eenvoudige logging-echo proxy service creëren die één mediator heeft.

Ga naar het tabblad “Main” en klik op “Add proxy service”.

Dit is de broncode:

<?xml version="1.0" encoding="UTF-8"?>
LOG4J2 11
<proxy name="logProxy" startOnLoad="true" transports="https http" xmlns="http://ws.apache.org/ns/synapse">
    <target>
        
        <inSequence>
          <log>
             <property expression="$ctx:SYSTEM_DATE" name="timetest"/>
          </log>
          <respond/>
        </inSequence>
        <outSequence/>
        <faultSequence/>
    </target>
</proxy>

Kies voor “Custom proxy” als type en gebruik “logProxy” als “Proxy Service Name”.

Na het invullen van de naam klik je op “Switch to source view” en vervang je de body met de broncode die hierboven staat.

Klik op “Save” om het maken van de proxy af te ronden.

Klik nu op “Try this service” van de logProxy, zodat we wat gegevens naar de proxy kunnen sturen.

Geef een simpele bodytekst mee in het ‘Try-it’-scherm.

LOG4J2 12

Klik op “Send” om de proxy service aan te roepen. Houd dit browserscherm open, want je hebt het later nog nodig.

Als je nu de logs in de console of in het wso2carbon.log bestand bestudeert, zul je zien dat daar een LogMediator regel staat die aangeeft dat de proxy aangeroepen is.

INFO {org.apache.synapse.mediators.builtin.LogMediator} -  To: /services/logProxy.logProxyHttpSoap12Endpoint, WSAction: urn:mediate, SOAPAction: urn:mediate, MessageID: urn:uuid:0cf3cc3f-3bb9-49c7-b754-06534f185e47, Direction: request {org.apache.synapse.mediators.builtin.LogMediator}

Aanpassingen in Log4j2 maken

Open het Log4j2 bestand en voeg een nieuwe logger toe op de manier die ik je eerder al liet zien. Voeg daarbij deze regels toe:

logger.org-apache-synapse-mediators.name=org.apache.synapse.mediators
logger.org-apache-synapse-mediators.level=DEBUG
logger.org-apache-synapse-mediators.appenderRef.CARBON_LOGFILE.ref = CARBON_LOGFILE

En vergeet niet de logger in de lijst met loggers te zetten. Zoek het laatste element van de lijst op en voeg aan het eind ‘ , org-apache-synapse-mediators’ toe. Sla het bestand op. 

Roep nu opnieuw de try-it service aan voor de logProxy. Deze zou nog in je browser open moeten staan. Zo niet, ga dan terug naar de instructies over hoe je een try-it service opent.

Als je nu het logbestand bestudeert, zie je dat er meer details in de log output van de mediators zijn opgenomen.

Deze regel zou bijvoorbeeld zichtbaar moeten worden:

[2021-06-03 15:35:46,253] DEBUG {org.apache.synapse.mediators.builtin.LogMediator} - Start : Log mediator
[2021-06-03 15:35:46,254]  INFO {org.apache.synapse.mediators.builtin.LogMediator} - To: /services/logProxy.logProxyHttpSoap12Endpoint, WSAction: urn:mediate, SOAPAction: urn:mediate, MessageID: urn:uuid:43393d8a-f10f-4d2a-accf-fa6e5f8beea1, Direction: request, datetest = 6/3/21 3:35 PM
[2021-06-03 15:35:46,255] DEBUG {org.apache.synapse.mediators.builtin.LogMediator} - End : Log mediator

Zoals je ziet hebben we nu meer informatie over de LogMediator die we zojuist gebruikten. Om precies te zijn hebben we het van alle mediators, omdat we de logger op mediators ingesteld hebben in plaats van alleen op de LogMediator. Ik heb dat hier alleen niet zichtbaar gemaakt.

Conclusie

Door te loggen krijgen system administrators en ontwikkelaars inzicht in wat er zich binnen in een product afspeelt. Loggegevens over wat het product doet als er een bericht het systeem binnenkomt of logs die laten zien welke stappen er in de mediation flow genomen worden, zijn enorm waardevol voor probleemanalyses. 

Bij Yenlo hebben we verschillende benaderingen ontwikkeld voor hoe we het beste onze integraties kunnen loggen, zodat we altijd kunnen achterhalen hoe een bericht verwerkt is in de integratielaag als er iets fout is gegaan. 

Zonder correct te loggen is een product een blackbox waar we niet in kunnen kijken om te zien wat er gebeurt als er onverwacht fouten optreden. Gepast loggen kan een product veel transparanter maken in wat het doet en daarom is het dus altijd een goed idee om het loggen mee te ontwerpen in je integraties en het log framework precies naar jouw wensen te configureren.

Door tools zoals de ELK-stack te gebruiken, kun je jouw logs uit verschillende bronnen verzamelen in één log-search tool en dat is voor ons een hele sterke combinatie. Zo kunnen we bijvoorbeeld een dashboard bouwen op basis van zakelijke logs over verkopen in Kibana. Maar dat zou een onderwerp kunnen zijn voor een volgende blog.