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.
1. 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
2. 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
2.1. 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"}
2.2. 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
2.3. 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"}
2.4. Comparing the presets
By comparing the outputs you can make the following observations:
- Both
Example
andProduction
loggers use the JSON encoder.Development
uses the Console encoder - The
logger.DPanic()
function causes a panic inDevelopment
logger but not inExample
orProduction
- 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
- Prints a stack trace from
- 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
3. 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.