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
   

   View Slide

2. Example Script
   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);
   

   View Slide

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
   

   View Slide

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
   

   View Slide

5. error_log
   • Ugly output, and it’s in the error log
   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"  
   

   View Slide

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
   

   View Slide

7. Install Monolog
   $  composer  require  monolog/monolog
   

   View Slide

8. 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);
   

   View Slide

9. 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);
   

   View Slide

10. 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);
    

    View Slide

11. 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);
    

    View Slide

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
    

    View Slide

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)
    

    View Slide

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

    View Slide

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
    

    View Slide

16. 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);
    

    View Slide

17. 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);
    

    View Slide

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
    

    View Slide

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

    View Slide

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
    

    View Slide

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)
    

    View Slide

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

    View Slide

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
    

    View Slide

24. Custom formatter example
    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);
    }
    ...
    }
    

    View Slide

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

    View Slide

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
    

    View Slide

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
    

    View Slide

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}  
    

    View Slide

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

    View Slide

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
    

    View Slide

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

    View Slide

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
    

    View Slide

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
    

    View Slide

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!');
    

    View Slide

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!
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

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!');
    

    View Slide

40. Log metrics in Kibana
    

    View Slide

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
    

    View Slide

42. Thank You
    Questions?
    @wldonohoe
    

    View Slide