Z tego artykułu dowiesz się

• Co umieścić w logach, aby były pożyteczne
• Jakie są poziomy logowania i jak je włączać
• Czym jest Slf4j
• Jak praktycznie konfigurować biblioteki logowania na przykładzie Logback

Jeżeli interesują Ciebie tematy dotyczące organizacji logów takie jak:

• Traceability w logach
• Utrzymywanie plików logów
• Performance w logowaniu
• Logowanie w środowisku rozproszonym

Zapraszam do osobnego artykułu: Logowanie aplikacji Java: Organizacja logów.

Opis problemu

Logowanie w aplikacjach Java to jedna z fundamentalnych rzeczy pozwalająca na uruchomienie jej w środowisku produkcyjnym. Odpowiednio zaimplementowane jest pomocne developerom, zespołom utrzymującym oprogramowanie i pozwala zaoszczędzić ogromną ilość czasu w nieoczekiwanych sytuacjach. Aby dziennik logów był nam przydatny, istotne jest to, co logujemy, kiedy logujemy, jak logujemy oraz w jaki sposób zorganizować logi (gdzie logujemy), aby wyciągać z nich interesujące nas informacje. Podzielę się moimi doświadczeniami w tym obszarze, jakie zdobyłem przez lata pracy z aplikacjami.

Logowanie to odnotowywanie istotnych informacji na temat zdarzeń w systemie, w czymś w rodzaju dziennika. Aplikacje backendowe są nieco nieme, poza monitoringiem na temat stanu aplikacji (zużycie pamięci, procesora, I/O, stan wątków) nie za bardzo można wizualizować obecnie przetwarzane procesy biznesowe. Z pomocą przychodzi notowanie zaistniałych zdarzeń do dziennika.

Elementy wpisów

Kluczowe elementy wpisów to:

• kiedy? – data i czas
  • Tutaj warto zastanowić się, w jakim kontekście działa aplikacja. Jeżeli jest to globalny produkt rozproszony w wielu regionach, warto logować w czasie UTC, wtedy uzyskamy ujednolicony czas na wielu węzłach rozproszonych geograficznie i w razie awarii łatwo będzie nam zawęzić obszar poszukiwań do wybranego czasu bez zastanawiania się, jaka strefa czasowa i wynikający z niej czas była w danym regonie.
• co? – treść wpisu, która dostarcza wartościowe informacje
• gdzie? – orientacyjne miejsce w kodzie, np. nazwa klasy wraz z pakietem
• poziom logowania – tzw. serverity, jak ważny jest to wpis (TRACE, DEBUG, INFO, WARNING, ERROR)
• nazwa wątku, na którym wykonywany jest kod
  • Szczególnie przydatne, gdy przetwarzanie jest wielowątkowe. Wtedy w naszym logu będą występować logi przemieszane wykonaniem różnych wątków, w momencie kiedy wątek został przełączony. Tym sposobem możemy wyłuskać informacje np. z wątku o danej nazwie, aby przejrzeć sekwencję zdarzeń. Jeżeli aplikacja jest napisana w sposób reaktywny (wciąż tego typu aplikacji jest bardzo mało), może to nam niewiele pomóc i pomocny nam będzie kontekst wykonania (czyt. dalej)
• kontekst wykonania
  • Każda informacja, która pozwoli nam skorelować logi z wielu wątków z jednym logicznym procesem, np. przetwarzaniem danego requestu, plus ew. nazwa procesu/flow biznesowego. Dobrą praktyką jest wygenerowanie ID requestu w momencie, kiedy dociera on do systemu – wtedy możemy łatwo wyodrębnić wszystkie informacje związane z jego przetwarzaniem.

Przykładowe wpisy w logu mogą wyglądać następująco:

Poziomy logowania

Wpisy w dzienniku zapisywane są jednym z poziomów logowania. Co do zasady określają one istotność wpisu, czy są alarmowe, informacyjne, czy pomagają w developmencie/testach. Są one kolejno uszeregowane od najwyższego poziomu, do najniższego.

• ERROR – Sytuacja wyjątkowa, na przykład utrata połączenia z krytycznym zasobem, nieoczekiwany stan aplikacji (złamanie założeń), lepiej przerwać przetwarzanie i uruchomić scenariusz bezpieczny i zanotować taką sytuację (np. przechwycenie i zalogowanie wyjątku oraz reakcja).
• WARNING – Niepokojąca sytuacja, ale aplikacja nadal może działać. Potencjalnie dane żądanie nie zostało do końca wykonane (np. pewien proces nie został dokończony, ale mamy ręczny proces rekoncyliacji).
• INFO – Odnotowanie jakiegoś normalnego faktu w aplikacji. Możemy odnotować kawałek stanu, parametrów, wyniku operacji.
• DEBUG – Informacje istotne dla odtwarzania błędów, diagnostyki, bardziej szczegółowe niż INFO. Raczej nieistotne z punktu widzenia produkcyjnie działającej aplikacji, potencjalnie przydatne w przypadku przejściowych problemów.
• TRACE – Bardziej szczegółowy poziom od DEBUG do dogłębnej diagnostyki. Istnieją dyskusje, czy ten poziom jest potrzebny, bo można skorzystać z DEBUG, niemniej jednak część bibliotek wykorzystuje ten poziom logownia.

