Add GetLogger, WithCaller, and WithCallerSkip

They add call site information (function name, filename, line number) to
a logger.

GetLogger is intended for direct one-shot logging calls, i.e.
“GetLogger().Debug(...)”.

Wrap reusable loggers with WithCaller():

    logger := utils.GetLogInstance().New(/* ... */)
    /* ... */
    utils.WithCaller(logger).Debug(/* ... */)

Or use a local getLogger() idiom:

    logger := utils.GetLogInstance().New(/* ... */)
    getLogger := func() log.Logger {
	return WithCallerSkip(logger, 1)
    }
    /* ... */
    getLogger().Debug(/* ... */)

Since getLogger() uses closure, logger can later be augmented with
“logger = logger.New(/* ... */)” syntax.

internal/utils/logging.go

@@ -0,0 +1,42 @@
+package utils
+
+import (
+	"path"
+	"runtime"
+
+	"github.com/ethereum/go-ethereum/log"
+)
+
+// WithCallerSkip logs the caller info in three context items "funcFile",
+// "funcLine", and "funcName".  skip is the number of frames to skip.
+// 0 adds the info of the caller of this WithCallerSkip.
+func WithCallerSkip(logger log.Logger, skip int) log.Logger {
+	pcs := make([]uintptr, 1)
+	numPCs := runtime.Callers(2+skip, pcs)
+	var ctx []interface{}
+	if numPCs >= 1 {
+		frames := runtime.CallersFrames(pcs[:numPCs])
+		frame, _ := frames.Next()
+		if frame.Function != "" {
+			ctx = append(ctx, "funcName", frame.Function)
+		}
+		if frame.File != "" {
+			ctx = append(ctx, "funcFile", path.Base(frame.File))
+		}
+		if frame.Line != 0 {
+			ctx = append(ctx, "funcLine", frame.Line)
+		}
+	}
+	return logger.New(ctx...)
+}
+
+// WithCaller logs the caller info in three context items "funcFile",
+// "funcLine", and "funcName".
+func WithCaller(logger log.Logger) log.Logger {
+	return WithCallerSkip(logger, 1)
+}
+
+// GetLogger is a shorthand for WithCaller(GetLogInstance()).
+func GetLogger() log.Logger {
+	return WithCallerSkip(GetLogInstance(), 1)
+}

internal/utils/logging_test.go

@@ -0,0 +1,89 @@
+package utils
+
+import (
+	"reflect"
+	"testing"
+
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/golang/mock/gomock"
+
+	matchers "github.com/harmony-one/harmony/gomock_matchers"
+	"github.com/harmony-one/harmony/internal/utils/mock_log"
+)
+
+//go:generate mockgen -destination mock_log/logger.go github.com/ethereum/go-ethereum/log Logger
+//go:generate mockgen -destination mock_log/handler.go github.com/ethereum/go-ethereum/log Handler
+
+const (
+	thisPkg  = "github.com/harmony-one/harmony/internal/utils"
+	thisFile = "logging_test.go"
+)
+
+func testWithCallerSkip0(t *testing.T, skip int, name string, line int) {
+	ctrl := gomock.NewController(t)
+	defer ctrl.Finish()
+	want := log.Root()
+	logger := mock_log.NewMockLogger(ctrl)
+	logger.EXPECT().New(matchers.Slice{
+		"funcName", thisPkg + "." + name,
+		"funcFile", thisFile,
+		"funcLine", line,
+	}).Return(want)
+	if got := WithCallerSkip(logger, skip); !reflect.DeepEqual(got, want) {
+		t.Errorf("WithCallerSkip() = %v, want %v", got, want)
+	}
+}
+
+func testWithCallerSkip1(t *testing.T, skip int, name string, line int) {
+	testWithCallerSkip0(t, skip, name, line)
+}
+
+func testWithCallerSkip2(t *testing.T, skip int, name string, line int) {
+	testWithCallerSkip1(t, skip, name, line)
+}
+
+func TestWithCallerSkip(t *testing.T) {
+	t.Run("0", func(t *testing.T) {
+		testWithCallerSkip2(t, 0, "testWithCallerSkip0", 32)
+	})
+	t.Run("1", func(t *testing.T) {
+		testWithCallerSkip2(t, 1, "testWithCallerSkip1", 38)
+	})
+	t.Run("2", func(t *testing.T) {
+		testWithCallerSkip2(t, 2, "testWithCallerSkip2", 42)
+	})
+}
+
+func TestWithCaller(t *testing.T) {
+	ctrl := gomock.NewController(t)
+	defer ctrl.Finish()
+	want := log.Root()
+	logger := mock_log.NewMockLogger(ctrl)
+	logger.EXPECT().New(matchers.Slice{
+		"funcName", thisPkg + ".TestWithCaller",
+		"funcFile", thisFile,
+		"funcLine", 67, // keep this in sync with WithCaller() call below
+	}).Return(want)
+	if got := WithCaller(logger); !reflect.DeepEqual(got, want) {
+		t.Errorf("WithCallerSkip() = %v, want %v", got, want)
+	}
+}
+
+func TestGetLogger(t *testing.T) {
+	oldHandler := GetLogInstance().GetHandler()
+	defer GetLogInstance().SetHandler(oldHandler)
+	ctrl := gomock.NewController(t)
+	handler := mock_log.NewMockHandler(ctrl)
+	handler.EXPECT().Log(matchers.Struct{
+		"Msg": "omg",
+		"Ctx": matchers.Slice{
+			"port", "", // added by the singleton instance
+			"ip", "", // added by the singleton instance
+			"funcName", thisPkg + ".TestGetLogger",
+			"funcFile", thisFile,
+			"funcLine", 88, // keep this in sync with Debug() call below
+		},
+	})
+	GetLogInstance().SetHandler(handler)
+	GetLogger().Debug("omg")
+}

