12. 5. 2015

Poznámky z migrace logovacího frameworku

Tento příspěvek píšu ve stavu doznívajícího pocitu vzteku na tu overengineerovanou tvář světa Javy, která mne minulý týden doprovázela při migraci z log4j 1.2 na log4j 2.2.

Problémy s deadlocky v major verzi 1 jsou známy a trápily i nás. K tomu byla v projektu zavlečena i závislost na apachí fasádě commons-logging, jež může přinášet problémy při redeployi, a samozřejmě SLF4J, kterou potřebují zas jiné knihovny. Neméně rozlezlá byla i přímá volání logovacího frameworku. Připočtěme oslavné články na novou technologii asynchronního logování v log4j2 na principu LMAX Disruptor a není divu, že jsem řekl: Je čas oddlužit a posunout projekt dál. Zde jsou poznámky z akce:

Odstranění Apache commons-logging

Lze snadno provést pomocí návodu ve známém článku Michala France, který jsem po redesignu na původním webu blog.fg.cz již nenašel, ale naštěstí se dochoval na blogu Honzy Novotného. Díky kluci. Doplňuji jen pár připomínek:
  • V případě multimodule projektu se nastavení musí provést u každého modulu, tj. pokud jsou moduly A, B a závislosti A -> B -> commons-logging, pouhé nastavení scope=provided u B nezabrání zavlečení knihovny do A.war.
  • Nastavení scope=provided nezabrání zavlečení závislostí artefaktu, později při vlastní migraci je proto nutno doplnit exclusion artefaktu log4j:log4j.
  • Pokud se v pom.xml pracuje s maven-dependency-pluginem (náš případ, kdy sestavujeme aplikaci pro Java Web Start), musí se knihovna excludnout i v konfiguraci pluginu (nejjistěji pomocí <excludeArtifactIds>commons-logging</excludeArtifactIds>, excludeScope opět nezabere na tranzitivní závislosti).
Přidání jcl-over-slf4j je pak bez problémů.

Přechod na SLF4J z Apache commons-logging

Když už nemáme apache-commons fyzicky v projektu, nemá smysl si na jejich použití hrát ani ve vlastním kódu. V SLF4J existuje utilita Migrator, kde stačí zaškrtnout příslušný převod a poštvat ji na projekt. Výsledkem je náhrada Apache za SLF4J. Jednoduchý a docela (viz další odstavec) účinný nástroj. Doporučené zálohování za nás řeší git, tak proč to nezkusit?


Po skončení činnosti nástroje je nezbytné sjet rozdíly vizuálně např. v patch souboru. Nástroj např. změnil typy fieldů i jejich inicializaci, ale už ne typy parametru jejich setteru. Také samozřejmě nezohlední rozdíly v API: Apache má debug(Object), zatímco SLF4J debug(String), takže v situacích, kdy se Object nepřevede na String, vyskákají kompilační chyby. Všechny tyto situace ale byly v našem případě pouze minoritní, takže celkově nástroj práci značně ušetřil.

Další úskalí vyvstane při dědění ze Spring tříd, které logují přes commons-logging. Pokud je zděděný logger z Apache a má se použít v místě, kde se s projektem již přešlo na SLF4J, může vzniknout nekompatibilita API. Řešením je buď "zavrtat" reflexí v adaptéru jcl-over-slf4j (nedoporučuji) nebo si vytáhnout potřebný logger podle jména přímo ze SLF4J.

Také bylo nutné zmigrovat konfiguraci ve Springu. Pro commons-logging existuje podpora v podobě CommonsLogFactoryBean, kde stačí nadefinovat:
<bean id="logger" class="org.springframework.beans.factory.config.CommonsLogFactoryBean">
  <property name="logName" value="myLoggerName" />
  ...

Ekvivalentní zápis pro SLF4J je (zdroj):

<bean id="logger" class="org.slf4j.LoggerFactory" factory-method="getLogger">
  <constructor-arg value="myLoggerName" />
  ...
</bean>

Přechod na SLF4J z přímého volání logovacího frameworku

Celý koncept logovacích fasád považuji za krásnou ukázku prosakující abstrakce. Je mi jasné, jak se historicky k tomu stavu dospělo. Nicméně mi vadí, že jakmile přidám do projektu (rozuměj na classpath) fasádu i implementaci, není už v Javě prostředek, jak implementaci zneviditelnit a přinutit používat pouze fasádu (nebo naopak, nechat fasádu pouze pro externí knihovny a v projektu ji zakázat). Důsledkem je, že programátor, který napíše Logger, Ctrl+mezera, pak dostane napovězen logger z fasády i implementace. Praxe pak potvrzuje, že bez dodatečné metodiky (a že se mi řízení programátorů dokumenty příčí) pak výběr záleží na příslovečném vkusu každého soudruha.

V tomto smyslu očekávám zlepšení s příchodem JDK9 modulů, kde koncept classpath projde revolucí umožňující definovat viditelnost mezi moduly s jemnější granularitou.

