Commit e51851a3 authored by Matthew Sykes's avatar Matthew Sykes
Browse files

[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: default avatarSaad Karim <skarim@us.ibm.com>
Signed-off-by: default avatarMatthew Sykes <sykesmat@us.ibm.com>
(cherry picked from commit 312f11343942d312510027a8a4787cf3be98fce1)
parent 4fd7013e
......@@ -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
}
......
......@@ -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)
}
......@@ -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 {
......
......@@ -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())
}
/*
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)
}
/*
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))
}
// Code generated by counterfeiter. DO NOT EDIT.
package mock
import (
sync "sync"
flogging "github.com/hyperledger/fabric/common/flogging"
zapcore "go.uber.org/zap/zapcore"
)
type Observer struct {
CheckStub func(zapcore.Entry, *zapcore.CheckedEntry)
checkMutex sync.RWMutex
checkArgsForCall []struct {
arg1 zapcore.Entry
arg2 *zapcore.CheckedEntry
}
WriteEntryStub func(zapcore.Entry, []zapcore.Field)
writeEntryMutex sync.RWMutex
writeEntryArgsForCall []struct {
arg1 zapcore.Entry
arg2 []zapcore.Field
}
invocations map[string][][]interface{}
invocationsMutex sync.RWMutex
}
func (fake *Observer) Check(arg1 zapcore.Entry, arg2 *zapcore.CheckedEntry) {
fake.checkMutex.Lock()
fake.checkArgsForCall = append(fake.checkArgsForCall, struct {
arg1 zapcore.Entry
arg2 *zapcore.CheckedEntry
}{arg1, arg2})
fake.recordInvocation("Check", []interface{}{arg1, arg2})
fake.checkMutex.Unlock()
if fake.CheckStub != nil {
fake.CheckStub(arg1, arg2)
}
}
func (fake *Observer) CheckCallCount() int {
fake.checkMutex.RLock()
defer fake.checkMutex.RUnlock()
return len(fake.checkArgsForCall)
}
func (fake *Observer) CheckCalls(stub func(zapcore.Entry, *zapcore.CheckedEntry)) {
fake.checkMutex.Lock()
defer fake.checkMutex.Unlock()
fake.CheckStub = stub
}
func (fake *Observer) CheckArgsForCall(i int) (zapcore.Entry, *zapcore.CheckedEntry) {
fake.checkMutex.RLock()
defer fake.checkMutex.RUnlock()
argsForCall := fake.checkArgsForCall[i]
return argsForCall.arg1, argsForCall.arg2
}
func (fake *Observer) WriteEntry(arg1 zapcore.Entry, arg2 []zapcore.Field) {
var arg2Copy []zapcore.Field
if arg2 != nil {
arg2Copy = make([]zapcore.Field, len(arg2))
copy(arg2Copy, arg2)
}
fake.writeEntryMutex.Lock()
fake.writeEntryArgsForCall = append(fake.writeEntryArgsForCall, struct {
arg1 zapcore.Entry
arg2 []zapcore.Field
}{arg1, arg2Copy})
fake.recordInvocation("WriteEntry", []interface{}{arg1, arg2Copy})
fake.writeEntryMutex.Unlock()
if fake.WriteEntryStub != nil {
fake.WriteEntryStub(arg1, arg2)
}
}
func (fake *Observer) WriteEntryCallCount() int {
fake.writeEntryMutex.RLock()
defer fake.writeEntryMutex.RUnlock()
return len(fake.writeEntryArgsForCall)
}
func (fake *Observer) WriteEntryCalls(stub func(zapcore.Entry, []zapcore.Field)) {
fake.writeEntryMutex.Lock()
defer fake.writeEntryMutex.Unlock()
fake.WriteEntryStub = stub
}
func (fake *Observer) WriteEntryArgsForCall(i int) (zapcore.Entry, []zapcore.Field) {
fake.writeEntryMutex.RLock()
defer fake.writeEntryMutex.RUnlock()
argsForCall := fake.writeEntryArgsForCall[i]
return argsForCall.arg1, argsForCall.arg2
}
func (fake *Observer) Invocations() map[string][][]interface{} {
fake.invocationsMutex.RLock()
defer fake.invocationsMutex.RUnlock()
fake.checkMutex.RLock()
defer fake.checkMutex.RUnlock()
fake.writeEntryMutex.RLock()
defer fake.writeEntryMutex.RUnlock()
copiedInvocations := map[string][][]interface{}{}
for key, value := range fake.invocations {
copiedInvocations[key] = value
}
return copiedInvocations
}
func (fake *Observer) recordInvocation(key string, args []interface{}) {
fake.invocationsMutex.Lock()
defer fake.invocationsMutex.Unlock()
if fake.invocations == nil {
fake.invocations = map[string][][]interface{}{}
}
if fake.invocations[key] == nil {
fake.invocations[key] = [][]interface{}{}
}
fake.invocations[key] = append(fake.invocations[key], args)
}
var _ flogging.Observer = new(Observer)
......@@ -2,14 +2,24 @@
package mock
import (
"sync"
sync "sync"
)
type WriteSyncer struct {
WriteStub func(p []byte) (n int, err error)
SyncStub func() error
syncMutex sync.RWMutex
syncArgsForCall []struct {
}
syncReturns struct {
result1 error
}
syncReturnsOnCall map[int]struct {
result1 error
}
WriteStub func([]byte) (int, error)
writeMutex sync.RWMutex
writeArgsForCall []struct {
p []byte
arg1 []byte
}
writeReturns struct {
result1 int
......@@ -19,39 +29,83 @@ type WriteSyncer struct {
result1 int
result2 error
}
SyncStub func() error
syncMutex sync.RWMutex
syncArgsForCall []struct{}
syncReturns struct {
result1 error
invocations map[string][][]interface{}
invocationsMutex sync.RWMutex
}
func (fake *WriteSyncer) Sync() error {
fake.syncMutex.Lock()
ret, specificReturn := fake.syncReturnsOnCall[len(fake.syncArgsForCall)]
fake.syncArgsForCall = append(fake.syncArgsForCall, struct {
}{})
fake.recordInvocation("Sync", []interface{}{})
fake.syncMutex.Unlock()
if fake.SyncStub != nil {
return fake.SyncStub()
}
syncReturnsOnCall map[int]struct {
if specificReturn {
return ret.result1
}
fakeReturns := fake.syncReturns
return fakeReturns.result1
}
func (fake *WriteSyncer) SyncCallCount() int {
fake.syncMutex.RLock()
defer fake.syncMutex.RUnlock()
return len(fake.syncArgsForCall)
}
func (fake *WriteSyncer) SyncCalls(stub func() error) {
fake.syncMutex.Lock()
defer fake.syncMutex.Unlock()
fake.SyncStub = stub
}
func (fake *WriteSyncer) SyncReturns(result1 error) {
fake.syncMutex.Lock()
defer fake.syncMutex.Unlock()
fake.SyncStub = nil
fake.syncReturns = struct {
result1 error
}{result1}
}
func (fake *WriteSyncer) SyncReturnsOnCall(i int, result1 error) {
fake.syncMutex.Lock()
defer fake.syncMutex.Unlock()
fake.SyncStub = nil
if fake.syncReturnsOnCall == nil {
fake.syncReturnsOnCall = make(map[int]struct {
result1 error
})
}
invocations map[string][][]interface{}
invocationsMutex sync.RWMutex
fake.syncReturnsOnCall[i] = struct {
result1 error
}{result1}
}
func (fake *WriteSyncer) Write(p []byte) (n int, err error) {
var pCopy []byte
if p != nil {
pCopy = make([]byte, len(p))
copy(pCopy, p)
func (fake *WriteSyncer) Write(arg1 []byte) (int, error) {
var arg1Copy []byte
if arg1 != nil {
arg1Copy = make([]byte, len(arg1))
copy(arg1Copy, arg1)
}
fake.writeMutex.Lock()
ret, specificReturn := fake.writeReturnsOnCall[len(fake.writeArgsForCall)]
fake.writeArgsForCall = append(fake.writeArgsForCall, struct {
p []byte
}{pCopy})
fake.recordInvocation("Write", []interface{}{pCopy})
arg1 []byte
}{arg1Copy})
fake.recordInvocation("Write", []interface{}{arg1Copy})
fake.writeMutex.Unlock()
if fake.WriteStub != nil {
return fake.WriteStub(p)
return fake.WriteStub(arg1)
}
if specificReturn {
return ret.result1, ret.result2
}
return fake.writeReturns.result1, fake.writeReturns.result2
fakeReturns := fake.writeReturns
return fakeReturns.result1, fakeReturns.result2
}
func (fake *WriteSyncer) WriteCallCount() int {
......@@ -60,13 +114,22 @@ func (fake *WriteSyncer) WriteCallCount() int {
return len(fake.writeArgsForCall)
}
func (fake *WriteSyncer) WriteCalls(stub func([]byte) (int, error)) {
fake.writeMutex.Lock()
defer fake.writeMutex.Unlock()
fake.WriteStub = stub
}
func (fake *WriteSyncer) WriteArgsForCall(i int) []byte {
fake.writeMutex.RLock()
defer fake.writeMutex.RUnlock()
return fake.writeArgsForCall[i].p
argsForCall := fake.writeArgsForCall[i]
return argsForCall.arg1
}
func (fake *WriteSyncer) WriteReturns(result1 int, result2 error) {
fake.writeMutex.Lock()
defer fake.writeMutex.Unlock()
fake.WriteStub = nil
fake.writeReturns = struct {
result1 int
......@@ -75,6 +138,8 @@ func (fake *WriteSyncer) WriteReturns(result1 int, result2 error) {
}
func (fake *WriteSyncer) WriteReturnsOnCall(i int, result1 int, result2 error) {
fake.writeMutex.Lock()