1# Zero Allocation JSON Logger 2 3[![godoc](http://img.shields.io/badge/godoc-reference-blue.svg?style=flat)](https://godoc.org/github.com/rs/zerolog) [![license](http://img.shields.io/badge/license-MIT-red.svg?style=flat)](https://raw.githubusercontent.com/rs/zerolog/master/LICENSE) [![Build Status](https://travis-ci.org/rs/zerolog.svg?branch=master)](https://travis-ci.org/rs/zerolog) [![Coverage](http://gocover.io/_badge/github.com/rs/zerolog)](http://gocover.io/github.com/rs/zerolog) 4 5The zerolog package provides a fast and simple logger dedicated to JSON output. 6 7Zerolog's API is designed to provide both a great developer experience and stunning [performance](#benchmarks). Its unique chaining API allows zerolog to write JSON (or CBOR) log events by avoiding allocations and reflection. 8 9Uber's [zap](https://godoc.org/go.uber.org/zap) library pioneered this approach. Zerolog is taking this concept to the next level with a simpler to use API and even better performance. 10 11To keep the code base and the API simple, zerolog focuses on efficient structured logging only. Pretty logging on the console is made possible using the provided (but inefficient) [`zerolog.ConsoleWriter`](#pretty-logging). 12 13![Pretty Logging Image](pretty.png) 14 15## Who uses zerolog 16 17Find out [who uses zerolog](https://github.com/rs/zerolog/wiki/Who-uses-zerolog) and add your company / project to the list. 18 19## Features 20 21* Blazing fast 22* Low to zero allocation 23* Level logging 24* Sampling 25* Hooks 26* Contextual fields 27* `context.Context` integration 28* `net/http` helpers 29* JSON and CBOR encoding formats 30* Pretty logging for development 31 32## Installation 33 34```bash 35go get -u github.com/rs/zerolog/log 36``` 37 38## Getting Started 39 40### Simple Logging Example 41 42For simple logging, import the global logger package **github.com/rs/zerolog/log** 43 44```go 45package main 46 47import ( 48 "github.com/rs/zerolog" 49 "github.com/rs/zerolog/log" 50) 51 52func main() { 53 // UNIX Time is faster and smaller than most timestamps 54 // If you set zerolog.TimeFieldFormat to an empty string, 55 // logs will write with UNIX time 56 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 57 58 log.Print("hello world") 59} 60 61// Output: {"time":1516134303,"level":"debug","message":"hello world"} 62``` 63> Note: By default log writes to `os.Stderr` 64> Note: The default log level for `log.Print` is *debug* 65 66### Contextual Logging 67 68**zerolog** allows data to be added to log messages in the form of key:value pairs. The data added to the message adds "context" about the log event that can be critical for debugging as well as myriad other purposes. An example of this is below: 69 70```go 71package main 72 73import ( 74 "github.com/rs/zerolog" 75 "github.com/rs/zerolog/log" 76) 77 78func main() { 79 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 80 81 log.Debug(). 82 Str("Scale", "833 cents"). 83 Float64("Interval", 833.09). 84 Msg("Fibonacci is everywhere") 85 86 log.Debug(). 87 Str("Name", "Tom"). 88 Send() 89} 90 91// Output: {"level":"debug","Scale":"833 cents","Interval":833.09,"time":1562212768,"message":"Fibonacci is everywhere"} 92// Output: {"level":"debug","Name":"Tom","time":1562212768} 93``` 94 95> You'll note in the above example that when adding contextual fields, the fields are strongly typed. You can find the full list of supported fields [here](#standard-types) 96 97### Leveled Logging 98 99#### Simple Leveled Logging Example 100 101```go 102package main 103 104import ( 105 "github.com/rs/zerolog" 106 "github.com/rs/zerolog/log" 107) 108 109func main() { 110 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 111 112 log.Info().Msg("hello world") 113} 114 115// Output: {"time":1516134303,"level":"info","message":"hello world"} 116``` 117 118> It is very important to note that when using the **zerolog** chaining API, as shown above (`log.Info().Msg("hello world"`), the chain must have either the `Msg` or `Msgf` method call. If you forget to add either of these, the log will not occur and there is no compile time error to alert you of this. 119 120**zerolog** allows for logging at the following levels (from highest to lowest): 121 122* panic (`zerolog.PanicLevel`, 5) 123* fatal (`zerolog.FatalLevel`, 4) 124* error (`zerolog.ErrorLevel`, 3) 125* warn (`zerolog.WarnLevel`, 2) 126* info (`zerolog.InfoLevel`, 1) 127* debug (`zerolog.DebugLevel`, 0) 128* trace (`zerolog.TraceLevel`, -1) 129 130You can set the Global logging level to any of these options using the `SetGlobalLevel` function in the zerolog package, passing in one of the given constants above, e.g. `zerolog.InfoLevel` would be the "info" level. Whichever level is chosen, all logs with a level greater than or equal to that level will be written. To turn off logging entirely, pass the `zerolog.Disabled` constant. 131 132#### Setting Global Log Level 133 134This example uses command-line flags to demonstrate various outputs depending on the chosen log level. 135 136```go 137package main 138 139import ( 140 "flag" 141 142 "github.com/rs/zerolog" 143 "github.com/rs/zerolog/log" 144) 145 146func main() { 147 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 148 debug := flag.Bool("debug", false, "sets log level to debug") 149 150 flag.Parse() 151 152 // Default level for this example is info, unless debug flag is present 153 zerolog.SetGlobalLevel(zerolog.InfoLevel) 154 if *debug { 155 zerolog.SetGlobalLevel(zerolog.DebugLevel) 156 } 157 158 log.Debug().Msg("This message appears only when log level set to Debug") 159 log.Info().Msg("This message appears when log level set to Debug or Info") 160 161 if e := log.Debug(); e.Enabled() { 162 // Compute log output only if enabled. 163 value := "bar" 164 e.Str("foo", value).Msg("some debug message") 165 } 166} 167``` 168 169Info Output (no flag) 170 171```bash 172$ ./logLevelExample 173{"time":1516387492,"level":"info","message":"This message appears when log level set to Debug or Info"} 174``` 175 176Debug Output (debug flag set) 177 178```bash 179$ ./logLevelExample -debug 180{"time":1516387573,"level":"debug","message":"This message appears only when log level set to Debug"} 181{"time":1516387573,"level":"info","message":"This message appears when log level set to Debug or Info"} 182{"time":1516387573,"level":"debug","foo":"bar","message":"some debug message"} 183``` 184 185#### Logging without Level or Message 186 187You may choose to log without a specific level by using the `Log` method. You may also write without a message by setting an empty string in the `msg string` parameter of the `Msg` method. Both are demonstrated in the example below. 188 189```go 190package main 191 192import ( 193 "github.com/rs/zerolog" 194 "github.com/rs/zerolog/log" 195) 196 197func main() { 198 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 199 200 log.Log(). 201 Str("foo", "bar"). 202 Msg("") 203} 204 205// Output: {"time":1494567715,"foo":"bar"} 206``` 207 208#### Logging Fatal Messages 209 210```go 211package main 212 213import ( 214 "errors" 215 216 "github.com/rs/zerolog" 217 "github.com/rs/zerolog/log" 218) 219 220func main() { 221 err := errors.New("A repo man spends his life getting into tense situations") 222 service := "myservice" 223 224 zerolog.TimeFieldFormat = zerolog.TimeFormatUnix 225 226 log.Fatal(). 227 Err(err). 228 Str("service", service). 229 Msgf("Cannot start %s", service) 230} 231 232// Output: {"time":1516133263,"level":"fatal","error":"A repo man spends his life getting into tense situations","service":"myservice","message":"Cannot start myservice"} 233// exit status 1 234``` 235 236> NOTE: Using `Msgf` generates one allocation even when the logger is disabled. 237 238### Create logger instance to manage different outputs 239 240```go 241logger := zerolog.New(os.Stderr).With().Timestamp().Logger() 242 243logger.Info().Str("foo", "bar").Msg("hello world") 244 245// Output: {"level":"info","time":1494567715,"message":"hello world","foo":"bar"} 246``` 247 248### Sub-loggers let you chain loggers with additional context 249 250```go 251sublogger := log.With(). 252 Str("component", "foo"). 253 Logger() 254sublogger.Info().Msg("hello world") 255 256// Output: {"level":"info","time":1494567715,"message":"hello world","component":"foo"} 257``` 258 259### Pretty logging 260 261To log a human-friendly, colorized output, use `zerolog.ConsoleWriter`: 262 263```go 264log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}) 265 266log.Info().Str("foo", "bar").Msg("Hello world") 267 268// Output: 3:04PM INF Hello World foo=bar 269``` 270 271To customize the configuration and formatting: 272 273```go 274output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339} 275output.FormatLevel = func(i interface{}) string { 276 return strings.ToUpper(fmt.Sprintf("| %-6s|", i)) 277} 278output.FormatMessage = func(i interface{}) string { 279 return fmt.Sprintf("***%s****", i) 280} 281output.FormatFieldName = func(i interface{}) string { 282 return fmt.Sprintf("%s:", i) 283} 284output.FormatFieldValue = func(i interface{}) string { 285 return strings.ToUpper(fmt.Sprintf("%s", i)) 286} 287 288log := zerolog.New(output).With().Timestamp().Logger() 289 290log.Info().Str("foo", "bar").Msg("Hello World") 291 292// Output: 2006-01-02T15:04:05Z07:00 | INFO | ***Hello World**** foo:BAR 293``` 294 295### Sub dictionary 296 297```go 298log.Info(). 299 Str("foo", "bar"). 300 Dict("dict", zerolog.Dict(). 301 Str("bar", "baz"). 302 Int("n", 1), 303 ).Msg("hello world") 304 305// Output: {"level":"info","time":1494567715,"foo":"bar","dict":{"bar":"baz","n":1},"message":"hello world"} 306``` 307 308### Customize automatic field names 309 310```go 311zerolog.TimestampFieldName = "t" 312zerolog.LevelFieldName = "l" 313zerolog.MessageFieldName = "m" 314 315log.Info().Msg("hello world") 316 317// Output: {"l":"info","t":1494567715,"m":"hello world"} 318``` 319 320### Add contextual fields to the global logger 321 322```go 323log.Logger = log.With().Str("foo", "bar").Logger() 324``` 325 326### Add file and line number to log 327 328```go 329log.Logger = log.With().Caller().Logger() 330log.Info().Msg("hello world") 331 332// Output: {"level": "info", "message": "hello world", "caller": "/go/src/your_project/some_file:21"} 333``` 334 335 336### Thread-safe, lock-free, non-blocking writer 337 338If your writer might be slow or not thread-safe and you need your log producers to never get slowed down by a slow writer, you can use a `diode.Writer` as follow: 339 340```go 341wr := diode.NewWriter(os.Stdout, 1000, 10*time.Millisecond, func(missed int) { 342 fmt.Printf("Logger Dropped %d messages", missed) 343 }) 344log := zerolog.New(wr) 345log.Print("test") 346``` 347 348You will need to install `code.cloudfoundry.org/go-diodes` to use this feature. 349 350### Log Sampling 351 352```go 353sampled := log.Sample(&zerolog.BasicSampler{N: 10}) 354sampled.Info().Msg("will be logged every 10 messages") 355 356// Output: {"time":1494567715,"level":"info","message":"will be logged every 10 messages"} 357``` 358 359More advanced sampling: 360 361```go 362// Will let 5 debug messages per period of 1 second. 363// Over 5 debug message, 1 every 100 debug messages are logged. 364// Other levels are not sampled. 365sampled := log.Sample(zerolog.LevelSampler{ 366 DebugSampler: &zerolog.BurstSampler{ 367 Burst: 5, 368 Period: 1*time.Second, 369 NextSampler: &zerolog.BasicSampler{N: 100}, 370 }, 371}) 372sampled.Debug().Msg("hello world") 373 374// Output: {"time":1494567715,"level":"debug","message":"hello world"} 375``` 376 377### Hooks 378 379```go 380type SeverityHook struct{} 381 382func (h SeverityHook) Run(e *zerolog.Event, level zerolog.Level, msg string) { 383 if level != zerolog.NoLevel { 384 e.Str("severity", level.String()) 385 } 386} 387 388hooked := log.Hook(SeverityHook{}) 389hooked.Warn().Msg("") 390 391// Output: {"level":"warn","severity":"warn"} 392``` 393 394### Pass a sub-logger by context 395 396```go 397ctx := log.With().Str("component", "module").Logger().WithContext(ctx) 398 399log.Ctx(ctx).Info().Msg("hello world") 400 401// Output: {"component":"module","level":"info","message":"hello world"} 402``` 403 404### Set as standard logger output 405 406```go 407log := zerolog.New(os.Stdout).With(). 408 Str("foo", "bar"). 409 Logger() 410 411stdlog.SetFlags(0) 412stdlog.SetOutput(log) 413 414stdlog.Print("hello world") 415 416// Output: {"foo":"bar","message":"hello world"} 417``` 418 419### Integration with `net/http` 420 421The `github.com/rs/zerolog/hlog` package provides some helpers to integrate zerolog with `http.Handler`. 422 423In this example we use [alice](https://github.com/justinas/alice) to install logger for better readability. 424 425```go 426log := zerolog.New(os.Stdout).With(). 427 Timestamp(). 428 Str("role", "my-service"). 429 Str("host", host). 430 Logger() 431 432c := alice.New() 433 434// Install the logger handler with default output on the console 435c = c.Append(hlog.NewHandler(log)) 436 437// Install some provided extra handler to set some request's context fields. 438// Thanks to that handler, all our logs will come with some prepopulated fields. 439c = c.Append(hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) { 440 hlog.FromRequest(r).Info(). 441 Str("method", r.Method). 442 Stringer("url", r.URL). 443 Int("status", status). 444 Int("size", size). 445 Dur("duration", duration). 446 Msg("") 447})) 448c = c.Append(hlog.RemoteAddrHandler("ip")) 449c = c.Append(hlog.UserAgentHandler("user_agent")) 450c = c.Append(hlog.RefererHandler("referer")) 451c = c.Append(hlog.RequestIDHandler("req_id", "Request-Id")) 452 453// Here is your final handler 454h := c.Then(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { 455 // Get the logger from the request's context. You can safely assume it 456 // will be always there: if the handler is removed, hlog.FromRequest 457 // will return a no-op logger. 458 hlog.FromRequest(r).Info(). 459 Str("user", "current user"). 460 Str("status", "ok"). 461 Msg("Something happened") 462 463 // Output: {"level":"info","time":"2001-02-03T04:05:06Z","role":"my-service","host":"local-hostname","req_id":"b4g0l5t6tfid6dtrapu0","user":"current user","status":"ok","message":"Something happened"} 464})) 465http.Handle("/", h) 466 467if err := http.ListenAndServe(":8080", nil); err != nil { 468 log.Fatal().Err(err).Msg("Startup failed") 469} 470``` 471 472## Multiple Log Output 473`zerolog.MultiLevelWriter` may be used to send the log message to multiple outputs. 474In this example, we send the log message to both `os.Stdout` and the in-built ConsoleWriter. 475```go 476func main() { 477 consoleWriter := zerolog.ConsoleWriter{Out: os.Stdout} 478 479 multi := zerolog.MultiLevelWriter(consoleWriter, os.Stdout) 480 481 logger := zerolog.New(multi).With().Timestamp().Logger() 482 483 logger.Info().Msg("Hello World!") 484} 485 486// Output (Line 1: Console; Line 2: Stdout) 487// 12:36PM INF Hello World! 488// {"level":"info","time":"2019-11-07T12:36:38+03:00","message":"Hello World!"} 489``` 490 491## Global Settings 492 493Some settings can be changed and will by applied to all loggers: 494 495* `log.Logger`: You can set this value to customize the global logger (the one used by package level methods). 496* `zerolog.SetGlobalLevel`: Can raise the minimum level of all loggers. Call this with `zerolog.Disabled` to disable logging altogether (quiet mode). 497* `zerolog.DisableSampling`: If argument is `true`, all sampled loggers will stop sampling and issue 100% of their log events. 498* `zerolog.TimestampFieldName`: Can be set to customize `Timestamp` field name. 499* `zerolog.LevelFieldName`: Can be set to customize level field name. 500* `zerolog.MessageFieldName`: Can be set to customize message field name. 501* `zerolog.ErrorFieldName`: Can be set to customize `Err` field name. 502* `zerolog.TimeFieldFormat`: Can be set to customize `Time` field value formatting. If set with `zerolog.TimeFormatUnix`, `zerolog.TimeFormatUnixMs` or `zerolog.TimeFormatUnixMicro`, times are formated as UNIX timestamp. 503* `zerolog.DurationFieldUnit`: Can be set to customize the unit for time.Duration type fields added by `Dur` (default: `time.Millisecond`). 504* `zerolog.DurationFieldInteger`: If set to `true`, `Dur` fields are formatted as integers instead of floats (default: `false`). 505* `zerolog.ErrorHandler`: Called whenever zerolog fails to write an event on its output. If not set, an error is printed on the stderr. This handler must be thread safe and non-blocking. 506 507## Field Types 508 509### Standard Types 510 511* `Str` 512* `Bool` 513* `Int`, `Int8`, `Int16`, `Int32`, `Int64` 514* `Uint`, `Uint8`, `Uint16`, `Uint32`, `Uint64` 515* `Float32`, `Float64` 516 517### Advanced Fields 518 519* `Err`: Takes an `error` and renders it as a string using the `zerolog.ErrorFieldName` field name. 520* `Timestamp`: Inserts a timestamp field with `zerolog.TimestampFieldName` field name, formatted using `zerolog.TimeFieldFormat`. 521* `Time`: Adds a field with time formatted with `zerolog.TimeFieldFormat`. 522* `Dur`: Adds a field with `time.Duration`. 523* `Dict`: Adds a sub-key/value as a field of the event. 524* `RawJSON`: Adds a field with an already encoded JSON (`[]byte`) 525* `Hex`: Adds a field with value formatted as a hexadecimal string (`[]byte`) 526* `Interface`: Uses reflection to marshal the type. 527 528Most fields are also available in the slice format (`Strs` for `[]string`, `Errs` for `[]error` etc.) 529 530## Binary Encoding 531 532In addition to the default JSON encoding, `zerolog` can produce binary logs using [CBOR](http://cbor.io) encoding. The choice of encoding can be decided at compile time using the build tag `binary_log` as follows: 533 534```bash 535go build -tags binary_log . 536``` 537 538To Decode binary encoded log files you can use any CBOR decoder. One has been tested to work 539with zerolog library is [CSD](https://github.com/toravir/csd/). 540 541## Related Projects 542 543* [grpc-zerolog](https://github.com/cheapRoc/grpc-zerolog): Implementation of `grpclog.LoggerV2` interface using `zerolog` 544 545## Benchmarks 546 547See [logbench](http://hackemist.com/logbench/) for more comprehensive and up-to-date benchmarks. 548 549All operations are allocation free (those numbers *include* JSON encoding): 550 551```text 552BenchmarkLogEmpty-8 100000000 19.1 ns/op 0 B/op 0 allocs/op 553BenchmarkDisabled-8 500000000 4.07 ns/op 0 B/op 0 allocs/op 554BenchmarkInfo-8 30000000 42.5 ns/op 0 B/op 0 allocs/op 555BenchmarkContextFields-8 30000000 44.9 ns/op 0 B/op 0 allocs/op 556BenchmarkLogFields-8 10000000 184 ns/op 0 B/op 0 allocs/op 557``` 558 559There are a few Go logging benchmarks and comparisons that include zerolog. 560 561* [imkira/go-loggers-bench](https://github.com/imkira/go-loggers-bench) 562* [uber-common/zap](https://github.com/uber-go/zap#performance) 563 564Using Uber's zap comparison benchmark: 565 566Log a message and 10 fields: 567 568| Library | Time | Bytes Allocated | Objects Allocated | 569| :--- | :---: | :---: | :---: | 570| zerolog | 767 ns/op | 552 B/op | 6 allocs/op | 571| :zap: zap | 848 ns/op | 704 B/op | 2 allocs/op | 572| :zap: zap (sugared) | 1363 ns/op | 1610 B/op | 20 allocs/op | 573| go-kit | 3614 ns/op | 2895 B/op | 66 allocs/op | 574| lion | 5392 ns/op | 5807 B/op | 63 allocs/op | 575| logrus | 5661 ns/op | 6092 B/op | 78 allocs/op | 576| apex/log | 15332 ns/op | 3832 B/op | 65 allocs/op | 577| log15 | 20657 ns/op | 5632 B/op | 93 allocs/op | 578 579Log a message with a logger that already has 10 fields of context: 580 581| Library | Time | Bytes Allocated | Objects Allocated | 582| :--- | :---: | :---: | :---: | 583| zerolog | 52 ns/op | 0 B/op | 0 allocs/op | 584| :zap: zap | 283 ns/op | 0 B/op | 0 allocs/op | 585| :zap: zap (sugared) | 337 ns/op | 80 B/op | 2 allocs/op | 586| lion | 2702 ns/op | 4074 B/op | 38 allocs/op | 587| go-kit | 3378 ns/op | 3046 B/op | 52 allocs/op | 588| logrus | 4309 ns/op | 4564 B/op | 63 allocs/op | 589| apex/log | 13456 ns/op | 2898 B/op | 51 allocs/op | 590| log15 | 14179 ns/op | 2642 B/op | 44 allocs/op | 591 592Log a static string, without any context or `printf`-style templating: 593 594| Library | Time | Bytes Allocated | Objects Allocated | 595| :--- | :---: | :---: | :---: | 596| zerolog | 50 ns/op | 0 B/op | 0 allocs/op | 597| :zap: zap | 236 ns/op | 0 B/op | 0 allocs/op | 598| standard library | 453 ns/op | 80 B/op | 2 allocs/op | 599| :zap: zap (sugared) | 337 ns/op | 80 B/op | 2 allocs/op | 600| go-kit | 508 ns/op | 656 B/op | 13 allocs/op | 601| lion | 771 ns/op | 1224 B/op | 10 allocs/op | 602| logrus | 1244 ns/op | 1505 B/op | 27 allocs/op | 603| apex/log | 2751 ns/op | 584 B/op | 11 allocs/op | 604| log15 | 5181 ns/op | 1592 B/op | 26 allocs/op | 605 606## Caveats 607 608Note that zerolog does no de-duplication of fields. Using the same key multiple times creates multiple keys in final JSON: 609 610```go 611logger := zerolog.New(os.Stderr).With().Timestamp().Logger() 612logger.Info(). 613 Timestamp(). 614 Msg("dup") 615// Output: {"level":"info","time":1494567715,"time":1494567715,"message":"dup"} 616``` 617 618In this case, many consumers will take the last value, but this is not guaranteed; check yours if in doubt. 619