pondělí 18. června 2012

Pár tipů na lepší logy

Naučit se správně logovat je skoro stejně složité, jako naučit se programovat. Po hříchu není nikde moc článků o tom, jak to správně dělat a proto naše logy vypadají, tak jak vypadají. Někdy logujeme moc, někdy málo, někdy vůbec a to velmi znesnadňuje řešení potíží na produkci. V GoodData používáme pro čtení logu nástroj Splunk, který nám umožňuje dělat dotazy nad stovkami gigabajtů logu, který denně produkujeme. Bohužel i s tímto skvostným nástrojem jste nahraní, pokud vám daná informace v logu chybí a nebo ji nejste schopní vykoukat z kontextu dalších logovaných událostí. Kouzlo správného logování není logovat všechny události, ale logovat ty důležité se správnou úrovní (závažností), zaznamenat kontext, ze kterého bude možné zjistit další detaily, a v neposlední řadě logování neustále zlepšovat, protože málokdy se podaří trefit logování na první pokus.

Úroveň logování

Úroveň a nebo závažnost logované informace vychází z několika úrovní TRACE, DEBUG, INFO, WARN, ERROR. Narýsovat mezi nimi rozdíl je první problém, se kterým se člověk potýká. Většina logovacího kódu používá buďto úroveň příliš nízkou v podobě DEBUG. Druhým extrémem je naopak použití úrovně ERROR, pro události ne zcela zásadního charakteru, která by naopak měla efektivně znamenat, že vás kvůli ní vzbudí ve dvě hodiny ráno. Pokud nebudete dostatečně důslední při rozlišování úrovně, nebudete moci efektivně váš systém monitorovat. Základní rozdělení událostí podle úrovně logování jsem našel v článku Logging levels - Logback - rule-of-thumb to assign log levels. Volně zkusím přeformulovat

ERROR
Používáme pro zásadní událostí, které přímo ohrožují chod systému. Přímý dopad na zákazníka/uživatele. Je nutný lidský zásah k odstranění příčiny. Jedná se o problém, kvůli kterému by vás měli vytáhnout ve dvě hodiny ráno z postele. Pokud se do vašeho systému nemůže někdo zalogovat, protože se nemůžete připojit do databáze, pak je to určitě ERROR.
WARN
Události, které nemají přímý dopad na zákazníka, nicméně jsou natolik závažné, že by se jim měl někdo ihned věnovat. Minimálně by pro ně měl existovat záznam v systému pro sledování incidentů, a mělo by dojít k jeho vyhodnocení. WARN používám například při kontrole konfigurace aplikace. Pokud se na produkci používají nastavení, které jsou určené primárně pro vývoj, určitě by to mělo vyvolat zdvižený prst. Události na WARN úrovni by měly znamenat, že chod systému může být ohrožen. Jako příklad uvedu nefungující cache, funkce systému není přímo ohrožena, nicméně může dojít k přetížení jiných komponent systému.
INFO
Běžné události v systému, ze kterých bychom měli být schopni poznat, co se dělo. Jedná se o události z pohledu vlastní infrastruktury (komponenta nastartovala, zastavena), ale i události z pohledu aplikační logiky (uživatel se úspěšně přihlásil, změna hesla, email byl odeslán atd.). Na této úrovni rozhodně nelogujeme události neočekávané, ty patří o úroveň výše.
DEBUG
Tato úroveň slouží pro zachycení velmi detailních událostí, podle kterých se dá velmi zrekonstruovat stav programu. Jedná se například o rozhodnutí (decision points), která proběhla, nebo měření času, který se kde strávilo. Tato úroveň bývá hodně ukecaná. Oproti předchozí úrovni zde logujeme události očekávané, ke kterým dochází zcela běžně např. získané databázové připojení, uživatel má tato oprávnění apod.
TRACE
Nejjemnější úroveň, která slouží v podstatě k debugování. Vypisují se stavy proměnných, volání metod apod. Tahle úroveň se používá jenom ve výjimečných případech, většina programů si bez ní vystačí. Rozdíl oproti DEBUG úrovni je v tom, že zatímco ta vám dává skoro přesný obraz, TRACE vám dává úplně přesný obraz.

