From abbee85352470a3268ce02614b822b08732cff99 Mon Sep 17 00:00:00 2001
From: Silas Davis <silas@monax.io>
Date: Mon, 19 Feb 2018 13:14:23 +0000
Subject: [PATCH] Allow Go template as logging format and clean up
Signed-off-by: Silas Davis <silas@monax.io>
---
execution/evm/snative.go | 3 +-
execution/evm/vm.go | 5 +-
logging/config/filter_test.go | 3 +-
logging/config/sinks.go | 4 +-
logging/lifecycle/lifecycle.go | 16 +++-
logging/loggers/burrow_format_logger.go | 26 +++---
logging/loggers/output_loggers.go | 44 ++++++++--
logging/loggers/output_loggers_test.go | 16 +++-
logging/loggers/vector_valued_logger_test.go | 3 +-
logging/structure/structure.go | 87 ++++++++++++++++----
logging/structure/structure_test.go | 27 +++++-
rpc/tm/integration/shared.go | 2 +-
12 files changed, 183 insertions(+), 53 deletions(-)
diff --git a/execution/evm/snative.go b/execution/evm/snative.go
index e98937ad..ac56a987 100644
--- a/execution/evm/snative.go
+++ b/execution/evm/snative.go
@@ -230,8 +230,7 @@ func NewSNativeContract(comment, name string,
func (contract *SNativeContractDescription) Dispatch(state acm.StateWriter, caller acm.Account,
args []byte, gas *uint64, logger logging_types.InfoTraceLogger) (output []byte, err error) {
- logger = logger.WithPrefix(structure.ComponentKey, "SNatives").
- With(structure.ScopeKey, "Dispatch", "contract_name", contract.Name)
+ logger = logger.With(structure.ScopeKey, "Dispatch", "contract_name", contract.Name)
if len(args) < abi.FunctionSelectorLength {
return nil, fmt.Errorf("SNatives dispatch requires a 4-byte function "+
diff --git a/execution/evm/vm.go b/execution/evm/vm.go
index 89a8304b..21d4d810 100644
--- a/execution/evm/vm.go
+++ b/execution/evm/vm.go
@@ -27,7 +27,6 @@ import (
"github.com/hyperledger/burrow/execution/evm/events"
"github.com/hyperledger/burrow/execution/evm/sha3"
"github.com/hyperledger/burrow/logging"
- "github.com/hyperledger/burrow/logging/structure"
logging_types "github.com/hyperledger/burrow/logging/types"
"github.com/hyperledger/burrow/permission"
ptypes "github.com/hyperledger/burrow/permission/types"
@@ -89,12 +88,12 @@ func NewVM(state acm.StateWriter, memoryProvider func() Memory, params Params, o
origin: origin,
callDepth: 0,
txid: txid,
- logger: logger.WithPrefix(structure.ComponentKey, "EVM"),
+ logger: logging.WithScope(logger, "NewVM"),
}
}
func (vm *VM) Debugf(format string, a ...interface{}) {
- logging.TraceMsg(vm.logger, fmt.Sprintf(format, a...))
+ logging.TraceMsg(vm.logger, fmt.Sprintf(format, a...), "tag", "vm_debug")
}
// satisfies go_events.Eventable
diff --git a/logging/config/filter_test.go b/logging/config/filter_test.go
index bde13531..5e847acb 100644
--- a/logging/config/filter_test.go
+++ b/logging/config/filter_test.go
@@ -91,7 +91,8 @@ func TestIncludeAllFilterPredicate(t *testing.T) {
assert.NoError(t, err)
assert.True(t, fp([]interface{}{"Foo", "bar", "Shoes", 42}))
// Don't filter, it has all the required key values
- assert.False(t, fp([]interface{}{"Foo", "bar", "Planks", 0.2, "Shoes", 42, "Bosh", "Bish"}))
+ assert.False(t, fp([]interface{}{"Foo", "bar", "Planks", 0.2, "Shoes", 42, "imBoshy", "unBishy"}))
+ assert.True(t, fp([]interface{}{"Foo", "bar", "Planks", 0.23, "Shoes", 42, "imBoshy", "unBishy"}))
assert.True(t, fp([]interface{}{"Food", 0.2, "Shoes", 42}))
}
diff --git a/logging/config/sinks.go b/logging/config/sinks.go
index 3974fd5f..169e886f 100644
--- a/logging/config/sinks.go
+++ b/logging/config/sinks.go
@@ -322,9 +322,9 @@ func BuildOutputLogger(outputConfig *OutputConfig) (kitlog.Logger, error) {
case File:
return loggers.NewFileLogger(outputConfig.FileConfig.Path, outputConfig.Format)
case Stdout:
- return loggers.NewStreamLogger(os.Stdout, outputConfig.Format), nil
+ return loggers.NewStreamLogger(os.Stdout, outputConfig.Format)
case Stderr:
- return loggers.NewStreamLogger(os.Stderr, outputConfig.Format), nil
+ return loggers.NewStreamLogger(os.Stderr, outputConfig.Format)
default:
return nil, fmt.Errorf("could not build logger for output: '%s'",
outputConfig.OutputType)
diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go
index d6992a94..8d9428fd 100644
--- a/logging/lifecycle/lifecycle.go
+++ b/logging/lifecycle/lifecycle.go
@@ -41,8 +41,12 @@ import (
func NewLoggerFromLoggingConfig(loggingConfig *config.LoggingConfig) (types.InfoTraceLogger, error) {
var logger types.InfoTraceLogger
var errCh channels.Channel
+ var err error
if loggingConfig == nil {
- logger, errCh = NewStdErrLogger()
+ logger, errCh, err = NewStdErrLogger()
+ if err != nil {
+ return nil, err
+ }
} else {
outputLogger, err := infoTraceLoggerFromLoggingConfig(loggingConfig)
if err != nil {
@@ -74,9 +78,13 @@ func SwapOutputLoggersFromLoggingConfig(logger types.InfoTraceLogger,
return nil
}
-func NewStdErrLogger() (types.InfoTraceLogger, channels.Channel) {
- logger := loggers.NewStreamLogger(os.Stderr, "terminal")
- return NewLogger(logger)
+func NewStdErrLogger() (types.InfoTraceLogger, channels.Channel, error) {
+ logger, err := loggers.NewStreamLogger(os.Stderr, loggers.TerminalFormat)
+ if err != nil {
+ return nil, nil, err
+ }
+ itLogger, errCh := NewLogger(logger)
+ return itLogger, errCh, nil
}
// Provided a standard logger that outputs to the supplied underlying outputLogger
diff --git a/logging/loggers/burrow_format_logger.go b/logging/loggers/burrow_format_logger.go
index d0a9a410..51f025e7 100644
--- a/logging/loggers/burrow_format_logger.go
+++ b/logging/loggers/burrow_format_logger.go
@@ -41,21 +41,17 @@ func (bfl *burrowFormatLogger) Log(keyvals ...interface{}) error {
return fmt.Errorf("log line contains an odd number of elements so "+
"was dropped: %v", keyvals)
}
- return bfl.logger.Log(structure.MapKeyValues(keyvals, burrowFormatKeyValueMapper)...)
-}
-
-func burrowFormatKeyValueMapper(key, value interface{}) (interface{}, interface{}) {
- switch key {
- default:
- switch v := value.(type) {
- case []byte:
- return key, fmt.Sprintf("%X", v)
- case time.Time:
- return key, v.Format(time.RFC3339Nano)
- }
-
- }
- return key, fmt.Sprintf("%v", value)
+ return bfl.logger.Log(structure.MapKeyValues(keyvals,
+ func(key interface{}, value interface{}) (interface{}, interface{}) {
+ switch v := value.(type) {
+ case string:
+ case []byte:
+ value = fmt.Sprintf("%X", v)
+ case time.Time:
+ value = v.Format(time.RFC3339Nano)
+ }
+ return structure.StringifyKey(key), value
+ })...)
}
func BurrowFormatLogger(logger kitlog.Logger) *burrowFormatLogger {
diff --git a/logging/loggers/output_loggers.go b/logging/loggers/output_loggers.go
index 6cd2e3d2..c39d3873 100644
--- a/logging/loggers/output_loggers.go
+++ b/logging/loggers/output_loggers.go
@@ -1,9 +1,10 @@
package loggers
import (
+ "fmt"
"io"
-
"os"
+ "text/template"
kitlog "github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/term"
@@ -19,14 +20,21 @@ const (
defaultFormatName = TerminalFormat
)
-func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger {
+const (
+ newline = '\n'
+)
+
+func NewStreamLogger(writer io.Writer, format string) (kitlog.Logger, error) {
var logger kitlog.Logger
- switch formatName {
+ var err error
+ switch format {
+ case "":
+ return NewStreamLogger(writer, defaultFormatName)
case JSONFormat:
logger = kitlog.NewJSONLogger(writer)
case LogfmtFormat:
logger = kitlog.NewLogfmtLogger(writer)
- default:
+ case TerminalFormat:
logger = term.NewLogger(writer, kitlog.NewLogfmtLogger, func(keyvals ...interface{}) term.FgBgColor {
switch structure.Value(keyvals, structure.ChannelKey) {
case types.TraceChannelName:
@@ -35,6 +43,12 @@ func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger {
return term.FgBgColor{Fg: term.Yellow}
}
})
+ default:
+ logger, err = NewTemplateLogger(writer, format, []byte{})
+ if err != nil {
+ return nil, fmt.Errorf("did not recognise format '%s' as named format and could not parse as "+
+ "template: %v", format, err)
+ }
}
// Don't log signals
return kitlog.LoggerFunc(func(keyvals ...interface{}) error {
@@ -42,7 +56,7 @@ func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger {
return nil
}
return logger.Log(keyvals...)
- })
+ }), nil
}
func NewFileLogger(path string, formatName string) (kitlog.Logger, error) {
@@ -50,7 +64,10 @@ func NewFileLogger(path string, formatName string) (kitlog.Logger, error) {
if err != nil {
return nil, err
}
- streamLogger := NewStreamLogger(f, formatName)
+ streamLogger, err := NewStreamLogger(f, formatName)
+ if err != nil {
+ return nil, err
+ }
return kitlog.LoggerFunc(func(keyvals ...interface{}) error {
if logging.Signal(keyvals) == structure.SyncSignal {
return f.Sync()
@@ -58,3 +75,18 @@ func NewFileLogger(path string, formatName string) (kitlog.Logger, error) {
return streamLogger.Log(keyvals...)
}), nil
}
+
+func NewTemplateLogger(writer io.Writer, textTemplate string, recordSeparator []byte) (kitlog.Logger, error) {
+ tmpl, err := template.New("template-logger").Parse(textTemplate)
+ if err != nil {
+ return nil, err
+ }
+ return kitlog.LoggerFunc(func(keyvals ...interface{}) error {
+ err := tmpl.Execute(writer, structure.KeyValuesMap(keyvals))
+ if err == nil {
+ _, err = writer.Write(recordSeparator)
+ }
+ return err
+ }), nil
+
+}
diff --git a/logging/loggers/output_loggers_test.go b/logging/loggers/output_loggers_test.go
index 7c229c66..77e948fc 100644
--- a/logging/loggers/output_loggers_test.go
+++ b/logging/loggers/output_loggers_test.go
@@ -32,8 +32,9 @@ func TestNewFileLogger(t *testing.T) {
func TestNewStreamLogger(t *testing.T) {
buf := new(bytes.Buffer)
- logger := NewStreamLogger(buf, LogfmtFormat)
- err := logger.Log("oh", "my")
+ logger, err := NewStreamLogger(buf, LogfmtFormat)
+ require.NoError(t, err)
+ err = logger.Log("oh", "my")
require.NoError(t, err)
err = logging.Sync(logger)
@@ -41,3 +42,14 @@ func TestNewStreamLogger(t *testing.T) {
assert.Equal(t, "oh=my\n", string(buf.Bytes()))
}
+
+func TestNewTemplateLogger(t *testing.T) {
+ buf := new(bytes.Buffer)
+ logger, err := NewTemplateLogger(buf, "Why Hello {{.name}}", []byte{'\n'})
+ require.NoError(t, err)
+ err = logger.Log("name", "Marjorie Stewart-Baxter", "fingertip_width_cm", float32(1.34))
+ require.NoError(t, err)
+ err = logger.Log("name", "Fred")
+ require.NoError(t, err)
+ assert.Equal(t, "Why Hello Marjorie Stewart-Baxter\nWhy Hello Fred\n", buf.String())
+}
diff --git a/logging/loggers/vector_valued_logger_test.go b/logging/loggers/vector_valued_logger_test.go
index b5510688..8b60e359 100644
--- a/logging/loggers/vector_valued_logger_test.go
+++ b/logging/loggers/vector_valued_logger_test.go
@@ -17,6 +17,7 @@ package loggers
import (
"testing"
+ "github.com/hyperledger/burrow/logging/structure"
"github.com/stretchr/testify/assert"
)
@@ -26,6 +27,6 @@ func TestVectorValuedLogger(t *testing.T) {
vvl.Log("foo", "bar", "seen", 1, "seen", 3, "seen", 2)
lls, err := logger.logLines(1)
assert.NoError(t, err)
- assert.Equal(t, []interface{}{"foo", "bar", "seen", []interface{}{1, 3, 2}},
+ assert.Equal(t, []interface{}{"foo", "bar", "seen", structure.Vector{1, 3, 2}},
lls[0])
}
diff --git a/logging/structure/structure.go b/logging/structure/structure.go
index 06520da3..97cfd7d3 100644
--- a/logging/structure/structure.go
+++ b/logging/structure/structure.go
@@ -14,6 +14,11 @@
package structure
+import (
+ "encoding/json"
+ "fmt"
+)
+
const (
// Log time (time.Time)
TimeKey = "time"
@@ -49,9 +54,9 @@ const (
// Returns a map of the key-values from the requested keys and
// the unmatched remainder keyvals as context as a slice of key-values.
func ValuesAndContext(keyvals []interface{},
- keys ...interface{}) (map[interface{}]interface{}, []interface{}) {
+ keys ...interface{}) (map[string]interface{}, []interface{}) {
- vals := make(map[interface{}]interface{}, len(keys))
+ vals := make(map[string]interface{}, len(keys))
context := make([]interface{}, len(keyvals))
copy(context, keyvals)
deletions := 0
@@ -62,7 +67,7 @@ func ValuesAndContext(keyvals []interface{},
for k := 0; k < len(keys); k++ {
if keyvals[i] == keys[k] {
// Pull the matching key-value pair into vals to return
- vals[keys[k]] = keyvals[i+1]
+ vals[StringifyKey(keys[k])] = keyvals[i+1]
// Delete the key once it's found
keys = DeleteAt(keys, k)
// And remove the key-value pair from context
@@ -77,19 +82,36 @@ func ValuesAndContext(keyvals []interface{},
return vals, context
}
+// Returns keyvals as a map from keys to vals
+func KeyValuesMap(keyvals []interface{}) map[string]interface{} {
+ length := len(keyvals) / 2
+ vals := make(map[string]interface{}, length)
+ for i := 0; i < 2*length; i += 2 {
+ vals[StringifyKey(keyvals[i])] = keyvals[i+1]
+ }
+ return vals
+}
+
+func RemoveKeys(keyvals []interface{}, dropKeys ...interface{}) []interface{} {
+ return DropKeys(keyvals, func(key, value interface{}) bool {
+ for _, dropKey := range dropKeys {
+ if key == dropKey {
+ return true
+ }
+ }
+ return false
+ })
+}
+
// Drops all key value pairs where the key is in keys
-func RemoveKeys(keyvals []interface{}, keys ...interface{}) []interface{} {
- keyvalsWithoutKeys := make([]interface{}, 0, len(keyvals))
-NEXT_KEYVAL:
+func DropKeys(keyvals []interface{}, dropKeyValPredicate func(key, value interface{}) bool) []interface{} {
+ keyvalsDropped := make([]interface{}, 0, len(keyvals))
for i := 0; i < 2*(len(keyvals)/2); i += 2 {
- for _, key := range keys {
- if keyvals[i] == key {
- continue NEXT_KEYVAL
- }
+ if !dropKeyValPredicate(keyvals[i], keyvals[i+1]) {
+ keyvalsDropped = append(keyvalsDropped, keyvals[i], keyvals[i+1])
}
- keyvalsWithoutKeys = append(keyvalsWithoutKeys, keyvals[i], keyvals[i+1])
}
- return keyvalsWithoutKeys
+ return keyvalsDropped
}
// Stateful index that tracks the location of a possible vector value
@@ -100,6 +122,25 @@ type vectorValueindex struct {
vector bool
}
+// To help with downstream serialisation
+type Vector []interface{}
+
+func (v Vector) Slice() []interface{} {
+ return v
+}
+
+func (v Vector) String() string {
+ return fmt.Sprintf("%v", v.Slice())
+}
+
+func (v Vector) MarshalJSON() ([]byte, error) {
+ return json.Marshal(v.Slice())
+}
+
+func (v Vector) MarshalText() ([]byte, error) {
+ return []byte(v.String()), nil
+}
+
// 'Vectorises' values associated with repeated string keys member by collapsing many values into a single vector value.
// The result is a copy of keyvals where the first occurrence of each matching key and its first value are replaced by
// that key and all of its values in a single slice.
@@ -128,11 +169,11 @@ func Vectorise(keyvals []interface{}, vectorKeys ...string) []interface{} {
vi := valueIndices[k]
if !vi.vector {
// This must be the only second occurrence of the key so now vectorise the value
- outputKeyvals[vi.valueIndex] = []interface{}{outputKeyvals[vi.valueIndex]}
+ outputKeyvals[vi.valueIndex] = Vector([]interface{}{outputKeyvals[vi.valueIndex]})
vi.vector = true
}
// Grow the vector value
- outputKeyvals[vi.valueIndex] = append(outputKeyvals[vi.valueIndex].([]interface{}), val)
+ outputKeyvals[vi.valueIndex] = append(outputKeyvals[vi.valueIndex].(Vector), val)
// We are now running two more elements behind the input keyvals because we have absorbed this key-value pair
elided += 2
}
@@ -188,3 +229,21 @@ func CopyPrepend(slice []interface{}, elements ...interface{}) []interface{} {
}
return newSlice
}
+
+// Provides a canonical way to stringify keys
+func StringifyKey(key interface{}) string {
+ switch key {
+ // For named keys we want to handle explicitly
+
+ default:
+ // Stringify keys
+ switch k := key.(type) {
+ case string:
+ return k
+ case fmt.Stringer:
+ return k.String()
+ default:
+ return fmt.Sprintf("%v", key)
+ }
+ }
+}
diff --git a/logging/structure/structure_test.go b/logging/structure/structure_test.go
index 995c187c..a5c96e39 100644
--- a/logging/structure/structure_test.go
+++ b/logging/structure/structure_test.go
@@ -27,6 +27,24 @@ func TestValuesAndContext(t *testing.T) {
assert.Equal(t, []interface{}{"dog", 2, "fork", 5}, ctx)
}
+func TestKeyValuesMap(t *testing.T) {
+ keyvals := []interface{}{
+ [][]interface{}{{2}}, 3,
+ "hello", 1,
+ "fish", 3,
+ "dog", 2,
+ "fork", 5,
+ }
+ vals := KeyValuesMap(keyvals)
+ assert.Equal(t, map[string]interface{}{
+ "[[2]]": 3,
+ "hello": 1,
+ "fish": 3,
+ "dog": 2,
+ "fork": 5,
+ }, vals)
+}
+
func TestVectorise(t *testing.T) {
kvs := []interface{}{
"scope", "lawnmower",
@@ -41,14 +59,19 @@ func TestVectorise(t *testing.T) {
kvsVector := Vectorise(kvs, "occupation", "scope")
// Vectorise scope
assert.Equal(t, []interface{}{
- "scope", []interface{}{"lawnmower", "hose pipe", "rake"},
+ "scope", Vector{"lawnmower", "hose pipe", "rake"},
"hub", "budub",
"occupation", "fish brewer",
- "flub", []interface{}{"dub", "brub"},
+ "flub", Vector{"dub", "brub"},
},
kvsVector)
}
+func TestVector_String(t *testing.T) {
+ vec := Vector{"one", "two", "grue"}
+ assert.Equal(t, "[one two grue]", vec.String())
+}
+
func TestRemoveKeys(t *testing.T) {
// Remove multiple of same key
assert.Equal(t, []interface{}{"Fish", 9},
diff --git a/rpc/tm/integration/shared.go b/rpc/tm/integration/shared.go
index 045debe8..a12358f1 100644
--- a/rpc/tm/integration/shared.go
+++ b/rpc/tm/integration/shared.go
@@ -81,7 +81,7 @@ func TestWrapper(runner func() int) int {
tmConf := tm_config.DefaultConfig()
logger := loggers.NewNoopInfoTraceLogger()
if debugLogging {
- logger, _ = lifecycle.NewStdErrLogger()
+ logger, _, _ = lifecycle.NewStdErrLogger()
}
privValidator := validator.NewPrivValidatorMemory(privateAccounts[0], privateAccounts[0])
--
GitLab