Merge pull request #15 from tendermint/develop

v0.2.0

.gitignore

@@ -1,2 +1,2 @@
-*.swp
-*.swo
+vendor
+.glide

CHANGELOG.md

@@ -0,0 +1,196 @@
+# Changelog
+
+## 0.2.0 (May 18, 2017)
+
+BREAKING CHANGES:
+
+- [common] NewBaseService takes the new logger
+
+
+FEATURES:
+
+- [cli] New library to standardize building command line tools
+- [log] New logging library
+
+BUG FIXES:
+
+- [autofile] Close file before rotating 
+
+## 0.1.0 (May 1, 2017)
+
+Initial release, combines what were previously independent repos:
+
+- go-autofile
+- go-clist
+- go-common
+- go-db
+- go-events
+- go-flowrate
+- go-logger
+- go-merkle
+- go-process
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+

Makefile

@@ -1,10 +1,10 @@
-.PHONEY: all test install get_vendor_deps ensure_tools
+.PHONY: all test get_vendor_deps ensure_tools
 
 GOTOOLS = \
 	github.com/Masterminds/glide
 REPO:=github.com/tendermint/tmlibs
 
-all: install test
+all: test
 
 test:
 	go test `glide novendor`
@@ -16,5 +16,3 @@ get_vendor_deps: ensure_tools
 
 ensure_tools:
 	go get $(GOTOOLS)
-
-

autofile/group.go

@@ -224,15 +224,17 @@ func (g *Group) RotateFile() {
 	g.mtx.Lock()
 	defer g.mtx.Unlock()
 
-	dstPath := filePathForIndex(g.Head.Path, g.maxIndex, g.maxIndex+1)
-	err := os.Rename(g.Head.Path, dstPath)
-	if err != nil {
+	headPath := g.Head.Path
+
+	if err := g.Head.closeFile(); err != nil {
 		panic(err)
 	}
-	err = g.Head.closeFile()
-	if err != nil {
+
+	indexPath := filePathForIndex(headPath, g.maxIndex, g.maxIndex+1)
+	if err := os.Rename(headPath, indexPath); err != nil {
 		panic(err)
 	}
+
 	g.maxIndex += 1
 }
 

cli/helper.go

@@ -0,0 +1,84 @@
+package cli
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"io/ioutil"
+	"os"
+	"path/filepath"
+)
+
+// WriteDemoConfig writes a toml file with the given values.
+// It returns the RootDir the config.toml file is stored in,
+// or an error if writing was impossible
+func WriteDemoConfig(vals map[string]string) (string, error) {
+	cdir, err := ioutil.TempDir("", "test-cli")
+	if err != nil {
+		return "", err
+	}
+	data := ""
+	for k, v := range vals {
+		data = data + fmt.Sprintf("%s = \"%s\"\n", k, v)
+	}
+	cfile := filepath.Join(cdir, "config.toml")
+	err = ioutil.WriteFile(cfile, []byte(data), 0666)
+	return cdir, err
+}
+
+// RunWithArgs executes the given command with the specified command line args
+// and environmental variables set. It returns any error returned from cmd.Execute()
+func RunWithArgs(cmd Executable, args []string, env map[string]string) error {
+	oargs := os.Args
+	oenv := map[string]string{}
+	// defer returns the environment back to normal
+	defer func() {
+		os.Args = oargs
+		for k, v := range oenv {
+			os.Setenv(k, v)
+		}
+	}()
+
+	// set the args and env how we want them
+	os.Args = args
+	for k, v := range env {
+		// backup old value if there, to restore at end
+		oenv[k] = os.Getenv(k)
+		err := os.Setenv(k, v)
+		if err != nil {
+			return err
+		}
+	}
+
+	// and finally run the command
+	return cmd.Execute()
+}
+
+// RunCaptureWithArgs executes the given command with the specified command line args
+// and environmental variables set. It returns whatever was writen to
+// stdout along with any error returned from cmd.Execute()
+func RunCaptureWithArgs(cmd Executable, args []string, env map[string]string) (output string, err error) {
+	old := os.Stdout // keep backup of the real stdout
+	r, w, _ := os.Pipe()
+	os.Stdout = w
+	defer func() {
+		os.Stdout = old // restoring the real stdout
+	}()
+
+	outC := make(chan string)
+	// copy the output in a separate goroutine so printing can't block indefinitely
+	go func() {
+		var buf bytes.Buffer
+		// io.Copy will end when we call w.Close() below
+		io.Copy(&buf, r)
+		outC <- buf.String()
+	}()
+
+	// now run the command
+	err = RunWithArgs(cmd, args, env)
+
+	// and grab the stdout to return
+	w.Close()
+	output = <-outC
+	return output, err
+}

cli/setup.go

@@ -0,0 +1,178 @@
+package cli
+
+import (
+	"fmt"
+	"os"
+	"strings"
+
+	"github.com/pkg/errors"
+	"github.com/spf13/cobra"
+	"github.com/spf13/viper"
+
+	data "github.com/tendermint/go-wire/data"
+	"github.com/tendermint/go-wire/data/base58"
+)
+
+const (
+	RootFlag     = "root"
+	HomeFlag     = "home"
+	TraceFlag    = "trace"
+	OutputFlag   = "output"
+	EncodingFlag = "encoding"
+)
+
+// Executable is the minimal interface to *corba.Command, so we can
+// wrap if desired before the test
+type Executable interface {
+	Execute() error
+}
+
+// PrepareBaseCmd is meant for tendermint and other servers
+func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor {
+	cobra.OnInitialize(func() { initEnv(envPrefix) })
+	cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "DEPRECATED. Use --home")
+	// -h is already reserved for --help as part of the cobra framework
+	// do you want to try something else??
+	// also, default must be empty, so we can detect this unset and fall back
+	// to --root / TM_ROOT / TMROOT
+	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}
+}
+
+// PrepareMainCmd is meant for client side libs that want some more flags
+//
+// This adds --encoding (hex, btc, base64) and --output (text, json) to
+// the command.  These only really make sense in interactive commands.
+func PrepareMainCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor {
+	cmd.PersistentFlags().StringP(EncodingFlag, "e", "hex", "Binary encoding (hex|b64|btc)")
+	cmd.PersistentFlags().StringP(OutputFlag, "o", "text", "Output format (text|json)")
+	cmd.PersistentPreRunE = concatCobraCmdFuncs(setEncoding, validateOutput, cmd.PersistentPreRunE)
+	return PrepareBaseCmd(cmd, envPrefix, defautRoot)
+}
+
+// initEnv sets to use ENV variables if set.
+func initEnv(prefix string) {
+	copyEnvVars(prefix)
+
+	// env variables with TM prefix (eg. TM_ROOT)
+	viper.SetEnvPrefix(prefix)
+	viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_"))
+	viper.AutomaticEnv()
+}
+
+// This copies all variables like TMROOT to TM_ROOT,
+// so we can support both formats for the user
+func copyEnvVars(prefix string) {
+	prefix = strings.ToUpper(prefix)
+	ps := prefix + "_"
+	for _, e := range os.Environ() {
+		kv := strings.SplitN(e, "=", 2)
+		if len(kv) == 2 {
+			k, v := kv[0], kv[1]
+			if strings.HasPrefix(k, prefix) && !strings.HasPrefix(k, ps) {
+				k2 := strings.Replace(k, prefix, ps, 1)
+				os.Setenv(k2, v)
+			}
+		}
+	}
+}
+
+// Executor wraps the cobra Command with a nicer Execute method
+type Executor struct {
+	*cobra.Command
+}
+
+// execute adds all child commands to the root command sets flags appropriately.
+// This is called by main.main(). It only needs to happen once to the rootCmd.
+func (e Executor) Execute() error {
+	e.SilenceUsage = true
+	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 err
+}
+
+type cobraCmdFunc func(cmd *cobra.Command, args []string) error
+
+// Returns a single function that calls each argument function in sequence
+// RunE, PreRunE, PersistentPreRunE, etc. all have this same signature
+func concatCobraCmdFuncs(fs ...cobraCmdFunc) cobraCmdFunc {
+	return func(cmd *cobra.Command, args []string) error {
+		for _, f := range fs {
+			if f != nil {
+				if err := f(cmd, args); err != nil {
+					return err
+				}
+			}
+		}
+		return nil
+	}
+}
+
+// Bind all flags and read the config into viper
+func bindFlagsLoadViper(cmd *cobra.Command, args []string) error {
+	// cmd.Flags() includes flags from this command and all persistent flags from the parent
+	if err := viper.BindPFlags(cmd.Flags()); err != nil {
+		return err
+	}
+
+	// rootDir is command line flag, env variable, or default $HOME/.tlc
+	// NOTE: we support both --root and --home for now, but eventually only --home
+	// Also ensure we set the correct rootDir under HomeFlag so we dont need to
+	// repeat this logic elsewhere.
+	rootDir := viper.GetString(HomeFlag)
+	if rootDir == "" {
+		rootDir = viper.GetString(RootFlag)
+		viper.Set(HomeFlag, rootDir)
+	}
+	viper.SetConfigName("config") // name of config file (without extension)
+	viper.AddConfigPath(rootDir)  // search root directory
+
+	// If a config file is found, read it in.
+	if err := viper.ReadInConfig(); err == nil {
+		// stderr, so if we redirect output to json file, this doesn't appear
+		// fmt.Fprintln(os.Stderr, "Using config file:", viper.ConfigFileUsed())
+	} else if _, ok := err.(viper.ConfigFileNotFoundError); !ok {
+		// we ignore not found error, only parse error
+		// stderr, so if we redirect output to json file, this doesn't appear
+		fmt.Fprintf(os.Stderr, "%#v", err)
+	}
+	return nil
+}
+
+// setEncoding reads the encoding flag
+func setEncoding(cmd *cobra.Command, args []string) error {
+	// validate and set encoding
+	enc := viper.GetString("encoding")
+	switch enc {
+	case "hex":
+		data.Encoder = data.HexEncoder
+	case "b64":
+		data.Encoder = data.B64Encoder
+	case "btc":
+		data.Encoder = base58.BTCEncoder
+	default:
+		return errors.Errorf("Unsupported encoding: %s", enc)
+	}
+	return nil
+}
+
+func validateOutput(cmd *cobra.Command, args []string) error {
+	// validate output format
+	output := viper.GetString(OutputFlag)
+	switch output {
+	case "text", "json":
+	default:
+		return errors.Errorf("Unsupported output format: %s", output)
+	}
+	return nil
+}

