Merge pull request #26 from tendermint/develop

v0.2.2

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:

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
@@ -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()
 }
 
@@ -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,18 @@ 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())
 		}
+
+		// 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
 }

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...)
@@ -63,47 +64,55 @@ 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
+	// make sure it handles dashed-words in the config, and ignores random info
-	conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar"})
+	conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar", "two-words": "WORD"})
 	require.Nil(err)
 
 	cases := []struct {
-		args     []string
+		args        []string
-		env      map[string]string
+		env         map[string]string
-		expected string
+		expected    string
+		expectedTwo string
 	}{
-		{nil, nil, ""},
+		{nil, nil, "", ""},
 		// setting on the command line
-		{[]string{"--boo", "haha"}, nil, "haha"},
+		{[]string{"--boo", "haha"}, nil, "haha", ""},
-		{[]string{"--root", conf1}, nil, cval1},
+		{[]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_BOO": "bang"}, "bang", ""},
-		{nil, map[string]string{"RD_ROOT": conf1}, cval1},
+		{nil, map[string]string{"RD_TWO_WORDS": "fly"}, "", "fly"},
-		{nil, map[string]string{"RDROOT": conf2}, cval2},
+		{nil, map[string]string{"RDTWO_WORDS": "fly"}, "", "fly"},
-		{nil, map[string]string{"RDHOME": conf1}, cval1},
+		{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) {}
 
 		viper.Reset()
 		args := append([]string{cmd.Use}, tc.args...)
 		err := RunWithArgs(cmd, args, tc.env)
 		require.Nil(err, i)
 		assert.Equal(tc.expected, foo, i)
+		assert.Equal(tc.expectedTwo, two, i)
 	}
 }
 
@@ -175,6 +184,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 +219,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...)

common/string.go

@@ -1,12 +1,15 @@
 package common
 
 import (
+	"encoding/hex"
 	"fmt"
 	"strings"
 )
 
+// Fmt shorthand, XXX DEPRECATED
 var Fmt = fmt.Sprintf
 
+// RightPadString adds spaces to the right of a string to make it length totalLength
 func RightPadString(s string, totalLength int) string {
 	remaining := totalLength - len(s)
 	if remaining > 0 {
@@ -15,6 +18,7 @@ func RightPadString(s string, totalLength int) string {
 	return s
 }
 
+// LeftPadString adds spaces to the left of a string to make it length totalLength
 func LeftPadString(s string, totalLength int) string {
 	remaining := totalLength - len(s)
 	if remaining > 0 {
@@ -22,3 +26,23 @@ func LeftPadString(s string, totalLength int) string {
 	}
 	return s
 }
+
+// IsHex returns true for non-empty hex-string prefixed with "0x"
+func IsHex(s string) bool {
+	if len(s) > 2 && s[:2] == "0x" {
+		_, err := hex.DecodeString(s[2:])
+		if err != nil {
+			return false
+		}
+		return true
+	}
+	return false
+}
+
+// StripHex returns hex string without leading "0x"
+func StripHex(s string) string {
+	if IsHex(s) {
+		return s[2:]
+	}
+	return s
+}

flowrate/io_test.go

@@ -6,7 +6,6 @@ package flowrate
 
 import (
 	"bytes"
-	"reflect"
 	"testing"
 	"time"
 )
@@ -90,8 +89,8 @@ 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) 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]) {
@@ -136,11 +135,55 @@ 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) 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()) {
 		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
+}

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.

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

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

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

version/version.go

@@ -0,0 +1,3 @@
+package version
+
+const Version = "0.2.2"