Metrics and an application log: Your new best friends

Do you remember the time you spent an afternoon putting print statements in your app trying to debug an issue and removed them before shipping the fix, only to add them back in a day later to work on another issue? Wouldn't it be great if those debug statements could just stay in your code forever? Like a little gift that keeps on giving, not just for you, but for everyone else on your team too.

That's what an application log is for! Logs aren't just for when things go wrong. They're for helping you to keep track of what's going on within your application.

We take a look at how you can add helpful messages throughout your codebase and leave them there, even in production! We'll cover common logging strategies, log aggregation and how to efficiently work with your logs to get the data back out again.

We'll also take a look at metrics solutions such as Graphite that can help augment your logs to help work out what was going on by correlating event logs with peaks/drops in other monitoring systems.

Transcript

1. Logging: Your new best friend Michael Heap (@mheap) Presented at PHPConfPH, October 2016
2. Me! I’m Michael I’m @mheap Developer at digi.me
3. Logging
4. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
5. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
6. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
7. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
8. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
9. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
10. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
11. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
12. Sound good?
13. Good!
14. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
15. Why log?
16. What went wrong? (Error log)
17. Who visited us? (Access log)
18. Who enabled <X>? (Audit log)
19. Runtime documentation (Application log)
20. I’m sold!
21. Can I have it for free?
22. Actually, yes!
23. (And more)
24. But that doesn’t help my application
25. Two types of log
26. Human readable
27. Machine readable
28. We should log both
29. What is an application log?
30. Debug information
31. Narrative information
32. Business information
33. “An application log signposts every twist and turn through the code”
34. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
35. Four W’s
36. When?
37. Who?
38. Where?
39. Why?
40. Getting started
41. error_log()
42. <?php function countConsonants($str){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); error_log("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael");
43. <?php function countConsonants($str){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); error_log("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael");
44. <?php ini_set("error_log", "/var/log/my-app.log"); function countConsonants($str){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); error_log("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael");
45. Pros ✴ It’s built in
46. Cons ✴ Is it semantically correct? ✴ Errors mixed with informational logs ✴ It’s not very powerful
47. Logging frameworks
48. 1) Monolog 2) Everything else
49. <?php require_once 'vendor/autoload.php'; $log = new Monolog\Logger('my-app'); $log->pushHandler(new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG)); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
50. <?php require_once 'vendor/autoload.php'; $log = new Monolog\Logger('my-app'); $log->pushHandler(new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG)); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
51. <?php require_once 'vendor/autoload.php'; $log = new Monolog\Logger('my-app'); $log->pushHandler(new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG)); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
52. <?php require_once 'vendor/autoload.php'; $log = new Monolog\Logger('my-app'); $log->pushHandler(new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG)); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
53. <?php require_once 'vendor/autoload.php'; $log = new Monolog\Logger('my-app'); $log->pushHandler(new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG)); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
54. [2016-05-25 03:56:01] my-app.INFO: Consonants in Michael: 4 [] []
55. FingersCrossedHandler
56. $log = new Monolog\Logger('my-app'); $streamHandler = new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG); $fcHandler = new Monolog\Handler\FingersCrossedHandler($streamHandler, Monolog \Logger::ERROR); $log->pushHandler($fcHandler); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
57. $log = new Monolog\Logger('my-app'); $streamHandler = new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG); $fcHandler = new Monolog\Handler\FingersCrossedHandler($streamHandler, Monolog \Logger::ERROR); $log->pushHandler($fcHandler); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
58. $log = new Monolog\Logger('my-app'); $streamHandler = new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG); $fcHandler = new Monolog\Handler\FingersCrossedHandler($streamHandler, Monolog \Logger::ERROR); $log->pushHandler($fcHandler); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); return $c; } echo countConsonants("Michael", $log);
59. $log = new Monolog\Logger('my-app'); $streamHandler = new Monolog\Handler\StreamHandler('/tmp/app.log', Monolog \Logger::DEBUG); $fcHandler = new Monolog\Handler\FingersCrossedHandler($streamHandler, Monolog \Logger::ERROR); $log->pushHandler($fcHandler); function countConsonants($str, $log){ $c = strlen(str_replace(['a','e','i','o','u'],'', $str)); $log->info("Consonants in {$str}: {$c}"); $log->error("Something bad happened"); return $c; } echo countConsonants("Michael", $log);
60. Pros ✴ It’s an object! Dependency injection FTW ✴ Supports multiple log writers ✴ Log level support
61. Cons ✴ Instantiating an instance can be complicated
62. Error Levels
63. 0. Emergency System is unusable 1. Alert Should be corrected immediately 2. Critical Critical conditions 3. Error Error conditions 4. Warning May indicate that an error will occur if action is not taken. 5. Notice Events that are unusual, but not error conditions. 6. Informational Normal operational messages that require no action. 7. Debug Information useful to developers for debugging the application. Syslog (RFC 5424)
64. 0. Emergency System is unusable 1. Alert Should be corrected immediately 2. Critical Critical conditions 3. Error Error conditions 4. Warning May indicate that an error will occur if action is not taken. 5. Notice Events that are unusual, but not error conditions. 6. Informational Normal operational messages that require no action. 7. Debug Information useful to developers for debugging the application. PSR3
65. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
66. Everything is on fire
67. The ELK Stack
68. Elasticsearch Logstash Kibana
69. Logstash Elasticsearch Kibana
70. Logstash
71. Beats CouchDB_Changes Drupal_DBLog Elasticsearch Exec Event log File Ganglia Gelf Generator Graphite Github Heartbeat Heroku HTTP HTTP_Poller IRC IMAP JDBC JMX
 Kafka Log4J Lumberjack Meetup Pipe Puppet_Facter Relp RSS Backspace RabbitMQ Redis Salesforce SNMPTrap Stdin sqlite S3 SQS Stomp Syslog TCP Twitter Unix UDP Varnishlog WMI Web socket XMPP Zenoss ZeroMQ Inputs
