The Power Of Log with Monolog

by @skowron-line

Logging data - why it is important ??

::1 - - [02/Aug/2016:21:36:47 +0200] "GET / HTTP/1.1" 200 45 ::1 - - [02/Aug/2016:21:37:10 +0200] "GET /sample.php HTTP/1.1" 404 208 ::1 - - [02/Aug/2016:21:37:13 +0200] "GET /sample.php HTTP/1.1" 404 208 ::1 - - [02/Aug/2016:21:42:19 +0200] "GET / HTTP/1.1" 200 45 ::1 - - [05/Aug/2016:09:42:47 +0200] "GET /sample.php HTTP/1.1" 404 208 ::1 - - [08/Aug/2016:08:28:22 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:28:23 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:28:23 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:28:24 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:29:10 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:29:14 +0200] "GET /sample.php HTTP/1.1" 404 208 ::1 - - [08/Aug/2016:08:34:30 +0200] "GET / HTTP/1.1" 304 - ::1 - - [08/Aug/2016:08:34:36 +0200] "GET / HTTP/1.1" 304 -

No content

➜ application git:(master) cat app/logs/dev.log | grep doctrine.DEBUG [2016-08-09 23:17:10] doctrine.DEBUG: SELECT t0.username AS username_1, t0.username_canonical AS username_canonical_2, t0.email AS email_3, t0.email_canonical AS email_canonical_4, t0.enabled AS enabled_5, t0.salt AS salt_6, t0.password AS password_7, t0.last_login AS last_login_8, t0.locked AS locked_9, t0.expired AS expired_10, t0.expires_at AS expires_at_11, t0.confirmation_token AS confirmation_token_12, t0.password_requested_at AS password_requested_at_13, t0.roles AS roles_14, t0.credentials_expired AS credentials_expired_15, t0.credentials_expire_at AS credentials_expire_at_16, t0.id AS id_17 FROM users t0 WHERE t0.username_canonical = ? LIMIT 1 ["[email protected]"] [] [2016-08-09 23:18:41] doctrine.DEBUG: SELECT t0.username AS username_1, t0.username_canonical AS username_canonical_2, t0.email AS email_3, t0.email_canonical AS email_canonical_4, t0.enabled AS enabled_5, t0.salt AS salt_6, t0.password AS password_7, t0.last_login AS last_login_8, t0.locked AS locked_9, t0.expired AS expired_10, t0.expires_at AS expires_at_11, t0.confirmation_token AS confirmation_token_12, t0.password_requested_at AS password_requested_at_13, t0.roles AS roles_14, t0.credentials_expired AS credentials_expired_15, t0.credentials_expire_at AS credentials_expire_at_16, t0.id AS id_17 FROM users t0 WHERE t0.username_canonical = ? LIMIT 1 ["[email protected]"] [] [2016-08-09 23:18:43] doctrine.DEBUG: SELECT t0.group FROM groups t0 []

Stop! Story time

if (true === empty($profitReport)) { $this->logger->error('No profit report found. Can\'t generate report.'); return; } if (0 === $operatorProfit) { $this->logger->error('Skipped due to zero operator profit {operatorId}', ['operatorId'=> $operatorId]); continue; } if (0 === $operatorLocalizations) { $this->logger->error('Skipped due to zero operator localizations {operatorId}', ['operatorId'=> $operatorId]); continue; }

[2016-08-10 23:38:15] report.ERROR: Skipped due to zero operator profit {operatorId} {"operatorId":6} {"memory_usage":"23 MB"} [2016-08-10 23:38:15] report.ERROR: Skipped due to zero operator profit {operatorId} {"operatorId":12} {"memory_usage":"23.25 MB"} [2016-08-10 23:38:15] report.ERROR: Skipped due to zero operator localizations {operatorId} {"operatorId":39} {"memory_usage":"29 MB"} [2016-08-10 23:38:15] report.ERROR: Skipped due to zero operator profit {operatorId} {"operatorId":41} {"memory_usage":"29 MB"}

Monolog

logger handler processor formatter

Record