Przy wyborze poziomu logowania możemy spojrzeć z dwóch perspektyw:

• Czy błąd, który wystąpił, powinien zapalić czerwoną lampkę na monitoringu (ERROR) i wymaga natychmiastowej reakcji? Czy jest to co prawda niecodzienny przypadek, ale można na niego spojrzeć w trybie niepilnym (WARNING) i zapala pomarańczową lampkę na monitoringu? Czy może jest to wpis informacyjny, który pomoże w naprawie potencjalnego błędu przy odtwarzaniu przypadku?
• Poziom logowania można ustalać, np. wyłączając wszystkie tryby poniżej (np. INFO wyłącza DEBUG i TRACE), czyli czy informacja jest na tyle istotna, aby zalogować ją na poziomie INFO, czy jest to informacja diagnostyczna włączona na żądanie.

Sfl4j

Z biegiem czasu powstało wiele bibliotek do logowania rozwiązujących z grubsza ten sam problem – sposób zapisu informacji do dziennika. Wybierając daną bibliotekę, kierujemy się jej możliwościami (np. jak można ją skonfigurować, jak szybko działa, czego z reguły używa się w naszej organizacji). Wywołanie dokonujące wpisu w dzienniku należy umieścić w kodzie programu. I tu pojawia się kilka problemów:

• Różne biblioteki do logowania mają odmienne API, pakiety, nazwy klas. Wymiana takiej biblioteki jest niemożliwa.
• Zależności, które deklarujemy, również logują coś do dziennika, zatem finalnie na classpath skończyłoby się to z wieloma bibliotekami do logowania.

Problem stara rozwiązać się Slf4j, czyli Simple Logging Facade For Java. Jest to zestaw klas i interfejsów uznanych jako standard i implementowanych przez najpopularniejsze biblioteki do logowania. To właśnie ze wspólnych interfejsów korzystamy przy dokonywaniu wpisu w dzienniku. Dzięki temu:

• Jeżeli nasza zależność lub my w programie potrzebuje coś zalogować, używamy fasady – nie jesteśmy związani z żadną biblioteką na stałe.
• Możemy wykluczyć implementacje bibliotek do logowania z naszych zależności i nadal wszystko powinno działać o ile zależności też korzystają z Slf4j.

Przykładowe użycie Slf4j w kodzie:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

class BasketController {

    private static final Logger LOGGER = LoggerFactory.getLogger(BasketController.class);

    public ResponseEntity<BasketSummaryView> method(UUID basketId) {
        try {
            LOGGER.info("Getting info about basket {}", basketId);
            // ...
        } catch (IllegalArgumentException e) {
            LOGGER.error("Error while getting info about basket {}",
               basketId, e);
            // ...
        }
    }
}

Slf4j wykrywa popularne biblioteki znajdujące się na classpath, np:

• Logback
• Log4j i Log4j2
• java.util.logging (JDK 1.4)
• JCL (Jakarta Common Logging)

Włączanie poziomów logowania

Na przykładzie biblioteki Logback, poziom logowania możemy ustawić na poziomie

• globalnym
• konkretnego logera (najczęściej nazwa klasy)
• lub całego pakietu (loggery są hierarchiczne)

Standardowo robimy to w pliku konfiguracyjnym, na przykład globalnie logujemy na poziomie INFO, a w wybranych klasach lub pakietach na DEBUG:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        // ...
    </appender>

    <logger name="org.springframework.web.filter.CommonsRequestLoggingFilter" level="debug" />
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Szybka zmiana na działającej aplikacji

Jeżeli mamy sytuację wyjątkową nie jest konieczne zatrzymywanie aplikacji, podmiana pliku konfiguracyjnego i jej restart. Możemy zmienić poziomu logowania w konsoli diagnostycznej naszej aplikacji Java poprzez podłączenie się pod JMX (na przykład przez Java Mission Control) i użycie wyeksponowanego MBeana: (Przeczytaj o tym Czym są MBeany i jak z nich korzystać?). W pliku konfiguracyjnym należy dodać sekcję:

<configuration>
    <jmxConfigurator />
    // ...
</configuration>

Następnie łączymy się do naszej aplikacji przez JMX i używamy MBeana ch.qos.logback.classic:Name=default,Type=ch.qos.logback.classic.jmx.JMXConfigurator

Psst… Interesujący artykuł?

