4. prosince 2017

Nešvary logování

Co se týká softwarového vývoje, logování je jedna z nejvíce zanedbávaných oblastí. Samozřejmě, pokud nejde o něco naprosto amatérského, tak je logování v každé aplikaci. Stejně tak, aby člověk pohledal vývojáře, který si během programování nevypisuje na konzoli potřebné runtime informace.

A bohužel, tak jako každý Javista má v CV napsaný Maven, i když umí jen naimportovat projekt do IDE a z příkazové řádky spustit mvn clean install; tak všichni o sto šest logují: chaoticky, nekonzistentně, bez vize, bez přemýšlení. A občas jsou ty logy dost odpudivé smetiště.

Tenhle pocit se ve mně hromadí léta letoucí. A jelikož jsem teď musel refaktorovat pár špatně designovaných a zanedbaných aplikací, rozhodl jsem se k tomu sepsat pár postřehů.

Obecný vývojářský přístup

To, jak se tým chová k logování se dá obvykle shrnout do tří axiomů:
  • Vývojáři si ad hoc logují to, co momentálně potřebují během vývoje aktuální feature. Co se jednou vloží do zdrojáků, to už tam na věky zůstane.
  • Operations/Support si stěžují, že v produkčním logu nejsou relevantní informace, zato spoustu balastu.
  • Kromě kavárenského stěžování si, s tím nikdo nic nedělá.

Situaci může drobně zlepšit, pokud má zákazník, nebo produktový tým definovanou nějakou explicitní logging policy. Daleko častější ale je, že politika logování je buď vágní, nebo žádná. Dá se to popsat i tak, že chybí vize a kontrola, jak logování provádět a používat.

Za dané situace, jsou největšími "viníky" vývojáři, protože jsou to právě oni, kdo do kódu logovací zprávy zanášejí, stejně tak jako je na jejich libovůli jakou severitu zprávám nastaví. Záleží na kontextu, ale někdy/často(?) existuje dokonce "logovací super-padouch"... technical leader, který tuto oblast buď zanedbává, nebo rovnou ignoruje. Je to nejspíš on, kdo by měl způsob logování definovat a kontrolovat.

Ponechme však stranou analýzu "kdo za to může" a pojďme se podívat, jak se špatné logování projevuje.

Špatný mindset

Již jsem naznačil, že za špatný stav logování můžou většinou vývojáři. To není nic překvapivého - jedním ze základních znaků echt vývojáře je, že trpí chronickým tunelovým viděním. U logování se to projevuje tak, že programátoři nepřemýšlí, co se s aplikací stane, jakmile opustí jejich vývojové prostředí.

Ačkoliv aplikace poběží roky na produkci, tak většina logování reflektuje relativně krátkou vývojovou fázi.

Chybějící konvence a postupy

Tohle je obecný problém, který se vyskytne kdykoli mají lidé volnost v zápisu textu zprávy. Kromě logování jsou to typicky commit komentáře. Číst historii je pak (masochistický) požitek, kdy člověk, jako archeolog, prozkoumává hranice lidské kreativity.

"Všechno je relativní", tak proč ne úrovně logování? Každý vývojář dokáže sám, subjektivně a správně posoudit, jaká má být pro danou zprávu severita logování. Trace/Debug/Info, vždyť se to na produkci odfiltruje, tak co?

Co takhle zmapovat flow nějaké entity, jak prochází procesem a systémem? Někdy jo, někdy ne, někdy tohle ID, jindy tamto. Stejně je to všechno "Request ID", bez ohledu na počet requestů, vrstev a systémů. Anebo radši "Session ID", co na tom, že je to bezstavový? "Korelační" je sprosté a zakázané slovo. A vůbec, aby to někdo pochopil, musí na tom pár týdnů/měsíců dělat, takže je jedno, jak se to bude jmenovat.

Nesmyslné logování v testech

Když spustíte testy, viděli byste na konzoli radši takovýhle výpis?
:clean
:compileJava
:processResources
:classes
:compileTestJava
:processTestResources
:testClasses
:test

BUILD SUCCESSFUL in 42s
6 actionable tasks: 6 executed

Nebo byste raději viděli 20 obrazovek balastu, který lítá z logů Hibernate a Spring testů? Předešlý výpis tam samozřejmě bude geniálně ukrytý jak hrst jehel v kupce sena.

Přitom pomoc je triviální - vypněte pro testy logování:


Výpisy na konzoli

Kdo by si čas od času nezahřešil starým dobrým:
System.out.println("Bla bla");
Výpisy na konzoli do logu nepatří. Ani když je to v testech. Samozřejmě, záleží na nastavení vašeho logovacího frameworku - někdy jsou výpisy na sdtout přešměrovaný do logu, někdy ne. Používat by se ale neměly (téměř) nikdy.

