From 6b1043246380a5c543b8aba4b9ea11da8550cb25 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Tue, 23 May 2017 15:19:48 +0200 Subject: [PATCH 1/8] [flowrate] refactor clock functions (Refs #16) this commit does not fix the original bug --- flowrate/util.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/flowrate/util.go b/flowrate/util.go index 4caac583f..b33ddc701 100644 --- a/flowrate/util.go +++ b/flowrate/util.go @@ -15,16 +15,16 @@ const clockRate = 20 * time.Millisecond // czero is the process start time rounded down to the nearest clockRate // increment. -var czero = time.Duration(time.Now().UnixNano()) / clockRate * clockRate +var czero = time.Now().Round(clockRate) // clock returns a low resolution timestamp relative to the process start time. func clock() time.Duration { - return time.Duration(time.Now().UnixNano())/clockRate*clockRate - czero + return time.Now().Round(clockRate).Sub(czero) } // clockToTime converts a clock() timestamp to an absolute time.Time value. func clockToTime(c time.Duration) time.Time { - return time.Unix(0, int64(czero+c)) + return czero.Add(c) } // clockRound returns d rounded to the nearest clockRate increment. From b5c57967b71ed5c3c4667687df2a1e91317439b7 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Tue, 23 May 2017 15:24:00 +0200 Subject: [PATCH 2/8] [flowrate] improve error formatting (Refs #16) --- flowrate/io_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/flowrate/io_test.go b/flowrate/io_test.go index fa7f4b4ae..f4049ed2a 100644 --- a/flowrate/io_test.go +++ b/flowrate/io_test.go @@ -91,7 +91,7 @@ func TestReader(t *testing.T) { } for i, s := range status { if !reflect.DeepEqual(&s, &want[i]) { - t.Errorf("r.Status(%v) expected %v; got %v", i, want[i], s) + t.Errorf("r.Status(%v)\nexpected: %v\ngot : %v", i, want[i], s) } } if !bytes.Equal(b[:20], in[:20]) { @@ -137,7 +137,7 @@ func TestWriter(t *testing.T) { } for i, s := range status { if !reflect.DeepEqual(&s, &want[i]) { - t.Errorf("w.Status(%v) expected %v; got %v", i, want[i], s) + t.Errorf("w.Status(%v)\nexpected: %v\ngot : %v\n", i, want[i], s) } } if !bytes.Equal(b, w.Writer.(*bytes.Buffer).Bytes()) { From ddaa4d9b4cdb7c3090c780ede636b496390a073a Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Tue, 23 May 2017 17:37:13 +0200 Subject: [PATCH 3/8] [log] tracing logger --- log/tm_logger.go | 2 +- log/tracing_logger.go | 76 ++++++++++++++++++++++++++++++++++++++ log/tracing_logger_test.go | 42 +++++++++++++++++++++ 3 files changed, 119 insertions(+), 1 deletion(-) create mode 100644 log/tracing_logger.go create mode 100644 log/tracing_logger_test.go diff --git a/log/tm_logger.go b/log/tm_logger.go index ae8f88c6a..a903dbe8d 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -43,7 +43,7 @@ func NewTMLogger(w io.Writer) Logger { return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} } -// NewTMLoggerWithColorFn allow you to provide your own color function. See +// NewTMLoggerWithColorFn allows you to provide your own color function. See // NewTMLogger for documentation. func NewTMLoggerWithColorFn(w io.Writer, colorFn func(keyvals ...interface{}) term.FgBgColor) Logger { return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} diff --git a/log/tracing_logger.go b/log/tracing_logger.go new file mode 100644 index 000000000..794bdaeb8 --- /dev/null +++ b/log/tracing_logger.go @@ -0,0 +1,76 @@ +package log + +import ( + "fmt" + + "github.com/pkg/errors" +) + +// NewTracingLogger enables tracing by wrapping all errors (if they +// implement stackTracer interface) in tracedError. +// +// All errors returned by https://github.com/pkg/errors implement stackTracer +// interface. +// +// For debugging purposes only as it doubles the amount of allocations. +func NewTracingLogger(next Logger) Logger { + return &tracingLogger{ + next: next, + } +} + +type stackTracer interface { + error + StackTrace() errors.StackTrace +} + +type tracingLogger struct { + next Logger +} + +func (l *tracingLogger) Info(msg string, keyvals ...interface{}) error { + return l.next.Info(msg, formatErrors(keyvals)...) +} + +func (l *tracingLogger) Debug(msg string, keyvals ...interface{}) error { + return l.next.Debug(msg, formatErrors(keyvals)...) +} + +func (l *tracingLogger) Error(msg string, keyvals ...interface{}) error { + return l.next.Error(msg, formatErrors(keyvals)...) +} + +func (l *tracingLogger) With(keyvals ...interface{}) Logger { + return &tracingLogger{next: l.next.With(formatErrors(keyvals)...)} +} + +func formatErrors(keyvals []interface{}) []interface{} { + newKeyvals := make([]interface{}, len(keyvals)) + copy(newKeyvals, keyvals) + for i := 0; i < len(newKeyvals)-1; i += 2 { + if err, ok := newKeyvals[i+1].(stackTracer); ok { + newKeyvals[i+1] = tracedError{err} + } + } + return newKeyvals +} + +// tracedError wraps a stackTracer and just makes the Error() result +// always return a full stack trace. +type tracedError struct { + wrapped stackTracer +} + +var _ stackTracer = tracedError{} + +func (t tracedError) StackTrace() errors.StackTrace { + return t.wrapped.StackTrace() +} + +func (t tracedError) Cause() error { + return t.wrapped +} + +func (t tracedError) Error() string { + return fmt.Sprintf("%+v", t.wrapped) +} diff --git a/log/tracing_logger_test.go b/log/tracing_logger_test.go new file mode 100644 index 000000000..584b34bef --- /dev/null +++ b/log/tracing_logger_test.go @@ -0,0 +1,42 @@ +package log_test + +import ( + "bytes" + stderr "errors" + "fmt" + "strings" + "testing" + + "github.com/pkg/errors" + "github.com/tendermint/tmlibs/log" +) + +func TestTracingLogger(t *testing.T) { + var buf bytes.Buffer + + var logger log.Logger + logger = log.NewTMJSONLogger(&buf) + + logger1 := log.NewTracingLogger(logger) + err1 := errors.New("Courage is grace under pressure.") + err2 := errors.New("It does not matter how slowly you go, so long as you do not stop.") + logger1.With("err1", err1).Info("foo", "err2", err2) + have := strings.Replace(strings.Replace(strings.TrimSpace(buf.String()), "\\n", "", -1), "\\t", "", -1) + if want := strings.Replace(strings.Replace(`{"_msg":"foo","err1":"`+fmt.Sprintf("%+v", err1)+`","err2":"`+fmt.Sprintf("%+v", err2)+`","level":"info"}`, "\t", "", -1), "\n", "", -1); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger.With("err1", stderr.New("Opportunities don't happen. You create them.")).Info("foo", "err2", stderr.New("Once you choose hope, anything's possible.")) + if want, have := `{"_msg":"foo","err1":"Opportunities don't happen. You create them.","err2":"Once you choose hope, anything's possible.","level":"info"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz") + if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} From 5f20b3323e6afa49eb7c681a953611af08f43206 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Thu, 25 May 2017 13:06:42 +0200 Subject: [PATCH 4/8] don't do DeepEqual, compare ranges for durations and rates (Refs #16) --- flowrate/io_test.go | 49 ++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 46 insertions(+), 3 deletions(-) diff --git a/flowrate/io_test.go b/flowrate/io_test.go index f4049ed2a..6d4934a8a 100644 --- a/flowrate/io_test.go +++ b/flowrate/io_test.go @@ -6,7 +6,6 @@ package flowrate import ( "bytes" - "reflect" "testing" "time" ) @@ -90,7 +89,7 @@ func TestReader(t *testing.T) { Status{false, start, _300ms, 0, 20, 3, 0, 0, 67, 100, 0, 0, 0}, } for i, s := range status { - if !reflect.DeepEqual(&s, &want[i]) { + if !statusesAreEqual(&s, &want[i]) { t.Errorf("r.Status(%v)\nexpected: %v\ngot : %v", i, want[i], s) } } @@ -136,7 +135,7 @@ func TestWriter(t *testing.T) { Status{true, start, _500ms, _100ms, 100, 5, 200, 200, 200, 200, 0, 0, 100000}, } for i, s := range status { - if !reflect.DeepEqual(&s, &want[i]) { + if !statusesAreEqual(&s, &want[i]) { t.Errorf("w.Status(%v)\nexpected: %v\ngot : %v\n", i, want[i], s) } } @@ -144,3 +143,47 @@ func TestWriter(t *testing.T) { t.Errorf("w.Write() input doesn't match output") } } + +const maxDeviationForDuration = 50 * time.Millisecond +const maxDeviationForRate int64 = 50 + +// statusesAreEqual returns true if s1 is equal to s2. Equality here means +// general equality of fields except for the duration and rates, which can +// drift due to unpredictable delays (e.g. thread wakes up 25ms after +// `time.Sleep` has ended). +func statusesAreEqual(s1 *Status, s2 *Status) bool { + if s1.Active == s2.Active && + s1.Start == s2.Start && + durationsAreEqual(s1.Duration, s2.Duration, maxDeviationForDuration) && + s1.Idle == s2.Idle && + s1.Bytes == s2.Bytes && + s1.Samples == s2.Samples && + ratesAreEqual(s1.InstRate, s2.InstRate, maxDeviationForRate) && + ratesAreEqual(s1.CurRate, s2.CurRate, maxDeviationForRate) && + ratesAreEqual(s1.AvgRate, s2.AvgRate, maxDeviationForRate) && + ratesAreEqual(s1.PeakRate, s2.PeakRate, maxDeviationForRate) && + s1.BytesRem == s2.BytesRem && + durationsAreEqual(s1.TimeRem, s2.TimeRem, maxDeviationForDuration) && + s1.Progress == s2.Progress { + return true + } + return false +} + +func durationsAreEqual(d1 time.Duration, d2 time.Duration, maxDeviation time.Duration) bool { + if d2-d1 <= maxDeviation { + return true + } + return false +} + +func ratesAreEqual(r1 int64, r2 int64, maxDeviation int64) bool { + sub := r1 - r2 + if sub < 0 { + sub = -sub + } + if sub <= maxDeviation { + return true + } + return false +} From 0ecb38c6da95a1e8f60117b2bd4a6f76c7a0f944 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 14 Jun 2017 16:51:33 +0200 Subject: [PATCH 5/8] Return exit code on error, disable in tests --- cli/setup.go | 16 ++++++++++++++-- cli/setup_test.go | 4 ++++ 2 files changed, 18 insertions(+), 2 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index 21b29a491..4a64f00fd 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -38,7 +38,7 @@ func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor { cmd.PersistentFlags().String(HomeFlag, "", "root directory for config and data") cmd.PersistentFlags().Bool(TraceFlag, false, "print out full stack trace on errors") cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) - return Executor{cmd} + return Executor{cmd, os.Exit} } // PrepareMainCmd is meant for client side libs that want some more flags @@ -82,6 +82,11 @@ func copyEnvVars(prefix string) { // Executor wraps the cobra Command with a nicer Execute method type Executor struct { *cobra.Command + Exit func(int) // this is os.Exit by default, override in tests +} + +type ExitCoder interface { + ExitCode() int } // execute adds all child commands to the root command sets flags appropriately. @@ -91,12 +96,19 @@ func (e Executor) Execute() error { e.SilenceErrors = true err := e.Command.Execute() if err != nil { - // TODO: something cooler with log-levels if viper.GetBool(TraceFlag) { fmt.Printf("ERROR: %+v\n", err) } else { fmt.Println("ERROR:", err.Error()) } + + fmt.Printf("%#v\n", e) + // return error code 1 by default, can override it with a special error type + exitCode := 1 + if ec, ok := err.(ExitCoder); ok { + exitCode = ec.ExitCode() + } + e.Exit(exitCode) } return err } diff --git a/cli/setup_test.go b/cli/setup_test.go index 8fb4ce140..538797c9e 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -46,6 +46,7 @@ func TestSetupEnv(t *testing.T) { } demo.Flags().String("foobar", "", "Some test value from config") cmd := PrepareBaseCmd(demo, "DEMO", "/qwerty/asdfgh") // some missing dir.. + cmd.Exit = func(int) {} viper.Reset() args := append([]string{cmd.Use}, tc.args...) @@ -98,6 +99,7 @@ func TestSetupConfig(t *testing.T) { } boo.Flags().String("boo", "", "Some test value from config") cmd := PrepareBaseCmd(boo, "RD", "/qwerty/asdfgh") // some missing dir... + cmd.Exit = func(int) {} viper.Reset() args := append([]string{cmd.Use}, tc.args...) @@ -175,6 +177,7 @@ func TestSetupUnmarshal(t *testing.T) { // from the default config here marsh.Flags().Int("age", base.Age, "Some test value from config") cmd := PrepareBaseCmd(marsh, "MR", "/qwerty/asdfgh") // some missing dir... + cmd.Exit = func(int) {} viper.Reset() args := append([]string{cmd.Use}, tc.args...) @@ -209,6 +212,7 @@ func TestSetupTrace(t *testing.T) { }, } cmd := PrepareBaseCmd(trace, "DBG", "/qwerty/asdfgh") // some missing dir.. + cmd.Exit = func(int) {} viper.Reset() args := append([]string{cmd.Use}, tc.args...) From 59a77e7bef092eef0e1f9b44c983dc9e35eed0d6 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 14 Jun 2017 17:01:15 +0200 Subject: [PATCH 6/8] Remove Printf --- cli/setup.go | 1 - 1 file changed, 1 deletion(-) diff --git a/cli/setup.go b/cli/setup.go index 4a64f00fd..148ac7b88 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -102,7 +102,6 @@ func (e Executor) Execute() error { fmt.Println("ERROR:", err.Error()) } - fmt.Printf("%#v\n", e) // return error code 1 by default, can override it with a special error type exitCode := 1 if ec, ok := err.(ExitCoder); ok { From 3400cee845a48508198845b3c227e6e1577c32a5 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Thu, 15 Jun 2017 20:16:22 +0200 Subject: [PATCH 7/8] Handle --two-words as TMTWO_WORDS env var --- cli/setup.go | 2 +- cli/setup_test.go | 35 +++++++++++++++++++++-------------- 2 files changed, 22 insertions(+), 15 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index 148ac7b88..35362ed81 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -58,7 +58,7 @@ func initEnv(prefix string) { // env variables with TM prefix (eg. TM_ROOT) viper.SetEnvPrefix(prefix) - viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) + viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_", "-", "_")) viper.AutomaticEnv() } diff --git a/cli/setup_test.go b/cli/setup_test.go index 538797c9e..36cbbcc90 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -64,40 +64,46 @@ func TestSetupConfig(t *testing.T) { cval1, cval2 := "fubble", "wubble" conf1, err := WriteDemoConfig(map[string]string{"boo": cval1}) require.Nil(err) - // even with some ignored fields, should be no problem - conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar"}) + // make sure it handles dashed-words in the config, and ignores random info + conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar", "two-words": "WORD"}) require.Nil(err) cases := []struct { - args []string - env map[string]string - expected string + args []string + env map[string]string + expected string + expectedTwo string }{ - {nil, nil, ""}, + {nil, nil, "", ""}, // setting on the command line - {[]string{"--boo", "haha"}, nil, "haha"}, - {[]string{"--root", conf1}, nil, cval1}, + {[]string{"--boo", "haha"}, nil, "haha", ""}, + {[]string{"--two-words", "rocks"}, nil, "", "rocks"}, + {[]string{"--root", conf1}, nil, cval1, ""}, // test both variants of the prefix - {nil, map[string]string{"RD_BOO": "bang"}, "bang"}, - {nil, map[string]string{"RD_ROOT": conf1}, cval1}, - {nil, map[string]string{"RDROOT": conf2}, cval2}, - {nil, map[string]string{"RDHOME": conf1}, cval1}, + {nil, map[string]string{"RD_BOO": "bang"}, "bang", ""}, + {nil, map[string]string{"RD_TWO_WORDS": "fly"}, "", "fly"}, + {nil, map[string]string{"RDTWO_WORDS": "fly"}, "", "fly"}, + {nil, map[string]string{"RD_ROOT": conf1}, cval1, ""}, + {nil, map[string]string{"RDROOT": conf2}, cval2, "WORD"}, + {nil, map[string]string{"RDHOME": conf1}, cval1, ""}, // and when both are set??? HOME wins every time! - {[]string{"--root", conf1}, map[string]string{"RDHOME": conf2}, cval2}, + {[]string{"--root", conf1}, map[string]string{"RDHOME": conf2}, cval2, "WORD"}, } for idx, tc := range cases { i := strconv.Itoa(idx) // test command that store value of foobar in local variable - var foo string + var foo, two string boo := &cobra.Command{ Use: "reader", RunE: func(cmd *cobra.Command, args []string) error { foo = viper.GetString("boo") + two = viper.GetString("two-words") return nil }, } boo.Flags().String("boo", "", "Some test value from config") + boo.Flags().String("two-words", "", "Check out env handling -") cmd := PrepareBaseCmd(boo, "RD", "/qwerty/asdfgh") // some missing dir... cmd.Exit = func(int) {} @@ -106,6 +112,7 @@ func TestSetupConfig(t *testing.T) { err := RunWithArgs(cmd, args, tc.env) require.Nil(err, i) assert.Equal(tc.expected, foo, i) + assert.Equal(tc.expectedTwo, two, i) } } From bd9d0d1637dadf1330e167189d5e5031aadcda6f Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Fri, 16 Jun 2017 11:40:14 -0400 Subject: [PATCH 8/8] changelog and version --- CHANGELOG.md | 17 +++++++++++++++++ version/version.go | 3 +++ 2 files changed, 20 insertions(+) create mode 100644 version/version.go diff --git a/CHANGELOG.md b/CHANGELOG.md index a97aa1285..e6783601a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,22 @@ # Changelog +## 0.2.2 (June 16, 2017) + +FEATURES: + +- [common] IsHex and StripHex for handling `0x` prefixed hex strings +- [log] NewTracingLogger returns a logger that output error traces, ala `github.com/pkg/errors` + +IMPROVEMENTS: + +- [cli] Error handling for tests +- [cli] Support dashes in ENV variables + +BUG FIXES: + +- [flowrate] Fix non-deterministic test failures + + ## 0.2.1 (June 2, 2017) FEATURES: diff --git a/version/version.go b/version/version.go new file mode 100644 index 000000000..42af8ff7a --- /dev/null +++ b/version/version.go @@ -0,0 +1,3 @@ +package version + +const Version = "0.2.2"