cli/setup_test.go

@@ -0,0 +1,226 @@
+package cli
+
+import (
+	"fmt"
+	"strconv"
+	"strings"
+	"testing"
+
+	"github.com/pkg/errors"
+	"github.com/spf13/cobra"
+	"github.com/spf13/viper"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestSetupEnv(t *testing.T) {
+	assert, require := assert.New(t), require.New(t)
+
+	cases := []struct {
+		args     []string
+		env      map[string]string
+		expected string
+	}{
+		{nil, nil, ""},
+		{[]string{"--foobar", "bang!"}, nil, "bang!"},
+		// make sure reset is good
+		{nil, nil, ""},
+		// test both variants of the prefix
+		{nil, map[string]string{"DEMO_FOOBAR": "good"}, "good"},
+		{nil, map[string]string{"DEMOFOOBAR": "silly"}, "silly"},
+		// and that cli overrides env...
+		{[]string{"--foobar", "important"},
+			map[string]string{"DEMO_FOOBAR": "ignored"}, "important"},
+	}
+
+	for idx, tc := range cases {
+		i := strconv.Itoa(idx)
+		// test command that store value of foobar in local variable
+		var foo string
+		demo := &cobra.Command{
+			Use: "demo",
+			RunE: func(cmd *cobra.Command, args []string) error {
+				foo = viper.GetString("foobar")
+				return nil
+			},
+		}
+		demo.Flags().String("foobar", "", "Some test value from config")
+		cmd := PrepareBaseCmd(demo, "DEMO", "/qwerty/asdfgh") // some missing dir..
+
+		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)
+	}
+}
+
+func TestSetupConfig(t *testing.T) {
+	assert, require := assert.New(t), require.New(t)
+
+	// we pre-create two config files we can refer to in the rest of
+	// the test cases.
+	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"})
+	require.Nil(err)
+
+	cases := []struct {
+		args     []string
+		env      map[string]string
+		expected string
+	}{
+		{nil, nil, ""},
+		// setting on the command line
+		{[]string{"--boo", "haha"}, nil, "haha"},
+		{[]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},
+		// and when both are set??? HOME wins every time!
+		{[]string{"--root", conf1}, map[string]string{"RDHOME": conf2}, cval2},
+	}
+
+	for idx, tc := range cases {
+		i := strconv.Itoa(idx)
+		// test command that store value of foobar in local variable
+		var foo string
+		boo := &cobra.Command{
+			Use: "reader",
+			RunE: func(cmd *cobra.Command, args []string) error {
+				foo = viper.GetString("boo")
+				return nil
+			},
+		}
+		boo.Flags().String("boo", "", "Some test value from config")
+		cmd := PrepareBaseCmd(boo, "RD", "/qwerty/asdfgh") // some missing dir...
+
+		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)
+	}
+}
+
+type DemoConfig struct {
+	Name   string `mapstructure:"name"`
+	Age    int    `mapstructure:"age"`
+	Unused int    `mapstructure:"unused"`
+}
+
+func TestSetupUnmarshal(t *testing.T) {
+	assert, require := assert.New(t), require.New(t)
+
+	// we pre-create two config files we can refer to in the rest of
+	// the test cases.
+	cval1, cval2 := "someone", "else"
+	conf1, err := WriteDemoConfig(map[string]string{"name": cval1})
+	require.Nil(err)
+	// even with some ignored fields, should be no problem
+	conf2, err := WriteDemoConfig(map[string]string{"name": cval2, "foo": "bar"})
+	require.Nil(err)
+
+	// unused is not declared on a flag and remains from base
+	base := DemoConfig{
+		Name:   "default",
+		Age:    42,
+		Unused: -7,
+	}
+	c := func(name string, age int) DemoConfig {
+		r := base
+		// anything set on the flags as a default is used over
+		// the default config object
+		r.Name = "from-flag"
+		if name != "" {
+			r.Name = name
+		}
+		if age != 0 {
+			r.Age = age
+		}
+		return r
+	}
+
+	cases := []struct {
+		args     []string
+		env      map[string]string
+		expected DemoConfig
+	}{
+		{nil, nil, c("", 0)},
+		// setting on the command line
+		{[]string{"--name", "haha"}, nil, c("haha", 0)},
+		{[]string{"--root", conf1}, nil, c(cval1, 0)},
+		// test both variants of the prefix
+		{nil, map[string]string{"MR_AGE": "56"}, c("", 56)},
+		{nil, map[string]string{"MR_ROOT": conf1}, c(cval1, 0)},
+		{[]string{"--age", "17"}, map[string]string{"MRHOME": conf2}, c(cval2, 17)},
+	}
+
+	for idx, tc := range cases {
+		i := strconv.Itoa(idx)
+		// test command that store value of foobar in local variable
+		cfg := base
+		marsh := &cobra.Command{
+			Use: "marsh",
+			RunE: func(cmd *cobra.Command, args []string) error {
+				return viper.Unmarshal(&cfg)
+			},
+		}
+		marsh.Flags().String("name", "from-flag", "Some test value from config")
+		// if we want a flag to use the proper default, then copy it
+		// 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...
+
+		viper.Reset()
+		args := append([]string{cmd.Use}, tc.args...)
+		err := RunWithArgs(cmd, args, tc.env)
+		require.Nil(err, i)
+		assert.Equal(tc.expected, cfg, i)
+	}
+}
+
+func TestSetupTrace(t *testing.T) {
+	assert, require := assert.New(t), require.New(t)
+
+	cases := []struct {
+		args     []string
+		env      map[string]string
+		long     bool
+		expected string
+	}{
+		{nil, nil, false, "Trace flag = false"},
+		{[]string{"--trace"}, nil, true, "Trace flag = true"},
+		{[]string{"--no-such-flag"}, nil, false, "unknown flag: --no-such-flag"},
+		{nil, map[string]string{"DBG_TRACE": "true"}, true, "Trace flag = true"},
+	}
+
+	for idx, tc := range cases {
+		i := strconv.Itoa(idx)
+		// test command that store value of foobar in local variable
+		trace := &cobra.Command{
+			Use: "trace",
+			RunE: func(cmd *cobra.Command, args []string) error {
+				return errors.Errorf("Trace flag = %t", viper.GetBool(TraceFlag))
+			},
+		}
+		cmd := PrepareBaseCmd(trace, "DBG", "/qwerty/asdfgh") // some missing dir..
+
+		viper.Reset()
+		args := append([]string{cmd.Use}, tc.args...)
+		out, err := RunCaptureWithArgs(cmd, args, tc.env)
+		require.NotNil(err, i)
+		msg := strings.Split(out, "\n")
+		desired := fmt.Sprintf("ERROR: %s", tc.expected)
+		assert.Equal(desired, msg[0], i)
+		if tc.long && assert.True(len(msg) > 2, i) {
+			// the next line starts the stack trace...
+			assert.Contains(msg[1], "TestSetupTrace", i)
+			assert.Contains(msg[2], "setup_test.go", i)
+		}
+	}
+}

