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

Go kit log package

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.

064097aba38ad57b94e60b90958f2962?s=128

Chris Hines

April 25, 2017
Tweet

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