The Power Of Log with Monolog

PHPCon 2016

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. Jordi Boggiano
12. logger processor formatter handler
13. Record
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. Log Level
16. [ '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' => [], ]
17. 100 -> Debug 200 -> Info 250 -> Notice 300 -> Warning 400 -> Error 500 -> Critical 600 -> Emergency
18. Channel
19. [ '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' => [], ]
20. php.DEBUG request.INFO doctrine.DEBUG
21. $logger = new Logger( `channel`);
22. Processor
23. [ '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' => [], ]
24. GitProcessor MemoryPeakUsageProcessor MemoryUsageProcessor PsrLogMessageProcessor UidProcessor IntrospectionProcessor MemoryProcessor ProcessIdProcessor TagProcessor WebProcessor
25. $handler = ...; $handler->pushProcessor(new PsrLogMessageProcessor()); $handler->pushProcessor(new GitProcessor()); new Logger('application', [$handler]);
26. 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"}
27. 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"}}
28. 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"}
29. 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
30. skowronline.monolog.user.processor: parent: skowronline.monolog.user.processor tags: - { name: monolog.processor }
31. Formatter
32. ChromePHPFormatter JsonFormatter LogstashFormatter ScalarFormatter ElasticaFormatter GelfMessageFormatter LineFormatter MongoDBFormatter WildfireFormatter FlowdockFormatter HtmlFormatter LogglyFormatter NormalizerFormatter
33. [ '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' => [], ]
34. [2016-04-08 12:30:52] event.DEBUG: Notified event "kernel.terminate" to listener "Symfony\Component\HttpKernel\EventListener\Pr ofilerListener::onKernelTerminate". [] []
35. <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>
37. $handler = new StreamHandler(...); $handler->setFormatter( new JsonFormatter() );
38. Handler
39. 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
40. 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
41. 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
42. 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
43. 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
44. 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
45. 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
46. ConsoleHandler <service class="..." id="..."> <argument type="service" id="logger" /> </service>
47. ConsoleHandler /** @var HandlerInterface $handler */ foreach ($logger->getHandlers() as $handler) { if (!$handler instanceof ConsoleHandler){ continue; } $handler->setOutput($output); }
48. 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>
49. 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
51. 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
52. FingersCrossedHandler - logs are handled when particular error level is call - buffer size is configured, by default is unlimited - decrease logs file
53. Bubbling
54. $handler = ...; $handler->setBuble(true); new Logger('application', [$handler]);
55. <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>
56. TriggerLevel
57. $handler = new StreamHandler(‘/prod.log’); $handler->setLevel(Logger::DEBUG); new Logger('application', [$handler]);
58. <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>
59. Custom Logger
60. <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>
61. <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="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="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>
62. <argument type="service"> <service class="Symfony\Bridge\Monolog\Handler\ConsoleHandler" /> </argument>
63. <service class="GoldenLine\UtilsBundle\Monolog\RavenHandler"> <argument type="service" id="raven_client" /> <argument type="constant">Monolog\Logger::CRITICAL</argument> <call method="setTags"> <argument type="collection"> <argument type="string">command</argument> </argument> </call> </service>
64. <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="constant">Monolog\Logger::CRITICAL</argument> </service>
65. Back to the story
66. 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 {operator}', ['operator'=> $operatorFullName]); continue; } if (0 === $operatorLocalizations) { $this->logger->error('Skipped due to zero operator localizations {operator}', ['operator'=> $operatorFullName]); continue; }
67. [2016-08-10 23:38:15] report.ERROR: {operator}, skipped due to zero operator profit {"operator": "John Doe"} {"memory_usage":"23 MB"} [2016-08-10 23:38:15] report.ERROR: {operator}, skipped due to zero operator profit {"operator": "Dan Smith"} {"memory_usage":"23.25 MB"} [2016-08-10 23:38:15] report.ERROR:{operator}, skipped due to zero operator localizations {"operator": "Tom Jones"} {"memory_usage":"29 MB"} [2016-08-10 23:38:15] report.ERROR: {operator}, skipped due to zero operator profit {"operator": "Michael Jordan"} {"memory_usage":"29 MB"}
68. PsrLogMessageProcessor + CustomFormatter
69. public function format(array $record) { return $record['message']; } public function formatBatch(array $records) { $message = ''; foreach ($records as $record) { $message .= $this->format($record); } return $message; }
70. John Doe, skipped due to zero operator profit Dan Smith, skipped due to zero operator profit Tom Jones, skipped due to zero operator localizations Michael Jordan, skipped due to zero operator profit
71. LNav Log File Navigator
72. “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”
73. 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
74. LNav - Overview
75. LNav - Overview
76. ;SELECT DATE(log_time), logger, COUNT(*) FROM monolog GROUP BY logger, DATE(log_time)
77. ;SELECT message FROM monolog WHERE message LIKE "%title%" AND logger = "doctrine"
78. lnav ./*
83. $record['extra']['tags'] = [ ‘type’ => ‘command’, ... ];
85. $record['context']['user'] = [ 'id' => $user->getId(), 'urlname' => $user->getUrlname(), 'email' => $user->getEmail(), 'session' => $request->getSession()->all(), 'attributes' => $request->attributes->all(), ];
87. References - https://github.com/Seldaek/monolog - http://lnav.readthedocs.io/ - https://gist.github.com/skowron-line/000733c361f63206cc9e - https://github.com/skowron-line/UserProcessorBundle
88. Questions ??
89. T.Hanks