common/service.go

@@ -3,7 +3,7 @@ package common
 import (
 	"sync/atomic"
 
-	"github.com/tendermint/log15"
+	"github.com/tendermint/tmlibs/log"
 )
 
 type Service interface {
@@ -19,6 +19,8 @@ type Service interface {
 	IsRunning() bool
 
 	String() string
+
+	SetLogger(log.Logger)
 }
 
 /*
@@ -64,7 +66,7 @@ Typical usage:
 	}
 */
 type BaseService struct {
-	log     log15.Logger
+	Logger  log.Logger
 	name    string
 	started uint32 // atomic
 	stopped uint32 // atomic
@@ -74,27 +76,31 @@ type BaseService struct {
 	impl Service
 }
 
-func NewBaseService(log log15.Logger, name string, impl Service) *BaseService {
+func NewBaseService(logger log.Logger, name string, impl Service) *BaseService {
+	if logger == nil {
+		logger = log.NewNopLogger()
+	}
+
 	return &BaseService{
-		log:  log,
-		name: name,
-		Quit: make(chan struct{}),
-		impl: impl,
+		Logger: logger,
+		name:   name,
+		Quit:   make(chan struct{}),
+		impl:   impl,
 	}
 }
 
+func (bs *BaseService) SetLogger(l log.Logger) {
+	bs.Logger = l
+}
+
 // Implements Servce
 func (bs *BaseService) Start() (bool, error) {
 	if atomic.CompareAndSwapUint32(&bs.started, 0, 1) {
 		if atomic.LoadUint32(&bs.stopped) == 1 {
-			if bs.log != nil {
-				bs.log.Warn(Fmt("Not starting %v -- already stopped", bs.name), "impl", bs.impl)
-			}
+			bs.Logger.Error(Fmt("Not starting %v -- already stopped", bs.name), "impl", bs.impl)
 			return false, nil
 		} else {
-			if bs.log != nil {
-				bs.log.Info(Fmt("Starting %v", bs.name), "impl", bs.impl)
-			}
+			bs.Logger.Info(Fmt("Starting %v", bs.name), "impl", bs.impl)
 		}
 		err := bs.impl.OnStart()
 		if err != nil {
@@ -104,9 +110,7 @@ func (bs *BaseService) Start() (bool, error) {
 		}
 		return true, err
 	} else {
-		if bs.log != nil {
-			bs.log.Debug(Fmt("Not starting %v -- already started", bs.name), "impl", bs.impl)
-		}
+		bs.Logger.Debug(Fmt("Not starting %v -- already started", bs.name), "impl", bs.impl)
 		return false, nil
 	}
 }
@@ -119,16 +123,12 @@ func (bs *BaseService) OnStart() error { return nil }
 // Implements Service
 func (bs *BaseService) Stop() bool {
 	if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) {
-		if bs.log != nil {
-			bs.log.Info(Fmt("Stopping %v", bs.name), "impl", bs.impl)
-		}
+		bs.Logger.Info(Fmt("Stopping %v", bs.name), "impl", bs.impl)
 		bs.impl.OnStop()
 		close(bs.Quit)
 		return true
 	} else {
-		if bs.log != nil {
-			bs.log.Debug(Fmt("Stopping %v (ignoring: already stopped)", bs.name), "impl", bs.impl)
-		}
+		bs.Logger.Debug(Fmt("Stopping %v (ignoring: already stopped)", bs.name), "impl", bs.impl)
 		return false
 	}
 }
@@ -147,9 +147,7 @@ func (bs *BaseService) Reset() (bool, error) {
 		bs.Quit = make(chan struct{})
 		return true, bs.impl.OnReset()
 	} else {
-		if bs.log != nil {
-			bs.log.Debug(Fmt("Can't reset %v. Not stopped", bs.name), "impl", bs.impl)
-		}
+		bs.Logger.Debug(Fmt("Can't reset %v. Not stopped", bs.name), "impl", bs.impl)
 		return false, nil
 	}
 	// never happens
@@ -182,11 +180,11 @@ type QuitService struct {
 	BaseService
 }
 
-func NewQuitService(log log15.Logger, name string, impl Service) *QuitService {
-	if log != nil {
-		log.Warn("QuitService is deprecated, use BaseService instead")
+func NewQuitService(logger log.Logger, name string, impl Service) *QuitService {
+	if logger != nil {
+		logger.Info("QuitService is deprecated, use BaseService instead")
 	}
 	return &QuitService{
-		BaseService: *NewBaseService(log, name, impl),
+		BaseService: *NewBaseService(logger, name, impl),
 	}
 }

events/events.go

@@ -45,7 +45,7 @@ type eventSwitch struct {
 
 func NewEventSwitch() EventSwitch {
 	evsw := &eventSwitch{}
-	evsw.BaseService = *NewBaseService(log, "EventSwitch", evsw)
+	evsw.BaseService = *NewBaseService(nil, "EventSwitch", evsw)
 	return evsw
 }
 

events/log.go

@@ -1,7 +0,0 @@
-package events
-
-import (
-	"github.com/tendermint/tmlibs/logger"
-)
-
-var log = logger.New("module", "events")

glide.lock

@@ -1,18 +1,67 @@
-hash: 47e715510d6b57cff8dc4750b6b9d89a41469a8330a7a8bea1c044b2ac61e581
-updated: 2017-04-21T16:04:25.798163098-04:00
+hash: 69359a39dbb6957c9f09167520317ad72d4bfa75f37a614b347e2510768c8a42
+updated: 2017-05-05T17:46:34.975369143Z
 imports:
+- name: github.com/fsnotify/fsnotify
+  version: 4da3e2cfbabc9f751898f250b49f2439785783a1
+- name: github.com/go-kit/kit
+  version: 0873e56b0faeae3a1d661b10d629135508ea5504
+  subpackages:
+  - log
+  - log/level
+  - log/term
+- name: github.com/go-logfmt/logfmt
+  version: 390ab7935ee28ec6b286364bba9b4dd6410cb3d5
 - name: github.com/go-stack/stack
-  version: 100eb0c0a9c5b306ca2fb4f165df21d80ada4b82
+  version: 7a2f19628aabfe68f0766b59e74d6315f8347d22
 - name: github.com/golang/snappy
-  version: d9eb7a3d35ec988b8585d4a0068e462c27d28380
+  version: 553a641470496b2327abcac10b36396bd98e45c9
+- name: github.com/hashicorp/hcl
+  version: a4b07c25de5ff55ad3b8936cea69a79a3d95a855
+  subpackages:
+  - hcl/ast
+  - hcl/parser
+  - hcl/scanner
+  - hcl/strconv
+  - hcl/token
+  - json/parser
+  - json/scanner
+  - json/token
+- name: github.com/inconshreveable/mousetrap
+  version: 76626ae9c91c4f2a10f34cad8ce83ea42c93bb75
 - name: github.com/jmhodges/levigo
   version: c42d9e0ca023e2198120196f842701bb4c55d7b9
+- name: github.com/kr/logfmt
+  version: b84e30acd515aadc4b783ad4ff83aff3299bdfe0
+- name: github.com/magiconair/properties
+  version: 51463bfca2576e06c62a8504b5c0f06d61312647
 - name: github.com/mattn/go-colorable
-  version: d228849504861217f796da67fae4f6e347643f15
+  version: ded68f7a9561c023e790de24279db7ebf473ea80
 - name: github.com/mattn/go-isatty
-  version: 30a891c33c7cde7b02a981314b4228ec99380cca
+  version: fc9e8d8ef48496124e79ae0df75490096eccf6fe
+- name: github.com/mitchellh/mapstructure
+  version: cc8532a8e9a55ea36402aa21efdf403a60d34096
+- name: github.com/pelletier/go-buffruneio
+  version: c37440a7cf42ac63b919c752ca73a85067e05992
+- name: github.com/pelletier/go-toml
+  version: 97253b98df84f9eef872866d079e74b8265150f1
+- name: github.com/pkg/errors
+  version: c605e284fe17294bda444b34710735b29d1a9d90
+- name: github.com/spf13/afero
+  version: 9be650865eab0c12963d8753212f4f9c66cdcf12
+  subpackages:
+  - mem
+- name: github.com/spf13/cast
+  version: acbeb36b902d72a7a4c18e8f3241075e7ab763e4
+- name: github.com/spf13/cobra
+  version: db6b9a8b3f3f400c8ecb4a4d7d02245b8facad66
+- name: github.com/spf13/jwalterweatherman
+  version: fa7ca7e836cf3a8bb4ebf799f472c12d7e903d66
+- name: github.com/spf13/pflag
+  version: 80fe0fb4eba54167e2ccae1c6c950e72abf61b73
+- name: github.com/spf13/viper
+  version: 0967fc9aceab2ce9da34061253ac10fb99bba5b2
 - name: github.com/syndtr/goleveldb
-  version: 23851d93a2292dcc56e71a18ec9e0624d84a0f65
+  version: 8c81ea47d4c41a385645e133e15510fc6a2a74b4
   subpackages:
   - leveldb
   - leveldb/cache
@@ -27,22 +76,32 @@ imports:
   - leveldb/table
   - leveldb/util
 - name: github.com/tendermint/go-wire
-  version: 4325edc613ad1e9286c8bb770ed40ad3fe647e6c
+  version: b53add0b622662731985485f3a19be7f684660b8
+  subpackages:
+  - data
+  - data/base58
 - name: github.com/tendermint/log15
-  version: ae0f3d6450da9eac7074b439c8e1c3cabf0d5ce6
+  version: f91285dece9f4875421b481da3e613d83d44f29b
   subpackages:
   - term
 - name: golang.org/x/crypto
-  version: 7c6cc321c680f03b9ef0764448e780704f486b51
+  version: 5a033cc77e57eca05bdb50522851d29e03569cbe
   subpackages:
   - ripemd160
 - name: golang.org/x/sys
-  version: d75a52659825e75fff6158388dddc6a5b04f9ba5
+  version: 9ccfe848b9db8435a24c424abbc07a921adf1df5
   subpackages:
   - unix
+- name: golang.org/x/text
+  version: 470f45bf29f4147d6fbd7dfd0a02a848e49f5bf4
+  subpackages:
+  - transform
+  - unicode/norm
+- name: gopkg.in/yaml.v2
+  version: cd8b52f8269e0feb286dfeef29f8fe4d5b397e0b
 testImports:
 - name: github.com/davecgh/go-spew
-  version: 6d212800a42e8ab5c146b8ace3490ee17e5225f9
+  version: 04cdfd42973bb9c8589fd6a731800cf222fde1a9
   subpackages:
   - spew
 - name: github.com/pmezard/go-difflib
@@ -50,6 +109,7 @@ testImports:
   subpackages:
   - difflib
 - name: github.com/stretchr/testify
-  version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0
+  version: 4d4bfba8f1d1027c4fdbe371823030df51419987
   subpackages:
   - assert
+  - require

glide.yaml

@@ -1,17 +1,31 @@
 package: github.com/tendermint/tmlibs
 import:
+- package: github.com/go-kit/kit
+  subpackages:
+  - log
+  - log/level
+  - log/term
+- package: github.com/go-logfmt/logfmt
 - package: github.com/jmhodges/levigo
+- package: github.com/pkg/errors
+- package: github.com/spf13/cobra
+- package: github.com/spf13/viper
 - package: github.com/syndtr/goleveldb
   subpackages:
   - leveldb
   - leveldb/errors
   - leveldb/opt
 - package: github.com/tendermint/go-wire
+  subpackages:
+  - data
+  - data/base58
 - package: github.com/tendermint/log15
 - package: golang.org/x/crypto
   subpackages:
   - ripemd160
 testImport:
 - package: github.com/stretchr/testify
+  version: ^1.1.4
   subpackages:
   - assert
+  - require

log/filter.go

@@ -0,0 +1,165 @@
+package log
+
+import "fmt"
+
+// NewFilter wraps next and implements filtering. See the commentary on the
+// Option functions for a detailed description of how to configure levels. If
+// no options are provided, all leveled log events created with Debug, Info or
+// Error helper methods are squelched.
+func NewFilter(next Logger, options ...Option) Logger {
+	l := &filter{
+		next:           next,
+		allowedKeyvals: make(map[keyval]level),
+	}
+	for _, option := range options {
+		option(l)
+	}
+	return l
+}
+
+// AllowLevel returns an option for the given level or error if no option exist
+// for such level.
+func AllowLevel(lvl string) (Option, error) {
+	switch lvl {
+	case "debug":
+		return AllowDebug(), nil
+	case "info":
+		return AllowInfo(), nil
+	case "error":
+		return AllowError(), nil
+	case "none":
+		return AllowNone(), nil
+	default:
+		return nil, fmt.Errorf("Expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl)
+	}
+}
+
+type filter struct {
+	next           Logger
+	allowed        level
+	allowedKeyvals map[keyval]level
+	errNotAllowed  error
+}
+
+type keyval struct {
+	key   interface{}
+	value interface{}
+}
+
+func (l *filter) Info(msg string, keyvals ...interface{}) error {
+	levelAllowed := l.allowed&levelInfo != 0
+	if !levelAllowed {
+		return l.errNotAllowed
+	}
+	return l.next.Info(msg, keyvals...)
+}
+
+func (l *filter) Debug(msg string, keyvals ...interface{}) error {
+	levelAllowed := l.allowed&levelDebug != 0
+	if !levelAllowed {
+		return l.errNotAllowed
+	}
+	return l.next.Debug(msg, keyvals...)
+}
+
+func (l *filter) Error(msg string, keyvals ...interface{}) error {
+	levelAllowed := l.allowed&levelError != 0
+	if !levelAllowed {
+		return l.errNotAllowed
+	}
+	return l.next.Error(msg, keyvals...)
+}
+
+// With implements Logger by constructing a new filter with a keyvals appended
+// to the logger.
+//
+// If custom level was set for a keyval pair using one of the
+// Allow*With methods, it is used as the logger's level.
+//
+// Examples:
+//     logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
+//		 logger.With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto"
+//
+//     logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam"))
+//		 logger.With("module", "crypto", "user", "Sam").Info("Hello") # returns nil
+//
+//     logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam"))
+//		 logger.With("user", "Sam").With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto user=Sam"
+func (l *filter) With(keyvals ...interface{}) Logger {
+	for i := len(keyvals) - 2; i >= 0; i -= 2 {
+		for kv, allowed := range l.allowedKeyvals {
+			if keyvals[i] == kv.key && keyvals[i+1] == kv.value {
+				return &filter{next: l.next.With(keyvals...), allowed: allowed, errNotAllowed: l.errNotAllowed, allowedKeyvals: l.allowedKeyvals}
+			}
+		}
+	}
+	return &filter{next: l.next.With(keyvals...), allowed: l.allowed, errNotAllowed: l.errNotAllowed, allowedKeyvals: l.allowedKeyvals}
+}
+
+// Option sets a parameter for the filter.
+type Option func(*filter)
+
+// AllowAll is an alias for AllowDebug.
+func AllowAll() Option {
+	return AllowDebug()
+}
+
+// AllowDebug allows error, info and debug level log events to pass.
+func AllowDebug() Option {
+	return allowed(levelError | levelInfo | levelDebug)
+}
+
+// AllowInfo allows error and info level log events to pass.
+func AllowInfo() Option {
+	return allowed(levelError | levelInfo)
+}
+
+// AllowError allows only error level log events to pass.
+func AllowError() Option {
+	return allowed(levelError)
+}
+
+// AllowNone allows no leveled log events to pass.
+func AllowNone() Option {
+	return allowed(0)
+}
+
+func allowed(allowed level) Option {
+	return func(l *filter) { l.allowed = allowed }
+}
+
+// ErrNotAllowed sets the error to return from Log when it squelches a log
+// event disallowed by the configured Allow[Level] option. By default,
+// ErrNotAllowed is nil; in this case the log event is squelched with no
+// error.
+func ErrNotAllowed(err error) Option {
+	return func(l *filter) { l.errNotAllowed = err }
+}
+
+// AllowDebugWith allows error, info and debug level log events to pass for a specific key value pair.
+func AllowDebugWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo | levelDebug }
+}
+
+// AllowInfoWith allows error and info level log events to pass for a specific key value pair.
+func AllowInfoWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo }
+}
+
+// AllowErrorWith allows only error level log events to pass for a specific key value pair.
+func AllowErrorWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError }
+}
+
+// AllowNoneWith allows no leveled log events to pass for a specific key value pair.
+func AllowNoneWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = 0 }
+}
+
+type level byte
+
+const (
+	levelDebug level = 1 << iota
+	levelInfo
+	levelError
+)

