Logování v PHP: možnosti výstupů logování zajišťovaných handlery

13. 10. 2021

Doba čtení: 13 minut

Líbí se vám článek?
Podpořte redakci

Ve druhém článku si ukážeme poměrně podrobně možnosti výstupů logování zajišťovaných handlery. Tyto možnosti jsou vcelku rozsáhlé a evidentně reagují na reálnou poptávku takřka „ze života“.

2.5. Handlery podrobně

Jak už víme, jejich úkolem je přenést zaznamenaný logovací záznam na cílové místo.

V současné verzi existuje značné množství handlerů, které jsou podle dokumentace Monologu členěny do skupin – podrobnosti viz dokumentaci Monologu.

Log to files and syslog – celkem 5 handlerů
Send alerts and emails – celkem 12 handlerů
Log specific servers and networked logging – celkem 14 handlerů
Logging in development – celkem 4 handlery
Log to databases – celkem 7 handlerů
Wrappers / Special Handlers – celkem 14 handlerů

Každý handler musí implementovat rozhraní Monolog\Handler\HandlerInterface, což mj. znamená, že každý handler lze uzavřít voláním close().

2.5.1. BrowserConsoleHandler

Patří do skupiny Logging in development a jedná se o základní handler, který se chová víceméně stejně ve všech prohlížečích. Je proto vhodný pro nejrůznější rychlé experimenty. Setkali jsme se s ním ve všech předchozích příkladech.

Jeho výchozí formát je:

%channel% %level_name% %message%

2.5.2. StreamHandler

Patří do skupiny Log to files and syslog a představuje základní handler pro zápis do souboru, což je zřejmě jeden z nejpoužívanějších výstupů.

Handler zapisuje do souboru, jehož jméno je uvedeno jako první povinný parametr konstruktoru. Přitom platí, že:

pokud neexistuje adresářová cesta, je vytvořena;
soubor se otevírá v režimu append. Pokud neexistuje, je založen.
Pokud existuje, další záznamy se připisují nakonec – toto je při logování typické chování.

Výchozí formát je:

