Tweet
Tweet

Slide 1

Slide 1 text

Go kit log Chris Hines

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

Topics github.com/go-kit/kit/log package Design Principles Logging in your packages

Slide 4

Slide 4 text

go-kit/kit/log design

Slide 5

Slide 5 text

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.

Slide 6

Slide 6 text

Structured logging Use key / value pairs across the board Otherwise remain policy free RFC Summary

Slide 7

Slide 7 text

My Reaction Reminds me a lot of log15. I think I can help. I want to help.

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

In reality it had a long way to go.

Slide 11

Slide 11 text

But then collaboration happened.

Slide 12

Slide 12 text

The result was better than any individual’s ideas.

Slide 13

Slide 13 text

Core Concepts Logger interface Contextual loggers Dynamic context values

Slide 14

Slide 14 text

Logger Interface

Slide 15

Slide 15 text

Logger interface Small and Composable type Logger interface { Log(keyvals ...interface{}) error }

Slide 16

Slide 16 text

Logger interface Alternating key / value pairs type Logger interface { Log(keyvals ...interface{}) error }

Slide 17

Slide 17 text

Logger interface Must be safe for concurrent use type Logger interface { Log(keyvals ...interface{}) error }

Slide 18

Slide 18 text

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}

Slide 19

Slide 19 text

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}

Slide 20

Slide 20 text

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}

Slide 21

Slide 21 text

Contextual Loggers

Slide 22

Slide 22 text

Contextual Loggers Store keyvals to include in all log events. Common in structured logging packages.

Slide 23

Slide 23 text

Contextual Loggers func With(logger Logger, keyvals ...interface{}) Logger func WithPrefix(logger Logger, keyvals ...interface{}) Logger

Slide 24

Slide 24 text

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) }

Slide 25

Slide 25 text

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) }

Slide 26

Slide 26 text

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) }

Slide 27

Slide 27 text

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) }

Slide 28

Slide 28 text

Example Use Logfmt Output taskID=1 event="starting task" taskID=1 cmd="echo Hello, world!" dur=42ms taskID=1 event="task complete"

Slide 29

Slide 29 text

Example Use Logfmt Output taskID=1 event="starting task" taskID=1 cmd="echo Hello, world!" dur=42ms taskID=1 event="task complete"

Slide 30

Slide 30 text

Dynamic Context Values

Slide 31

Slide 31 text

Dynamic Context Values Stored in a contextual logger; But generate a new value each time they are logged.

Slide 32

Slide 32 text

Dynamic Context Values type Valuer func() interface{}

Slide 33

Slide 33 text

Dynamic Context Values type Valuer func() interface{} With.Log() WithPrefix.Log()

Slide 34

Slide 34 text

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")

Slide 35

Slide 35 text

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")

Slide 36

Slide 36 text

Example Use Logfmt Output count=1 call=first count=2 call=second

Slide 37

Slide 37 text

Useful Valuers func Caller(depth int) Valuer func Timestamp(t func() time.Time) Valuer func TimestampFormat(t func() time.Time, layout string) Valuer

Slide 38

Slide 38 text

Useful Valuers var ( DefaultTimestamp = TimestampFormat(time.Now, time.RFC3339Nano) DefaultTimestampUTC = TimestampFormat( func() time.Time { return time.Now().UTC() }, time.RFC3339Nano, ) DefaultCaller = Caller(3) )

Slide 39

Slide 39 text

Putting it all Together

Slide 40

Slide 40 text

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) } }

Slide 41

Slide 41 text

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) } }

Slide 42

Slide 42 text

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) } }

Slide 43

Slide 43 text

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."

Slide 44

Slide 44 text

go-kit/kit/log/level

Slide 45

Slide 45 text

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) } }

Slide 46

Slide 46 text

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."

Slide 47

Slide 47 text

Design Principles

Slide 48

Slide 48 text

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”

Slide 49

Slide 49 text

Logging in Your Packages

Slide 50

Slide 50 text

Logging is an Application Concern Package main should set logging policy. Only packages tightly coupled to package main should log directly.

Slide 51

Slide 51 text

Shared Packages Should Not Log Instead: Return values, or Provide optional event hooks.

Slide 52

Slide 52 text

Where on the Package Spectrum to Log main project private shared public shared log at your leisure log at your peril

Slide 53

Slide 53 text

Let Applications Set Policy Library events could translate to: ● Log output ● Metrics data ● Trace events ● Nothing ● Something else

Slide 54

Slide 54 text

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.

Slide 55

Slide 55 text

Thanks Chris Hines Twitter: @chris_csguy Gopher Slack: csguy