log/filter_test.go

@@ -0,0 +1,138 @@
+package log_test
+
+import (
+	"bytes"
+	"errors"
+	"strings"
+	"testing"
+
+	"github.com/tendermint/tmlibs/log"
+)
+
+func TestVariousLevels(t *testing.T) {
+	testCases := []struct {
+		name    string
+		allowed log.Option
+		want    string
+	}{
+		{
+			"AllowAll",
+			log.AllowAll(),
+			strings.Join([]string{
+				`{"_msg":"here","level":"debug","this is":"debug log"}`,
+				`{"_msg":"here","level":"info","this is":"info log"}`,
+				`{"_msg":"here","level":"error","this is":"error log"}`,
+			}, "\n"),
+		},
+		{
+			"AllowDebug",
+			log.AllowDebug(),
+			strings.Join([]string{
+				`{"_msg":"here","level":"debug","this is":"debug log"}`,
+				`{"_msg":"here","level":"info","this is":"info log"}`,
+				`{"_msg":"here","level":"error","this is":"error log"}`,
+			}, "\n"),
+		},
+		{
+			"AllowInfo",
+			log.AllowInfo(),
+			strings.Join([]string{
+				`{"_msg":"here","level":"info","this is":"info log"}`,
+				`{"_msg":"here","level":"error","this is":"error log"}`,
+			}, "\n"),
+		},
+		{
+			"AllowError",
+			log.AllowError(),
+			strings.Join([]string{
+				`{"_msg":"here","level":"error","this is":"error log"}`,
+			}, "\n"),
+		},
+		{
+			"AllowNone",
+			log.AllowNone(),
+			``,
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			var buf bytes.Buffer
+			logger := log.NewFilter(log.NewTMJSONLogger(&buf), tc.allowed)
+
+			logger.Debug("here", "this is", "debug log")
+			logger.Info("here", "this is", "info log")
+			logger.Error("here", "this is", "error log")
+
+			if want, have := tc.want, strings.TrimSpace(buf.String()); want != have {
+				t.Errorf("\nwant:\n%s\nhave:\n%s", want, have)
+			}
+		})
+	}
+}
+
+func TestErrNotAllowed(t *testing.T) {
+	myError := errors.New("squelched!")
+	opts := []log.Option{
+		log.AllowError(),
+		log.ErrNotAllowed(myError),
+	}
+	logger := log.NewFilter(log.NewNopLogger(), opts...)
+
+	if want, have := myError, logger.Info("foo", "bar", "baz"); want != have {
+		t.Errorf("want %#+v, have %#+v", want, have)
+	}
+
+	if want, have := error(nil), logger.Error("foo", "bar", "baz"); want != have {
+		t.Errorf("want %#+v, have %#+v", want, have)
+	}
+}
+
+func TestLevelContext(t *testing.T) {
+	var buf bytes.Buffer
+
+	var logger log.Logger
+	logger = log.NewTMJSONLogger(&buf)
+	logger = log.NewFilter(logger, log.AllowError())
+	logger = logger.With("context", "value")
+
+	logger.Error("foo", "bar", "baz")
+	if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"error"}`, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+	logger.Info("foo", "bar", "baz")
+	if want, have := ``, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+}
+
+func TestVariousAllowWith(t *testing.T) {
+	var buf bytes.Buffer
+
+	var logger log.Logger
+	logger = log.NewTMJSONLogger(&buf)
+
+	logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"))
+	logger1.With("context", "value").Info("foo", "bar", "baz")
+	if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info"}`, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+
+	logger2 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam"))
+	logger2.With("context", "value", "user", "Sam").Info("foo", "bar", "baz")
+	if want, have := ``, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+
+	logger3 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam"))
+	logger3.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)
+	}
+}

