Making Logs Useful

It's all well and good to use the default PHP error log and grep to track down bugs in your application, but the information it provides is often not useful without some additional context. In this talk, I'll discuss how you can use Monolog to enrich your logs with all the information you need to make your life easy when you're debugging an error.

I'll also cover shipping your logs into Elasticsearch with Logstash and finding the needles in your haystack of log entries with Kibana.

Transcript

1. Making logs useful with monolog and the ELK stack Will Donohoe McSimp Melbourne PHP Users Group March 2015
2. Example Script <?php header('Content-Type: application/json'); $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) { 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);
3. 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
4. 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
5. error_log • Ugly output, and it’s in the error log <?php error_log('Log message 1'); error_log('Log message 2'); error_log('Log message 3'); 2015/03/16  12:50:55  [error]  2553#0:  *128179  FastCGI  sent  in   stderr:  "PHP  message:  Log  message  1   PHP  message:  Log  message  2   PHP  message:  Log  message  3"  while  reading  response  header   from  upstream,  client:  x.x.x.x,  server:  hostname,  request:   "GET  /test.php  HTTP/1.1",  upstream:  "fastcgi://unix:/var/ run/php5-­‐fpm.sock:",  host:  "hostname"  
6. Monolog • https://github.com/Seldaek/monolog • Made by Jordi Boggiano (Composer, Symfony) • Requirements: PHP 5.3+ • Lots of built-in functionality, easy to extend
7. Install Monolog $  composer  require  monolog/monolog
8. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
9. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
10. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
11. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
12. Handlers • Take in log records • Apply formatters and processors (more on these later) • Do something with final log message (e.g. write to file, send to syslog, buffer) • Implement HandlerInterface
13. 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)
14. StreamHandler new StreamHandler('example.log', Logger::DEBUG) • Destination • Anything PHP can fopen/fwrite Minimum level
15. 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
16. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
17. <?php header('Content-Type: application/json'); require 'vendor/autoload.php'; use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\ErrorHandler; $log = new Logger('example'); $log->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);
18. 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
19. 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)"}  []
20. 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
21. 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)
22. Custom formatter example • Converts strings in context with non-printable characters to hex • Documentation lacking on $record format, easier to var_dump it
23. 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
24. Custom formatter example <?php use Monolog\Formatter\LineFormatter; class SpecialCharFormatter extends LineFormatter { public function format(array $record) { foreach ($record['context'] as $key => $val) { if (is_string($val) && !ctype_print($val)) { $record['context'][$key] = '0x' . bin2hex($val); } } return parent::format($record); } ... }
25. Custom formatter example $log = new Logger('example'); $handler = new StreamHandler('example.log', Logger::DEBUG); $handler->setFormatter(new SpecialCharFormatter()); $log->pushHandler($handler);
26. 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
27. 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
28. 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}  
29. Processors • GitProcessor  adds current commit hash • Make your own for user information (ID, name)
30. FingersCrossedHandler • Noisy logs = annoying and ignored • Only keep logs if there is one of sufficient level • No problems means no logs • No more noise! • Awesome feature
31. 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);
32. 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
33. 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
34. 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!');
35. 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!
36. 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
37. Shipping logs to Logstash • LOTS of ways of doing this • To keep things simple, we’ll use a TCP socket
38. Shipping logs to Logstash input  {      tcp  {          port  =>  9999          codec  =>  "json_lines"      }   }   output  {      elasticsearch  {          host  =>  localhost      }   }   /etc/logstash/conf.d/01-tcp-es.conf
39. 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!');
40. Log metrics in Kibana
41. Log metrics in Kibana • User agents • Requests during every hour of the day • Map of request sources • PHP memory usage • Unique users • Response times
42. Thank You Questions? @wldonohoe