10 Tips for Proper application Logging

onze nieuwste JCP-partner, Tomasz Nurkiewicz, heeft een aantal berichten ingediend waarin de basisprincipes van de juiste application logging worden beschreven. Ik vond ze heel interessant, dus heb ik besloten om ze samen te voegen in een meer compacte formaat en presenteren ze aan u. Dus, hier zijn zijn suggesties voor schone en nuttige logs: (opmerking: De oorspronkelijke berichten zijn enigszins aangepast om de leesbaarheid te verbeteren)

1) Gebruik de juiste tools voor de taak

veel programmeurs lijken te vergeten hoe belangrijk het is om het gedrag van een toepassing en zijn huidige activiteit te loggen. Als iemand:

log.info("Happy and carefree logging");

gelukkig ergens in de code realiseert hij zich waarschijnlijk niet het belang van applicatielogs tijdens onderhoud, tuning en foutidentificatie. Het onderschatten van de waarde van goede logs is een vreselijke fout.

naar mijn mening, SLF4J is de beste logging API beschikbaar, vooral vanwege een grote patroon substitutie ondersteuning:

log.debug("Found {} records matching filter: '{}'", records, filter); 

in Log4j zou je moeten gebruiken:

log.debug("Found " + records + " records matching filter: '" + filter + "'");

Dit is niet alleen langer en minder leesbaar, maar ook inefficiënt vanwege het uitgebreide gebruik van string concatenation. SLF4J voegt een mooie {} substitutie functie. Ook, omdat string aaneenschakeling wordt vermeden en toString() niet wordt aangeroepen als het logging statement wordt gefilterd, is isDebugEnabled() niet meer nodig. BTW, heb je gemerkt enkele citaten rond filter string parameter?

SLF4J is slechts een gevel. Als een implementatie zou ik het Logback framework aanbevelen, al geadverteerd, in plaats van de gevestigde Log4J. het heeft veel interessante functies en, in tegenstelling tot Log4J, is actief ontwikkeld.

Het Laatste hulpmiddel om aan te bevelen is Perf4J. om hun motto te citeren:

Perf4J is to System.currentTimeMillis () als log4j is systeem.uit.println ()

Ik heb Perf4J toegevoegd aan een bestaande toepassing onder zware belasting en zag het in werking in enkele andere. Zowel beheerders als zakelijke gebruikers waren onder de indruk van de mooie grafieken geproduceerd door dit eenvoudige hulpprogramma. Ook konden we in een mum van tijd prestatiefouten ontdekken. Perf4J zelf verdient een eigen artikel, maar voor nu gewoon check hun Developer Guide.

bovendien, merk op dat Ceki Gülcü (oprichter van de Log4J, SLF4J en Logback projecten) een eenvoudige aanpak voorstelde om zich te ontdoen van commons-logging afhankelijkheid (zie zijn commentaar).

2) Vergeet niet, logging levels zijn er voor u

elke keer dat u een logging statement maakt, denkt u goed na welk logging level geschikt is voor dit type gebeurtenis, nietwaar? Op de een of andere manier besteedt 90% van de programmeurs nooit aandacht aan het loggen van niveaus, gewoon alles loggen op hetzelfde niveau, meestal INFO of DEBUG. Waarom? Logging frameworks hebben twee belangrijke voordelen ten opzichte van het systeem.uit., d.w.z. categorieën en niveaus. Beide kunt u selectief filteren logging statements permanent of alleen voor diagnostiek tijd. Als je echt het verschil niet kunt zien, print deze tabel en kijk ernaar elke keer dat u begint te typen “log.”in uw IDE:

fout-Er was iets vreselijk misgegaan, dat onmiddellijk moet worden onderzocht. Geen enkel systeem kan op dit niveau ingelogde items verdragen. Voorbeeld: NPE, database niet beschikbaar, bedrijfskritische use case kan niet worden voortgezet.

