Making Logs Useful

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.

0f12d7684de4e6a54915ba586c0e4118?s=128

Will Donohoe

March 17, 2015
Tweet

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