72. Filters
73. filter { json { source => "message" add_field => [ “my_field", “mheap_%{host}” ] } }
74. filter { kv { default_keys => [ "from", "logstash@example.com", "to", "default@dev.null" ] } }
75. Accepted publickey for root from 172.14.183.11 port 22 ssh2
76. Accepted publickey for root from 172.14.183.11 port 22 ssh2
77. filter { grok { match => { "message" => "Accepted %{WORD:auth_method} for %{USER:username} from %{IP:src_ip} port %{INT:src_port} ssh2" } } } Accepted publickey for root from 172.14.183.11 port 22 ssh2
78. filter { grok { match => { "message" => "Accepted %{WORD:auth_method} for %{USER:username} from %{IP:src_ip} port %{INT:src_port} ssh2" } } } Accepted publickey for root from 172.14.183.11 port 22 ssh2
79. http://grokdebug.herokuapp.com/
80. Boundary Circus CSV Cloud watch Datadog Datadog_Metrics Email Elastic search Exec File Google BigQuery Google Cloud Storage Ganglia Gelf Graphtastic Graphite Hipchat HTTP IRC InfluxDB Juggernaut Jira Kafka Lumberjack Librato Loggly MongoDB MetricCatcher Nagios Null OpenTSDB Pagerduty Pipe Riemann Redmine Rackspace RabbitMQ Redis Riak S3 SQS Stomp StatsD Solr SNS Syslog Stdout TCP UDP WebHDFS Websocket XMPP Outputs Zabbix ZeroMQ
81. Input -> Filter -> Output
82. Logstash is slow(ish)
83. Elasticsearch
84. Kibana
85. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
90. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
91. Asimov’s Law
92. “A robot may not injure a human being or, through inaction, allow a human being to come to harm.”
93. @mheap’s Law
94. “An application log may not injure a an application’s performance or readability”
95. Plan for bursts of data
96. Disk space
97. Index management
98. Ship what’s relevant
99. Devs create dashboards
100. Unique request IDs
101. Normalise timezones
102. No really. Normalise timezones
103. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
104. Beats
105. Graphite
108. Pagerduty
109. Elastalert
110. 1. Logging 2. Getting started 3. The ELK stack 4. Logs and dashboards 5. Log management 6. Supporting services 7. Conclusion
111. Logging is required
112. Developers are empowered
113. Use PSR-3
114. Logging isn’t free
115. “Would you rather fly slowly or fly blind?”
116. Thanks! I’ve been @mheap, you’ve been awesome. Any questions?