Mierz logi na zamiary

Każdy, kto podczas codziennej pracy opiekuje się jakąś aplikacją na pewno nie raz spotkał się z potrzebą przeszukiwania setek (lub setek tysięcy) wpisów w logu. Czy logi to najlepszy sposób na kontrolowanie stanu aplikacji? W dzisiejszym poście będę zachęcał do rezygnacji z nadmiarowych logów na rzecz miar.

Po co w ogóle pisać logi?

Logi pozwalają dodawać kontekst dla sytuacji, która wystąpiła. Szczególnie przydatne są podczas analizy problemu lub debugowania. 

Logowanie jednak często występuje “między wierszami” logiki aplikacji. Często jest też bagatelizowane albo traktowane po macoszemu.

A przecież fakt logowania wiąże się z dbaniem o:

W przypadku miar, kłopotów jest mniej,  ponieważ wartości liczbowe są czytelne i spójne, łatwiej zadbać o bezpieczeństwo, prywatność i cenzurę, a indeksowanie zastąpić można hierarchizacją. W wielu przypadkach pobieranie metryk zbiorczych może być wydajniejsze niż logowanie na standardowe wyjście. Nie pisałem o ograniczonym miejscu na dysku i zarządzaniu retencją, ponieważ te problemy trzeba rozwiązać niezależnie od formy zbierania danych z aplikacji.

Dodatkowym utrudnieniem w pracy z logami są poziomy logowania – szczególnie, jeśli chodzi o prostą i zrozumiałą definicję każdego z poziomów. 

Twórcy Go uznali, że ich standardowa biblioteka logująca – https://golang.org/pkg/log/ posiada tylko jeden poziom logowania – print, czyli informacje które chcesz przekazać użytkownikowi. Jeśli coś się nie uda masz też do dyspozycji fatal – jedna wiadomość zanim program zakończy swoje działanie.  Powstały oczywiście biblioteki którym to podejście się nie podoba i dodają poziomy (logrus, zap, glog, loggo) – ale czuję, że powielają one „stare, dobre standardy” – niczym log4j. Czy powinni zrobić więcej poziomów? To temat na oddzielny post ;)

Obserwacja działania aplikacji

Dla niektórych, mnogość logów aplikacji daje poczucie bezpieczeństwa. Wszystko działa, widzę co się dzieje i mogę prześledzić drogę każdego żądania.

Jeśli musisz wszystko logować, żeby mieć pewność, że aplikacja działa poprawnie to jest to sytuacja patologiczna

Detektyw Tomek pracuje nad aplikacją, która łączy się z systemem zewnętrznego dostawcy. W momencie, kiedy zewnętrzny system odpowiada błędami (co widać dobrze na wykresach) – Tomek dzwoni do dostawcy, celem wyjaśnienia awarii. Wtedy Tomek dowiaduje się, że dostawca błędu nie widzi. Tomek podaje godzinę i minutę w której zaczął występować problem – jednak jest to zbyt duży zakres czasu dla firmy zewnętrznej, ponieważ w ciągu 1 minuty, generują tak dużo logów, że nie są w stanie znaleźć przyczyny problemu – pojedyncze wpisy dotyczące błędu giną pośród tysięcy nieistotnych. Tomek dopiero po podaniu konkretnej sekundy występowania błędu – dostaje odpowiedź, że teraz firma potrzebuje 30 minut na analizę logów.

Nie logi, a wskaźniki biznesowe i miary techniczne powinny świadczyć o kondycji aplikacji. Co więcej – może właśnie bardzo przejrzysty i krótki log świadczy o tym, że wszystko z aplikacją jest w porządku? Pokuszę się o stwierdzenie: loguj tylko wtedy, kiedy coś nie działa poprawnie.

Miary uważam też za prostsze do analizy. Można je zwizualizować na wykresie – przez co są łatwiejsze do analizy i porównania. Wierzę, że każdy developer bez problemu posługuje się grepem i wyrażeniami regularnymi, więc wyszuka w logu wszystko czego dusza zapragnie. Jeśli jednak chcemy obserwować coś dostatecznie często, to ta technika staje się niepraktyczna, nieskalowalna i narażona na błędy (pewnego dnia zastosujemy inne filtry niż poprzednio). 

Miary dzielę na dwie główne grupy: techniczne i biznesowe. Obie kategorie mogą dawać jakiś obraz zdrowia naszej aplikacji.

Miary biznesowe

Rozmawiałem na temat dzisiejszego posta z kolegą, który przytoczył mi sytuację ze swojego zespołu. Ich aplikacja loguje informację o tym, że podana przez użytkownika fraza była wyszukiwana w indeksie zbyt długo – dzięki temu mogą sprawdzić czy fraza to np. losowe znaki, czy może fraza, która powinna zostać zoptymalizowana.