internal/utils/mock_log/handler.go

@@ -0,0 +1,48 @@
+// Code generated by MockGen. DO NOT EDIT.
+// Source: github.com/ethereum/go-ethereum/log (interfaces: Handler)
+
+// Package mock_log is a generated GoMock package.
+package mock_log
+
+import (
+	log "github.com/ethereum/go-ethereum/log"
+	gomock "github.com/golang/mock/gomock"
+	reflect "reflect"
+)
+
+// MockHandler is a mock of Handler interface
+type MockHandler struct {
+	ctrl     *gomock.Controller
+	recorder *MockHandlerMockRecorder
+}
+
+// MockHandlerMockRecorder is the mock recorder for MockHandler
+type MockHandlerMockRecorder struct {
+	mock *MockHandler
+}
+
+// NewMockHandler creates a new mock instance
+func NewMockHandler(ctrl *gomock.Controller) *MockHandler {
+	mock := &MockHandler{ctrl: ctrl}
+	mock.recorder = &MockHandlerMockRecorder{mock}
+	return mock
+}
+
+// EXPECT returns an object that allows the caller to indicate expected use
+func (m *MockHandler) EXPECT() *MockHandlerMockRecorder {
+	return m.recorder
+}
+
+// Log mocks base method
+func (m *MockHandler) Log(arg0 *log.Record) error {
+	m.ctrl.T.Helper()
+	ret := m.ctrl.Call(m, "Log", arg0)
+	ret0, _ := ret[0].(error)
+	return ret0
+}
+
+// Log indicates an expected call of Log
+func (mr *MockHandlerMockRecorder) Log(arg0 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Log", reflect.TypeOf((*MockHandler)(nil).Log), arg0)
+}

internal/utils/mock_log/logger.go

