Add vector valued logger

client/client.go

@@ -80,7 +80,7 @@ func NewErisNodeClient(rpcString string) *ErisNodeClient {
 // it needs to be initialised before go-rpc, hence it's placement here.
 func init() {
 	h := tendermint_log.LvlFilterHandler(tendermint_log.LvlWarn, tendermint_log.StdoutHandler)
-    tendermint_log.Root().SetHandler(h)
+	tendermint_log.Root().SetHandler(h)
 }
 
 //------------------------------------------------------------------------------------

cmd/serve.go

@@ -115,6 +115,8 @@ func NewCoreFromDo(do *definitions.Do) (*core.Core, error) {
 	// Capture all logging from tendermint/tendermint and tendermint/go-*
 	// dependencies
 	lifecycle.CaptureTendermintLog15Output(logger)
+	// And from stdlib go log
+	lifecycle.CaptureStdlibLogOutput(logger)
 
 	cmdLogger := logger.With("command", "serve")
 

consensus/consensus.go

@@ -28,7 +28,8 @@ func LoadConsensusEngineInPipe(moduleConfig *config.ModuleConfig,
 	pipe definitions.Pipe) error {
 	switch moduleConfig.Name {
 	case "tendermint":
-		tmint, err := tendermint.NewTendermint(moduleConfig, pipe.GetApplication())
+		tmint, err := tendermint.NewTendermint(moduleConfig, pipe.GetApplication(),
+		pipe.Logger().With())
 		if err != nil {
 			return fmt.Errorf("Failed to load Tendermint node: %v", err)
 		}

consensus/tendermint/tendermint.go

@@ -41,6 +41,7 @@ import (
 	// files  "github.com/eris-ltd/eris-db/files"
 	blockchain_types "github.com/eris-ltd/eris-db/blockchain/types"
 	consensus_types "github.com/eris-ltd/eris-db/consensus/types"
+	"github.com/eris-ltd/eris-db/logging/loggers"
 	"github.com/eris-ltd/eris-db/txs"
 	"github.com/tendermint/go-wire"
 )
@@ -57,7 +58,8 @@ var _ consensus_types.ConsensusEngine = (*Tendermint)(nil)
 var _ blockchain_types.Blockchain = (*Tendermint)(nil)
 
 func NewTendermint(moduleConfig *config.ModuleConfig,
-	application manager_types.Application) (*Tendermint, error) {
+	application manager_types.Application,
+	logger loggers.InfoTraceLogger) (*Tendermint, error) {
 	// re-assert proper configuration for module
 	if moduleConfig.Version != GetTendermintVersion().GetMinorVersionString() {
 		return nil, fmt.Errorf("Version string %s did not match %s",
@@ -74,7 +76,7 @@ func NewTendermint(moduleConfig *config.ModuleConfig,
 	tendermintConfigViper, err := config.ViperSubConfig(moduleConfig.Config, "configuration")
 	if tendermintConfigViper == nil {
 		return nil,
-				fmt.Errorf("Failed to extract Tendermint configuration subtree: %s", err)
+			fmt.Errorf("Failed to extract Tendermint configuration subtree: %s", err)
 	}
 	// wrap a copy of the viper config in a tendermint/go-config interface
 	tmintConfig := GetTendermintConfig(tendermintConfigViper)

core/core.go

@@ -22,20 +22,19 @@ import (
 	// TODO: [ben] swap out go-events with eris-db/event (currently unused)
 	events "github.com/tendermint/go-events"
 
-	log "github.com/eris-ltd/eris-logger"
-
-	config "github.com/eris-ltd/eris-db/config"
-	consensus "github.com/eris-ltd/eris-db/consensus"
-	definitions "github.com/eris-ltd/eris-db/definitions"
-	event "github.com/eris-ltd/eris-db/event"
-	manager "github.com/eris-ltd/eris-db/manager"
+	"github.com/eris-ltd/eris-db/config"
+	"github.com/eris-ltd/eris-db/consensus"
+	"github.com/eris-ltd/eris-db/definitions"
+	"github.com/eris-ltd/eris-db/event"
+	"github.com/eris-ltd/eris-db/manager"
 	// rpc_v0 is carried over from Eris-DBv0.11 and before on port 1337
 	rpc_v0 "github.com/eris-ltd/eris-db/rpc/v0"
 	// rpc_tendermint is carried over from Eris-DBv0.11 and before on port 46657
 
+	"github.com/eris-ltd/eris-db/logging"
 	"github.com/eris-ltd/eris-db/logging/loggers"
 	rpc_tendermint "github.com/eris-ltd/eris-db/rpc/tendermint/core"
-	server "github.com/eris-ltd/eris-db/server"
+	"github.com/eris-ltd/eris-db/server"
 )
 
 // Core is the high-level structure
@@ -60,15 +59,15 @@ func NewCore(chainId string,
 	if err != nil {
 		return nil, fmt.Errorf("Failed to load application pipe: %v", err)
 	}
-	log.Debug("Loaded pipe with application manager")
+	logging.TraceMsg(logger, "Loaded pipe with application manager")
 	// pass the consensus engine into the pipe
 	if e := consensus.LoadConsensusEngineInPipe(consensusConfig, pipe); e != nil {
 		return nil, fmt.Errorf("Failed to load consensus engine in pipe: %v", e)
 	}
 	tendermintPipe, err := pipe.GetTendermintPipe()
 	if err != nil {
-		log.Warn(fmt.Sprintf("Tendermint gateway not supported by %s",
-			managerConfig.Version))
+		logging.TraceMsg(logger, "Tendermint gateway not supported by manager",
+			"manager-version", managerConfig.Version)
 	}
 	return &Core{
 		chainId:        chainId,

logging/convention.go

@@ -0,0 +1,52 @@
+package logging
+
+import (
+	"github.com/eris-ltd/eris-db/logging/loggers"
+	"github.com/eris-ltd/eris-db/logging/structure"
+	"github.com/eris-ltd/eris-db/util/slice"
+	kitlog "github.com/go-kit/kit/log"
+)
+
+// Helper functions for InfoTraceLoggers, sort of extension methods to loggers
+// to centralise and establish logging conventions on top of in with the base
+// logging interface
+
+// Record structured Info log line with a message and conventional keys
+func InfoMsgVals(logger loggers.InfoTraceLogger, message string, vals ...interface{}) {
+	MsgVals(kitlog.LoggerFunc(logger.Info), message, vals...)
+}
+
+// Record structured Trace log line with a message and conventional keys
+func TraceMsgVals(logger loggers.InfoTraceLogger, message string, vals ...interface{}) {
+	MsgVals(kitlog.LoggerFunc(logger.Trace), message, vals...)
+}
+
+// Record structured Info log line with a message
+func InfoMsg(logger loggers.InfoTraceLogger, message string, keyvals ...interface{}) {
+	Msg(kitlog.LoggerFunc(logger.Info), message, keyvals...)
+}
+
+// Record structured Trace log line with a message
+func TraceMsg(logger loggers.InfoTraceLogger, message string, keyvals ...interface{}) {
+	Msg(kitlog.LoggerFunc(logger.Trace), message, keyvals...)
+}
+
+func WithScope(logger loggers.InfoTraceLogger, scopes... string) loggers.InfoTraceLogger {
+	return logger.With()
+}
+
+// Record a structured log line with a message
+func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error {
+	return logger.Log(slice.CopyPrepend(keyvals, structure.MessageKey, message))
+}
+
+// Record a structured log line with a message and conventional keys
+func MsgVals(logger kitlog.Logger, message string, vals ...interface{}) error {
+	keyvals := make([]interface{}, len(vals)*2)
+	for i := 0; i < len(vals); i++ {
+		kv := i * 2
+		keyvals[kv] = structure.KeyFromValue(vals[i])
+		keyvals[kv+1] = vals[i]
+	}
+	return Msg(logger, message, keyvals)
+}

logging/lifecycle/lifecycle.go

@@ -6,11 +6,12 @@ import (
 	"os"
 
 	"github.com/eris-ltd/eris-db/logging"
+	"github.com/eris-ltd/eris-db/logging/adapters/stdlib"
 	tmLog15adapter "github.com/eris-ltd/eris-db/logging/adapters/tendermint_log15"
 	"github.com/eris-ltd/eris-db/logging/loggers"
+	"github.com/eris-ltd/eris-db/logging/structure"
 	kitlog "github.com/go-kit/kit/log"
 	tmLog15 "github.com/tendermint/log15"
-	"github.com/eris-ltd/eris-db/logging/structure"
 )
 
 func NewLoggerFromConfig(LoggingConfig logging.LoggingConfig) loggers.InfoTraceLogger {
@@ -33,5 +34,10 @@ func NewLogger(infoLogger, traceLogger kitlog.Logger) loggers.InfoTraceLogger {
 func CaptureTendermintLog15Output(infoTraceLogger loggers.InfoTraceLogger) {
 	tmLog15.Root().SetHandler(
 		tmLog15adapter.InfoTraceLoggerAsLog15Handler(infoTraceLogger.
-			With(structure.ComponentKey, "tendermint")))
+			With(structure.ComponentKey, "tendermint_log15")))
+}
+
+func CaptureStdlibLogOutput(infoTraceLogger loggers.InfoTraceLogger) {
+	stdlib.CaptureRootLogger(infoTraceLogger.
+		With(structure.ComponentKey, "stdlib_log"))
 }

logging/loggers/info_trace_logger.go

@@ -66,15 +66,16 @@ var _ InfoTraceLogger = (*infoTraceLogger)(nil)
 var _ kitlog.Logger = (InfoTraceLogger)(nil)
 
 func NewInfoTraceLogger(infoLogger, traceLogger kitlog.Logger) InfoTraceLogger {
-	// We will never halt progress a log emitter. If log output takes too long
-	// will start dropping log lines by using a ring buffer.
+	// We will never halt the progress of a log emitter. If log output takes too
+	// long will start dropping log lines by using a ring buffer.
 	// We also guard against any concurrency bugs in underlying loggers by feeding
 	// them from a single channel
-	logger := kitlog.NewContext(NonBlockingLogger(MultipleChannelLogger(
-		map[string]kitlog.Logger{
-			InfoChannelName:  infoLogger,
-			TraceChannelName: traceLogger,
-		})))
+	logger := kitlog.NewContext(NonBlockingLogger(VectorValuedLogger(
+		MultipleChannelLogger(
+			map[string]kitlog.Logger{
+				InfoChannelName:  infoLogger,
+				TraceChannelName: traceLogger,
+			}))))
 	return &infoTraceLogger{
 		infoLogger: logger.With(
 			structure.ChannelKey, InfoChannelName,

logging/loggers/vector_valued_logger.go

@@ -0,0 +1,29 @@
+package loggers
+
+import (
+	"github.com/eris-ltd/eris-db/logging/structure"
+	kitlog "github.com/go-kit/kit/log"
+)
+
+// Treat duplicate keys
+type vectorValuedLogger struct {
+	logger kitlog.Logger
+}
+
+var _ kitlog.Logger = &vectorValuedLogger{}
+
+func (vvl *vectorValuedLogger) Log(keyvals ...interface{}) error {
+	keys, vals := structure.KeyValuesVector(keyvals)
+	kvs := make([]interface{}, len(keys)*2)
+	for i := 0; i < len(keys); i++ {
+		kv := i * 2
+		key := keys[i]
+		kvs[kv] = key
+		kvs[kv+1] = vals[key]
+	}
+	return vvl.logger.Log(kvs...)
+}
+
+func VectorValuedLogger(logger kitlog.Logger) *vectorValuedLogger {
+	return &vectorValuedLogger{logger: logger}
+}

logging/loggers/vector_valued_logger_test.go

@@ -0,0 +1,17 @@
+package loggers
+
+import (
+	"testing"
+
+	. "github.com/eris-ltd/eris-db/util/slice"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestVectorValuedLogger(t *testing.T) {
+	logger := newTestLogger()
+	vvl := VectorValuedLogger(logger)
+	vvl.Log("foo", "bar", "seen", 1, "seen", 3, "seen", 2)
+
+	assert.Equal(t, Slice("foo", "bar", "seen", Slice(1, 3, 2)),
+		logger.logLines[0])
+}

logging/metadata.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/eris-ltd/eris-db/logging/loggers"
 	"github.com/eris-ltd/eris-db/logging/structure"
+	"github.com/eris-ltd/mint-client/Godeps/_workspace/src/github.com/inconshreveable/log15/stack"
 	kitlog "github.com/go-kit/kit/log"
 )
 
@@ -25,3 +26,7 @@ func WithMetadata(infoTraceLogger loggers.InfoTraceLogger) loggers.InfoTraceLogg
 	return infoTraceLogger.With(structure.TimeKey, defaultTimestampUTCValuer,
 		structure.CallerKey, kitlog.Caller(infoTraceLoggerCallDepth))
 }
+
+func CallersValuer() kitlog.Valuer {
+	return func() interface{} { return stack.Callers() }
+}

logging/structure/structure.go

@@ -1,20 +1,29 @@
 package structure
 
-import . "github.com/eris-ltd/eris-db/util/slice"
+import (
+	"reflect"
+
+	. "github.com/eris-ltd/eris-db/util/slice"
+)
 
 const (
-	// Key for go time.Time object
+	// Log time (time.Time)
 	TimeKey = "time"
-	// Key for call site for log invocation
+	// Call site for log invocation (go-stack.Call)
 	CallerKey = "caller"
-	// Key for String name for level
-	LevelKey   = "level"
-	// Key to switch on for channel in a multiple channel logging context
+	// Level name (string)
+	LevelKey = "level"
+	// Channel name in a multiple channel logging context
 	ChannelKey = "channel"
-	// Key for string message
+	// Log message (string)
 	MessageKey = "message"
-	// Key for module or function or struct that is the subject of the logging
+	// Top-level component (choose one) name
 	ComponentKey = "component"
+	// Vector-valued scope
+	ScopeKey = "scope"
+	// Globally unique identifier persisting while a single instance (root process)
+	// of this program/service is running
+	RunId = "run_id"
 )
 
 // Pull the specified values from a structured log line into a map.
@@ -49,6 +58,42 @@ func ValuesAndContext(keyvals []interface{},
 	return vals, context
 }
 
+type vector []interface{}
+
+func newVector(vals... interface{}) vector {
+	return vals
+}
+
+func (v vector) Slice() []interface{} {
+	return v
+}
+
+// Returns the unique keys in keyvals and a map of values where values of
+// repeated keys are merged into a slice of those values in the order which they
+// appeared
+func KeyValuesVector(keyvals []interface{}) ([]interface{}, map[interface{}]interface{}) {
+	keys := []interface{}{}
+	vals := make(map[interface{}]interface{}, len(keyvals)/2)
+	for i := 0; i < 2*(len(keyvals)/2); i += 2 {
+		key := keyvals[i]
+		val := keyvals[i+1]
+		switch oldVal := vals[key].(type) {
+		case nil:
+			keys = append(keys, key)
+			vals[key] = val
+		case vector:
+			// if this is, in fact, only the second time we have seen key and the
+			// first time it had a value of []interface{} then here we are doing the
+			// wrong thing by appending val. We will end up with
+			// Slice(..., val) rather than Slice(Slice(...), val)
+			vals[key] = vector(append(oldVal, val))
+		default:
+			vals[key] = newVector(oldVal, val)
+		}
+	}
+	return keys, vals
+}
+
 // Return a single value corresponding to key in keyvals
 func Value(keyvals []interface{}, key interface{}) interface{} {
 	for i := 0; i < 2*(len(keyvals)/2); i += 2 {
@@ -57,4 +102,16 @@ func Value(keyvals []interface{}, key interface{}) interface{} {
 		}
 	}
 	return nil
-}
+}
+
+// Obtain a canonical key from a value. Useful for structured logging where the
+// type of value alone may be sufficient to determine its key. Providing this
+// function centralises any convention over type names
+func KeyFromValue(val interface{}) string {
+	switch val.(type) {
+	case string:
+		return "text"
+	default:
+		return reflect.TypeOf(val).Name()
+	}
+}

logging/structure/structure_test.go

@@ -13,3 +13,14 @@ func TestValuesAndContext(t *testing.T) {
 	assert.Equal(t, map[interface{}]interface{}{"hello": 1, "fish": 3}, vals)
 	assert.Equal(t, Slice("dog", 2, "fork", 5), ctx)
 }
+
+func TestKeyValuesToMap(t *testing.T) {
+	kvs := Slice("scope", "lawnmower",
+		"occupation", "fish brewer",
+		"scope", "hose pipe",
+		"scope", "rake")
+	assert.Equal(t, map[interface{}]interface{}{
+		"occupation": "fish brewer",
+		"scope":     Slice("lawnmower", "hose pipe", "rake")},
+		KeyValuesToMap(kvs))
+}

rpc/tendermint/test/common.go

@@ -6,6 +6,7 @@ package test
 import (
 	"fmt"
 
+	vm "github.com/eris-ltd/eris-db/manager/eris-mint/evm"
 	rpc_core "github.com/eris-ltd/eris-db/rpc/tendermint/core"
 	"github.com/eris-ltd/eris-db/test/fixtures"
 )
@@ -17,6 +18,7 @@ func TestWrapper(runner func() int) int {
 
 	defer ffs.RemoveAll()
 
+	vm.SetDebug(true)
 	err := initGlobalVariables(ffs)
 
 	if err != nil {