pondělí 11. listopadu 2013

Logovací vzory - stopování požadavků, logování průběhu, agregované zprávy a výjimku z pravidla

V tomto článku se podíváme na několik vzorů logování, které zvyšují čitelnost logu a umožňují mnohem efektivnější správu systému a vhled do toho co se právě stalo.

Background

GoodData je Business Inteligence platforma provozovaná jako Software As A Service. Koncový uživatel konzumuje GoodData ve formě interaktivních grafů a reportů v prohlížeči. Uživatel si nemusí nic instalovat, všechny služby nutné pro analýzu dat - jako je ETL, ROLAP, model - běží v rámci GoodData platformy někde v cloudu. Rozhraní, přes které se komunikuje s okolním světem i uvnitř platformy, představuje REST (s výjimkou uploadu dat přes WebDAV). Obecně řečeno jakákoliv interakce s GoodData platformou je HTTP požadavek a to platí i pro interakci mezi jednotlivými službami uvnitř. Jednomu HTTP požadavku na vstupu odpovídá několik vnitřních HTTP požadavků a většinou několik SQL příkazů případně volání do NoSQL úložišť jako je Cassandra nebo MongoDB.

Stopování požadavku

Pokud se vám jeden HTTP požadavek rozpadne na X dílčích, navíc distribuovaných přes vícero služeb, je potřeba zajistit jeho dohledatelnost. Pokud navíc dojde k chybě při jeho zpracování, musí mít klient možnost nějakým způsobem ten požadavek identifikovat. Z tohoto důvodu na vstupu zpracování každého HTTP požadavku vygenerujeme unikátní identifikátor, který cestuje s požadavkem po celou dobu jeho zpracování uvnitř GoodData, a nakonec je vrácen i klientovi. Každá ze služeb si tento identifikátor přečte/předává dál v HTTP hlavičce X-GDC-REQUEST. V případě messagingu se předává v rámci zprávy. Bez ohledu na to, jak se tento identifikátor reprezentuje na protokolové úrovni, platí že každá komponenta jej musí nastavit do logovacího kontextu. Tím je zaručeno, že každá hláška v logu bude mít tento unikátní identifikátor.


Identifikátor je možné dále rozdělit na segmenty oddělené dvojtečkou. Každá ze služeb si může libovolně přidat vlastní segment. To umožňuje filtrovat pouze logovací zprávy zprávy týkající se zpracování požadavku v rámci dané služby a všech následujících za ní. Zároveň je možné, aby tento identifikátor vygeneroval přímo klient. Například naše UI aplikace v browseru generuje první segment tohoto identifikátoru ve chvíli zobrazení nového dashboardu. Všechny HTTP požadavky v rámci dashboardu mají stejný první segment. To umožňuje dělat analýzu toho, jak rychle se načítá celý dashboard, kolik HTTP požadavků je na to potřeba atd. Segment tvoří určitý kontext, ke kterému je možné vztahovat další informace z logu.


Pokud stopujete požadavek, existuje několik informací, které se vyplatí logovat - velikost požadavku, user agent, dobu zpracování, unikátní identifikátor viz výše, URI požadavku, uživatele, HTTP status, IP adresu klienta. Většina z těchto hodnot odpovídá standardnímu Apache Access Logu. Kromě toho je dobré logovat čas události, vlákno, kategorii a severitu. Protože používáme k zpracování logů Splunk, více nám vyhovuje strukturovat logovací zprávy na klíč=hodnota.


    
2013-11-10T17:50:49.891+0100 http-bio-8080-exec-194 c.g.c.web.filter.RequestLoggingFilter INFO: action=processing_request status=end uri=/gdc/app/account/bootstrap method=GET time=74 size=8361 httpStatus=200 userAgent='Mozilla/5.0 ...' remote_address=10.250.70.65 forwarded_for='109.80.143.171' component=webapp request_id=uix94085b999276_0:bbnL3uR9mVB3FzUS auth_user=4375 project_id=fc97da87icodqn408r9m4mr25rypatrt 
    

S takto komplexně zalogované zprávy jste schopni vytěžit celkem dost informací - poměr mezi read/write operacemi, časy zpracování požadavků, sledování anomálií indikujících potenciální problém např. poměr mezi HTTP statusy, negativní odchylky z dlouhodobě naměřených dat. Následující dashboard je právě ukázkou měření anomálií. Z dlouhodobě nasbíraných dat známe dobu odpovědí jednotlivých REST resourců. Každý čtvereček zobrazuje měřenou hodinu a barva signalizuje odchylku - zelená ok, žlutá došlo k malému zpomalení, červená - došlo k většímu zpomalení. Bílé kostičky signalizují nedostatek dat případně downtime.



Logování průběhu

Zpracování požadavku prochází většinou různými fázemi - existují minimálně tři - začátek, konec úspěchem, konec neúspěchem.


