Enkle tips for bedre logger

Har du opplevd at feilsøking er vanskelig, fordi loggen du leser er umulig å forstå? Eller at viktig informasjon rett og slett mangler? Har du irritert deg over debug-linjer som bare gir mening til utvikleren som skrev dem, og nå fremstår kryptiske? Eller bryr du deg ikke om loggene i det hele tatt, fordi de inneholder altfor mye unyttig informasjon?

Her følger noen perspektiver på logging jeg selv prøver å ta inn over meg, og som jeg håper kan være inspirerende for andre.

Fortellinger fra applikasjonen

Man logger på ulike loggnivå. Det vanlige tipset om nivå er en liste over hvilke hendelser som hører hjemme på hvilke nivå. Jeg vil heller snu det litt på hodet, og fokusere på hva leseren skal få ut av loggen på ulike nivå. Da fokuserer man ikke bare på å velge riktig nivå når man først logger, men også på hva man faktisk burde logge.

Tenk på loggen din som en fortelling, en historie om hva som skjer i applikasjonen. De forskjellige loggnivåene er forskjellige fortellinger fra det samme hendelsesforløpet:

ERROR:
Historier om hva som gikk galt i applikasjonen. Dette er den delen av loggen som skal nå frem til drifteren. Hver gang han hører fortellinger herfra, vil du at han skal lytte. Ikke misbruk dette nivået, og tenk om det du forteller virkelig er så viktig at drifteren trenger å høre det. Sammenheng og flyt er ikke viktig, for ofte er hver linje sin egen historie. Det kan være lurt å ikke bare fortelle hva som har gått galt, men også konsekvensen, og eventuelt hva som bør gjøres. Får du 404 mot en ekstern tjeneste? Skriv ut URL, hva den skulle blitt brukt til, og be drifteren sjekke om tjenesten er oppe!

WARN:
Dette er historier om ting som ikke gikk helt slik det skulle. I likhet med ERROR vil nok historiene her for det meste begrense seg til én og én linje. En advarsel vil sannsynligvis ikke stoppe applikasjonen, så en god idé kan være å fortelle hvordan koden fortsetter. Klarte du ikke å oppdatere kundedata fra en ekstern tjeneste? Fortell at det skjedde, og at brukeren fortsetter med gamle data.

INFO:
Denne historien inneholder alle viktige hendelser som har skjer. Avhengig av hva slags applikasjon du lager, så kan alt fra individuelle klikk være viktig, eller bare større transaksjoner. Brukerhistoriene du brukte da du implementerte løsningen kan være et godt utgangspunkt for hva du kan forvente å finne her. For at denne historien skal bli lest, må det være en viss konsistens i språket, og du må være veldig varsom så du ikke skriver for mye. Denne historien bør utviklere og testere lese kontinuerlig. Dette nivået er veldig avhengig av hva slags applikasjon du har, så jeg hopper over eksempel her.

DEBUG:
Dette er historien om alt som skjer i applikasjonen. Denne er bare for bruk under feilsøking eller verifikasjon, og utviklere bør bruke denne flittig under utvikling. Da er sjansen større for at de bruker den til feilsøking av egen kode, og at den er nyttig for feilsøking senere. Eksempler kan være sidevisninger, valideringsfeil, utfallet av utregninger, etc. Fortellingen skal gi et klart bilde av alt om skjer i applikasjonen, og helst gjøre en utvikler istand til å reprodusere hendelser i sitt eget miljø.

En god logg speiler hva som skjer i koden, og er en slags lesbar parallell. Det bringer oss rett på neste tips.

Logging som dokumentasjon

Ofte bruker man kommentarer for å forklare hva som skjer i koden. Mitt tips er å erstatte slike kommentarer med logging. Et eksempel jeg ofte har sett er følgende feilhåndtering under lukking av en stream:

try {
    if (stream != null) {
        stream.close();
    }
} catch(IOException e) {
    // ignorerer denne
}

Dette er en hendelse det kan være greit å vite om, så den burde antagelig logges på WARN, og lesbarheten blir ikke redusert av å gjøre følgende:

try {
    if (stream != null) {
        stream.close();
    }
} catch(IOException e) {
    LOGGER.warn("Feil ved lukking av strøm etter lesing av brukerdata: {}. Ignorerer og går videre.", e.getMessage(), e);
}

Her illustreres et generelt prinsipp i feilhåndtering, som jeg har nevnt i forrige seksjon: Fortell at feilen ble oppdaget, men også hva koden gjør med den! Da hjelper du både leseren av loggen (og av koden) med å skjønne konsekvensene av feilen, og ta riktige avgjørelser om hva som bør gjøres.

Et annet eksempel er en kodesnutt hvor flyten kan ta mange forskjellige stier:

if (brukerFraEksterntSystem == null && cachetBruker == null) {
     // bruker finnes ikke i EksterntSystem, og vi har heller ingen informasjon cachet
     ... [nekte brukeren tilgang etc]...
} else if (brukerFraEksterntSystem != null && cachetBruker == null) {
   // ny bruker
   ... [legge ny bruker i cache, logge på etc]...
} else if (brukerFraEksterntSystem == null && cachetBruker != null) {
    // brukeren har vært hos oss før, men er fjernet fra eksternt system
   ... [fjerne lokal bruker, nekte tilgang etc]...
} else {
  // vi har hentet bruker, og har cache
  if (!brukerFraEksterntSystem.equals(cachetBruker)) {
      ...[oppdater cache}...
  }
}

