Jak najlepiej wykorzystać pliki dziennika PHP: praktyczny przewodnik

Opublikowany: 2022-03-11

Można słusznie powiedzieć, że logi są jednym z najbardziej niedocenianych i niedostatecznie wykorzystywanych narzędzi do dyspozycji niezależnego programisty php. Pomimo bogactwa informacji, jakie mogą zaoferować, często zdarza się, że logi są ostatnim miejscem, w którym programista szuka rozwiązania problemu.

W rzeczywistości pliki dziennika PHP powinny w wielu przypadkach być pierwszym miejscem, w którym należy szukać wskazówek, gdy wystąpią problemy. Często informacje, które zawierają, mogą znacznie skrócić czas spędzany na wyrywaniu włosów, próbując wyśledzić sękaty błąd.

Ale być może co ważniejsze, przy odrobinie kreatywności i przezorności, Twoje pliki dzienników mogą służyć jako cenne źródło informacji o użytkowaniu i analiz. Kreatywne wykorzystanie plików dziennika może pomóc w uzyskaniu odpowiedzi na takie pytania, jak: Jakie przeglądarki są najczęściej używane do odwiedzania mojej witryny? Jaki jest średni czas odpowiedzi z mojego serwera? Jaki był procent żądań do katalogu głównego witryny? Jak zmieniło się użycie od czasu wdrożenia najnowszych aktualizacji? I dużo dużo więcej.

Pliki dziennika PHP

Ten artykuł zawiera szereg wskazówek dotyczących konfigurowania plików dziennika, a także przetwarzania zawartych w nich informacji, aby zmaksymalizować korzyści, jakie zapewniają.

Chociaż ten artykuł skupia się technicznie na logowaniu dla programistów PHP, wiele z przedstawionych tu informacji jest dość agnostycznych dla technologii i odnosi się również do innych języków i stosów technologii.

Uwaga: Ten artykuł zakłada podstawową znajomość powłoki Unix. Dla tych, którzy nie mają tej wiedzy, udostępniono dodatek, który przedstawia niektóre polecenia potrzebne do uzyskania dostępu i odczytu plików dziennika w systemie Unix.

Nasz przykładowy projekt pliku dziennika PHP

Jako przykładowy projekt do celów dyskusji w tym artykule, weźmiemy Symfony Standard jako działający projekt i skonfigurujemy go na Debianie 7 Wheezy z rsyslogd , nginx i PHP-FPM .

 composer create-project symfony/framework-standard-edition my "2.6.*"

To szybko daje nam działający projekt testowy z ładnym interfejsem użytkownika.

Wskazówki dotyczące konfiguracji plików dziennika

Oto kilka wskazówek, jak skonfigurować pliki dziennika, aby zmaksymalizować ich wartość.

Konfiguracja dziennika błędów

Dzienniki błędów stanowią najbardziej podstawową formę rejestrowania; tj. przechwytywanie dodatkowych informacji i szczegółów w przypadku wystąpienia problemów. Tak więc w idealnym świecie chciałbyś, aby nie było błędów, a dzienniki błędów były puste. Ale gdy pojawią się problemy (co zawsze się dzieje), twoje dzienniki błędów powinny być jednym z pierwszych przystanków na ścieżce debugowania.

Dzienniki błędów są zazwyczaj dość łatwe do skonfigurowania.

Po pierwsze, wszystkie komunikaty o błędach i awariach mogą być rejestrowane w dzienniku błędów w dokładnie takim samym formacie, w jakim byłyby prezentowane użytkownikowi. Dzięki prostej konfiguracji użytkownik końcowy nigdy nie będzie musiał widzieć tych brzydkich śladów błędów w Twojej witrynie, podczas gdy devops nadal będzie mógł monitorować system i przeglądać te komunikaty o błędach we wszystkich ich krwawych szczegółach. Oto jak skonfigurować ten rodzaj logowania w PHP:

 log_errors = On error_reporting = E_ALL error_log = /path/to/my/error/log

