W kontekście jednego z naszych projektów mieliśmy do czynienia z wieloma przypadkami debugowania. Zwykłe komunikaty w logach nie zawsze są wystarczające. Na przykład, może być konieczne posiadanie więcej informacji o użytkowniku, który wykonał akcję (jego IP, jego uprawnienia, jego identyfikator, …). W naszym przypadku, nasza aplikacja została zbudowana z kilku mikroserwisów i chcieliśmy dokładnie zidentyfikować przepływ, jaki następuje w żądaniu, które przechodzi z jednego mikroserwisu do drugiego. W tym celu został wygenerowany unikalny identyfikator, który był wyświetlany w logach każdej aplikacji internetowej. Bardzo nam to pomogło w rozwiązywaniu problemów z aplikacjami innych firm, z których korzystaliśmy.
- Jak logować komunikaty?
- Jakie informacje kontekstowe dodawać do naszych komunikatów?
- Czy te informacje mogą być dodawane podczas uruchamiania wątków asynchronicznych?
Ten artykuł pomoże Ci zbudować aplikację Spring Boot Java do logowania komunikatów za pomocą Log4j oraz wykorzystać MDC tej biblioteki (Mapping Diagnostic Context) do dodawania danych kontekstowych oprócz komunikatów, szczególnie dla zadań asynchronicznych.
Zacznijmy od wygenerowania klasycznej aplikacji Spring Boot z wbudowaną biblioteką Log4j. Biblioteka ta pozwala nam na użycie loggera, który generuje komunikaty dziennika różnych typów (info, error, warning, …)
- Na Spring Initializr (https://start.spring.io/) zbuduj podstawowy projekt Spring Boot bez żadnych zależności.
- Edytuj plik pom.xml, aby dodać zależności potrzebne do użycia biblioteki Log4j
- Utwórz plik src/main/resources/log4j2.xml, który definiuje format przyszłych komunikatów dziennika
pom.xml
src/main/resources/log4j2.xml
Wyświetl nasz pierwszy komunikat dziennika
W obecnym stanie, jeśli uruchomimy aplikację (na przykład przez IDE lub używając Mavena), nie pojawi się żaden komunikat dziennika. Stworzymy komponent, który wykorzysta bibliotekę Log4j do rejestrowania komunikatu informacyjnego.
Utwórz plik src/main/java/com/sipios/example/mdc/Execute.java z poniższym kodem. Nazwą pakietu jest tutaj com.sipios.example.mdc, oczywiście należy ją zastąpić swoją 🙂
src/main/java/com/sipios/example/mdc/Execute.java
Jeżeli uruchomisz aplikację, zostanie wyświetlony pierwszy komunikat logu zgodny ze zdefiniowanym formatem. Możliwe jest również użycie metod error i warning. Komunikaty dziennika odpowiadające tym typom zostaną wyświetlone.
Użyj MDC (Mapping Diagnostic Context) w swoim dzienniku
Teraz, gdy wiemy już jak korzystać z biblioteki Log4j, będziemy mogli użyć Mapping Diagnostic Context (MDC), który pozwala nam powiązać Mapę danych z naszym komunikatem. Kilka przykładów danych, które zalecamy umieścić w MDC:
- Dane bieżącej sesji (użytkownik, zapytanie, żądanie …)
- Metryki dotyczące wykonania procesu (czas początkowy i czas wykonania, …)
- Informacje o wersji aplikacji
- …
Ta mapa jest wyświetlana w logach, jeżeli maska %X jest użyta w definicji formatu wiadomości Log4j. Tak jest w przypadku naszego pliku src/main/resources/log4j2.xml. W poprzednim wykonaniu widzimy {}, co wskazuje na pustą Mapę.
Użycie MDC jest bardzo proste i używa się go jak klasycznej Mapy poprzez metody put, get, remove, clear…. Dodajmy dwa wpisy do MDC i wykonajmy aplikację.
src/main/java/com/sipios/example/mdc/Execute.java
MDC jest globalne i jest zachowywane tak długo, jak długo nie jest modyfikowane. Jeśli chcesz go opróżnić przez opuszczenie np. komponentu, wystarczy użyć metody clear. Dałoby to następujący wynik.
Jak to działa z komponentami asynchronicznymi?
Spróbujmy MDC z komponentami asynchronicznymi (komponent wykonywany na wątku równoległym do wątku głównego)! Przede wszystkim musimy skonfigurować naszą aplikację do wykonywania takich beanów. Tworzymy usługę z dwiema metodami, z których jedna jest synchroniczna, a druga asynchroniczna.
- Dodaj adnotację @EnableAsync do klasy Application
- Utwórz usługę z normalną metodą i @Async
- Zmodyfikuj komponent, aby wstrzykiwał i używał metod usługi
- Uruchom aplikację
src/main/java/com/sipios/example/mdc/Application.java
src/main/java/com/sipios/example/mdc/service/Example.java
src/main/java/com/sipios/example/mdc/Execute.java
Add taskExecutor in Application class
src/main/java/com/sipios/example/mdc/Application.java
Re-execute :
Jak widzimy, MDC w wątku asynchronicznym jest puste. W rzeczywistości każde zadanie asynchroniczne jest uruchamiane w nowym wątku. Każdy wątek jest połączony z Map MDC zainicjowanym przez executor zadania. Możliwe jest zagranie na tym executorze, aby uzyskać to samo MDC, co na głównym wątku. Dodajmy dekorator w asyncExecutor w celu zduplikowania MDC!
src/main/java/com/sipios/example/mdc/ExampleTaskDecorator.java
Set this decorator in async config
src/main/java/com/sipios/example/mdc/Application.java
Relaunch application
There you go! Możemy przekazać w logach cały kontekst jaki chcemy w zadaniach synchronicznych czy asynchronicznych.
Dzięki temu debugowanie aplikacji jest uproszczone i bardziej zrozumiałe. W ramach naszego projektu zaoszczędziło nam to sporo czasu w wymianie z naszymi współpracownikami. Teraz wszystko zależy od Ciebie 🙂
Bibliografia
- http://www.baeldung.com/mdc-in-log4j-2-logback
- https://spring.io/guides/gs/async-method/
- https://moelholm.com/2017/07/24/spring-4-3-using-a-taskdecorator-to-copy-mdc-data-to-async-threads/
.