waarschuwen – het proces kan worden voortgezet, maar wees extra voorzichtig. Eigenlijk heb ik hier altijd al twee niveaus willen hebben: een voor voor de hand liggende problemen waar work-around bestaat (bijvoorbeeld: “Current data unavailable, using cache values”) en ten tweede (name it: ATTENTION) voor potentiële problemen en suggesties. Voorbeeld:” toepassing draait in de ontwikkelingsmodus “of”beheerconsole is niet beveiligd met een wachtwoord”. De toepassing kan waarschuwingsberichten tolereren, maar ze moeten altijd worden gerechtvaardigd en onderzocht.

INFO-belangrijk bedrijfsproces is voltooid. In ideale wereld, beheerder of gevorderde gebruiker moet in staat zijn om INFO berichten te begrijpen en snel erachter te komen wat de toepassing doet. Bijvoorbeeld als een applicatie is alles over het boeken van vliegtickets, moet er slechts één info statement per ticket te zeggen ” geboekt ticket van naar “. Andere definitie van INFO-bericht: elke actie die de status van de toepassing aanzienlijk verandert (database-update, extern systeemverzoek).

debug-ontwikkelaars dingen. Ik zal later bespreken wat voor soort informatie het verdient om te worden geregistreerd.

TRACE-zeer gedetailleerde informatie, alleen bestemd voor ontwikkeling. U kunt traceerberichten gedurende een korte periode bewaren na de implementatie in de productieomgeving, maar deze logstatements behandelen als Tijdelijk, die uiteindelijk moeten of kunnen worden uitgeschakeld. Het onderscheid tussen DEBUG en TRACE is het moeilijkst, maar als je logging statement plaatst en het verwijdert nadat de functie is ontwikkeld en getest, moet het waarschijnlijk op TRACE-niveau zijn.

de bovenstaande lijst is slechts een suggestie, U kunt uw eigen set instructies maken om te volgen, maar het is belangrijk om een aantal te hebben. Mijn ervaring is dat altijd alles wordt gelogd zonder te filteren (tenminste van de applicatie code), maar met de mogelijkheid om snel te filteren logs en extraheren van de informatie met de juiste detail niveau, kan een life-saver.

Het Laatste dat het vermelden waard is, is de infamous is*enabled() voorwaarde. Sommigen zetten het voor elk log statement:

if(log.isDebugEnabled()) log.debug("Place for your commercial");

persoonlijk vind ik dit idioom gewoon rommel die moet worden vermeden. De prestatieverbetering (vooral bij het gebruik van SLF4J patroon substitutie eerder besproken) lijkt irrelevant en ruikt naar een voortijdige optimalisatie. Kun je ook de duplicatie zien? Er zijn zeer zeldzame gevallen waarin het hebben van een expliciete voorwaarde gerechtvaardigd is-wanneer we kunnen bewijzen dat het maken van logboekberichten duur is. In andere situaties, doe gewoon je werk van logging en laat logging framework zijn werk doen (filteren).

3) weet u wat u registreert?

elke keer dat u een log statement uitgeeft, neem dan een moment en kijk wat er precies in uw logbestand komt. Lees uw logs achteraf en spot misvormde zinnen. Ten eerste, vermijd NPE ‘ s zoals deze:

log.debug("Processing request with id: {}", request.getId());

Weet je zeker dat het verzoek hier niet null is?

een andere valkuil is het loggen van collecties. Als u de verzameling van domeinobjecten uit de database hebt opgehaald met behulp van Hibernate en ze achteloos logt zoals hier:

log.debug("Returning users: {}", users);

SLF4J zal toString() alleen aanroepen als het statement daadwerkelijk is afgedrukt, wat best leuk is. Maar als het wel zo is… geheugenverlies fout, N + 1 Selecteer probleem, thread verhongering (loggen is synchroon!), luie initialisatie uitzondering, logs opslag volledig gevuld-elk van deze kunnen optreden.

het is een veel beter idee om bijvoorbeeld alleen id ‘ s van domeinobjecten te loggen (of zelfs alleen de grootte van de collectie). Maar het maken van een verzameling van ids bij het hebben van een verzameling van objecten met getId() methode is ongelooflijk moeilijk en omslachtig in Java. Groovy heeft een grote spread operator (gebruikers*. id), in Java kunnen We emuleren met behulp van de Commons Beanutils bibliotheek:

