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: hyperledger-archives#21

Signed-off-by: sudesh.shetty <[email protected]>

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)
+}

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)
+}

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)
+}