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...