log/logger.go

@@ -0,0 +1,30 @@
+package log
+
+import (
+	"io"
+
+	kitlog "github.com/go-kit/kit/log"
+)
+
+// Logger is what any Tendermint library should take.
+type Logger interface {
+	Debug(msg string, keyvals ...interface{}) error
+	Info(msg string, keyvals ...interface{}) error
+	Error(msg string, keyvals ...interface{}) error
+
+	With(keyvals ...interface{}) Logger
+}
+
+// NewSyncWriter returns a new writer that is safe for concurrent use by
+// multiple goroutines. Writes to the returned writer are passed on to w. If
+// another write is already in progress, the calling goroutine blocks until
+// the writer is available.
+//
+// If w implements the following interface, so does the returned writer.
+//
+//    interface {
+//        Fd() uintptr
+//    }
+func NewSyncWriter(w io.Writer) io.Writer {
+	return kitlog.NewSyncWriter(w)
+}

log/nop_logger.go

@@ -0,0 +1,25 @@
+package log
+
+type nopLogger struct{}
+
+// Interface assertions
+var _ Logger = (*nopLogger)(nil)
+
+// NewNopLogger returns a logger that doesn't do anything.
+func NewNopLogger() Logger { return &nopLogger{} }
+
+func (nopLogger) Info(string, ...interface{}) error {
+	return nil
+}
+
+func (nopLogger) Debug(string, ...interface{}) error {
+	return nil
+}
+
+func (nopLogger) Error(string, ...interface{}) error {
+	return nil
+}
+
+func (l *nopLogger) With(...interface{}) Logger {
+	return l
+}

