Slide 1

Slide 1 text

The Power Of Log with Monolog

Slide 2

Slide 2 text

by @skowron-line

Slide 3

Slide 3 text

Logging data - why it is important ??

Slide 4

Slide 4 text

::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 -

Slide 5

Slide 5 text

No content

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

Stop! Story time

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

Monolog

Slide 11

Slide 11 text

Jordi Boggiano

Slide 12

Slide 12 text

logger processor formatter handler

Slide 13

Slide 13 text

Record

Slide 14

Slide 14 text

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

Slide 15

Slide 15 text

Log Level

Slide 16

Slide 16 text

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

Channel

Slide 19

Slide 19 text

Slide 20

Slide 20 text

php.DEBUG request.INFO doctrine.DEBUG

Slide 21

Slide 21 text

$logger = new Logger( `channel`);

Slide 22

Slide 22 text

Processor

Slide 23

Slide 23 text

Slide 24

Slide 24 text

GitProcessor MemoryPeakUsageProcessor MemoryUsageProcessor PsrLogMessageProcessor UidProcessor IntrospectionProcessor MemoryProcessor ProcessIdProcessor TagProcessor WebProcessor

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

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

Slide 28

Slide 28 text

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

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

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

Slide 31

Slide 31 text

Formatter

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

Slide 34

Slide 34 text

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

Slide 35

Slide 35 text

DEBUG

Message:

Notified event "kernel.terminate" to listener
"Symfony\Component\HttpKernel\EventListener\ProfilerListener::onKerne
lTerminate

Time:

2016-06-15 13:38:45

Channel:

custom

Slide 36

Slide 36 text

No content

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

Handler

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

Slide 41

Slide 41 text

Slide 42

Slide 42 text

Slide 43

Slide 43 text

Slide 44

Slide 44 text

Slide 45

Slide 45 text

Slide 46

Slide 46 text

ConsoleHandler

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

ConsoleHandler sample

Slide 49

Slide 49 text

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

Slide 50

Slide 50 text

No content

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

Bubbling

Slide 54

Slide 54 text

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

Slide 55

Slide 55 text

%kernel.logs_dir%/invoice_generator.log argument> parameter('kernel.environment') !== "prod"

Slide 56

Slide 56 text

TriggerLevel

Slide 57

Slide 57 text

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

Slide 58

Slide 58 text

Monolog\Logger::CRITICAL

Slide 59

Slide 59 text

Custom Logger

Slide 60

Slide 60 text

custom %kernel.logs_dir%/custom_logger.log

Slide 61

Slide 61 text

suggester.archive Monolog\Logger::CRITICAL command Suggester archive command %mail.fo% FO %mail.fo% Monolog\Logger::CRITICAL

Slide 62

Slide 62 text

Slide 63

Slide 63 text

Monolog\Logger::CRITICAL command

Slide 64

Slide 64 text

Suggester archive command %mail.fo% FO %mail.fo% Monolog\Logger::CRITICAL

Slide 65

Slide 65 text

Back to the story

Slide 66

Slide 66 text

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

Slide 67

Slide 67 text

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

Slide 68

Slide 68 text

PsrLogMessageProcessor + CustomFormatter

Slide 69

Slide 69 text

public function format(array $record) { return $record['message']; } public function formatBatch(array $records) { $message = ''; foreach ($records as $record) { $message .= $this->format($record); } return $message; }

Slide 70

Slide 70 text

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

Slide 71

Slide 71 text

LNav Log File Navigator

Slide 72

Slide 72 text

“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”

Slide 73

Slide 73 text

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

Slide 74

Slide 74 text

LNav - Overview

Slide 75

Slide 75 text

LNav - Overview

Slide 76

Slide 76 text

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

Slide 77

Slide 77 text

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

Slide 78

Slide 78 text

lnav ./*

Slide 79

Slide 79 text

No content

Slide 80

Slide 80 text

No content

Slide 81

Slide 81 text

No content

Slide 82

Slide 82 text

No content

Slide 83

Slide 83 text

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

Slide 84

Slide 84 text

No content

Slide 85

Slide 85 text

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

Slide 86

Slide 86 text

No content

Slide 87

Slide 87 text

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