Pokud by člověk logy analyzoval sám, pak by bylo skoro jedno, jakou úroveň logování by použil. Pokud z logu ovšem analyzuje více lidí, pak je pochopitelné, že bez správných úrovní budou pravděpodobně ztraceni. Dalším dobrým důvodem pro správné použití úrovní je monitorování a automatické poplachy pokud dojde k nějakému ERRORu nebo WARNu. Standardní úroveň zapnutá v produkčních systémech je INFO. Úroveň DEBUG se zapíná podle potřeby, protože logování na této úrovni může produkovat velké množství dat a systém zatěžovat.

Pár rad

Pokud nevíte jestli by měla být událost logována na DEBUG nebo INFO úroveň, zkuste se zamyslet nad tím, jestli se jedná o událost očekávanou z pohledu systému (DEBUG) a nebo výjimečnou (INFO).

//user session validity
if(System.currentTimeMillis() > userSession.getValidity()) {
    log.debug("User session has expired already");
    return false;
}

V tomto případě byla zvolena DEBUG úroveň, protože session vypršela a nejedná se o nic výjimečného.

if(userSession.cookie.id != userSession.httpParam.id) {
  log.info("User session id in cookie dosn't match with  session id in HTTP request param");
  return false;
}        

V tomto případě jsme zvolili INFO, protože došlo k situaci, kterou pokládáme za neočekávanou. Nemělo by k ní normálně docházet, pokud je vše v pořádku. Nicméně k ní může dojít a my se o tom chceme dovědět.

V některých případech používám DEBUG událost namísto vloženého komentáře v kódu. Původní funkce vysvětlit kontext zůstala zachována a navíc je jí možné použít pro popis toho co se v systému děje.


if(!shoppingCart.isEmpty()) {
    //Creates a new order based on the shopping cart
    return new Order(shoppingCart);
}
if(!shoppingCart.isEmpty()) {
    logger.debug(Creating a new order based on the shopping cart {} ", shoppingCart);
    return new Order(shoppingCart);
}

Vetšina logovacích knihoven (používáme SLF4J) dneska umožňuje používat parametry, díky tomu nemusíte sčítat řetězce. To není problém z hlediska výkonnosti, protože to za vás zoptimalizuje kompilátor, ale z hlediska čitelnosti vlastního kódu.

logger.debug("User " + user + " with login " + login + " updated profile ");
logger.debug("User {} with login {} updated profile", user, login);

Pokud máte události, které se budou strojově zpracovávat, je dobré tomu jít naproti. Například Splunk rozeznává a indexuje parametry. Parametr je cokoliv oddělené přes znak rovná se. Díky tomu jsem schopen dělat dotazy a analyzovat je.

log.info("action=request_processing_request status=end uri={} method={} time={} size={} httpStatus={}",...);


Poměrně často máme tendence logovat stacktrace, ačkoliv to není úplně potřeba. Stacktrace a výjimka by se měla logovat obecně ve chvíli kdy nevíme co s ní a nastala neočekávaně a nebyla ošetřena, případně si nejsme jisti příčinou. Potom nám totiž stacktrace pomůže hledat příčinu. Pokud víme k čemu došlo, výjimka resp. její stacktrace znepřehledňuje log.

try (BufferedReader br = new BufferedReader(new FileReader(file))) {
    ...
} catch (FileNotFoundException e) {
    log.error(e);
}

V tomhle případě, kdy známe důvod selhání, nemá cenu výjimku logovat. Namísto toho bychom měli zalogovat lidsky srozumitelně to k čemu došlo.

try (BufferedReader br = new BufferedReader(new FileReader(file))) {
    ...
} catch (FileNotFoundException e) {
    log.error("The  key file '{}' for signature verification doesn't exist");
}

Vždy bychom měli rozlišovat, jestli daná událost bude spíše určena člověku a nebo stroji k zpracování. Pokud logujeme události a bude je analyzovat člověk např, proto aby zjistil co se stalo, bude lepší použít mnohem obšírnější způsob s uvedením kontextu. Pokud máme události určené k strojovému zpracování, zvolíme formát tomu odpovídající. V aplikaci máme většinou zastoupeny oba dva typy událostí.

Závěr

Logování je běh na dlouhou trať. V tomhle článku jsem se snažil dát k dobru pár tipů a postupů, které používám a zdají se mi celkem užitečné. Samozřejmě můžete mít své vlastní postřehy. Nebojte se je sdílet v diskuzi pod tímhle článkem.