try {
    log.info("action=started ...");
    doSomething();
    log.info("action=finished_ok ...");
}catch(RuntimeException e) {
    log.info("action=finished_error", e);
}

Tímhle triviálním způsobem jste schopni jednak zjistit poměr mezi úspěšnými/neúspěšnými běhy. Pokud byste jenom vyhazovali výjimku, mnohem hůře by se vám to v logu párovalo. Nemluvě o faktu, kdy má běh několik fází.


Agregace logovacích zpráv

V případě kdy logujeme detaily, např. časy provedení různých částí programu a jsme omezeni velikostí logu z důvodu jeho zpracování, vyplatí se agregovat na zprávy na aplikační úrovni. Obzvláště pokud má každá logovací zpráva velkou režii (logovací kontext).


long start = currentTimeMillis();
foo();
log.info("foo time={}", currentTimeMillis() - start);
start = currentTimeMillis();
hoo();
log.info("hoo time={}", currentTimeMillis() - start);
start = currentTimeMillis();
bar();
log.info("bar time={}", currentTimeMillis() - start);



long start1 = currentTimeMillis();
foo();
long start2 = currentTimeMillis();
hoo();
long start3 = currentTimeMillis();
bar();
log.info("foo time={} hoo time={}  bar time={} ", start2 - start1, start3 - start2, currentTimeMillis() - start3);

My produkujeme řádově stovky gigabajtů logů denně a mohlo by se zdát, že nehraje roli jestli se někde zaloguje o dvě řádky více nebo méně, ale opak je pravdou. Představte si, že tyhle tři nebo jedna řádka se generují s každým HTTP požadavkem. Řekněme, že včetně logovacího kontextu má jedna řádka 500b, na produkci máme 13 milionů HTTP volání za 24 hodin. To dělá při jedné logovací řádce 6GB logů denně a při třech 18GB logů. Další výhodou těchto agregovaných zpráv je lepší čitelnost pro člověka. Pokud do logu přibývá stovky řádek za sekundu, musíte si logovací zprávy nějakým způsobem dohledat. V rámci agregované zprávy máte vše na jednom místě. Daní za přehlednost a menší velikost logu je větší komplexita logovacího kódu.


Výjimka z pravidla

Bez ohledu na to, jaký nástroj budete používat na zpracování logů, vždy budete mít mantinely, mezi kterými se budete muset pohybovat. Právě vybalancování mezi tím, co je potřeba nutně logovat a tím co už je v uvozovkách odpad, nejde moc generalizovat. Je to tedy iterativní proces, kdy bojujete s tím, že vám v logu něco chybí nebo naopak přebývá a vytékají vám data někde jinde. Asi jako nejlepší kompromis mi přijde logovat výjimky z pravidla. Pokud jsou potřeba další detaily, zvednout úroveň logování v runtime pro danou kategorii a nebo udělat přímo změnu kódu.



public boolean verifyCredentials(String userName, String password) {
    log.info("Username '{}' exists", userName);
    ...
    log.info("Password matches", password);
    ...
    log.info("Account is active");
    ...
    return ...
}

Výjimka z pravidla je v tomhle případě neplatnost přihlašovacích údajů. V takovém případě nemusíme logovat, že nějaké podmínka (existence účtu, správné heslo a platnost účtu) byla splněna, ale naopak splněna nebyla.


public boolean verifyCredentials(String userName, String password) {
    log.info("Unknown username={}", userName);
    ...
    return false;
    
    log.info("Password doesn't match", password);
    ...
    return false;
    
    log.info("Account for username={} has not been activated", username);
    ...
    return false;
    
    return ...
}

Tímhle reverzním způsobem máme v 99% nulovou zátěž, protože vše se chová očekávaně. V tom jednom procentu případů. kdy si zákazník stěžuje, na nemožnost přihlášení, mu můžeme z logu jasně říci v čem je problém. Tenhle kód se dá samozřejmě ještě zrefaktorovat.



public boolean verifyCredentials(String userName, String password) {
    boolean verified = false;
    String reason = "Password doesn't match";
    try {
        ...
        reason = "";
        return verified;
    } finally {
        if(!verified) {
          log.info("Supplied credentials for username={} are not valid. reason={}", username, reason);
        }
    }
}

V tomto článku jsem se pokusil sepsat pár postřehů logování. Určitě máte i vy nějaké tipy a postřehy, které jste si vypěstovali, proto budu rád pokud se o ně podělíte.

Starší články k tématu

neděle 10. listopadu 2013

CZ Podcast 87 - Clojure v praxi

Kdo tenhle vlak zastaví? V 87. dílu jsme se věnovali Clojure v praxi. Samozřejmě jsme se museli dotknout i samotného funkcionálního programování, zabrousili jsme k databázi Datomic a nebo nástroji Cascalog. Hostem tohoto dílu jsou pánové Daniel Škarda, Jiří Knesl a Tomáš Svárovský.