W przypadku gdy mamy jedną monolityczną aplikację śledzenie zdarzeń jest banalne. Najczęściej dorzucamy logger np. Slf4j i zapisujemy mniej lub bardziej krytyczne zdarzenia odbywające się w naszej aplikacji. o ile coś zawiedzie to w logach wyszukamy coś co przypomina nam błąd i dzięki temu łatwo możemy przeanalizować co się stało. Stosunkowo łatwo w takich aplikacjach odnaleźć jest też wąskie gardła (bottleneck).
Jednak takich aplikacji jest coraz mniej. Żyjemy w czasach gdzie postawienie kolejnego mikroserwisu jesteśmy w stanie wykonać w kilka minut. Analizowanie ruchu naszej aplikacji w takim rozproszonym systemie przestaje być już takie proste.
Załóżmy taki problem: mamy endpoint GET, który zwraca jakąś informację. Chcemy przeanalizować czemu czasami endpoint ten działo wolno.
Co to znaczy wolno?
To jest pytanie od którego powinniśmy zacząć. Dla jednych systemów wolno to będą setki milisekund, a dla innych kilka minut. Musimy się dowiedzieć „jakie jest” nasze wolno. Chcemy wiedzieć jaki jest średni czas wywołania takiej operacji.
Czytanie logów
Logi są naszym przyjacielem. Niestety jest to często trudna przyjaźń. o ile chcemy przeanalizować całą komunikację odbywającą się w naszym systemie podczas danej operacji to zwykle jest to dosyć trudne (w niektórych sytuacjach niemożliwe). Ilość informacji przez jaką musimy się przekopać, aby wyciągnąć jedynie te, które są nam aktualnie potrzebne jest ogromna. w uproszczeniu – zbadanie takiego problemu w ten sposób to zdecydowanie nie jest coś co chcielibyśmy robić.
Jeszcze gorzej o ile nasze logi ze wszystkich systemów nie są scentralizowane w jednym miejscu. Analizowanie przepływu procesu staje się udręką w przypadku złożonej architektury mikroserwisów. Logujemy się na siódmej instancji usługi B, aby dowiedzieć się, iż akurat to zapytanie zostało wykonane na instancji ósmej.
Jeżeli jednak mamy już takie jedno miejsce do którego lądują wszystkie logi to dalej problematyczne jest wyciągnięcie tych logów, które obrazują pełny przepływ tego jednego żądania.
Przykładowo dla naszego zapytania GET, które działa wolno chcielibyśmy zobaczyć wizualizację podobną do tej:
Na której jasno widzimy z jakimi systemami się komunikowaliśmy i ile czasu zajęła ta komunikacja.
Jeżeli byśmy byli w stanie tworzyć takie wizualizacje to w momencie gdy już zbierzemy trochę takich przykładowych zapytań będziemy w stanie wywnioskować czym jest nasze wolno i gdzie szukać przyczyny. Tak jak choćby w przypadku tego samego zapytania, ale wykonanego o innej godzinie:
Łatwo można zauważyć, iż chyba coś nie tak w serwisie D?
Widać więc, iż takie rozproszone śledzenie pomoże nam również w sytuacji gdy nasz system nie wykonał zapytania z powodu jakiegoś błędu.
Problem korelowania logów z różnych systemów
Musimy nasze zapytania w obrębie danego procesu w jakiś sposób ze sobą powiązać. Pierwsza myśl jaka może nam przyjść do głowy to nadanie unikalnego ID przy pierwszym wywołaniu procesu i przekazywanie tego ID do kolejnych systemów.
Ten REQUEST_ID powinien być następnie przypisywany do wszystkich logów, które nasze systemy wytwarzają. I w tym momencie teoretycznie możemy odpytać nasze scentralizowane logi, aby wyświetliły nam wszystkie takie logi dla których ten REQUEST_ID=123
Niestety podczas implementacji takiego rozwiązania natkniemy się na kilka problemów:
- W jaki sposób przekazywać ten REQUEST_ID do pozostałych systemów? Musimy dostosować każdy istniejący kontrakt lub przekazywać to w nagłówku co nie jest możliwe w przypadku wszystkich technologii.
- Co w przypadku zapytań asynchronicznych – jak przekazać kontekst?
- Co w przypadku kontynuacji procesu dzięki wywołania cron?
Rozwiązanie wydawało się dosyć proste, a jednak nie jest to takie trywialne.
B3 Propagation
Jest to standard wprowadzony przez OpenZipkin.
Narzuca on nie jeden, a cztery identyfikatory dzięki którym jesteśmy w stanie zidentyfikować przepływ naszego procesu.
W bardzo dużym skrócie:
- TraceID – identyfikator, który nie zmienia się podczas trwania całego procesu,
- SpanID – identyfikator konkretnego żądania (dla pierwszego żądania traceId == spanId),
- ParentSpanID – identyfikator poprzedniego żądania (SpanID systemu, który wywołał nasz system),
- Sampled – informacja czy dany trace jest próbkowany. Jest to mechanizm, który redukuje ilość danych, które zostaną zapisane w systemie odpowiedzialnym za sklejenie całego trace.
Bardziej szczegółowy opis możecie znaleźć tutaj.
Spring Cloud Sleuth
Jest to biblioteka, która automatycznie dodaje do naszych logów oraz zapytań do zewnętrznych systemów identyfikatory potrzebne do śledzenia procesu.
INFO [my-example-app2,f766af10373bcdc1,d2328e44d6047837,true] 9408 --- [nio-8081-exec-1] d.p.d.ExampleController [...]Gdzie my-example-app2 to wartość zmiennej:
spring.application.name=my-example-app2Natomiast f766af10373bcdc1 to traceId, a d2328e44d6047837 to spanId
Dla przykładu poniżej log z aplikacji, która wywołała tę operację:
INFO [my-example-app,f766af10373bcdc1,f766af10373bcdc1,true] 6772 --- [nio-8080-exec-1] d.p.d.ExampleControllerWidzimy tutaj, iż traceId == spanId, a więc jest to pierwsze żądanie w ramach tego przepływu procesu.
Identyfikatory są automatycznie dodawane do komunikacji kanałami:
- requests over messaging technologies like Apache Kafka or RabbitMQ (or any other Spring Cloud Stream binder
- HTTP headers received at Spring MVC controllers
- requests that pass through a Netflix Zuul microproxy
- requests made with the RestTemplate, etc.
Zipkin – wizualizacja całego procesu
Wiemy już, iż dzięki standardowi B3 Propagation jesteśmy w stanie odnaleźć wszystkie logi dotyczące interesującego nas procesu. Jednak na szczęście nie musimy robić tego manualnie.
Zróbmy szybkie dwie spring-bootowe aplikacje i stworzymy prostą komunikację między nimi. Pełny kod jest na githubie.
Pierwsza aplikacja:
@RestController @Slf4j public class ExampleController { private final RestTemplate restTemplate; public ExampleController(RestTemplate restTemplate) { this.restTemplate = restTemplate; } @GetMapping public String get() { log.info("my service is doing something"); return restTemplate.exchange("http://localhost:8081/", HttpMethod.GET, null, new ParameterizedTypeReference<String>() { }).getBody(); } }application.properties:
spring.application.name=my-example-appDruga aplikacja (na porcie 8081):
@RestController @Slf4j public class ExampleController { private final RestTemplate restTemplate; public ExampleController(RestTemplate restTemplate) { this.restTemplate = restTemplate; } @GetMapping public String get() throws InterruptedException { Thread.sleep(5000); log.info("Hi from second application"); return "hello"; } } }application.properties:
spring.application.name=my-example-app2Oczywiście oprócz standardowych zależności springboot’a potrzebne będzie jeszcze dodanie:
<dependency> <groupId>org.springframework.cloud</groupId> <artifactId>spring-cloud-starter-zipkin</artifactId> </dependency>Jest to zależność, która ma w sobie spring-cloud-sleuth oraz dodatkowo wysyła część logów do naszego (jeszcze nie istniejącego) Zipkina.
Oraz sam Zipkin:
@SpringBootApplication @EnableZipkinServer public class ZipkinServer { public static void main(String[] args) { SpringApplication.run(ZipkinServer.class, args); } }Domyślnie nasze aplikacje będą próbowały komunikować się z Zipkin na porcie 9411 dlatego ustawimy mu ten port w application.properties:
server.port=9411Jeszcze brakujące zależności:
<dependency> <groupId>io.zipkin.java</groupId> <artifactId>zipkin-server</artifactId> <version>2.11.7</version> </dependency> <dependency> <groupId>io.zipkin.java</groupId> <artifactId>zipkin-autoconfigure-ui</artifactId> <version>2.11.7</version> </dependency>I możemy uruchamiać aplikacje. Wejdźmy pod adres http://localhost:8080.
A następnie zobaczmy nasz proces w Zipkin pod adresem http://localhost:9411/zipkin/:
Widać dokładnie cały przepływ naszego procesu.
Inny przykład – niech teraz my-example-app2 uderza znowu do my-example-app, ale tym razem na adres, który nie istnieje.
Widzimy dzięki temu jak łatwo można zobaczyć w którym momencie proces zakończył się błędem. Co więcej, możemy zobaczyć czemu:
Konfiguracja Zipkin – kiedy przesyłać logi i w jaki sposób?
Sam Zipkin odbiera logi w różny sposób – po HTTP, poprzez kolejki, streamy. Nie musimy również zapisywać śledzenia dla wszystkich żądania. Właśnie tutaj potrzebny jest ten mechanizm Sampled, ponieważ dany proces może być zapisywany w Zipknie, albo nie być. Prawdopodobnie nie chcemy śledzić wszystkich żądań, a jedynie jakąś część.
Na pytanie zawarte w nagłówku mogę odpowiedzieć: to zależy. Trzeba po prostu przeanalizować to pod kątem naszego indywidualnego przypadku.
![317. WJUG - Andrus Adamchik - "DataFrame - a Swiss Army Knife of Java Data Processing" [English]](https://i1.ytimg.com/vi/ZGYtrooPVyk/maxresdefault.jpg)
