Jak korzystam z poziomów logowania

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?