Kommentarene hjelper nok utvikleren som leser koden med å skjønne de forskjellige mulighetene, men burde vi ikke fortelle leseren av loggen hva som skjer? Jeg ville endret koden slik at viktige hendelser havner i info-loggen, alle detaljene i debug-loggen, og samtidig sørget for at dokumentasjonen gjenbrukes i loggen.

if (brukerFraEksterntSystem == null && cachetBruker == null) {
     LOGGER.info("Bruker '{}' fantes ikke i EksterntSystem, og vi har heller ingen informasjon cachet. Nekter bruker tilgang.", brukernavn);
     ... [nekte brukeren tilgang etc]...
} else if (brukerFraEksterntSystem != null && cachetBruker == null) {
   LOGGER.info("Bruker fra EksterntSystem '{}' er ny for oss, og vil bli lagt til i cache og logget på.", brukerFraEksterntSystem );
   ... [legge ny bruker i cache, logge på etc]...
} else if (brukerFraEksterntSystem == null && cachetBruker != null) {
    LOGGER.info("Bruker '{}' finnes ikke i EksterntSystem, men i cache ({}). Vil bli fjernet og nektet tilgang.", brukernavn, cachetBruker );
   ... [fjerne lokal bruker, nekte tilgang etc]...
} else {
  if (!brukerFraEksterntSystem.equals(cachetBruker)) {
    LOGGER.info("Bruker er endret fra {} til {}. Cache skal bli oppdatert og bruker logget på..", cachetBruker, brukerFraEksterntSystem);
    ...[oppdater cache}...
  } else {
     LOGGER.debug("Bruker '{}' var lik i EksterntSystem. Bruker skal bli logget på.", brukernavn);
  }
}

Legg merke til at i denne koden er alle stiene gjennom koden representert med én logglinje. Det kan være veldig frustrerende om noen stier gjennom sentral kode ikke logger i det hele tatt, og det er oftest ikke nødvendig med mer enn én logglinje per sti.

Skriv skikkelig!

Å lese en logg kan være smertefullt. Ofte virker det som forfatteren har kastet alle sine skriveferdigheter overbord, og istedet er begrenset til en uregelmessig strøm av enstavelser og forkortelser. Skjerp deg! Bruk forklarende, gode setninger. Unngå tvetydigheter.

En ofte følt frustrasjon er at jeg må se i koden for å skjønne når en logglinje blir skrevet ut i forhold til andre hendelser i systemet. Et eksempel jeg ofte ser varianter av:

Lagre bruker 'anders'

Dette er ikke bare en dårlig setning, men det etterlater leseren i tvil. Ble brukeren lagret? Eller skjer dette før lagring blir forsøkt? Hvorfor har forfatteren brukt imperativsform? Eller er det infinitiv?

En bedre løsninger en av følgende:

Skal lagre bruker med brukernavn 'anders'
Bruker med brukernavn 'anders' ble lagret

Da er det klart for leseren om dette skjer før eller etter den faktiske lagre-operasjonen. Jeg vil anbefale den siste varianten.

Test dine logger

Loggene skal inneholde nyttig informasjon. Bruk applikasjonen mens du skrur på loggnivået! Er historiene som du forventer? Er det noen linjer som bare forstyrrer? Er det brukt et inkonsistent språk? Er informasjon duplisert, som kan utledes fra tidligere linjer? Jeg bruker alltid noen minutter ekstra på å finpusse loggene etter at jeg har utviklet eller endret funksjonalitet.

En god øvelse kan være å starte applikasjonen med alle loggere satt til DEBUG. Prøver andre utviklere i teamet å fortelle deg noe viktig? Forstår du hva som skjer i applikasjonen? Forstår du hva rammeverkene du bruker forteller? Om du finner mye informasjon du ikke forstår, er det en sjanse for at du enten bruker et rammeverk du ikke kan godt nok, eller at du bruker det feil. Et symptom på at teamet ditt ikke leser loggene med nok respekt er warn-linjer fra eksterne bibliotek. Disse burde noen oppdage og ta tak i! Jeg prøver enten å fikse dem, eller å lage en JIRA-sak hver gang jeg ser slike.

Vi vet at loggene er viktige for oss når noe går galt, men tester vi at loggene er hjelpsomme under destruktive tester? Forventet informasjon i loggene bør være en del av test-spesifikasjonen! Hver gang en tester rapporterer en feil, prøver jeg å sjekke om loggen ga fornuftig og hjelpsom informasjon. Ofte ligger de i feilens natur at ingen hadde tenkt på muligheten i koden, og heller ikke logget godt nok. Dette bør fikses samtidig med feilretting!

Om alle i utviklingsteamet, samt testere og driftere, begynner å bry seg om loggene, vil forhåpentligvis forbedringene skje av seg selv. Logging er applikasjonens interne brukergrensesnitt! Skriv pent!

"Tips for bedre logger" på Booster

I mars 2013 holdt jeg en lyntale basert på denne bloggartikkelen på Booster-konferansen i Bergen. Under kan du se foredraget.

Litt om forfatteren

comments powered by Disqus