[ 'message' => 'Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Profil erListener::onKernelTerminate"', 'context' => [], 'level' => '100', 'level_name' => 'debug', 'channel' => 'event', 'datetime' => '2016-04-08 12:30:52' 'extra' => [], ]

[ 'message' => 'Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Profil erListener::onKernelTerminate"', 'context' => [], 'level' => '100', 'level_name' => 'debug', 'channel' => 'event', 'datetime' => '2016-04-08 12:30:52' 'extra' => [], ]

100 -> Debug 200 -> Info 250 -> Notice 300 -> Warning 400 -> Error 500 -> Critical 600 -> Emergency

Channel

[ 'message' => 'Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Profil erListener::onKernelTerminate"', 'context' => [], 'level' => '100', 'level_name' => 'debug', 'channel' => 'event', 'datetime' => '2016-04-08 12:30:52' 'extra' => [], ]

php.DEBUG request.INFO doctrine.DEBUG

$logger = new Logger( `channel`);

Handler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

AmqpHandler BrowserConsoleHandl er BufferHandler ChromePHPHandler CouchDBHandler CubeHandler DeduplicationHandler DoctrineCouchDBHan dler DynamoDbHandler ElasticSearchHandler ErrorLogHandler FilterHandler FingersCrossedHandle r FirePHPHandler FleepHookHandler FlowdockHandler GelfHandler GroupHandler HipChatHandler IFTTTHandler LogEntriesHandler LogglyHandler MailHandler MandrillHandler MongoDBHandler NativeMailerHandler NewRelicHandler NullHandler PHPConsoleHandler PsrHandler PushoverHandler RavenHandler RedisHandler RollbarHandler RotatingFileHandler SamplingHandler SlackHandler SocketHandler StreamHandler SwiftMailerHandler SyslogHandler SyslogUdpHandler TestHandler WhatFailureGroupHan dler ZendMonitorHandler

ConsoleHandler

ConsoleHandler /** @var HandlerInterface $handler */ foreach ($logger->getHandlers() as $handler) { if (!$handler instanceof ConsoleHandler){ continue; } $handler->setOutput($output); }

ConsoleHandler sample

ConsoleHandler - OutputInterface::VERBOSITY_NORMAL will show all WARNING and higher logs - OutputInterface::VERBOSITY_VERBOSE (-v) will show all NOTICE and higher logs - OutputInterface::VERBOSITY_VERY_VERBOSE (-vv) will show all INFO and higher logs - OutputInterface::VERBOSITY_DEBUG (-vvv) will show all DEBUG and higher logs, i.e. all logs

RotatingFileHandler - fixed numer of files, named by date Y-m-d - ex. only 14 last days parameter('kernel.logs_dir') ~'/ja/'~ parameter('kernel.environment') ~'_postman_'~ service('jobs.postman.manager.helper').getPostmanStrategyName() ~'.log' 14 - prod_postman_heavy-2016-06-04.log x 14 - prod_postman_regular-2016-05-05.log x 14

FingersCrossedHandler - logs are handled when particular error level is call - buffer size is configured, by default is unlimited - decrease logs file

Processor

[ 'message' => 'Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Profil erListener::onKernelTerminate"', 'context' => [], 'level' => '100', 'level_name' => 'debug', 'channel' => 'event', 'datetime' => '2016-04-08 12:30:52' 'extra' => [], ]

GitProcessor MemoryPeakUsageProcessor MemoryUsageProcessor PsrLogMessageProcessor UidProcessor IntrospectionProcessor MemoryProcessor ProcessIdProcessor TagProcessor WebProcessor

$handler = ...; $handler->pushProcessor(new PsrLogMessageProcessor()); $handler->pushProcessor(new GitProcessor()); new Logger('application', [$handler]);

MemoryUsageProcessor $monolog->debug('Start generating invoice for {user}', ['user' => $this->getUser()->getName(),]); [2016-06-15 15:05:55] custom.DEBUG: Start generating invoice for {user} {"user":"skowron-line"} {"memory_usage":"12.25 MB"}

