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.

Chris Hines

April 25, 2017
Tweet

Other Decks in Programming

Transcript

  1. 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
  2. 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.
  3. Structured logging Use key / value pairs across the board

    Otherwise remain policy free RFC Summary
  4. 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
  5. 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
  6. Logger interface Must be safe for concurrent use type Logger

    interface { Log(keyvals ...interface{}) error }
  7. 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}
  8. 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}
  9. 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}
  10. 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) }
  11. 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) }
  12. 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) }
  13. 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) }
  14. 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")
  15. 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")
  16. Useful Valuers func Caller(depth int) Valuer func Timestamp(t func() time.Time)

    Valuer func TimestampFormat(t func() time.Time, layout string) Valuer
  17. Useful Valuers var ( DefaultTimestamp = TimestampFormat(time.Now, time.RFC3339Nano) DefaultTimestampUTC =

    TimestampFormat( func() time.Time { return time.Now().UTC() }, time.RFC3339Nano, ) DefaultCaller = Caller(3) )
  18. 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) } }
  19. 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) } }
  20. 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) } }
  21. 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) } }
  22. 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”
  23. Logging is an Application Concern Package main should set logging

    policy. Only packages tightly coupled to package main should log directly.
  24. Where on the Package Spectrum to Log main project private

    shared public shared log at your leisure log at your peril
  25. Let Applications Set Policy Library events could translate to: •

    Log output • Metrics data • Trace events • Nothing • Something else
  26. 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.