Zadałem mu pytanie, czy to na pewno powinien być log? Nie widzę nic złego w miarze, która pokazywałaby ogon zapytań, które długo trwały (zapytanie/czas-odpowiedzi):

Dzięki takiemu wykresowi mógłbym szybko zarekomendować zablokowanie zapytania “SELECT * FROM users” i optymalizację (albo przekierowanie) słowa “hiułałej” – które za pewne teraz przeszukuje cały indeks nie zwracając żadnego wyniku.

Miara z opowieści “z życia” jest z pogranicza tych biznesowych. Z całą pewnością ilość transakcji, ilość zalogowanych użytkowników lub ilość dodanych zdjęć jest jeszcze lepszym przykładem miary biznesowej.

Miary techniczne

Kolejki, pule wątków, statystyki pamięci podręcznej, utylizacja czasu procesora albo ilość zużywanej pamięci RAM – wszystko od programistów dla programistów!

Kilka przykładowych rekomendacji dotyczących popularnych przypadków logów które zamieniłbym na miary techniczne:

  • logi dotyczące zasobów – zrób metrykę, określ maksymalny próg (np. ilość wiszących połączeń, ilość miejsca na dysku) po przekroczeniu którego musisz zareagować. Co z tego jeśli pojawi się warning, że zajęte zostało 75% miejsca na dysku, jeśli dopiero przy 90% zachce Ci się zrobić porządek?
  • logi dotyczące API – na pewno wersjonujesz swoje publiczne endpointy – zrób więc metrykę pokazującą ilość odpytań wersji api (x) i identyfikatora klienta (y). Monitoruj trend – alarmuj kiedy wystąpi anomalia (np. trend używania niewspieranych endpointów jest rosnący). Logowanie wszystkich żądań w końcu obróci się przeciwko Tobie – https://github.com/dcos/dcos-diagnostics/pull/119
  • logi dotyczące normalnej pracy aplikacji – jeśli widzisz setki logów o podobnej treści, świadczącej o poprawnym działaniu aplikacji – na pewno można je zastąpić wykresem ilościowym (np. ilość przetworzonych transakcji).

Logi w prezencie od innych

Czasem znajdziemy się w sytuacji, kiedy wdrażamy oprogramowanie, którego nie jesteśmy autorami i nie możemy zmienić sposobu, w jaki raportuje o swoim stanie. Do tego celu powstał projekt https://github.com/google/mtail – dzięki któremu możemy w łatwy sposób zamienić log na miary. Czasem wystarczy też odrobina chęci – łatwo zrobić drobny PR w opensourcowym projekcie.

Podsumowanie

Zrób rachunek sumienia i odpowiedz sobie na pytanie: po co to loguję?.

Za każdym razem, kiedy będziesz chciał coś zalogować w dzienniku aplikacji – zastanów się, czy miara nie będzie lepszym pomysłem. 

Zachęcam do spróbowania metody 5 why:

Dlaczego chcesz to logować? 
Bo chcę wiedzieć, że dane zostały pobrane z cache. 

Czy potrzebujesz informacji dla jakiego klucza? 
Nie, chcę tylko wiedzieć czy cache działa.

Czy miara nie mogłaby w czytelny sposób pokazać liczby hit i miss w cache? 
Faktyczne, na metryce będzie to dobrze widać. Wykres pomoże nam łatwo określić, że coś jest nie tak jak powinno – a szczegółów błędów poszukamy w logach kiedy problem wystąpi. Gdyby jakaś sytuacja się powtarzała – można dodać dodatkową miarę – która pokaże nam konkretny problem: np. ilość wystąpień duplikacji kluczy cachowania. Zostawimy log na wszystkie inne przypadki, których jeszcze nie znamy i nie wiemy jak sobie z nimi poradzić.

Miary pozwalają łatwo dostrzec problem lub szybko sprawdzić czy system zachowuje się prawidłowo. Logi przydatne są dopiero kiedy coś się wydarzyło i trzeba dotrzeć do przyczyny problemu.



Autor Bartosz Gałek

Tak jak Obelix nie potrzebował magicznego napoju do bycia silnym, tak Bartosz nie potrzebuje kawy do tego, aby tryskać energią na prawo i lewo i zarażać nią zespół, któremu przewodzi jako Team Leader w Allegro.
Prywatnie, ogromny fan gier planszowych, zwolennik i współtwórca otwartego oprogramowania oraz ruchu DevOps.

2 thoughts on “Mierz logi na zamiary

Leave a Reply