log.debug("Returning user ids: {}", collect(users, "id"));

waarbij de collect () – methode als volgt kan worden toegepast:

public static Collection collect(Collection collection, String propertyName) { return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));}

het laatste ding om te vermelden is de onjuiste implementatie of het gebruik van toString (). Maak eerst toString() aan voor elke klasse die ergens in logging statements voorkomt, bij voorkeur met ToStringBuilder (maar niet zijn reflecterende tegenhanger). Ten tweede, kijk uit voor arrays en niet-typische collecties. Arrays en sommige vreemde collecties hebben mogelijk niet toString() geïmplementeerd aanroep toString () van elk item. Gebruik Arrays # deepToString JDK utility methode. En lees uw logboeken vaak om verkeerd geformatteerde berichten te herkennen.

4) vermijd bijwerkingen

Logopmerkingen zouden geen of weinig invloed moeten hebben op het gedrag van de toepassing. Onlangs gaf een vriend van mij een voorbeeld van een systeem dat overwintert’ Lazy Initializationuitzondering alleen bij het draaien op een bepaalde omgeving gooide. Zoals je waarschijnlijk hebt geraden uit de context, sommige logging statement veroorzaakt lazy initialized collectie te worden geladen wanneer sessie werd bevestigd. Op deze omgeving werden de logging niveaus verhoogd en collectie werd niet meer geïnitialiseerd. Hoe lang zou het duren om een bug te vinden zonder deze context te kennen?

een andere bijwerking vertraagt de toepassing. Snel antwoord: als u te veel of onjuist gebruik toString() en/of string aaneenschakeling, loggen heeft een prestatie bijwerking. Hoe groot? Nou, ik heb gezien server herstarten elke 15 minuten als gevolg van een draad honger veroorzaakt door overmatige logging. Dit is een bijwerking. Uit mijn ervaring, enkele honderden MiB is waarschijnlijk de bovengrens van hoeveel je kunt inloggen op schijf per uur.

natuurlijk is dit ook een enorm neveneffect als logging statement zelf faalt en het bedrijfsproces door uitzondering beëindigt. Ik heb zo ‘ n constructie gezien om dit te vermijden.:

try { log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())} catch(NullPointerException e) {}

Dit is een echte code, maar maak de wereld een beetje beter plaats en doe het niet, nooit.

5) Wees beknopt en beschrijvend

elk logbestand moet zowel gegevens als een beschrijving bevatten. Bekijk de volgende voorbeelden:

log.debug("Message processed");log.debug(message.getJMSMessageID());log.debug("Message with id '{}' processed", message.getJMSMessageID());

welk logboek wilt u zien bij het diagnosticeren van een storing in een onbekende toepassing? Geloof me, alle bovenstaande voorbeelden zijn bijna even algemeen. Een ander anti-patroon:

if(message instanceof TextMessage) //...else log.warn("Unknown message type");

Was het zo moeilijk om u werkelijke berichttype, bericht-id, enz. in de waarschuwingsstring? Ik weet dat er iets mis is gegaan, maar wat? Wat was de context?

een derde anti-patroon is het “magic-log”. Real life voorbeeld: de meeste programmeurs in het team wisten dat 3 ampersands gevolgd door uitroepteken, gevolgd door hash, gevolgd door pseudorandom alfanumerieke string log betekent “bericht met XYZ id ontvangen”. Niemand nam de moeite om het logboek te veranderen, gewoon iemand raakte het toetsenbord en koos een aantal unieke “&&&!* “string, so that it can be easily found by himself.

als gevolg hiervan ziet het hele logbestand eruit als een willekeurige reeks tekens. Iemand zou dat bestand zelfs kunnen beschouwen als een geldig perl programma. In plaats daarvan moet een logbestand leesbaar, schoon en beschrijvend zijn. Gebruik geen magische getallen, log waarden, getallen, ID ‘ s en omvatten hun context. Toon de gegevens die worden verwerkt en Toon de betekenis ervan. Laat zien wat het programma eigenlijk doet. Goede logs kunnen dienen als een grote documentatie van de applicatie code zelf.

