Wyciszanie śmiecących logów Springa przy kończeniu testów

Wielowątkowe testy (takie jak używające Kafki) są źródłem kłopotów. Na przykład zaśmiecają przebieg buildu w Gradle’u.

Normalnie Gradle przechwytuje stdout i stderr z testów, przerzuca je do raportów HTML-owych, a terminal zachowuje czysty:

> Task :my-module:testClasses
> Task :my-module:test

Moduły korzystające ze Springa i uruchamiające wiele wątków potrafią kompletnie zabić czytelność terminala:

> Task :my-module:testClasses
INFO [ntainer#0-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-my.event-2, groupId=my.event] Revoke previously assigned partitions my.event-0, my.event-1, my.event-2
20
ERROR [sson-netty-1-15] i.n.u.c.D.rejectedExecution             : Failed to submit a listener notification task. Event loop shut down?
java.util.concurrent.RejectedExecutionException: event executor terminated
	at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:934)
> Task :my-module:test

Łatwo może się zdarzyć, że dostaniemy ponad 100 niechcianych śmieciowych linii.

W dalszej części artykułu objaśnię, co w działaniu biblioteki spring-test powoduje taki zgrzyt w integracji z Gradle’em. Zaproponuję też obejście problemu za pomocą specjalnego beana wyłączającego część logowania.

Niedopasowanie cyklu życia

spring-test daje rzecz kluczową z punktu widzenia wydajności testów: cache’uje konteksty Springa. Czyli jeśli nasz kontekst startuje 30 sekund, to (upraszczając trochę) niezależnie od tego, czy testy umieścimy w 1 pliku czy w 10 plikach, wszystkie testy wykonają się w tak około 30 sekund, a tylko raz „zapłacimy” za start wszystkich beanów. Co oczywiście jest rzeczą piękną, a nawet niezbędną, bo nie chcielibyśmy kisić wszystkich testów w jednym pliku.

Ceną za wydajność jest lekkie przyhaczenie integracji z frameworkami testowymi. Kończenie testu nie zamyka żadnego kontekstu. Konteksty są zamykane dopiero, gdy testowa JVM jest zamykana (dla zainteresowanych: tłumaczenie z oficjalnej dokumentacji Context Caching).

Zamykanie kontekstu to nie jest prosta operacja, zresztą podobnie jak startowanie kontekstu. Coś się może wysypać, dużo rzeczy loguje zarówno istotne informacje, jak i bezużyteczne śmieci.

Jest otwarta prośba o uporządkowanie zamykania kontekstu (https://github.com/spring-projects/spring-framework/issues/26196), ale skoro wisi otwarta 5 lat, to nie liczyłbym, że coś się w tej materii prędko zmieni.

Musimy radzić sobie sami.

Pomysł

Dodamy do kontekstu beana, który będzie wyciszał najbardziej śmieciowe logi. Zgodnie z zasadą 80/20, celem nie jest idealne pokrycie każdego przypadku, ale usunięcie logów zajmujących najwięcej miejsca.

Użyjemy Phased, żeby nasz bean był pierwszy w kolejności do odpalenia przy zamykaniu kontekstu.

Kod

@Component
class TestShutdownLogSilencer : DisposableBean, Phased {
    override fun getPhase() = Integer.MAX_VALUE

    override fun destroy() {
        logger("com.zaxxer.hikari").level = Level.WARN
        logger("io.netty.util.concurrent.DefaultPromise.rejectedExecution").level = Level.OFF
        logger("org.apache.kafka.clients.consumer").level = Level.WARN
        logger("org.apache.kafka.common.utils").level = Level.WARN
        logger("org.hibernate.orm.cache").level = Level.ERROR
        logger("org.springframework.orm.jpa").level = Level.WARN
    }

    private fun logger(logger: String) =
        LoggerFactory.getLogger(logger) as Logger
}

Komplikacje

Nasz kod jest prosty i nie przewiduje, że wyłączone logi będą jeszcze przydatne. W typowym scenariuszu, bean jest wołany przy zamknięciu kontekstu podczas zamykania JVM, więc nie ma żadnej możliwości, że odpali się jeszcze jakiś test i napotka wyłączone logi.

Może się jednak zdarzyć, że kontekst zostanie zamknięty pomiędzy testami. spring-test ma określony rozmiar cache’a kontekstów i gdy kontekstów przybywa, stare będą zamykane, a nie cache’owane w nieskończoność.

Mamy wtedy kilka opcji:

1. poprawiamy kod testów, żeby ograniczyć liczbę kontekstów, najlepiej do jednego, co poprawi nie tylko wygląd terminala, ale przede wszystkim czas wykonania
2. modyfikujemy kod powyżej, żeby przy starcie beana wyciszone logi były ponownie włączane (dość kłopotliwe, bo trzeba ręcznie synchronizować plik Kotlina z konfiguracją Logbacka/Log4j)
3. uznać, że to za dużo wysiłku i ryzyka, odpuścić sobie takiego beana

Skuteczność

Phased nie jest gwarancją, że nasza logika będzie uruchomiona jako bezwzględnie pierwsza. Czasem zdarzy się, że jakieś śmieci i tak zostaną zalogowane. Jednak ogólnie, różnica w czytelności terminala jest uderzająca.