fbpx
devstyle.pl - Blog dla każdego programisty
devstyle.pl - Blog dla każdego programisty
7 minut

Jak korzystam z poziomów logowania


09.03.2011

Pod jednym z moich ostatnich postów na temat logowania Jacek zasugerował w komentarzu abym napisał trochę więcej o tym jak dzielę logi na poszczególne poziomy.

Poniżej opis moich ZAMIERZEŃ. Zamierzeń, ponieważ jeszcze w ten sposób z logowania nie korzystałem, ale po dość długim rozmyślaniu wydaje mi się to najsensowniejszy podział. Może pojawią się uwagi korygujące takie podejście zanim wprowadzę je do projektu?:)

TRACE

Najbardziej szczegółowy poziom logowania. Tak szczegółowy, że nawet nie ma go w log4net (co jest jedną z głównych wad tego frameworka). Idealnie nadaje się to do zapisywania wszystkich możliwych aktywności systemu, na poziomie wywołania każdej jednej metody. Być może nawet z wartościami parametrów? I zwracanym obiektem?

Babranie się w ręczne dodawanie logowania w każdej metodzie to kara, jakiej nie zadałbym nawet praktykantowi, który wszedł na produkcyjny serwer i skasował bazę danych. Doskonale ten cel realizuje filozofia Aspect Oriented Programming. Można to osiągnąć dedykowanymi narzędziami do AOP (jak PostSharp) albo wykorzystując moc swojego kontenera DI. W moim przypadku zamierzam dodać tą odpowiedzialność do Autofac.

Oczywiście poziom ten włącza się w najbardziej drastycznych przypadkach, gdy wszystko inne zawodzi. Uruchomienie takiego czegoś na produkcji może skutkować dość znacznym spadkiem wydajności systemu i raczej szybszym niż wolniejszym zapchaniem całego dysku:).

DEBUG

Komunikaty "DEBUG" określiłbym mianem "komentarzy". Wiele już napisano o komentowaniu kodu, bardziej doświadczeni programiści mówią: komentarzy być nie powinno. Absolutnie się z tym zgadzam. Ale…

No właśnie, można być geniuszem w teorii, ale w praktyce trzeba się zmierzyć z zadaniem "znajdź bug w systemie bardziej skomplikowanym niż stronka WWW mając tylko logi". Niestety bez naprawdę porządnej dawki informacji jest to raczej niemożliwe. Dlatego też logami na poziomie DEBUG powinno się moim zdaniem plwać na prawo i lewo, wszędzie gdzie tylko można. Zdecydowanie lepiej więcej niż mniej. Jak się okaże że logi stają się z tego powodu nieczytelne to zawsze można takie logowanie stuningować, przez dokładniejszą konfigurację loggera bądź po prostu wywalenie zbędnego logowania z kodu.

Kilka przykładów:

  • start zadania wykonywanego w tle, na przykład "EmailSender started"
  • koniec powyższego zadania, jeśli nie miało nic do roboty, na przykład "EmailSender did not find any messages to send"
  • cząstkowe wykonanie takiego zadania, np. do wysłania czeka 10 wiadomości, to wysłanie KAŻDEJ z nich wrzuciłbym do logów DEBUG : "Attempting to send message {0}" oraz "Message {0} sent successfully"
  • wykonanie jakiegoś złożonego algorytmu z wynikiem tych obliczeń
  • próba pobrania danych z zewnętrznego źródła
  • heartbeat – w aplikacjach webowych co jakiś czas (np co minutę) walę do loga info o aktywności aplikacji; przydatne aby skontrolować czy aplikacja faktycznie cały czas działa (np czy coś na hostingu jej nie ubiło) a jeśli nie działa – to kiedy działać przestała
  • eccecera, eccecera…

Czy włączone na produkcji? Podczas testów systemu – tak. Podczas normalnego wykorzystania – zdecydowanie nie.

INFO

Jak sama nazwa wskazuje, INFO to informacje o akcjach zachodzących w systemie. Po otwarciu pliku z takimi logami chciałbym wiedzieć co faktycznie zostało wykonane, kto co zrobił i kiedy. Nie chciałbym jednak przebijać się przez czynności, które nie miały żadnego wpływu na aktualny stan aplikacji – od tego jest DEBUG.

