From 6ca27f5d49a3dce28ff4fbff1d2cf44caaa464ce Mon Sep 17 00:00:00 2001
From: "sudesh.shetty" <sudesh.shetty@securekey.com>
Date: Mon, 29 Jul 2019 16:40:54 -0400
Subject: [PATCH] feat: default logger implementation

- defLog : default implementation of moduled logger built on top
of go 'log' package.
- modLog: moduled level based logger implementation wrapping custom logger implementation.
- Story: #21

Signed-off-by: sudesh.shetty <sudesh.shetty@securekey.com>
---
 pkg/internal/common/logging/modlog/deflog.go  | 157 +++++++++++++++
 .../common/logging/modlog/deflog_test.go      |  22 +++
 .../common/logging/modlog/logtestutils.go     | 183 ++++++++++++++++++
 pkg/internal/common/logging/modlog/modlog.go  |  65 +++++++
 .../common/logging/modlog/modlog_test.go      |  17 ++
 .../common/logging/modlog/provider.go         |  49 +++++
 .../common/logging/modlog/provider_test.go    |  49 +++++
 7 files changed, 542 insertions(+)
 create mode 100644 pkg/internal/common/logging/modlog/deflog.go
 create mode 100644 pkg/internal/common/logging/modlog/deflog_test.go
 create mode 100644 pkg/internal/common/logging/modlog/logtestutils.go
 create mode 100644 pkg/internal/common/logging/modlog/modlog.go
 create mode 100644 pkg/internal/common/logging/modlog/modlog_test.go
 create mode 100644 pkg/internal/common/logging/modlog/provider.go
 create mode 100644 pkg/internal/common/logging/modlog/provider_test.go

