kvlog provides a structured logging facility. The underlying structure is based on key-value pairs.
key-value pairs are rendered as JSON lines but other Formatters can be used to provide different outputs
including custom ones.
kvlog tries to find a balance between highly performance optimized libs such as zap or zerolog and those
that define a "dead simple" API (such as go-kit or logrus). It does not perform as well as the first two
but significantly better than the last two. kvlog tries to provide an easy-to-use API for producing
structured log events while keeping up a good performance.
kvlog uses go modules and requires Go 1.16 or greater.
$ go get -u github.com/halimath/kvlog
To emit log events, you need a Logger. kvlog provides a ready-to-use Logger via the L variable.
You can create a custom logger giving you more flexibility on the logger's target and format.
Creating a new Logger is done via the kvlog.New function.
It accepts any number of Handlers. Each Handler pairs an io.Writer as well as a Formatter.
logger := kvlog.New(kvlog.NewSyncHandler(os.Stdout, kvlog.JSONLFormatter())).
AddHook(kvlog.TimeHook)Handlers can be synchronous as well as asynchronous.
Synchronous Handlers execute the Formatter as well as writing the output in the same goroutine that invoked
the Logger.
Asynchronous Handlers dispatch the log event to a different goroutine via a channel.
Thus, asynchronous Handlers must be closed before shutdown in order to flush the channel and emit all log
events.
The easiest way to emit a simple log message is to use a Logger's Log, Log or Logf method.
kvlog.L.Logs("hello, world")
kvlog.L.Logf("hello, %s", "world)Log will log all given key-value pairs while Logs and Logf will format a message with additional
key-value pairs. With the default JSONL formatter, this produces:
{"msg":"hello"}
{"msg":"hello, world"}If you want to add more key-value pairs - which is the primary use case for a structured logger - you can pass
additional arguments to any of the log methods. key-value pairs are best created using one of the With...
functions from kvlog.
kvlog.L.Logs("hello, world",
kvlog.WithKV("tracing_id", 1234),
kvlog.WithDur(time.Second),
kvlog.WithErr(fmt.Errorf("some error")),
)Logger's can be derived from another Logger. This enables to configure a set of key-value-pairs to be added
to every event emmitted via the deriverd logger. The syntax works similar to emitting log messages this time
only invoking the Sub method instead of Log.
dl := l.Sub(
kvlog.WithKV("tracing_id", "1234"),
)In addition to deriving loggers, any number of Hooks may be added to a logger. The hook's callback function
is invoked everytime an Event is emitted via this logger or any of its derived loggers. Hooks are useful
to add dynamic values, such as timestamps or anything else read from the surrounding context. Adding a
timestamp to every log event is realized via the TimeHook.
l := kvlog.New(kvlog.NewSyncHandler(&buf, kvlog.JSONLFormatter())).
AddHook(kvlog.TimeHook)You can write your own hook by implement the kvlog.Hook interface or using the kvlog.HookFunc convenience
type for a simple function.
// This is an example for some function that determines a dynamic value.
extractTracingID := func() string {
// some real implementation here
return "1234"
}
// Create a logger and add the hook
logger := kvlog.New(kvlog.NewSyncHandler(os.Stdout, kvlog.JSONLFormatter())).
AddHook(kvlog.HookFunc(func(e *kvlog.Event) {
e.AddPair(kvlog.WithKV("tracing_id", extractTracingID()))
}))
// Emit some event
logger.Logs("request")This example produces:
{"tracing_id":"1234","msg":"request"}The go standard library provides package context to pass contextual values
to operations being called downstream. kvlog provides functions that hook into
a context and add a Logger which can later be retrieved. As a sub logger can
be configured with context keys, you can pass that logger down via the context.
Use ContextWithLogger to create a derived context holding a logger. Calling
FromContext restores the logger. If no logger is contained in the context a
default NoOp logger is returned, so code can run without panic.
ctx = ContextWithLogger(ctx, subLogger)
// ...
l = FromContext(ctx)
l.Logs("my message")The kvlog package comes with three Formatters out of the box:
JSONLFormatterformats events as JSON line valuesConsoleFormatterformats events for output on a terminal which includes colorizing the eventKVFormatterformats events in the legacy KV-Format
The JSONLFormatter features a lot of optimizations to improve time and memory behavior. The other two have a
less optimized performance. While the ConsoleFormatter is intended for dev use the KVFormatter is only
provided for compatibility reasons and should be considered deprecated. Use JSONLFormatter for production
systems.
Custom formatters may be created by implementing the kvlog.Formatter interface or using the
kvlog.FormatterFunc convenience type.
kvlog contains a HTTP middleware that generates an access log and supports adding a logger to the request's
Context. The middleware is compatible with frameworks such as Chi that support Use but you can also
use the middleware with bare net/http.
package main
import (
"net/http"
"github.com/halimath/kvlog"
)
func main() {
mux := http.NewServeMux()
// ...
kvlog.L.Log("started")
http.ListenAndServe(":8000", kvlog.Middleware(kvlog.L, true)(mux))
}The following table lists the default keys used by kvlog. You can customize these by setting a module-level
variable. These are also given in the table below.
| Key | Used with | Variable to change | Description |
|---|---|---|---|
time |
TimeHook |
KeyTime |
The default key used to identify an event's time stamp. |
err |
Event.Err |
KeyError |
The default key used to identify an event's error. |
msg |
Event.Log or Event.Logf |
KeyMessage |
The default key used to identify an event's message. |
dur |
Event.Dur |
KeyDuration |
The default key used to identify an event's duration value. |
kvlog includes a set of performance optimizations. Most of them work by pre-allocating memory for data
structures to be reused in order to avoid allocations for each log event. These pre-allocations can be tuned
in case an application has a specific load profile. This tuning can be performed by setting module-global
variables.
There are two primary areas, where pre-allocation is used.
- New
Events are not created every time a logger'sWithmethod is called. Instead, most of the time a pre-existingEventis pulled from async.Pooland put back after the event has been formatted. Such a pool exists for each root logger - that is every logger created withkvlog.New. The pool is pre-filled with a number of events. All the events pre-filled into the pool also have a pre-allocated number of key-value-pair slots which are re-used by overwriting them whenever aKVmethod is called. Both numbers - initial pool size and pre-allocated number of pairs - can be changed. - When using an asynchronous handler, the handler's formatter is invoked synchronously. The output is written
to a
bytes.Buffer. This buffer comes from async.Pooland has a pre-allocated bytes slice. After the event has been formatted, the buffer is sent over a bufferd channel. The channel is consumed by another goroutine, which copies the buffer's bytes on the output writer. After that, the buffer is put back into the pool. Pool size, buffer size and channel buffer size can be customized.
Changes to these variables only take effect for loggers/handlers created after the variable have been assigned. Use at your own risk.
| Variable | Default Value | Description |
|---|---|---|
DefaultEventSize |
16 | The default size Events created from an Event pool. |
InitialEventPoolSize |
128 | Number of events to allocate for a new Event pool. |
AsyncHandlerBufferSize |
2048 | Defines the size of an async handler's buffer that is preallocated. |
AsyncHandlerPoolSize |
64 | Defines the number of preallocated buffers in a pool of buffers. |
AsyncHandlerChannelSize |
1024 | Number of log events to buffer in an async handler's channel. |
The benchmarks directory contains some benchmarking tests which compare different logging
libs with a structured log event consisting of several key-value-pairs of different types. These are the
results run on a developers laptop.
| Library | ns/op | B/op | allocs/op |
|---|---|---|---|
| kvlog (sync handler) | 1527 | 152 | 8 |
| kvlog (async handler) | 1392 | 153 | 8 |
| zerolog | 352.9 | 0 | 0 |
| logrus | 4430 | 2192 | 34 |
| go-kit/log | 2201 | 970 | 18 |
- New HTTP middleware function compatible with other frameworks (such as Chi)
- Middleware can add logger to
Context
- Context API
- NoOp Logger
- New API
- Performance improvements
- Fix: add
sync.Mutexto lockHandler
- added
NoOpHandlerto easily silence logging output
- New chaining API to create messages
- Performance optimization
- Nested loggers allow adding default key value pairs to add to all logger (i.e. for use with a category)
- Reorganization into several packages; root package
kvlogacts as a facade - Renamed some types (mostly interfaces) to better match the new package name (i.e.
handler.Interfaceinstead ofhandler.Handler) - Added
jsonlformatter which creates JSON lines output
KVFormattersorts pairs based on key- New
TerminalFormatterproviding colored output on terminals - Moved to github
- Export package level logger instance
L
- Introduction of new component structure (see description above)
- Improve log message rendering
- Initial release
Copyright 2019, 2020 Alexander Metzner.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.