Making Logs Useful - Speaker Deck

Slide 1

Slide 1 text

Making logs useful with monolog and the ELK stack Will Donohoe McSimp Melbourne PHP Users Group March 2015

Slide 2

Slide 2 text

Example Script setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION); $db->setAttribute(PDO::ATTR_EMULATE_PREPARES, false); $requestCode = $_POST['code']; if (strlen($requestCode) < 3) { die('[]'); } $stmt = $db->prepare("SELECT col1,col2 FROM sometable WHERE code LIKE CONCAT(?, '%') LIMIT 10;"); $stmt->execute([$requestCode]); $rows = $stmt->fetchAll(PDO::FETCH_ASSOC); echo json_encode($rows);

Slide 3

Slide 3 text

PHP Fatal error: Uncaught exception 'PDOException' with message 'SQLSTATE[HY000]: General error: 1267 Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation 'like'' in / path/to/file.php:16 $stmt = $db->prepare("SELECT col1,col2 FROM sometable WHERE code LIKE CONCAT(?, '%') LIMIT 10;"); $stmt->execute([$requestCode]); PHP Error Log • Rough idea of the problem, but some context would be useful

Slide 4

Slide 4 text

Logging in PHP • How do you log things in PHP (without a library)? • echo  FAIL - That’s not logging • file_put_contents('my.log', ...);  Not ideal - No log rotation, lots of boilerplate    You'll end up running ‘rm my.log’ when disk has 0 bytes free and it's 3am. • error_log('Log message’);  Bit of a hack - Misleading for informational messages

Slide 5

Slide 5 text

error_log • Ugly output, and it’s in the error log

Slide 6

Slide 6 text

Monolog • https://github.com/Seldaek/monolog • Made by Jordi Boggiano (Composer, Symfony) • Requirements: PHP 5.3+ • Lots of built-in functionality, easy to extend

Slide 7

Slide 7 text

Install Monolog $ composer require monolog/monolog

Slide 8

Slide 8 text

pushHandler(new StreamHandler('example.log', Logger::DEBUG)); ErrorHandler::register($log); $db = new PDO(...); $db->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION); $db->setAttribute(PDO::ATTR_EMULATE_PREPARES, false); $requestCode = $_POST['code']; if (strlen($requestCode) < 3) { $log->addInfo('Invalid request code', ['code' => $requestCode]); die('[]'); } $log->addInfo('Valid request code', ['code' => $requestCode]); $stmt = $db->prepare("SELECT col1,col2 FROM sometable WHERE code LIKE CONCAT(?, '%') LIMIT 10;"); $stmt->execute([$requestCode]); $rows = $stmt->fetchAll(PDO::FETCH_ASSOC); echo json_encode($rows);

Slide 9

Slide 9 text

Slide 10

Slide 10 text

Slide 11

Slide 11 text

Slide 12

Slide 12 text

Handlers • Take in log records • Apply formatters and processors (more on these later) • Do something with ﬁnal log message (e.g. write to ﬁle, send to syslog, buffer) • Implement HandlerInterface

Slide 13

Slide 13 text

HandlerInterface /** * Handles a record. * * All records may be passed to this method, and the handler * should discard those that it does not want to handle. * * The return value of this function controls the bubbling * process of the handler stack. Unless the bubbling is * interrupted (by returning true), the Logger class will keep on * calling further handlers in the stack with a given log record. * * @param array $record The record to handle * @return Boolean true means that this handler handled the record, * and that bubbling is not permitted. * false means the record was either not processed * or that this handler allows bubbling. */ public function handle(array $record); (Basically)

Slide 14

Slide 14 text

StreamHandler new StreamHandler('example.log', Logger::DEBUG) • Destination • Anything PHP can fopen/fwrite Minimum level

Slide 15

Slide 15 text

Log Levels Name Level Description DEBUG 100 Detailed debug information INFO 200 Interesting events. Examples: User logs in, SQL logs. NOTICE 250 Uncommon events WARNING 300 Exceptional occurrences that are not errors ERROR 400 Runtime errors CRITICAL 500 Critical conditions. Example: Application component unavailable, unexpected exception. ALERT 550 Action must be taken immediately. This should wake you up. EMERGENCY 600 Urgent alert