diff --git a/pkg/internal/common/logging/modlog/deflog.go b/pkg/internal/common/logging/modlog/deflog.go
new file mode 100644
index 0000000000..b0420fff61
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/deflog.go
@@ -0,0 +1,157 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"fmt"
+	"io"
+	"log"
+	"os"
+	"path/filepath"
+	"runtime"
+	"strings"
+
+	"github.com/hyperledger/aries-framework-go/pkg/internal/common/logging/metadata"
+
+	logapi "github.com/hyperledger/aries-framework-go/pkg/common/log"
+)
+
+const (
+	logLevelFormatter   = "UTC %s-> %s "
+	logPrefixFormatter  = " [%s] "
+	callerInfoFormatter = "- %s "
+)
+
+// defLog is a logger implementation built on top of standard go log.
+// This is moduled logger where each module can have different logging levels (default is INFO).
+// There is a  configurable caller info feature which displays caller function information name in logged lines.
+// caller info can be configured by log levels and modules. By default it is enabled.
+// Log Format : [<MODULE NAME>] <TIME IN UTC> - <CALLER INFO> -> <LOG LEVEL> <LOG TEXT>
+type defLog struct {
+	logger *log.Logger
+	module string
+}
+
+//Fatalf is CRITICAL log formatted followed by a call to os.Exit(1).
+func (l *defLog) Fatalf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.CRITICAL)
+	l.logf(opts, logapi.CRITICAL, format, args...)
+	os.Exit(1)
+}
+
+//Panicf is CRITICAL log formatted followed by a call to panic()
+func (l *defLog) Panicf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.CRITICAL)
+	l.logf(opts, logapi.CRITICAL, format, args...)
+	panic(fmt.Sprintf(format, args...))
+}
+
+//Debugf calls go 'log.Output' and can be used for logging verbose messages.
+// Arguments are handled in the manner of fmt.Printf.
+func (l *defLog) Debugf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.DEBUG)
+	if !opts.LevelEnabled {
+		return
+	}
+	l.logf(opts, logapi.DEBUG, format, args...)
+}
+
+//Infof calls go 'log.Output' and can be used for logging general information messages.
+//INFO is default logging level
+// Arguments are handled in the manner of fmt.Printf.
+func (l *defLog) Infof(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.INFO)
+	if !opts.LevelEnabled {
+		return
+	}
+	l.logf(opts, logapi.INFO, format, args...)
+}
+
+// Warnf calls go log.Output and can be used for logging possible errors.
+// Arguments are handled in the manner of fmt.Printf.
+func (l *defLog) Warnf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.WARNING)
+	if !opts.LevelEnabled {
+		return
+	}
+	l.logf(opts, logapi.WARNING, format, args...)
+}
+
+// Errorf calls go 'log.Output' and can be used for logging errors.
+// Arguments are handled in the manner of fmt.Printf.
+func (l *defLog) Errorf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(l.module, logapi.ERROR)
+	if !opts.LevelEnabled {
+		return
+	}
+	l.logf(opts, logapi.ERROR, format, args...)
+}
+
+//SetOutput sets the output destination for the logger.
+func (l *defLog) SetOutput(output io.Writer) {
+	l.logger.SetOutput(output)
+}
+
+func (l *defLog) logf(opts *metadata.LoggerOpts, level logapi.Level, format string, args ...interface{}) {
+	//Format prefix to show function name and log level and to indicate that timezone used is UTC
+	customPrefix := fmt.Sprintf(logLevelFormatter, l.getCallerInfo(opts), metadata.ParseString(level))
+	err := l.logger.Output(2, customPrefix+fmt.Sprintf(format, args...))
+	if err != nil {
+		fmt.Printf("error from logger.Output %v\n", err)
+	}
+}
+
+//getCallerInfo going through runtime caller frames to determine the caller of logger function by filtering
+// internal logging library functions
+func (l *defLog) getCallerInfo(opts *metadata.LoggerOpts) string {
+
+	if !opts.CallerInfoEnabled {
+		return ""
+	}
+
+	// search MAXCALLERS caller frames for the real caller,
+	// MAXCALLERS defines maximum number of caller frames needed to be recorded to find the actual caller frame
+	const MAXCALLERS = 6
+	// skip SKIPCALLERS frames when determining the real caller
+	// SKIPCALLERS is the number of stack frames to skip before recording caller frames,
+	// this is mainly used to filter logger library functions in caller frames
+	const SKIPCALLERS = 4
+
+	const NOTFOUND = "n/a"
+	const DEFAULTLOGPREFIX = "logging.(*Logger)"
+
+	fpcs := make([]uintptr, MAXCALLERS)
+
+	n := runtime.Callers(SKIPCALLERS, fpcs)
+	if n == 0 {
+		return fmt.Sprintf(callerInfoFormatter, NOTFOUND)
+	}
+
+	frames := runtime.CallersFrames(fpcs[:n])
+	loggerFrameFound := false
+
+	for f, more := frames.Next(); more; f, more = frames.Next() {
+		_, fnName := filepath.Split(f.Function)
+
+		if f.Func == nil || f.Function == "" {
+			fnName = NOTFOUND // not a function or unknown
+		}
+
+		if loggerFrameFound {
+			return fmt.Sprintf(callerInfoFormatter, fnName)
+		}
+
+		if strings.HasPrefix(fnName, DEFAULTLOGPREFIX) {
+			loggerFrameFound = true
+			continue
+		}
+
+		return fmt.Sprintf(callerInfoFormatter, fnName)
+	}
+
+	return fmt.Sprintf(callerInfoFormatter, NOTFOUND)
+}
diff --git a/pkg/internal/common/logging/modlog/deflog_test.go b/pkg/internal/common/logging/modlog/deflog_test.go
new file mode 100644
index 0000000000..556513efb5
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/deflog_test.go
@@ -0,0 +1,22 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"fmt"
+	"log"
+	"testing"
+
+	"github.com/hyperledger/aries-framework-go/pkg/internal/common/logging/metadata"
+)
+
+func TestDefLog(t *testing.T) {
+	const module = "sample-module"
+	logger := &defLog{logger: log.New(&buf, fmt.Sprintf(logPrefixFormatter, module), log.Ldate|log.Ltime|log.LUTC), module: module}
+
+	VerifyDefaultLogging(t, logger, module, metadata.SetLevel)
+}
diff --git a/pkg/internal/common/logging/modlog/logtestutils.go b/pkg/internal/common/logging/modlog/logtestutils.go
new file mode 100644
index 0000000000..21b5f32af8
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/logtestutils.go
@@ -0,0 +1,183 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"bytes"
+	"fmt"
+	"log"
+	"regexp"
+	"testing"
+
+	logapi "github.com/hyperledger/aries-framework-go/pkg/common/log"
+	"github.com/hyperledger/aries-framework-go/pkg/internal/common/logging/metadata"
+	"github.com/stretchr/testify/require"
+)
+
+const (
+	defLoggerOutputRegex           = "\\[%s\\] .* UTC - modlog.VerifyDefaultLogging -> %s %s"
+	defLoggerNoCallerInfoRegex     = "\\[%s\\] .* UTC -> %s %s"
+	msgFormat                      = "brown %s jumps over the lazy %s"
+	msgArg1                        = "fox"
+	msgArg2                        = "dog"
+	customOutput                   = "CUSTOM LOG OUTPUT"
+	customLevelOutputExpectedRegex = "\\[%s\\] .* CUSTOM LOG OUTPUT"
+)
+
+var buf bytes.Buffer
+
+//VerifyDefaultLogging verifies default logging behaviour.
+//Should only be used for tests
+func VerifyDefaultLogging(t *testing.T, logger logapi.Logger, module string, setLevel func(module string, level logapi.Level)) {
+	allTestLevels := []logapi.Level{logapi.ERROR, logapi.DEBUG, logapi.INFO, logapi.WARNING, logapi.CRITICAL}
+
+	for _, levelEnabled := range allTestLevels {
+
+		//change log level
+		setLevel(module, levelEnabled)
+
+		logger.Infof(msgFormat, msgArg1, msgArg2)
+		matchDefLogOutput(t, module, logapi.INFO, levelEnabled, true)
+
+		logger.Errorf(msgFormat, msgArg1, msgArg2)
+		matchDefLogOutput(t, module, logapi.ERROR, levelEnabled, true)
+
+		logger.Debugf(msgFormat, msgArg1, msgArg2)
+		matchDefLogOutput(t, module, logapi.DEBUG, levelEnabled, true)
+
+		logger.Warnf(msgFormat, msgArg1, msgArg2)
+		matchDefLogOutput(t, module, logapi.WARNING, levelEnabled, true)
+	}
+
+	//testing critical logging by handling panic
+	defer func() {
+		r := recover()
+		require.NotNil(t, r, "supposed to panic")
+		matchDefLogOutput(t, module, logapi.CRITICAL, logapi.WARNING, true)
+	}()
+
+	logger.Panicf(msgFormat, msgArg1, msgArg2)
+}
+
+func matchDefLogOutput(t *testing.T, module string, currentLevel, levelEnabled logapi.Level, infoEnabled bool) {
+	if currentLevel > levelEnabled {
+		require.Empty(t, buf.String())
+		return
+	}
+	defer buf.Reset()
+
+	var regex string
+
+	if infoEnabled {
+		regex = fmt.Sprintf(defLoggerOutputRegex, module, metadata.ParseString(currentLevel), fmt.Sprintf(msgFormat, msgArg1, msgArg2))
+	} else {
+		regex = fmt.Sprintf(defLoggerNoCallerInfoRegex, module, metadata.ParseString(currentLevel), fmt.Sprintf(msgFormat, msgArg1, msgArg2))
+	}
+
+	match, err := regexp.MatchString(regex, buf.String())
+
+	require.Empty(t, err, "error while matching regex with logoutput wasnt expected")
+	require.True(t, match, "logger isn't producing output as expected,\n\tLevel Enabled:[%s]\n\tlogoutput:%s\n\tregex:%s", metadata.ParseString(currentLevel), buf.String(), regex)
+}
+
+//VerifyCustomLogger verifies custom logging behaviour.
+//Should only be used for tests
+func VerifyCustomLogger(t *testing.T, logger logapi.Logger, module string) {
+	regex := fmt.Sprintf(customLevelOutputExpectedRegex, module)
+	allTestLevels := []logapi.Level{logapi.ERROR, logapi.DEBUG, logapi.INFO, logapi.WARNING, logapi.CRITICAL}
+
+	for _, levelEnabled := range allTestLevels {
+
+		//change log level
+		metadata.SetLevel(module, levelEnabled)
+
+		//print in all levels and verify
+		logger.Infof("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.INFO, levelEnabled)
+
+		logger.Debugf("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.DEBUG, levelEnabled)
+
+		logger.Warnf("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.WARNING, levelEnabled)
+
+		logger.Errorf("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.ERROR, levelEnabled)
+
+		logger.Panicf("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.CRITICAL, levelEnabled)
+
+		logger.Fatalf("brown fox jumps over the lazy dog")
+		matchCustomLogOutput(t, regex, logapi.CRITICAL, levelEnabled)
+	}
+}
+
+func matchCustomLogOutput(t *testing.T, regex string, level, levelEnabled logapi.Level) {
+	if level > levelEnabled {
+		require.Empty(t, buf.String())
+		return
+	}
+	defer buf.Reset()
+	match, err := regexp.MatchString(regex, buf.String())
+	require.Empty(t, err, "error while matching regex with logoutput wasnt expected")
+	require.True(t, match, "logger isn't producing output as expected,\n\tLevel Enabled:[%s]\n\tlogoutput:%s\n\tregex:%s", metadata.ParseString(level), buf.String(), regex)
+}
+
+//GetSampleCustomLogger returns custom logger which can only be used for testing purposes.
+func GetSampleCustomLogger(output *bytes.Buffer, module string) logapi.Logger {
+	logger := log.New(output, fmt.Sprintf(logPrefixFormatter, module), log.Ldate|log.Ltime|log.LUTC)
+	return &sampleLog{logger}
+}
+
+//NewCustomLoggingProvider returns new custom logging provider which can only be used for testing purposes.
+func NewCustomLoggingProvider() logapi.LoggerProvider {
+	return &sampleProvider{}
+}
+
+// sampleProvider is a custom logging provider
+type sampleProvider struct {
+}
+
+//GetLogger returns custom logger implementation
+func (p *sampleProvider) GetLogger(module string) logapi.Logger {
+	return GetSampleCustomLogger(&buf, module)
+}
+
+//modLog is a moduled wrapper for api.Logger implementation
+type sampleLog struct {
+	logger *log.Logger
+}
+
+// Fatal calls underlying logger.Fatal
+func (m *sampleLog) Fatalf(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
+
+// Panic calls underlying logger.Panic
+func (m *sampleLog) Panicf(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
+
+// Debug calls error log function if DEBUG level enabled
+func (m *sampleLog) Debugf(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
+
+// Info calls error log function if INFO level enabled
+func (m *sampleLog) Infof(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
+
+// Warn calls error log function if WARNING level enabled
+func (m *sampleLog) Warnf(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
+
+// Error calls error log function if ERROR level enabled
+func (m *sampleLog) Errorf(format string, args ...interface{}) {
+	m.logger.Print(customOutput)
+}
diff --git a/pkg/internal/common/logging/modlog/modlog.go b/pkg/internal/common/logging/modlog/modlog.go
new file mode 100644
index 0000000000..83ada8a3ec
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/modlog.go
@@ -0,0 +1,65 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"github.com/hyperledger/aries-framework-go/pkg/common/log"
+	"github.com/hyperledger/aries-framework-go/pkg/internal/common/logging/metadata"
+)
+
+// modLog is a moduled wrapper for any custom 'log.Logger' implementation.
+// Since this is a moduled wrapper where each module can have different logging levels (default is INFO).
+type modLog struct {
+	logger log.Logger
+	module string
+}
+
+//Fatalf calls underlying logger.Fatal
+func (m *modLog) Fatalf(format string, args ...interface{}) {
+	m.logger.Fatalf(format, args...)
+}
+
+//Panicf calls underlying logger.Panic
+func (m *modLog) Panicf(format string, args ...interface{}) {
+	m.logger.Panicf(format, args...)
+}
+
+//Debugf calls error log function if DEBUG level enabled
+func (m *modLog) Debugf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(m.module, log.DEBUG)
+	if !opts.LevelEnabled {
+		return
+	}
+	m.logger.Debugf(format, args...)
+}
+
+//Infof calls error log function if INFO level enabled
+func (m *modLog) Infof(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(m.module, log.INFO)
+	if !opts.LevelEnabled {
+		return
+	}
+	m.logger.Infof(format, args...)
+}
+
+//Warnf calls error log function if WARNING level enabled
+func (m *modLog) Warnf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(m.module, log.WARNING)
+	if !opts.LevelEnabled {
+		return
+	}
+	m.logger.Warnf(format, args...)
+}
+
+//Errorf calls error log function if ERROR level enabled
+func (m *modLog) Errorf(format string, args ...interface{}) {
+	opts := metadata.GetLoggerOpts(m.module, log.ERROR)
+	if !opts.LevelEnabled {
+		return
+	}
+	m.logger.Errorf(format, args...)
+}
diff --git a/pkg/internal/common/logging/modlog/modlog_test.go b/pkg/internal/common/logging/modlog/modlog_test.go
new file mode 100644
index 0000000000..88e50429c8
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/modlog_test.go
@@ -0,0 +1,17 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"testing"
+)
+
+func TestModLog(t *testing.T) {
+	const module = "sample-module"
+	modLogger := &modLog{logger: GetSampleCustomLogger(&buf, module), module: module}
+	VerifyCustomLogger(t, modLogger, module)
+}
diff --git a/pkg/internal/common/logging/modlog/provider.go b/pkg/internal/common/logging/modlog/provider.go
new file mode 100644
index 0000000000..9eb04caf9d
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/provider.go
@@ -0,0 +1,49 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"fmt"
+	"log"
+	"os"
+
+	logapi "github.com/hyperledger/aries-framework-go/pkg/common/log"
+)
+
+//NewModLogProvider returns new moduled logger provider wrapper for given custom logger provider
+func NewModLogProvider(customProvider logapi.LoggerProvider) logapi.LoggerProvider {
+	if customProvider == nil {
+		//instead of panic while logging, switch to default
+		return NewDefLogProvider()
+	}
+	return &modProvider{customProvider}
+}
+
+//NewDefLogProvider returns new logging provider for default logger implementation built on top of standard go log.
+func NewDefLogProvider() logapi.LoggerProvider {
+	return &defProvider{}
+}
+
+// defProvider is provider for logger implementation built on top of standard go log.
+type defProvider struct {
+}
+
+//GetLogger returns moduled default logger implementation.
+func (p *defProvider) GetLogger(module string) logapi.Logger {
+	newDefLogger := log.New(os.Stdout, fmt.Sprintf(logPrefixFormatter, module), log.Ldate|log.Ltime|log.LUTC)
+	return &defLog{logger: newDefLogger, module: module}
+}
+
+// modProvider is the moduled logger wrapper for custom provider
+type modProvider struct {
+	customProvider logapi.LoggerProvider
+}
+
+//GetLogger returns moduled logger implementation.
+func (p *modProvider) GetLogger(module string) logapi.Logger {
+	return &modLog{logger: p.customProvider.GetLogger(module), module: module}
+}
diff --git a/pkg/internal/common/logging/modlog/provider_test.go b/pkg/internal/common/logging/modlog/provider_test.go
new file mode 100644
index 0000000000..ac2d8f2eed
--- /dev/null
+++ b/pkg/internal/common/logging/modlog/provider_test.go
@@ -0,0 +1,49 @@
+/*
+Copyright SecureKey Technologies Inc. All Rights Reserved.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package modlog
+
+import (
+	"testing"
+
+	"github.com/hyperledger/aries-framework-go/pkg/internal/common/logging/metadata"
+
+	"github.com/hyperledger/aries-framework-go/pkg/common/log"
+)
+
+func TestDefLoggerProvider(t *testing.T) {
+	const module = "sample-module"
+	defProvider := NewDefLogProvider()
+	deflogger := defProvider.GetLogger(module)
+
+	//Change output function to bytes.Buffer for testing
+	deflogger.(*defLog).SetOutput(&buf)
+
+	VerifyDefaultLogging(t, deflogger, module, metadata.SetLevel)
+}
+
+func TestDefLoggerProviderNoCallerInfo(t *testing.T) {
+	const module = "sample-module-no-caller-info"
+	defProvider := NewDefLogProvider()
+	deflogger := defProvider.GetLogger(module)
+
+	//Change output function to bytes.Buffer for testing
+	deflogger.(*defLog).SetOutput(&buf)
+
+	metadata.HideCallerInfo(module, log.INFO)
+	metadata.SetLevel(module, log.DEBUG)
+
+	deflogger.Infof(msgFormat, msgArg1, msgArg2)
+	matchDefLogOutput(t, module, log.INFO, log.DEBUG, false)
+}
+
+func TestCustomLoggerProvider(t *testing.T) {
+	const module = "sample-module"
+	defProvider := NewModLogProvider(NewCustomLoggingProvider())
+	customLogger := defProvider.GetLogger(module)
+
+	VerifyCustomLogger(t, customLogger, module)
+}