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 full-size slide

  2. by @skowron-line

    View full-size slide

  3. Logging data - why it is important ??

    View full-size 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 full-size slide

  5. ➜ 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 full-size slide

  6. Stop! Story time

    View full-size slide

  7. 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 full-size slide

  8. [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 full-size slide

  9. Jordi Boggiano

    View full-size slide

  10. logger
    processor
    formatter
    handler

    View full-size slide

  11. [
    '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 full-size slide

  12. [
    '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 full-size slide

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

    View full-size 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 full-size slide

  15. php.DEBUG
    request.INFO
    doctrine.DEBUG

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  20. 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 full-size slide

  21. 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 full-size slide

  22. 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 full-size slide

  23. 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 full-size slide

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

    View full-size slide

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

    View full-size slide

  26. [
    '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 full-size slide

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

    View full-size slide

  28. 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 full-size slide

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

    View full-size slide

  30. 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 full-size slide

  31. 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 full-size slide

  32. 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 full-size slide

  33. 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 full-size slide

  34. 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 full-size slide

  35. 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 full-size slide

  36. 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 full-size slide

  37. ConsoleHandler



    View full-size slide

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

    View full-size slide

  39. ConsoleHandler

    sample


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



    View full-size slide

  40. 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 full-size slide

  41. 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 full-size slide

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

    View full-size slide

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

    View full-size slide




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

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







    View full-size slide

  45. TriggerLevel

    View full-size slide

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

    View full-size slide



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

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



    View full-size slide

  48. Custom Logger

    View full-size slide


  49. custom



    %kernel.logs_dir%/custom_logger.log










    View full-size slide




  50. suggester.archive







    Monolog\Logger::CRITICAL


    command









    Suggester archive command

    %mail.fo%
    FO


    %mail.fo%



    Monolog\Logger::CRITICAL












    View full-size slide

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

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


    command



    View full-size slide





  52. Suggester archive command

    %mail.fo%
    FO


    %mail.fo%



    Monolog\Logger::CRITICAL

    View full-size slide

  53. Back to the story

    View full-size slide

  54. 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 full-size slide

  55. [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 full-size slide

  56. PsrLogMessageProcessor
    +
    CustomFormatter

    View full-size slide

  57. 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 full-size slide

  58. 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 full-size slide

  59. LNav
    Log File Navigator

    View full-size slide

  60. “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 full-size slide

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

    View full-size slide

  62. LNav - Overview

    View full-size slide

  63. LNav - Overview

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  69. Questions ??

    View full-size slide