Go kit log package

The Go kit log package is small but mighty. It has a small API, but wields the power of simplicity and composition. It provides tools for common logging needs and simple abstractions that allow easy customization. In this talk I share a bit of the package’s history, how we arrived at its core abstractions, and how they fit together. I also share examples of typical use and advice about how to accomodate logging in your own packages.

Transcript

1. Go kit log Chris Hines
2. Backstory inconshreveable/log15 — Summer 2014 — Add caller and stack trace features go-stack/stack — Fall 2014 go-kit/kit/log — Spring 2015 go-logfmt/logfmt — Summer 2015 improvement and maintenance — ongoing
3. Topics github.com/go-kit/kit/log package Design Principles Logging in your packages
4. go-kit/kit/log design
5. RFC Highlights SHALL use key / value pairs for structured data. SHALL be format agnostic by providing an interface for log formatting. SHALL provide a way to set a default k/v set per log context. SHALL be transport agnostic with pluggable transports. SHALL include severity as a k/v pair and allow setting it through the same mechanism as any other k/v pair. MUST NOT intrinsically tie severity levels to program actions.
6. Structured logging Use key / value pairs across the board Otherwise remain policy free RFC Summary
7. My Reaction Reminds me a lot of log15. I think I can help. I want to help.
8. Did we need a new log package? Maybe not. There was talk of “blessing” an existing package. Log15 was the best fit in early 2015, but: It was a bit more opinionated than desired for Go kit, and Had some recognized design flaws
9. Diving in I submitted a first attempt at package log Simplified and less opinionated variation on log15 I felt it resolved most design flaws Except one I was still struggling with Overall I was pretty happy with it
10. In reality it had a long way to go.
11. But then collaboration happened.
12. The result was better than any individual’s ideas.
13. Core Concepts Logger interface Contextual loggers Dynamic context values
14. Logger Interface
15. Logger interface Small and Composable type Logger interface { Log(keyvals ...interface{}) error }
16. Logger interface Alternating key / value pairs type Logger interface { Log(keyvals ...interface{}) error }
17. Logger interface Must be safe for concurrent use type Logger interface { Log(keyvals ...interface{}) error }
18. Example Use func RunTask(task Task, logger log.Logger) { logger.Log("taskID", task.ID, "event", "starting task") // ... logger.Log("taskID", task.ID, "event", "task complete") } Logfmt Output taskID=1 event="starting task" taskID=1 event="task complete" JSON Output {"event":"starting task","taskID":1} {"event":"task complete","taskID":1}
19. Example Use func RunTask(task Task, logger log.Logger) { logger.Log("taskID", task.ID, "event", "starting task") // ... logger.Log("taskID", task.ID, "event", "task complete") } Logfmt Output taskID=1 event="starting task" taskID=1 event="task complete" JSON Output {"event":"starting task","taskID":1} {"event":"task complete","taskID":1}
20. Example Use func RunTask(task Task, logger log.Logger) { logger.Log("taskID", task.ID, "event", "starting task") // ... logger.Log("taskID", task.ID, "event", "task complete") } Logfmt Output taskID=1 event="starting task" taskID=1 event="task complete" JSON Output {"event":"starting task","taskID":1} {"event":"task complete","taskID":1}
21. Contextual Loggers
22. Contextual Loggers Store keyvals to include in all log events. Common in structured logging packages.
23. Contextual Loggers func With(logger Logger, keyvals ...interface{}) Logger func WithPrefix(logger Logger, keyvals ...interface{}) Logger
24. Example Use func RunTask(task Task, logger log.Logger) { logger = log.With(logger, "taskID", task.ID) logger.Log("event", "starting task") execCmd(task.Cmd, logger) logger.Log("event", "task complete") } func execCmd(cmd string, logger log.Logger) { // execute(cmd) logger.Log("cmd", cmd, "dur", 42*time.Millisecond) }
25. Example Use func RunTask(task Task, logger log.Logger) { logger = log.With(logger, "taskID", task.ID) logger.Log("event", "starting task") execCmd(task.Cmd, logger) logger.Log("event", "task complete") } func execCmd(cmd string, logger log.Logger) { // execute(cmd) logger.Log("cmd", cmd, "dur", 42*time.Millisecond) }
26. Example Use func RunTask(task Task, logger log.Logger) { logger = log.With(logger, "taskID", task.ID) logger.Log("event", "starting task") execCmd(task.Cmd, logger) logger.Log("event", "task complete") } func execCmd(cmd string, logger log.Logger) { // execute(cmd) logger.Log("cmd", cmd, "dur", 42*time.Millisecond) }
27. Example Use func RunTask(task Task, logger log.Logger) { logger = log.With(logger, "taskID", task.ID) logger.Log("event", "starting task") execCmd(task.Cmd, logger) logger.Log("event", "task complete") } func execCmd(cmd string, logger log.Logger) { // execute(cmd) logger.Log("cmd", cmd, "dur", 42*time.Millisecond) }
28. Example Use Logfmt Output taskID=1 event="starting task" taskID=1 cmd="echo Hello, world!" dur=42ms taskID=1 event="task complete"
29. Example Use Logfmt Output taskID=1 event="starting task" taskID=1 cmd="echo Hello, world!" dur=42ms taskID=1 event="task complete"
30. Dynamic Context Values
31. Dynamic Context Values Stored in a contextual logger; But generate a new value each time they are logged.
32. Dynamic Context Values type Valuer func() interface{}
33. Dynamic Context Values type Valuer func() interface{} With.Log() WithPrefix.Log()
34. Example Use count := 0 counter := func() interface{} { count++ return count } logger = log.With(logger, "count", log.Valuer(counter)) logger.Log("call", "first") logger.Log("call", "second")
35. Example Use count := 0 counter := func() interface{} { count++ return count } logger = log.With(logger, "count", log.Valuer(counter)) logger.Log("call", "first") logger.Log("call", "second")
36. Example Use Logfmt Output count=1 call=first count=2 call=second
37. Useful Valuers func Caller(depth int) Valuer func Timestamp(t func() time.Time) Valuer func TimestampFormat(t func() time.Time, layout string) Valuer
38. Useful Valuers var ( DefaultTimestamp = TimestampFormat(time.Now, time.RFC3339Nano) DefaultTimestampUTC = TimestampFormat( func() time.Time { return time.Now().UTC() }, time.RFC3339Nano, ) DefaultCaller = Caller(3) )
39. Putting it all Together
40. Typical Logger Setup func main() { logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller, ) logger.Log("event", "app starting") _, err := os.Open("no-file.txt") if err != nil { logger.Log("err", err) } }
41. Typical Logger Setup func main() { logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller, ) logger.Log("event", "app starting") _, err := os.Open("no-file.txt") if err != nil { logger.Log("err", err) } }
42. Typical Logger Setup func main() { logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller, ) logger.Log("event", "app starting") _, err := os.Open("no-file.txt") if err != nil { logger.Log("err", err) } }
43. Typical Logger Setup Output ts=2017-04-23T02:19:32.5492459Z caller=main.go:16 event="app starting" ts=2017-04-23T02:19:32.5497471Z caller=main.go:20 err="open no-file.txt: The system cannot find the file specified."
44. go-kit/kit/log/level
45. Log Levels func main() { logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) logger = level.NewFilter(logger, level.AllowInfo()) logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller, ) level.Debug(logger).Log("event", "app starting") _, err := os.Open("no-file.txt") if err != nil { level.Error(logger).Log("err", err) } }
46. Log Levels Output level=error ts=2017-04-23T02:19:32.5497471Z caller=main.go:20 err="open no-file.txt: The system cannot find the file specified."
47. Design Principles
48. API: Design Matters Michi Henning (ACM Queue, Vol. 5, Issue 4) • Minimal, without imposing undue inconvenience on the caller • Designed from the perspective of the caller • General-purpose APIs should be “policy-free” • Special-purpose APIs should be “policy-rich”
49. Logging in Your Packages
50. Logging is an Application Concern Package main should set logging policy. Only packages tightly coupled to package main should log directly.
51. Shared Packages Should Not Log Instead: Return values, or Provide optional event hooks.
52. Where on the Package Spectrum to Log main project private shared public shared log at your leisure log at your peril
53. Let Applications Set Policy Library events could translate to: • Log output • Metrics data • Trace events • Nothing • Something else
54. Final Thoughts • Logging is an application concern. • General purpose packages should not impose policy on applications. • Consider github.com/go-kit/kit/log for your application’s logging needs. • Learn more about the rest of Go kit at gokit.io.
55. Thanks Chris Hines Twitter: @chris_csguy Gopher Slack: csguy