From 01bf0c4f4489e386f8b2a2d5e90aa288fabf9da3 Mon Sep 17 00:00:00 2001
From: Silas Davis <silas@erisindustries.com>
Date: Sat, 17 Dec 2016 18:23:31 +0000
Subject: [PATCH] Add vector valued logger
---
client/client.go | 2 +-
cmd/serve.go | 2 +
consensus/consensus.go | 3 +-
consensus/tendermint/tendermint.go | 6 +-
core/core.go | 21 +++---
logging/convention.go | 52 ++++++++++++++
logging/lifecycle/lifecycle.go | 10 ++-
logging/loggers/info_trace_logger.go | 15 ++--
logging/loggers/vector_valued_logger.go | 29 ++++++++
logging/loggers/vector_valued_logger_test.go | 17 +++++
logging/metadata.go | 5 ++
logging/structure/structure.go | 75 +++++++++++++++++---
logging/structure/structure_test.go | 11 +++
rpc/tendermint/test/common.go | 2 +
rpc/tendermint/test/shared.go | 2 +
15 files changed, 219 insertions(+), 33 deletions(-)
create mode 100644 logging/convention.go
create mode 100644 logging/loggers/vector_valued_logger.go
create mode 100644 logging/loggers/vector_valued_logger_test.go
diff --git a/client/client.go b/client/client.go
index 24eeb033..34275c8b 100644
--- a/client/client.go
+++ b/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)
}
//------------------------------------------------------------------------------------
diff --git a/cmd/serve.go b/cmd/serve.go
index 8d23e4b3..f8b99c08 100644
--- a/cmd/serve.go
+++ b/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")
diff --git a/consensus/consensus.go b/consensus/consensus.go
index 03296eed..01fc2d12 100644
--- a/consensus/consensus.go
+++ b/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)
}
diff --git a/consensus/tendermint/tendermint.go b/consensus/tendermint/tendermint.go
index 87553697..545e4c1a 100644
--- a/consensus/tendermint/tendermint.go
+++ b/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)
diff --git a/core/core.go b/core/core.go
index c4e08963..3bd32fdc 100644
--- a/core/core.go
+++ b/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,
diff --git a/logging/convention.go b/logging/convention.go
new file mode 100644
index 00000000..7a105853
--- /dev/null
+++ b/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)
+}
diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go
index fd85a324..914791fe 100644
--- a/logging/lifecycle/lifecycle.go
+++ b/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"))
}
diff --git a/logging/loggers/info_trace_logger.go b/logging/loggers/info_trace_logger.go
index 7374477a..db2e744c 100644
--- a/logging/loggers/info_trace_logger.go
+++ b/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,
diff --git a/logging/loggers/vector_valued_logger.go b/logging/loggers/vector_valued_logger.go
new file mode 100644
index 00000000..d7f50d76
--- /dev/null
+++ b/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}
+}
diff --git a/logging/loggers/vector_valued_logger_test.go b/logging/loggers/vector_valued_logger_test.go
new file mode 100644
index 00000000..d6bc54eb
--- /dev/null
+++ b/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])
+}
diff --git a/logging/metadata.go b/logging/metadata.go
index 3fbed2cf..b0ce3f3d 100644
--- a/logging/metadata.go
+++ b/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() }
+}
diff --git a/logging/structure/structure.go b/logging/structure/structure.go
index 9420b200..151fda92 100644
--- a/logging/structure/structure.go
+++ b/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
-}
\ No newline at end of file
+}
+
+// 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()
+ }
+}
diff --git a/logging/structure/structure_test.go b/logging/structure/structure_test.go
index 2fbdaa3e..36f48c52 100644
--- a/logging/structure/structure_test.go
+++ b/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))
+}
diff --git a/rpc/tendermint/test/common.go b/rpc/tendermint/test/common.go
index 76909182..a060833c 100644
--- a/rpc/tendermint/test/common.go
+++ b/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 {
diff --git a/rpc/tendermint/test/shared.go b/rpc/tendermint/test/shared.go
index 8ddce9b3..8c01b6a2 100644
--- a/rpc/tendermint/test/shared.go
+++ b/rpc/tendermint/test/shared.go
@@ -88,6 +88,8 @@ func initGlobalVariables(ffs *fixtures.FileFixtures) error {
// To spill tendermint logs on the floor:
// lifecycle.CaptureTendermintLog15Output(loggers.NewNoopInfoTraceLogger())
lifecycle.CaptureTendermintLog15Output(logger)
+ lifecycle.CaptureStdlibLogOutput(logger)
+
testCore, err = core.NewCore("testCore", consensusConfig, managerConfig,
logger)
if err != nil {
--
GitLab