Upgrade to Pro — share decks privately, control downloads, hide ads and more …

The Power Of Log with Monolog

The Power Of Log with Monolog

PHPCon 2016

K.Skaradziński

October 02, 2016
Tweet

More Decks by K.Skaradziński

Other Decks in Programming

Transcript

  1. The Power
    Of Log
    with Monolog

    View Slide

  2. by @skowron-line

    View Slide

  3. Logging data - why it is important ??

    View Slide

  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 -

    View Slide

  5. View Slide

  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 ["[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 []

    View Slide

  7. Stop! Story time

    View Slide

  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;
    }

    View Slide

  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"}

    View Slide

  10. Monolog

    View Slide

  11. Jordi Boggiano

    View Slide

  12. logger
    processor
    formatter
    handler

    View Slide

  13. Record

    View Slide

  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' => [],
    ]

    View Slide

  15. Log Level

    View Slide

  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' => [],
    ]

    View Slide

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

    View Slide

  18. Channel

    View Slide

  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' => [],
    ]

    View Slide

  20. php.DEBUG
    request.INFO
    doctrine.DEBUG

    View Slide

  21. $logger = new Logger( `channel`);

    View Slide

  22. Processor

    View Slide

  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' => [],
    ]

    View Slide

  24. GitProcessor
    MemoryPeakUsageProcessor
    MemoryUsageProcessor
    PsrLogMessageProcessor
    UidProcessor
    IntrospectionProcessor
    MemoryProcessor
    ProcessIdProcessor
    TagProcessor
    WebProcessor

    View Slide

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

    View Slide

  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"}

    View Slide

  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"}}

    View Slide

  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"}

    View Slide

  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

    View Slide

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

    View Slide

  31. Formatter

    View Slide

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

    View Slide

  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' => [],
    ]

    View Slide

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

    View Slide

  35. class="monolog-output">DEBUGclass="monolog-output">
    Message:
    Notified event "kernel.terminate" to listener
    "Symfony\Component\HttpKernel\EventListener\ProfilerListener::onKerne
    lTerminate

    Time:
    2016-06-15 13:38:45

    Channel:
    custom

    View Slide

  36. View Slide

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

    View Slide

  38. Handler

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  46. ConsoleHandler



    View Slide

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

    View Slide

  48. ConsoleHandler

    sample


    class="Symfony\Bridge\Monolog\Handler\ConsoleHandler" />



    View Slide

  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

    View Slide

  50. View Slide

  51. 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

    View Slide

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

    View Slide

  53. Bubbling

    View Slide

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

    View Slide




  55. type="string">%kernel.logs_dir%/invoice_generator.log
    argument>

    type="expression">parameter('kernel.environment') !==
    "prod"







    View Slide

  56. TriggerLevel

    View Slide

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

    View Slide



  58. class="GoldenLine\UtilsBundle\Monolog\RavenHandler">

    type="constant">Monolog\Logger::CRITICAL



    View Slide

  59. Custom Logger

    View Slide


  60. custom



    %kernel.logs_dir%/custom_logger.log










    View Slide




  61. suggester.archive







    Monolog\Logger::CRITICAL


    command









    Suggester archive command

    %mail.fo%
    FO


    %mail.fo%



    Monolog\Logger::CRITICAL












    View Slide




  62. View Slide

  63. class="GoldenLine\UtilsBundle\Monolog\RavenHandler">

    type="constant">Monolog\Logger::CRITICAL


    command



    View Slide





  64. Suggester archive command

    %mail.fo%
    FO


    %mail.fo%



    Monolog\Logger::CRITICAL

    View Slide

  65. Back to the story

    View Slide

  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;
    }

    View Slide

  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"}

    View Slide

  68. PsrLogMessageProcessor
    +
    CustomFormatter

    View Slide

  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;
    }

    View Slide

  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

    View Slide

  71. LNav
    Log File Navigator

    View Slide

  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”

    View Slide

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

    View Slide

  74. LNav - Overview

    View Slide

  75. LNav - Overview

    View Slide

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

    View Slide

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

    View Slide

  78. lnav ./*

    View Slide

  79. View Slide

  80. View Slide

  81. View Slide

  82. View Slide

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

    View Slide

  84. View Slide

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

    View Slide

  86. View Slide

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

    View Slide

  88. Questions ??

    View Slide

  89. T.Hanks

    View Slide