Logování v PHP: logovací systém integrovaný do známých frameworků

Poznámka: Články budou popisovat základní použití uvedených technik bez ambicí o úplnost. Pokud máte zkušenosti s různými rozšířeními, jinými frameworky, jinými způsoby používání, zmiňte je, prosím, v diskuzi. Naším společným cílem by mělo být rozšíření poznání čtenářů Root.cz.

1. Logování – úvodní informace

Jedná se o jednu z velmi často používaných činností. U naprosté většiny velkých systémů je logování jejich nedílnou součástí, ale může být velmi prospěšné i u systémů malých.

Logování slouží primárně pro dlouhodobé (rozdíl od prvotního ladění) sledování činnosti programu. Ovšem poměrně běžně se využívá i pro ladění, kdy se považuje za jednu z nízkoúrovňových technik ladění. V tomto směru je nedocenitelné v případě distribuovaných programů či systémů, protože „debugger na vzdálený server neumístíte“.

Základní princip logování je, že do zdrojového kódu vkládáme dodatečné příkazy, zapisující aktuální stav průběhu výpočtu. Tím se logování podobá nejprimitivnějšímu způsobu ladění, tj. kontrolním výpisům. Ovšem oproti nim má logování množství výhod, které budou dále zmíněny.

Z nutnosti doplňovat zdrojový kód dalšími příkazy též pramení nejčastější námitka proti použití logování. Dle kritiků logování tak dochází ke dvěma nepříjemným věcem:

• Zdrojový kód je zanášen příkazy, které nemají s vlastní činností aplikace nic společného, a tím se snižuje jeho čitelnost.
• Voláním logovacích příkazů, kterému nelze zabránit ani v případě, že logovat ve skutečnosti nechceme, dochází ke snížení rychlosti programu.

Tyto námitky vypadají na první pohled důvěryhodně a dostatečně „hrozivě“, ale skutečnost je jiná:

• Pokud použijeme standardní příkazy pro logování (typicky je to volání jen jedné metody) je čitelnost zdrojového kódu pro znalého programátora nezměněna. Vliv volání logovací metody na snížení čitelnosti zdrojového kódu je tak prakticky zanedbatelný.
• Rozhodnutí za běhu programu, zda logovat či nikoliv, zabere v případě použití kvalitního logovacího frameworku jen minimum času. Problém s časováním bylo by nutné řešit pouze v časově kritických sekcích programu.

Jak již bylo řečeno, občas se používá logování už při primárním ladění i běžné aplikace. Ať již budeme používat logování pro prvotní ladění programu nebo pro dlouhodobé sledování jeho činnosti, vždy typicky sledujeme:

• běžnou činnost programu, případně lze analyzovat způsob používání programu uživateli,
• výskyt chyb,
• výskyt výjimek,
• konfiguraci aplikace a její změny,
• informace užitečné pro ladění,
• cokoli dalšího užitečného pro zpětnou analýzu,

Podrobněji viz tahák k logování.

Významnou výhodou logování – v porovnání s použitím debuggeru – je, že nám poskytuje časovou sekvenci záznamů, ve které je možné následně dohledat souvislosti.

Zapisované (tj. logované) informace se ukládají do souborů nazývaných logy (občas žurnály). Jsou to nejčastěji rozsáhlé TXT soubory, přičemž je ale v běžných možnostech logovacího frameworku změnit formát na JSON dokumenty či jiné formáty.

Zmiňované soubory ale nejsou jedinou možností. Výpis je možný i např. na konzoli, do paměti, do obecného streamu atd.

Logy slouží:

• při zpětné analýze k rozpoznání, zda došlo k nějaké chybě – kde, kdy, v jakých souvislostech, …
• pomáhají určit, co se v systému dělo – a nemusí to být nutně přímo chybový stav – a proč,
• dokazují (ne)funkčnost programu,
• dokumentují běh programu pro audit, atd.

