Commit 97215fa6 authored by Matthew Sykes's avatar Matthew Sykes
Browse files

[FAB-9131] wire zap based fabric logger



Replace go-logging with a zap based implementation. The implementation
is mostly compatible with the legacy format but differs in a two key
ways:

1. CRITICAL and NOTICE log levels no longer exist. Calls to Critical get
   mapped to error and NOTICE gets mapped to INFO. The methods
   associated with these levels will be removed in a future CR.
2. The log level constants are now sourced from the zap/zapcore packages.
   These values are incompatible wit the go-logging constants. Please be
   sure to use the appropriate constant when necessary.

The existing go-logging package is still used by the chaincode shim to
reduce the risk of negatively impacting legacy chaincode.

Change-Id: Iaf5fac807244883a8285892ccd350c5256959782
Signed-off-by: default avatarMatthew Sykes <sykesmat@us.ibm.com>
parent bb90ac40
......@@ -41,7 +41,6 @@ import (
"github.com/hyperledger/fabric/bccsp/signer"
"github.com/hyperledger/fabric/bccsp/sw"
"github.com/hyperledger/fabric/bccsp/utils"
"github.com/op/go-logging"
"github.com/stretchr/testify/assert"
"golang.org/x/crypto/sha3"
)
......@@ -59,9 +58,6 @@ type testConfig struct {
}
func TestMain(m *testing.M) {
// Activate DEBUG level to cover listAttrs function
logging.SetLevel(logging.DEBUG, "bccsp_p11")
ks, err := sw.NewFileBasedKeyStore(nil, os.TempDir(), false)
if err != nil {
fmt.Printf("Failed initiliazing KeyStore [%s]", err)
......
......@@ -17,7 +17,7 @@ import (
"sync"
"github.com/miekg/pkcs11"
"github.com/op/go-logging"
"go.uber.org/zap/zapcore"
)
func loadLib(lib, pin, label string) (*pkcs11.Ctx, uint, *pkcs11.SessionHandle, error) {
......@@ -290,7 +290,7 @@ func (csp *impl) generateECKey(curve asn1.ObjectIdentifier, ephemeral bool) (ski
pubGoKey := &ecdsa.PublicKey{Curve: nistCurve, X: x, Y: y}
if logger.IsEnabledFor(logging.DEBUG) {
if logger.IsEnabledFor(zapcore.DebugLevel) {
listAttrs(p11lib, session, prv)
listAttrs(p11lib, session, pub)
}
......
......@@ -11,14 +11,9 @@ import (
cb "github.com/hyperledger/fabric/protos/common"
"github.com/op/go-logging"
"github.com/stretchr/testify/assert"
)
func init() {
logging.SetLevel(logging.DEBUG, pkgLogID)
}
func TestSatisfied(t *testing.T) {
var capsMap map[string]*cb.Capability
for _, provider := range []*registry{
......
......@@ -14,8 +14,7 @@ import (
"github.com/hyperledger/fabric/msp"
cb "github.com/hyperledger/fabric/protos/common"
mb "github.com/hyperledger/fabric/protos/msp"
"github.com/op/go-logging"
"go.uber.org/zap/zapcore"
)
var cauthdslLogger = flogging.MustGetLogger("cauthdsl")
......@@ -93,7 +92,7 @@ func compile(policy *cb.SignaturePolicy, identities []*mb.MSPPrincipal, deserial
cauthdslLogger.Debugf("%p skipping identity %d because it has already been used", signedData, i)
continue
}
if cauthdslLogger.IsEnabledFor(logging.DEBUG) {
if cauthdslLogger.IsEnabledFor(zapcore.DebugLevel) {
// Unlike most places, this is a huge print statement, and worth checking log level before create garbage
cauthdslLogger.Debugf("%p processing identity %d with bytes of %x", signedData, i, sd.Identity)
}
......
......@@ -14,17 +14,13 @@ import (
"github.com/golang/protobuf/proto"
"github.com/hyperledger/fabric/common/flogging"
"github.com/hyperledger/fabric/common/flogging/floggingtest"
"github.com/hyperledger/fabric/msp"
cb "github.com/hyperledger/fabric/protos/common"
mb "github.com/hyperledger/fabric/protos/msp"
logging "github.com/op/go-logging"
"github.com/stretchr/testify/assert"
)
func init() {
logging.SetLevel(logging.DEBUG, "")
}
var invalidSignature = []byte("badsigned")
type mockIdentity struct {
......@@ -289,13 +285,11 @@ func TestDeserializeIdentityError(t *testing.T) {
spe, err := compile(policy.Rule, policy.Identities, &mockDeserializer{fail: errors.New("myError")})
assert.NoError(t, err)
// Let logger output to buf
var buf bytes.Buffer
backend := logging.NewLogBackend(&buf, "", 0)
cauthdslLogger.SetBackend(logging.AddModuleLevel(backend))
defer func() {
flogging.Reset()
}()
logger, recorder := floggingtest.NewTestLogger(t)
defer func(old *flogging.FabricLogger) {
cauthdslLogger = old
}(cauthdslLogger)
cauthdslLogger = logger
// Call
signedData, used := toSignedData([][]byte{nil}, [][]byte{nil}, [][]byte{nil})
......@@ -303,5 +297,5 @@ func TestDeserializeIdentityError(t *testing.T) {
// Check result (ret and log)
assert.False(t, ret)
assert.Contains(t, buf.String(), "Principal deserialization failure (myError) for identity ")
assert.Contains(t, string(recorder.Buffer().Contents()), "Principal deserialization failure (myError) for identity")
}
......@@ -15,13 +15,8 @@ import (
"github.com/golang/protobuf/proto"
. "github.com/onsi/gomega"
logging "github.com/op/go-logging"
)
func init() {
logging.SetLevel(logging.DEBUG, "")
}
func TestApplicationInterface(t *testing.T) {
_ = Application((*ApplicationConfig)(nil))
}
......
......@@ -12,7 +12,6 @@ import (
cb "github.com/hyperledger/fabric/protos/common"
pb "github.com/hyperledger/fabric/protos/peer"
logging "github.com/op/go-logging"
"github.com/pkg/errors"
)
......@@ -69,8 +68,6 @@ func (aog *ApplicationOrgConfig) AnchorPeers() []*pb.AnchorPeer {
}
func (aoc *ApplicationOrgConfig) Validate() error {
if logger.IsEnabledFor(logging.DEBUG) {
logger.Debugf("Anchor peers for org %s are %v", aoc.name, aoc.protos.AnchorPeers)
}
logger.Debugf("Anchor peers for org %s are %v", aoc.name, aoc.protos.AnchorPeers)
return aoc.OrganizationConfig.Validate()
}
......@@ -15,14 +15,9 @@ import (
"github.com/hyperledger/fabric/common/util"
cb "github.com/hyperledger/fabric/protos/common"
logging "github.com/op/go-logging"
"github.com/stretchr/testify/assert"
)
func init() {
logging.SetLevel(logging.DEBUG, "")
}
func TestInterface(t *testing.T) {
_ = Channel(&ChannelConfig{})
}
......
......@@ -11,14 +11,9 @@ import (
ab "github.com/hyperledger/fabric/protos/orderer"
logging "github.com/op/go-logging"
"github.com/stretchr/testify/assert"
)
func init() {
logging.SetLevel(logging.DEBUG, "")
}
func TestBatchSize(t *testing.T) {
validMaxMessageCount := uint32(10)
validAbsoluteMaxBytes := uint32(1000)
......
......@@ -11,14 +11,9 @@ import (
cb "github.com/hyperledger/fabric/protos/common"
logging "github.com/op/go-logging"
"github.com/stretchr/testify/assert"
)
func init() {
logging.SetLevel(logging.DEBUG, "")
}
func TestBadKey(t *testing.T) {
assert.Error(t, addToMap(comparable{key: "[Label]", path: []string{}}, make(map[string]comparable)),
"Should have errored on key with illegal characters")
......
/*
Copyright IBM Corp. All Rights Reserved.
SPDX-License-Identifier: Apache-2.0
*/
package flogging
import (
"go.uber.org/zap/zapcore"
)
type Encoding int8
const (
CONSOLE = iota
JSON
)
// EncodingSelector is used to determine whether log records are
// encoded as JSON or in a human readable CONSOLE format.
type EncodingSelector interface {
Encoding() Encoding
}
// Core is a custom implementation of a zapcore.Core. It's a terrible hack that
// only exists to work around the intersection of state associated with
// encoders, implementation hiding in zapcore, and implicit, ad-hoc logger
// initialization within fabric.
//
// In addition to encoding log entries and fields to a buffer, zap Encoder
// implementations also need to maintain field state. When zapcore.Core.With is
// used, the associated encoder is cloned and the fields are added to the
// encoder. This means that encoder instances cannot be shared across cores.
//
// In terms of implementation hiding, it's difficult for our FormatEncoder to
// cleanly wrap the JSON and console implementations from zap as all methods
// from the zapcore.ObjectEncoder would need to be implemented to delegate to
// the correct backend.
//
// Finally, fabric logging can go through initialization multiple times. The
// first is via package initialization where hard-coded defaults are used for
// configuration. The second init is typically after any process configuration
// has been processed. This configuration can come from environment variables,
// command line flags, or config documents.
//
// Since logging can be initialized multiple times, we need to be able to
// handle modification of the type of encoders we are using. While, for legacy
// reasons, a console based encoder is the default, a JSON logger is more likely
// to be desired in production.
//
// This implementation works by associating multiple encoders with a core. When
// fields are added to the core, the fields are added to all of the encoder
// implementations. The core also references the logging configuration to
// determine the proper encoding to use, the writer to delegate to, and the
// enabled levels.
type Core struct {
zapcore.LevelEnabler
Encoders map[Encoding]zapcore.Encoder
Selector EncodingSelector
Output zapcore.WriteSyncer
}
func (c *Core) With(fields []zapcore.Field) zapcore.Core {
clones := map[Encoding]zapcore.Encoder{}
for name, enc := range c.Encoders {
clone := enc.Clone()
addFields(clone, fields)
clones[name] = clone
}
return &Core{
LevelEnabler: c.LevelEnabler,
Encoders: clones,
Selector: c.Selector,
Output: c.Output,
}
}
func (c *Core) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
if c.Enabled(e.Level) {
return ce.AddCore(e, c)
}
return ce
}
func (c *Core) Write(e zapcore.Entry, fields []zapcore.Field) error {
encoding := c.Selector.Encoding()
enc := c.Encoders[encoding]
buf, err := enc.EncodeEntry(e, fields)
if err != nil {
return err
}
_, err = c.Output.Write(buf.Bytes())
buf.Free()
if err != nil {
return err
}
if e.Level >= zapcore.PanicLevel {
c.Sync()
}
return nil
}
func (c *Core) Sync() error {
return c.Output.Sync()
}
func addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) {
for i := range fields {
fields[i].AddTo(enc)
}
}
/*
Copyright IBM Corp. All Rights Reserved.
SPDX-License-Identifier: Apache-2.0
*/
package flogging_test
import (
"bytes"
"errors"
"testing"
"github.com/hyperledger/fabric/common/flogging"
"github.com/stretchr/testify/assert"
"go.uber.org/zap"
"go.uber.org/zap/buffer"
"go.uber.org/zap/zapcore"
)
func TestCoreWith(t *testing.T) {
core := &flogging.Core{
Encoders: map[flogging.Encoding]zapcore.Encoder{},
}
clone := core.With([]zapcore.Field{zap.String("key", "value")})
assert.Equal(t, core, clone)
jsonEncoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{})
consoleEncoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{})
core = &flogging.Core{
Encoders: map[flogging.Encoding]zapcore.Encoder{
flogging.JSON: jsonEncoder,
flogging.CONSOLE: consoleEncoder,
},
}
decorated := core.With([]zapcore.Field{zap.String("key", "value")})
// verify the objects differ
assert.NotEqual(t, core, decorated)
// verify the objects only differ by the encoded fields
jsonEncoder.AddString("key", "value")
consoleEncoder.AddString("key", "value")
assert.Equal(t, core, decorated)
}
func TestCoreCheck(t *testing.T) {
var enabledArgs []zapcore.Level
core := &flogging.Core{
LevelEnabler: zap.LevelEnablerFunc(func(l zapcore.Level) bool {
enabledArgs = append(enabledArgs, l)
return l != zapcore.WarnLevel
}),
}
// enabled
ce := core.Check(zapcore.Entry{Level: zapcore.DebugLevel}, nil)
assert.NotNil(t, ce)
ce = core.Check(zapcore.Entry{Level: zapcore.InfoLevel}, nil)
assert.NotNil(t, ce)
// not enabled
ce = core.Check(zapcore.Entry{Level: zapcore.WarnLevel}, nil)
assert.Nil(t, ce)
assert.Equal(t, enabledArgs, []zapcore.Level{zapcore.DebugLevel, zapcore.InfoLevel, zapcore.WarnLevel})
}
type sw struct {
bytes.Buffer
writeErr error
syncCalled bool
syncErr error
}
func (s *sw) Sync() error {
s.syncCalled = true
return s.syncErr
}
func (s *sw) Write(b []byte) (int, error) {
if s.writeErr != nil {
return 0, s.writeErr
}
return s.Buffer.Write(b)
}
func (s *sw) Encoding() flogging.Encoding {
return flogging.CONSOLE
}
func TestCoreWrite(t *testing.T) {
encoderConfig := zap.NewDevelopmentEncoderConfig()
encoderConfig.EncodeTime = nil
output := &sw{}
core := &flogging.Core{
Encoders: map[flogging.Encoding]zapcore.Encoder{
flogging.CONSOLE: zapcore.NewConsoleEncoder(encoderConfig),
},
Selector: output,
Output: output,
}
entry := zapcore.Entry{
Level: zapcore.InfoLevel,
Message: "this is a message",
}
err := core.Write(entry, nil)
assert.NoError(t, err)
assert.Equal(t, "INFO\tthis is a message\n", output.String())
output.writeErr = errors.New("super-loose")
err = core.Write(entry, nil)
assert.EqualError(t, err, "super-loose")
}
func TestCoreWriteSync(t *testing.T) {
encoderConfig := zap.NewDevelopmentEncoderConfig()
encoderConfig.EncodeTime = nil
output := &sw{}
core := &flogging.Core{
Encoders: map[flogging.Encoding]zapcore.Encoder{
flogging.CONSOLE: zapcore.NewConsoleEncoder(encoderConfig),
},
Selector: output,
Output: output,
}
entry := zapcore.Entry{
Level: zapcore.DebugLevel,
Message: "no bugs for me",
}
err := core.Write(entry, nil)
assert.NoError(t, err)
assert.False(t, output.syncCalled)
entry = zapcore.Entry{
Level: zapcore.PanicLevel,
Message: "gah!",
}
err = core.Write(entry, nil)
assert.NoError(t, err)
assert.True(t, output.syncCalled)
}
type brokenEncoder struct{ zapcore.Encoder }
func (b *brokenEncoder) EncodeEntry(zapcore.Entry, []zapcore.Field) (*buffer.Buffer, error) {
return nil, errors.New("broken encoder")
}
func TestCoreWriteEncodeFail(t *testing.T) {
output := &sw{}
core := &flogging.Core{
Encoders: map[flogging.Encoding]zapcore.Encoder{
flogging.CONSOLE: &brokenEncoder{},
},
Selector: output,
Output: output,
}
entry := zapcore.Entry{
Level: zapcore.DebugLevel,
Message: "no bugs for me",
}
err := core.Write(entry, nil)
assert.EqualError(t, err, "broken encoder")
}
func TestCoreSync(t *testing.T) {
syncWriter := &sw{}
core := &flogging.Core{
Output: syncWriter,
}
err := core.Sync()
assert.NoError(t, err)
assert.True(t, syncWriter.syncCalled)
syncWriter.syncErr = errors.New("bummer")
err = core.Sync()
assert.EqualError(t, err, "bummer")
}
......@@ -27,36 +27,12 @@ type Formatter interface {
Format(w io.Writer, entry zapcore.Entry, fields []zapcore.Field)
}
// NewFormatEncoder creates a zapcore.Encoder that supports a subset of the
// formats provided by go-logging.
//
// The op-loggng specifiers supported by this formatter are:
// - %{color} - level specific SGR color escape or SGR reset
// - %{id} - a unique log sequence number
// - %{level} - the log level of the entry
// - %{message} - the log message
// - %{module} - the zap logger name
// - %{shortfunc} - the name of the function creating the log record
// - %{time} - the time the log entry was created
//
// Specifiers may include an optional format verb:
// - color: reset|bold
// - id: a fmt style numeric formatter without the leading %
// - level: a fmt style string formatter without the leading %
// - message: a fmt style string formatter without the leading %
// - module: a fmt style string formatter without the leading %
//
func NewFormatEncoder(formatSpec string) (*FormatEncoder, error) {
formatters, err := ParseFormat(formatSpec)
if err != nil {
return nil, err
}
func NewFormatEncoder(formatters ...Formatter) *FormatEncoder {
return &FormatEncoder{
Encoder: zapcore.NewConsoleEncoder(zapcore.EncoderConfig{LineEnding: "\n"}),
formatters: formatters,
pool: buffer.NewPool(),
}, nil
}
}
// Clone creates a new instance of this encoder with the same configuration.
......
......@@ -17,11 +17,6 @@ import (
"go.uber.org/zap/zapcore"
)
func TestNewFormatEncoderBadFormat(t *testing.T) {
_, err := fabenc.NewFormatEncoder("%{color:garbage}")
assert.EqualError(t, err, "invalid color option: garbage")
}
func TestEncodeEntry(t *testing.T) {
var tests = []struct {
name string
......@@ -38,9 +33,11 @@ func TestEncodeEntry(t *testing.T) {
for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
enc, err := fabenc.NewFormatEncoder(tc.spec)
formatters, err := fabenc.ParseFormat(tc.spec)
assert.NoError(t, err)
enc := fabenc.NewFormatEncoder(formatters...)
line, err := enc.EncodeEntry(zapcore.Entry{}, tc.fields)
assert.NoError(t, err)
assert.Equal(t, tc.expected, line.String())
......@@ -55,17 +52,15 @@ func (b *brokenEncoder) EncodeEntry(zapcore.Entry, []zapcore.Field) (*buffer.Buf
}
func TestEncodeFieldsFailed(t *testing.T) {
enc, err := fabenc.NewFormatEncoder("spec")
assert.NoError(t, err)
enc := fabenc.NewFormatEncoder()
enc.Encoder = &brokenEncoder{}
_, err = enc.EncodeEntry(zapcore.Entry{}, nil)
_, err := enc.EncodeEntry(zapcore.Entry{}, nil)
assert.EqualError(t, err, "broken encoder")
}
func TestFormatEncoderClone(t *testing.T) {
enc, err := fabenc.NewFormatEncoder("spec")
assert.NoError(t, err)
enc := fabenc.NewFormatEncoder()
cloned := enc.Clone()
assert.Equal(t, enc, cloned)
}
......@@ -12,6 +12,7 @@ import (
"regexp"
"runtime"
"strings"
"sync"
"sync/atomic"
"go.uber.org/zap/zapcore"
......@@ -27,6 +28,23 @@ var formatRegexp = regexp.MustCompile(`%{(color|id|level|message|module|shortfun
// ParseFormat parses a log format spec and returns a slice of formatters
// that should be iterated over to build a formatted log record.
//
// The op-loggng specifiers supported by this formatter are:
// - %{color} - level specific SGR color escape or SGR reset
// - %{id} - a unique log sequence number
// - %{level} - the log level of the entry
// - %{message} - the log message
// - %{module} - the zap logger name
// - %{shortfunc} - the name of the function creating the log record
// - %{time} - the time the log entry was created
//
// Specifiers may include an optional format verb:
// - color: reset|bold
// - id: a fmt style numeric formatter without the leading %
// - level: a fmt style string formatter without the leading %
// - message: a fmt style string formatter without the leading %