log/nop_logger_test.go

@@ -0,0 +1,18 @@
+package log_test
+
+import (
+	"testing"
+
+	"github.com/tendermint/tmlibs/log"
+)
+
+func TestNopLogger(t *testing.T) {
+	t.Parallel()
+	logger := log.NewNopLogger()
+	if err := logger.Info("Hello", "abc", 123); err != nil {
+		t.Error(err)
+	}
+	if err := logger.With("def", "ghi").Debug(""); err != nil {
+		t.Error(err)
+	}
+}

log/testing_logger.go

@@ -0,0 +1,49 @@
+package log
+
+import (
+	"os"
+	"testing"
+
+	"github.com/go-kit/kit/log/term"
+)
+
+var (
+	// reuse the same logger across all tests
+	_testingLogger Logger
+)
+
+// TestingLogger returns a TMLogger which writes to STDOUT if testing being run
+// with the verbose (-v) flag, NopLogger otherwise.
+//
+// Note that the call to TestingLogger() must be made
+// inside a test (not in the init func) because
+// verbose flag only set at the time of testing.
+func TestingLogger() Logger {
+	if _testingLogger != nil {
+		return _testingLogger
+	}
+
+	if testing.Verbose() {
+		_testingLogger = NewTMLogger(NewSyncWriter(os.Stdout))
+	} else {
+		_testingLogger = NewNopLogger()
+	}
+
+	return _testingLogger
+}
+
+// TestingLoggerWithColorFn allow you to provide your own color function. See
+// TestingLogger for documentation.
+func TestingLoggerWithColorFn(colorFn func(keyvals ...interface{}) term.FgBgColor) Logger {
+	if _testingLogger != nil {
+		return _testingLogger
+	}
+
+	if testing.Verbose() {
+		_testingLogger = NewTMLoggerWithColorFn(NewSyncWriter(os.Stdout), colorFn)
+	} else {
+		_testingLogger = NewNopLogger()
+	}
+
+	return _testingLogger
+}