Kolejne dwa wiersze, które należy uwzględnić w pliku dziennika działającej witryny, aby uniemożliwić wyświetlanie użytkownikom krwawych poziomów szczegółów błędów, to:

 display_errors = Off display_startup_errors = Off

Dziennik systemowy ( syslog ) Konfiguracja

Istnieje wiele ogólnie kompatybilnych implementacji demona syslog w świecie open source, w tym:

  • syslogd i sysklogd – najczęściej spotykane w systemach z rodziny BSD, CentOS, Mac OS X i innych
  • syslog-ng – domyślny dla nowoczesnych kompilacji Gentoo i SuSE
  • rsyslogd – szeroko stosowany w rodzinach systemów operacyjnych Debian i Fedora

(Uwaga: w tym artykule będziemy używać rsyslogd dla naszych przykładów.)

Podstawowa konfiguracja sysloga jest generalnie wystarczająca do przechwytywania komunikatów dziennika w ogólnosystemowym pliku dziennika (zwykle /var/log/syslog ; może to być również /var/log/messages lub /var/log/system.log w zależności od dystrybucji używasz).

Dziennik systemowy udostępnia kilka funkcji dziennika, z których osiem ( od LOG_LOCAL0 do LOG_LOCAL7 ) jest zarezerwowanych dla projektów wdrożonych przez użytkownika. Oto, na przykład, jak skonfigurować LOG_LOCAL0 , aby zapisywał w 4 oddzielnych plikach dziennika, w oparciu o poziom rejestrowania (tj. błąd, ostrzeżenie, informacje, debugowanie):

 # /etc/rsyslog.d/my.conf local0.err /var/log/my/err.log local0.warning /var/log/my/warning.log local0.info -/var/log/my/info.log local0.debug -/var/log/my/debug.log

Teraz, za każdym razem, gdy napiszesz komunikat dziennika do obiektu LOG_LOCAL0 , komunikaty o błędach trafią do /var/log/my/err.log , komunikaty ostrzegawcze do /var/log/my/warning.log i tak dalej. Należy jednak pamiętać, że demon syslog filtruje wiadomości dla każdego pliku w oparciu o zasadę „tego poziomu i wyższego”. Tak więc w powyższym przykładzie wszystkie komunikaty o błędach pojawią się we wszystkich czterech skonfigurowanych plikach, komunikaty ostrzegawcze pojawią się we wszystkich oprócz dziennika błędów, komunikaty informacyjne pojawią się w dziennikach informacji i debugowania, a komunikaty debugowania będą trafiać tylko do debug.log .

Jedna dodatkowa ważna uwaga; Znaki - przed plikami poziomu informacji i debugowania w powyższym przykładzie pliku konfiguracyjnego wskazują, że zapisy do tych plików powinny być wykonywane asynchronicznie (ponieważ te operacje nie blokują). Jest to zazwyczaj dobre (a nawet zalecane w większości sytuacji) w przypadku dzienników informacji i debugowania, ale najlepiej jest, aby zapisy w dzienniku błędów (i najprawdopodobniej także w dzienniku ostrzeżeń) były synchroniczne.

Aby zamknąć mniej ważny poziom logowania (np. na serwerze produkcyjnym), możesz po prostu przekierować powiązane komunikaty do /dev/null (tj. donikąd):

 local0.debug /dev/null # -/var/log/my/debug.log

Jednym ze szczególnych dostosowań, które jest przydatne, szczególnie do obsługi parsowania plików dziennika PHP, które omówimy w dalszej części tego artykułu, jest użycie tabulatora jako znaku ogranicznika w komunikatach dziennika. Można to łatwo zrobić, dodając następujący plik w /etc/rsyslog.d :

 # /etc/rsyslog.d/fixtab.conf $EscapeControlCharactersOnReceive off

I na koniec, nie zapomnij zrestartować demona syslog po wprowadzeniu jakichkolwiek zmian w konfiguracji, aby zaczęły obowiązywać:

 service rsyslog restart

Konfiguracja dziennika serwera

