I was intrigued when Uber announced zap, a logging library for Go with claims of really high speed and memory efficiency. I had tried structured logging earlier using logrus, but while I did not experience it myself, I was worried by a lot of folks telling me about its performance issues at high log volumes. So when zap claimed performance exceeding the log package from standard library, I had to try it. Also, its flexible framework left the door open to a future plan of mine of sending logs filebeat style to ELK.

The documentation for the library was pretty standard, but I could not find a reasonable introduction to explore the various ways one can use the library. So I decided to document some of my experiments with the library.

I collected my code examples in Github, and decided to break it up into a series of posts.

---

Contents:

• Trying out the examples
• Using logger presets
  • Using the Example logger preset
  • Using the Development logger preset
  • Using the Production logger preset
  • Comparing the presets
• Using the Sugar logger

Trying out the examples

For working code examples, clone my github repository, setup the environment, install zap and then start running the examples:

$ git clone https://github.com/sandipb/zap-examples.git

$ cd zap-examples

$ source env.sh

$ go get -u go.uber.org/zap

$ go run src/simple1/main.go

Using logger presets

zap recommends using logger presets for the simplest of cases. These presets have pre-configured log levels and output formats.

There are three presets currently available:

• Example
• Development
• Production

Using the Example logger preset

logger := zap.NewExample()
logger.Debug("This is a DEBUG message")
logger.Info("This is an INFO message")
logger.Info("This is an INFO message with fields", zap.String("region", "us-west"), zap.Int("id", 2))
logger.Warn("This is a WARN message")
logger.Error("This is an ERROR message")
// logger.Fatal("This is a FATAL message")  // would exit if uncommented
logger.DPanic("This is a DPANIC message")
//logger.Panic("This is a PANIC message")   // would exit if uncommented

Output:

{"level":"debug","msg":"This is a DEBUG message"}
{"level":"info","msg":"This is an INFO message"}
{"level":"info","msg":"This is an INFO message with fields","region":"us-west","id":2}
{"level":"warn","msg":"This is a WARN message"}
{"level":"error","msg":"This is an ERROR message"}
{"level":"dpanic","msg":"This is a DPANIC message"}

Using the Development logger preset

logger, _ = zap.NewDevelopment()
logger.Debug("This is a DEBUG message")
logger.Info("This is an INFO message")
logger.Info("This is an INFO message with fields", zap.String("region", "us-west"), zap.Int("id", 2))
logger.Warn("This is a WARN message")
logger.Error("This is an ERROR message")
// logger.Fatal("This is a FATAL message")   // would exit if uncommented
// logger.DPanic("This is a DPANIC message") // would exit if uncommented
//logger.Panic("This is a PANIC message")    // would exit if uncommented

Output:

2018-05-02T13:52:44.332-0700    DEBUG   simple1/main.go:28      This is a DEBUG message
2018-05-02T13:52:44.332-0700    INFO    simple1/main.go:29      This is an INFO message
2018-05-02T13:52:44.332-0700    INFO    simple1/main.go:30      This is an INFO message with fields     {"region": "us-west", "id": 2}
2018-05-02T13:52:44.332-0700    WARN    simple1/main.go:31      This is a WARN messagemain.main
        /Users/snbhatta/dev/zap-examples/src/simple1/main.go:31
runtime.main
        /Users/snbhatta/.gradle/language/golang/1.9.2/go/src/runtime/proc.go:195
2018-05-02T13:52:44.332-0700    ERROR   simple1/main.go:32      This is an ERROR message
main.main
        /Users/snbhatta/dev/zap-examples/src/simple1/main.go:32
runtime.main
        /Users/snbhatta/.gradle/language/golang/1.9.2/go/src/runtime/proc.go:195

Using the Production logger preset

logger, _ = zap.NewProduction()
logger.Debug("This is a DEBUG message")
logger.Info("This is an INFO message")
logger.Info("This is an INFO message with fields", zap.String("region", "us-west"), zap.Int("id", 2))
logger.Warn("This is a WARN message")
logger.Error("This is an ERROR message")
// logger.Fatal("This is a FATAL message")   // would exit if uncommented
logger.DPanic("This is a DPANIC message")
// logger.Panic("This is a PANIC message")   // would exit if uncommented

Output:

{"level":"info","ts":1525294364.332839,"caller":"simple1/main.go:43","msg":"This is an INFO message"}
{"level":"info","ts":1525294364.332864,"caller":"simple1/main.go:44","msg":"This is an INFO message with fields","region":"us-west","id":2}
{"level":"warn","ts":1525294364.3328729,"caller":"simple1/main.go:45","msg":"This is a WARN message"}
{"level":"error","ts":1525294364.332882,"caller":"simple1/main.go:46","msg":"This is an ERROR message","stacktrace":"main.main\n\t/Users/snbhatta/dev/zap-examples/src/simple1/main.go:46\nruntime.main\n\
t/Users/snbhatta/.gradle/language/golang/1.9.2/go/src/runtime/proc.go:195"}
{"level":"dpanic","ts":1525294364.332895,"caller":"simple1/main.go:48","msg":"This is a DPANIC message","stacktrace":"main.main\n\t/Users/snbhatta/dev/zap-examples/src/simple1/main.go:48\nruntime.main\n
\t/Users/snbhatta/.gradle/language/golang/1.9.2/go/src/runtime/proc.go:195"}

Comparing the presets

By comparing the outputs you can make the following observations:

• Both Example and Production loggers use the JSON encoder. Development uses the Console encoder
• The logger.DPanic() function causes a panic in Development logger but not in Example or Production
• The Development logger:
  • Prints a stack trace from Warn level and up.
  • Always prints the package/file/line number (the caller)
  • Tacks any extra fields as a json string at the end of the line
  • Prints the level names in uppercase
  • Prints timestamp in ISO8601 format with milliseconds
• The Production logger:
  • Doesn’t log messages at debug level
  • Adds stack trace as a json field for Error, DPanic levels, but not for Warn
  • Always adds the caller as a json field
  • Prints timestamp in epoch format
  • Prints level names in lower case

Using the Sugar logger

The default zap loggers expect structured tags, i.e. for every tag, you need to use a function for the specific value type. It can sometimes feel too verbose.

logger.Info("This is an INFO message with fields", 
            zap.String("region", "us-west"), 
            zap.Int("id", 2))

This is the fastest option for an application where performance is important. (Actually it can get even faster if the logger has tags pre-configured, which will see in further posts in this series.)

However, for a just a small additional penalty (which is actually still slightly better than the standard library log package), you can use the sugar logger, which uses printf-style reflection based type detection to give you a simpler syntax to add tags of mixed types.

slogger := logger.Sugar()
slogger.Info("Info() uses sprint")
slogger.Infof("Infof() uses %s", "sprintf")
slogger.Infow("Infow() allows tags", "name", "Legolas", "type", 1)

Output:

2018-05-02T18:13:22.376-0700    INFO    simple1/main.go:56      Info() uses sprint
2018-05-02T18:13:22.376-0700    INFO    simple1/main.go:57      Infof() uses sprintf
2018-05-02T18:13:22.376-0700    INFO    simple1/main.go:58      Infow() allows tags     {"name": "Legolas", "type": 1}

If you need to, you can switch from a sugar logger to a standard logger any time using the .Desugar() method on the logger.

comments powered by Disqus