Slide 16

Slide 16 text

Slide 17

Slide 17 text

Slide 18

Slide 18 text

Adding logs • Logger provides method for each level /** * Adds a log record at the INFO level. * * @param string $message The log message * @param array $context The log context * @return Boolean Whether the record has been processed */ public function addInfo($message, array $context = array()) $log->addInfo('Valid request code', ['code' => $requestCode]); • Use $context instead of string concatenation

Slide 19

Slide 19 text

Example Output [2015-‐03-‐16 15:09:34] example.INFO: Got a request [] [] [2015-‐03-‐16 15:09:34] example.INFO: Valid request code {"code":"TEST1"} [] [2015-‐03-‐16 15:09:41] example.INFO: Got a request [] [] [2015-‐03-‐16 15:09:41] example.INFO: Invalid request code {"code":"NO"} [] [2015-‐03-‐16 15:09:45] example.INFO: Got a request [] [] [2015-‐03-‐16 15:09:45] example.NOTICE: E_NOTICE: Undefined index: code {"code":8,"message":"Undefined index: code”,”file":"/path/to/ test.php","line":21} [] [2015-‐03-‐16 15:09:45] example.INFO: Invalid request code {"code":""} [] [2015-‐03-‐16 15:09:50] example.INFO: Got a request [] [] [2015-‐03-‐16 15:09:50] example.INFO: Valid request code [] [2015-‐03-‐16 15:09:50] example.ERROR: Uncaught Exception PDOException: "SQLSTATE[HY000]: General error: 1267 Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation 'like'" at /path/to/test.php line 31 {"exception":"[object] (PDOException(code: HY000): SQLSTATE[HY000]: General error: 1267 Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation 'like' at /path/to/test.php: 31)"} []

Slide 20

Slide 20 text

Formatters • Applied to handlers to transform log messages before being saved • One per handler • Default is LineFormatter (previous slide) • Lots already built in • Easy to make your own

Slide 21

Slide 21 text

FormatterInterface interface FormatterInterface { /** * Formats a log record. * * @param array $record A record to format * @return mixed The formatted record */ public function format(array $record); // ... } (Basically)

Slide 22

Slide 22 text

Custom formatter example • Converts strings in context with non-printable characters to hex • Documentation lacking on $record format, easier to var_dump it

Slide 23

Slide 23 text

Custom formatter example array (size=7) 'message' => string 'Valid request code' (length=18) 'context' => array (size=1) 'code' => string 'abc' (length=3) 'level' => int 200 'level_name' => string 'INFO' (length=4) 'channel' => string 'example' (length=7) 'datetime' => object(DateTime)[8] public 'date' => string '2015-03-16 18:17:09.206215' (length=26) public 'timezone_type' => int 3 public 'timezone' => string 'Australia/Melbourne' (length=19) 'extra' => array (size=0) empty

Slide 24

Slide 24 text

Custom formatter example $val) { if (is_string($val) && !ctype_print($val)) { $record['context'][$key] = '0x' . bin2hex($val); } } return parent::format($record); } ... }

Slide 25

Slide 25 text

Custom formatter example $log = new Logger('example'); $handler = new StreamHandler('example.log', Logger::DEBUG); $handler->setFormatter(new SpecialCharFormatter()); $log->pushHandler($handler);

Slide 26

Slide 26 text

Custom formatter example [2015-‐03-‐16 18:29:06] example.INFO: Got a request [] [] [2015-‐03-‐16 18:29:06] example.INFO: Valid request code {"code":"TEST1"} [] [2015-‐03-‐16 18:29:10] example.INFO: Got a request [] [] [2015-‐03-‐16 18:29:10] example.INFO: Valid request code {"code":"0x618063"} [] [2015-‐03-‐16 18:29:10] example.ERROR: Uncaught Exception PDOException: "SQLSTATE[HY000]: ...”} [] • 0x80 inside the parameter breaks things

Slide 27

Slide 27 text

Processors • Add additional context to every log entry • As many as you want per handler • Lots built in already • Noisy (usually apply to every log message) • Easy to make your own

Slide 28

Slide 28 text