had ik al gezegd geen wachtwoorden en persoonlijke informatie te registreren? Niet doen!

6) Tune your pattern

Logging pattern is een prachtig hulpmiddel, dat op transparante wijze een betekenisvolle context toevoegt aan elk logging statement dat je maakt. Maar je moet goed overwegen welke informatie je in je patroon moet opnemen. Bijvoorbeeld, logging datum wanneer uw logs roll elk uur is zinloos als de datum is al opgenomen in de log bestandsnaam. Integendeel, zonder in te loggen van de thread naam zou je niet in staat zijn om een proces te volgen met behulp van logs wanneer twee threads gelijktijdig werken – de logs zullen overlappen. Dit kan prima zijn in toepassingen met één schroefdraad – die tegenwoordig bijna dood zijn.

uit mijn ervaring, zou het ideale logpatroon moeten bestaan uit (natuurlijk behalve het gelogde bericht zelf): huidige tijd (zonder datum, milliseconden precisie), loggen niveau, naam van de thread, eenvoudige logger naam (niet volledig gekwalificeerd) en het bericht. In Logback is het iets als:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level %m%n</pattern> </encoder></appender>

u moet nooit bestandsnaam, class-naam en regelnummer opnemen, hoewel het erg verleidelijk is. Ik heb zelfs lege log statements uit de code gezien:

log.info("");

omdat de programmeur aannam dat het regelnummer een deel van het logpatroon zal zijn en hij wist dat “als het lege logboekbericht verschijnt in de 67e regel van het bestand (in authenticate() methode), betekent dit dat de gebruiker geauthenticeerd is”. Bovendien, logging Klasse naam, methode naam en / of regelnummer heeft een ernstige impact op de prestaties.

een iets geavanceerdere eigenschap van een logboekraamwerk is het concept van een toegewezen diagnostische Context. MDC is gewoon een kaart beheerd op een thread-lokale basis. U kunt elk sleutel-waarde paar in deze kaart en sindsdien elk logging statement uitgegeven van deze thread gaat deze waarde toegevoegd als onderdeel van het patroon.

7) log methodeargumenten en retourneer waarden

wanneer u een bug vindt tijdens de ontwikkeling, voert u meestal een debugger uit die probeert de mogelijke oorzaak op te sporen. Stel je nu eens voor dat je geen debugger kunt gebruiken. Bijvoorbeeld, omdat de bug manifesteerde zich op een klantomgeving enkele dagen geleden en alles wat je hebt is logs. Zou je er iets in kunnen vinden?

als u de eenvoudige regel van het loggen van elke methode invoer en uitvoer (argumenten en return waarden) volgt, hebt u zelfs geen debugger meer nodig. Natuurlijk moet je redelijk zijn, maar elke methode die: toegang tot extern systeem (inclusief database), blokken, wacht, enz. moet worden overwogen. Volg gewoon dit patroon:

public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = //Lengthy printing operation log.debug("Leaving printDocument(): {}", id); return id;}

omdat u zowel het begin als het einde van de methode – aanroep registreert, kunt u handmatig inefficiënte code ontdekken en zelfs mogelijke oorzaken van deadlocks en uithongering detecteren-gewoon door te kijken naar “entering” zonder overeenkomstige “leaving”. Als uw methoden betekenisvolle namen hebben, zou het lezen van logs een genoegen zijn. Ook, analyseren wat er mis is gegaan is veel eenvoudiger, omdat op elke stap Weet je precies wat er is verwerkt. U kunt zelfs een eenvoudig AOP-aspect gebruiken om een breed scala aan methoden in uw code te loggen. Dit vermindert code duplicatie, maar wees voorzichtig, omdat het kan leiden tot enorme hoeveelheid enorme logs.

