kiwi

README

Kiwi logger & context keeper

The project is long live experiment. Use it carefully.

Kiwi /kiːwiː/ are birds native to New Zealand, in the genus Apteryx and family Apterygidae. They are flightless, have hair-like feathers and smell like mushrooms. They look strange and funny so when I wrote a logger for Go language I decided to devote it to this beast which I never seen in a wild (I live very far from places where kiwis are live).

Kiwi Logger — this is a library with an odd logic that log your application data in its own strange way.

Well... kiwi package is structured logger for key-value formats (with logfmt as default), it highly customizable without hardcoded levels or nailed fields. It has dynamic filters that allow you change you logs on the fly in two aspects: reduce number of records and restrict fields for each record. It allows fine control on that should be logged in the moment and especially useful for debugging. So kiwi separates output logic (when and where you want write) from logging process itself (just log anything what you want).

Features offered by structered logging and logfmt generally and by Kiwi particularly

• simple logfmt-like format for high readability by humans
• JSON format that liked by robots
• no hardcoded levels
• change log verbosity and set of record fields on the fly
• dynamic filtering
• keep context of the application
• fast forking of subloggers with inherited context
• optional lazy evaluation of arguments for lowering logger footprint

Kiwi logger has built around the idea:

Log everything in the code with as much details as possible. But actually write only that you need in the moment.

In the ideal world of course you could log everything and it is right way. Then you are look up the central log storage that gathered logs from all the applications instances. You could view and filter the records you are interested in the moment. But in the reality the most of the systems developed locally and often you have no central log storage in development environment. And the grep utility is only the interface for logs filtering.

For example you are in debugging of the feature1 that spread across several modules of your system. You are instrumenting the code with multiple log() calls and set verbosity level to DEBUG. Then you have done with the feature and decrease you level to ERROR. Then you are begin to debug feature2 that spread even more across the modules of your system. And all repeat again. You are set the level to DEBUG and you are see the records both for the feature2 you are need and for feature1 from the past. Welcome to grepping.

The "logfmt" format solves this problem with tags. The log records consists of arbitrary number of key-value pairs. You can easily filter the only records you are need by the keys. The kiwi logger allows you set filters dynamically in runtime.

Architecture?

Scared? ;) Ha-ha... Well, really it is not too weird as this picture looks :) Let me explain with more clear and boring illustrations.

The logger instances (in different goroutines for example) write everything what you want to log. Sinks gather the data from all the instances. Sink is the name for the output — it could be a file or stdout or any other thing that realizes io.Writer(). Filters for the sinks have rules to pass only records you are really want for this output. For example you can dedicate the file for errors come from module1 and another file for errors and warnings that come from module2.

For example you can pass details of the record to a logfile for full debug. But write only important information with an error message and status to stderr.

Recipe: export the handler or setup any kind of client for setting these filters in your app. Then you get ability for dynamically change the flow and the verbosity of logs. For example increase verbosity for a specific module or a single handler and decrease them for the rest of the application.

Docs

