Using Zap - Simple use cases

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:

This post is first of a series of posts showing different ways of using zap. The other posts are Creating custom loggers, Custom encoders and Working With Global Loggers

This documentation was written for zap v1.8.

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

The full source for the code extracts in the rest of the post is here

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