Do INFO nadają się zatem moim zdaniem między innymi takie scenariusze:

  • start aplikacji z podsumowaniem inicjalizacji
  • fakt wykonywania zadania w tle, nawiązując do przykładu z DEBUG: "EmailSender found {0} pending messages. Attempting delivery."
  • zalogowanie/wylogowanie użytkownika, fakt zmiany hasła
  • próba zalogowania z nieprawidłowym hasłem
  • ważniejsze czynności administracyjne, jak zablokowanie konta użytkownika przez kogoś z większymi uprawnieniami
  • zakończenie długotrwałych procesów, np przetwarzania zamówienia
  • eccecera, eccecera…

Celem tego poziomu jest dla mnie możliwość włączenia go na produkcji w celu obserwacji normalnego zachowania systemu. Rzut okiem na kilka stron logów powinien mi powiedzieć czy wszystko jest raczej OK czy może coś wygląda podejrzanie. Nie można tam pchać zbyt wiele, ale musi być wystarczająco informacji aby ocenić co się aktualnie dzieje i dlaczego.

WARN

W skrócie: wszystko co jest podejrzane, ale nie powoduje poważnych zakłóceń w pracy aplikacji. W idealnie działającym systemie log ten powinien być pusty. Kilka scenariuszy w których bym go zastosował:

  • pierwszy timeout na bazie danych podczas wykonywania zadania "w tle" (nie error, bo system działa dalej i można dać szansę na ponowne wykonanie zapytania)
  • brak możliwości połączenia z zewnętrznym źródłem dostarczającym danych, bez których zdecydowanie można się obejść; na przykład box ściągający prognozę pogody z jakiejś innej strony? dobrze jest zwrócić uwagę jeśli źródło odmawia udzielenia takich informacji, ale wtedy możemy po prostu wyświetlić starszą prognozę bez panikowania; CHYBA ŻE tworzymy stronę, której głównym zadaniem jest wyświetlanie aktualnej prognozy pogody, wtedy oczywiście należy krzyczeć o wiele głośniej niż WARN:)
  • próba wejścia na "bezpieczną" stronę z nieprawidłowymi danymi; chodzi o strony, które wymagają czegoś więcej niż tylko adresu www, czyli np. potwierdzenie poprawności adresu email podczas rejestracji wg schematu: …/ConfirmEmail?email=some@email.com&token=6523-1232-3123-5467; po wejściu na ten link powinniśmy oznaczyć email jako poprawny i zakończyć proces rejestracji; jeżeli ktoś wchodzi na taki link, ale nie zgadza się jego "token" to mamy spore prawdopodobieństwo, że coś się skopało w wysyłanych przez nas mailach albo procedurze weryfikacyjnej, w końcu raczej nikt nie będzie przepisywał go ręcznie:)
  • eccecera, eccecera…

Na produkcji włączony i kontrolowany regularnie przez obsługę systemu. Powinny tam się jednak znajdować takie informacje, które wystarczy monitorować raz dziennie, czyli nie problemy w działaniu kluczowych komponentów systemu.

ERROR

Tutaj sytuacja jest najprostsza – w ERROR lądują wszystkie przechwycone – tak systemowe, jak i własne – wyjątki. Koniec kropka.

Dodatkowo w tym przypadku również zastosowałbym AOP do logiki, która może dostarczyć informacji niezbędnych wręcz do wykrycia błędu, czyli: wartości parametrów dostarczonych do metody. Nie polegałbym jednak na standardowym .ToString() – do logu z wywołania metody dołączyłbym po prostu całą tablicę parametrów zserializowaną do JSONa, żeby mieć pewność że posiadam tyle informacji ile tylko jest możliwe.

Zdecydowanie włączone na produkcji, prawdopodobnie skonfigurowane do zapisywania poprzez więcej niż jeden kanał (pewnie plik + baza + ewentualnie email do admina).

FATAL

