jsternberg / zap-logfmt

Logfmt Encoder

This package implements logfmt for zap.

Usage

The encoder is simple to use.

package main

import (
	"os"

	"github.com/jsternberg/zap-logfmt"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	config := zap.NewProductionEncoderConfig()
	logger := zap.New(zapcore.NewCore(
		zaplogfmt.NewEncoder(config),
		os.Stdout,
		zapcore.DebugLevel,
	))
	logger.Info("Hello World")
}

To use RFC3339 output for the time instead of an integer timestamp, you can do this:

package main

import (
	"os"

	"github.com/jsternberg/zap-logfmt"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	config := zap.NewProductionEncoderConfig()
	config.EncodeTime = func(ts time.Time, encoder zapcore.PrimitiveArrayEncoder) {
		encoder.AppendString(ts.UTC().Format(time.RFC3339))
	}
	logger := zap.New(zapcore.NewCore(
		zaplogfmt.NewEncoder(config),
		os.Stdout,
		zapcore.DebugLevel,
	))
	logger.Info("Hello World")
}

Limitations

It is not possible to log an array, channel, function, map, slice, or struct. Functions and channels since they don't really have a suitable representation to begin with. Logfmt does not have a method of outputting arrays or maps so arrays, slices, maps, and structs cannot be rendered.

Namespaces

Namespaces are supported. If a namespace is opened, all of the keys will be prepended with the namespace name. For example, with the namespace foo and the key bar, you would get a key of foo.bar.

zap-logfmt's Issues

When fields are added to the encoder, an extra space gets added to the output of EncodeEntry

When a minimal zapcore.EncoderConfig is used to create a logfmt encoder and a field is added to the encoder, an extra space is added to the beginning of the formatted message.

This was discovered while trying to delegate field formatting to the logfmt encoder from within another custom encoder.

Inconsistent namespace handling for reserved logger keys

The encoder somewhat breaks namespacing that zap provides, since it appends the namespace foo to the msg key (and others) as well. This is not the case in the zap package.

Compare the output of logfmt (from this plugin):

database.ts=2022-11-25T13:50:59.759+0100 database.level=info database.caller=cmd/root.go:150 database.msg="initializing DB connection" 

to standard json encoding via zap package:

{"level":"info","ts":"2022-11-25T13:52:12.539+0100","caller":"cmd/root.go:150","msg":"initializing DB connection","app_name":"main","app_version":"snapshot","database":{"host": ... }}

The solution would be something along the lines of

func (enc *logfmtEncoder) addKey(key string) {
	if enc.buf.Len() > 0 {
		enc.buf.AppendByte(' ')
	}
	switch key {
	case enc.EncoderConfig.TimeKey, enc.EncoderConfig.LevelKey, enc.EncoderConfig.NameKey, enc.EncoderConfig.CallerKey, enc.EncoderConfig.MessageKey, enc.EncoderConfig.StacktraceKey:
	default:
		for _, ns := range enc.namespaces {
			enc.safeAddString(ns)
			enc.buf.AppendByte('.')
		}
	}
	enc.safeAddString(key)
	enc.buf.AppendByte('=')
}

Let me know if I should open a PR.

AppendReflected call should use integers for integers

At the moment, using the reflected part of the code will always output a string. If the value is an integer or a float, it should be appended as those data types instead.

Use a type switch instead and the appropriate method rather than attempting to use the reflect package.

panic when processing reflected slice field

If a zap.Reflect field is provided then a reflect: call of reflect.Value.Elem on slice Value panic occurs.

For example this:

package main

import (
	"os"

	zaplogfmt "github.com/jsternberg/zap-logfmt"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	config := zap.NewProductionEncoderConfig()
	logger := zap.New(zapcore.NewCore(
		zaplogfmt.NewEncoder(config),
		os.Stdout,
		zapcore.DebugLevel,
	))
	logger.Info("Hello World", zap.Reflect("v", []string{"hello", "world"}))
}

produces:

panic: reflect: call of reflect.Value.Elem on slice Value

goroutine 1 [running]:
reflect.Value.Elem({0x102473c60?, 0x1400000e210?, 0x14000125898?})
	/usr/local/go/src/reflect/value.go:1259 +0x1a4
github.com/jsternberg/zap-logfmt.(*logfmtEncoder).AddReflected(0x2?, {0x10240dc7b, 0x1}, {0x102473c60?, 0x1400000e210?})
	/Users/mhilton/Library/go/pkg/mod/github.com/jsternberg/[email protected]/encoder.go:111 +0x1a0
go.uber.org/zap/zapcore.Field.AddTo({{0x10240dc7b, 0x1}, 0x17, 0x0, {0x0, 0x0}, {0x102473c60, 0x1400000e210}}, {0x1024ab358, 0x1400007ede0?})
	/Users/mhilton/Library/go/pkg/mod/go.uber.org/[email protected]/zapcore/field.go:170 +0x6d4
github.com/jsternberg/zap-logfmt.addFields(...)
	/Users/mhilton/Library/go/pkg/mod/github.com/jsternberg/[email protected]/encoder.go:537
github.com/jsternberg/zap-logfmt.(*logfmtEncoder).EncodeEntry(0x1400007ed80, {0x0, {0xc0b842abd4bf62d8, 0x11b9c4, 0x1025a8260}, {0x0, 0x0}, {0x10240f485, 0xb}, {0x0, ...}, ...}, ...)
	/Users/mhilton/Library/go/pkg/mod/github.com/jsternberg/[email protected]/encoder.go:307 +0x3b0
go.uber.org/zap/zapcore.(*ioCore).Write(0go: exit 1
x1400007edb0, {0x0, {0xc0b842abd4bf62d8, 0x11b9c4, 0x1025a8260}, {0x0, 0x0}, {0x10240f485, 0xb}, {0x0, ...}, ...}, ...)
	/Users/mhilton/Library/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:86 +0x54
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0x14000101380, {0x1400012c1c0, 0x1, 0x1})
	/Users/mhilton/Library/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:255 +0x150
go.uber.org/zap.(*Logger).Info(0x14000062160?, {0x10240f485?, 0x2?}, {0x1400012c1c0, 0x1, 0x1})
	/Users/mhilton/Library/go/pkg/mod/go.uber.org/[email protected]/logger.go:213 +0x54
main.main()
	/Users/mhilton/src/zap-logfmt-test/main.go:18 +0x308

Simplify Example, Extend README

Since zap-logfmt registers itself as an encoder with zap, (arguably), it's even simpler to use than the current example in the README suggests, i.e. e.g.:

package main

import (
	"go.uber.org/zap"
	_ "github.com/jsternberg/zap-logfmt"
)

func main() {
	config := zap.NewProductionConfig()
	config.DisableCaller = true
	config.Encoding = "logfmt"
	logger, _ := config.Build()
	logger.Info("Hello World")
}

That means it's 5 lines shorter, doesn't require knowledge of zap's core API and doesn't change other zap defaults (i.e. logging to stdout instead of stderr and changing the logging severity to debug - although debug isn't used in the example).

It produces the same output as the current first example:

ts=1598901552.010505 level=info msg="Hello World"

Thus, perhaps you want include something like the above in your README.

Perhaps you also want to extend the README a bit:

1. Explicitly mention that this package registers itself with the "logfmt" key such that Config.Encoding can be used to switch to logfmt output. FWIW - as being new to zap and your package - this wasn't obvious to me.
2. Add some example output for the examples.