Dobře napsaný program využívající pro logování kvalitní framework umožňuje při minimálních zásazích do zdrojového kódu logování jednoduše:

• vypnout,
• zapnout,
• nastavit jeho úroveň, tzn. určit, kolik a jak moc detailních informací se do logů má ukládat,
• nastavit formát výpisu (TXT, XML, HTML, …),
• nastavit cíl výpisu (konzole / paměť / soubor / vzdálený server / stream, …).

Je samozřejmě možné zařídit si logování vlastními silami, ale použití již existující knihovny či frameworku nám (bezpracně a zadarmo) přinese výhody:

• snadnost použití – vše potřebné naprogramováno a přednastaveno,
• parametrizovatelnost:
  • zápisy do různých výstupů (přepisovatelné soubory, …),
  • rozsáhlé možnosti typu (včetně formátování) výstupu,
  • snadno volitelná úroveň závažnosti (detailu).

Samostatně zmíněnou výhodou budiž to, že existující frameworky/knihovny představují de facto standard, kterému každý rozumí.

Pro PHP je běžně užívaná knihovna Monolog.

Poznámka:
PHP má vlastní logovací funkci error_log() . Ta nebude dále zmiňována.

2. Knihovna Monolog

Dostupná na GitHubu.

Jedná se o sofistikovaný, průběžně vyvíjený, profesionálně používaný systém integrovaný do známých frameworků, např.:

• Symfony
• Laravel
• Nette

V tomto článku je popisována verze 2.3.2 ze 23.července 2021.

Dokumentace (přímo na GitHubu) je bohužel velmi strohá a v mnoha případech odkazuje jen na zdrojové kódy.

Poznámka: Další popis je subjektivní výběr možností. Pro příklady bude využíváno prostředí PHPStorm 2021.2. Zdrojové kódy všech uvedených příkladů si můžete stáhnout u mě na webu.

2.1. Instalace

Monolog se instaluje přes Composer jako adresář PHP souborů. V ukázkovém příkladu pomocí composer.json  , a to včetně žádosti o současné vytvoření autoloaderu.

{
  "autoload": {
    "psr-4": {
      "src\\app\\": "./"
    }
  },
  "require": {
    "monolog/monolog": "2.3.2"
  }
}

Díky PHPStormu je instalace velmi jednoduchá:

Po úspěšné instalaci využijeme předpřipravený autoload.php  – viz dále.

2.2. Logované informace

Informace, které je vhodné logovat, jsou z naprosté většiny připraveny / zjištěny automaticky díky službám knihovny. Informace jsou uloženy v logovacím záznamu. To je pole, jehož jednotlivé položky mají následující význam (přesný název položek bude důležitý pro jejich pozdější výpis či formátování):

• level  – úroveň (jako celé číslo v řádu stovek)
• level_name  – jméno úrovně
• datetime  – časová známka z Monolog\DateTimeImmutable
• channel  – jméno loggeru
• extra  – pole, kam může registrovaný procesor (viz navazující článek) zapsat dodatečné informace;
  • generuje se automaticky až po registraci procesoru
• context  – pole s libovolnými informacemi, které mohou být dodány navíc k logovacímu záznamu;
  • negeneruje se automaticky
• message  – zpráva, kterou chce programátor zaznamenat
  • negeneruje se automaticky
  • obsahem zprávy může být cokoli, co programátor uzná za potřebné logovat
  • je samozřejmě zbytečné dávat do zprávy údaje, které jsou již v logovacím záznamu automaticky jako součást předchozích položek

Pozor:
Obsahy logovacích záznamů typicky sami nevytváříme, vznikají automaticky „interním efektem“ použití loggeru.

Logovací záznam se do výstupního souboru (obecně do výstupu) nemusí vždy zapsat kompletní. Úroveň detailu zápisu, tj. jaké položky logovacího záznamu se použijí, se dá snadno ovlivnit – viz dále kapitolu Formátování v navazujícím článku.