[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n

Příklad pouzitiStreamHandler.php

<?php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\soubor.log';
$logger = new Logger('soubor');
$handler = new StreamHandler($jmenoSouboru, Logger::DEBUG);
$logger->pushHandler($handler);

echo "StreamHandler";  // jen pro kontrolu spusteni PHP skriptu

$logger->debug('zpráva log-debug');
$logger->info('zpráva log-info');

Vypíše do soubor.log např.:

[2021-09-06T15:23:24.188155+02:00] soubor.DEBUG: zpráva log-debug [] []
[2021-09-06T15:23:24.200494+02:00] soubor.INFO: zpráva log-info [] []

Adresářová struktura na disku je:

Autor: Pavel Herout

2.5.3. RotatingFileHandler

Patří do skupiny Log to files and syslog a také zapisuje do souboru jako předchozí StreamHandler. Od něj se však způsobem práce významně liší. Tato odlišnost si vyžaduje podrobnější objasnění.

Častým známým problémem při kvalitně provedeném logování je, že se po nasazení do produkce zapomene vypnout úroveň DEBUG se svými podrobnými informacemi, tj. i s rozsáhlými záznamy v logovacím souboru. Pak aplikace běží dlouho v pořádku, ale protože žádný disk není nekonečně velký, po určité době dojde (z pohledu tvůrce aplikace) k nepochopitelnému zaplnění disku. Pravděpodobně by ale již před zaplněním disku došlo k problémům s překročením max. velikosti souboru. Nemusí jít ani o zapomenuté debugování úrovně DEBUG. Stačí v provozu logovat běžné události dostatečně dlouho (roky).

Tento problém elegantně řeší právě zápis do rotujících souborů. Vychází se z jednoduché myšlenky, že pro nalezení příčiny problému stačí většinou jen N posledních logovacích záznamů (N může být řádu tisíců, statisíců, milionů). A pokud je N překročeno, přemazávají nejnovější záznamy ty nejstarší záznamy. Je to něco na způsob kruhového bufferu, byť ne doslova.

Praktická realizace pro RotatingFileHandler je, že aktuální logovací záznamy zapisuje po celý kalendářní den do souboru, jehož jméno je v prvním povinném parametru konstruktoru. K tomuto jménu se připojí i aktuální datum ve formátu -Y-m-d, např. souborRot-2021-09-06.log.
Druhý, už nepovinný, parametr konstruktoru je počet těchto „denních“ souborů, které se mají uchovávat. Výchozí hodnota je 0, což znamená uchovávat všechny existující soubory. Toto výchozí nastavení by ale nemělo až tak velký praktický význam – zabránilo by zřejmě problému s překročením maximální velikosti souboru, ale problém s přeplněným diskem by neřešilo. Proto se zadává i hodnota nepovinného parametru, což je celé číslo ve významu, „kolik dnů historie se uschovává“. Hodnota 1 tak znamená uchovávat pouze jeden soubor do historie (tj. včerejší), takže předvčerejší soubor se automaticky maže.

RotatingFileHandler (stejně jako StreamHandler) zapisuje do souboru během celého dne v režimu append.

Výchozí formát je:

[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n

Příklad pouzitiRotatingFileHandler.php

<?php

use Monolog\Logger;
use Monolog\Handler\RotatingFileHandler;

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\souborRot.log';
$logger = new Logger('souborRot');
$handler = new RotatingFileHandler($jmenoSouboru, 1, Logger::DEBUG);
$logger->pushHandler($handler);

echo "RotatingFileHandler";  // jen pro kontrolu spusteni PHP skriptu

$logger->debug('zpráva log-debug');
$logger->info('zpráva log-info');

Po dvojím spuštění vypíše do ouborRot-2021-09-06.log např.:

[2021-09-06T15:52:05.172178+02:00] souborRot.DEBUG: zpráva log-debug [] []
[2021-09-06T15:52:05.174289+02:00] souborRot.INFO: zpráva log-info [] []
[2021-09-06T15:52:59.960743+02:00] souborRot.DEBUG: zpráva log-debug [] []
[2021-09-06T15:52:59.962291+02:00] souborRot.INFO: zpráva log-info [] []

Adresářová struktura na disku je:

Autor: Pavel Herout

2.5.4. Wrapper FingersCrossedHandler

Patří do skupiny Wrappers / Special Handlers a funguje podle filozofie: „dej vědět, pokud nastane problém“. Neboli, poskytuje podrobnou informaci, až když je potřeba.

Princip jeho práce je, že obaluje jiný handler – typicky StreamHandler, který je zadán jako první povinný parametr konstruktoru. Jako druhý parametr konstruktoru se zadá logovací úroveň, kterou považujeme za kritickou. To znamená, že až teprve při výskytu logovacího záznamu této úrovně (např. Logger::ERROR) chceme být informováni a tato událost bude spouštět zápis všech záznamů.

Při tomto nastavení bude FingersCrossedHandler ukládat do vyrovnávací paměti všechny záznamy nižší úrovně a pokud se nevyskytne záznam úrovně Logger::ERROR nebo vyšší, nic se nestane. To znamená, že se nezaloží soubor ze StreamHandler a z vyrovnávací paměti se nevyužívají žádné záznamy nižších úrovní než Logger::ERROR. Takže běží-li aplikace v pořádku, nic se nezapisuje do výstupu.

Pokud ale nastane záznam úrovně Logger::ERROR nebo vyšší, zapíší se z vyrovnávací paměti všechny dosud uložené záznamy nižších úrovní a pak i záznam kritické úrovně. Následné další záznamy se již zapisují všechny bez ohledu na jejich úroveň.

To prakticky znamená, že v případě výskytu problému, můžeme ze vzniklého logovacího záznamu vyčíst celou podrobnou historii.

Poznámka:
Tento způsob se jeví jako naprosto ideální, tj. máme uložené logy, jen když je opravdu potřebujeme. Ovšem pozor na skutečnost, že logovací záznamy se průběžně ukládají do vyrovnávací paměti a ta také není nekonečná. Z tohoto pohledu obsahuje manuál Monologu různá varování – viz dále Resetování handleru.

Příklad pouzitiFingersCrossedHandler.php

Při prvním spuštění je zakomentovaná řádka

//$logger->error('zpráva error');

<?php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Handler\FingersCrossedHandler;

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\souborFinger.log';
$logger = new Logger('fingerscrossed');
$handlerStr = new StreamHandler($jmenoSouboru);
$handlerFin = new FingersCrossedHandler($handlerStr, Logger::ERROR);
$logger->pushHandler($handlerFin);

echo "FingersCrossedHandler";  // jen pro kontrolu spusteni PHP skriptu

for ($i = 1;  $i <= 3;  $i++) {
  $logger->debug('zpráva debug');
  $logger->info('zpráva info');
}

//$logger->error('zpráva error');
$logger->warning('zpráva warning');

Po spuštění se nestane nic, soubor souborFinger.log nevznikne.

Při druhém spuštění je odkomentovaná řádka:

$logger->error('zpráva error');

Obsah souboru souborFinger.log bude (mezi spuštěními je odřádkováno) např.:

[2021-09-06T16:16:58.059655+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:16:58.059680+02:00] fingerscrossed.INFO: zpráva info [] []
[2021-09-06T16:16:58.059695+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:16:58.059709+02:00] fingerscrossed.INFO: zpráva info [] []
[2021-09-06T16:16:58.059723+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:16:58.059735+02:00] fingerscrossed.INFO: zpráva info [] []

[2021-09-06T16:17:31.027203+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:17:31.027226+02:00] fingerscrossed.INFO: zpráva info [] []
[2021-09-06T16:17:31.027241+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:17:31.027255+02:00] fingerscrossed.INFO: zpráva info [] []
[2021-09-06T16:17:31.027269+02:00] fingerscrossed.DEBUG: zpráva debug [] []
[2021-09-06T16:17:31.027282+02:00] fingerscrossed.INFO: zpráva info [] []
[2021-09-06T16:17:31.027295+02:00] fingerscrossed.ERROR: zpráva error [] []
[2021-09-06T16:17:31.029408+02:00] fingerscrossed.WARNING: zpráva warning [] []

2.5.5. Wrapper BufferHandler

Patří do skupiny Wrappers / Special Handlers a funguje podle filozofie: „večer chci seznam problémů“.

Tento handler pracuje podobně jako předchozí FingersCrossedHandler, tj. do vyrovnávací paměti se ukládají všechny záznamy. Spouštěčem zápisu do cílového výstupu je zde volání funkce close(). V tomto okamžiku jsou do handleru z vyrovnávací paměti předány všechny záznamy najednou. Tento přístup je užitečný například při použití NativeMailerHandler, kdy se odešle jeden souhrnný email místo mnoha jednotlivých emailů, ve kterých by byl vždy jen jeden logovací záznam.

2.5.6. Resetování loggeru

Některé handlery, např. dříve uvedené FingersCrossedHandler nebo BufferHandler zapisují nejdříve do paměti a až po splnění určitých podmínek zapíší najednou logovací záznamy na cílové persistentní médium. Při dlouhotrvajících operacích tak může dojít k problémům s pamětí.

Tomu se dá bránit příkazem $logger->reset(), který vyčistí všechny buffery, vyresetuje vnitřní stav loggeru a nastaví vše tak, jako je to po vytvoření nového loggeru.

Tento příkaz by se měl používat, když je ukončena nějaká komplexní operace, která se opakuje. A samozřejmě je třeba jej užívat jen na určité typy handlerů.

2.5.7. Wrapper FilterHandler

Patří do skupiny Wrappers / Special Handlers a funguje podle filozofie: „loguje se všechno, ale já si vyberu to zajímavé“.

Opět funguje jako dva předchozí handlery, tj. je navázán na „skutečný“ handler. Pro něj pak propouští logovací záznamy jen určitých úrovní – filtruje je.

V konstruktoru se nastaví jeden ze dvou základních režimů pro úrovně, které budou procházet:

seznam úrovní – nemusí být spojitý,
dolní a horní mez (včetně) úrovní.

Příklad pouzitiFilterHandler.php, kdy logger bude zapisovat pomocí dvou handlerů do dvou souborů.

<?php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Handler\FilterHandler;

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

$logger = new Logger('filter');

$souborSeznam = __DIR__ . '\..\..\..\logy\souborFilterSeznam.log';
$handlerStrSeznam = new StreamHandler($souborSeznam);
$seznamUrovni = array(Logger::DEBUG, Logger::NOTICE, Logger::ALERT);
$handlerFilterSeznam = new FilterHandler($handlerStrSeznam, $seznamUrovni);
$logger->pushHandler($handlerFilterSeznam);

$souborMeze = __DIR__ . '\..\..\..\logy\souborFilterMeze.log';
$handlerStrMeze = new StreamHandler($souborMeze);
$handlerFilterMeze = new FilterHandler($handlerStrMeze, Logger::WARNING, Logger::CRITICAL);
$logger->pushHandler($handlerFilterMeze);

echo "FilterHandler";  // 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');

Obsah souboru souborFilterSeznam.log

[2021-09-06T16:34:12.831293+02:00] filter.DEBUG: zpráva log-debug [] []
[2021-09-06T16:34:12.833979+02:00] filter.NOTICE: zpráva log-notice [] []
[2021-09-06T16:34:12.834953+02:00] filter.ALERT: zpráva log-alert [] []

Obsah souboru souborFilterMeze.log

[2021-09-06T16:34:12.834160+02:00] filter.WARNING: zpráva log-warning [] []
[2021-09-06T16:34:12.834631+02:00] filter.ERROR: zpráva log-error [] []
[2021-09-06T16:34:12.834796+02:00] filter.CRITICAL: zpráva log-critical [] []

2.6. Přidávání dodatečných informací do logovacího záznamu

Od samého začátku popisu Monologu víme, že logovací záznam má položky context a extra, obě typu array. Pokud pro jejich naplnění explicitně nic neuděláme, jsou ve výchozím stavu prázdné a vypisují se jako prázdné array (tj. []) na konci některých logovacích záznamů – viz předchozí výpis

[2021-09-06T16:34:12.834796+02:00] filter.CRITICAL: zpráva log-critical [] []

Naplnění těchto položek je závislé na jejich typu.

2.6.1. Položka context

Použijeme ji, když chceme přidat doplňkovou informaci jen k některým logovacím záznamům, tj. selektivně.

Zde nás hned napadne, že tím je context podobný již známé message.

Rozdíl od možného zápisu téže informace rovnou do logovací zprávy (message) je dvojí. Za prvé, že obsahem context může být libovolně strukturované pole, kdežto message je pouze typu string. A za druhé, při výpisu logovací informace se zapsaný context může nebo nemusí použít, a to bez závislosti na použití message, která se většinou použije vždy.

Jak se context do logovacího záznamu zapíše? Jednoduše – každá z metod logujících úrovně (tj. debug() až emergency()) může využít druhý nepovinný parametr pro zapsání hodnoty do context, např.

$logger->info('Uživatel se přihlásil', ['username' => 'Pavel']);

kde druhý skutečný parametr je array ( ['username' => 'Pavel']). Rozšířené použití bude vidět na příkladu – viz proměnnou $identifikace.

Příklad pouzitiContext.php

<?php

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

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\souborContext.log';
$logger = new Logger('soubor');
$handler = new StreamHandler($jmenoSouboru, Logger::INFO);
$logger->pushHandler(new BrowserConsoleHandler(Logger::INFO));
$logger->pushHandler($handler);

echo "Context";  // jen pro kontrolu spusteni PHP skriptu

$logger->info('zpráva log-info');
$logger->info('Uživatel se přihlásil', ['username' => 'Pavel']);
$identifikace = array('jmeno' => 'Pavel', 'prijmeni' => 'Herout');
$logger->info('Identifikace uživatele', $identifikace);

Obsah souboru souborContext.log (je provedeno odřádkování pro lepší čitelnost)

[2021-09-06T16:49:24.943262+02:00] soubor.INFO: zpráva log-info [] []

[2021-09-06T16:49:24.945258+02:00] soubor.INFO: Uživatel se přihlásil {"username":"Pavel"} []

[2021-09-06T16:49:24.945525+02:00] soubor.INFO: Identifikace uživatele {"jmeno":"Pavel","prijmeni":"Herout"} []

2.6.2. Položka extra – procesor

Od context se liší tím, že je automaticky v každém logovacím záznamu.

Procesor dovoluje nakonfigurovat logger (voláním $logger->pushProcessor()) nebo handler ( $handler->pushProcessor()) tak, že bude ke každému logovacímu záznamu přidávána informace generovaná procesorem.

Jedná se většinou (viz dále Existující procesory) o podrobnou informaci o místě či okolnostech vzniku logované události.

Poznámka:
Procesor může být libovolný callable. Musí jen (viz příklad) zajistit zápis do položky extra, např.:

$record['extra']['zpravaProcessoru'] = 'jsem v každém záznamu';

Příklad pouzitiProcesor.php

<?php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\souborProcessor.log';
$logger = new Logger('soubor');
$handler = new StreamHandler($jmenoSouboru, Logger::INFO);
$logger->pushHandler($handler);

echo "Processor";  // jen pro kontrolu spusteni PHP skriptu

$logger->pushProcessor(function ($record) {
  $record['extra']['zpravaProcessoru'] = 'jsem v každém záznamu';
  return $record;
});

$logger->info('zpráva log-info');
$logger->error('zpráva log-error');

Obsah souboru souborProcessor.log (je provedeno odřádkování pro lepší čitelnost):

[2021-09-06T17:02:35.346303+02:00] soubor.INFO: zpráva log-info []
{"zpravaProcessoru":"jsem v každém záznamu"}

[2021-09-06T17:02:35.356539+02:00] soubor.ERROR: zpráva log-error []
{"zpravaProcessoru":"jsem v každém záznamu"}

2.6.3. Existující procesory

V popisované verzi Monologu je předdefinováno 11 procesorů.

Dále budou uvedeny ukázky většiny z nich, přičemž pro všechny bude použit program pouzitiExistujiciProcessor.php, začínající:

<?php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Handler\BrowserConsoleHandler;
use Monolog\Formatter\LineFormatter;
use Monolog\Processor\HostnameProcessor;
use Monolog\Processor\IntrospectionProcessor;
use Monolog\Processor\MemoryPeakUsageProcessor;
use Monolog\Processor\MemoryUsageProcessor;
use Monolog\Processor\ProcessIdProcessor;
use Monolog\Processor\TagProcessor;
use Monolog\Processor\UidProcessor;
use Monolog\Processor\WebProcessor;

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

$jmenoSouboru = __DIR__ . '\..\..\..\logy\souborExistujiciProcessor.log';
$output = "%channel%: %extra% \n";
$formatter = new LineFormatter($output);
$handler = new StreamHandler($jmenoSouboru, Logger::INFO);
$handler->setFormatter($formatter);

echo "ExistujiciProcessor";  // jen pro kontrolu spusteni PHP skriptu

Program funguje tak, že:

bude zapisovat vždy do souboru souborExistujiciProcessor.log
formátovaný výstup bude:
"%channel%: %extra% \n"
tj. pouze jméno loggeru a informace generované procesorem

Takto nakonfigurovaný handler použijí všechny další loggery vždy s jedním konkrétním připojeným procesorem. Logger je vždy pojmenován podle procesoru.

1. IntrospectionProcessor – line/file/class/method odkud byl logovací záznam vytvořen

$logger = new Logger('Introspection');
$logger->pushProcessor(new IntrospectionProcessor());
$logger->pushHandler($handler);
$handlerC = new BrowserConsoleHandler(Logger::DEBUG);
$logger->pushHandler($handlerC);
$logger->info('zpráva log-info');

Záznam v souboru souborExistujiciProcessor.log (je provedeno odřádkování pro lepší čitelnost)

Introspection: {"file":"C:\\xampp\\htdocs\\logovani\\src\\app\\procesor\\pouzitiExistujiciProcessor.php",
"line":31,"class":null,"function":null}

2. WebProcessor – URI, request method a client IP

$logger = new Logger('Web');
$logger->pushProcessor(new WebProcessor());
$logger->pushHandler($handler);
$logger->info('zpráva log-info');

Záznam v souboru souborExistujiciProcessor.log (je provedeno odřádkování pro lepší čitelnost)

Web: {"url":"/logovani/src/app/procesor/pouzitiExistujiciProcessor.php",
"ip":"127.0.0.1","http_method":"GET","server":"PHPStorm 2021.2","referrer":null}

3. MemoryUsageProcessor – použitá paměť

$logger = new Logger('MemoryUsage');
$logger->pushProcessor(new MemoryUsageProcessor());
$logger->pushHandler($handler);
$logger->info('zpráva log-info');