Når først et softwareprojekt er released og kører ude hos kunderne, så er der ikke ret mange andre muligheder for fejlfinding og support end at kigge i log-filerne for at løse eventuelle problemer med softwaren. Men det kan ofte være svært for kunderne/slutbrugerne at forstå log-beskederne. Enten er der for mange log-beskeder eller for få. Log-beskeder fortæller ikke altid præcis hvad der er sket og hvad årsagen til fejlen er. Teksten kan ofte være uforståelig for slutbrugerne, fordi teksten er ment til brug for udviklerne.
Når et softwareprojekt sættes i gang bør man få tænkt en logging-strategi på plads, således at logging ikke blot bliver en sideeffekt af udviklingsarbejdet. Hvis man har en logging-strategi fra start, så bliver det nemmere at vedligeholde koden, som håndterer logning, når fx nye funktionaliteter skal implementeres og systemet skal udvides.
Med en logging-strategi bliver det også mere overskueligt hvilke typer fejlscenarier, der skal logges på hvilke niveauer. I et team er der med sikkerhed mange forskellige slags holdninger til hvad der skal logges hvornår og på hvilket nivau. Derfor er det en god idé at få diskuteret hvad den fælles strategi er for teamet fremover, for at undgå at dele af koden ikke afspejler hver enkelt udviklers personlige præferencer mht. logging (hvilket i sidste ende ville resultere i en meget forvirrende oplevelse hos slutbrugerne).
Man kan sagtens snakke om logging-strategier uden at tænke på et konkret programmeringssprog. Når man har den samme logging-strategi fx i hele virksomheden, så kommer de forskellige produkter (uanset hvilket programmeringssprog de er skrevet i) til at se mere ens ud, hvilket altid er at efterstræbe.
Tidsstempler i log-beskeder
En log-besked indeholder
typisk et tidsstempel. Der findes mange forskellige måder at skrive dato og årstal på, og derfor er det vigtigt at vælge én og kun én måde at skrive tidsstempler på i log-beskederne for alle projekter og produkter der arbejdes på – for igen at få mere ensartethed på tværs af projekter.
Der findes faktisk en ISO standard mht. repræsentation af dato og tid med henblik på at udveksle dato og tids-relateret data, nemlig ISO 8601. Et billede siger mere end 1000 ord, så derfor dette billede (som en af mine kollegaer har fundet frem) fra xkcd.com
Hvor ofte skal man logge?
Alt for ofte logger udviklere alt for meget info alt for ofte – dvs. så snart der er mulighed for det. Eller også logges der alt for sjældent. Mere logning i koden giver i sidste ende mere kode – hvilket ikke er godt både for overskuelighedens skyld (log-linjer er flettet sammen med business logic), og pga. performance og af pladshensyn. Logging er ikke altid særligt effektivt, og brugen af logging frameworks bruger mere af et programs udførselstid end man regner med. Så derfor er det vigtigt at få tænkt dette med når man lægger en logging-strategi.
Et andet spørgsmål man kan stille sig selv: Skal man i øvrigt overhovedet have en log-fil, som er gemt væk et sted og måske aldrig kigget i? Hvorfor ikke vise kritiske fejl i selve applikationen i stedet? På den anden side er formålet med log-filer netop at man kan gå tilbage og se hvilken fejl der opstod på et givent tidspunkt.
Logging-niveauer
Når man skal have gennemtænkt en logging-strategi, skal man bl.a. finde ud af hvad de forskellige logging-niveauer betyder for ens eget domæne. Hvem er målgruppen for log-filerne? Er det support, kunder eller udviklere?
- ERROR – en alvorlig fejl er opstået og skal undersøges med det samme. Systemet kan ikke længere forventes at opføre sig normalt.
- WARN – en fejl er opstået, men systemet kan godt forstat blive brugt. Fejlen skal undersøges.
- INFO – en besked der fortæller hvad systemet/applikationen har udført. Beskeden skal være let at tyde for en administrator og skal logges når systemet udfører en vigtig handling.
- DEBUG – kun til brug for udviklere.
- TRACE – meget detaljeret information for udviklere.
Indhold af en log-besked
En log-fil skal være beskrivende, så brug ikke ubrugelige tal og forkortelser, logværdier, ID’er og lignende i teksten. Og log aldrig passwords eller anden personligt information i en log-fil. Vis i stedet det data, der bliver processeret, og vis dets betydning. Vis hvad programmet er i gang med at udføre.
Logging-fælder
Hvis man logger en exception inde i en catch block, hvorefter en ny exception bliver kastet med det samme, så kan man ende med at få en log-fil fyldt med stack traces af den samme fejl men i forskellige varianter, der intet nyt siger om den fejl, der oprindeligt opstod. Så undgå “Catch-Log-Throw”. En anden ting man også skal undgå er at der kan opstå nullpointer exceptions, imens man udfylder teksten i en log-besked.
Har du erfaringer (gode eller dårlige) med logging-strategier? Og er tiden, man bruger på at udforme en logging-strategi, godt givet ud i sidste ende?
Med hensyn til dato, så anbefaler jeg
YYMMDD hhmmss
fremfor
YYYY-MM-DD hh:mm:ss
Det er måske ikke ISO, men man sparer 6 karakterer per line, både disk plads, men især skærm plads. (Måske er der også noget OCD agtigt ind over 🙂 *))
/Rene
*) I have CDO, it’s like OCD, but with the characters in the right order, as they should be….
Der er vel ikke den store forskel om det er med eller uden bindestreger, men ja, det gør tidsstemplet mere kompakt.
Det vigtigste er dog, at hvis man beslutter sig for at anvende ét bestemt format, så gør man det konsekvent – dvs. på alle projekter (store som små) man arbejder på.
Tak for en god og relevant artikel.
Når jeg udvikler systemer, anvender jeg gerne flere opdelte logfiler til det enkelte system. Jeg anvender typisk såvel “tekniske” som “forretningslogiske” logfiler, hvori emner af relevans for detaljeret fejlsøgning på tekniske problemer, men også af relevans for opklaring af udført forretningslogik, persisteres.
Har jeg flere væsentlige komponenter, fx adaptors, køer, workers etc., anvender jeg endvidere typisk én logfil pr. komponent/komponenttype (dog afhængigt af systemets beskaffenhed og kompleksitet), og jeg sørger typisk for at strømline outputbeskedernes format.
I et distribueret system kan det endvidere give mening at logge lokalt såvel som til en centraliseret logserver (eksempelvis en Syslog-server), hvormed fejlsøgningsmulighederne består og er nemt tilgængelige i flere kontekster.
Har man et distribueret system vil jeg endvidere altid anbefale, at man også logger centralt over netværket, for det hænder, at en disk løber fuld (mere om dette senere), førend en logskrivende proces på den berørte maskine crasher.
Med et kommandolinieværktøj som fx “multitail” er det endvidere trivielt samtidigt at følge output fra disse multiple logfiler, hvilket giver et godt overblik i fejlsøgningssammenhænge.
Farvet log-output er endvidere guld værd. Det letter overblikket over indholdet og gør det meget nemmere at spotte uregelmæssigheder i output, når man sidder og følger med. Jeg farver gerne log-output efter log-level samt efter indhold, når jeg har en fejlsøgningssession. Regulære udtryk is your friend og kan anvendes effektivt til farvelægning samt til filtrering af indhold (når man ved, hvad man leder efter).
Når jeg udvikler systemer med en webbaseret grænseflade, har jeg også for vane at eksponere logfilerne i et beskyttet administratormodul. Dette giver mulighed for at kunden og man selv meget nemt og hurtigt kan se de seneste liniers logfiler og sammenholde log-output fra fx forretningslogiske aktiviteter med de handlinger, man sideløbende udfører i en webbrowser, hvilket har vist sigt, at vores kunder er meget glade for.
Endelig er det vigtigt at imødegå det evigt tilbagevendende problem relateret til IT-drift: At disken løber fuld og serveren efterfølgende crasher. Sørg altid – altid – for at designe, afstemme og implementere et solidt og automatiseret regime for log-rotation, således at en god balance imellem tilgængelighed i fejlsøgningssammenhænge og arkivering samt sletning af logfiler opnås.
Og få så etableret/presset kunden til at etablere en ordentlig overvågning af serveren, hvor nogen faktisk reagerer på alarmer derfra. 🙂
Tak for et godt og langt svar på blogindlægget.
Du kommer med gode løsningsforslag til logging når det drejer sig om store, distribuerede systemer. Hvilke kan være svære at få styr på mht. ens logging.
For at undgå at disken løber fuld, kan man bruge rolling log-files (og evt. gemme gamle logfiler i en database). Eller logge direkte i en tilhørende database, og derefter sørge for at rydde op i disse logfiler en gang imellem – fx ved at gemme gamle log filer eksternt (hvis der er behov for det), og derefter slette dem helt fra databasen.