Jeżeli podoba Ci się ten artykuł i chcesz takich więcej – dołącz do newslettera. Nie ominą Cię materiały tego typu.

Dołączam

Dziękujemy!

Wysłaliśmy Ci mail powitalny, w którym znajdziesz link do aktywacji newslettera. Do usłyszenia!

Kiedy i co logować

Błędy i wyjątki

Bez wątpienia należy logować błędy i wyjątki, z których aplikacja nie może się wykaraskać. Jeżeli już taka sytuacja nastąpi, należy zalogować istotne informacje, parametry i koniecznie wyjątek (jako ostatni parametr metody logującej) – wtedy będziemy dysponowali stacktrace. Gdy wyłapiemy wyjątek i nie zalogujemy go – informacja przepadła. Przykład poprawnego logowania wyjątku:

try {
    LOGGER.info("Getting info about basket {}", basketId);
    // ...
} catch (IllegalArgumentException e) {
    LOGGER.error("Error while getting info about basket {}", basketId, e);
    // ...
}

Mała dygresja: Gdyby przyjąć założenie, że każdy ERROR budzi nas w nocy, staralibyśmy się pisać aplikacje safe-to-fail, czyli np.: jeżeli jakiś serwis nie jest dostępny – przełącz się na inną instancję. Lub jeżeli nie działa, zwróć domyślną odpowiedź i zaloguj WARNING, a monitoring serwisu, od którego zależymy, zapali lampki na czerwono.

Przychodzące i wychodzące żądania

Ważnym elementem działania systemu produkcyjnego jest to, żeby móc odtwarzać ewentualne błędy na środowisku testowym. Można do tego wykorzystać stacktrace błędu/warninga, albo logować więcej informacji, np. rodzaje i treść przychodzących żądań i odpowiedzi. Jeżeli w naszym systemie nie mamy innego punktu zaczepienia (np. audytywna baza lub tworzenie eventów), może okazać się to jedyną możliwością.

Warto też logować żądania wychodzące i przychodzące z innych systemów zaraz po odebraniu/wysłaniu wiadomości. Wraz z datą, kontekstem wykonania i danymi o stanie (np. baza danych) z wysokim prawdopodobieństwem będziemy w stanie odtworzyć błąd na środowisku testowym.

Przykład logowania requestów HTTP w Spring Boot:

LoggingFilter.java

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.filter.AbstractRequestLoggingFilter;

import javax.servlet.http.HttpServletRequest;

@Slf4j
public class LoggingFilter extends AbstractRequestLoggingFilter {

    @Override
    protected void beforeRequest(HttpServletRequest httpServletRequest, String message) {
        log.info(message);
    }

    @Override
    protected void afterRequest(HttpServletRequest httpServletRequest, String message) {
    }
}

Konfiguracja WebMvc:

import org.springframework.context.annotation.Bean;
import org.springframework.web.servlet.config.annotation.EnableWebMvc;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

@EnableWebMvc
public class RestConfig implements WebMvcConfigurer {

    @Bean
    LoggingFilter loggingFilter() {
        LoggingFilter filter = new LoggingFilter();
        filter.setIncludeHeaders(true);
        filter.setIncludeQueryString(true);
        filter.setIncludePayload(true);
        return filter;
    }
}

Przykładowy wpis o przychodzącym żądaniu:

2020-05-28 07:21:51,081Z {ce5c75b9-34bb-4dee-a74f-aaf486398f68} [http-nio-8080-exec-2] INFO  p.s.c.t.b.r.i.LoggingFilter - Before request [POST /basket/fee991d2-c95a-41cd-94cb-e2eeb4df7198/summary?a=1, headers=[host:"localhost:8080", connection:"keep-alive", content-length:"113", cache-control:"no-cache", user-agent:"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36", accept:"*/*", sec-fetch-site:"none", sec-fetch-mode:"cors", sec-fetch-dest:"empty", accept-encoding:"gzip, deflate, br", accept-language:"pl-PL,pl;q=0.9,en-US;q=0.8,en;q=0.7", Content-Type:"application/json;charset=UTF-8"]]
2020-05-28 07:21:51,184Z {ce5c75b9-34bb-4dee-a74f-aaf486398f68} [http-nio-8080-exec-2] INFO  p.s.c.t.b.r.c.BasketController - Getting information about basket fee991d2-c95a-41cd-94cb-e2eeb4df7198
// ...

Podoba Ci się ten artykuł? Weź więcej.

Jeżeli uważasz ten materiał za wartościowy i chcesz więcej treści tego typu – nie przegap ich i otrzymuj je prosto na swoją skrzynkę. Nawiążmy kontakt.

Dołączam

Dziękujemy!

Wysłaliśmy Ci mail powitalny, w którym znajdziesz link do aktywacji newslettera. Do usłyszenia!

Gdybyś potrzebował jeszcze więcej:

Zdjęcie: Designed by jcomp / Freepik