Nešvary logování
Publikováno: 22.2.2018
Text vyšel původně na autorově webu.
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 tým přistupuje 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 spousta 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áší, stejně tak jako je na jejich libovůli jakou severitu (závažnost) 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í:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
<Loggers>
<Root level="off"/>
</Loggers>
</Configuration>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řesměrované do logu, jindy 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 hned na 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ódu. 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?