Upgrade to Pro — share decks privately, control downloads, hide ads and more …

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.

Will Donohoe

March 17, 2015
Tweet

More Decks by Will Donohoe

Other Decks in Programming

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