Dziennik pokładowy, cechy dobrego logowania - Programowanie jest łatwe

Nawet najprostszy program, w swojej ostatecznej formie, robi bardzo wiele rzeczy. Operuje wieloma wartościami cząstkowymi, które nie zawsze są wyświetlane użytkownikowi, a mogą mieć kluczowe znaczenie, np. przy szukaniu błędów albo doborze odpowiednich parametrów wejściowych. Wszystko, czego użytkownik ma nie widzieć a może się przydać, ląduje do dziennika programu, czyli logów.

Dziennik pokładowy, ang. logbook, źródło zdjęcia: https://en.wikipedia.org/wiki/Logbook Dziennik programu (ang. Logbook, czyli dziennik pokładowy, w skrócie log), czy w żargonie programistów, administratorów, devopsów i innych ludzi z branży- logi to kolejne linie tekstu z informacjami, co program robi w danym czasie. Te informacje są przygotowane oczywiście przez programistę, który podczas pisania programu natrafiając na ważne fragmenty kodu, według własnej opinii/uznania/przekonania, dodaje je do dziennika. Mogą to być sytuacje wyjątkowe, błędy podczas wykonywania się programu albo po prostu miejsca, w których wiedza o np. przetwarzanych wartościach, może się komuś przydać. Dziennik to zazwyczaj funkcja bądź obiekt, który przyjmuje kilka parametrów. W najprostszej wersji jest to po prostu ciąg znaków. Funkcja logująca umieszcza je na ekranie bądź w pliku, do późniejszego wglądu, nawet po zakończeniu działania programu. Klasycznym przykładem będzie log z serwera, który obsługuje połączenia. Cenną informacją, która może nas później interesować to adres, z jakiego przyszło połączenie, czas kiedy zostało nawiązane, czas rozłączenia i, dla przykładu, ilość przesłanych bajtów. Gdy serwer obsługuje jednego klienta może to być przerost formy nad treścią, jednak nawet przy kilku połączeniach taki dziennik pozwala lepiej rozeznać się w sytuacji.

Poziomy logowania

Duże programy mogą naprawdę sporo logować, wtedy przeglądanie wszystkich informacji może okazać się koszmarem, a samo logowanie mijać się z celem. Dlatego powszechną techniką jest podział zapisanych informacji do loga na ich priorytet. Wtedy, przy uruchamianiu programu (a czasami nawet podczas jego wykonywania się) można określić zakres informacji, które nas interesują. Jeżeli już istnieje stopniowanie poziomu logowania (ang. Log Level), zazwyczaj można spotkać się z trzema stopniami:

Stopniowanie powinno pozwalać na wyświetlanie informacji o wyższym priorytecie, gdy wybrano niższy poziom logowania. To znaczy, że jako użytkownik, wybierając poziom Warning, powinienem także otrzymać logi z poziomu Error. Debug powinno dostarczyć wszystkie wpisy. Pisząc aplikację na Android, programista ma do dyspozycji naprawdę szeroki wachlarz poziomów logowania bo aż sześć (od najwyższego priorytetu do najniższego): Assert, Error, Warn, Info, Debug, Verbose.

Co powinien zawierać log

Jak każdy dziennik, kod, który obsługuje logowanie powinien dołączać stempel czasu, czyli informację o dacie, i godzinie, w której zdarzenie zostało zapisane do dziennika (zalogowane). Informacja o milisekundach nie jest tutaj przesadzona, w końcu w ciągu jednej sekundy może wydarzyć się naprawdę wiele. Następnie warto zaznaczyć jaki jest priorytet wpisu, czyli poziom logowania (log level). Pozwoli to na sprawniejsze przeczesywania dziennika i zawężanie wyników wyszukiwania konkretnej informacji, jeżeli wpisów jest naprawdę dużo. Ostatnim podstawowym elementem jednego wpisu do dziennika jest informacja, czego dotyczy. Tutaj warto posługiwać się lakoniczną formą bezokolicznkową. Im krótsza i sensowna informacja tym lepiej. Należy pamiętać, że logi służą osobom zainteresowanym, nie stanowią sposobu na komunikację z aplikacją, więc dodatkowe opisy są zbędne. Jeżeli jednak posługujemy się np. kodami błędów, to moim zdaniem warto dodać etykietę do każdego, celem zwiększenia czytelności. Poza tymi trzema niezbędnymi informacjami, możemy wyposażyć dziennik o dodatkowe wpisy, jeżeli jest taka potrzeba. Warto jednak przestrzegać starych mądrości: co więcej od diabła pochodzi. Poniżej kilka przykładów logów z różnych programów (z każdego po jednej linii):