2.2.1. Úrovně závažnosti

Monolog podporuje úrovně závažnosti logů dle doporučení RFC 5424.

Je definováno 8 úrovní (konstant). Jméno konstanty je položka level_name a číslo v závorce je položka level z logovacího záznamu:

Varování:
Uvedené příklady použití není možné brát doslovně jako dogma. Vždy záleží na povaze celé aplikace.

• DEBUG (100) – úroveň ladění
  • podrobné ladicí informace – použití jednotlivých položek menu, klikání na nápovědu, dotazy do DB, …
  • výpis v této úrovni poskytuje nejvíce detailních informací
• INFO (200) – informační výpisy u zcela běžných akcí
  • jméno právě zpracovávaného souboru
  • událost zajímavá pro zaznamenání, např. uživatel se přihlásil
• NOTICE (250) – významné, ale v aplikaci normální / očekávané události
  • registrace nového uživatele
  • změna hesla
• WARNING (300) – varovná hlášení – stavy potenciálně nebezpečné
  • použití zastaralého API
  • chybné heslo uživatele
  • nežádoucí věci, jako je detekovaný pokus o SQL injekci
  • odkaz na neexistující stránku
• ERROR (400) – runtime chyby v programu, které nevyžadují bezprostřední reakci, ale časem se musí řešit
  • čtení ze souboru se neprovedlo
• CRITICAL (500) – kritické chování ohrožující celkovou funkcionalitu
  • vyhození neočekávané výjimky
• ALERT (550) – stav aplikace, který vyžaduje okamžitý zásah, protože je prakticky nefunkční nebo s velmi omezenou funkcionalitou
  • nedostupná databáze
• EMERGENCY (600) – aplikace spadla a je nepoužitelná
  • výpis v této úrovni poskytuje pouze nejdůležitější informace

Poznámka:
Je ovšem otázkou, zda v našem programu dokážeme úroveň EMERGENCY správně (nebo vůbec) detekovat a tedy i zalogovat.

Programátor zadávající jednotlivé logovací příkazy (viz dále) samozřejmě nemusí používat všechny úrovně.

Znalost těchto osmi úrovní je klíčová pro použití celého systému logování. Úrovně si volíme v našich logovacích příkazech sami a jejich vhodné použití umožní následně snadno filtrovat výpisy. Například pro celou naši aplikaci lze jednoduše nastavit, že se budou logovat jen úrovně WARNING a vyšší.

Platí pravidlo, že nastavením úrovně se povolují i všechny vyšší a současně i zakazují i všechny nižší, takže např. nastavení ERROR způsobí:

• zakázání DEBUG, INFO, NOTICE,  WARNING
• povolení ERROR, CRITICAL, ALERT,  EMERGENCY

2.3. Základní použití logování

Základní třída pro veškeré použití je třída Logger

use Monolog\Logger;

Její instance (loggery) se používají k vytváření logovacích záznamů (viz výše). Vytvořený záznam může být zaslán na výstup (či několik výstupů), což se zajistí tím, že se k loggeru připojí jeden nebo více handlerů. Ty pak zajistí výpis zvolených částí logovacího záznamu na zvolené zařízení. Před vlastním výpisem se položky záznamu ještě formátují.

Instance třídy Logger (tj. logger) používá logovací metody pojmenované podle úrovní, např. info(). Jejich jediným povinným parametrem je logovací zpráva (položka message v logovacím záznamu). Zpráva může být samozřejmě i prázdná, ale to není dobrý návyk.

Potřebujeme-li do logovacího záznamu vypsat výjimku, pak použijeme metodu

log($level, $zprava, $vyjimka) např.:

logger->log(Logger::CRITICAL, "zpracování souboru", $exp);

