[FAB-13237] metrics for log records

Created counters to track the number of log records checked and
written. (filtered = checked - written)

Change-Id: I1b4dcbdc636891e8deca41440c40d58415edc438
Signed-off-by: Saad Karim <skarim@us.ibm.com>
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>

Author: sykesm

common/flogging/core.go

@@ -49,6 +49,14 @@ type Core struct {
 	Encoders map[Encoding]zapcore.Encoder
 	Selector EncodingSelector
 	Output   zapcore.WriteSyncer
+	Observer Observer
+}
+
+//go:generate counterfeiter -o mock/observer.go -fake-name Observer . Observer
+
+type Observer interface {
+	Check(e zapcore.Entry, ce *zapcore.CheckedEntry)
+	WriteEntry(e zapcore.Entry, fields []zapcore.Field)
 }
 
 func (c *Core) With(fields []zapcore.Field) zapcore.Core {
@@ -65,10 +73,15 @@ func (c *Core) With(fields []zapcore.Field) zapcore.Core {
 		Encoders:     clones,
 		Selector:     c.Selector,
 		Output:       c.Output,
+		Observer:     c.Observer,
 	}
 }
 
 func (c *Core) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	if c.Observer != nil {
+		c.Observer.Check(e, ce)
+	}
+
 	if c.Enabled(e.Level) && c.Levels.Level(e.LoggerName).Enabled(e.Level) {
 		return ce.AddCore(e, c)
 	}
@@ -93,6 +106,10 @@ func (c *Core) Write(e zapcore.Entry, fields []zapcore.Field) error {
 		c.Sync()
 	}
 
+	if c.Observer != nil {
+		c.Observer.WriteEntry(e, fields)
+	}
+
 	return nil
 }
 

common/flogging/core_test.go

@@ -12,6 +12,7 @@ import (
 	"testing"
 
 	"github.com/hyperledger/fabric/common/flogging"
+	"github.com/hyperledger/fabric/common/flogging/mock"
 	"github.com/stretchr/testify/assert"
 	"go.uber.org/zap"
 	"go.uber.org/zap/buffer"
@@ -21,6 +22,7 @@ import (
 func TestCoreWith(t *testing.T) {
 	core := &flogging.Core{
 		Encoders: map[flogging.Encoding]zapcore.Encoder{},
+		Observer: &mock.Observer{},
 	}
 	clone := core.With([]zapcore.Field{zap.String("key", "value")})
 	assert.Equal(t, core, clone)
@@ -187,3 +189,63 @@ func TestCoreSync(t *testing.T) {
 	err = core.Sync()
 	assert.EqualError(t, err, "bummer")
 }
+
+func TestObserverCheck(t *testing.T) {
+	observer := &mock.Observer{}
+	entry := zapcore.Entry{
+		Level:   zapcore.DebugLevel,
+		Message: "message",
+	}
+	checkedEntry := &zapcore.CheckedEntry{}
+
+	levels := &flogging.LoggerLevels{}
+	levels.ActivateSpec("debug")
+	core := &flogging.Core{
+		LevelEnabler: zap.LevelEnablerFunc(func(l zapcore.Level) bool { return true }),
+		Levels:       levels,
+		Observer:     observer,
+	}
+
+	ce := core.Check(entry, checkedEntry)
+	assert.Exactly(t, ce, checkedEntry)
+
+	assert.Equal(t, 1, observer.CheckCallCount())
+	observedEntry, observedCE := observer.CheckArgsForCall(0)
+	assert.Equal(t, entry, observedEntry)
+	assert.Equal(t, ce, observedCE)
+}
+
+func TestObserverWriteEntry(t *testing.T) {
+	observer := &mock.Observer{}
+	entry := zapcore.Entry{
+		Level:   zapcore.DebugLevel,
+		Message: "message",
+	}
+	fields := []zapcore.Field{
+		{Key: "key1", Type: zapcore.SkipType},
+		{Key: "key2", Type: zapcore.SkipType},
+	}
+
+	levels := &flogging.LoggerLevels{}
+	levels.ActivateSpec("debug")
+	selector := &sw{}
+	output := &sw{}
+	core := &flogging.Core{
+		LevelEnabler: zap.LevelEnablerFunc(func(l zapcore.Level) bool { return true }),
+		Levels:       levels,
+		Selector:     selector,
+		Encoders: map[flogging.Encoding]zapcore.Encoder{
+			flogging.CONSOLE: zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}),
+		},
+		Output:   output,
+		Observer: observer,
+	}
+
+	err := core.Write(entry, fields)
+	assert.NoError(t, err)
+
+	assert.Equal(t, 1, observer.WriteEntryCallCount())
+	observedEntry, observedFields := observer.WriteEntryArgsForCall(0)
+	assert.Equal(t, entry, observedEntry)
+	assert.Equal(t, fields, observedFields)
+}

common/flogging/logging.go

@@ -52,6 +52,7 @@ type Logging struct {
 	encoderConfig  zapcore.EncoderConfig
 	multiFormatter *fabenc.MultiFormatter
 	writer         zapcore.WriteSyncer
+	observer       Observer
 }
 
 // New creates a new logging system and initializes it with the provided
@@ -208,12 +209,35 @@ func (s *Logging) ZapLogger(name string) *zap.Logger {
 		},
 		Selector: s,
 		Output:   s,
+		Observer: s,
 	}
 	s.mutex.RUnlock()
 
 	return NewZapLogger(core).Named(name)
 }
 
