Już dostępny

Program Szkoleniowy Java Developer dostępny 🔥💪 tylko TERAZ za 999 zł  Sprawdź szczegóły i agendę

Zakres

Monitoring • Apache Kafka • Clean Code Testowanie • Hibernate • Systemy kolejkowe Sprawdź szczegóły i agendę

Zakres

14 modułów  /  ponad 40h nagrań  /  230 lekcji  /  dożywotni dostęp  /  Sprawdź szczegóły i agendę

Logowanie aplikacji Java: Co, Kiedy, Gdzie i Jak?

utworzone przez Java

[Szybkie info]: Startujemy z II edycją Programu Szkoleniowego Java Developera 🚀. To MEGA piguła wiedzy o Java 🔥💪

  • 14 tygodniowy program szkoleniowy online,
  • 230 lekcji w formie video (40 godzin materiału)
  • z dożywotnim dostępem
  • Case Studies, masz dostęp do kodu i obrazów Dockerowych
  • zamknięta grupa mentorzy + uczestnicy i webinary na żywo

W agendzie znajdziesz: Mikroserwisy, Systemy kolejnowe, Apache Kafka, Caching, Hibernate/MyBatis/Spring Data, techniki efektywnych Testów kodu, Clean Code i Maven.

Tylko teraz dołączysz z 63% rabatem to 2699 zł 999 zł (+VAT). I nigdy już nie będzie taniej. Poniżej dowiesz się więcej:

Zobacz więcej

A teraz przechodzimy do artykułu:

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:

Slf4j implementations. Źródło: http://www.slf4j.org/manual.html
Slf4j implementations. Źródło: http://www.slf4j.org/manual.html

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

Ustawienie poziomu logowania na działającej aplikacji poprzez MBean

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.

.

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.

.

Gdybyś potrzebował jeszcze więcej:

Jesteś Java Developerem?

Przejdź na wyższy poziom wiedzy 
„Droga do Seniora” 🔥💪

Jesteś Team Leaderem? Masz zespół?

Podnieś efektywność i wiedzę swojego zespołu 👌

Zdjęcie: Designed by jcomp / Freepik

Dyskusja