Focus on your users and stakeholders. Dat is voor mij een belangrijke regel bij software ontwikkeling. En dat zijn niet alleen de eindgebruikers, maar ook degenen die onderhoud doen en de afdeling operations.
Voor de laatste groep is monitoring en configuratie erg belangrijk en voor beide de is goede logging van belang. Goede logging helpt bovendien het ontwikkelteam bij het oplossen van bugs en operationele problemen. Toch zie ik vaak dat logging, monitoring en configuratie een ondergeschoven kindje is.
Voorbeelden zijn log files waarin zoveel onzinnige informatie wordt geschreven dat de belangrijke en zinvolle meldingen ondergesneeuwd raken.
In principe maakt het niet veel uit welk logging framework gebruikt wordt als de basis maar gezond is. Naar mijn idee voldoet goede logging aan onder meer de volgende regels:
- in productie en acceptatie test omgevingen worden alleen de info, warnings, error en fatal categorieen geschreven in de log files
- fine en debug levels worden alleen geactiveerd als er een probleem is
- de log levels moeten dynamisch aan te passen zijn per software component in geval van problemen
- op info niveau worden meldingen gegeven van de hoofd processen die starten en eindigen, inclusief voldoende context informatie
- een “chain of actions” kunnen identificeren door een uniek id te loggen
- errors en fatal levels alleen gebruiken bij echte errors, en alle context informatie meegeven die voorhanden is; stacktrace, user id, waarde van input velden of method parameters, regel nummers en column van de input op moment van falen, relevante configuratie settings
- bij opstarten van componenten alle configuratie settings loggen
Als ik een software project uitvoer let ik bij systeem test en vooral bij acceptatie test op de log files. Kan je goed volgen wat er in grote lijnen gebeurt met de info logging? Staan er geen errors of fatals in die genegeerd worden? Staan er op info logging geen zaken die beter op fine of debug niveau thuis horen? Als er een error in de log staat, is dan direkt duidelijk wat er aan de hand is?
Als dit niet het geval is neem ik meteen aktie om het te verbeteren.
Wat ik merk is dat developers en operations veel meer vertrouwen krijgen in de software en dat problemen snel kunnen worden opgelost.
Neem de volgende twee voorbeelden van een log file snippet:
INFO connecting to remote system
INFO getting sales.xml file from system
INFO processing file
FATAL cannot read file contents: conversion error
[stacktrace]
INFO processing file
en vergelijk met de volgende versie:
INFO processId: 837468874 connecting with FTP to account@archive.backoffice.org:2121
INFO processId: 837468874 getting file 'outgoing/sales.20100909.xml'
INFO processId: 647837443 start parsing file 'sales.20100908.xml'
FATAL processId 647837443 cannot convert 'null' to integer. File: 'sales.20100908.xml' line: 2244 column: 156
[stacktrace]
INFO processId: 837468874 start parsing file 'sales.20100908.xml'
In de eerste stukje log is het niet duidelijk dat er eigenlijk twee threads lopen. De FATAL hoort niet bij de twee INFO log statements daarboven, zoals in het tweede voorbeeld wel duidelijk is door toevoeging van het processId.
Het zal de lezer duidelijk zijn wat de benodigde effort is om de bug op te lossen in het eerste geval en het tweede geval. En de winst in effort is niet alleen in productie te incasseren, maar ook op alle test omgevingen.
Voor software ontwikkelaars is het een een kwestie van even stilstaan bij het schrijven van logger.log(…) statements. Het kan veel tijd en kosten besparen.
Leave Your Response