u moet DEBUG-of TRACE-niveaus beschouwen als het meest geschikt voor dit type logs. En als je ontdekt dat een bepaalde methode te vaak worden genoemd en logging kan schade toebrengen aan de prestaties, gewoon verlagen logging niveau voor die klasse of verwijder de log volledig (misschien het verlaten van slechts een voor de hele methode aanroep?) Maar het is altijd beter om te veel in plaats van te weinig logging statements. Behandel login statements met hetzelfde respect als unit tests-uw code moet worden behandeld met logging routines zoals het is met unit tests. Geen enkel deel van het systeem mag zonder logs blijven. Vergeet niet, soms observeren logs rollen door is de enige manier om te vertellen of uw toepassing goed werkt of hangt voor altijd.

8) Let op voor externe systemen

Dit is het speciale geval van de vorige tip: Als u communiceert met een extern systeem, overweeg dan om elk stukje data dat uit uw applicatie komt en binnenkomt te loggen. Periode. Integratie is een moeilijke taak en het diagnosticeren van problemen tussen twee toepassingen (denk aan twee verschillende leveranciers, omgevingen, technologiestacks en teams) is bijzonder moeilijk. Onlangs, bijvoorbeeld, hebben we ontdekt dat het loggen van volledige berichten inhoud, met inbegrip van SOAP en HTTP headers in Apache CXF web services is zeer nuttig tijdens de integratie en het testen van het systeem.

dit is een grote overhead en als de prestaties een probleem zijn, kunt u loggen altijd uitschakelen. Maar wat is het nut van het hebben van een snelle, maar gebroken applicatie, dat niemand kan repareren? Wees extra voorzichtig bij de integratie met externe systemen en bereid je voor om die kosten te betalen. Als je geluk hebt en al je integratie wordt afgehandeld door een ESB, dan is de bus waarschijnlijk de beste plek om elke inkomende aanvraag en reactie te loggen. Zie bijvoorbeeld Mules’ log-component.

soms is het door de hoeveelheid informatie die wordt uitgewisseld met externe systemen onaanvaardbaar om alles te loggen. Aan de andere kant willen we tijdens het testen en voor een korte periode tijdens de productie (bijvoorbeeld wanneer er iets mis is) alles graag in logs opslaan en zijn we klaar om prestatiekosten te betalen. Dit kan worden bereikt door zorgvuldig te loggen niveaus. Neem een kijkje op de volgende idioom:

Collection<Integer> requestIds = //...if(log.isDebugEnabled()) log.debug("Processing ids: {}", requestIds);else log.info("Processing ids size: {}", requestIds.size());

als deze specifieke logger is geconfigureerd om DEBUG-berichten te loggen, zal het de hele inhoud van de requestIds-collectie afdrukken. Maar als het is geconfigureerd om INFO-berichten af te drukken, wordt alleen de grootte van de collectie uitgevoerd. Als je je afvraagt waarom ik ben vergeten isInfoEnabled() voorwaarde, ga terug naar tip #2. Een ding het vermelden waard is dat requestIds collectie mag niet nul in dit geval. Hoewel het correct zal worden gelogd als null als DEBUG is ingeschakeld, maar big fat NullPointerException zal worden gegooid als logger is geconfigureerd om INFO. Herinner je je mijn les over bijwerkingen in tip # 4?

9) log uitzonderingen correct

ten eerste, vermijd log uitzonderingen, laat uw framework of container (wat het ook is) het voor u doen. Er is één, ekhem, uitzondering op deze regel: als je uitzonderingen gooit van een externe service (RMI, EJB remote session bean, enz.), die in staat is om serializing uitzonderingen, zorg ervoor dat ze allemaal beschikbaar zijn voor de client (zijn onderdeel van de API). Anders zal de client NoClassDefFoundError: SomeFancyException ontvangen in plaats van de” true ” fout.

logging exceptions is een van de belangrijkste rollen van logging, maar veel programmeurs hebben de neiging om logging te behandelen als een manier om met de uitzondering om te gaan. Ze retourneren soms de standaardwaarde (meestal null, 0 of lege tekenreeks) en doen alsof er niets is gebeurd. Andere keren loggen ze eerst de uitzondering in en wikkelen het dan in en gooien het terug:

log.error("IO exception", e);throw new MyCustomException(e);