WebProcessor $handler->pushProcessor(new Monolog\Processor\WebProcessor()); [2015-‐03-‐16 18:35:31] example.INFO: Got a request [] {“url”:”/ test.php","ip":"10.10.0.142","http_method":"POST","server":"0.0.0.0","r eferrer":null} [2015-‐03-‐16 18:35:31] example.INFO: Valid request code {"code":"TEST1"} {"url":"/ test.php","ip":"10.10.0.142","http_method":"POST","server":"0.0.0.0","r eferrer":null}

Slide 29

Slide 29 text

Processors • GitProcessor adds current commit hash • Make your own for user information (ID, name)

Slide 30

Slide 30 text

FingersCrossedHandler • Noisy logs = annoying and ignored • Only keep logs if there is one of sufﬁcient level • No problems means no logs • No more noise! • Awesome feature

Slide 31

Slide 31 text

FingersCrossedHandler Handler to forward logs to Trigger level use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\Handler\FingersCrossedHandler; $log = new Logger('example'); $handler = new StreamHandler('example.log', Logger::DEBUG); $fcHandler = new FingersCrossedHandler($handler, Logger::WARNING); $log->pushHandler($fcHandler);

Slide 32

Slide 32 text

FingersCrossedHandler $log->addInfo(...); $log->addDebug(...); $log->addNotice(...); $log->addInfo(...); $log->addInfo(...); $log->addWarning(...); $log->addNotice(...); $log->addInfo(...); 0 log entries added 4 log entries added

Slide 33

Slide 33 text

Stacking Handlers • Add as many handlers as you want • Structured as a stack • Built in handlers will bubble by default • Specialise behaviour depending on level

Slide 34

Slide 34 text

Stacking Handlers use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\Handler\FingersCrossedHandler; use Monolog\Handler\PushoverHandler; $log = new Logger('example'); $handler = new StreamHandler('example.log', Logger::DEBUG); $fcHandler = new FingersCrossedHandler($handler, Logger::WARNING); $poHandler = new PushoverHandler('API KEY', 'User ID', 'Example Alert', Logger::CRITICAL); $log->pushHandler($fcHandler); $log->pushHandler($poHandler); // ... $log->addCritical('Something bad happened!');

Slide 35

Slide 35 text

The ELK Stack • Refers to Elasticsearch + Logstash + Kibana • Really needs a separate talk • Elasticsearch stores JSON documents • Logstash pushes data into ES • Kibana pulls data out • Useful when you have lots of logs • Lots of moving parts, beware!

Slide 36

Slide 36 text

The ELK Stack • Setup is… painful • Have a look around for ansible playbooks • https://www.digitalocean.com/community/tutorials/ how-to-use-logstash-and-kibana-to-centralize-and- visualize-logs-on-ubuntu-14-04

Slide 37

Slide 37 text

Shipping logs to Logstash • LOTS of ways of doing this • To keep things simple, we’ll use a TCP socket

Slide 38

Slide 38 text

Shipping logs to Logstash input { tcp { port => 9999 codec => "json_lines" } } output { elasticsearch { host => localhost } } /etc/logstash/conf.d/01-tcp-es.conf

Slide 39

Slide 39 text

Shipping logs to Logstash use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\Handler\FingersCrossedHandler; use Monolog\Formatter\LogstashFormatter; use Monolog\Processor\WebProcessor; use Monolog\ErrorHandler; $log = new Logger('example'); $handler = new StreamHandler(fsockopen('172.16.33.245', 9999), Logger::DEBUG); $handler->setFormatter(new LogstashFormatter('example', 'server-name')); $handler->pushProcessor(new WebProcessor()); $fcHandler = new FingersCrossedHandler($handler, Logger::WARNING); $log->pushHandler($fcHandler); ErrorHandler::register($log); // ... $log->addCritical('Something bad happened!', ['some_var' => mt_rand()]); throw new Exception('Oh no!');

Slide 40

Slide 40 text

Log metrics in Kibana

Slide 41

Slide 41 text

Log metrics in Kibana • User agents • Requests during every hour of the day • Map of request sources • PHP memory usage • Unique users • Response times

Slide 42

Slide 42 text

Thank You Questions? @wldonohoe