Hamna inte snett, logga rätt

Datasökning

I en tidigare bloggpost tog vi upp loggning generellt. Det har nu blivit dags för en mer ingående koll på vad man kan tänkas vilja logga. I takt med att den egna applikationsparken blir mer och mer komplicerad ökar värdet i att standardisera loggformatet oavsett tjänst/applikation i den mån det går. Nedan följer ett antal olika fält med tillhörande förklaringar. Listans mål är att ge er en bra grund för diskussion avseende era specifika behov.

Datum och tidpunkt

Följ alltid någon form av standard format. Förslagsvis ISO 8601 och ange tid i UTC, exempelvis 2018-01-02T13:37:13.370Z. Notera att det är tidpunkten när händelsen inträffade som avses, inte när loggen sparades ner. Speciellt viktigt att komma ihåg i det fall alla logghändelser skickas asynkront till ett annat system för att sparas. Bonustips: Passa på att se över att systemklockorna på era servrar är synkade.

Nivå

Syftet med nivån är att ge en fingervisning om allvaret i det som loggas utifrån ett funktionsperspektiv. Sträcker sig ofta från debug, information, varning och slutligen till fel. Lägg en del tid på att definiera dessa nivåer inom er organisation. Se även till att kontinuerligt följa upp hur definitionen efterföljs. Det har ni tveklöst igen i det långa loppet, framförallt om er IT-organisation består av 10+ medarbetare.

Server

När alla applikationer eller Microservices är utspridda över ett kluster av noder är det guld värt att veta exakt vilken nod/server logghändelsen inträffade på. Generellt rekommenderar vi en tydlig namnkonvention för varje nod i den mån det är möjligt. Om noder skapas/tas bort dynamiskt kan det enklaste dock vara att låta t.ex. Amazon Web Services själv bestämma nomenklaturen.

SessionsID

Ett sessionsID lever under en hel användarsession, t.ex. under den stund en inloggad användare nyttjar en eller flera självadministrationstjänster på er hemsida. SessionsIDet skapas oftast i samband med att användaren loggar in och kastas i samband med utloggning (sessionen avslutas). Vi rekommenderar att generera ett UUID som sessionsID. Utvecklar ni en webbapplikation så är det här lämpligt att använda HttpSession-objektets ID. Notera dock att det är upp till servlet containern att definiera ID:et för HttpSessionen i det fall ni utvecklar i Java.

TransaktionsID

Om det är en fristående applikation där användaren interagerar direkt med applikationen skapas transaktionsIDet med fördel i det ögonblick systemet tar emot en förfrågan från användaren. IDet lever bara under den stund det tar från det att systemet triggas fram till dess att ett svar givits. Om applikationen däremot ingår i en kedja av applikationer så spelar det plötsligt roll var i kedjan man befinner sig. Är man först så är man ansvarig för att skapa transaktionsIDet och passa vidare det till alla berörda underordnade system. Det är här mycket viktigt att de underordnade systemen passar tillbaka transaktionsIDet i sina svar så att den anropande applikationen kan avgöra när transaktionen är avslutad. Bra både för loggning och uppstädning av arbetstrådar. Gemensamt för båda dessa fall är att transaktionsIDet bara har ett värde under själva anropskedjan. När användaren fått svaret kan IDet kastas. Vi rekommenderar att generera ett UUID som transaktionsID.

Service

Namnet på den tjänst som körs. Om tjänsten byggs med Maven rekommenderar vi att ni väljer artifactID-fältet. Är det en stor monolit så kan det vara komponentensnamn eller helt sonika applikationen om all kod ligger i en och samma artefakt.

Klass

Klassen som triggade logghändelsen. Inkludera i de fall det är lämpligt komplett paket- och klass-namn. T.ex.

se.exertusit.demo.authentication.LoginService

Meddelande

Försök alltid att ha med kort, koncis och relevant information. Less is More men hyvla inte bort för mycket data. Typiskt bra är att låta hela stacktracen följa med som meddelande (eller till och med som ett eget valfritt fält). Glöm dock inte att inleda med någon meta-data som sätter stacktracen i ett context. OBS: Om felet beror på felaktigt inmatad data se till att få med vilken data som skickades in.

Exempel på dåligt meddelande:

Unexpected error. Please consult documentation.

Exempel på bra meddelande:

com.sun.mail.smtp.SMTPAddressFailedException: 554 5.7.1 <enigma@exertusit.se>: Relay access denied
        at com.sun.mail.smtp.SMTPTransport.rcptTo(SMTPTransport.java:1094)
        at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:584)
        at javax.mail.Transport.send0(Transport.java:169)
        at javax.mail.Transport.send(Transport.java:98)
        at com.liferay.util.mail.MailEngine._send(MailEngine.java:553)
        at com.liferay.util.mail.MailEngine.send(MailEngine.java:328)
        at com.liferay.util.mail.MailEngine.send(MailEngine.java:397)
        ...

CPU och RAM %

Serverns användning av processorkraft (CPU) och RAM minne vid logtillfället. Kan användas för att se trender/mönster över tid så väl som att underlätta felsökning. Om det av någon anledning är resurskrävande att plocka ut denna information i realtid kan det vara värt att istället periodvis plocka ut värdena. Resultatet blir lite trubbigare information i loggarna, men det är oftast bättre än ingen data alls.

Datastrukturen

Nedan följer ett exempel på hur den kompletta datastrukturen kan tänkas se ut uttryckt i JSON:

{
    timeOfEvent: "2018-01-02T13:37:13.370Z",
    level: "INFO",
    server: "exertus1",
    sessionId: "d63da1ed-9acb-45ff-b7c6-ecc5314d4829",
    transactionId: "aecd0269-fa45-4a6a-86af-da102840ce0f",
    service: "authentication",
    class: "se.exertusit.demo.authentication.LoginService",
    message: "Failed login attempt number 3 for username 'exertus'.",
    cpuUtilization: "12 %",
    ramUtilization: "40 %"
}

Slutord

Använd gärna denna bloggpost som en inspirationskälla. Syftet är främst att få igång en dialog samt att lyfta det faktum att ett gemensamt loggformat ofta underlättar såväl felsökning som underhåll. Några vanligt förekommande fält tas upp här, men listan är på intet sätt att anse som komplett. Sitt ner och fundera över vilka fält som passar bäst för just er verksamhet och applikationspark. Kanske är det värdefullt att veta hur många samtida användare som är inloggade i systemet när en logghändelse inträffar, eller varför inte vilken version av applikationen/tjänsten som körs. Kom ihåg att inte bara logga för den goda sakens skull utan se till att ha en strategi där varje fält har ett värde. Horder av “dåliga loggar” gör ingen glad; kvalité över kvantitet!