@@ -0,0 +1,180 @@
+// Code generated by MockGen. DO NOT EDIT.
+// Source: github.com/ethereum/go-ethereum/log (interfaces: Logger)
+
+// Package mock_log is a generated GoMock package.
+package mock_log
+
+import (
+	log "github.com/ethereum/go-ethereum/log"
+	gomock "github.com/golang/mock/gomock"
+	reflect "reflect"
+)
+
+// MockLogger is a mock of Logger interface
+type MockLogger struct {
+	ctrl     *gomock.Controller
+	recorder *MockLoggerMockRecorder
+}
+
+// MockLoggerMockRecorder is the mock recorder for MockLogger
+type MockLoggerMockRecorder struct {
+	mock *MockLogger
+}
+
+// NewMockLogger creates a new mock instance
+func NewMockLogger(ctrl *gomock.Controller) *MockLogger {
+	mock := &MockLogger{ctrl: ctrl}
+	mock.recorder = &MockLoggerMockRecorder{mock}
+	return mock
+}
+
+// EXPECT returns an object that allows the caller to indicate expected use
+func (m *MockLogger) EXPECT() *MockLoggerMockRecorder {
+	return m.recorder
+}
+
+// Crit mocks base method
+func (m *MockLogger) Crit(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Crit", varargs...)
+}
+
+// Crit indicates an expected call of Crit
+func (mr *MockLoggerMockRecorder) Crit(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Crit", reflect.TypeOf((*MockLogger)(nil).Crit), varargs...)
+}
+
+// Debug mocks base method
+func (m *MockLogger) Debug(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Debug", varargs...)
+}
+
+// Debug indicates an expected call of Debug
+func (mr *MockLoggerMockRecorder) Debug(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Debug", reflect.TypeOf((*MockLogger)(nil).Debug), varargs...)
+}
+
+// Error mocks base method
+func (m *MockLogger) Error(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Error", varargs...)
+}
+
+// Error indicates an expected call of Error
+func (mr *MockLoggerMockRecorder) Error(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Error", reflect.TypeOf((*MockLogger)(nil).Error), varargs...)
+}
+
+// GetHandler mocks base method
+func (m *MockLogger) GetHandler() log.Handler {
+	m.ctrl.T.Helper()
+	ret := m.ctrl.Call(m, "GetHandler")
+	ret0, _ := ret[0].(log.Handler)
+	return ret0
+}
+
+// GetHandler indicates an expected call of GetHandler
+func (mr *MockLoggerMockRecorder) GetHandler() *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetHandler", reflect.TypeOf((*MockLogger)(nil).GetHandler))
+}
+
+// Info mocks base method
+func (m *MockLogger) Info(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Info", varargs...)
+}
+
+// Info indicates an expected call of Info
+func (mr *MockLoggerMockRecorder) Info(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Info", reflect.TypeOf((*MockLogger)(nil).Info), varargs...)
+}
+
+// New mocks base method
+func (m *MockLogger) New(arg0 ...interface{}) log.Logger {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{}
+	for _, a := range arg0 {
+		varargs = append(varargs, a)
+	}
+	ret := m.ctrl.Call(m, "New", varargs...)
+	ret0, _ := ret[0].(log.Logger)
+	return ret0
+}
+
+// New indicates an expected call of New
+func (mr *MockLoggerMockRecorder) New(arg0 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "New", reflect.TypeOf((*MockLogger)(nil).New), arg0...)
+}
+
+// SetHandler mocks base method
+func (m *MockLogger) SetHandler(arg0 log.Handler) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "SetHandler", arg0)
+}
+
+// SetHandler indicates an expected call of SetHandler
+func (mr *MockLoggerMockRecorder) SetHandler(arg0 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "SetHandler", reflect.TypeOf((*MockLogger)(nil).SetHandler), arg0)
+}
+
+// Trace mocks base method
+func (m *MockLogger) Trace(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Trace", varargs...)
+}
+
+// Trace indicates an expected call of Trace
+func (mr *MockLoggerMockRecorder) Trace(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Trace", reflect.TypeOf((*MockLogger)(nil).Trace), varargs...)
+}
+
+// Warn mocks base method
+func (m *MockLogger) Warn(arg0 string, arg1 ...interface{}) {
+	m.ctrl.T.Helper()
+	varargs := []interface{}{arg0}
+	for _, a := range arg1 {
+		varargs = append(varargs, a)
+	}
+	m.ctrl.Call(m, "Warn", varargs...)
+}
+
+// Warn indicates an expected call of Warn
+func (mr *MockLoggerMockRecorder) Warn(arg0 interface{}, arg1 ...interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	varargs := append([]interface{}{arg0}, arg1...)
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Warn", reflect.TypeOf((*MockLogger)(nil).Warn), varargs...)
+}