+func (s *Logging) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) {
+	s.mutex.RLock()
+	if s.observer != nil {
+		s.observer.Check(e, ce)
+	}
+	s.mutex.RUnlock()
+}
+
+func (s *Logging) WriteEntry(e zapcore.Entry, fields []zapcore.Field) {
+	s.mutex.RLock()
+	if s.observer != nil {
+		s.observer.WriteEntry(e, fields)
+	}
+	s.mutex.RUnlock()
+}
+
+func (s *Logging) SetObserver(observer Observer) {
+	s.mutex.Lock()
+	s.observer = observer
+	s.mutex.Unlock()
+}
+
 // Logger instantiates a new FabricLogger with the specified name. The name is
 // used to determine which log levels are enabled.
 func (s *Logging) Logger(name string) *FabricLogger {

common/flogging/logging_test.go

@@ -108,3 +108,28 @@ func TestInvalidLoggerName(t *testing.T) {
 		})
 	}
 }
+
+func TestCheck(t *testing.T) {
+	l := &flogging.Logging{}
+	observer := &mock.Observer{}
+	e := zapcore.Entry{}
+
+	// set observer
+	l.SetObserver(observer)
+	l.Check(e, nil)
+	assert.Equal(t, 1, observer.CheckCallCount())
+	e, ce := observer.CheckArgsForCall(0)
+	assert.Equal(t, e, zapcore.Entry{})
+	assert.Nil(t, ce)
+
+	l.WriteEntry(e, nil)
+	assert.Equal(t, 1, observer.WriteEntryCallCount())
+	e, f := observer.WriteEntryArgsForCall(0)
+	assert.Equal(t, e, zapcore.Entry{})
+	assert.Nil(t, f)
+
+	//	remove observer
+	l.SetObserver(nil)
+	l.Check(zapcore.Entry{}, nil)
+	assert.Equal(t, 1, observer.CheckCallCount())
+}

common/flogging/metrics/observer.go

