Allow Go template as logging format and clean up

Signed-off-by: Silas Davis <silas@monax.io>

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 "+

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

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

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)

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

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 {

logging/loggers/output_loggers.go

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

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

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

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

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},

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])