Measuring and Logging Everything in Real Time

Do you know what is happening in your web application right now, this second, how many requests, logins, exceptions you have, how many and what data your users are generating and what the click through rate of each of your registration step is? Or do you know exactly which exception with which stack trace caused the error your users are seeing? If not, this talk will show how you can easily measure and log everything that happens in your application with the help of open source tools, such as Graphite, StatsD, Elasticsearch and Logstash, without influencing your production environment.

Transcript

1. Measuring & Logging Everything in Real-Time @BastianHofmann
2. Logging
3. Measuring
4. Real-Time
5. Many roads
6. A few words about me
10. Questions? Ask
11. http://speakerdeck.com/u/bastianhofmann
12. Logging
13. For when something goes wrong
14. server error log access log debug logs slow query log ...
15. $ ssh my_simple_server
16. $ tail -f error.log $ cat error.log | grep Exception
17. Error Logs
18. ErrorLog /var/logs/apache/error.log
19. bool error_log ( string $message [, int $message_type = 0 [, string $destination [, string $extra_headers ]]] )
21. callable set_exception_handler( callable $exception_handler );
22. Log additional info
24. Not only error codes
25. Request Information
26. Handling Notices, Warnings, Errors
27. callable set_error_handler( callable $error_handler [, int $error_types = E_ALL | E_STRICT ] );
28. set_error_handler( function($errno, $msg, $file, $line) { $e = new \Exception(); $error = [ 'type' => $errno, 'message' => $msg, 'file' => $file, 'line' => $line, 'trace' => $e->getTrace(), ]; error_log(json_encode($error)); return true; });
29. Or directly turn them into Exceptions
30. set_error_handler( function($errno, $msg, $file, $line) { switch ($errno) { case E_RECOVERABLE_ERROR: case E_USER_ERROR: throw new \ErrorException($msg, null, $errno, $file, $line); case E_WARNING: case E_USER_WARNING: case E_CORE_WARNING: case E_COMPILE_WARNING: throw new WarningException($msg, null, $errno, $file, $line); case E_NOTICE: case E_USER_NOTICE: throw new NoticeException($msg, null, $errno, $file, $line); case E_STRICT: throw new StrictException($msg, null, $errno, $file, $line); } return true; }); $a = []; try { $b = $a['doesNotExist']; } catch (NoticeException $e) { }
31. But what about fatal errors
32. Use error_get_last() in a Shutdown Handler http://php.net/manual/en/function.error- get-last.php
34. http://php.net/manual/en/class.error.php
35. Access Logs
36. 192.168.56.1 - - [09/Jul/2012:19:18:19 +0200] "GET /rg_trunk/webroot/c/af10c/ images/template/rg_logo_default.png HTTP/ 1.1" 200 882 "http://devm/rg_trunk/webroot/ directory/publications/"
37. LogFormat "%h %l %u %t \"%r\" %>s %b" custom CustomLog /var/logs/apache/access.log custom http://httpd.apache.org/docs/2.2/mod/ mod_log_config.html#logformat
38. http://de.php.net/apache_note string apache_note ( string $note_name [, string $note_value = "" ] )
39. LogFormat "...\"%{referer}i\" \"%{user- agent}i\" %{session_id}n %{account_id}n..." custom
40. Debug Logs
41. https://github.com/Seldaek/monolog/
42. <?php use Monolog\Logger; use Monolog\Handler\StreamHandler; // create a log channel $log = new Logger('name'); $log->pushHandler( new StreamHandler( 'path/to/your.log', Logger::WARNING ) ); // add records to the log $log->addWarning('Foo'); $log->addError('Bar');
43. Handlers •Stream •Mail •FirePHP •ChromePHP •Socket •Roating File •MongoDB •Syslog •Gelf •Null •Test •FingersCrossed
44. Log in a structured way
45. JSON http://www.ietf.org/rfc/rfc4627.txt
46. <?php use Monolog\Logger; use Monolog\Handler\StreamHandler; use Monolog\Formatter\JsonFormatter; $log = new Logger('name'); $handler = new StreamHandler( 'path/to/your.log', Logger::WARNING ); $handler->setFormatter(new JsonFormatter()); $log->pushHandler($handler);
47. Logs from other services
48. web server http service http service http service http service user request log log log log log
49. Correlation / Tracing ID
50. web server http service http service http service http service create unique trace_id for request user request trace_id trace_id trace_id trace_id log log log log log
51. X-Trace-Id: bbr8ehb984tbab894
52. web server http service http service http service http service create unique trace_id for request user request trace_id trace_id trace_id trace_id log log log log log
56. Aggregate the logs in a central place
57. Make them easily full-text searchable
58. Make them aggregate-able
59. Always Log to file
60. Directly to a database
61. webserver webserver webserver DB
62. Disadvantages
63. Database is down?
64. Database is slow?
65. Database is full?
66. How to integrate access logs?
67. Influences application performance
68. Frontend?
69. Better solutions?
70. Logstash + Elasticsearch + Kibana
71. Full text search
72. Structured Messages
73. Always Log to file
74. Logstash elasticsearch webserver webserver webserver AMQP log log log logstash logstash logstash
75. logstash http://logstash.net/
76. input filter output
77. Very rich plugin system
78. Logstash elasticsearch webserver webserver webserver AMQP log log log logstash logstash logstash
79. input { file { type => "error" path => [ "/var/logs/php/*.log" ] add_field => [ "severity", "error" ] } file { type => "access" path => [ "/var/logs/apache/*_access.log" ] add_field => [ "severity", "info" ] }
80. filter{ grok { match => ["@source", "\/%{USERNAME:facility}\.log$"] } grok { type => "access" pattern => "^%{IP:OriginalIp} \s[a-zA-Z0-9_-]+\s[a-zA-Z0-9_-]+\s\[.*? \]\s\"%{DATA:Request}..." } }
81. output { amqp { host => "amqp.host" exchange_type => "fanout" name => "logs" } }
82. Logstash elasticsearch webserver webserver webserver AMQP log log log logstash logstash logstash
83. input {
 rabbitmq {
 queue => "logs"
 host => "amqp.host"
 exchange => "ls_exchange"
 exclusive => false
 }
 }
84. filter { grok {
 match => [
 'Type','EntityNotFoundException| TimeoutException'
 ]
 break_on_match => true
 add_tag => ['not_serious']
 tag_on_failure => ['serious']
 } }
85. output {
 elasticsearch {
 embedded => false
 bind_host => "localhost"
 bind_port => "9305"
 host => "localhost"
 cluster => "logs"
 }
 }
86. Kibana http://www.elasticsearch.org/overview/kibana/
88. Measuring
89. For knowing what happens
90. https://metrics.librato.com/
92. Graphite http://graphite.wikidot.com/
94. webserver webserver webserver graphite TCP
95. StatsD https://github.com/etsy/statsd/
96. webserver webserver webserver graphite UDP statsd TCP
97. webserver webserver webserver statsd statsd statsd graphite
98. webserver webserver webserver statsd statsd statsd graphite statsd
99. Metric?
100. Counters
101. Timers
102. Gauges
103. Anomaly detection
104. http://codeascraft.com/2013/06/11/introducing-kale/
105. What can we measure?
106. Business Metrics
107. Experiments (A/B Testing)
108. Partial rollouts
109. Technical Metrics
110. Response Times
111. Easiest approach:
     Get it out of the access log
112. 192.168.56.1 - - [09/Jul/2012:19:18:19 +0200] "GET /rg_trunk/webroot/c/af10c/ images/template/rg_logo_default.png HTTP/ 1.1" 200 882 "http://devm/rg_trunk/webroot/ directory/publications/"
113. Or measure it in your PHP process
114. Is this actually what we want to measure?
115. External Resources CSS JavaScript Images Slow connections Slow Browsers SSL Handshakes DNS resolving
116. http://www.stevesouders.com/blog/2012/02/10/the-performance-golden-rule/
117. That is what we want to measure!
118. Navigation Timing API https://developer.mozilla.org/en-US/docs/ Navigation_timing
120. Resource Timing API http://www.w3.org/TR/resource-timing/
122. https://github.com/lognormal/boomerang
123. Getting it back to the server
124. Tracking request
125. https://tracking.example.com/? page=profile&backend=123&co mplete=890&domReady=580
126. browser JS: boomerang logstash trackingServer access log requests tracking image with timing information as query parameters graphite statsd
127. Can we measure more?
128. Load balancer
129. Slow query logs
130. From within your PHP app
131. browser JS: boomerang logstash trackingServer access log requests tracking image with timing information as query parameters graphite statsd logstash load balancer access log logstash service access log
132. Database Queries
133. HTTP calls
134. Cache access
135. Rendering time
136. More fine grained metrics
137. By pages
138. By component
139. By browser
140. By country
141. Logged in / out
142. Profiling information
143. XHProf https://github.com/facebook/xhprof
144. Use it in production for a subset of requests
145. XHGUI https://github.com/perftools/xhgui
150. https://blackfire.io/
151. https://tidyways.io/
154. Symfony Debug Toolbar
157. Extend it http://symfony.com/doc/current/cookbook/profiler/ data_collector.html
164. Aggregate it
166. https://joind.in/talk/43978
167. http://twitter.com/BastianHofmann http://profiles.google.com/bashofmann http://lanyrd.com/people/BastianHofmann http://speakerdeck.com/u/bastianhofmann https://github.com/bashofmann https://www.researchgate.net/profile/Bastian_Hofmann/ mail@bastianhofmann.de