Příklad zakladniPouziti.php  – ukázka základního použití logování s výpisem do konzole prohlížeče ( BrowserConsoleHandler(Logger::ERROR)). V příkladu se ukázkově logují všechny úrovně, ale ve výpisu se objeví jen úrovně od Logger::ERROR  výše.

<?php

use Monolog\Logger;
use Monolog\Handler\BrowserConsoleHandler;

require __DIR__ . '/../../../vendor/autoload.php';

$logger = new Logger('nazev_logeru');
$logger->pushHandler(new BrowserConsoleHandler(Logger::ERROR));

echo "logovani";  // jen pro kontrolu spusteni Php skriptu

$logger->debug('zpráva log-debug');
$logger->info('zpráva log-info');
$logger->notice('zpráva log-notice');
$logger->warning('zpráva log-warning');
$logger->error('zpráva log-error');
$logger->critical('zpráva log-critical');
$logger->alert('zpráva log-alert');
$logger->emergency('zpráva log-emergency');

Po spuštění se v prohlížeči objeví:

Po zobrazení konzole v prohlížeči (klávesa F12) se objeví:

Z výpisu je vidět, že ze všech položek každého ze čtyř vypsaných logovacích záznamů byly použity jen tři položky, a to:

• channel, tj.  nazev_logeru
• level_name, tj. např.  ERROR
• message, tj. např.  zpráva log-error

Je vidět, že se nemusí vypisovat všechny informace z logovacího záznamu – zde např. není časová známka.

Poznámka: Identifikace zdrojového PHP souboru a řádky s logovacím příkazem, tj. např. zakladniPouziti.php:2 není informace z logovacího záznamu.

Varovné hlášení o DevTools pro nás není nedůležité a v dalších výpisech již nebude uváděno

Dále je vidět, že úrovně nižší než Logger::ERROR, nejsou vypisovány (ale jsou logovány). A pokud by se handler vytvořil bez nepovinného zadání úrovně, tj:

$logger->pushHandler(new BrowserConsoleHandler());

místo předchozího:

$logger->pushHandler(new BrowserConsoleHandler(Logger::ERROR));

budou se vypisovat všechny úrovně:

2.3.1. Vhodné jméno loggeru

Logger (tj. ve výpisu položka channel) může být pojmenován libovolně, ale mělo by to být významové jméno. Doporučují se dva způsoby pojmenování, které je možné kombinovat:

• logger se jmenuje stejně jako (významná) logovaná třída, např.  DB
• logger je pojmenován podle globálního účelu, např. provoz nebo  bezpecnost

2.4. Běžné způsoby používání

Zde si ukážeme počáteční vytvoření loggerů a k nim přiřazení handlerů a dalších elementů, případně kombinace loggerů a handlerů.

2.4.1. Handlery a jejich hierarchie

Jak již bylo řečeno, handler je zodpovědný za zápis logovacího záznamu na zvolené výstupní zařízení. Zdálo by se jako samozřejmé, že každý logger bude mít jeden svůj unikátní handler. Je to samozřejmě možné, ale kupodivu se tento přístup nepoužívá zcela důsledně. V reálné praxi se setkáváme se dvěma zcela běžnými přístupy, které princip „jeden logger, jeden handler“ porušují.

• Potřebujeme výstupy z jednotlivých loggerů sjednotit do jednoho výstupního souboru. Typicky se jedná o debuggování (a úroveň DEBUG), kdy při ladění vzniká jeden velký výstupní soubor s kompletní informací z celé laděné aplikace. Potom bude existovat jen jeden handler, který mají všechny loggery k sobě připojen.
• Potřebujeme, aby jeden logger zapisoval (nejčastěji podle úrovně závažnosti) do více různých výstupů. Při nižší úrovni závažnosti to může být soubor, při vyšších např. e-mail. Pak má jeden logger přiřazeno více handlerů.

Druhý zmíněný způsob má více možností, kterým je třeba věnovat pozornost a budou popsány právě zde.