GitProcessor $monolog->debug('Start generating invoice for {user}', ['user' => $this->getUser()->getName(),]); [2016-06-15 15:12:41] custom.DEBUG: Start generating invoice for {user} {"user":"skowron-line"} {"git":{"branch":"master","commit":"0235f841f3671e6f4e0bcf6a cad8dcee7d03c69a"}}

PsrLogMessageProcessor $monolog->debug(sprintf('Start generating invoice for %s', $this->getUser()->getName())); $monolog->debug('Start generating invoice for {user}', ['user' => $this->getUser()->getName(),]); [2016-06-15 15:12:41] custom.DEBUG: Start generating invoice for skowron-line {"user":"skowron-line"}

UserProcessor $monolog->debug('Start generating invoice for {user}', ['user' => $this->getUser()->getName(),]); [2016-06-15 15:06:02] custom.DEBUG: Start generating invoice for {user} {"user":"skowron-line"} {"user":"skowron-line"} https://github.com/skowron-line/UserProcessorBundle

services.yml skowronline.monolog.user.processor: parent: skowronline.monolog.user.processor tags: - { name: monolog.processor }

Formatter

ChromePHPFormatter JsonFormatter LogstashFormatter ScalarFormatter ElasticaFormatter GelfMessageFormatter LineFormatter MongoDBFormatter WildfireFormatter FlowdockFormatter HtmlFormatter LogglyFormatter NormalizerFormatter

[ 'message' => 'Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Profil erListener::onKernelTerminate"', 'context' => [], 'level' => '100', 'level_name' => 'debug', 'channel' => 'event', 'datetime' => '2016-04-08 12:30:52' 'extra' => [], ]

[2016-04-08 12:30:52] event.DEBUG: Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Pr ofilerListener::onKernelTerminate". [] []

DEBUG

Message:

Notified event "kernel.terminate" to listener
"Symfony\Component\HttpKernel\EventListener\ProfilerListener::onKerne
lTerminate

Time:

2016-06-15 13:38:45

Channel:

custom

No content

$handler = new StreamHandler(...); $handler->setFormatter( new JsonFormatter() );

Bubbling

$handler = ...; $handler->setBuble(true); new Logger('application', [$handler]);

%kernel.logs_dir%/invoice_generator.log argument> parameter('kernel.environment') !== "prod"

TriggerLevel

$handler = new StreamHandler(‘/prod.log’); $handler->setLevel(Logger::DEBUG); new Logger('application', [$handler]);

Monolog\Logger::CRITICAL

Custom Logger

custom < argument type="string">%kernel.logs_dir%/custom_logger.log argument>

suggester.archive constant('\\Monolog\\Logger::CRITICAL') command Suggester archive command %mail.fo% FO %mail.fo% constant('\\Monolog\\Logger::CRITICAL')

- ConsoleHandler - RavenHandler - SwiftMailerHandler

LNav Log File Navigator

“Log files are directly used as the backing for SQLite virtual tables. This means you can perform queries on messages without having to load the data into an SQL database”

LNav - Format for monolog "regex": { "default": { "pattern": "\\[(?P.*)\\] (?P\\w+).(?P\\w+): (?P[^\\[\\{]+) (?P[\\[\\{].*[\\]\\}]) (?P[\\[\\{].*[\\]\\}])" } } https://gist.github.com/skowron-line/000733c361f63206cc9e

LNav - Overview

LNav - Overview

;SELECT DATE(log_time), logger, COUNT(*) FROM monolog GROUP BY logger, DATE(log_time)

;SELECT message FROM monolog WHERE message LIKE "%title%" AND logger = "doctrine"

lnav ./*

Sentry

No content

No content

No content

No content

$record['extra']['tags'] = [ ‘type’ => ‘suggester’, ... ];

No content

$record['context']['user'] = [ 'id' => $user->getId(), 'urlname' => $user->getUrlname(), 'email' => $user->getEmail(), 'session' => $request->getSession()->all(), 'attributes' => $request->attributes->all(), ];

No content

References - https://github.com/Seldaek/monolog - http://lnav.readthedocs.io/ - https://gist.github.com/skowron-line/000733c361f63206cc9e - https://github.com/skowron-line/UserProcessorBundle

Questions ??

T.Hanks