Log z Apache (serwer www):

172.17.0.1 - - [14/Jun/2017:10:57:25 +0000] "GET / HTTP/1.1" 200 24529 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36"

Syslog na Ubuntu 16.04:

Mar  6 21:58:21 taurus systemd[1]: Started User Manager for UID 1000.

Mysql (serwer baz danych):

2018-02-16T09:38:36.436363Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

Logcat (system logowania Android):

03-06 22:00:36.308 I/art     (  907): Explicit concurrent mark sweep GC freed 13222(643KB) AllocSpace objects, 0(0B) LOS objects, 24% free, 50MB/66MB, paused 3.082ms total 172.332ms

Przechowywanie logów

Jeżeli to program decyduje o miejscu przechowania dziennika i nomenklaturze nazewnictwa, należy rozważyć czy dziennik powinien wszystko przechowywać w jednym miejscu, np. jednym pliku o nazwie log.txt) czy w wielu miejscach, np. każde uruchomienie programu, tworzące osobny plik z logiem, który w nazwie będzie przechowywać stempel czasu (log-20180307-193232.txt). Jeżeli program będzie uruchamiany wiele razy, ilość plików może się nagromadzić i zająć więcej miejsca na dysku, niż faktycznie przechowuje danych. Z drugiej strony, miałem kiedyś okazję szukać czegoś w pliku z logami, który zajmował ponad 1GB miejsca na dysku- prawdziwie kowbojska przygoda, nie polecam. Czasami logi przechowywane są w bazie danych, np. gdy przeszukiwanie logów jest częstym elementem całej infrastruktury systemu. Chociażby w sytuacji, gdy z logów (metadanych) wysysane są inne informacje. Systemy z rodziny Unix/Linux posiadają (syslog)[https://pl.wikipedia.org/wiki/Syslog]- mechanizm do zapisywania logów w dzienniku systemowym. Syslog udostępnia interface dla programisty i umożliwia tworzenie wpisów, które są zarządzane przez system. Z tego rozwiązania korzystają aplikacje, które świadczą usługi i działają w tle jako demony (czyli programy, które po uruchomieniu nie dostarczają interface’u do komunikacji z nimi). W innych przypadkach korzystanie z syslogu nie jest dobrą praktyką.

Czy logi mogą stwarzać problemy

Logowanie to część programu, czyli algorytm, który wykonuje się podczas działania aplikacji. Jak każda czynność, zajmuje czas procesora. Jeżeli logowana jest bardzo duża ilość danych, może ono spowolnić działanie programu. W przypadku urządzeń korzystających z wewnętrznego zasilania może to znacząco wpływać na czas pracy na baterii. Jeżeli chodzi o ilość zajmowanego miejsca, to w większości przypadków nie jest to problem, chyba, że tworzymy program na urządzenia przenośne, w których przestrzeń dyskowa jest mocno ograniczona. Dodatkowo warto pamiętać, że ilość zajmowanego miejsca na dysku (fizycznie) różni się od wielkości pliku. Pusty plik może zajmować 16KB miejsca na dysku albo i więcej (metadane o pliku). Gdy utworzymy tysiące małych plików z logami, łącznie mogą zajmować naprawdę sporą przestrzeń.

Logowanie to temat rzeka. Jak większość rzeczy w świecie programowania - nie ma idealnego rozwiązania i zawsze jest to kwestia kompromisu. Nie mniej jednak warto logować, to taka druga para oczu programisty. Jakie masz doświadczenia z logowaniem? Co byś zalecał tworząc własny dziennik i z czym miałeś najwięcej problemów, gdy zajmowałeś się logami? A może masz jakąś ciekawą historię/interesujący log, którym możesz się podzielić?

Dodano: 2018-03-06 09:19 przez Piotr Poźniak

log , dziennik , logowanie , syslog , warn , debug , error ,
Piotr Poźniak
O autorze:

Programuję od ponad 15 lat. Prowadzę software house. Angażuję i zachęcam wszystkich do programowania w ramach inicjatywy Programowanie jest łatwe.