Szczerze mówiąc tego jeszcze nigdy nie użyłem i nie wiem co można by tutaj wrzucić. Raczej błędy z tej rodziny i tak wywrócą aplikację i zostaną przez system zapisane w różne fajne miejsca samoczynnie (za mało pamięci, błąd dysku itd).

Ewentualnie można pokusić się o zapisanie z tym poziomem czynników, które powodują niemożność startu aplikacji – jak niepoprawna licencja czy błąd połączenia z wymaganymi zasobami… choć nie jestem przekonany czy to faktycznie FATAL czy może jeszcze ERROR.

Może jakieś pomysły?


A jak Wy to robicie?

Nie przegap kolejnych postów!

Dołącz do ponad 9000 programistów w devstyle newsletter!

Tym samym wyrażasz zgodę na otrzymanie informacji marketingowych z devstyle.pl (doh...). Powered by ConvertKit
Notify of
dario-g

He he :) Tak samo. U mnie wyszło to po prostu z opisu poziomów logowania w NLogu ;)

procent

@dario-g:
Muszę przyznać że nie wpadlem na poczytanie o tym na stronach loggerow, co faktycznie bylo glupie z mojej strony i niepotrzebnie marnowalem cykle wewnetrznego procesora na takie glupoty:)

twk
twk

Ja po prostu zaczynając korzystać z NLoga wydrukowałem sobie nad monitorem to: NLog supports the following log levels: Trace – very detailed logs, which may include high-volume information such as protocol payloads. This log level is typically only enabled during development Debug – debugging information, less detailed than trace, typically not enabled in production environment. Info – information messages, which are normally enabled in production environment Warn – warning messages, typically for non-critical issues, which can be recovered or which are temporary failures Error – error messages Fatal – very serious errors

jacek

Też zastanawiałem się trochę nad tematem i pytanie: czy nie warto by było dla publicznych metod dodać ich kolejne wywołania również w wyższym poziomie niż TRACE (lub niższym, zależy jak kto patrzy ;) Mozemy zastosowac ten sam mechanizm co dla Trace (AOP) i odpowiednio go sparametryzowac. Pomijamy wówczas wszystko co mniej istotne (internal,private, itd.) co będziemy logować na poziomie trace. W takim logu widzimy kolejne wywolania publicznych metod ktore obrazuje nam dzialanie samego programu na wyzszym poziomie. Mozna ewentualnie rowniez logowac wyjscia z tych metod (i zwracane wartosci). Co o tym myslicie ?

procent

@jacek:
Dla mnie takie coś pasowałoby pomiędzy TRACE a DEBUG, a nie ma żadnego "pomiędzy":). Poza tym… chyba by mi się w ogóle nie przydało. Jak przypominam sobie teraz sesje z czytaniem i analizą gigabajtowych logów to raczej nie widzę dla takiego rozwiązania zastosowania.

jakubin
jakubin

Dwie uwagi:
1) Wrzucanie parametrów metod do logów jest ryzykowne. Logu, który zawiera dane biznesowe z systemu produkcyjnego, raczej nikt nie przekaże programistom. Nie mówiąc już o danych osobowych. Uważam, że można to ew. robić na poziomie Debug/Verbose, w których wiadomo, że nigdy nie uruchomimy systemu produkcyjnego.

2) Ja używam FATAL do zalogowania błędu, który powoduje, że cały system lub jego część nie nadaje się do użycia. Np. utraciliśmy połączenie z feedem z bieżącymi danymi (notowanie giełdowe, aktualne stany, itp.) przez co spora część systemu wyświetla nieaktualne dane.

mnajman

Wartości parametrów metod w których wystąpił błąd mogą się bardzo przydać w wykryciu błędu w kodzie. Faktycznie, poziom Trace, który to umożliwia jest zbyt "grubym" rozwiązaniem. W przypadku ASP MVC można użyć globalnego filtra akcji, który nie spowoduje niepotrzebnego napompowania pliku logu. Zbyt mało tu miejsca na szczegółowy opis mojego rozwiązania, więc zapraszam na blog.

Szkolenie z testów

Facebook

Książka

Zobacz również