339 lines
11 KiB
Go
339 lines
11 KiB
Go
/*
|
|
Copyright IBM Corp. All Rights Reserved.
|
|
|
|
SPDX-License-Identifier: Apache-2.0
|
|
*/
|
|
|
|
package flogging_test
|
|
|
|
import (
|
|
"bytes"
|
|
"errors"
|
|
"io/ioutil"
|
|
"testing"
|
|
|
|
"github.com/hyperledger/fabric/common/flogging"
|
|
"github.com/hyperledger/fabric/common/flogging/fabenc"
|
|
"github.com/hyperledger/fabric/common/flogging/mock"
|
|
"github.com/stretchr/testify/require"
|
|
"go.uber.org/zap"
|
|
"go.uber.org/zap/zapcore"
|
|
"go.uber.org/zap/zaptest/observer"
|
|
"google.golang.org/grpc/grpclog"
|
|
)
|
|
|
|
func TestFabricLoggerEncoding(t *testing.T) {
|
|
formatters, err := fabenc.ParseFormat("%{color}[%{module}] %{shortfunc} -> %{level:.4s}%{color:reset} %{message}")
|
|
require.NoError(t, err)
|
|
enc := fabenc.NewFormatEncoder(formatters...)
|
|
|
|
buf := &bytes.Buffer{}
|
|
core := zapcore.NewCore(enc, zapcore.AddSync(buf), zap.NewAtomicLevel())
|
|
zl := flogging.NewZapLogger(core).Named("test").With(zap.String("extra", "field"))
|
|
fl := flogging.NewFabricLogger(zl)
|
|
|
|
buf.Reset()
|
|
fl.Info("string value", 0, 1.23, struct{}{})
|
|
require.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{}{})
|
|
require.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{}{})
|
|
require.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) {
|
|
var enabler zap.LevelEnablerFunc = func(l zapcore.Level) bool { return true }
|
|
|
|
tests := []struct {
|
|
desc string
|
|
f func(fl *flogging.FabricLogger)
|
|
level zapcore.Level
|
|
message string
|
|
fields []zapcore.Field
|
|
panics bool
|
|
}{
|
|
{
|
|
desc: "DPanic",
|
|
f: func(fl *flogging.FabricLogger) { fl.DPanic("arg1", "arg2") },
|
|
level: zapcore.DPanicLevel,
|
|
message: "arg1 arg2",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "DPanicf",
|
|
f: func(fl *flogging.FabricLogger) { fl.DPanicf("panic: %s, %d", "reason", 99) },
|
|
level: zapcore.DPanicLevel,
|
|
message: "panic: reason, 99",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "DPanicw",
|
|
f: func(fl *flogging.FabricLogger) { fl.DPanicw("I'm in a panic", "reason", "something", "code", 99) },
|
|
level: zapcore.DPanicLevel,
|
|
message: "I'm in a panic",
|
|
fields: []zapcore.Field{zap.String("reason", "something"), zap.Int("code", 99)},
|
|
},
|
|
{
|
|
desc: "Debug",
|
|
f: func(fl *flogging.FabricLogger) { fl.Debug("arg1", "arg2") },
|
|
level: zapcore.DebugLevel,
|
|
message: "arg1 arg2",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Debugf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Debugf("debug: %s, %d", "goo", 99) },
|
|
level: zapcore.DebugLevel,
|
|
message: "debug: goo, 99",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Debugw",
|
|
f: func(fl *flogging.FabricLogger) { fl.Debugw("debug data", "key", "value") },
|
|
level: zapcore.DebugLevel,
|
|
message: "debug data",
|
|
fields: []zapcore.Field{zap.String("key", "value")},
|
|
},
|
|
{
|
|
desc: "Error",
|
|
f: func(fl *flogging.FabricLogger) { fl.Error("oh noes", errors.New("bananas")) },
|
|
level: zapcore.ErrorLevel,
|
|
message: "oh noes bananas",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Errorf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Errorf("error: %s", errors.New("bananas")) },
|
|
level: zapcore.ErrorLevel,
|
|
message: "error: bananas",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Errorw",
|
|
f: func(fl *flogging.FabricLogger) { fl.Errorw("something failed", "err", errors.New("bananas")) },
|
|
level: zapcore.ErrorLevel,
|
|
message: "something failed",
|
|
fields: []zapcore.Field{zap.NamedError("err", errors.New("bananas"))},
|
|
},
|
|
{
|
|
desc: "Info",
|
|
f: func(fl *flogging.FabricLogger) { fl.Info("fyi", "things are great") },
|
|
level: zapcore.InfoLevel,
|
|
message: "fyi things are great",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Infof",
|
|
f: func(fl *flogging.FabricLogger) { fl.Infof("fyi: %s", "things are great") },
|
|
level: zapcore.InfoLevel,
|
|
message: "fyi: things are great",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Infow",
|
|
f: func(fl *flogging.FabricLogger) { fl.Infow("fyi", "fish", "are smelly", "fruit", "is sweet") },
|
|
level: zapcore.InfoLevel,
|
|
message: "fyi",
|
|
fields: []zapcore.Field{zap.String("fish", "are smelly"), zap.String("fruit", "is sweet")},
|
|
},
|
|
{
|
|
desc: "Panic",
|
|
f: func(fl *flogging.FabricLogger) { fl.Panic("oh noes", errors.New("platypus")) },
|
|
level: zapcore.PanicLevel,
|
|
message: "oh noes platypus",
|
|
fields: []zapcore.Field{},
|
|
panics: true,
|
|
},
|
|
{
|
|
desc: "Panicf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Panicf("error: %s", errors.New("platypus")) },
|
|
level: zapcore.PanicLevel,
|
|
message: "error: platypus",
|
|
fields: []zapcore.Field{},
|
|
panics: true,
|
|
},
|
|
{
|
|
desc: "Panicw",
|
|
f: func(fl *flogging.FabricLogger) { fl.Panicw("something failed", "err", errors.New("platypus")) },
|
|
level: zapcore.PanicLevel,
|
|
message: "something failed",
|
|
fields: []zapcore.Field{zap.NamedError("err", errors.New("platypus"))},
|
|
panics: true,
|
|
},
|
|
{
|
|
desc: "Warn",
|
|
f: func(fl *flogging.FabricLogger) { fl.Warn("oh noes", errors.New("monkeys")) },
|
|
level: zapcore.WarnLevel,
|
|
message: "oh noes monkeys",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Warnf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Warnf("error: %s", errors.New("monkeys")) },
|
|
level: zapcore.WarnLevel,
|
|
message: "error: monkeys",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Warnw",
|
|
f: func(fl *flogging.FabricLogger) { fl.Warnw("something is weird", "err", errors.New("monkeys")) },
|
|
level: zapcore.WarnLevel,
|
|
message: "something is weird",
|
|
fields: []zapcore.Field{zap.NamedError("err", errors.New("monkeys"))},
|
|
},
|
|
{
|
|
desc: "Warning",
|
|
f: func(fl *flogging.FabricLogger) { fl.Warning("oh noes", errors.New("monkeys")) },
|
|
level: zapcore.WarnLevel,
|
|
message: "oh noes monkeys",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Warningf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Warningf("error: %s", errors.New("monkeys")) },
|
|
level: zapcore.WarnLevel,
|
|
message: "error: monkeys",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "With",
|
|
f: func(fl *flogging.FabricLogger) { fl.With("key", "value").Debug("cool messages", "and stuff") },
|
|
level: zapcore.DebugLevel,
|
|
message: "cool messages and stuff",
|
|
fields: []zapcore.Field{zap.String("key", "value")},
|
|
},
|
|
{
|
|
desc: "WithOptions",
|
|
f: func(fl *flogging.FabricLogger) {
|
|
fl.WithOptions(zap.Fields(zap.String("optionkey", "optionvalue"))).Debug("cool messages", "and stuff")
|
|
},
|
|
level: zapcore.DebugLevel,
|
|
message: "cool messages and stuff",
|
|
fields: []zapcore.Field{zap.String("optionkey", "optionvalue")},
|
|
},
|
|
{
|
|
desc: "Critical",
|
|
f: func(fl *flogging.FabricLogger) { fl.Critical("critical as error", errors.New("kiwi")) },
|
|
level: zapcore.ErrorLevel,
|
|
message: "critical as error kiwi",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Criticalf",
|
|
f: func(fl *flogging.FabricLogger) { fl.Criticalf("critical: %s", errors.New("kiwi")) },
|
|
level: zapcore.ErrorLevel,
|
|
message: "critical: kiwi",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Notice",
|
|
f: func(fl *flogging.FabricLogger) { fl.Notice("notice", "as info") },
|
|
level: zapcore.InfoLevel,
|
|
message: "notice as info",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
{
|
|
desc: "Noticef",
|
|
f: func(fl *flogging.FabricLogger) { fl.Noticef("notice: %s", "this is info") },
|
|
level: zapcore.InfoLevel,
|
|
message: "notice: this is info",
|
|
fields: []zapcore.Field{},
|
|
},
|
|
}
|
|
|
|
for _, tc := range tests {
|
|
t.Run(tc.desc, func(t *testing.T) {
|
|
core, logs := observer.New(enabler)
|
|
fl := flogging.NewFabricLogger(zap.New(core)).Named("lname")
|
|
|
|
if tc.panics {
|
|
require.Panics(t, func() { tc.f(fl) })
|
|
} else {
|
|
tc.f(fl)
|
|
}
|
|
|
|
err := fl.Sync()
|
|
require.NoError(t, err)
|
|
|
|
entries := logs.All()
|
|
require.Len(t, entries, 1)
|
|
entry := entries[0]
|
|
|
|
require.Equal(t, tc.level, entry.Level)
|
|
require.Equal(t, tc.message, entry.Message)
|
|
require.Equal(t, tc.fields, entry.Context)
|
|
require.Equal(t, "lname", entry.LoggerName)
|
|
})
|
|
}
|
|
}
|
|
|
|
func TestIsEnabledFor(t *testing.T) {
|
|
formatters, err := fabenc.ParseFormat("%{color}[%{module}] %{shortfunc} -> %{level:.4s}%{color:reset} %{message}")
|
|
require.NoError(t, err)
|
|
enc := fabenc.NewFormatEncoder(formatters...)
|
|
|
|
enablerCallCount := 0
|
|
enabler := zap.LevelEnablerFunc(func(l zapcore.Level) bool {
|
|
enablerCallCount++
|
|
return l == zapcore.ErrorLevel
|
|
})
|
|
|
|
core := zapcore.NewCore(enc, zapcore.AddSync(ioutil.Discard), enabler)
|
|
zl := zap.New(core).Named("test")
|
|
fl := flogging.NewFabricLogger(zl)
|
|
|
|
require.True(t, fl.IsEnabledFor(zapcore.ErrorLevel))
|
|
require.False(t, fl.IsEnabledFor(zapcore.PanicLevel))
|
|
require.Equal(t, 2, enablerCallCount)
|
|
}
|
|
|
|
func logCaller(l grpclog.Logger, msg string) { l.Println(msg) }
|
|
func callWrapper(l grpclog.Logger, msg string) { logCaller(l, msg) }
|
|
|
|
func TestGRPCLogger(t *testing.T) {
|
|
// ensure it includes the name as module, logs at debug level, and the caller with appropriate skip level
|
|
formatters, err := fabenc.ParseFormat("%{module} %{level} %{shortfunc} %{message}")
|
|
require.NoError(t, err)
|
|
enc := fabenc.NewFormatEncoder(formatters...)
|
|
|
|
buf := &bytes.Buffer{}
|
|
enabler := zap.LevelEnablerFunc(func(l zapcore.Level) bool { return true })
|
|
core := zapcore.NewCore(enc, zapcore.AddSync(buf), enabler)
|
|
zl := zap.New(core).Named("grpc")
|
|
gl := flogging.NewGRPCLogger(zl)
|
|
|
|
callWrapper(gl, "message")
|
|
require.Equal(t, "grpc DEBUG TestGRPCLogger message\n", buf.String())
|
|
}
|
|
|
|
// FAB-15432
|
|
//
|
|
// When the FabricLogger is used, the zap Core check function should not be
|
|
// driven if the minimum log level is above the level we are logging at.
|
|
// In other words, with a log spec of "info", logging at Debug should prevent
|
|
// a call to Check while logging at Info will not.
|
|
func TestEnabledLevelCheck(t *testing.T) {
|
|
buf := &bytes.Buffer{}
|
|
logging, err := flogging.New(flogging.Config{
|
|
LogSpec: "info",
|
|
Writer: buf,
|
|
})
|
|
require.NoError(t, err)
|
|
|
|
fakeObserver := &mock.Observer{}
|
|
logging.SetObserver(fakeObserver)
|
|
|
|
logger := logging.ZapLogger("foo")
|
|
fabricLogger := flogging.NewFabricLogger(logger)
|
|
|
|
fabricLogger.Debug("debug message")
|
|
require.Equal(t, 0, fakeObserver.CheckCallCount(), "Check should not have been called")
|
|
|
|
fabricLogger.Info("info message")
|
|
require.Equal(t, 1, fakeObserver.CheckCallCount(), "Check should have been called")
|
|
}
|