log/tm_json_logger.go

@@ -0,0 +1,15 @@
+package log
+
+import (
+	"io"
+
+	kitlog "github.com/go-kit/kit/log"
+)
+
+// NewTMJSONLogger returns a Logger that encodes keyvals to the Writer as a
+// single JSON object. Each log event produces no more than one call to
+// w.Write. The passed Writer must be safe for concurrent use by multiple
+// goroutines if the returned Logger will be used concurrently.
+func NewTMJSONLogger(w io.Writer) Logger {
+	return &tmLogger{kitlog.NewJSONLogger(w)}
+}

log/tm_logger.go

@@ -0,0 +1,74 @@
+package log
+
+import (
+	"fmt"
+	"io"
+
+	kitlog "github.com/go-kit/kit/log"
+	kitlevel "github.com/go-kit/kit/log/level"
+	"github.com/go-kit/kit/log/term"
+)
+
+const (
+	msgKey    = "_msg" // "_" prefixed to avoid collisions
+	moduleKey = "module"
+)
+
+type tmLogger struct {
+	srcLogger kitlog.Logger
+}
+
+// Interface assertions
+var _ Logger = (*tmLogger)(nil)
+
+// NewTMTermLogger returns a logger that encodes msg and keyvals to the Writer
+// using go-kit's log as an underlying logger and our custom formatter. Note
+// that underlying logger could be swapped with something else.
+func NewTMLogger(w io.Writer) Logger {
+	// Color by level value
+	colorFn := func(keyvals ...interface{}) term.FgBgColor {
+		if keyvals[0] != kitlevel.Key() {
+			panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0]))
+		}
+		switch keyvals[1].(kitlevel.Value).String() {
+		case "debug":
+			return term.FgBgColor{Fg: term.DarkGray}
+		case "error":
+			return term.FgBgColor{Fg: term.Red}
+		default:
+			return term.FgBgColor{}
+		}
+	}
+
+	return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)}
+}
+
+// NewTMLoggerWithColorFn allow 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)}
+}
+
+// Info logs a message at level Info.
+func (l *tmLogger) Info(msg string, keyvals ...interface{}) error {
+	lWithLevel := kitlevel.Info(l.srcLogger)
+	return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...)
+}
+
+// Debug logs a message at level Debug.
+func (l *tmLogger) Debug(msg string, keyvals ...interface{}) error {
+	lWithLevel := kitlevel.Debug(l.srcLogger)
+	return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...)
+}
+
+// Error logs a message at level Error.
+func (l *tmLogger) Error(msg string, keyvals ...interface{}) error {
+	lWithLevel := kitlevel.Error(l.srcLogger)
+	return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...)
+}
+
+// With returns a new contextual logger with keyvals prepended to those passed
+// to calls to Info, Debug or Error.
+func (l *tmLogger) With(keyvals ...interface{}) Logger {
+	return &tmLogger{kitlog.With(l.srcLogger, keyvals...)}
+}

log/tm_logger_test.go

@@ -0,0 +1,41 @@
+package log_test
+
+import (
+	"io/ioutil"
+	"testing"
+
+	"github.com/tendermint/tmlibs/log"
+)
+
+func TestTMLogger(t *testing.T) {
+	t.Parallel()
+	logger := log.NewTMLogger(ioutil.Discard)
+	if err := logger.Info("Hello", "abc", 123); err != nil {
+		t.Error(err)
+	}
+	if err := logger.With("def", "ghi").Debug(""); err != nil {
+		t.Error(err)
+	}
+}
+
+func BenchmarkTMLoggerSimple(b *testing.B) {
+	benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), baseInfoMessage)
+}
+
+func BenchmarkTMLoggerContextual(b *testing.B) {
+	benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), withInfoMessage)
+}
+
+func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
+	lc := logger.With("common_key", "common_value")
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		f(lc)
+	}
+}
+
+var (
+	baseInfoMessage = func(logger log.Logger) { logger.Info("foo_message", "foo_key", "foo_value") }
+	withInfoMessage = func(logger log.Logger) { logger.With("a", "b").Info("c", "d", "f") }
+)

log/tmfmt_logger.go

