Un-broken logging - the foundation of software operability - Operability.io - 2015 - Matthew Skelton

The way in which many (most?) software teams use logging needs a re-think as we move into a world of microservices and remote sensors. Instead of using logging merely to dump out stack traces, our logs become a continuous trace of application state, with unique-enough identifiers for every interesting point of execution. We also use transaction identifiers to trace calls across components, services, and queues, so that we can reconstruct distributed calls after the fact. Logging becomes a rich source of insight for developers and operations people alike, as we 'listen to the logs' and tighten feedback cycles to improve our software systems.

---

From a talk at Operability.io 2015 conference

Transcript

1. Un-Broken Logging the foundation of software operability Operability.io conference #OIO15 Friday 25th September 2015 Matthew Skelton Skelton Thatcher Consulting @matthewpskelton
3. The way we use logging is (often) broken How to make our logging more awesome Why we should care
7. Matthew Skelton @matthewpskelton #OIO15
12. @Operability #operability WhoOwnsMyOperability.com
13. confession: I am a big fan of logging
15. exceptional situations edge cases metrics analytics ‘audits’ … @evanphx
16. execution trace
17. BAD STUFF
18. Logging is often unloved 1. Discontinuous 2. Errors only, or arbitrary 3. ‘Bolted on’ 4. No aggregation & search 5. Specify severity up front
19. GOOD STUFF
20. How to make logging awesome 1. Continuous event IDs 2. Transaction tracing 3. Log aggregation & search tools 4. Design for logging 5. Decoupled severity
21. reduce time-to-detect increase team engagement increase configurability enhance DevOps collaboration #operability
22. Background
23. Autonomous weather station
26. MRI brain scan imaging
29. Oil well monitoring
32. Web-scale systems
39. logging makes things work
40. (event sourcing) (structured logging) (CQRS)
41. How is logging usually broken?
42. Logging is often unloved 1. Discontinuous 2. Errors only, or arbitrary 3. ‘Bolted on’ 4. No aggregation & search 5. Specify severity up front
44. using logging mainly for errors
46. inconsistent use of logging
48. logging slows down the software
50. logging ‘pollutes’ my precious domain model
52. logging is just for those weird Ops people
54. logging assumed to be free ($0) to implement no budget for aggregating logs across machines
56. log aggregation happens only in Production logs not available to Devs
58. fights over log severity levels
60. poor time synchronisation
62. Some history, with pirates
67. weather, course, sightings, latitude, longitude, … (even when quiet)
68. John Harrison
69. Why log?
70. verification traceability accountability charting the waters
72. - June 13th – Pirates!!!! - Weds – Sharks!!! - 19th Jun –BIGGER sharks!!!!
73. How to make logging awesome
74. How to make logging awesome 1. Continuous event IDs 2. Transaction tracing 3. Log aggregation & search tools 4. Design for logging 5. Decoupled severity
76. Storage I/O Worker Job Queue Upload
77. Continuous event IDs
78. How many distinct event types (state transitions) in your application?
80. represent distinct states
81. enum Human-readable sets: unique values, sparse, immutable C#, Java, Python, node (Ruby, PHP, …)
82. public enum EventID { // Badly-initialised logging data NotSet = 0, // An unrecognised event has occurred UnexpectedError = 10000, ApplicationStarted = 20000, ApplicationShutdownNoticeReceived = 20001, PageGenerationStarted = 30000, PageGenerationCompleted = 30001, MessageQueued = 40000, MessagePeeked = 40001, BasketItemAdded = 60001, BasketItemRemoved = 60002, CreditCardDetailsSubmitted = 70001, // ... }
83. Technical Domain public enum EventID { // Badly-initialised logging data NotSet = 0, // An unrecognised event has occurred UnexpectedError = 10000, ApplicationStarted = 20000, ApplicationShutdownNoticeReceived = 20001, PageGenerationStarted = 30000, PageGenerationCompleted = 30001, MessageQueued = 40000, MessagePeeked = 40001, BasketItemAdded = 60001, BasketItemRemoved = 60002, CreditCardDetailsSubmitted = 70001, // ... }
84. BasketItemAdded = 60001
85. BasketItemAdded = 60001 BasketItemRemoved = 60002
86. BasketItemAdded = 60001 BasketItemRemoved = 60002
87. represent distinct states
89. OrderSvc_BasketItemAdded
91. Monolith to microservices: debugger does not have the full view
92. Even with remote debugger, it’s boring to attach and detach
94. Storage I/O Worker Job Queue Upload
98. Transaction tracing
99. ‘Unique-ish’ identifier for each request Passed through downstream layers
100. Unique-ish ID
101. What about APM?
102. APM gives us application insight BUT How much do we learn? Is APM available on the Dev box? It’s not just ‘an Ops problem’!
104. Helps us to understand how the software really works Small overhead is worth it
105. Configurable severity levels
106. Which log level is right?
107. DEBUG, INFO, WARNING, ERROR, CRITICAL
108. Log level should *not* be fixed at compile or build time!
109. Tune log levels
110. Tune log levels
111. Tune log levels
112. { "eventmappings": { "events": { "event": [ { "id": "CacheServiceStarted", "severity": { "level": "Information" } }, { "id": "PageCachePurged", "severity": { "level": "Debug" }, "state": { "enabled": false } }, { "id": "DatabaseConnectionTimeOut", "severity": { "level": "Error" } } ] } } }
114. Tune severity levels of specific event IDs
116. Event tracing Use enumerations (or closest thing) Technical and Domain event types Distributed systems: debuggers less useful Trace calls with ‘unique-enough’ handles Tune log levels via config
117. Log aggregation & search tools
122. Design for log aggregation
123. develop the software using log aggregation as a first-class thing
126. stories for testing logging
127. BasketItemAdded grep BasketItem
128. logging is (‘just’) another system component
129. NTP
130. Dev and Ops collaboration* * and testers too!
132. Where?
134. auditing compliance pre-emptive fault diagnosis performance metrics …
135. Recap
136. Logging is often unloved 1. Discontinuous 2. Errors only, or arbitrary 3. ‘Bolted on’ 4. No aggregation & search 5. Specify severity up front
137. How to make logging awesome 1. Continuous event IDs 2. Transaction tracing 3. Log aggregation & search tools 4. Design for logging 5. Decoupled severity
138. logging makes things work
139. “There is no thought behind aspect-oriented programming”
140. MINDFUL LOGGING (?!)
141. database transaction logs
142. ‘Structured Logging’ TW: “Adopt” (May 2015) https://www.thoughtworks.com/radar/techniques/structured-logging http://gregoryszorc.com/ .NET: http://serilog.net/ Java: https://github.com/fluent/fluent-logger-java
143. sanity
145. More Ditch the Debugger and Use Log Analysis Instead Matthew Skelton https://blog.logentries.com/2015/07/ditch- the-debugger-and-use-log-analysis-instead/
146. More Using Log Aggregation Across Dev & Ops: The Pricing Advantage Rob Thatcher https://blog.logentries.com/2015/08/using- log-aggregation-across-dev-ops-the-pricing- advantage/
147. Evan Phoenix (@evanphx) youtube.com/watch?v=Z-JskKlIBOA
148. Books operabilitybook.com operationalfeatures.com
149. Thank you http://skeltonthatcher.com/ enquiries@skeltonthatcher.com @SkeltonThatcher +44 (0)20 8242 4103 @matthewpskelton