Po zvážení výhod a nevýhod jsme se nakonec přiklonili k setrvání u fasády a migraci přímých volání na fasádu (včetně migrace použití třídy MDC). Umím si ale představit, že v některých případech může být rozumné použít framework napřímo. Argumentace á la tento článek už neplatí - placeholdery jsou "nativně" i v log4j2 - a navíc mi smrdí overengineeringem typu "co kdyby se měnilo něco, co se měnit nebude".

(Pro úplnost: log4j2 nabízí i možnost obrácené adaptace na SLF4J, ale to se samozřejmě vylučuje s použitím SLF4J jako fasády, protože by došlo k zacyklení volání.)

Vlastní upgrade na log4j2

  • v pom.xml změnit závislosti z org.slf4j:slf4j-log4j12 na org.apache.logging.log4j:log4j-slf4j-impl a přidat org.apache.logging.log4j:log4j-core
  • u webové aplikace navíc přidat org.apache.logging.log4j:log4j-web a com.lmax:disruptor:3.3.2
  • vlastní framework má poměrně pěkně napsaný manuál (pokud pominu ten frustrující pocit, že tak jednoduchá věc jako logování vůbec potřebuje takový manuál), kde je vše vysvětleno, doporučuji předtím přečíst, zejména kapitolu o celkové architektuře a o migraci
  • migrace XML konfigurace (pokud už u ní chceme zůstat; jinak se nabízí i JSON nebo YAML) je přímočará, trochu se divím, že po vzoru SLF4J Migratoru ještě nikoho nenapadlo napsat na to XSLT šablonu
Specifika:

Asynchronní logování

V log4j2 kromě dosavadního konceptu asychronních appenderů postavených na ArrayBlockingQueue přibyl ještě koncept asynchronních loggerů postavený na knihovně LMAX Disruptor. Podrobnější info je v manuálu. Funkcionalita se nastavuje buď pomocí systémové property, pokud chceme mít všechny loggery asynchronní, nebo pomocí speciálních XML elementů v konfiguraci, pokud chceme asynchronní jen některé. V prostředí webové aplikace považuji nastavení systémové property za trochu kontroverzní způsob, protože tuto konfiguraci považuji za cosi, co by se mělo dodat s warem, nikoli za konfiguraci Tomcatu, kde nakonec systémová property skončí. Programové nastavení pomocí System.setProperty je nejisté, vyžaduje další úsilí spojené s ohlídáním, že bude zavoláno před inicializací logovacího frameworku. Jiná řešení založená na vlomení se do log4j2 nejsou pěkná kvůli nutnosti použít ošklivé reflexní hacky. Proto jsem upřednostnil způsob pomocí XML elementů, i když z výkonového hlediska představuje režii jednoho threadu navíc.

Rollover


Překlápění souborů po splnění určité podmínky je v log4j2 řešeno také nově. Nechci posuzovat, zda byl náš usecase tak specifický nebo knihovna tak nepřipravená, nicméně starý framework s naším usecasem problém neměl, nový ano. Za vše mluví můj dotaz na SO. Nakonec jsem se ošklivému hacku nevyhnul, řešení je tamtéž. Opět se mi framework jevil jako přehlídka všech možných OO patternů a principů, ale běda když chci open, co je myšleno jako closed. Typickým příkladem je tvorba potomků FileManager pomocí factory, privátní field s instancí privátní classy, takže nejde podědit ani neexistuje mechanismus přenastavení zvenčí.

Zajímavé odkazy z hledání příčiny, o podobných problémech: 1, 2, 3, 4, 5, 6, příbuzné issues v log4j2 JIRA.

Vlastní appender

V aplikaci byl appender z log4j verze 1 pro ukládání logovacích zpráv do Swing komponenty. Změna major verze přináší změnu API a s tím spojenou nutnost třídu přepsat: náhradu předka AppenderSkeleton za AbstractAppender, změněný vztah k layoutům, zavedení konceptu filtrů, zavírání.

AsyncAppender final

Klientská aplikace posílá události s úrovní ERROR na server. To se provádí asynchronním appenderem, který deleguje na appender provádějící vlastní odeslání zprávy. Aby se celý mechanismus asynchronního appenderu nevolal při každé události, vytvořil jsem v původní verzi vlastního potomka AsyncAppenderu, který volal super.append(event) pouze v případě úrovně ERROR. V nové verzi už je AsyncAppender final. Proto bylo nutné použít mechanismus filtrů, který je pro tento případ určen, konkrétně ThresholdFilter.

Dynamické změny konfigurace

Programové nastavení konfigurace (appenderů, levelu) je poměrně bez problémů, stačí pochopit architektonické změny ve verzi 2 (rozlišování objektu loggeru a jeho konfigurace). Samozřejmě se tím odřezáváme od fasády, ale pro administrátorské zásahy se stále funkcionalita hodí. Za ocenění stojí mechanismus pluginů: stačí vlastní třídu označit příslušnou anotací a specifikovat způsob vyhledání pluginů (kterých je opět spousta, log4j2 je prostě tank) - v našem případě hledání v zadaném packagi. O zbytek se postará framework. Anotace dokážou popsat i podobu konfiguračních XML elementů.

