From 5595b0d8b12c8f2d8d73331b4d7c90d402573000 Mon Sep 17 00:00:00 2001 From: Silas Davis <silas@monax.io> Date: Mon, 8 Jan 2018 12:16:06 +0000 Subject: [PATCH] Logging: various tweaks to aid with debugging and improve output. Added language for building logging configs from preset sink tree builders. Signed-off-by: Silas Davis <silas@monax.io> --- logging/adapters/tendermint_log15/capture.go | 124 ------------ logging/config/config.go | 28 ++- logging/config/config_test.go | 48 ++--- logging/config/filter.go | 7 +- logging/config/filter_test.go | 29 ++- logging/config/presets/instructions.go | 198 +++++++++++++++++++ logging/config/presets/instructions_test.go | 41 ++++ logging/config/sinks.go | 165 ++++++++-------- logging/config/sort.go | 3 + logging/convention.go | 11 +- logging/lifecycle/lifecycle.go | 8 +- logging/lifecycle/lifecycle_test.go | 23 --- logging/loggers/burrow_format_logger.go | 13 +- logging/loggers/filter_logger.go | 27 +-- logging/loggers/filter_logger_test.go | 5 +- logging/loggers/info_trace_logger.go | 3 +- logging/loggers/output_loggers.go | 54 ++--- logging/loggers/shared_test.go | 9 +- logging/loggers/sort_logger.go | 68 +++++++ logging/loggers/sort_logger_test.go | 31 +++ logging/loggers/vector_valued_logger_test.go | 3 +- logging/metadata.go | 1 - logging/structure/structure.go | 26 ++- logging/structure/structure_test.go | 45 +++-- util/logging/cmd/main.go | 3 +- 25 files changed, 579 insertions(+), 394 deletions(-) delete mode 100644 logging/adapters/tendermint_log15/capture.go create mode 100644 logging/config/presets/instructions.go create mode 100644 logging/config/presets/instructions_test.go create mode 100644 logging/config/sort.go create mode 100644 logging/loggers/sort_logger.go create mode 100644 logging/loggers/sort_logger_test.go diff --git a/logging/adapters/tendermint_log15/capture.go b/logging/adapters/tendermint_log15/capture.go deleted file mode 100644 index 1ad8550f..00000000 --- a/logging/adapters/tendermint_log15/capture.go +++ /dev/null @@ -1,124 +0,0 @@ -// Copyright 2017 Monax Industries Limited -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package tendermint_log15 - -import ( - "time" - - kitlog "github.com/go-kit/kit/log" - "github.com/go-stack/stack" - "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" - . "github.com/hyperledger/burrow/util/slice" - "github.com/tendermint/log15" -) - -type infoTraceLoggerAsLog15Handler struct { - logger types.InfoTraceLogger -} - -var _ log15.Handler = (*infoTraceLoggerAsLog15Handler)(nil) - -type log15HandlerAsKitLogger struct { - handler log15.Handler -} - -var _ kitlog.Logger = (*log15HandlerAsKitLogger)(nil) - -func (l *log15HandlerAsKitLogger) Log(keyvals ...interface{}) error { - record := LogLineToRecord(keyvals...) - return l.handler.Log(record) -} - -func (h *infoTraceLoggerAsLog15Handler) Log(record *log15.Record) error { - if record.Lvl < log15.LvlDebug { - // Send to Critical, Warning, Error, and Info to the Info channel - h.logger.Info(RecordToLogLine(record)...) - } else { - // Send to Debug to the Trace channel - h.logger.Trace(RecordToLogLine(record)...) - } - return nil -} - -func Log15HandlerAsKitLogger(handler log15.Handler) kitlog.Logger { - return &log15HandlerAsKitLogger{ - handler: handler, - } -} - -func InfoTraceLoggerAsLog15Handler(logger types.InfoTraceLogger) log15.Handler { - return &infoTraceLoggerAsLog15Handler{ - logger: logger, - } -} - -// Convert a go-kit log line (i.e. keyvals... interface{}) into a log15 record -// This allows us to use log15 output handlers -func LogLineToRecord(keyvals ...interface{}) *log15.Record { - vals, ctx := structure.ValuesAndContext(keyvals, structure.TimeKey, - structure.MessageKey, structure.CallerKey, structure.LevelKey) - - // Mapping of log line to Record is on a best effort basis - theTime, _ := vals[structure.TimeKey].(time.Time) - call, _ := vals[structure.CallerKey].(stack.Call) - level, _ := vals[structure.LevelKey].(string) - message, _ := vals[structure.MessageKey].(string) - - return &log15.Record{ - Time: theTime, - Lvl: Log15LvlFromString(level), - Msg: message, - Call: call, - Ctx: ctx, - KeyNames: log15.RecordKeyNames{ - Time: structure.TimeKey, - Msg: structure.MessageKey, - Lvl: structure.LevelKey, - }} -} - -// Convert a log15 record to a go-kit log line (i.e. keyvals... interface{}) -// This allows us to capture output from dependencies using log15 -func RecordToLogLine(record *log15.Record) []interface{} { - return Concat( - Slice( - structure.CallerKey, record.Call, - structure.LevelKey, record.Lvl.String(), - ), - record.Ctx, - Slice( - structure.MessageKey, record.Msg, - )) -} - -// Collapse our weak notion of leveling and log15's into a log15.Lvl -func Log15LvlFromString(level string) log15.Lvl { - if level == "" { - return log15.LvlDebug - } - switch level { - case types.InfoLevelName: - return log15.LvlInfo - case types.TraceLevelName: - return log15.LvlDebug - default: - lvl, err := log15.LvlFromString(level) - if err == nil { - return lvl - } - return log15.LvlDebug - } -} diff --git a/logging/config/config.go b/logging/config/config.go index f620f816..9eba4085 100644 --- a/logging/config/config.go +++ b/logging/config/config.go @@ -6,16 +6,18 @@ import ( "github.com/hyperledger/burrow/logging/structure" + "encoding/json" + "github.com/BurntSushi/toml" ) type LoggingConfig struct { - RootSink *SinkConfig `toml:"root_sink,omitempty"` + RootSink *SinkConfig `toml:",omitempty"` } // For encoding a top-level '[logging]' TOML table type LoggingConfigWrapper struct { - Logging *LoggingConfig `toml:"logging"` + Logging *LoggingConfig `toml:",omitempty"` } func DefaultNodeLoggingConfig() *LoggingConfig { @@ -36,11 +38,19 @@ func DefaultClientLoggingConfig() *LoggingConfig { // Returns the TOML for a top-level logging config wrapped with [logging] func (lc *LoggingConfig) RootTOMLString() string { - return tomlString(LoggingConfigWrapper{lc}) + return TOMLString(LoggingConfigWrapper{lc}) } func (lc *LoggingConfig) TOMLString() string { - return tomlString(lc) + return TOMLString(lc) +} + +func (lc *LoggingConfig) RootJSONString() string { + return JSONString(LoggingConfigWrapper{lc}) +} + +func (lc *LoggingConfig) JSONString() string { + return JSONString(lc) } func LoggingConfigFromMap(loggingRootMap map[string]interface{}) (*LoggingConfig, error) { @@ -65,7 +75,7 @@ func LoggingConfigFromMap(loggingRootMap map[string]interface{}) (*LoggingConfig return lc, nil } -func tomlString(v interface{}) string { +func TOMLString(v interface{}) string { buf := new(bytes.Buffer) encoder := toml.NewEncoder(buf) err := encoder.Encode(v) @@ -75,3 +85,11 @@ func tomlString(v interface{}) string { } return buf.String() } + +func JSONString(v interface{}) string { + bs, err := json.MarshalIndent(v, "", "\t") + if err != nil { + return fmt.Sprintf("Error encoding JSON: %s", err) + } + return string(bs) +} diff --git a/logging/config/config_test.go b/logging/config/config_test.go index de53dd3a..089710aa 100644 --- a/logging/config/config_test.go +++ b/logging/config/config_test.go @@ -1,42 +1,32 @@ package config import ( - "strings" "testing" "github.com/BurntSushi/toml" - "github.com/spf13/viper" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) -var complexConfig *LoggingConfig = &LoggingConfig{ - RootSink: Sink(). - SetTransform(LabelTransform(false, "Info", "Trace")). - AddSinks( - Sink(). - SetOutput(StdoutOutput()). - SetTransform(FilterTransform(ExcludeWhenAnyMatches, - "Foo", "Bars")). - AddSinks( - Sink(). - SetOutput(RemoteSyslogOutput("Eris-db", "tcp://example.com:6514")), - Sink(). - SetOutput(StdoutOutput()), - ), - ), -} - func TestLoggingConfig_String(t *testing.T) { + complexConfig := &LoggingConfig{ + RootSink: Sink(). + SetTransform(LabelTransform(false, "Info", "Trace")). + AddSinks( + Sink(). + SetOutput(StdoutOutput()). + SetTransform(FilterTransform(ExcludeWhenAnyMatches, + "Foo", "Bars")). + AddSinks( + Sink(). + SetOutput(StderrOutput()), + Sink(). + SetOutput(StdoutOutput()), + ), + ), + } lc := new(LoggingConfig) - toml.Decode(complexConfig.TOMLString(), lc) - assert.Equal(t, complexConfig, lc) -} - -func TestReadViperConfig(t *testing.T) { - conf := viper.New() - conf.SetConfigType("toml") - conf.ReadConfig(strings.NewReader(complexConfig.TOMLString())) - lc, err := LoggingConfigFromMap(conf.AllSettings()) - assert.NoError(t, err) + _, err := toml.Decode(complexConfig.TOMLString(), lc) + require.NoError(t, err) assert.Equal(t, complexConfig, lc) } diff --git a/logging/config/filter.go b/logging/config/filter.go index 1ddf35ff..d4d4aede 100644 --- a/logging/config/filter.go +++ b/logging/config/filter.go @@ -4,8 +4,6 @@ import ( "fmt" "regexp" - - "github.com/hyperledger/burrow/common/math/integral" ) func BuildFilterPredicate(filterConfig *FilterConfig) (func([]interface{}) bool, error) { @@ -59,7 +57,10 @@ func matchLogLine(keyvals []interface{}, keyRegexes, valueRegexes []*regexp.Rege all := matchAll // We should be passed an aligned list of keyRegexes and valueRegexes, but since we can't error here we'll guard // against a failure of the caller to pass valid arguments - length := integral.MinInt(len(keyRegexes), len(valueRegexes)) + length := len(keyRegexes) + if len(valueRegexes) < length { + length = len(valueRegexes) + } for i := 0; i < length; i++ { matched := findMatchInLogLine(keyvals, keyRegexes[i], valueRegexes[i]) if matchAll { diff --git a/logging/config/filter_test.go b/logging/config/filter_test.go index 3c5edf5a..bde13531 100644 --- a/logging/config/filter_test.go +++ b/logging/config/filter_test.go @@ -3,7 +3,6 @@ package config import ( "testing" - . "github.com/hyperledger/burrow/util/slice" "github.com/stretchr/testify/assert" ) @@ -16,7 +15,7 @@ func TestBuildKeyValuesPredicateMatchAll(t *testing.T) { } kvp, err := BuildKeyValuesPredicate(conf, true) assert.NoError(t, err) - assert.True(t, kvp(Slice("Foo", "bar", "Bosh", "Bish"))) + assert.True(t, kvp([]interface{}{"Foo", "bar", "Bosh", "Bish"})) } func TestBuildKeyValuesPredicateMatchAny(t *testing.T) { @@ -28,7 +27,7 @@ func TestBuildKeyValuesPredicateMatchAny(t *testing.T) { } kvp, err := BuildKeyValuesPredicate(conf, false) assert.NoError(t, err) - assert.True(t, kvp(Slice("Foo", "bar", "Bosh", "Bish"))) + assert.True(t, kvp([]interface{}{"Foo", "bar", "Bosh", "Bish"})) } func TestExcludeAllFilterPredicate(t *testing.T) { @@ -47,9 +46,9 @@ func TestExcludeAllFilterPredicate(t *testing.T) { } fp, err := BuildFilterPredicate(fc) assert.NoError(t, err) - assert.False(t, fp(Slice("Bosh", "Bash", "Shoes", 42))) - assert.True(t, fp(Slice("Bosh", "Bash", "Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) - assert.False(t, fp(Slice("Food", 0.2, "Shoes", 42))) + assert.False(t, fp([]interface{}{"Bosh", "Bash", "Shoes", 42})) + assert.True(t, fp([]interface{}{"Bosh", "Bash", "Foo", "bar", "Shoes", 42, "Bosh", "Bish"})) + assert.False(t, fp([]interface{}{"Food", 0.2, "Shoes", 42})) } func TestExcludeAnyFilterPredicate(t *testing.T) { @@ -68,9 +67,9 @@ func TestExcludeAnyFilterPredicate(t *testing.T) { } fp, err := BuildFilterPredicate(fc) assert.NoError(t, err) - assert.False(t, fp(Slice("Foo", "bar", "Shoes", 42))) - assert.True(t, fp(Slice("Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) - assert.True(t, fp(Slice("Food", 0.2, "Shoes", 42, "Bosh", "Bish"))) + assert.False(t, fp([]interface{}{"Foo", "bar", "Shoes", 42})) + assert.True(t, fp([]interface{}{"Foo", "bar", "Shoes", 42, "Bosh", "Bish"})) + assert.True(t, fp([]interface{}{"Food", 0.2, "Shoes", 42, "Bosh", "Bish"})) } @@ -90,10 +89,10 @@ func TestIncludeAllFilterPredicate(t *testing.T) { } fp, err := BuildFilterPredicate(fc) assert.NoError(t, err) - assert.True(t, fp(Slice("Foo", "bar", "Shoes", 42))) + assert.True(t, fp([]interface{}{"Foo", "bar", "Shoes", 42})) // Don't filter, it has all the required key values - assert.False(t, fp(Slice("Foo", "bar", "Planks", 0.2, "Shoes", 42, "Bosh", "Bish"))) - assert.True(t, fp(Slice("Food", 0.2, "Shoes", 42))) + assert.False(t, fp([]interface{}{"Foo", "bar", "Planks", 0.2, "Shoes", 42, "Bosh", "Bish"})) + assert.True(t, fp([]interface{}{"Food", 0.2, "Shoes", 42})) } func TestIncludeAnyFilterPredicate(t *testing.T) { @@ -112,8 +111,8 @@ func TestIncludeAnyFilterPredicate(t *testing.T) { } fp, err := BuildFilterPredicate(fc) assert.NoError(t, err) - assert.False(t, fp(Slice("Foo", "bar", "Shoes", 3427))) - assert.False(t, fp(Slice("Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) - assert.False(t, fp(Slice("Food", 0.2, "Shoes", 42))) + assert.False(t, fp([]interface{}{"Foo", "bar", "Shoes", 3427})) + assert.False(t, fp([]interface{}{"Foo", "bar", "Shoes", 42, "Bosh", "Bish"})) + assert.False(t, fp([]interface{}{"Food", 0.2, "Shoes", 42})) } diff --git a/logging/config/presets/instructions.go b/logging/config/presets/instructions.go new file mode 100644 index 00000000..2844ae8b --- /dev/null +++ b/logging/config/presets/instructions.go @@ -0,0 +1,198 @@ +package presets + +import ( + "fmt" + + "github.com/hyperledger/burrow/logging/config" + "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" +) + +// Function to generate part of a tree of Sinks (e.g. append a single child node, or an entire subtree). +// Each Instruction takes a (sub)root, which it may modify, and appends further child sinks below that root. +// Returning the new subroot from which to apply any further Presets. +// When chained together in a pre-order instructions can be composed to form an entire Sink tree. +type Instruction struct { + name string + desc string + // The builder for the Instruction is a function that may modify the stack or ops string. Typically + // by mutating the sink at the top of the stack and may move the cursor or by pushing child sinks + // to the stack. The builder may also return a modified ops slice whereby it may insert Instruction calls + // acting as a macro or consume ops as arguments. + builder func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) +} + +func (i Instruction) Name() string { + return i.name +} + +func (i Instruction) Description() string { + return i.desc +} + +const ( + Info = "info" + Minimal = "minimal" + IncludeAny = "include-any" + Stderr = "stderr" + Stdout = "stdout" + Terminal = "terminal" + Up = "up" + Down = "down" +) + +var instructions = []Instruction{ + { + name: Up, + desc: "Ascend the sink tree by travelling up the stack to the previous sink recorded on the stack", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + return pop(stack), ops, nil + }, + }, + { + name: Down, + desc: "Descend the sink tree by inserting a sink as a child to the current sink and adding it to the stack", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + return push(stack, config.Sink()), ops, nil + }, + }, + { + name: Minimal, + desc: "A generally less chatty log output, follow with output options", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + return push(stack, + config.Sink().SetTransform(config.PruneTransform(structure.TraceKey, structure.RunId)), + config.Sink().SetTransform(config.FilterTransform(config.IncludeWhenAllMatch, + structure.ChannelKey, types.InfoChannelName)), + config.Sink().SetTransform(config.FilterTransform(config.ExcludeWhenAnyMatches, + structure.ComponentKey, "Tendermint", + "module", "p2p", + "module", "mempool"))), + ops, nil + }, + }, + { + name: IncludeAny, + desc: "Establish an 'include when any predicate matches' filter transform at this this sink", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + sink := peek(stack) + ensureFilter(sink) + sink.Transform.FilterConfig.FilterMode = config.IncludeWhenAnyMatches + return stack, ops, nil + }, + }, + { + name: Info, + desc: "Add a filter predicate to match the Info logging channel", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + sink := peek(stack) + ensureFilter(sink) + sink.Transform.FilterConfig.AddPredicate(structure.ChannelKey, types.InfoChannelName) + return stack, ops, nil + }, + }, + { + name: Stdout, + desc: "Use Stdout output for this sink", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + sink := peek(stack) + ensureOutput(sink) + sink.Output.OutputType = config.Stdout + return stack, ops, nil + }, + }, + { + name: Stderr, + desc: "Use Stderr output for this sink", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + sink := peek(stack) + ensureOutput(sink) + sink.Output.OutputType = config.Stderr + return stack, ops, nil + }, + }, + { + name: Terminal, + desc: "Use the the terminal output format for this sink", + builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { + sink := peek(stack) + ensureOutput(sink) + sink.Output.Format = loggers.TerminalFormat + return stack, ops, nil + }, + }, +} + +var instructionsMap map[string]Instruction + +func init() { + instructionsMap = make(map[string]Instruction, len(instructions)) + for _, p := range instructions { + instructionsMap[p.name] = p + } +} + +func Instructons() []Instruction { + ins := make([]Instruction, len(instructions)) + copy(ins, instructions) + return ins +} + +func Describe(name string) string { + preset, ok := instructionsMap[name] + if !ok { + return fmt.Sprintf("No logging preset named '%s'", name) + } + return preset.desc +} + +func BuildSinkConfig(ops ...string) (*config.SinkConfig, error) { + stack := []*config.SinkConfig{config.Sink()} + var err error + for len(ops) > 0 { + // Keep applying instructions until their are no ops left + preset, ok := instructionsMap[ops[0]] + if !ok { + return nil, fmt.Errorf("could not find logging preset '%s'", ops[0]) + } + stack, ops, err = preset.builder(stack, ops[1:]) + if err != nil { + return nil, err + } + } + return stack[0], nil +} + +func ensureFilter(sinkConfig *config.SinkConfig) { + if sinkConfig.Transform == nil { + sinkConfig.Transform = &config.TransformConfig{} + } + if sinkConfig.Transform.FilterConfig == nil { + sinkConfig.Transform.FilterConfig = &config.FilterConfig{} + } + sinkConfig.Transform.TransformType = config.Filter +} + +func ensureOutput(sinkConfig *config.SinkConfig) { + if sinkConfig.Output == nil { + sinkConfig.Output = &config.OutputConfig{} + } +} + +// Push a path sequence of sinks onto the stack +func push(stack []*config.SinkConfig, sinkConfigs ...*config.SinkConfig) []*config.SinkConfig { + for _, sinkConfig := range sinkConfigs { + peek(stack).AddSinks(sinkConfig) + stack = append(stack, sinkConfig) + } + return stack +} + +func pop(stack []*config.SinkConfig) []*config.SinkConfig { + return stack[:len(stack)-1] +} + +func peek(stack []*config.SinkConfig) *config.SinkConfig { + return stack[len(stack)-1] +} diff --git a/logging/config/presets/instructions_test.go b/logging/config/presets/instructions_test.go new file mode 100644 index 00000000..7252db28 --- /dev/null +++ b/logging/config/presets/instructions_test.go @@ -0,0 +1,41 @@ +package presets + +import ( + "testing" + + "fmt" + + "github.com/BurntSushi/toml" + "github.com/hyperledger/burrow/logging/config" + "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestBuildSinkConfig(t *testing.T) { + builtSink, err := BuildSinkConfig(IncludeAny, Info, Stdout, Terminal, Down, Down, Info, Stdout, Up, Info, Stderr) + require.NoError(t, err) + expectedSink := config.Sink(). + SetTransform(config.FilterTransform(config.IncludeWhenAnyMatches, + structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StdoutOutput().SetFormat(loggers.TerminalFormat)).AddSinks( + config.Sink().SetTransform(config.FilterTransform(config.NoFilterMode, + structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StderrOutput()).AddSinks( + config.Sink().SetTransform(config.FilterTransform(config.NoFilterMode, + structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StdoutOutput()))) + + fmt.Println(config.JSONString(expectedSink), "\n", config.JSONString(builtSink)) + assert.Equal(t, config.JSONString(expectedSink), config.JSONString(builtSink)) +} + +func TestMinimalPreset(t *testing.T) { + builtSink, err := BuildSinkConfig(Minimal) + require.NoError(t, err) + loggingConfig := &config.LoggingConfig{ + RootSink: builtSink, + } + loggingConfigOut := new(config.LoggingConfig) + toml.Decode(loggingConfig.TOMLString(), loggingConfigOut) + assert.Equal(t, loggingConfig.TOMLString(), loggingConfigOut.TOMLString()) +} diff --git a/logging/config/sinks.go b/logging/config/sinks.go index fbea38d8..c96712f2 100644 --- a/logging/config/sinks.go +++ b/logging/config/sinks.go @@ -4,8 +4,6 @@ import ( "fmt" "os" - "net/url" - "github.com/eapache/channels" kitlog "github.com/go-kit/kit/log" "github.com/hyperledger/burrow/logging/loggers" @@ -22,9 +20,6 @@ type filterMode string const ( // OutputType NoOutput outputType = "" - Graylog outputType = "graylog" - Syslog outputType = "syslog" - File outputType = "file" Stdout outputType = "stdout" Stderr outputType = "stderr" @@ -37,14 +32,17 @@ const ( // Add key value pairs to each log line Label transformType = "label" Capture transformType = "capture" + Sort transformType = "sort" + // TODO [Silas]: add 'flush on exit' transform which flushes the buffer of // CaptureLogger to its OutputLogger a non-passthrough capture when an exit // signal is detected or some other exceptional thing happens + NoFilterMode filterMode = "" IncludeWhenAllMatch filterMode = "include_when_all_match" - IncludeWhenAnyMatches filterMode = "include_when_any_matches" + IncludeWhenAnyMatches filterMode = "include_when_any_match" ExcludeWhenAllMatch filterMode = "exclude_when_all_match" - ExcludeWhenAnyMatches filterMode = "exclude_when_any_matches" + ExcludeWhenAnyMatches filterMode = "exclude_when_any_match" ) // Only include log lines matching the filter so negate the predicate in filter @@ -84,59 +82,65 @@ type ( } SyslogConfig struct { - Url string `toml:"url"` - Tag string `toml:"tag"` + Url string + Tag string } FileConfig struct { - Path string `toml:"path"` + Path string } OutputConfig struct { - OutputType outputType `toml:"output_type"` - Format string `toml:"format,omitempty"` - *GraylogConfig - *FileConfig - *SyslogConfig + OutputType outputType + Format string + *GraylogConfig `json:",omitempty" toml:",omitempty"` + *FileConfig `json:",omitempty" toml:",omitempty"` + *SyslogConfig `json:",omitempty" toml:",omitempty"` } // Transforms LabelConfig struct { - Labels map[string]string `toml:"labels"` - Prefix bool `toml:"prefix"` + Labels map[string]string + Prefix bool } PruneConfig struct { - Keys []string `toml:"keys"` + Keys []string } CaptureConfig struct { - Name string `toml:"name"` - BufferCap int `toml:"buffer_cap"` - Passthrough bool `toml:"passthrough"` + Name string + BufferCap int + Passthrough bool } // Generates true if KeyRegex matches a log line key and ValueRegex matches that key's value. // If ValueRegex is empty then returns true if any key matches // If KeyRegex is empty then returns true if any value matches KeyValuePredicateConfig struct { - KeyRegex string `toml:"key_regex"` - ValueRegex string `toml:"value_regex"` + KeyRegex string + ValueRegex string } // Filter types FilterConfig struct { - FilterMode filterMode `toml:"filter_mode"` + FilterMode filterMode // Predicates to match a log line against using FilterMode - Predicates []*KeyValuePredicateConfig `toml:"predicates"` + Predicates []*KeyValuePredicateConfig + } + + SortConfig struct { + // Sort keys-values with keys in this list first + Keys []string } TransformConfig struct { - TransformType transformType `toml:"transform_type"` - *LabelConfig - *PruneConfig - *CaptureConfig - *FilterConfig + TransformType transformType + LabelConfig *LabelConfig `json:",omitempty" toml:",omitempty"` + PruneConfig *PruneConfig `json:",omitempty" toml:",omitempty"` + CaptureConfig *CaptureConfig `json:",omitempty" toml:",omitempty"` + FilterConfig *FilterConfig `json:",omitempty" toml:",omitempty"` + SortConfig *SortConfig `json:",omitempty" toml:",omitempty"` } // Sink @@ -144,9 +148,9 @@ type ( // before transmitting its log it applies zero or one transforms to the stream of log lines. // by chaining together many Sinks arbitrary transforms to and multi SinkConfig struct { - Transform *TransformConfig `toml:"transform"` - Sinks []*SinkConfig `toml:"sinks"` - Output *OutputConfig `toml:"output"` + Transform *TransformConfig `json:",omitempty" toml:",omitempty"` + Sinks []*SinkConfig `json:",omitempty" toml:",omitempty"` + Output *OutputConfig `json:",omitempty" toml:",omitempty"` } ) @@ -187,29 +191,6 @@ func StderrOutput() *OutputConfig { } } -func SyslogOutput(tag string) *OutputConfig { - return RemoteSyslogOutput(tag, "") -} - -func FileOutput(path string) *OutputConfig { - return &OutputConfig{ - OutputType: File, - FileConfig: &FileConfig{ - Path: path, - }, - } -} - -func RemoteSyslogOutput(tag, remoteUrl string) *OutputConfig { - return &OutputConfig{ - OutputType: Syslog, - SyslogConfig: &SyslogConfig{ - Url: remoteUrl, - Tag: tag, - }, - } -} - func CaptureTransform(name string, bufferCap int, passthrough bool) *TransformConfig { return &TransformConfig{ TransformType: Capture, @@ -264,6 +245,28 @@ func FilterTransform(fmode filterMode, keyvalueRegexes ...string) *TransformConf } } +func (filterConfig *FilterConfig) SetFilterMode(filterMode filterMode) *FilterConfig { + filterConfig.FilterMode = filterMode + return filterConfig +} + +func (filterConfig *FilterConfig) AddPredicate(keyRegex, valueRegex string) *FilterConfig { + filterConfig.Predicates = append(filterConfig.Predicates, &KeyValuePredicateConfig{ + KeyRegex: keyRegex, + ValueRegex: valueRegex, + }) + return filterConfig +} + +func SortTransform(keys ...string) *TransformConfig { + return &TransformConfig{ + TransformType: Sort, + SortConfig: &SortConfig{ + Keys: keys, + }, + } +} + // Logger formation func (sinkConfig *SinkConfig) BuildLogger() (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { return BuildLoggerFromSinkConfig(sinkConfig, make(map[string]*loggers.CaptureLogger)) @@ -307,41 +310,27 @@ func BuildOutputLogger(outputConfig *OutputConfig) (kitlog.Logger, error) { switch outputConfig.OutputType { case NoOutput: return kitlog.NewNopLogger(), nil - //case Graylog: - case Syslog: - urlString := outputConfig.SyslogConfig.Url - if urlString != "" { - remoteUrl, err := url.Parse(urlString) - if err != nil { - return nil, fmt.Errorf("Error parsing remote syslog URL: %s, "+ - "error: %s", - urlString, err) - } - return loggers.NewRemoteSyslogLogger(remoteUrl, - outputConfig.SyslogConfig.Tag, outputConfig.Format) - } - return loggers.NewSyslogLogger(outputConfig.SyslogConfig.Tag, - outputConfig.Format) case Stdout: return loggers.NewStreamLogger(os.Stdout, outputConfig.Format), nil case Stderr: return loggers.NewStreamLogger(os.Stderr, outputConfig.Format), nil - case File: - return loggers.NewFileLogger(outputConfig.FileConfig.Path, outputConfig.Format) default: - return nil, fmt.Errorf("Could not build logger for output: '%s'", + return nil, fmt.Errorf("could not build logger for output: '%s'", outputConfig.OutputType) } } -func BuildTransformLogger(transformConfig *TransformConfig, - captures map[string]*loggers.CaptureLogger, +func BuildTransformLogger(transformConfig *TransformConfig, captures map[string]*loggers.CaptureLogger, outputLogger kitlog.Logger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { + switch transformConfig.TransformType { case NoTransform: return outputLogger, captures, nil case Label: - keyvals := make([]interface{}, 0, len(transformConfig.Labels)*2) + if transformConfig.LabelConfig == nil { + return nil, nil, fmt.Errorf("label transform specified but no LabelConfig provided") + } + keyvals := make([]interface{}, 0, len(transformConfig.LabelConfig.Labels)*2) for k, v := range transformConfig.LabelConfig.Labels { keyvals = append(keyvals, k, v) } @@ -351,6 +340,9 @@ func BuildTransformLogger(transformConfig *TransformConfig, return kitlog.With(outputLogger, keyvals...), captures, nil } case Prune: + if transformConfig.PruneConfig == nil { + return nil, nil, fmt.Errorf("prune transform specified but no PruneConfig provided") + } keys := make([]interface{}, len(transformConfig.PruneConfig.Keys)) for i, k := range transformConfig.PruneConfig.Keys { keys[i] = k @@ -360,9 +352,12 @@ func BuildTransformLogger(transformConfig *TransformConfig, }), captures, nil case Capture: + if transformConfig.CaptureConfig == nil { + return nil, nil, fmt.Errorf("capture transform specified but no CaptureConfig provided") + } name := transformConfig.CaptureConfig.Name if _, ok := captures[name]; ok { - return nil, captures, fmt.Errorf("Could not register new logging capture since name '%s' already "+ + return nil, captures, fmt.Errorf("could not register new logging capture since name '%s' already "+ "registered", name) } // Create a capture logger according to configuration (it may tee the output) @@ -375,12 +370,20 @@ func BuildTransformLogger(transformConfig *TransformConfig, // Pass it upstream to be logged to return captureLogger, captures, nil case Filter: + if transformConfig.FilterConfig == nil { + return nil, nil, fmt.Errorf("filter transform specified but no FilterConfig provided") + } predicate, err := BuildFilterPredicate(transformConfig.FilterConfig) if err != nil { - return nil, captures, fmt.Errorf("Could not build filter predicate: '%s'", err) + return nil, captures, fmt.Errorf("could not build filter predicate: '%s'", err) + } + return loggers.FilterLogger(outputLogger, predicate), captures, nil + case Sort: + if transformConfig.SortConfig == nil { + return nil, nil, fmt.Errorf("sort transform specified but no SortConfig provided") } - return loggers.NewFilterLogger(outputLogger, predicate), captures, nil + return loggers.SortLogger(outputLogger, transformConfig.SortConfig.Keys...), captures, nil default: - return nil, captures, fmt.Errorf("Could not build logger for transform: '%s'", transformConfig.TransformType) + return nil, captures, fmt.Errorf("could not build logger for transform: '%s'", transformConfig.TransformType) } } diff --git a/logging/config/sort.go b/logging/config/sort.go new file mode 100644 index 00000000..b663f62c --- /dev/null +++ b/logging/config/sort.go @@ -0,0 +1,3 @@ +package config + + diff --git a/logging/convention.go b/logging/convention.go index d470451a..0772efcc 100644 --- a/logging/convention.go +++ b/logging/convention.go @@ -18,7 +18,6 @@ import ( kitlog "github.com/go-kit/kit/log" "github.com/hyperledger/burrow/logging/structure" "github.com/hyperledger/burrow/logging/types" - "github.com/hyperledger/burrow/util/slice" ) // Helper functions for InfoTraceLoggers, sort of extension methods to loggers @@ -26,13 +25,13 @@ import ( // logging interface // Record structured Info log line with a message -func InfoMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) { - Msg(kitlog.LoggerFunc(logger.Info), message, keyvals...) +func InfoMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) error { + return Msg(kitlog.LoggerFunc(logger.Info), message, keyvals...) } // Record structured Trace log line with a message -func TraceMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) { - Msg(kitlog.LoggerFunc(logger.Trace), message, keyvals...) +func TraceMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) error { + return Msg(kitlog.LoggerFunc(logger.Trace), message, keyvals...) } // Establish or extend the scope of this logger by appending scopeName to the Scope vector. @@ -46,6 +45,6 @@ func WithScope(logger types.InfoTraceLogger, scopeName string) types.InfoTraceLo // Record a structured log line with a message func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error { - prepended := slice.CopyPrepend(keyvals, structure.MessageKey, message) + prepended := structure.CopyPrepend(keyvals, structure.MessageKey, message) return logger.Log(prepended...) } diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go index bd9d6a83..d6992a94 100644 --- a/logging/lifecycle/lifecycle.go +++ b/logging/lifecycle/lifecycle.go @@ -21,7 +21,6 @@ import ( "time" "github.com/hyperledger/burrow/logging/adapters/stdlib" - tmLog15adapter "github.com/hyperledger/burrow/logging/adapters/tendermint_log15" "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" @@ -33,7 +32,6 @@ import ( "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/types" "github.com/streadway/simpleuuid" - tmLog15 "github.com/tendermint/log15" ) // Lifecycle provides a canonical source for burrow loggers. Components should use the functions here @@ -93,10 +91,8 @@ func NewLogger(outputLogger kitlog.Logger) (types.InfoTraceLogger, channels.Chan return logging.WithMetadata(infoTraceLogger.With(structure.RunId, runId)), errCh } -func CaptureTendermintLog15Output(infoTraceLogger types.InfoTraceLogger) { - tmLog15.Root().SetHandler( - tmLog15adapter.InfoTraceLoggerAsLog15Handler(infoTraceLogger. - With(structure.CapturedLoggingSourceKey, "tendermint_log15"))) +func JustLogger(logger types.InfoTraceLogger, _ channels.Channel) types.InfoTraceLogger { + return logger } func CaptureStdlibLogOutput(infoTraceLogger types.InfoTraceLogger) { diff --git a/logging/lifecycle/lifecycle_test.go b/logging/lifecycle/lifecycle_test.go index f0de3789..c38e6491 100644 --- a/logging/lifecycle/lifecycle_test.go +++ b/logging/lifecycle/lifecycle_test.go @@ -6,9 +6,7 @@ import ( "bufio" - . "github.com/hyperledger/burrow/logging/config" "github.com/stretchr/testify/assert" - "github.com/tendermint/log15" ) func TestNewLoggerFromLoggingConfig(t *testing.T) { @@ -23,27 +21,6 @@ func TestNewLoggerFromLoggingConfig(t *testing.T) { assert.NotEmpty(t, lineString) } -func TestCaptureTendermintLog15Output(t *testing.T) { - reader := CaptureStderr(t, func() { - loggingConfig := &LoggingConfig{ - RootSink: Sink(). - SetOutput(StderrOutput().SetFormat("logfmt")). - SetTransform(FilterTransform(ExcludeWhenAllMatch, - "log_channel", "Trace", - )), - } - outputLogger, err := NewLoggerFromLoggingConfig(loggingConfig) - assert.NoError(t, err) - CaptureTendermintLog15Output(outputLogger) - log15Logger := log15.New() - log15Logger.Info("bar", "number_of_forks", 2) - }) - line, _, err := reader.ReadLine() - assert.NoError(t, err) - assert.Contains(t, string(line), "number_of_forks=2") - assert.Contains(t, string(line), "message=bar") -} - func CaptureStderr(t *testing.T, runner func()) *bufio.Reader { stderr := os.Stderr defer func() { diff --git a/logging/loggers/burrow_format_logger.go b/logging/loggers/burrow_format_logger.go index 2af1b403..d3a61864 100644 --- a/logging/loggers/burrow_format_logger.go +++ b/logging/loggers/burrow_format_logger.go @@ -16,11 +16,10 @@ package loggers import ( "fmt" - - "github.com/hyperledger/burrow/logging/structure" + "time" kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/word256" + "github.com/hyperledger/burrow/logging/structure" ) // Logger that implements some formatting conventions for burrow and burrow-client @@ -39,7 +38,7 @@ func (efl *burrowFormatLogger) Log(keyvals ...interface{}) error { return nil } if len(keyvals)%2 != 0 { - return fmt.Errorf("Log line contains an odd number of elements so "+ + return fmt.Errorf("log line contains an odd number of elements so "+ "was dropped: %v", keyvals) } return efl.logger.Log(structure.MapKeyValues(keyvals, burrowFormatKeyValueMapper)...) @@ -51,12 +50,12 @@ func burrowFormatKeyValueMapper(key, value interface{}) (interface{}, interface{ switch v := value.(type) { case []byte: return key, fmt.Sprintf("%X", v) - case word256.Word256: - return burrowFormatKeyValueMapper(key, v.Bytes()) + case time.Time: + return key, v.Format(time.RFC3339Nano) } } - return key, value + return key, fmt.Sprintf("%v", value) } func BurrowFormatLogger(logger kitlog.Logger) *burrowFormatLogger { diff --git a/logging/loggers/filter_logger.go b/logging/loggers/filter_logger.go index ba9e542f..67f8949b 100644 --- a/logging/loggers/filter_logger.go +++ b/logging/loggers/filter_logger.go @@ -4,25 +4,12 @@ import kitlog "github.com/go-kit/kit/log" // Filter logger allows us to filter lines logged to it before passing on to underlying // output logger -type filterLogger struct { - logger kitlog.Logger - predicate func(keyvals []interface{}) bool -} - -var _ kitlog.Logger = (*filterLogger)(nil) - -func (fl filterLogger) Log(keyvals ...interface{}) error { - if !fl.predicate(keyvals) { - return fl.logger.Log(keyvals...) - } - return nil -} - // Creates a logger that removes lines from output when the predicate evaluates true -func NewFilterLogger(outputLogger kitlog.Logger, - predicate func(keyvals []interface{}) bool) kitlog.Logger { - return &filterLogger{ - logger: outputLogger, - predicate: predicate, - } +func FilterLogger(outputLogger kitlog.Logger, predicate func(keyvals []interface{}) bool) kitlog.Logger { + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + if !predicate(keyvals) { + return outputLogger.Log(keyvals...) + } + return nil + }) } diff --git a/logging/loggers/filter_logger_test.go b/logging/loggers/filter_logger_test.go index f200a827..e989ad81 100644 --- a/logging/loggers/filter_logger_test.go +++ b/logging/loggers/filter_logger_test.go @@ -3,16 +3,15 @@ package loggers import ( "testing" - . "github.com/hyperledger/burrow/util/slice" "github.com/stretchr/testify/assert" ) func TestFilterLogger(t *testing.T) { testLogger := NewChannelLogger(100) - filterLogger := NewFilterLogger(testLogger, func(keyvals []interface{}) bool { + filterLogger := FilterLogger(testLogger, func(keyvals []interface{}) bool { return len(keyvals) > 0 && keyvals[0] == "Spoon" }) filterLogger.Log("Fish", "Present") filterLogger.Log("Spoon", "Present") - assert.Equal(t, [][]interface{}{Slice("Fish", "Present")}, testLogger.FlushLogLines()) + assert.Equal(t, [][]interface{}{{"Fish", "Present"}}, testLogger.FlushLogLines()) } diff --git a/logging/loggers/info_trace_logger.go b/logging/loggers/info_trace_logger.go index 2b9a5539..7e3923e0 100644 --- a/logging/loggers/info_trace_logger.go +++ b/logging/loggers/info_trace_logger.go @@ -97,5 +97,6 @@ func (l *infoTraceLogger) Log(keyvals ...interface{}) error { // Wrap the output loggers with a a set of standard transforms, a non-blocking // ChannelLogger and an outer context func wrapOutputLogger(outputLogger kitlog.Logger) (kitlog.Logger, channels.Channel) { - return NonBlockingLogger(BurrowFormatLogger(VectorValuedLogger(outputLogger))) + return NonBlockingLogger(VectorValuedLogger(SortLogger(BurrowFormatLogger(outputLogger), + structure.ChannelKey, structure.MessageKey, structure.TimeKey, structure.ComponentKey))) } diff --git a/logging/loggers/output_loggers.go b/logging/loggers/output_loggers.go index 28f46fae..a9a88ffe 100644 --- a/logging/loggers/output_loggers.go +++ b/logging/loggers/output_loggers.go @@ -3,16 +3,13 @@ package loggers import ( "io" - "log/syslog" - "net/url" - kitlog "github.com/go-kit/kit/log" - log15a "github.com/hyperledger/burrow/logging/adapters/tendermint_log15" - "github.com/tendermint/log15" + "github.com/go-kit/kit/log/term" + "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" ) const ( - syslogPriority = syslog.LOG_LOCAL0 JSONFormat = "json" LogfmtFormat = "logfmt" TerminalFormat = "terminal" @@ -26,42 +23,13 @@ func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger { case LogfmtFormat: return kitlog.NewLogfmtLogger(writer) default: - return log15a.Log15HandlerAsKitLogger(log15.StreamHandler(writer, - format(formatName))) - } -} - -func NewFileLogger(path string, formatName string) (kitlog.Logger, error) { - handler, err := log15.FileHandler(path, format(formatName)) - return log15a.Log15HandlerAsKitLogger(handler), err -} - -func NewRemoteSyslogLogger(url *url.URL, tag, formatName string) (kitlog.Logger, error) { - handler, err := log15.SyslogNetHandler(url.Scheme, url.Host, syslogPriority, - tag, format(formatName)) - if err != nil { - return nil, err - } - return log15a.Log15HandlerAsKitLogger(handler), nil -} - -func NewSyslogLogger(tag, formatName string) (kitlog.Logger, error) { - handler, err := log15.SyslogHandler(syslogPriority, tag, format(formatName)) - if err != nil { - return nil, err - } - return log15a.Log15HandlerAsKitLogger(handler), nil -} - -func format(name string) log15.Format { - switch name { - case JSONFormat: - return log15.JsonFormat() - case LogfmtFormat: - return log15.LogfmtFormat() - case TerminalFormat: - return log15.TerminalFormat() - default: - return format(defaultFormatName) + return term.NewLogger(writer, kitlog.NewLogfmtLogger, func(keyvals ...interface{}) term.FgBgColor { + switch structure.Value(keyvals, structure.ChannelKey) { + case types.TraceChannelName: + return term.FgBgColor{Fg: term.DarkGreen} + default: + return term.FgBgColor{Fg: term.Yellow} + } + }) } } diff --git a/logging/loggers/shared_test.go b/logging/loggers/shared_test.go index 94c2a15e..55657e2c 100644 --- a/logging/loggers/shared_test.go +++ b/logging/loggers/shared_test.go @@ -8,7 +8,7 @@ import ( kitlog "github.com/go-kit/kit/log" ) -const logLineTimeout time.Duration = time.Second +const logLineTimeout = time.Second type testLogger struct { channelLogger *ChannelLogger @@ -27,7 +27,7 @@ func (tl *testLogger) logLines(numberOfLines int) ([][]interface{}, error) { case logLine := <-tl.logLineCh: logLines[i] = logLine case <-time.After(logLineTimeout): - return logLines, fmt.Errorf("Timed out waiting for log line "+ + return logLines, fmt.Errorf("timed out waiting for log line "+ "(waited %s)", logLineTimeout) } } @@ -49,7 +49,7 @@ func newTestLogger() *testLogger { func makeTestLogger(err error) *testLogger { cl := NewChannelLogger(100) - logLineCh := make(chan ([]interface{})) + logLineCh := make(chan []interface{}) go cl.DrainForever(kitlog.LoggerFunc(func(keyvals ...interface{}) error { logLineCh <- keyvals return nil @@ -61,8 +61,9 @@ func makeTestLogger(err error) *testLogger { } } +// Utility function that returns a slice of log lines. // Takes a variadic argument of log lines as a list of key value pairs delimited -// by the empty string +// by the empty string and splits func logLines(keyvals ...string) [][]interface{} { llines := make([][]interface{}, 0) line := make([]interface{}, 0) diff --git a/logging/loggers/sort_logger.go b/logging/loggers/sort_logger.go new file mode 100644 index 00000000..bddb1b21 --- /dev/null +++ b/logging/loggers/sort_logger.go @@ -0,0 +1,68 @@ +package loggers + +import ( + "sort" + + kitlog "github.com/go-kit/kit/log" +) + +type sortableKeyvals struct { + indices map[string]int + keyvals []interface{} + len int +} + +func sortKeyvals(indices map[string]int, keyvals []interface{}) { + sort.Stable(sortable(indices, keyvals)) +} + +func sortable(indices map[string]int, keyvals []interface{}) *sortableKeyvals { + return &sortableKeyvals{ + indices: indices, + keyvals: keyvals, + len: len(keyvals) / 2, + } +} + +func (skv *sortableKeyvals) Len() int { + return skv.len +} + +// Less reports whether the element with +// index i should sort before the element with index j. +func (skv *sortableKeyvals) Less(i, j int) bool { + return skv.indexOfKey(i) < skv.indexOfKey(j) +} + +// Swap swaps the elements with indexes i and j. +func (skv *sortableKeyvals) Swap(i, j int) { + keyIdx, keyJdx := i*2, j*2 + valIdx, valJdx := keyIdx+1, keyJdx+1 + keyI, valI := skv.keyvals[keyIdx], skv.keyvals[valIdx] + skv.keyvals[keyIdx], skv.keyvals[valIdx] = skv.keyvals[keyJdx], skv.keyvals[valJdx] + skv.keyvals[keyJdx], skv.keyvals[valJdx] = keyI, valI +} + +func (skv *sortableKeyvals) indexOfKey(i int) int { + key, ok := skv.keyvals[i*2].(string) + if !ok { + return skv.len + 1 + } + idx, ok := skv.indices[key] + if !ok { + return skv.len + } + return idx +} + +// Provides a logger that sorts key-values with keys in keys before other key-values +func SortLogger(outputLogger kitlog.Logger, keys... string) kitlog.Logger { + indices := make(map[string]int, len(keys)) + for i, k := range keys { + indices[k] = i + } + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + sortKeyvals(indices, keyvals) + return outputLogger.Log(keyvals...) + }) +} diff --git a/logging/loggers/sort_logger_test.go b/logging/loggers/sort_logger_test.go new file mode 100644 index 00000000..e22e0136 --- /dev/null +++ b/logging/loggers/sort_logger_test.go @@ -0,0 +1,31 @@ +package loggers + +import ( + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func Test_sortKeyvals(t *testing.T) { + keyvals := []interface{}{"foo", 3, "bar", 5} + indices := map[string]int{"foo": 1, "bar": 0} + sortKeyvals(indices, keyvals) + assert.Equal(t, []interface{}{"bar", 5, "foo", 3}, keyvals) +} + +func TestSortLogger(t *testing.T) { + testLogger := newTestLogger() + sortLogger := SortLogger(testLogger, "foo", "bar", "baz") + sortLogger.Log([][]int{}, "bar", "foo", 3, "baz", "horse", "crabs", "cycle", "bar", 4, "ALL ALONE") + sortLogger.Log("foo", 0) + sortLogger.Log("bar", "foo", "foo", "baz") + lines, err := testLogger.logLines(3) + require.NoError(t, err) + // non string keys sort after string keys, specified keys sort before unspecifed keys, specified key sort in order + assert.Equal(t, [][]interface{}{ + {"foo", 3, "bar", 4, "baz", "horse", "crabs", "cycle", [][]int{}, "bar", "ALL ALONE"}, + {"foo", 0}, + {"foo", "baz", "bar", "foo"}, + }, lines) +} diff --git a/logging/loggers/vector_valued_logger_test.go b/logging/loggers/vector_valued_logger_test.go index 62d85f61..b5510688 100644 --- a/logging/loggers/vector_valued_logger_test.go +++ b/logging/loggers/vector_valued_logger_test.go @@ -17,7 +17,6 @@ package loggers import ( "testing" - . "github.com/hyperledger/burrow/util/slice" "github.com/stretchr/testify/assert" ) @@ -27,6 +26,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, Slice("foo", "bar", "seen", Slice(1, 3, 2)), + assert.Equal(t, []interface{}{"foo", "bar", "seen", []interface{}{1, 3, 2}}, lls[0]) } diff --git a/logging/metadata.go b/logging/metadata.go index 8d8ca1d3..1699fb1a 100644 --- a/logging/metadata.go +++ b/logging/metadata.go @@ -38,7 +38,6 @@ var defaultTimestampUTCValuer kitlog.Valuer = func() interface{} { func WithMetadata(infoTraceLogger types.InfoTraceLogger) types.InfoTraceLogger { return infoTraceLogger.With(structure.TimeKey, defaultTimestampUTCValuer, - structure.CallerKey, kitlog.Caller(infoTraceLoggerCallDepth), structure.TraceKey, TraceValuer()) } diff --git a/logging/structure/structure.go b/logging/structure/structure.go index 271d8564..6946270c 100644 --- a/logging/structure/structure.go +++ b/logging/structure/structure.go @@ -14,8 +14,6 @@ package structure -import . "github.com/hyperledger/burrow/util/slice" - const ( // Log time (time.Time) TimeKey = "time" @@ -160,3 +158,27 @@ func MapKeyValues(keyvals []interface{}, fn func(interface{}, interface{}) (inte } return mappedKeyvals } + +// Deletes n elements starting with the ith from a slice by splicing. +// Beware uses append so the underlying backing array will be modified! +func Delete(slice []interface{}, i int, n int) []interface{} { + return append(slice[:i], slice[i+n:]...) +} + +// Delete an element at a specific index and return the contracted list +func DeleteAt(slice []interface{}, i int) []interface{} { + return Delete(slice, i, 1) +} + +// Prepend elements to slice in the order they appear +func CopyPrepend(slice []interface{}, elements ...interface{}) []interface{} { + elementsLength := len(elements) + newSlice := make([]interface{}, len(slice)+elementsLength) + for i, e := range elements { + newSlice[i] = e + } + for i, e := range slice { + newSlice[elementsLength+i] = e + } + return newSlice +} diff --git a/logging/structure/structure_test.go b/logging/structure/structure_test.go index d7e14735..995c187c 100644 --- a/logging/structure/structure_test.go +++ b/logging/structure/structure_test.go @@ -17,19 +17,18 @@ package structure import ( "testing" - . "github.com/hyperledger/burrow/util/slice" "github.com/stretchr/testify/assert" ) func TestValuesAndContext(t *testing.T) { - keyvals := Slice("hello", 1, "dog", 2, "fish", 3, "fork", 5) + keyvals := []interface{}{"hello", 1, "dog", 2, "fish", 3, "fork", 5} vals, ctx := ValuesAndContext(keyvals, "hello", "fish") assert.Equal(t, map[interface{}]interface{}{"hello": 1, "fish": 3}, vals) - assert.Equal(t, Slice("dog", 2, "fork", 5), ctx) + assert.Equal(t, []interface{}{"dog", 2, "fork", 5}, ctx) } func TestVectorise(t *testing.T) { - kvs := Slice( + kvs := []interface{}{ "scope", "lawnmower", "hub", "budub", "occupation", "fish brewer", @@ -37,36 +36,48 @@ func TestVectorise(t *testing.T) { "flub", "dub", "scope", "rake", "flub", "brub", - ) + } kvsVector := Vectorise(kvs, "occupation", "scope") // Vectorise scope - assert.Equal(t, Slice( - "scope", Slice("lawnmower", "hose pipe", "rake"), + assert.Equal(t, []interface{}{ + "scope", []interface{}{"lawnmower", "hose pipe", "rake"}, "hub", "budub", "occupation", "fish brewer", - "flub", Slice("dub", "brub"), - ), + "flub", []interface{}{"dub", "brub"}, + }, kvsVector) } func TestRemoveKeys(t *testing.T) { // Remove multiple of same key - assert.Equal(t, Slice("Fish", 9), - RemoveKeys(Slice("Foo", "Bar", "Fish", 9, "Foo", "Baz", "odd-key"), + assert.Equal(t, []interface{}{"Fish", 9}, + RemoveKeys([]interface{}{"Foo", "Bar", "Fish", 9, "Foo", "Baz", "odd-key"}, "Foo")) // Remove multiple different keys - assert.Equal(t, Slice("Fish", 9), - RemoveKeys(Slice("Foo", "Bar", "Fish", 9, "Foo", "Baz", "Bar", 89), + assert.Equal(t, []interface{}{"Fish", 9}, + RemoveKeys([]interface{}{"Foo", "Bar", "Fish", 9, "Foo", "Baz", "Bar", 89}, "Foo", "Bar")) // Remove nothing but supply keys - assert.Equal(t, Slice("Foo", "Bar", "Fish", 9), - RemoveKeys(Slice("Foo", "Bar", "Fish", 9), + assert.Equal(t, []interface{}{"Foo", "Bar", "Fish", 9}, + RemoveKeys([]interface{}{"Foo", "Bar", "Fish", 9}, "A", "B", "C")) // Remove nothing since no keys supplied - assert.Equal(t, Slice("Foo", "Bar", "Fish", 9), - RemoveKeys(Slice("Foo", "Bar", "Fish", 9))) + assert.Equal(t, []interface{}{"Foo", "Bar", "Fish", 9}, + RemoveKeys([]interface{}{"Foo", "Bar", "Fish", 9})) +} + +func TestDelete(t *testing.T) { + assert.Equal(t, []interface{}{1, 2, 4, 5}, Delete([]interface{}{1, 2, 3, 4, 5}, 2, 1)) +} + +func TestCopyPrepend(t *testing.T) { + assert.Equal(t, []interface{}{"three", 4, 1, "two"}, + CopyPrepend([]interface{}{1, "two"}, "three", 4)) + assert.Equal(t, []interface{}{}, CopyPrepend(nil)) + assert.Equal(t, []interface{}{1}, CopyPrepend(nil, 1)) + assert.Equal(t, []interface{}{1}, CopyPrepend([]interface{}{1})) } diff --git a/util/logging/cmd/main.go b/util/logging/cmd/main.go index fc6d16dd..cc6960b6 100644 --- a/util/logging/cmd/main.go +++ b/util/logging/cmd/main.go @@ -31,8 +31,7 @@ func main() { "module", "p2p", "captured_logging_source", "tendermint_log15")). AddSinks( - Sink().SetOutput(SyslogOutput("Burrow-network")), - Sink().SetOutput(FileOutput("/var/log/burrow-network.log")), + Sink().SetOutput(StdoutOutput()), ), ), } -- GitLab