The Power Of Log with Monolog

The Power Of Log with Monolog

PHPers Summit 2016
20.08.2016 Poznań

6280bd845b84c195239417cdb33575c8?s=128

K.Skaradziński

August 20, 2016
Tweet

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 -
  5. None
  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>
  48. None
  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

  69. None
  70. None
  71. None
  72. None
  73. $record['extra']['tags'] = [ ‘type’ => ‘suggester’, ... ];

  74. None
  75. $record['context']['user'] = [ 'id' => $user->getId(), 'urlname' => $user->getUrlname(), 'email'

    => $user->getEmail(), 'session' => $request->getSession()->all(), 'attributes' => $request->attributes->all(), ];
  76. None
  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