Je asi zřejmé, že každý handler může směřovat výstup na jiné médium. Ovšem ale existuje i možnost vzájemného ovlivňování handlerů přiřazených jednomu loggeru. Tyto handlery totiž fungují v zásobníkové hierarchii. To znamená, že naposledy přiřazený handler (vrcholek LIFO zásobníku, tj. nejvyšší priorita) může filtrovat logovací záznamy předávané dalším handlerům v pořadí umístění v zásobníku (nižší priority). Toto má samozřejmě praktický smysl naznačený již výše – někdy nechceme, aby se informace z různých úrovní logování zapisovala do všech výstupů (stačí např. do e-mailu). Samozřejmě ale existují i situace, kdy toto chceme.

Předávání logovacích záznamů již jedním (prioritně vyšším) handlerem dalšímu (prioritně nižšímu) handleru se označuje termínem bubble (probublávání) a nastavuje se voláním metody handleru  bubble(bool).

Dvě možnosti nastavení skutečného parametru:

• bubble(true)  – k filtrování záznamů nedochází, tj. vyšší handler záznam vypíše a nezměněný jej poskytuje nižšímu handleru. Toto je výchozí nastavení každého handleru.
• bubble(false)  – prioritně vyšší handler zpracuje (vypíše) všechny logovací záznamy až do své úrovně včetně a ty pak dále nepropouští. Prioritně nižší handler pak zpracovává jen zbylé logovací záznamy nižších úrovní.

V manuálu je uveden příklad, kdy prioritně nejvýše je MailHandler, který zpracovává záznamy do úrovně ALERT (tj. EMERGENCY a ALERT) – tzn. jen nejvážnější případy. Nižší úroveň záznamů (tj. CRITICAL a níže) pak propouští do StreamHandler, který může do logovacího souboru zapsat mnohem více informací, než se zapisuje do emailu z nadřazeného  MailHandler.

Příklad dvaHandlery.php ukazuje nastavení spolupráce a filtrování záznamů dvěma handlery. Pro jednoduchost zapisují oba handlery do konzole.

<?php

use Monolog\Logger;
use Monolog\Handler\BrowserConsoleHandler;

require __DIR__ . '/../../../vendor/autoload.php';

$logger = new Logger('dvaHandlery');
$handlerError = new BrowserConsoleHandler(Logger::ERROR);
$handlerAlert = new BrowserConsoleHandler(Logger::ALERT);
$handlerAlert->setBubble(false);
$logger->pushHandler($handlerError);
$logger->pushHandler($handlerAlert);

echo "logovani - dva handlery";  // jen pro kontrolu spusteni Php skriptu

$logger->debug('zpráva log-debug');
$logger->info('zpráva log-info');
$logger->notice('zpráva log-notice');
$logger->warning('zpráva log-warning');
$logger->error('zpráva log-error');
$logger->critical('zpráva log-critical');
$logger->alert('zpráva log-alert');
$logger->emergency('zpráva log-emergency');

Při nastavení:

$handlerAlert->setBubble(true);

se zobrazí zdvojené záznamy:

Při nastavení:

$handlerAlert->setBubble(false);

se zobrazí každý záznam jen jednou:

Úroveň logování (zde Logger::ERROR) nemusí být nastavena jen v konstruktoru handleru, jak tomu bylo v příkladech dosud:

$logger = new Logger('dvaHandlery');

$handlerError = new BrowserConsoleHandler(Logger::ERROR);

$logger->pushHandler($handlerError);

Úroveň je možné i nastavit při připojování handleru k loggeru, např.:

$logger = new Logger('dvaHandlery');

$handlerError = new BrowserConsoleHandler();

$logger->pushHandler($handlerError, Logger::ERROR);

2.4.2. Principy formátování záznamů

Poznámka: Detailní možnosti formátování budou uvedeny v následujícím článku.

