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.

What #Java #logging framework do you use these days?

— SoftWare Samuraj (@sw_samuraj) November 20, 2017

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?