The Power Of Log with Monolog

PHPers Summit 2016
20.08.2016 Poznań

Transcript

1. The Power Of Log with Monolog
2. by @skowron-line
3. Logging data - why it is important ??
4. ::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 -
6. ➜ 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 ["tomasz.ucho@gmail.com"] [] [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 ["jan.galazka@gmail.com"] [] [2016-08-09 23:18:43] doctrine.DEBUG: SELECT t0.group FROM groups t0 []
7. Stop! Story time
8. 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; }
9. [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"}
10. Monolog
11. logger handler processor formatter
12. Record
13. [ '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' => [], ]
14. [ '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' => [], ]
15. 100 -> Debug 200 -> Info 250 -> Notice 300 -> Warning 400 -> Error 500 -> Critical 600 -> Emergency
16. Channel
17. [ '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' => [], ]
18. php.DEBUG request.INFO doctrine.DEBUG
19. $logger = new Logger( `channel`);
20. Handler
21. 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
22. 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
23. 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
24. 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
25. 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
26. 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
27. 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
28. ConsoleHandler <service class="..." id="..."> <argument type="service" id="logger" /> </service>
29. ConsoleHandler /** @var HandlerInterface $handler */ foreach ($logger->getHandlers() as $handler) { if (!$handler instanceof ConsoleHandler){ continue; } $handler->setOutput($output); }
30. ConsoleHandler <service class="Symfony\Bridge\Monolog\Logger"> <argument type="string">sample</argument> <argument type="collection"> <argument type="service"> <service class="Symfony\Bridge\Monolog\Handler\ConsoleHandler" /> </argument> </argument> </service>
31. 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
32. RotatingFileHandler - fixed numer of files, named by date Y-m-d - ex. only 14 last days <service class="Monolog\Handler\RotatingFileHandler"> <argument type="expression">parameter('kernel.logs_dir') ~'/ja/'~ parameter('kernel.environment') ~'_postman_'~ service('jobs.postman.manager.helper').getPostmanStrategyName() ~'.log'</argument> <argument type="string">14</argument> </service> - prod_postman_heavy-2016-06-04.log x 14 - prod_postman_regular-2016-05-05.log x 14
33. FingersCrossedHandler - logs are handled when particular error level is call - buffer size is configured, by default is unlimited - decrease logs file
34. Processor
35. [ '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' => [], ]
36. GitProcessor MemoryPeakUsageProcessor MemoryUsageProcessor PsrLogMessageProcessor UidProcessor IntrospectionProcessor MemoryProcessor ProcessIdProcessor TagProcessor WebProcessor
37. $handler = ...; $handler->pushProcessor(new PsrLogMessageProcessor()); $handler->pushProcessor(new GitProcessor()); new Logger('application', [$handler]);
38. 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"}
39. 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"}}
40. 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"}
41. 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
42. services.yml skowronline.monolog.user.processor: parent: skowronline.monolog.user.processor tags: - { name: monolog.processor }
43. Formatter
44. ChromePHPFormatter JsonFormatter LogstashFormatter ScalarFormatter ElasticaFormatter GelfMessageFormatter LineFormatter MongoDBFormatter WildfireFormatter FlowdockFormatter HtmlFormatter LogglyFormatter NormalizerFormatter
45. [ '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' => [], ]
46. [2016-04-08 12:30:52] event.DEBUG: Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Pr ofilerListener::onKernelTerminate". [] []
47. <h1 style="background: #cccccc;color: #ffffff;padding: 5px;" class="monolog-output">DEBUG</h1><table cellspacing="1" width="100%" class="monolog-output"><tr style="padding: 4px;spacing: 0;text-align: left;"> <th style="background: #cccccc" width="100px">Message:</th> <td style="padding: 4px;spacing: 0;text-align: left;background: #eeeeee"><pre>Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\ProfilerListener::onKerne lTerminate</pre></td> </tr><tr style="padding: 4px;spacing: 0;text-align: left;"> <th style="background: #cccccc" width="100px">Time:</th> <td style="padding: 4px;spacing: 0;text-align: left;background: #eeeeee"><pre>2016-06-15 13:38:45</pre></td> </tr><tr style="padding: 4px;spacing: 0;text-align: left;"> <th style="background: #cccccc" width="100px">Channel:</th> <td style="padding: 4px;spacing: 0;text-align: left;background: #eeeeee"><pre>custom</pre></td> </tr></table>
49. $handler = new StreamHandler(...); $handler->setFormatter( new JsonFormatter() );
50. Bubbling
51. $handler = ...; $handler->setBuble(true); new Logger('application', [$handler]);
52. <argument type="collection"> <argument type="service"> <service class="Monolog\Handler\StreamHandler"> <argument type="string">%kernel.logs_dir%/invoice_generator.log</ argument> <call method="setBubble"> <argument type="expression">parameter('kernel.environment') !== "prod"</argument> </call> </service> </argument> <argument type="service"> <service class="Monolog\Handler\SlackHandler" /> </argument> </argument>
53. TriggerLevel
54. $handler = new StreamHandler(‘/prod.log’); $handler->setLevel(Logger::DEBUG); new Logger('application', [$handler]);
55. <argument type="collection"> <argument type="service"> <service class="GoldenLine\UtilsBundle\Monolog\RavenHandler"> <argument type="service" id="raven_client" /> <argument type="constant">Monolog\Logger::CRITICAL</argument> </service> </argument> </argument>
56. Custom Logger
57. <service id="custom.logger" class="Symfony\Bridge\Monolog\Logger"> <argument type="string">custom</argument> <argument type="collection"> <argument type="service"> <service class="Monolog\Handler\StreamHandler"> < argument type="string">%kernel.logs_dir%/custom_logger.log</ argument> </service> </argument> </argument> <call method="pushProcessor"> <argument type="service"> <service class="Monolog\Processor\MemoryUsageProcessor" /> </argument> </call> <tag name="monolog.logger" /> </service>
58. <service id="jobs.archive_suggestions.command" class="GoldenLine\JobsBundle\Command\ArchiveSuggestionsCommand"> <argument type="service"> <service class="Symfony\Bridge\Monolog\Logger"> <argument type="string">suggester.archive</argument> <argument type="collection"> <argument type="service"> <service class="Symfony\Bridge\Monolog\Handler\ConsoleHandler" /> </argument> <argument type="service"> <service class="GoldenLine\UtilsBundle\Monolog\RavenHandler"> <argument type="service" id="raven_client" /> <argument type="expression">constant('\\Monolog\\Logger::CRITICAL')</argument> <call method="setTags"> <argument type="collection"> <argument type="string">command</argument> </argument> </call> </service> </argument> <argument type="service"> <service class="Symfony\Bridge\Monolog\Handler\SwiftMailerHandler"> <argument type="service" id="swiftmailer.mailer" /> <argument type="service"> <service class="Swift_Message"> <argument type="string">Suggester archive command</argument> <call method="setFrom"> <argument type="string">%mail.fo%</argument> <argument type="string">FO</argument> </call> <call method="addTo"> <argument type="string">%mail.fo%</argument> </call> </service> </argument> <argument type="expression">constant('\\Monolog\\Logger::CRITICAL')</argument> </service> </argument> </argument> <argument type="collection"> <argument type="service"> <service class="Monolog\Processor\MemoryUsageProcessor" /> </argument> </argument> </service> </argument> <tag name="console.command" /> </service>
59. - ConsoleHandler - RavenHandler - SwiftMailerHandler
60. LNav Log File Navigator
61. “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”
62. LNav - Format for monolog "regex": { "default": { "pattern": "\\[(?P<timestamp>.*)\\] (?P<logger>\\w+).(?P<level>\\w+): (?P<message>[^\\[\\{]+) (?P<context>[\\[\\{].*[\\]\\}]) (?P<extra>[\\[\\{].*[\\]\\}])" } } https://gist.github.com/skowron-line/000733c361f63206cc9e
63. LNav - Overview
64. LNav - Overview
65. ;SELECT DATE(log_time), logger, COUNT(*) FROM monolog GROUP BY logger, DATE(log_time)
66. ;SELECT message FROM monolog WHERE message LIKE "%title%" AND logger = "doctrine"
67. lnav ./*
68. Sentry
73. $record['extra']['tags'] = [ ‘type’ => ‘suggester’, ... ];
75. $record['context']['user'] = [ 'id' => $user->getId(), 'urlname' => $user->getUrlname(), 'email' => $user->getEmail(), 'session' => $request->getSession()->all(), 'attributes' => $request->attributes->all(), ];
77. References - https://github.com/Seldaek/monolog - http://lnav.readthedocs.io/ - https://gist.github.com/skowron-line/000733c361f63206cc9e - https://github.com/skowron-line/UserProcessorBundle
78. Questions ??
79. T.Hanks