@@ -0,0 +1,122 @@
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"sync"
+	"time"
+
+	kitlog "github.com/go-kit/kit/log"
+	kitlevel "github.com/go-kit/kit/log/level"
+	"github.com/go-logfmt/logfmt"
+)
+
+type tmfmtEncoder struct {
+	*logfmt.Encoder
+	buf bytes.Buffer
+}
+
+func (l *tmfmtEncoder) Reset() {
+	l.Encoder.Reset()
+	l.buf.Reset()
+}
+
+var tmfmtEncoderPool = sync.Pool{
+	New: func() interface{} {
+		var enc tmfmtEncoder
+		enc.Encoder = logfmt.NewEncoder(&enc.buf)
+		return &enc
+	},
+}
+
+type tmfmtLogger struct {
+	w io.Writer
+}
+
+// NewTMFmtLogger returns a logger that encodes keyvals to the Writer in
+// Tendermint custom format.
+//
+// Each log event produces no more than one call to w.Write.
+// The passed Writer must be safe for concurrent use by multiple goroutines if
+// the returned Logger will be used concurrently.
+func NewTMFmtLogger(w io.Writer) kitlog.Logger {
+	return &tmfmtLogger{w}
+}
+
+func (l tmfmtLogger) Log(keyvals ...interface{}) error {
+	enc := tmfmtEncoderPool.Get().(*tmfmtEncoder)
+	enc.Reset()
+	defer tmfmtEncoderPool.Put(enc)
+
+	lvl := "none"
+	msg := "unknown"
+	module := "unknown"
+
+	// indexes of keys to skip while encoding later
+	excludeIndexes := make([]int, 0)
+
+	for i := 0; i < len(keyvals)-1; i += 2 {
+		// Extract level
+		if keyvals[i] == kitlevel.Key() {
+			excludeIndexes = append(excludeIndexes, i)
+			switch keyvals[i+1].(type) {
+			case string:
+				lvl = keyvals[i+1].(string)
+			case kitlevel.Value:
+				lvl = keyvals[i+1].(kitlevel.Value).String()
+			default:
+				panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1]))
+			}
+			// and message
+		} else if keyvals[i] == msgKey {
+			excludeIndexes = append(excludeIndexes, i)
+			msg = keyvals[i+1].(string)
+			// and module (could be multiple keyvals; if such case last keyvalue wins)
+		} else if keyvals[i] == moduleKey {
+			excludeIndexes = append(excludeIndexes, i)
+			module = keyvals[i+1].(string)
+		}
+	}
+
+	// Form a custom Tendermint line
+	//
+	// Example:
+	//     D[05-02|11:06:44.322] Stopping AddrBook (ignoring: already stopped)
+	//
+	// Description:
+	//     D										- first character of the level, uppercase (ASCII only)
+	//     [05-02|11:06:44.322] - our time format (see https://golang.org/src/time/format.go)
+	//     Stopping ...					- message
+	enc.buf.WriteString(fmt.Sprintf("%c[%s] %-44s ", lvl[0]-32, time.Now().UTC().Format("01-02|15:04:05.000"), msg))
+
+	if module != "unknown" {
+		enc.buf.WriteString("module=" + module + " ")
+	}
+
+KeyvalueLoop:
+	for i := 0; i < len(keyvals)-1; i += 2 {
+		for _, j := range excludeIndexes {
+			if i == j {
+				continue KeyvalueLoop
+			}
+		}
+
+		if err := enc.EncodeKeyval(keyvals[i], keyvals[i+1]); err != nil {
+			return err
+		}
+	}
+
+	// Add newline to the end of the buffer
+	if err := enc.EndRecord(); err != nil {
+		return err
+	}
+
+	// The Logger interface requires implementations to be safe for concurrent
+	// use by multiple goroutines. For this implementation that means making
+	// only one call to l.w.Write() for each call to Log.
+	if _, err := l.w.Write(enc.buf.Bytes()); err != nil {
+		return err
+	}
+	return nil
+}

log/tmfmt_logger_test.go

@@ -0,0 +1,116 @@
+package log_test
+
+import (
+	"bytes"
+	"errors"
+	"io/ioutil"
+	"math"
+	"regexp"
+	"testing"
+
+	kitlog "github.com/go-kit/kit/log"
+	"github.com/stretchr/testify/assert"
+	"github.com/tendermint/tmlibs/log"
+)
+
+func TestTMFmtLogger(t *testing.T) {
+	t.Parallel()
+	buf := &bytes.Buffer{}
+	logger := log.NewTMFmtLogger(buf)
+
+	if err := logger.Log("hello", "world"); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ hello=world\n$`), buf.String())
+
+	buf.Reset()
+	if err := logger.Log("a", 1, "err", errors.New("error")); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ a=1 err=error\n$`), buf.String())
+
+	buf.Reset()
+	err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0})
+	assert.NotNil(t, err)
+
+	buf.Reset()
+	if err := logger.Log("level", "error"); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`E\[.+\] unknown \s+\n$`), buf.String())
+
+	buf.Reset()
+	if err := logger.Log("_msg", "Hello"); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`N\[.+\] Hello \s+\n$`), buf.String())
+
+	buf.Reset()
+	if err := logger.Log("module", "main", "module", "crypto", "module", "wire"); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+module=wire\s+\n$`), buf.String())
+}
+
+func BenchmarkTMFmtLoggerSimple(b *testing.B) {
+	benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), baseMessage)
+}
+
+func BenchmarkTMFmtLoggerContextual(b *testing.B) {
+	benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), withMessage)
+}
+
+func TestTMFmtLoggerConcurrency(t *testing.T) {
+	t.Parallel()
+	testConcurrency(t, log.NewTMFmtLogger(ioutil.Discard), 10000)
+}
+
+func benchmarkRunnerKitlog(b *testing.B, logger kitlog.Logger, f func(kitlog.Logger)) {
+	lc := kitlog.With(logger, "common_key", "common_value")
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		f(lc)
+	}
+}
+
+var (
+	baseMessage = func(logger kitlog.Logger) { logger.Log("foo_key", "foo_value") }
+	withMessage = func(logger kitlog.Logger) { kitlog.With(logger, "a", "b").Log("d", "f") }
+)
+
+// These test are designed to be run with the race detector.
+
+func testConcurrency(t *testing.T, logger kitlog.Logger, total int) {
+	n := int(math.Sqrt(float64(total)))
+	share := total / n
+
+	errC := make(chan error, n)
+
+	for i := 0; i < n; i++ {
+		go func() {
+			errC <- spam(logger, share)
+		}()
+	}
+
+	for i := 0; i < n; i++ {
+		err := <-errC
+		if err != nil {
+			t.Fatalf("concurrent logging error: %v", err)
+		}
+	}
+}
+
+func spam(logger kitlog.Logger, count int) error {
+	for i := 0; i < count; i++ {
+		err := logger.Log("key", i)
+		if err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+type mymap map[int]int
+
+func (m mymap) String() string { return "special_behavior" }

logger/log.go

@@ -1,10 +1,11 @@
+// DEPRECATED! Use newer log package.
 package logger
 
 import (
 	"os"
 
-	. "github.com/tendermint/tmlibs/common"
 	"github.com/tendermint/log15"
+	. "github.com/tendermint/tmlibs/common"
 )
 
 var mainHandler log15.Handler
@@ -40,14 +41,14 @@ func MainHandler() log15.Handler {
 	return mainHandler
 }
 
-func BypassHandler() log15.Handler {
-	return bypassHandler
-}
-
 func New(ctx ...interface{}) log15.Logger {
 	return NewMain(ctx...)
 }
 
+func BypassHandler() log15.Handler {
+	return bypassHandler
+}
+
 func NewMain(ctx ...interface{}) log15.Logger {
 	return log15.Root().New(ctx...)
 }