W przeciwieństwie do dzienników aplikacji i dzienników błędów, do których można zapisywać, dzienniki serwera są zapisywane wyłącznie przez odpowiednie demony serwera (np. serwer WWW, serwer bazy danych itp.) przy każdym żądaniu. Jedyną „kontrolą”, jaką masz nad tymi dziennikami, jest to, że serwer umożliwia skonfigurowanie funkcji rejestrowania. Chociaż w tych plikach może być wiele do przeszukania, często są one jedynym sposobem, aby uzyskać jasny obraz tego, co dzieje się „pod maską” z serwerem.

Wdróżmy naszą przykładową aplikację Symfony Standard w środowisku nginx z zapleczem pamięci masowej MySQL. Oto konfiguracja hosta nginx, której będziemy używać:

 server { server_name my.log-sandbox; root /var/www/my/web; location / { # try to serve file directly, fallback to app.php try_files $uri /app.php$is_args$args; } # DEV # This rule should only be placed on your development environment # In production, don't include this and don't deploy app_dev.php or config.php location ~ ^/(app_dev|config)\.php(/|$) { fastcgi_pass unix:/var/run/php5-fpm.sock; fastcgi_split_path_info ^(.+\.php)(/.*)$; include fastcgi_params; fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name; fastcgi_param HTTPS off; } # PROD location ~ ^/app\.php(/|$) { fastcgi_pass unix:/var/run/php5-fpm.sock; fastcgi_split_path_info ^(.+\.php)(/.*)$; include fastcgi_params; fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name; fastcgi_param HTTPS off; # Prevents URIs that include the front controller. This will 404: # http://domain.tld/app.php/some-path # Remove the internal directive to allow URIs like this internal; } error_log /var/log/nginx/my_error.log; access_log /var/log/nginx/my_access.log; }

W odniesieniu do dwóch ostatnich dyrektyw powyżej: access_log reprezentuje ogólny dziennik żądań, podczas gdy error_log dotyczy błędów, i tak jak w przypadku dzienników błędów aplikacji, warto skonfigurować dodatkowe monitorowanie, aby otrzymywać powiadomienia o problemach, dzięki czemu możesz szybko zareagować.

Uwaga: jest to celowo uproszczony plik konfiguracyjny nginx, który jest udostępniany tylko w celach przykładowych. Nie zwraca prawie żadnej uwagi na bezpieczeństwo i wydajność i nie powinien być używany w takim stanie, w jakim jest w żadnym „prawdziwym” środowisku.

To właśnie otrzymujemy w /var/log/nginx/my_access.log po wpisaniu http://my.log-sandbox/app_dev.php/ w przeglądarce i naciśnięciu Enter .

 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /app_dev.php/ HTTP/1.1" 200 6715 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/framework/css/body.css HTTP/1.1" 200 6657 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/framework/css/structure.css HTTP/1.1" 200 1191 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/acmedemo/css/demo.css HTTP/1.1" 200 2204 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/acmedemo/images/welcome-quick-tour.gif HTTP/1.1" 200 4770 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/acmedemo/images/welcome-demo.gif HTTP/1.1" 200 4053 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /bundles/acmedemo/images/welcome-configure.gif HTTP/1.1" 200 3530 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:28 +0300] "GET /favicon.ico HTTP/1.1" 200 6518 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36" 192.168.56.1 - - [26/Apr/2015:16:13:30 +0300] "GET /app_dev.php/_wdt/e50d73 HTTP/1.1" 200 13265 "http://my.log-sandbox/app_dev.php/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36"

To pokazuje, że w celu obsługi jednej strony przeglądarka faktycznie wykonuje 9 wywołań HTTP. 7 z nich to jednak żądania treści statycznych, które są proste i lekkie. Jednak nadal zajmują zasoby sieciowe i to można zoptymalizować za pomocą różnych sprite'ów i technik minifikacji.

Chociaż te optymalizacje zostaną omówione w innym artykule, istotne jest tutaj to, że możemy oddzielnie rejestrować żądania dotyczące zawartości statycznej, używając dla nich innej dyrektywy location :

 location ~ \.(jpg|jpeg|gif|png|ico|css|zip|tgz|gz|rar|bz2|pdf|txt|tar|wav|bmp|rtf|js)$ { access_log /var/log/nginx/my_access-static.log; }

Pamiętaj, że location nginx wykonuje proste dopasowywanie wyrażeń regularnych, dzięki czemu możesz uwzględnić tyle rozszerzeń treści statycznych, ile chcesz wysłać w swojej witrynie.

Analiza takich dzienników nie różni się od analizowania dzienników aplikacji.

Inne logi, o których warto wspomnieć

Dwa inne dzienniki PHP, o których warto wspomnieć, to dziennik debugowania i dziennik przechowywania danych.

Dziennik debugowania

Inną wygodną rzeczą dotyczącą dzienników nginx jest dziennik debugowania. Możemy go włączyć, zamieniając wiersz error_log w konfiguracji na następujący (wymaga zainstalowania modułu debugowania nginx):

 error_log /var/log/nginx/my_error.log debug;

To samo ustawienie dotyczy Apache lub dowolnego innego używanego serwera WWW.

Nawiasem mówiąc, dzienniki debugowania nie są powiązane z dziennikami błędów, mimo że są skonfigurowane w dyrektywie error_log .

Chociaż dziennik debugowania może być rzeczywiście szczegółowy (na przykład pojedyncze żądanie nginx wygenerowało 127 KB danych dziennika!), nadal może być bardzo przydatne. Przedzieranie się przez plik dziennika może być kłopotliwe i nużące, ale często może szybko dostarczyć wskazówek i informacji, które znacznie przyśpieszą proces debugowania.

W szczególności dziennik debugowania może naprawdę pomóc w debugowaniu konfiguracji nginx, zwłaszcza najbardziej skomplikowanych części, takich jak dopasowywanie location i rewrite łańcuchów.

Oczywiście dzienniki debugowania nigdy nie powinny być włączane w środowisku produkcyjnym. Ilość zajmowanego przez nie miejsca oraz ilość przechowywanych informacji oznacza duże obciążenie I/O na serwerze, co może znacząco obniżyć wydajność całego systemu.

Dzienniki przechowywania danych

Innym rodzajem dziennika serwera (przydatnym do debugowania) są dzienniki przechowywania danych. W MySQL możesz je włączyć, dodając te wiersze:

 [mysqld] general_log = 1 general_log_file = /var/log/mysql/query.log

Dzienniki te zawierają po prostu listę zapytań uruchamianych przez system podczas obsługi żądań bazy danych w porządku chronologicznym, co może być pomocne w przypadku różnych potrzeb związanych z debugowaniem i śledzeniem. Jednak nie powinny pozostać włączone w systemach produkcyjnych, ponieważ będą generować dodatkowe niepotrzebne obciążenie we/wy, co wpływa na wydajność.

Zapisywanie do plików dziennika

Sam PHP udostępnia funkcje do otwierania, zapisywania i zamykania plików dziennika (odpowiednio openlog() , syslog() i closelog() ).

Istnieją również liczne biblioteki rejestrujące dla programistów PHP, takie jak Monolog (popularne wśród użytkowników Symfony i Laravel), a także różne implementacje specyficzne dla frameworka, takie jak możliwości rejestrowania wbudowane w CakePHP. Ogólnie rzecz biorąc, biblioteki takie jak Monolog nie tylko zawijają wywołania syslog() , ale także umożliwiają korzystanie z innych funkcji i narzędzi zaplecza.

Oto prosty przykład, jak pisać do dziennika:

 <?php openlog(uniqid(), LOG_ODELAY, LOG_LOCAL0); syslog(LOG_INFO, 'It works!');

Nasz apel tutaj do openlog :

  • konfiguruje PHP tak, aby dołączał unikalny identyfikator do każdego komunikatu dziennika systemowego w czasie życia skryptu
  • ustawia go tak, aby opóźniał otwarcie połączenia syslog do momentu wystąpienia pierwszego wywołania syslog()
  • ustawia LOG_LOCAL0 jako domyślną funkcję logowania

Oto jak wyglądałaby zawartość pliku dziennika po uruchomieniu powyższego kodu:

 # cat /var/log/my/info.log Mar 2 00:23:29 log-sandbox 54f39161a2e55: It works!

Maksymalizacja wartości plików dziennika PHP

Teraz, gdy wszyscy jesteśmy dobrzy z teorią i podstawami, zobaczmy, ile możemy uzyskać z dzienników, dokonując jak najmniejszej liczby zmian w naszym przykładowym projekcie Symfony Standard.

Najpierw utwórzmy skrypty src/log-begin.php (aby poprawnie otwierać i konfigurować nasze logi) oraz src/log-end.php (aby logować informacje o pomyślnym zakończeniu). Zwróć uwagę, że dla uproszczenia po prostu zapiszemy wszystkie wiadomości w dzienniku informacyjnym.

 # src/log-begin.php <?php define('START_TIME', microtime(true)); openlog(uniqid(), LOG_ODELAY, LOG_LOCAL0); syslog(LOG_INFO, 'BEGIN'); syslog(LOG_INFO, "URI\t{$_SERVER['REQUEST_URI']}"); $browserHash = substr(md5($_SERVER['HTTP_USER_AGENT']), 0, 7); syslog(LOG_INFO, "CLIENT\t{$_SERVER['REMOTE_ADDR']}\t{$browserHash}"); <br /> # src/log-end.php <?php syslog(LOG_INFO, "DISPATCH TIME\t" . round(microtime(true) - START_TIME, 2)); syslog(LOG_INFO, 'END');

I wymagajmy tych skryptów w app.php :

 <?php require_once(dirname(__DIR__) . '/src/log-begin.php'); syslog(LOG_INFO, "MODE\tPROD"); # original app.php contents require_once(dirname(__DIR__) . '/src/log-end.php');

Dla środowiska programistycznego chcemy również wymagać tych skryptów w app_dev.php . Kod do tego byłby taki sam jak powyżej, z wyjątkiem tego, że ustawilibyśmy MODE na DEV , a nie PROD .

Chcemy również śledzić, jakie kontrolery są wywoływane, więc dodajmy jeszcze jedną linię w Acme\DemoBundle\EventListener\ControllerListener , na samym początku metody ControllerListener::onKernelController() :

 syslog(LOG_INFO, "CONTROLLER\t" . get_class($event->getController()[0]));

Zauważ, że te zmiany to zaledwie 15 dodatkowych linijek kodu, ale łącznie mogą dostarczyć wielu informacji.

Analiza danych w plikach dziennika

Na początek zobaczmy, ile żądań HTTP jest wymaganych do obsługi każdego ładowania strony.

Oto informacje w dziennikach dla jednego żądania, na podstawie sposobu, w jaki skonfigurowaliśmy nasze rejestrowanie:

 Mar 3 12:04:20 log-sandbox 54f58724b1ccc: BEGIN Mar 3 12:04:20 log-sandbox 54f58724b1ccc: URI /app_dev.php/ Mar 3 12:04:20 log-sandbox 54f58724b1ccc: CLIENT 192.168.56.1 1b101cd Mar 3 12:04:20 log-sandbox 54f58724b1ccc: MODE DEV Mar 3 12:04:23 log-sandbox 54f58724b1ccc: CONTROLLER Acme\DemoBundle\Controller\WelcomeController Mar 3 12:04:25 log-sandbox 54f58724b1ccc: DISPATCH TIME 4.51 Mar 3 12:04:25 log-sandbox 54f58724b1ccc: END Mar 3 12:04:25 log-sandbox 54f5872967dea: BEGIN Mar 3 12:04:25 log-sandbox 54f5872967dea: URI /app_dev.php/_wdt/59b8b6 Mar 3 12:04:25 log-sandbox 54f5872967dea: CLIENT 192.168.56.1 1b101cd Mar 3 12:04:25 log-sandbox 54f5872967dea: MODE DEV Mar 3 12:04:28 log-sandbox 54f5872967dea: CONTROLLER Symfony\Bundle\WebProfilerBundle\Controller\ProfilerController Mar 3 12:04:29 log-sandbox 54f5872967dea: DISPATCH TIME 4.17 Mar 3 12:04:29 log-sandbox 54f5872967dea: END

Teraz wiemy, że każde ładowanie strony jest w rzeczywistości obsługiwane przez dwa żądania HTTP.

Właściwie są tu dwie kwestie, o których warto wspomnieć. Po pierwsze, dwa żądania na ładowanie strony dotyczą używania Symfony w trybie deweloperskim (co zrobiłem w tym artykule). Możesz zidentyfikować wywołania trybu deweloperskiego, wyszukując fragmenty adresów URL /app-dev.php/ . Po drugie, powiedzmy, że każde ładowanie strony jest obsługiwane z dwoma kolejnymi żądaniami do aplikacji Symfony. Jak widzieliśmy wcześniej w dziennikach dostępu nginx, w rzeczywistości jest więcej wywołań HTTP, z których niektóre dotyczą zawartości statycznej.

OK, teraz zajrzyjmy trochę na stronę demonstracyjną (aby zgromadzić dane w plikach logów) i zobaczmy, czego jeszcze możemy się nauczyć z tych logów.

Ile żądań zostało w sumie obsłużonych od początku pliku dziennika?

 # grep -c BEGIN info.log 10

Czy któryś z nich się nie powiódł (czy skrypt wyłączył się, nie dochodząc do końca)?

 # grep -c END info.log 10

Widzimy, że liczba rekordów BEGIN i END jest taka sama, więc mówi nam to, że wszystkie połączenia zakończyły się powodzeniem. (Jeśli skrypt PHP nie zakończyłby się pomyślnie, nie osiągnąłby wykonania skryptu src/log-end.php ).

Jaki był procent żądań do katalogu głównego witryny?

 # `grep -cE "\s/app_dev.php/$" info.log` 2

To mówi nam, że w katalogu głównym witryny były załadowane 2 strony. Ponieważ wcześniej dowiedzieliśmy się, że (a) przy każdym załadowaniu strony są 2 żądania do aplikacji i (b) łącznie było 10 żądań HTTP, odsetek żądań do katalogu głównego witryny wyniósł 40% (tj. 2x2/10).

Która klasa kontrolera jest odpowiedzialna za obsługę żądań do katalogu głównego witryny?

 # grep -E "\s/$|\s/app_dev.php/$" info.log | head -n1 Mar 3 12:04:20 log-sandbox 54f58724b1ccc: URI /app_dev.php/ # grep 54f58724b1ccc info.log | grep CONTROLLER Mar 3 12:04:23 log-sandbox 54f58724b1ccc: CONTROLLER Acme\DemoBundle\Controller\WelcomeController

Tutaj użyliśmy unikalnego identyfikatora żądania, aby sprawdzić wszystkie komunikaty dziennika związane z tym pojedynczym żądaniem. W ten sposób udało nam się ustalić, że klasą kontrolera odpowiedzialną za obsługę żądań do katalogu głównego witryny jest Acme\DemoBundle\Controller\WelcomeController .

Którzy klienci z adresami IP podsieci 192.168.0.0/16 uzyskali dostęp do witryny?

 # grep CLIENT info.log | cut -d":" -f4 | cut -f2 | sort | uniq 192.168.56.1

Zgodnie z oczekiwaniami w tym prostym przypadku testowym tylko mój komputer główny uzyskał dostęp do witryny. Jest to oczywiście bardzo uproszczony przykład, ale jego zdolność (możliwość analizy źródeł ruchu do Twojej witryny) jest oczywiście dość potężna i ważna.

Ile ruchu do mojej witryny pochodzi z FireFox?

Mając 1b101cd jako hash mojego agenta użytkownika przeglądarki Firefox, mogę odpowiedzieć na to pytanie w następujący sposób:

 # grep -c 1b101cd info.log 8 # grep -c CLIENT info.log 10

Odpowiedź: 80% (tj. 8/10)

Jaki jest procent żądań, które spowodowały powolną odpowiedź?

Na potrzeby tego przykładu zdefiniujemy „wolno” jako odpowiedź trwającą dłużej niż 5 sekund. Odpowiednio:

 # grep "DISPATCH TIME" info.log | grep -cE "\s[0-9]{2,}\.|\s[5-9]\." 2

Odpowiedź: 20% (tj. 2/10)

Czy ktoś kiedykolwiek podał parametry GET?

 # grep URI info.log | grep \?

Nie, standard Symfony używa tylko slugów URL, więc to również mówi nam, że nikt nie próbował włamać się na stronę.

To tylko kilka stosunkowo szczątkowych przykładów sposobów kreatywnego wykorzystania plików dzienników w celu uzyskania cennych informacji o użytkowaniu, a nawet podstawowych analiz.

Inne rzeczy, o których warto pamiętać

Bezpieczeństwo rzeczy

Kolejne heads-up dotyczy bezpieczeństwa. Możesz pomyśleć, że prośby o rejestrację to dobry pomysł, w większości przypadków rzeczywiście tak jest. Jednak ważne jest, aby zachować szczególną ostrożność podczas usuwania potencjalnie poufnych informacji o użytkowniku przed zapisaniem ich w dzienniku.

Walka z rozrostem pliku dziennika

Ponieważ pliki dziennika to pliki tekstowe, do których zawsze dołącza się informacje, stale rosną. Ponieważ jest to dobrze znany problem, istnieje kilka dość standardowych metod kontrolowania wzrostu pliku dziennika.

Najłatwiej jest obracać kłody . Obracanie dzienników oznacza:

  • Okresowe zastępowanie dziennika nowym pustym plikiem do dalszego zapisu
  • Przechowywanie starego pliku dla historii
  • Usuwanie plików, które „przestarzały się” wystarczająco, aby zwolnić miejsce na dysku
  • Upewnienie się, że aplikacja może zapisywać dzienniki w sposób ciągły po wystąpieniu tych zmian w plikach

Najpopularniejszym rozwiązaniem jest logrotate , który jest dostarczany z preinstalowaną większością dystrybucji *nix. Zobaczmy prosty plik konfiguracyjny do obracania naszych logów:

 /var/log/my/debug.log /var/log/my/info.log /var/log/my/warning.log /var/log/my/error.log { rotate 7 daily missingok notifempty delaycompress compress sharedscripts postrotate invoke-rc.d rsyslog rotate > /dev/null endscript }

Innym, bardziej zaawansowanym podejściem jest sprawienie, by sam rsyslogd zapisywał wiadomości do plików, tworzonych dynamicznie na podstawie bieżącej daty i czasu. To nadal wymagałoby niestandardowego rozwiązania do usuwania starszych plików, ale pozwala Devops precyzyjnie zarządzać ramami czasowymi dla każdego pliku dziennika. Dla naszego przykładu:

 $template DynaLocal0Err, "/var/log/my/error-%$NOW%-%$HOUR%.log" $template DynaLocal0Info, "/var/log/my/info-%$NOW%-%$HOUR%.log" $template DynaLocal0Warning, "/var/log/my/warning-%$NOW%-%$HOUR%.log" $template DynaLocal0Debug, "/var/log/my/debug-%$NOW%-%$HOUR%.log" local1.err -?DynaLocal0Err local1.info -?DynaLocal0Info local1.warning -?DynaLocal0Warning local1.debug -?DynaLocal0Debug

W ten sposób rsyslog co godzinę utworzy osobny plik dziennika i nie będzie potrzeby ich obracania i restartowania demona. Oto jak można usunąć pliki dziennika starsze niż 5 dni, aby wykonać to rozwiązanie:

 find /var/log/my/ -mtime +5 -print0 | xargs -0 rm

Dzienniki zdalne

W miarę rozwoju projektu analizowanie informacji z dzienników staje się coraz bardziej zasobożerne. Oznacza to nie tylko tworzenie dodatkowego obciążenia serwera; oznacza to również tworzenie szczytowego obciążenia procesora i dysków w czasie, gdy analizujesz logi, co może pogorszyć czas odpowiedzi serwera dla użytkowników (lub w najgorszym przypadku może nawet spowodować awarię witryny).

Aby rozwiązać ten problem, rozważ skonfigurowanie scentralizowanego serwera rejestrowania . Wszystko, czego potrzebujesz do tego, to kolejna skrzynka z otwartym portem UDP 514 (domyślnie). Aby rsyslogd nasłuchiwał połączeń, dodaj następujący wiersz do jego pliku konfiguracyjnego:

 $UDPServerRun 514

Dzięki temu konfiguracja klienta jest tak prosta, jak:

 *.* @HOSTNAME:514

(gdzie HOSTNAME jest nazwą hosta zdalnego serwera rejestrowania).

Wniosek

Chociaż w tym artykule pokazano kilka kreatywnych sposobów, w jakie pliki dziennika mogą oferować o wiele więcej cennych informacji, niż można było wcześniej sobie wyobrazić, należy podkreślić, że tylko zarysowaliśmy powierzchnię tego, co jest możliwe. Zakres, zakres i format tego, co można rejestrować, jest prawie nieograniczony. Oznacza to, że jeśli istnieją dane dotyczące użytkowania lub analizy, które chcesz wyodrębnić ze swoich dzienników, po prostu musisz je zalogować w sposób, który ułatwi późniejszą analizę i analizę. Co więcej, taką analizę można często przeprowadzić za pomocą standardowych narzędzi wiersza poleceń Linuksa, takich jak grep , sed , czy awk .

Rzeczywiście, pliki dziennika PHP są najpotężniejszym narzędziem, które może przynieść ogromne korzyści.

Zasoby

Kod na GitHub: https://github.com/isanosyan/toptal-blog-logs-post-example

Dodatek: Odczytywanie i manipulowanie plikami dziennika w powłoce uniksowej

Oto krótkie wprowadzenie do niektórych z bardziej popularnych narzędzi wiersza poleceń *nix, które warto znać do czytania i manipulowania plikami dziennika.

  • cat jest chyba najprostszym. Drukuje cały plik do strumienia wyjściowego. Na przykład następujące polecenie wyświetli logfile1 na konsoli:

     cat logfile1

  • Znak > umożliwia użytkownikowi przekierowanie wyjścia, na przykład do innego pliku. Otwiera strumień docelowy w trybie zapisu (co oznacza czyszczenie zawartości docelowej). Oto jak zastępujemy zawartość tmpfile zawartością logfile1 :

     cat logfile1 > tmpfile

  • >> przekierowuje wyjście i otwiera strumień docelowy w trybie dołączania. Aktualna zawartość pliku docelowego zostanie zachowana, nowe wiersze zostaną dodane na dole. To doda zawartość logfile1 do tmpfile :

     cat logfile1 >> tmpfile

  • grep filtruje plik według jakiegoś wzorca i drukuje tylko pasujące wiersze. Poniższe polecenie wyświetli tylko wiersze logfile1 zawierającego wiadomość Bingo :

     grep Bingo logfile1

  • cut drukuje zawartość pojedynczej kolumny (po numerze zaczynając od 1). Domyślnie wyszukuje znaki tabulacji jako ograniczniki między kolumnami. Na przykład, jeśli masz plik pełen znaczników czasu w formacie YYYY-MM-DD HH:MM:SS , pozwoli to na wydrukowanie tylko lat:

     cut -d"-" -f1 logfile1

  • head wyświetla tylko pierwsze wiersze pliku

  • tail wyświetla tylko ostatnie linie pliku

  • sort sortuje wiersze na wyjściu

  • uniq odfiltrowuje zduplikowane linie

  • wc liczy słowa (lub wiersze, gdy jest używany z flagą -l )

  • | (tj. symbol „rury”) dostarcza dane wyjściowe jednego polecenia jako dane wejściowe do następnego. Pipe jest bardzo wygodny do łączenia poleceń. Na przykład, oto jak możemy znaleźć miesiące 2014, które występują w zbiorze sygnatur czasowych:

     grep -E "^2014" logfile1 | cut -d"-" -f2 | sort | uniq

Tutaj najpierw dopasowujemy wiersze do wyrażenia regularnego „zaczyna się od 2014”, a następnie wycinamy miesiące. Na koniec używamy kombinacji sort i uniq , aby wyświetlić wystąpienia tylko raz.