See documentation in the wiki. Examples of logger usage see at cmd/* subfolders. And of course for API description look at godoc.

Installation

Package have no external dependencies except standard library. So just

go get github.com/grafov/kiwi

The library builds has been tested with go 1.8.

Usage examples

import "github.com/grafov/kiwi"

func main() {
	// Creates a new logger instance.
	log:=kiwi.New()

	// Now just log something as key/value pair. It will pass to output immediately (read about outputs below).
	log.Log("msg", "something", "another key", "another value")
	// Expected output:
	// msg="something" another\ key="another value"

	// You can pass odd number of parameters. Odd parameter passed to output just as is.
	log.Log("key-only")
	// Expected output:
	// "key-only"

	// It can add key=value pairs to a new log record.
	// They don't passed to the output until Log() call.
	log.Add("where", "module1", "event", "something happened")

	// So it may be any number of Add() calls with additional pairs.
	// Then flush them all.
	log.Add("event", "and now something completely different").Log()

	// You can pass any scalar types from Go standard library as record keys and values
	// they will be converted to their string representation.
	log.Log("key", 123, "key2", 1.23e3, "key3", 'u', "key4", true)
	// Expected output:
	// key=123 key2=1.23e3 key3="u" key4=true

	// You need define even one sink: set writer and logging format.
	// Until the sink defined log records just saved nowhere.
	// You can define arbitrary number of sinks. Each sink has its own set of filters.
	out:=kiwi.SinkTo(os.StdOut, kiwi.Logfmt).Start()

	// Filters decide pass or not incoming log record to this output.
	// Example filters below will pass only records which has key "userID" and has value of level="FATAL".
	out.WithKey("userID").WithValue("level", "FATAL")

	// So in this manner you can fan out log record to several outputs.
	// For example write separate log of critical errors and common log with all errors.
	// By default without any filters any output accepts any incoming log records.
	out2 := kiwi.SinkTo(os.StdErr, kiwi.JSON).Start()

	// Kiwi offers various filters for set conditions for outputs.
	out2.WithInt64Range("userID", 100, 500).WithoutValue("label", "debug")
}

See more ready to run samples in cmd subdirs. Filters described in the wiki: Filtering.

The context records

Kiwi logger allows you keep some pairs during lifetime of a logger instance.

import "github.com/grafov/kiwi"

func main() {
	// Creates a new logger instance.
	log1 := kiwi.New()

	// You can set permanent pairs as logger context.
	log1.With("userID", 1000, "PID", os.GetPID())

	// They will be passed implicitly amongst other pairs for the each record.
	log1.Log("msg", "details about something")
	// Expect output:
	// userID=1000 PID=12345 msg="details about something"

	// Context copied into a new logger instance after logger cloned.
	log2 := log1.New()

	log2.Log("key", "value")
	// Expect output:
	// userID=1000 PID=12345 key="value"

	// Get previously keeped context values. Results returned as map[string]interface{}
	appContext := log2.GetContext()
	fmt.Printf("%+v\n", appContext)

	// You can reset context at any time with
	log2.ResetContext()
}

Thread safety

It is unsafe by design. Firstly I have used version for safe work in multiple goroutines. And it was not only slow but in just not need in many cases. If you need a new logger in another execution thread you will create another instanse. Better is clone old instance to a new one for passing the context to a subroutine. It is all.

	// Creates a new logger instance.
	log1 := kiwi.New().With("context key", "context value")

	// Just clone old instance to a new one. It will keep the context of the first instance.
	log2 := log1.New()

	// And you can extend context for cloned instance.
	log2.With("another key", "another value")

	// So other concurrent routines may accept logger with the same context.
	go subroutine(log2, otherArgs...)

For the small apps where you won't init all these instances you would like use global kiwi.Log() method. This method just immediately flush it's args to the sinks. And by design it is safe for concurrent usage. Also due design simplicity it not supports context, only regular values. If you need context then you application is complex thing hence you will need initialize a new instance of kiwi.Logger().

Evaluating rules

• Keys and values evaluated immediately after they added to a record.
• Context values evaluated once when they added to a logger.
• For lazy evaluating of context and record values pass them as functions:

	# For lazy evaluating you need function that returns string
	func longActionForDelayedEvaluation() string {
		// Do something complex...
		// and got for example integer result.
		//
		// You need convert the result to a string.
		return strconv.Itoa(result)
	}
	myLog.Add("lazy-sample", longActionForDelayedEvaluation) # but not longActionForDelayedEvaluation()

Logger accepts functions without args that returns a string: func () string. Hence value of lazy-sample from the example above will be evaluated only on Log() call.

Additional features in other packages

I try to keep the main logging package simple. Filters-formatters-sinks concept is core thing in kiwi tag filtering so it all placed in the single package. Alongside with basic formatters for JSON and Logfmt. All other features I try to move to separate packages. The kiwi repository have the subpackages you could import:

• level — imitate traditional syslog-like levels (read more details below)
• timestamp — provide the logger instance with additional timestamp field
• strict — helper functions for providing more type control on your records

Warning about evil severity levels

The most of loggers came to you with concept of levels. So you are filter anything but only records of the preconigured level and levels above really appear in the log. The current level read from the configuration of the application. There are loggers that allow you change the level in runtime. The level here is like the key in logfmt. But logfmt became with more general idea: you can arbitrary number of keys for the filtering. Not only predefined words for levels but any things like feature, module etc. So you can filter not only by the severity but set general taxonomy of the categories across all the parts (subsystems, modules) of your application.

Another problem with traditional syslog-like levels is non clear specification what exactly should pass to each level. Look up the internet for many guides with controversial recommendations how to distinguish all these "standard" levels and try map them to various events in your application. So in the reality programmers often debate about level for the log record. For example when you should use "fatal" instead of "critical" or use "debug" instead of "info". So very often severity levels obstruct understanding of the logs.

You can use log syslog-like levels in kiwi if you are comfortable with them (see helper functions in level subpackage) and interprete them as you wish. Severity levels in kiwi don't play any role in deciding how to output the record. Any records with any level will pass to all sinks. Filters in each sink will decide how to actually display the record or filter it out completely.

Instead of FAQ

1. Kiwi logger not strictly follows logfmt specs.
2. Ideas of key-value format are like JSON format but with orientation on readability for humans first.
3. Yes, it was architectured and developed to be a standard number 15 that competing with others. It is not pretend to be log format for everything.
4. No, it is not related to log15 logger though kiwi shares the same logfmt format and some ideas with him.
5. It did not offer "Logger" interface because IMO interface is useless for loggers. It offers interfaces for the parts of logger like formatters.

Similar works for structured logging

• zap
• zerolog
• logxi
• logrus
• log15
• zlog - this one is even not in Go but this C logger has some similar ideas.

Comparison with other loggers

It is not the fastest logger among benchmarked but fast enough and careful about memory allocations. It much faster than logrus and log15. But slower than logxi tests. Need more detailed tests though. See the benchmarks results at github.com/grafov/go-loggers-comparison.

Roadmap

What should be done before the first release:

• handle nils in more convenient way
• test behaviour of all the filters and fix possible bugs
• test JSON output and fix possible bugs
• realize API for custom filters

Future plans:

• extend the predefined filters (cancelled)
• optional colour formatter for the console
• throttling mode for sinks
• increase tests coverage up to 50%
• add tests for concurrent execution use cases
• increase tests coverage up to 75%
• multiline output for values
• increase tests coverage up to 80%

See details about tasks and ideas in TODO.org (orgmode format). See current tests coverage.

Origins

• logfmt description brandur.org/logfmt
• logfmt realization in Go and specs godoc.org/github.com/kr/logfmt
• see also logfmt realization github.com/go-logfmt/logfmt
• picture used for logo openclipart.org/detail/4416/kiwi-bird

Documentation

Overview

Package kiwi is a library with an odd logic that log your application' data in its own strange way.

WIP. API and features is subject of changes. Use it carefully!

Features briefly:

• simple format with explicit key for each log message (*logfmt* like) - for high readability by humans

• JSON format that so liked by machines

• ability to define own custom format of the output

• there are not nailed levels, not hardcoded fields in the format

• output dynamic filtering (change log verbosity on the fly)

• can keep context of application

• it fast enough and careful about memory allocs

Key feature of `kiwi` logger is dynamic filtering of incoming records. Instead of checking severety level for decide about pass or not the record to the output, `kiwi` passes all records to *all* the outputs (they called *sinks* in `kiwi` terminology). But before actual writing each record checked with a set of filters. Each sink has its own filter set. It takes into account record keys, values, ranges of values. So each sink decides pass the record to a writer or filter it out. Also any pairs in the record may be hidden: so different sinks may display different parts of the same record. Other effect is: any record may be written to any number of outputs.

Index

• Constants
• Variables
• func AsJSON() *formatJSON
• func AsLogfmt() *formatLogfmt
• func FlushAll()
• func Log(kv ...interface{})
• func ResetContext()
• func With(kv ...interface{})
• func Without(keys ...string)
• type Filter
• type Formatter
• type Logger
  • func Fork() *Logger
  • func New() *Logger
  • func (l *Logger) Add(keyVals ...interface{}) *Logger
  • func (l *Logger) Fork() *Logger
  • func (l *Logger) Log(keyVals ...interface{})
  • func (l *Logger) New() *Logger
  • func (l *Logger) Reset() *Logger
  • func (l *Logger) ResetContext() *Logger
  • func (l *Logger) With(keyVals ...interface{}) *Logger
  • func (l *Logger) Without(keys ...string) *Logger
• type Pair
• type Sink
  • func SinkTo(w io.Writer, fn Formatter) *Sink
  • func (s *Sink) Close()
  • func (s *Sink) Float64NotRange(key string, from, to float64) *Sink
  • func (s *Sink) Float64Range(key string, from, to float64) *Sink
  • func (s *Sink) Flush() *Sink
  • func (s *Sink) HasKey(keys ...string) *Sink
  • func (s *Sink) HasNotKey(keys ...string) *Sink
  • func (s *Sink) HasNotValue(key string, vals ...string) *Sink
  • func (s *Sink) HasValue(key string, vals ...string) *Sink
  • func (s *Sink) Hide(keys ...string) *Sink
  • func (s *Sink) Int64NotRange(key string, from, to int64) *Sink
  • func (s *Sink) Int64Range(key string, from, to int64) *Sink
  • func (s *Sink) Reset(keys ...string) *Sink
  • func (s *Sink) Start() *Sink
  • func (s *Sink) Stop() *Sink
  • func (s *Sink) TimeNotRange(key string, from, to time.Time) *Sink
  • func (s *Sink) TimeRange(key string, from, to time.Time) *Sink
  • func (s *Sink) Unhide(keys ...string) *Sink
  • func (s *Sink) WithFilter(key string, customFilter Filter) *Sink
• type Stringer
• type Valuer

Constants

const (
	// BooleanVal and other types below commonly formatted unquoted.
	// But it depends on the formatter.
	BooleanVal = iota
	IntegerVal
	FloatVal
	ComplexVal
	CustomUnquoted
	// VoidVal and other types below commonly formatted unquoted.
	// But it depends on the formatter.
	StringVal
	TimeVal
	CustomQuoted
)

Possible kinds of logged values.

Variables

var (
	MessageKey = "message"
	ErrorKey   = "kiwi-error"
	InfoKey    = "kiwi-info"
)

var FloatFormat byte = 'e'

FloatFormat used in Float to String conversion. It is second parameter passed to strconv.FormatFloat()

var TimeLayout = time.RFC3339

TimeLayout used in time.Time to String conversion.

Functions

func AsJSON

func AsJSON() *formatJSON

AsJSON says that a sink uses JSON (RFC-7159) format for records output.

func AsLogfmt

func AsLogfmt() *formatLogfmt

AsLogfmt says that a sink uses Logfmt format for records output.

func FlushAll

func FlushAll()

FlushAll should wait for all the sinks to be flushed. It does nothing currently. It has left for compatibility with old API.

func Log

func Log(kv ...interface{})

Log is simplified realization of Logger.Log(). You would like use it in short applications where context and initialization of logger could brought extra complexity. If you wish separate contexts and achieve better performance use Logger type instead.

func ResetContext

func ResetContext()

ResetContext resets the global context for the global logger and its descendants. It is safe for concurrency.

func With

func With(kv ...interface{})

With adds key-vals to the global logger context. It is safe for concurrency.

func Without

func Without(keys ...string)

Without drops the keys from the context of the global logger. It is safe for concurrency.

Types

type Filter

type Filter interface {
	Check(string, string) bool
}

Filter accepts key and value. If the filter passed it should return true. Custom filters must conform the interface.

type Formatter

type Formatter interface {
	// Begin function allows to add prefix string for the output
	// or make some preparations before the output.
	Begin()
	// Pair function called for each key-value pair of the record.
	// ValueType is hint that helps the formatter decide how to output the value.
	// For example formatter can format string values in quotes but numbers without them.
	Pair(key, value string, valueType int)
	// Finish function allows to add suffix string for the output.
	// Also it returns result string for the displaying of the single record.
	// It may be multiline if you wish. Result has no restrictions for you imagination :)
	Finish() []byte
}

Formatter represents format of the output.

type Logger

type Logger struct {
	// contains filtered or unexported fields
}

Logger keeps context and log record. There are many loggers initialized in different places of application. Loggers are not safe for concurrent usage so then you need logger for another goroutine you will need clone existing instance. See Logger.New() method below for details.

func Fork

func Fork() *Logger

Fork creates a new logger instance that inherited the context from the global logger. Thi fuction is concurrent safe.

func New

func New() *Logger

New creates a new logger instance but not copy context from the global logger. The method is empty now, I keep it for compatibility with older versions of API.

func (*Logger) Add

func (l *Logger) Add(keyVals ...interface{}) *Logger

Add a new key-value pairs to the log record. If a key already added then value will be updated. If a key already exists in a contextSrc then it will be overridden by a new value for a current record only. After flushing a record with Log() old context value will be restored.

func (*Logger) Fork

func (l *Logger) Fork() *Logger

Fork creates a new instance of the logger. It copies the context from the logger from the parent logger. But the values of the current record of the parent logger discarded.

func (*Logger) Log

func (l *Logger) Log(keyVals ...interface{})

Log is the most common method for flushing previously added key-val pairs to an output. After current record is flushed all pairs removed from a record except contextSrc pairs.

func (*Logger) New

func (l *Logger) New() *Logger

New creates a new instance of the logger. It not inherited the context of the parent logger. The method is empty now, I keep it for compatibility with older versions of API.

func (*Logger) Reset

func (l *Logger) Reset() *Logger

Reset logger values added after last Log() call. It keeps context untouched.

func (*Logger) ResetContext

func (l *Logger) ResetContext() *Logger

ResetContext resets the context of the logger. The function is not concurrent safe.

func (*Logger) With

func (l *Logger) With(keyVals ...interface{}) *Logger

With defines a context for the logger. The context overrides pairs in the record. The function is not concurrent safe.

func (*Logger) Without

func (l *Logger) Without(keys ...string) *Logger

Without drops some keys from a context for the logger. The function is not concurrent safe.

type Pair

type Pair struct {
	Key  string
	Val  string
	Eval interface{}
	Type int
}

Pair is key and value together. They can be used by custom helpers for example for logging timestamps or something.

type Sink

type Sink struct {
	In chan chain

	sync.RWMutex
	// contains filtered or unexported fields
}

Sink used for filtering incoming log records from all logger instances and decides how to filter them. Each output wraps its own io.Writer. Sink methods are safe for concurrent usage.

func SinkTo

func SinkTo(w io.Writer, fn Formatter) *Sink

SinkTo creates a new sink for an arbitrary number of loggers. There are any number of sinks may be created for saving incoming log records to different places. The sink requires explicit start with Start() before usage. That allows firstly setup filters before sink will really accept any records.

func (*Sink) Close

func (s *Sink) Close()

Close closes the sink. It flushes records for the sink before closing.

func (*Sink) Float64NotRange

func (s *Sink) Float64NotRange(key string, from, to float64) *Sink

Float64NotRange sets restriction for records output.

func (*Sink) Float64Range

func (s *Sink) Float64Range(key string, from, to float64) *Sink

Float64Range sets restriction for records output.

func (*Sink) Flush

func (s *Sink) Flush() *Sink

Flush waits that all previously sent to the output records worked. It does nothing currently. It has left for compatibility with old API.

func (*Sink) HasKey

func (s *Sink) HasKey(keys ...string) *Sink

HasKey sets restriction for records output. Only the records WITH any of the keys will be passed to output.

func (*Sink) HasNotKey

func (s *Sink) HasNotKey(keys ...string) *Sink

HasNotKey sets restriction for records output. Only the records WITHOUT any of the keys will be passed to output.

func (*Sink) HasNotValue

func (s *Sink) HasNotValue(key string, vals ...string) *Sink

HasNotValue sets restriction for records output.

func (*Sink) HasValue

func (s *Sink) HasValue(key string, vals ...string) *Sink

HasValue sets restriction for records output. A record passed to output if the key equal one of any of the listed values.

func (*Sink) Hide

func (s *Sink) Hide(keys ...string) *Sink

Hide keys from the output. Other keys in record will be displayed but not hidden keys.

func (*Sink) Int64NotRange

func (s *Sink) Int64NotRange(key string, from, to int64) *Sink

Int64NotRange sets restriction for records output.

func (*Sink) Int64Range

func (s *Sink) Int64Range(key string, from, to int64) *Sink

Int64Range sets restriction for records output.

func (*Sink) Reset

func (s *Sink) Reset(keys ...string) *Sink

Reset all filters for the keys for the output. If no one key provided it do global reset for all filters of the sink.

func (*Sink) Start

func (s *Sink) Start() *Sink

Start writing to the output. After creation of a new sink it will paused and you need explicitly start it. It allows setup the filters before the sink will accepts any records.

func (*Sink) Stop

func (s *Sink) Stop() *Sink

Stop stops writing to the output.

func (*Sink) TimeNotRange

func (s *Sink) TimeNotRange(key string, from, to time.Time) *Sink

TimeNotRange sets restriction for records output.

func (*Sink) TimeRange

func (s *Sink) TimeRange(key string, from, to time.Time) *Sink

TimeRange sets restriction for records output.

func (*Sink) Unhide

func (s *Sink) Unhide(keys ...string) *Sink

Unhide previously hidden keys. They will be displayed in the output again.

func (*Sink) WithFilter

func (s *Sink) WithFilter(key string, customFilter Filter) *Sink

WithFilter setup custom filtering function for values for a specific key. Custom filter should realize Filter interface. All custom filters treated as positive filters. So if the filter returns true then it will be passed.

type Stringer

type Stringer interface {
	String() string
}

Stringer is the same as fmt.Stringer

type Valuer

type Valuer interface {
	Stringer
	IsQuoted() bool
}

Valuer allows log data from any custom types if they conform this interface. Also types that conform fmt.Stringer can be used. But as they not have IsQuoted() check they always treated as strings and displayed in quotes.