Jedinou výjimkou by mohlo být, pokud píšete CLI aplikaci. Ale i tam bych zvážil, jestli místo println nepoužívat logování s vhodným formátem a severitou zprávy. Minimálně to půjde vypnout v testech.

Dedikovaný logger z interního frameworku

Zažili jste někdy, že by si firma vyvíjela vlastní framework? Já už jsem si tím párkrát prošel. Možná jsem jen neměl štěstí... ale pokaždé to byl průser - tam kde vám to 1/3 práce ušetřilo, tam vám to později 2/3 práce přidalo. K internímu frameworku samozřejmě patří custom logger. Jinak by to nebylo ono.

Ona je to vlastně dobrá myšlenka - některé z výše zmíněných problémů by se daly takovým speciálním loggerem podchytit. Bohužel, v realitě to bylo stejně úspešný jak implementace Scrumu v kovaným enterprise-korporátním prostředí. No, možná jsem jen neměl štěstí.

Zapomeňte na custom/interní/proprietární loggery! Vykašlete se na to a použijte vanilla logování svého srdce.

Jak z toho ven?

Tak jako na dovolený poznáte na hned první pohled rozdíl mezi rozvinutou a rozvojovou zemí, tak u funkčních aplikací poznáte, jestli někdo přemýšlel i kousek za kompilaci kódů. Pročetli jste si někdy logovací zprávy když vám startuje čistý aplikační server, nebo rozumný buildovací nástroj (ne, Maven to není)?

Zkuste někdy taky psát takové pěkné logy. Chce to jenom:
  • Mít vizi, jak má logování vypadat.
  • Dělat code review.
  • Čas od času udělat na logování audit.

Jaký je váš oblíbený logovací nešvar?

6 komentářů:

  1. Můj oblíbený logovací nešvar je logování té samé výjimky opakovaně v každé vrstvě aplikace.

    Výjimku zachytím, zaloguju pěkně včetne celého call stacku, a zase ji vyhodím, nejlépe obalenou do jiné výjimky. Tohle zopakuju cestou nahoru nejlépe v každé metodě na call stacku. Než to dojde do webového frameworku nebo nějaké top-level komponenty která se nad tím smiluje a už to dál nikam nevyhodí, tak se do logu stihnou vypsat stovky řádků opakujících dokola tutéž informaci, ať se to maintenance developerovi pořádně vypálí do sítnice.

    OdpovědětVymazat
    Odpovědi
    1. Jo, tak to je "dobrý". S tím jsem se snad asi ani nesetkal, ale umím si to živě představit.

      Vymazat
  2. U nas ve firme jsme na logovani hodne zapracovali od doby, co vsechny logy posilame do Graylogu. Najednou clovek potrebuje mit dost informaci, aby dohledal souvisejici logy. Strukturovat zpravy tak, aby davaly smysl a obsahovaly veskere informace nutne k vyhodnoceni. Byly dost kratke, aby se snadno cetly i jako notifikace na Slacku. V okamziku, kdy si jako jako vyvojari sami resime i operations, logovani se v mnohem zlepsuje a neustale upravuje.

    Jako nejvetsi nesvar mame v soucasne chvili logovani citlivych dat. Nektera mista loguji treba cely odchozi registracni e-mail, vcetne prihlasovacich udaju.

    OdpovědětVymazat
    Odpovědi
    1. To je jedna z věcí, který mi z článku vypadly - externí nástroj, třeba Splunk to může hodně zlepšit, minimálně na úrovni konvencí.

      A pravda, DevOps by to měl zlepšovat tak nějak přirozeně.

      Nad tím logováním citlivých dat jsem taky přemýšlel, ale to je dost specifické - jednak by to měly pokrývat security requirementy a jednak by to měl odchytit security audit. Nebo méně formálně jsou to vlastně ty dva poslední body, co jsem napsal, tj. code review a "obyčejný" audit/review.

      Vymazat
  3. Myslim, ze nejhorsi zlocin v logovani je kdyz se do error message nezaloguje cely context.

    Napriklad
    error message :
    Can't create map layer view.

    Je mnohem lepsi takto:
    Can't create map layer. Map with [id] , layer template [id], map layer view [settings]

    obzvlaste kdyz clovek cte log z produkce.

    Debug message jsou na produkci stejne vetsinou vypnute kvuli gc ...

    OdpovědětVymazat
    Odpovědi
    1. Ano, debug a často i info severita bývá na produkci vypnutá. Ale když se vyskytne produkční issue, tak se někdy můžou dočasně zapnout. Takže pak stojí za to, mít dobré logování i na těch nižších úrovních.

      Vymazat