Nutnost inicializovat log4j2 jako první


Ve webové aplikaci musí být log4j2 inicializován hned ze začátku. Toho se dosáhne uvedením org.apache.logging.log4j.web.Log4jServletContextListeneru jako prvního listeneru, nicméně to ještě není postačující podmínka - pokud jiné listenery mají logger jako statický field, je tento field inicializován při nahrání classy, tj. ještě předtím, než se volá samotná lifecycle metoda contextInitialized. (V prostředí servletů 2.5 jsem toto chování zaznamenal a byl nucen to obejít, doufám, že s migrací na verzi 3 se tyto problémy vyřeší.) Při příliš pozdní inicializaci pak např. není správně inicializován WebLookup (identický problém, podobné problémy).

Konfigurace logování z externích properties


Do starého log4j.xml bylo možné napsat např. <level value="${log4j.root.level}" /> a pomocí Springu nastavit framework na čtení z dodaných properties. To je v novém frameworku dosaženo pomocí mechanismu lookupů. V našem případě je pro tyto properties potřeba znát ServletContext. Konkrétně lze použít buď WebLookup, který je založen na thread-local znalosti servlet contextu, nebo vytvořit vlastní na stejném principu. Placeholder se pak musí upravit na <level value="${config:log4j.root.level}">, kde config je prefix definovaný anotací (lookup opět není nic jiného než log4j2 plugin). Funguje to dobře, za předpokladu, že je log4j2 inicializován ze servlet contextu a ne předčasně (viz předchozí odstavec).

Závěr

Log4j2 celkově hodnotím jako pěknou knihovnu, kterou má smysl zkusit. Rozhodně převažují pozitivní změny, které si autoři mohli se změnou major verze dovolit: zásahy do architektury, koncept filtrů, pluginů, failover, sloučení MDC a NDC do ThreadContext.


Na druhou stranu nemohu se ubránit hořkému dojmu, že tak jednoduchá věc jako logování nabobtnala do tak odpudivého shluku návrhových vzorů. Pamatuji si dosud na ten naivní pocit naděje, kdy jsem jako začátečník v Javě 1.4 objevil package java.util.logging a těšil se, že brzy už žádné externí logovací knihovny potřeba nebudou. Kdybych věděl, že o 12 let později budu tweetovat tohle...

2 komentáře:

  1. 1. Pouzivat _VSUDE_ SLF4J je podle me postulat. SLF4J je sice esencialni predevsim pro knihovny, aby vam nevychovana knihovna nezpusobila, ze byste museli mit pro aplikaci 2 soubory.log. Nikdy ale nevite, kdy kus vaseho kodu skonci nekde jinde pretaveny do knihovny. Takze _VSUDE_. Bez vyjimky.
    2. Pokud vam vadi, ze vam pri programovani IDE nabizi Logger z Log4J, nedavejte ho na classpath projektu, ale pribalujte ho az behem faze assemble v Gradlu.
    3. Prijde mi naivni myslet si, ze logovani je tak jednoduche, ze o tom neni treba si nic precist. Asi jako ze transakce funguji samy, kdyz pouzijete @Transactional nebo ze odpadky z popelnice pred domem mizeji samy. Naopak to, ze si muzete ze zacatku myslet, ze logovani je snadne, ukazuje, jak dobre je zvoleno rozhrani mezi svetem aplikace a logovani, protoze dokud se tim nezabyvate, nemate poneti, ze je to veda.
    4. V clanku jste nezminil, proc jste si vybrali Log4J 2 a nikoliv LogBack. Mela jsem pocit, ze Log4J 2 je zatim jen "beta" a ze dospelost LogBacku se neda srovnat s zadnym jinym logovacim frameworkem.

    OdpovědětVymazat
  2. Díky za komentář.
    ad 1) tak kategoricky to nevidím, nicméně souhlasím, obzvlášť v případě knihoven. Jinak SLF4J i Log4j jsou napsány stejným rukopisem (Ceki Gülcü), takže i když např. Log4j přejmenuje MDC na ThreadContext, v SLF4J z principu musel starý název zůstat.
    ad 2) dobrý tip! Sice tento projekt je nad Mavenem, ale myšlenku beru. V Mavenu by se nejspíš závislost excludnula a přidělala k waru v nějaké pozdější fázi, čímž by více vynikl charakter workaroundu. Mohli bychom pak diskutovat, jestli je to víc problém návrhu Mavenu nebo Log4j :-) A navíc jak znám Eclipse, muselo by se toto opatření udělat na každém otevřeném projektu ve workspacu.
    ad 3) to byla narážka na kontrast mezi jednoduchostí rozhraní a složitostí a uzavřeností implementace, na kterou člověk narazí, když tam chce něco jinak, viz případ s rolloverem.
    ad 4) byly to především dobré výsledky ve výkonových benchmarcích

    OdpovědětVymazat