deze constructie zal bijna altijd afdrukken dezelfde stack trace twee keer, omdat iets uiteindelijk zal vangen MyCustomException en log de oorzaak ervan. Log, of wrap en gooi terug (wat de voorkeur heeft), nooit beide, anders uw logs zal verwarrend zijn.

maar als we de uitzondering echt willen loggen? Om de een of andere reden (omdat we geen API ‘ s en documentatie lezen?), ongeveer de helft van de logging statements die ik zie zijn verkeerd. Quick quiz, welke van de volgende log statements zal de NPE correct loggen?

try { Integer x = null; ++x;} catch (Exception e) { log.error(e); //A log.error(e, e); //B log.error("" + e); //C log.error(e.toString()); //D log.error(e.getMessage()); //E log.error(null, e); //F log.error("", e); //G log.error("{}", e); //H log.error("{}", e.getMessage()); //I log.error("Error reading configuration file: " + e); //J log.error("Error reading configuration file: " + e.getMessage()); //K log.error("Error reading configuration file", e); //L}

verrassend genoeg zijn alleen G en bij voorkeur L correct! A en B compileren niet eens in SLF4J, anderen verwerpen stack sporen en / of printen onjuiste berichten. Bijvoorbeeld, E zal niets afdrukken als NPE meestal geen uitzondering bericht en de stack trace zal niet zo goed worden afgedrukt. Vergeet niet, het eerste argument is altijd het sms-bericht, schrijf iets over de aard van het probleem. Neem geen uitzondering bericht, omdat het automatisch wordt afgedrukt na de log statement, voorafgaand aan stack trace. Maar om dat te doen, moet je de uitzondering zelf als het tweede argument doorgeven.

10) Logs gemakkelijk te lezen, gemakkelijk te ontleden

er zijn twee groepen ontvangers die bijzonder geïnteresseerd zijn in uw applicatielogs: mensen (u bent het misschien niet eens, maar programmeurs behoren ook tot deze groep) en computers (meestal shell scripts geschreven door systeembeheerders). Logs moeten geschikt zijn voor beide groepen. Als iemand op zoek van achter je rug naar uw toepassing logs ziet (Bron Wikipedia):

dan heb je waarschijnlijk mijn tips niet gevolgd. Logs moeten leesbaar en gemakkelijk te begrijpen zijn, net als de code zou moeten zijn.

aan de andere kant, als uw applicatie half GB logs per uur produceert, zal geen man en geen grafische teksteditor er ooit in slagen om ze volledig te lezen. Hier komen old-school grep, sed en awk van pas. Als het mogelijk is, probeer dan logboekberichten zo te schrijven dat ze zowel door mensen als door computers kunnen worden begrepen, bijv. vermijd het formatteren van getallen, gebruik patronen die gemakkelijk kunnen worden herkend door reguliere expressies, enz. Als dit niet mogelijk is, drukt u de gegevens in twee formaten af:

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

Computers zullen waarderen “ms na 1970 epoch” tijdnotatie, terwijl mensen blij zou zijn te zien “1 dag 10 uur 17 minuten 36 seconden” Tekst. BTW neem een kijkje op DurationFormatUtils, leuk hulpmiddel.

That ‘ s all guys, een “logging tips extravaganza” van onze JCP partner, Tomasz Nurkiewicz. Vergeet niet te delen!

Gerelateerde Artikelen :
  • logging Antipatronen
  • dingen die elke programmeur zou moeten weten
  • wetten van softwareontwerp
  • Java Best Practices – Vector vs ArrayList vs HashSet
  • Java Best Practices – DateFormat in a Multithreading Environment
  • Java Best Practices – high performance serialisatie
  • Java Best Practices – String performance and Exact String Matching
  • gerelateerde fragmenten :
    • aangepaste opmaak maken voor Logger handler
    • log method call
    • filter instellen op Logger handler
    • Formatter instellen voor Logger handler
    • logging aspect voorbeeld
    • Log4j Maven voorbeeld
    • Hibernate Logging Configuration-SLF4J + Log4j and Logback