Přejít k navigační liště

Zdroják » Různé » Nešvary logování

Nešvary logování

Články Různé

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.

Nálepky:

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.

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?

Komentáře

Subscribe
Upozornit na
guest
11 Komentářů
Nejstarší
Nejnovější Most Voted
Inline Feedbacks
View all comments
Tomas Kafka

Charity Majors rika (a ja souhlasim) at jdeme o krok dal, a misto textovych retezcu ukladame strukturovane eventy. Podekuje e si pozdeji.

https://honeycomb.io/blog/2017/04/lies-my-parents-told-me-about-logs/

https://www.percona.com/live/17/sites/default/files/slides/2017-04-25-percona-lies-about-logs.pdf

balki

Moj oblubeny nesvar je zabudnut po sebe vycistit debug logy typy „moje_priezvisko tralalala iteracia: 50 nastalo toto a toto.“

Alebo nezalogovat exception z threadu v multithreadovej aplikacii. Potom mozem dohladavat, ze co sa vlastne pokazilo ….

Oldis

bude následovat serál jak správně logovat?

ivoszz

S většinou ze zde tepaných nešvarů nelze nesouhlasit, ale autor zde prokazuje, jak je zarostlý do Java prostředí a jde i proti některým moderním trendům (12 factor apps).

Oldis

je otazkou jde-li o chyby, za chybu povazuju kdyz neco nefunguje nebo to rovnou spadne, ale formatovani logu a podobne je spis šlendrian nez chyba.

Oldis

ano, ale vývojáři jsou dost citliví na slovíčka a proto místo bug či wrong jim radši řeknu že je to imperfect nebo imcomplete.

emik

Poslanci, když něco udělají blbě, říkají, že došlo k diskrepanci.
Zní to dobře, ne?
A sdělovací prostředky a zainteresovaní (potrefení) už měsíc dopředu rovnou říkají, že je to blbě. Pak se to schválí.

Enum a statická analýza kódu

Mám jednu univerzální radu pro začínající programátorty. V učení sice neexistují rychlé zkratky, ovšem tuhle radu můžete snadno začít používat a zrychlit tak tempo učení. Tou tajemnou ingrediencí je statická analýza kódu. Ukážeme si to na příkladu enum.

Pocta C64

Za prvopočátek své programátorské kariéry vděčím počítači Commodore 64. Tehdy jsem genialitu návrhu nemohl docenit. Dnes dokážu lehce nahlédnout pod pokličku. Chtěl bych se o to s vámi podělit a vzdát mu hold.