@@ -0,0 +1,50 @@
+/*
+Copyright IBM Corp. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package metrics
+
+import (
+	"github.com/hyperledger/fabric/common/metrics"
+	"go.uber.org/zap/zapcore"
+)
+
+var (
+	CheckedCountOpts = metrics.CounterOpts{
+		Namespace:    "logging",
+		Name:         "entries_checked",
+		Help:         "Number of log entries checked against the active logging level",
+		LabelNames:   []string{"level"},
+		StatsdFormat: "%{#fqname}.%{level}",
+	}
+
+	WriteCountOpts = metrics.CounterOpts{
+		Namespace:    "logging",
+		Name:         "entries_written",
+		Help:         "Number of log entries that are written",
+		LabelNames:   []string{"level"},
+		StatsdFormat: "%{#fqname}.%{level}",
+	}
+)
+
+type Observer struct {
+	CheckedCounter metrics.Counter
+	WrittenCounter metrics.Counter
+}
+
+func NewObserver(provider metrics.Provider) *Observer {
+	return &Observer{
+		CheckedCounter: provider.NewCounter(CheckedCountOpts),
+		WrittenCounter: provider.NewCounter(WriteCountOpts),
+	}
+}
+
+func (m *Observer) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) {
+	m.CheckedCounter.With("level", e.Level.String()).Add(1)
+}
+
+func (m *Observer) WriteEntry(e zapcore.Entry, fields []zapcore.Field) {
+	m.WrittenCounter.With("level", e.Level.String()).Add(1)
+}

common/flogging/metrics/observer_test.go

@@ -0,0 +1,74 @@
+/*
+Copyright IBM Corp. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package metrics_test
+
+import (
+	"testing"
+
+	"github.com/hyperledger/fabric/common/flogging/metrics"
+	commonmetrics "github.com/hyperledger/fabric/common/metrics"
+	"github.com/hyperledger/fabric/common/metrics/metricsfakes"
+	"github.com/stretchr/testify/assert"
+	"go.uber.org/zap/zapcore"
+)
+
+func TestNewObserver(t *testing.T) {
+	provider := &metricsfakes.Provider{}
+	checkedCounter := &metricsfakes.Counter{}
+	writtenCounter := &metricsfakes.Counter{}
+	provider.NewCounterStub = func(c commonmetrics.CounterOpts) commonmetrics.Counter {
+		switch c.Name {
+		case "entries_checked":
+			assert.Equal(t, metrics.CheckedCountOpts, c)
+			return checkedCounter
+		case "entries_written":
+			assert.Equal(t, metrics.WriteCountOpts, c)
+			return writtenCounter
+		default:
+			return nil
+		}
+	}
+
+	expectedObserver := &metrics.Observer{
+		CheckedCounter: checkedCounter,
+		WrittenCounter: writtenCounter,
+	}
+	m := metrics.NewObserver(provider)
+	assert.Equal(t, expectedObserver, m)
+	assert.Equal(t, 2, provider.NewCounterCallCount())
+}
+
+func TestCheck(t *testing.T) {
+	counter := &metricsfakes.Counter{}
+	counter.WithReturns(counter)
+
+	m := metrics.Observer{CheckedCounter: counter}
+	entry := zapcore.Entry{Level: zapcore.DebugLevel}
+	checkedEntry := &zapcore.CheckedEntry{}
+	m.Check(entry, checkedEntry)
+
+	assert.Equal(t, 1, counter.WithCallCount())
+	assert.Equal(t, []string{"level", "debug"}, counter.WithArgsForCall(0))
+
+	assert.Equal(t, 1, counter.AddCallCount())
+	assert.Equal(t, float64(1), counter.AddArgsForCall(0))
+}
+
+func TestWrite(t *testing.T) {
+	counter := &metricsfakes.Counter{}
+	counter.WithReturns(counter)
+
+	m := metrics.Observer{WrittenCounter: counter}
+	entry := zapcore.Entry{Level: zapcore.DebugLevel}
+	m.WriteEntry(entry, nil)
+
+	assert.Equal(t, 1, counter.WithCallCount())
+	assert.Equal(t, []string{"level", "debug"}, counter.WithArgsForCall(0))
+
+	assert.Equal(t, 1, counter.AddCallCount())
+	assert.Equal(t, float64(1), counter.AddArgsForCall(0))
+}