Handlery mají nastaven, a pokud není změněn tak i používají, výchozí formátovač, který je pro každý typ handleru jiný. Potřebujeme-li handleru nastavit vlastní formátovač, použijeme metodu  setFormatter().

Příklad dvaHandleryForm.php je rozšíření předchozího příkladu. Zde má každý handler svůj formátovač:

<?php

use Monolog\Logger;
use Monolog\Handler\BrowserConsoleHandler;
use Monolog\Formatter\LineFormatter;

require __DIR__ . '/../../../vendor/autoload.php';

// the default date format is "Y-m-d\TH:i:sP"
$dateFormat = "Y-m-d H:i:s";
// the default output format is "[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n"
$outputError = "%datetime% > %channel% > %level_name%";
$formatterError = new LineFormatter($outputError, $dateFormat);
$outputAlert = "%datetime% %level_name% : %message%";
$formatterAlert = new LineFormatter($outputAlert, $dateFormat);

$logger = new Logger('dvaHandleryForm');
$handlerError = new BrowserConsoleHandler(Logger::ERROR);
$handlerAlert = new BrowserConsoleHandler(Logger::ALERT);
$handlerAlert->setBubble(false);
$handlerError->setFormatter($formatterError);
$handlerAlert->setFormatter($formatterAlert);
$logger->pushHandler($handlerError);
$logger->pushHandler($handlerAlert);

echo "logovani - dva handlery - formatovani";  // jen pro kontrolu spusteni Php skriptu

$logger->debug('zpráva log-debug');
$logger->info('zpráva log-info');
$logger->notice('zpráva log-notice');
$logger->warning('zpráva log-warning');
$logger->error('zpráva log-error');
$logger->critical('zpráva log-critical');
$logger->alert('zpráva log-alert');
$logger->emergency('zpráva log-emergency');

Při nastavení:

$handlerAlert->setBubble(false);

se zobrazí každý záznam jen jednou, vypisují se rozdílné části logovacího záznamu a záznamy jsou výrazně rozdílně formátovány:

2.4.3. Více loggerů na jeden handler

Již dříve bylo zmíněno, že můžeme chtít mít jen jeden výstup a do něj z důvodu přehlednosti výsledků zapisovat z několika loggerů. I to je běžné použití.

Příklad dvaLoggery.php ukazuje sdílení společného handleru. Oba loggery vypisují o jedné a téže události rozdílné informace, které se ve výstupu spojí.

<?php

use Monolog\Logger;
use Monolog\Handler\BrowserConsoleHandler;

require __DIR__ . '/../../../vendor/autoload.php';

$logUzi = new Logger('sprava uzivatelu');
$logDB = new Logger('operace s DB');
$handler = new BrowserConsoleHandler();

$logUzi->pushHandler($handler);
$logDB->pushHandler($handler);

//$logDB = $logUzi->withName('operace s DB');

echo "logovani - dva loggery";  // jen pro kontrolu spusteni Php skriptu

$logUzi->notice('Pavel se zaregistroval');
$logDB->info('heslo uloženo');
$logUzi->warning('email ve špatném formátu');
$logDB->error('neznámé kódování češtiny');

Podle barevného rozlišení názvů loggerů (channel) v konzoli je zřejmé, že se s možností sdílení jednoho handleru běžně počítá. Zobrazí se:

V příkladu je zakomentován příkaz:

//$logDB = $logUzi->withName('operace s DB');

Jeho smysl (samozřejmě po případném odkomentování) je tom, že pokud bychom měli jeden logger nějakým složitějším způsobem nakonfigurovaný a druhý logger by měl být kopie prvního, lze toto snadno udělat jedním příkazem  withName().

Takže následující zápis dává stejné výsledky jako předchozí příklad:

$logUzi = new Logger('sprava uzivatelu');
$handler = new BrowserConsoleHandler();
$logUzi->pushHandler($handler);

$logDB = $logUzi->withName('operace s DB');