Commit 2a8127f0 authored by Matthew Sykes's avatar Matthew Sykes
Browse files

[FAB-12942] use logfmt format for log fields



Change-Id: Ibbbf4f55bd42a0914edc4b247c391e020b3a68a4
Signed-off-by: default avatarMatthew Sykes <sykesmat@us.ibm.com>
parent 8a887975
......@@ -681,6 +681,14 @@
revision = "f35b8ab0b5a2cef36673838d662e249dd9c94686"
version = "v1.2.2"
[[projects]]
branch = "master"
digest = "1:b9a00fb37a0075071b6787ff0abc4caad3e23b8b0986ca8a0a9f5d1311de06ea"
name = "github.com/sykesm/zap-logfmt"
packages = ["."]
pruneopts = "NUT"
revision = "f9c81d9cb090ad639813e03ea60132bdd515d3f8"
[[projects]]
branch = "master"
digest = "1:f2ffd421680b0a3f7887501b3c6974bcf19217ecd301d0e2c9b681940ec363d5"
......@@ -988,6 +996,7 @@
"github.com/stretchr/testify/assert",
"github.com/stretchr/testify/mock",
"github.com/stretchr/testify/require",
"github.com/sykesm/zap-logfmt",
"github.com/syndtr/goleveldb/leveldb",
"github.com/syndtr/goleveldb/leveldb/errors",
"github.com/syndtr/goleveldb/leveldb/iterator",
......
......@@ -157,6 +157,10 @@ noverify = [
name = "go.uber.org/zap"
version = "1.9.0"
[[constraint]]
branch = "master"
name = "github.com/sykesm/zap-logfmt"
[[constraint]]
name = "github.com/grpc-ecosystem/go-grpc-middleware"
version = "1.0.0"
......
......@@ -15,10 +15,11 @@ type Encoding int8
const (
CONSOLE = iota
JSON
LOGFMT
)
// EncodingSelector is used to determine whether log records are
// encoded as JSON or in a human readable CONSOLE format.
// encoded as JSON or in human readable CONSOLE or LOGFMT formats.
type EncodingSelector interface {
Encoding() Encoding
}
......
......@@ -10,6 +10,7 @@ import (
"io"
"time"
zaplogfmt "github.com/sykesm/zap-logfmt"
"go.uber.org/zap/buffer"
"go.uber.org/zap/zapcore"
)
......@@ -29,7 +30,7 @@ type Formatter interface {
func NewFormatEncoder(formatters ...Formatter) *FormatEncoder {
return &FormatEncoder{
Encoder: zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
Encoder: zaplogfmt.NewEncoder(zapcore.EncoderConfig{
MessageKey: "", // disable
LevelKey: "", // disable
TimeKey: "", // disable
......
......@@ -29,12 +29,12 @@ func TestEncodeEntry(t *testing.T) {
expected string
}{
{name: "empty spec and nil fields", spec: "", fields: nil, expected: "\n"},
{name: "empty spec with fields", spec: "", fields: []zapcore.Field{zap.String("key", "value")}, expected: `{"key": "value"}` + "\n"},
{name: "empty spec with fields", spec: "", fields: []zapcore.Field{zap.String("key", "value")}, expected: "key=value\n"},
{name: "simple spec and nil fields", spec: "simple-string", expected: "simple-string\n"},
{name: "simple spec and empty fields", spec: "simple-string", fields: []zapcore.Field{}, expected: "simple-string\n"},
{name: "simple spec with fields", spec: "simple-string", fields: []zapcore.Field{zap.String("key", "value")}, expected: `simple-string {"key": "value"}` + "\n"},
{name: "duration", spec: "", fields: []zapcore.Field{zap.Duration("duration", time.Second)}, expected: `{"duration": "1s"}` + "\n"},
{name: "time", spec: "", fields: []zapcore.Field{zap.Time("time", startTime)}, expected: fmt.Sprintf(`{"time": "%s"}`+"\n", startTime.Format("2006-01-02T15:04:05.999Z07:00"))},
{name: "simple spec with fields", spec: "simple-string", fields: []zapcore.Field{zap.String("key", "value")}, expected: "simple-string key=value\n"},
{name: "duration", spec: "", fields: []zapcore.Field{zap.Duration("duration", time.Second)}, expected: "duration=1s\n"},
{name: "time", spec: "", fields: []zapcore.Field{zap.Time("time", startTime)}, expected: fmt.Sprintf("time=%s\n", startTime.Format("2006-01-02T15:04:05.999Z07:00"))},
}
for _, tc := range tests {
......
......@@ -88,5 +88,5 @@ func TestRecordingCoreWith(t *testing.T) {
logger = logger.With("key", "value")
logger.Debug("message")
gt.Expect(recorder).To(gbytes.Say(`message {"key": "value"}`))
gt.Expect(recorder).To(gbytes.Say(`message key=value`))
}
......@@ -64,6 +64,23 @@ func TestGlobalInitJSON(t *testing.T) {
assert.Regexp(t, `{"level":"debug","ts":\d+.\d+,"name":"testlogger","caller":"flogging/global_test.go:\d+","msg":"this is a message"}\s+`, buf.String())
}
func TestGlobalInitLogfmt(t *testing.T) {
flogging.Reset()
defer flogging.Reset()
buf := &bytes.Buffer{}
flogging.Init(flogging.Config{
Format: "logfmt",
LogSpec: "DEBUG",
Writer: buf,
})
logger := flogging.MustGetLogger("testlogger")
logger.Debug("this is a message")
assert.Regexp(t, `^ts=\d+.\d+ level=debug name=testlogger caller=flogging/global_test.go:\d+ msg="this is a message"`, buf.String())
}
func TestGlobalInitPanic(t *testing.T) {
flogging.Reset()
defer flogging.Reset()
......
......@@ -14,6 +14,7 @@ import (
"github.com/hyperledger/fabric/common/flogging/fabenc"
logging "github.com/op/go-logging"
zaplogfmt "github.com/sykesm/zap-logfmt"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
......@@ -101,9 +102,10 @@ func (s *Logging) Apply(c Config) error {
s.SetWriter(c.Writer)
var formatter logging.Formatter
if s.Encoding() == JSON {
switch s.Encoding() {
case JSON, LOGFMT:
formatter = SetFormat(defaultFormat)
} else {
default:
formatter = SetFormat(c.Format)
}
......@@ -128,6 +130,11 @@ func (s *Logging) SetFormat(format string) error {
return nil
}
if format == "logfmt" {
s.encoding = LOGFMT
return nil
}
formatters, err := fabenc.ParseFormat(format)
if err != nil {
return err
......@@ -214,6 +221,7 @@ func (s *Logging) ZapLogger(name string) *zap.Logger {
Encoders: map[Encoding]zapcore.Encoder{
JSON: zapcore.NewJSONEncoder(s.encoderConfig),
CONSOLE: fabenc.NewFormatEncoder(s.multiFormatter),
LOGFMT: zaplogfmt.NewEncoder(s.encoderConfig),
},
Selector: s,
Output: s,
......
......@@ -33,15 +33,15 @@ func TestFabricLoggerEncoding(t *testing.T) {
buf.Reset()
fl.Info("string value", 0, 1.23, struct{}{})
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string value 0 1.23 {} {\"extra\": \"field\"}\n", buf.String())
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string value 0 1.23 {} extra=field\n", buf.String())
buf.Reset()
fl.Infof("string %s, %d, %.3f, %v", "strval", 0, 1.23, struct{}{})
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string strval, 0, 1.230, {} {\"extra\": \"field\"}\n", buf.String())
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string strval, 0, 1.230, {} extra=field\n", buf.String())
buf.Reset()
fl.Infow("this is a message", "int", 0, "float", 1.23, "struct", struct{}{})
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m this is a message {\"extra\": \"field\", \"int\": 0, \"float\": 1.23, \"struct\": {}}\n", buf.String())
assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m this is a message extra=field int=0 float=1.23 struct={}\n", buf.String())
}
func TestFabricLogger(t *testing.T) {
......
The MIT License (MIT)
Copyright (c) 2017 Jonathan Sternberg
Copyright (c) 2019 Matthew Sykes
Permission is hereby granted, free of charge, to any person obtaining a copy of
this software and associated documentation files (the "Software"), to deal in
the Software without restriction, including without limitation the rights to
use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of
the Software, and to permit persons to whom the Software is furnished to do so,
subject to the following conditions:
The above copyright notice and this permission notice shall be included in all
copies or substantial portions of the Software.
THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS
FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER
IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
// Package zaplogfmt provides a zap encoder that formats log entries in
// "logfmt" format.
package zaplogfmt
import (
"bytes"
"encoding"
"encoding/base64"
"fmt"
"math"
"reflect"
"strings"
"sync"
"time"
"unicode/utf8"
"go.uber.org/zap/buffer"
"go.uber.org/zap/zapcore"
)
var (
logfmtPool = sync.Pool{
New: func() interface{} { return &logfmtEncoder{} },
}
bufferpool = buffer.NewPool()
)
func getEncoder() *logfmtEncoder {
return logfmtPool.Get().(*logfmtEncoder)
}
func putEncoder(enc *logfmtEncoder) {
enc.EncoderConfig = nil
enc.buf = nil
enc.namespaces = nil
enc.arrayLiteral = false
logfmtPool.Put(enc)
}
type logfmtEncoder struct {
*zapcore.EncoderConfig
buf *buffer.Buffer
namespaces []string
arrayLiteral bool
}
// NewEncoder creates an encoder writes logfmt formatted log entries.
func NewEncoder(cfg zapcore.EncoderConfig) zapcore.Encoder {
return &logfmtEncoder{
EncoderConfig: &cfg,
buf: bufferpool.Get(),
}
}
func (enc *logfmtEncoder) AddArray(key string, arr zapcore.ArrayMarshaler) error {
enc.addKey(key)
return enc.AppendArray(arr)
}
func (enc *logfmtEncoder) AddBinary(key string, value []byte) {
enc.AddString(key, base64.StdEncoding.EncodeToString(value))
}
func (enc *logfmtEncoder) AddBool(key string, value bool) {
enc.addKey(key)
enc.AppendBool(value)
}
func (enc *logfmtEncoder) AddByteString(key string, value []byte) {
enc.addKey(key)
enc.AppendByteString(value)
}
func (enc *logfmtEncoder) AddComplex64(k string, v complex64) { enc.AddComplex128(k, complex128(v)) }
func (enc *logfmtEncoder) AddComplex128(key string, value complex128) {
enc.addKey(key)
enc.AppendComplex128(value)
}
func (enc *logfmtEncoder) AddDuration(key string, value time.Duration) {
enc.addKey(key)
enc.AppendDuration(value)
}
func (enc *logfmtEncoder) AddFloat32(key string, value float32) {
enc.addKey(key)
enc.AppendFloat32(value)
}
func (enc *logfmtEncoder) AddFloat64(key string, value float64) {
enc.addKey(key)
enc.AppendFloat64(value)
}
func (enc *logfmtEncoder) AddInt(k string, v int) { enc.AddInt64(k, int64(v)) }
func (enc *logfmtEncoder) AddInt8(k string, v int8) { enc.AddInt64(k, int64(v)) }
func (enc *logfmtEncoder) AddInt32(k string, v int32) { enc.AddInt64(k, int64(v)) }
func (enc *logfmtEncoder) AddInt16(k string, v int16) { enc.AddInt64(k, int64(v)) }
func (enc *logfmtEncoder) AddInt64(key string, value int64) {
enc.addKey(key)
enc.AppendInt64(value)
}
func (enc *logfmtEncoder) AddObject(key string, obj zapcore.ObjectMarshaler) error {
enc.addKey(key)
return enc.AppendObject(obj)
}
func (enc *logfmtEncoder) AddReflected(key string, value interface{}) error {
enc.addKey(key)
return enc.AppendReflected(value)
}
func (enc *logfmtEncoder) AddString(key, value string) {
enc.addKey(key)
enc.AppendString(value)
}
func (enc *logfmtEncoder) AddTime(key string, value time.Time) {
enc.addKey(key)
enc.AppendTime(value)
}
func (enc *logfmtEncoder) AddUint(k string, v uint) { enc.AddUint64(k, uint64(v)) }
func (enc *logfmtEncoder) AddUint8(k string, v uint8) { enc.AddUint64(k, uint64(v)) }
func (enc *logfmtEncoder) AddUint32(k string, v uint32) { enc.AddUint64(k, uint64(v)) }
func (enc *logfmtEncoder) AddUint16(k string, v uint16) { enc.AddUint64(k, uint64(v)) }
func (enc *logfmtEncoder) AddUintptr(k string, v uintptr) { enc.AddUint64(k, uint64(v)) }
func (enc *logfmtEncoder) AddUint64(key string, value uint64) {
enc.addKey(key)
enc.AppendUint64(value)
}
func (enc *logfmtEncoder) AppendArray(arr zapcore.ArrayMarshaler) error {
marshaler := enc.clone()
marshaler.namespaces = nil
marshaler.arrayLiteral = true
marshaler.buf.AppendByte('[')
err := arr.MarshalLogArray(marshaler)
if err == nil {
marshaler.buf.AppendByte(']')
enc.AppendByteString(marshaler.buf.Bytes())
} else {
enc.AppendByteString(nil)
}
marshaler.buf.Free()
putEncoder(marshaler)
return err
}
func (enc *logfmtEncoder) AppendBool(value bool) {
if value {
enc.AppendString("true")
} else {
enc.AppendString("false")
}
}
func (enc *logfmtEncoder) AppendByteString(value []byte) {
enc.addSeparator()
needsQuotes := bytes.IndexFunc(value, needsQuotedValueRune) != -1
if needsQuotes {
enc.buf.AppendByte('"')
}
enc.safeAddByteString(value)
if needsQuotes {
enc.buf.AppendByte('"')
}
}
func (enc *logfmtEncoder) AppendComplex64(v complex64) { enc.AppendComplex128(complex128(v)) }
func (enc *logfmtEncoder) AppendComplex128(value complex128) {
enc.addSeparator()
// Cast to a platform-independent, fixed-size type.
r, i := float64(real(value)), float64(imag(value))
enc.buf.AppendFloat(r, 64)
enc.buf.AppendByte('+')
enc.buf.AppendFloat(i, 64)
enc.buf.AppendByte('i')
}
func (enc *logfmtEncoder) AppendDuration(value time.Duration) {
cur := enc.buf.Len()
if enc.EncodeDuration != nil {
enc.EncodeDuration(value, enc)
}
if cur == enc.buf.Len() {
enc.AppendInt64(int64(value))
}
}
func (enc *logfmtEncoder) AppendFloat32(v float32) { enc.appendFloat(float64(v), 32) }
func (enc *logfmtEncoder) AppendFloat64(v float64) { enc.appendFloat(v, 64) }
func (enc *logfmtEncoder) appendFloat(val float64, bitSize int) {
enc.addSeparator()
switch {
case math.IsNaN(val):
enc.buf.AppendString(`NaN`)
case math.IsInf(val, 1):
enc.buf.AppendString(`+Inf`)
case math.IsInf(val, -1):
enc.buf.AppendString(`-Inf`)
default:
enc.buf.AppendFloat(val, bitSize)
}
}
func (enc *logfmtEncoder) AppendInt(v int) { enc.AppendInt64(int64(v)) }
func (enc *logfmtEncoder) AppendInt8(v int8) { enc.AppendInt64(int64(v)) }
func (enc *logfmtEncoder) AppendInt16(v int16) { enc.AppendInt64(int64(v)) }
func (enc *logfmtEncoder) AppendInt32(v int32) { enc.AppendInt64(int64(v)) }
func (enc *logfmtEncoder) AppendInt64(value int64) {
enc.addSeparator()
enc.buf.AppendInt(value)
}
func (enc *logfmtEncoder) AppendObject(obj zapcore.ObjectMarshaler) error {
marshaler := enc.clone()
marshaler.namespaces = nil
err := obj.MarshalLogObject(marshaler)
if err == nil {
enc.AppendByteString(marshaler.buf.Bytes())
} else {
enc.AppendByteString(nil)
}
marshaler.buf.Free()
putEncoder(marshaler)
return err
}
func (enc *logfmtEncoder) AppendReflected(value interface{}) error {
switch v := value.(type) {
case nil:
enc.AppendString("null")
case error:
enc.AppendString(v.Error())
case []byte:
enc.AppendByteString(v)
case fmt.Stringer:
enc.AppendString(v.String())
case encoding.TextMarshaler:
b, err := v.MarshalText()
if err != nil {
return err
}
enc.AppendString(string(b))
default:
rvalue := reflect.ValueOf(value)
switch rvalue.Kind() {
case reflect.Bool:
enc.AppendBool(rvalue.Bool())
case reflect.Int, reflect.Int8, reflect.Int16, reflect.Int32, reflect.Int64:
enc.AppendInt64(rvalue.Int())
case reflect.Uint, reflect.Uint8, reflect.Uint16, reflect.Uint32, reflect.Uint64, reflect.Uintptr:
enc.AppendUint64(rvalue.Uint())
case reflect.Float32:
enc.appendFloat(rvalue.Float(), 32)
case reflect.Float64:
enc.AppendFloat64(rvalue.Float())
case reflect.String:
enc.AppendString(rvalue.String())
case reflect.Complex64, reflect.Complex128:
enc.AppendComplex128(rvalue.Complex())
case reflect.Chan, reflect.Func:
enc.AppendString(fmt.Sprintf("%T(%p)", value, value))
case reflect.Map, reflect.Struct:
enc.AppendString(fmt.Sprint(value))
case reflect.Array, reflect.Slice:
enc.AppendArray(zapcore.ArrayMarshalerFunc(func(ae zapcore.ArrayEncoder) error {
for i := 0; i < rvalue.Len(); i++ {
ae.AppendReflected(rvalue.Index(i).Interface())
}
return nil
}))
case reflect.Interface, reflect.Ptr:
return enc.AppendReflected(rvalue.Elem().Interface())
}
}
return nil
}
func (enc *logfmtEncoder) AppendString(value string) {
enc.addSeparator()
needsQuotes := strings.IndexFunc(value, needsQuotedValueRune) != -1
if needsQuotes {
enc.buf.AppendByte('"')
}
enc.safeAddString(value)
if needsQuotes {
enc.buf.AppendByte('"')
}
}
func (enc *logfmtEncoder) AppendTime(value time.Time) {
cur := enc.buf.Len()
if enc.EncodeTime != nil {
enc.EncodeTime(value, enc)
}
if cur == enc.buf.Len() {
enc.AppendInt64(value.UnixNano())
}
}
func (enc *logfmtEncoder) AppendUint(v uint) { enc.AppendUint64(uint64(v)) }
func (enc *logfmtEncoder) AppendUint8(v uint8) { enc.AppendUint64(uint64(v)) }
func (enc *logfmtEncoder) AppendUint16(v uint16) { enc.AppendUint64(uint64(v)) }
func (enc *logfmtEncoder) AppendUint32(v uint32) { enc.AppendUint64(uint64(v)) }
func (enc *logfmtEncoder) AppendUintptr(v uintptr) { enc.AppendUint64(uint64(v)) }
func (enc *logfmtEncoder) AppendUint64(value uint64) {
enc.addSeparator()
enc.buf.AppendUint(value)
}
func (enc *logfmtEncoder) Clone() zapcore.Encoder {
clone := enc.clone()
clone.buf.Write(enc.buf.Bytes())
return clone
}
func (enc *logfmtEncoder) clone() *logfmtEncoder {
clone := getEncoder()
clone.EncoderConfig = enc.EncoderConfig
clone.buf = bufferpool.Get()
clone.namespaces = enc.namespaces
return clone
}
func (enc *logfmtEncoder) OpenNamespace(key string) {
key = strings.Map(keyRuneFilter, key)
enc.namespaces = append(enc.namespaces, key)
}
func (enc *logfmtEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) {
final := enc.clone()
if final.TimeKey != "" {
final.AddTime(final.TimeKey, ent.Time)
}
if final.LevelKey != "" {
final.addKey(final.LevelKey)
cur := final.buf.Len()
if final.EncodeLevel != nil {
final.EncodeLevel(ent.Level, final)
}
if cur == final.buf.Len() {
// User-supplied EncodeLevel was a no-op. Fall back to strings to keep
// output valid.
final.AppendString(ent.Level.String())
}
}
if ent.LoggerName != "" && final.NameKey != "" {
final.addKey(final.NameKey)
cur := final.buf.Len()
if final.EncodeName != nil {
final.EncodeName(ent.LoggerName, final)
}
if cur == final.buf.Len() {
// User-supplied EncodeName was a no-op. Fall back to strings to
// keep output valid.
final.AppendString(ent.LoggerName)
}
}
if ent.Caller.Defined && final.CallerKey != "" {
final.addKey(final.CallerKey)
cur := final.buf.Len()
if final.EncodeCaller != nil {
final.EncodeCaller(ent.Caller, final)
}
if cur == final.buf.Len() {
// User-supplied EncodeCaller was a no-op. Fall back to strings to
// keep output valid.
final.AppendString(ent.Caller.String())
}
}
if final.MessageKey != "" {
final.addKey(enc.MessageKey)
final.AppendString(ent.Message)
}
if enc.buf.Len() > 0 {
if final.buf.Len() > 0 {
final.buf.AppendByte(' ')
}