From b92bd8f6a8d10553d27fdff8cf6d7205c83904f3 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Tue, 2 May 2017 17:01:50 +0200 Subject: [PATCH 01/36] Separate out PrepareBaseCmd, try to set env vars --- cli/setup.go | 136 +++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 136 insertions(+) create mode 100644 cli/setup.go diff --git a/cli/setup.go b/cli/setup.go new file mode 100644 index 00000000..be5735d9 --- /dev/null +++ b/cli/setup.go @@ -0,0 +1,136 @@ +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" + OutputFlag = "output" + EncodingFlag = "encoding" +) + +// PrepareBaseCmd is meant for tendermint and other servers +func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { + cobra.OnInitialize(func() { initEnv(envPrefix) }) + cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "root directory for config and data") + cmd.PersistentPreRunE = multiE(bindFlags, cmd.PersistentPreRunE) + return func() { execute(cmd) } +} + +// PrepareMainCmd is meant for client side libs that want some more flags +func PrepareMainCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { + cmd.PersistentFlags().StringP(EncodingFlag, "e", "hex", "Binary encoding (hex|b64|btc)") + cmd.PersistentFlags().StringP(OutputFlag, "o", "text", "Output format (text|json)") + cmd.PersistentPreRunE = multiE(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, "=", 1) + 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) + } + } +} + +// 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 execute(cmd *cobra.Command) { + // TODO: this can do something cooler with debug and log-levels + if err := cmd.Execute(); err != nil { + fmt.Println(err) + os.Exit(-1) + } +} + +type wrapE func(cmd *cobra.Command, args []string) error + +func multiE(fs ...wrapE) wrapE { + 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 + } +} + +func bindFlags(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 + rootDir := viper.GetString("root") + 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 +} From d4ab9679d71c8fc174284696d15930cb799fa24f Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Tue, 2 May 2017 17:16:22 +0200 Subject: [PATCH 02/36] Fix up error in copyEnv --- cli/setup.go | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index be5735d9..5a7218a8 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -50,11 +50,13 @@ func copyEnvVars(prefix string) { prefix = strings.ToUpper(prefix) ps := prefix + "_" for _, e := range os.Environ() { - kv := strings.SplitN(e, "=", 1) - 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) + 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) + } } } } From a95a60cb0bece614db9c0d16faade4aaad0dfab5 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Tue, 2 May 2017 14:50:24 -0400 Subject: [PATCH 03/36] cli: support --root and --home --- cli/setup.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index 5a7218a8..d7a11e06 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -14,6 +14,7 @@ import ( const ( RootFlag = "root" + HomeFlag = "home" OutputFlag = "output" EncodingFlag = "encoding" ) @@ -21,7 +22,8 @@ const ( // PrepareBaseCmd is meant for tendermint and other servers func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { cobra.OnInitialize(func() { initEnv(envPrefix) }) - cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "root directory for config and data") + cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "DEPRECATED. Use --home") + cmd.PersistentFlags().StringP(HomeFlag, "h", defautRoot, "root directory for config and data") cmd.PersistentPreRunE = multiE(bindFlags, cmd.PersistentPreRunE) return func() { execute(cmd) } } @@ -93,7 +95,11 @@ func bindFlags(cmd *cobra.Command, args []string) error { } // rootDir is command line flag, env variable, or default $HOME/.tlc - rootDir := viper.GetString("root") + // NOTE: we support both --root and --home for now, but eventually only --home + rootDir := viper.GetString(HomeFlag) + if !viper.IsSet(HomeFlag) && viper.IsSet(RootFlag) { + rootDir = viper.GetString(RootFlag) + } viper.SetConfigName("config") // name of config file (without extension) viper.AddConfigPath(rootDir) // search root directory From 7becd35126765a5cad3018c1efc3922cd2f1a0d2 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Tue, 2 May 2017 14:57:32 -0400 Subject: [PATCH 04/36] cli: more descriptive naming --- cli/setup.go | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index d7a11e06..14801ee5 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -8,6 +8,7 @@ import ( "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" ) @@ -24,7 +25,7 @@ func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { cobra.OnInitialize(func() { initEnv(envPrefix) }) cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "DEPRECATED. Use --home") cmd.PersistentFlags().StringP(HomeFlag, "h", defautRoot, "root directory for config and data") - cmd.PersistentPreRunE = multiE(bindFlags, cmd.PersistentPreRunE) + cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) return func() { execute(cmd) } } @@ -32,7 +33,7 @@ func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { func PrepareMainCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { cmd.PersistentFlags().StringP(EncodingFlag, "e", "hex", "Binary encoding (hex|b64|btc)") cmd.PersistentFlags().StringP(OutputFlag, "o", "text", "Output format (text|json)") - cmd.PersistentPreRunE = multiE(setEncoding, validateOutput, cmd.PersistentPreRunE) + cmd.PersistentPreRunE = concatCobraCmdFuncs(setEncoding, validateOutput, cmd.PersistentPreRunE) return PrepareBaseCmd(cmd, envPrefix, defautRoot) } @@ -73,9 +74,10 @@ func execute(cmd *cobra.Command) { } } -type wrapE func(cmd *cobra.Command, args []string) error +type cobraCmdFunc func(cmd *cobra.Command, args []string) error -func multiE(fs ...wrapE) wrapE { +// Returns a single function that calls each argument function in sequence +func concatCobraCmdFuncs(fs ...cobraCmdFunc) cobraCmdFunc { return func(cmd *cobra.Command, args []string) error { for _, f := range fs { if f != nil { @@ -88,7 +90,8 @@ func multiE(fs ...wrapE) wrapE { } } -func bindFlags(cmd *cobra.Command, args []string) error { +// 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 From 435fd0ece75acd97910f7e617525bc31839730bc Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 09:25:04 +0200 Subject: [PATCH 05/36] Add clarifying comments as requested by Rigel --- cli/setup.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/cli/setup.go b/cli/setup.go index 14801ee5..8120449c 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -30,6 +30,9 @@ func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { } // 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) func() { cmd.PersistentFlags().StringP(EncodingFlag, "e", "hex", "Binary encoding (hex|b64|btc)") cmd.PersistentFlags().StringP(OutputFlag, "o", "text", "Output format (text|json)") @@ -77,6 +80,7 @@ func execute(cmd *cobra.Command) { 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 { From 62427adbec0814203bfcc93ee20e40092b5f6f3c Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 10:02:21 +0200 Subject: [PATCH 06/36] First basic test case on setup functionality --- cli/setup_test.go | 122 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 122 insertions(+) create mode 100644 cli/setup_test.go diff --git a/cli/setup_test.go b/cli/setup_test.go new file mode 100644 index 00000000..4e16bdfe --- /dev/null +++ b/cli/setup_test.go @@ -0,0 +1,122 @@ +package cli + +import ( + "bytes" + "io" + "os" + "strconv" + "testing" + + "github.com/spf13/cobra" + "github.com/spf13/viper" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// Executable is the minimal interface to *corba.Command, so we can +// wrap if desired before the test +type Executable interface { + Execute() error +} + +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 + cmd := &cobra.Command{ + Use: "demo", + RunE: func(cmd *cobra.Command, args []string) error { + foo = viper.GetString("foobar") + return nil + }, + } + cmd.Flags().String("foobar", "", "Some test value from config") + PrepareBaseCmd(cmd, "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) + } +} + +// 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 + ov := os.Getenv(k) + if ov != "" { + oenv[k] = ov + } + 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 +} From 5637a7885430b695dc06fb9d9b7f034a2a0361b2 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 10:23:58 +0200 Subject: [PATCH 07/36] Test setting config file as root --- cli/setup_test.go | 71 ++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 67 insertions(+), 4 deletions(-) diff --git a/cli/setup_test.go b/cli/setup_test.go index 4e16bdfe..fb8e5655 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -2,8 +2,11 @@ package cli import ( "bytes" + "fmt" "io" + "io/ioutil" "os" + "path/filepath" "strconv" "testing" @@ -61,6 +64,69 @@ func TestSetupEnv(t *testing.T) { } } +func writeConfig(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 +} + +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 := writeConfig(map[string]string{"boo": cval1}) + require.Nil(err) + // even with some ignored fields, should be no problem + conf2, err := writeConfig(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}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + var foo string + cmd := &cobra.Command{ + Use: "reader", + RunE: func(cmd *cobra.Command, args []string) error { + foo = viper.GetString("boo") + return nil + }, + } + cmd.Flags().String("boo", "", "Some test value from config") + PrepareBaseCmd(cmd, "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) + } +} + // 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 { @@ -78,10 +144,7 @@ func runWithArgs(cmd Executable, args []string, env map[string]string) error { os.Args = args for k, v := range env { // backup old value if there, to restore at end - ov := os.Getenv(k) - if ov != "" { - oenv[k] = ov - } + oenv[k] = os.Getenv(k) err := os.Setenv(k, v) if err != nil { return err From d05b8131a32c72139bf187834478c09889aa6b30 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 10:30:50 +0200 Subject: [PATCH 08/36] Updated glide with cobra/viper, fixed Makefile typo --- Makefile | 2 +- glide.lock | 68 ++++++++++++++++++++++++++++++++++++++++++++++++++---- glide.yaml | 3 +++ 3 files changed, 68 insertions(+), 5 deletions(-) diff --git a/Makefile b/Makefile index 49acb091..cd1a5734 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,4 @@ -.PHONEY: all test install get_vendor_deps ensure_tools +.PHONY: all test install get_vendor_deps ensure_tools GOTOOLS = \ github.com/Masterminds/glide diff --git a/glide.lock b/glide.lock index 003e3d61..b7d4fb8f 100644 --- a/glide.lock +++ b/glide.lock @@ -1,16 +1,65 @@ -hash: 47e715510d6b57cff8dc4750b6b9d89a41469a8330a7a8bea1c044b2ac61e581 -updated: 2017-04-21T16:04:25.798163098-04:00 +hash: a28817fffc1bfbba980a957b7782a84ea574fb73d5dfb01730f7e304c9dee630 +updated: 2017-05-03T10:27:41.060683376+02:00 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 - name: github.com/golang/snappy - version: d9eb7a3d35ec988b8585d4a0068e462c27d28380 + version: 553a641470496b2327abcac10b36396bd98e45c9 +- name: github.com/hashicorp/hcl + version: 630949a3c5fa3c613328e1b8256052cbc2327c9b + 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 - name: github.com/mattn/go-isatty version: 30a891c33c7cde7b02a981314b4228ec99380cca +- name: github.com/mitchellh/mapstructure + version: 53818660ed4955e899c0bcafa97299a388bd7c8e +- name: github.com/pelletier/go-buffruneio + version: c37440a7cf42ac63b919c752ca73a85067e05992 +- name: github.com/pelletier/go-toml + version: 13d49d4606eb801b8f01ae542b4afc4c6ee3d84a +- name: github.com/pkg/errors + version: bfd5150e4e41705ded2129ec33379de1cb90b513 +- name: github.com/spf13/afero + version: 9be650865eab0c12963d8753212f4f9c66cdcf12 + subpackages: + - mem +- name: github.com/spf13/cast + version: acbeb36b902d72a7a4c18e8f3241075e7ab763e4 +- name: github.com/spf13/cobra + version: fcd0c5a1df88f5d6784cb4feead962c3f3d0b66c +- name: github.com/spf13/jwalterweatherman + version: fa7ca7e836cf3a8bb4ebf799f472c12d7e903d66 +- name: github.com/spf13/pflag + version: 9ff6c6923cfffbcd502984b8e0c80539a94968b7 +- name: github.com/spf13/viper + version: 5d46e70da8c0b6f812e0b170b7a985753b5c63cb - name: github.com/syndtr/goleveldb version: 23851d93a2292dcc56e71a18ec9e0624d84a0f65 subpackages: @@ -27,7 +76,10 @@ imports: - leveldb/table - leveldb/util - name: github.com/tendermint/go-wire - version: 4325edc613ad1e9286c8bb770ed40ad3fe647e6c + version: 334005c236d19c632fb5f073f9de3b0fab6a522b + subpackages: + - data + - data/base58 - name: github.com/tendermint/log15 version: ae0f3d6450da9eac7074b439c8e1c3cabf0d5ce6 subpackages: @@ -40,6 +92,13 @@ imports: version: d75a52659825e75fff6158388dddc6a5b04f9ba5 subpackages: - unix +- name: golang.org/x/text + version: f4b4367115ec2de254587813edaa901bc1c723a8 + subpackages: + - transform + - unicode/norm +- name: gopkg.in/yaml.v2 + version: cd8b52f8269e0feb286dfeef29f8fe4d5b397e0b testImports: - name: github.com/davecgh/go-spew version: 6d212800a42e8ab5c146b8ace3490ee17e5225f9 @@ -53,3 +112,4 @@ testImports: version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0 subpackages: - assert + - require diff --git a/glide.yaml b/glide.yaml index a4c5dd2b..b0f22d1a 100644 --- a/glide.yaml +++ b/glide.yaml @@ -11,6 +11,9 @@ import: - package: golang.org/x/crypto subpackages: - ripemd160 +- package: github.com/go-logfmt/logfmt +- package: github.com/spf13/cobra +- package: github.com/spf13/viper testImport: - package: github.com/stretchr/testify subpackages: From ef3b9610a17f4d87d5cb03bfe9d69f1d416e1ce3 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 10:37:25 +0200 Subject: [PATCH 09/36] Fixed up the --home flag, ebuchman check this out --- cli/setup.go | 8 ++++++-- cli/setup_test.go | 3 +++ 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index 8120449c..b6f00658 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -24,7 +24,8 @@ const ( func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) func() { cobra.OnInitialize(func() { initEnv(envPrefix) }) cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "DEPRECATED. Use --home") - cmd.PersistentFlags().StringP(HomeFlag, "h", defautRoot, "root directory for config and data") + // -h is already reserved for --help as part of the cobra framework + cmd.PersistentFlags().String(HomeFlag, "", "root directory for config and data") cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) return func() { execute(cmd) } } @@ -104,7 +105,10 @@ func bindFlagsLoadViper(cmd *cobra.Command, args []string) error { // rootDir is command line flag, env variable, or default $HOME/.tlc // NOTE: we support both --root and --home for now, but eventually only --home rootDir := viper.GetString(HomeFlag) - if !viper.IsSet(HomeFlag) && viper.IsSet(RootFlag) { + // @ebuchman: viper.IsSet doesn't do what you think... + // Even a default of "" on the pflag marks it as set, + // simply by fact of having a pflag. + if rootDir == "" { rootDir = viper.GetString(RootFlag) } viper.SetConfigName("config") // name of config file (without extension) diff --git a/cli/setup_test.go b/cli/setup_test.go index fb8e5655..47170fe2 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -103,6 +103,9 @@ func TestSetupConfig(t *testing.T) { {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 { From 8efeeb5f38e8647dcb1f162f3f1e58500c02f0ed Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 3 May 2017 11:25:07 +0200 Subject: [PATCH 10/36] Add --debug flag to return full stack trace on error --- cli/setup.go | 39 +++++++++++++++++++++++------- cli/setup_test.go | 61 +++++++++++++++++++++++++++++++++++++---------- 2 files changed, 80 insertions(+), 20 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index b6f00658..e55baf90 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -16,25 +16,36 @@ import ( const ( RootFlag = "root" HomeFlag = "home" + DebugFlag = "debug" 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) func() { +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(DebugFlag, false, "print out full stack trace on errors") cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) - return func() { execute(cmd) } + 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) func() { +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) @@ -68,14 +79,26 @@ func copyEnvVars(prefix string) { } } +// 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 execute(cmd *cobra.Command) { - // TODO: this can do something cooler with debug and log-levels - if err := cmd.Execute(); err != nil { - fmt.Println(err) - os.Exit(-1) +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(DebugFlag) { + fmt.Printf("ERROR: %+v\n", err) + } else { + fmt.Println("ERROR:", err.Error()) + } } + return err } type cobraCmdFunc func(cmd *cobra.Command, args []string) error diff --git a/cli/setup_test.go b/cli/setup_test.go index 47170fe2..d8e37d3a 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -8,20 +8,16 @@ import ( "os" "path/filepath" "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" ) -// Executable is the minimal interface to *corba.Command, so we can -// wrap if desired before the test -type Executable interface { - Execute() error -} - func TestSetupEnv(t *testing.T) { assert, require := assert.New(t), require.New(t) @@ -46,15 +42,15 @@ func TestSetupEnv(t *testing.T) { i := strconv.Itoa(idx) // test command that store value of foobar in local variable var foo string - cmd := &cobra.Command{ + demo := &cobra.Command{ Use: "demo", RunE: func(cmd *cobra.Command, args []string) error { foo = viper.GetString("foobar") return nil }, } - cmd.Flags().String("foobar", "", "Some test value from config") - PrepareBaseCmd(cmd, "DEMO", "/qwerty/asdfgh") // some missing dir.. + 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...) @@ -112,15 +108,15 @@ func TestSetupConfig(t *testing.T) { i := strconv.Itoa(idx) // test command that store value of foobar in local variable var foo string - cmd := &cobra.Command{ + boo := &cobra.Command{ Use: "reader", RunE: func(cmd *cobra.Command, args []string) error { foo = viper.GetString("boo") return nil }, } - cmd.Flags().String("boo", "", "Some test value from config") - PrepareBaseCmd(cmd, "RD", "/qwerty/asdfgh") // some missing dir... + 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...) @@ -130,6 +126,47 @@ func TestSetupConfig(t *testing.T) { } } +func TestSetupDebug(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, "Debug flag = false"}, + {[]string{"--debug"}, nil, true, "Debug flag = true"}, + {[]string{"--no-such-flag"}, nil, false, "unknown flag: --no-such-flag"}, + {nil, map[string]string{"DBG_DEBUG": "true"}, true, "Debug flag = true"}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + debug := &cobra.Command{ + Use: "debug", + RunE: func(cmd *cobra.Command, args []string) error { + return errors.Errorf("Debug flag = %t", viper.GetBool(DebugFlag)) + }, + } + cmd := PrepareBaseCmd(debug, "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], "TestSetupDebug", i) + assert.Contains(msg[2], "setup_test.go", i) + } + } +} + // 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 { From ee45dbdc8b7947e95f403b736711ff8000f2927d Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Thu, 4 May 2017 19:16:58 +0200 Subject: [PATCH 11/36] Test how unmarshall plays with flags/env/config/default struct --- cli/setup_test.go | 77 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 77 insertions(+) diff --git a/cli/setup_test.go b/cli/setup_test.go index d8e37d3a..169b1400 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -126,6 +126,83 @@ func TestSetupConfig(t *testing.T) { } } +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 := writeConfig(map[string]string{"name": cval1}) + require.Nil(err) + // even with some ignored fields, should be no problem + conf2, err := writeConfig(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 TestSetupDebug(t *testing.T) { assert, require := assert.New(t), require.New(t) From 3585a542a0e07d0e9d396b2f809c2826c8536437 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Fri, 5 May 2017 00:48:23 -0400 Subject: [PATCH 12/36] cli: viper.Set(HomeFlag, rootDir) --- cli/setup.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index e55baf90..7a4a2098 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -127,12 +127,12 @@ func bindFlagsLoadViper(cmd *cobra.Command, args []string) error { // 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) - // @ebuchman: viper.IsSet doesn't do what you think... - // Even a default of "" on the pflag marks it as set, - // simply by fact of having a pflag. 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 From d0132b0fffc2eb79c7a129a2faeae08cc0e5fcad Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Fri, 5 May 2017 14:46:04 +0200 Subject: [PATCH 13/36] Moved helper functions into non-test code for reuse elsewhere --- .gitignore | 1 + cli/helper.go | 64 ++++++++++++++++++++++++++++++++++++++++++++ cli/setup_test.go | 68 +++-------------------------------------------- 3 files changed, 69 insertions(+), 64 deletions(-) create mode 100644 cli/helper.go diff --git a/.gitignore b/.gitignore index 38193138..f37225ba 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ *.swp *.swo +vendor diff --git a/cli/helper.go b/cli/helper.go new file mode 100644 index 00000000..b0662c78 --- /dev/null +++ b/cli/helper.go @@ -0,0 +1,64 @@ +package cli + +import ( + "bytes" + "io" + "os" +) + +// 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 +} diff --git a/cli/setup_test.go b/cli/setup_test.go index 169b1400..34877209 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -1,11 +1,8 @@ package cli import ( - "bytes" "fmt" - "io" "io/ioutil" - "os" "path/filepath" "strconv" "strings" @@ -54,7 +51,7 @@ func TestSetupEnv(t *testing.T) { viper.Reset() args := append([]string{cmd.Use}, tc.args...) - err := runWithArgs(cmd, args, tc.env) + err := RunWithArgs(cmd, args, tc.env) require.Nil(err, i) assert.Equal(tc.expected, foo, i) } @@ -120,7 +117,7 @@ func TestSetupConfig(t *testing.T) { viper.Reset() args := append([]string{cmd.Use}, tc.args...) - err := runWithArgs(cmd, args, tc.env) + err := RunWithArgs(cmd, args, tc.env) require.Nil(err, i) assert.Equal(tc.expected, foo, i) } @@ -197,7 +194,7 @@ func TestSetupUnmarshal(t *testing.T) { viper.Reset() args := append([]string{cmd.Use}, tc.args...) - err := runWithArgs(cmd, args, tc.env) + err := RunWithArgs(cmd, args, tc.env) require.Nil(err, i) assert.Equal(tc.expected, cfg, i) } @@ -231,7 +228,7 @@ func TestSetupDebug(t *testing.T) { viper.Reset() args := append([]string{cmd.Use}, tc.args...) - out, err := runCaptureWithArgs(cmd, args, tc.env) + out, err := RunCaptureWithArgs(cmd, args, tc.env) require.NotNil(err, i) msg := strings.Split(out, "\n") desired := fmt.Sprintf("ERROR: %s", tc.expected) @@ -243,60 +240,3 @@ func TestSetupDebug(t *testing.T) { } } } - -// 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 -} From 2f02ed18e9b706467c9474d024a25a0b7a9c0e97 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Fri, 5 May 2017 14:58:53 +0200 Subject: [PATCH 14/36] One more helper function for cli tests... --- cli/helper.go | 20 ++++++++++++++++++++ cli/setup_test.go | 24 ++++-------------------- 2 files changed, 24 insertions(+), 20 deletions(-) diff --git a/cli/helper.go b/cli/helper.go index b0662c78..79654bc3 100644 --- a/cli/helper.go +++ b/cli/helper.go @@ -2,10 +2,30 @@ 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 { diff --git a/cli/setup_test.go b/cli/setup_test.go index 34877209..6396b769 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -2,8 +2,6 @@ package cli import ( "fmt" - "io/ioutil" - "path/filepath" "strconv" "strings" "testing" @@ -57,30 +55,16 @@ func TestSetupEnv(t *testing.T) { } } -func writeConfig(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 -} - 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 := writeConfig(map[string]string{"boo": cval1}) + conf1, err := WriteDemoConfig(map[string]string{"boo": cval1}) require.Nil(err) // even with some ignored fields, should be no problem - conf2, err := writeConfig(map[string]string{"boo": cval2, "foo": "bar"}) + conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar"}) require.Nil(err) cases := []struct { @@ -135,10 +119,10 @@ func TestSetupUnmarshal(t *testing.T) { // we pre-create two config files we can refer to in the rest of // the test cases. cval1, cval2 := "someone", "else" - conf1, err := writeConfig(map[string]string{"name": cval1}) + conf1, err := WriteDemoConfig(map[string]string{"name": cval1}) require.Nil(err) // even with some ignored fields, should be no problem - conf2, err := writeConfig(map[string]string{"name": cval2, "foo": "bar"}) + conf2, err := WriteDemoConfig(map[string]string{"name": cval2, "foo": "bar"}) require.Nil(err) // unused is not declared on a flag and remains from base From ed76afd409058b162748bb77232d584ea89fe498 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Thu, 27 Apr 2017 13:42:03 +0400 Subject: [PATCH 15/36] Logger interface and tmLogger impl based on go-kit --- .gitignore | 3 +- common/service.go | 58 ++++++++++---------- events/events.go | 2 +- events/log.go | 7 --- glide.lock | 40 +++++++------- glide.yaml | 16 +++++- log/logger.go | 27 +++++++++ log/nop_logger.go | 18 ++++++ log/nop_logger_test.go | 18 ++++++ log/tm_logger.go | 74 +++++++++++++++++++++++++ log/tm_logger_test.go | 41 ++++++++++++++ log/tmfmt_logger.go | 116 +++++++++++++++++++++++++++++++++++++++ log/tmfmt_logger_test.go | 110 +++++++++++++++++++++++++++++++++++++ logger/log.go | 11 ++-- 14 files changed, 473 insertions(+), 68 deletions(-) delete mode 100644 events/log.go create mode 100644 log/logger.go create mode 100644 log/nop_logger.go create mode 100644 log/nop_logger_test.go create mode 100644 log/tm_logger.go create mode 100644 log/tm_logger_test.go create mode 100644 log/tmfmt_logger.go create mode 100644 log/tmfmt_logger_test.go diff --git a/.gitignore b/.gitignore index f37225ba..62f28681 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,2 @@ -*.swp -*.swo vendor +.glide diff --git a/common/service.go b/common/service.go index 6a274a79..71fc03cb 100644 --- a/common/service.go +++ b/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 { - return &BaseService{ - log: log, - name: name, - Quit: make(chan struct{}), - impl: impl, +func NewBaseService(logger log.Logger, name string, impl Service) *BaseService { + if logger == nil { + logger = log.NewNopLogger() } + + return &BaseService{ + 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), } } diff --git a/events/events.go b/events/events.go index 487d120b..12aa0781 100644 --- a/events/events.go +++ b/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 } diff --git a/events/log.go b/events/log.go deleted file mode 100644 index adb6bab0..00000000 --- a/events/log.go +++ /dev/null @@ -1,7 +0,0 @@ -package events - -import ( - "github.com/tendermint/tmlibs/logger" -) - -var log = logger.New("module", "events") diff --git a/glide.lock b/glide.lock index b7d4fb8f..37fe6ba4 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: a28817fffc1bfbba980a957b7782a84ea574fb73d5dfb01730f7e304c9dee630 -updated: 2017-05-03T10:27:41.060683376+02:00 +hash: 69359a39dbb6957c9f09167520317ad72d4bfa75f37a614b347e2510768c8a42 +updated: 2017-05-05T17:40:30.424309209Z imports: - name: github.com/fsnotify/fsnotify version: 4da3e2cfbabc9f751898f250b49f2439785783a1 @@ -12,11 +12,11 @@ imports: - name: github.com/go-logfmt/logfmt version: 390ab7935ee28ec6b286364bba9b4dd6410cb3d5 - name: github.com/go-stack/stack - version: 100eb0c0a9c5b306ca2fb4f165df21d80ada4b82 + version: 7a2f19628aabfe68f0766b59e74d6315f8347d22 - name: github.com/golang/snappy version: 553a641470496b2327abcac10b36396bd98e45c9 - name: github.com/hashicorp/hcl - version: 630949a3c5fa3c613328e1b8256052cbc2327c9b + version: a4b07c25de5ff55ad3b8936cea69a79a3d95a855 subpackages: - hcl/ast - hcl/parser @@ -35,17 +35,17 @@ imports: - 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: 53818660ed4955e899c0bcafa97299a388bd7c8e + version: cc8532a8e9a55ea36402aa21efdf403a60d34096 - name: github.com/pelletier/go-buffruneio version: c37440a7cf42ac63b919c752ca73a85067e05992 - name: github.com/pelletier/go-toml - version: 13d49d4606eb801b8f01ae542b4afc4c6ee3d84a + version: 97253b98df84f9eef872866d079e74b8265150f1 - name: github.com/pkg/errors - version: bfd5150e4e41705ded2129ec33379de1cb90b513 + version: c605e284fe17294bda444b34710735b29d1a9d90 - name: github.com/spf13/afero version: 9be650865eab0c12963d8753212f4f9c66cdcf12 subpackages: @@ -53,15 +53,15 @@ imports: - name: github.com/spf13/cast version: acbeb36b902d72a7a4c18e8f3241075e7ab763e4 - name: github.com/spf13/cobra - version: fcd0c5a1df88f5d6784cb4feead962c3f3d0b66c + version: db6b9a8b3f3f400c8ecb4a4d7d02245b8facad66 - name: github.com/spf13/jwalterweatherman version: fa7ca7e836cf3a8bb4ebf799f472c12d7e903d66 - name: github.com/spf13/pflag - version: 9ff6c6923cfffbcd502984b8e0c80539a94968b7 + version: 80fe0fb4eba54167e2ccae1c6c950e72abf61b73 - name: github.com/spf13/viper - version: 5d46e70da8c0b6f812e0b170b7a985753b5c63cb + version: 0967fc9aceab2ce9da34061253ac10fb99bba5b2 - name: github.com/syndtr/goleveldb - version: 23851d93a2292dcc56e71a18ec9e0624d84a0f65 + version: 8c81ea47d4c41a385645e133e15510fc6a2a74b4 subpackages: - leveldb - leveldb/cache @@ -76,24 +76,24 @@ imports: - leveldb/table - leveldb/util - name: github.com/tendermint/go-wire - version: 334005c236d19c632fb5f073f9de3b0fab6a522b + 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: f4b4367115ec2de254587813edaa901bc1c723a8 + version: 470f45bf29f4147d6fbd7dfd0a02a848e49f5bf4 subpackages: - transform - unicode/norm @@ -101,7 +101,7 @@ imports: version: cd8b52f8269e0feb286dfeef29f8fe4d5b397e0b testImports: - name: github.com/davecgh/go-spew - version: 6d212800a42e8ab5c146b8ace3490ee17e5225f9 + version: 04cdfd42973bb9c8589fd6a731800cf222fde1a9 subpackages: - spew - name: github.com/pmezard/go-difflib @@ -109,7 +109,7 @@ testImports: subpackages: - difflib - name: github.com/stretchr/testify - version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0 + version: 4d4bfba8f1d1027c4fdbe371823030df51419987 subpackages: - assert - require diff --git a/glide.yaml b/glide.yaml index b0f22d1a..2df88017 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,20 +1,30 @@ 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 -- package: github.com/go-logfmt/logfmt -- package: github.com/spf13/cobra -- package: github.com/spf13/viper testImport: - package: github.com/stretchr/testify subpackages: - assert + - require diff --git a/log/logger.go b/log/logger.go new file mode 100644 index 00000000..790bcad7 --- /dev/null +++ b/log/logger.go @@ -0,0 +1,27 @@ +package log + +import ( + "fmt" + + 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 returns a new contextual logger with keyvals prepended to those passed +// to calls to Info, Debug or Error. +func With(logger Logger, keyvals ...interface{}) Logger { + switch logger.(type) { + case *tmLogger: + return &tmLogger{kitlog.With(logger.(*tmLogger).srcLogger, keyvals...)} + case *nopLogger: + return logger + default: + panic(fmt.Sprintf("Unexpected logger of type %T", logger)) + } +} diff --git a/log/nop_logger.go b/log/nop_logger.go new file mode 100644 index 00000000..b6e31263 --- /dev/null +++ b/log/nop_logger.go @@ -0,0 +1,18 @@ +package log + +type nopLogger struct{} + +// 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 +} diff --git a/log/nop_logger_test.go b/log/nop_logger_test.go new file mode 100644 index 00000000..9757d4f1 --- /dev/null +++ b/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 := log.With(logger, "def", "ghi").Debug(""); err != nil { + t.Error(err) + } +} diff --git a/log/tm_logger.go b/log/tm_logger.go new file mode 100644 index 00000000..0d01a970 --- /dev/null +++ b/log/tm_logger.go @@ -0,0 +1,74 @@ +package log + +import ( + "fmt" + "io" + + kitlog "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" + "github.com/go-kit/kit/log/term" +) + +const ( + msgKey = "_msg" // "_" prefixed to avoid collisions +) + +type tmLogger struct { + srcLogger kitlog.Logger +} + +// 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] != level.Key() { + panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0])) + } + switch keyvals[1].(level.Value).String() { + case "debug": + return term.FgBgColor{Fg: term.DarkGray} + case "error": + return term.FgBgColor{Fg: term.Red} + default: + return term.FgBgColor{} + } + } + + srcLogger := term.NewLogger(w, NewTmfmtLogger, colorFn) + srcLogger = level.NewFilter(srcLogger, level.AllowInfo()) + return &tmLogger{srcLogger} +} + +// WithLevel returns a copy of the logger with a level set to lvl. +func (l *tmLogger) WithLevel(lvl string) Logger { + switch lvl { + case "info": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowInfo())} + case "debug": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowDebug())} + case "error": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowError())} + default: + panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) + } +} + +// Info logs a message at level Info. +func (l *tmLogger) Info(msg string, keyvals ...interface{}) error { + lWithLevel := level.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 := level.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 := level.Error(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} diff --git a/log/tm_logger_test.go b/log/tm_logger_test.go new file mode 100644 index 00000000..f301c9fd --- /dev/null +++ b/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 := log.With(logger, "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 := log.With(logger, "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) { log.With(logger, "a", "b").Info("c", "d", "f") } +) diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go new file mode 100644 index 00000000..db689c08 --- /dev/null +++ b/log/tmfmt_logger.go @@ -0,0 +1,116 @@ +package log + +import ( + "bytes" + "fmt" + "io" + "sync" + "time" + + kitlog "github.com/go-kit/kit/log" + "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" + lvlIndex := -1 + msgIndex := -1 + + for i := 0; i < len(keyvals)-1; i += 2 { + // Extract level + if keyvals[i] == level.Key() { + lvlIndex = i + switch keyvals[i+1].(type) { + case string: + lvl = keyvals[i+1].(string) + case level.Value: + lvl = keyvals[i+1].(level.Value).String() + default: + panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1])) + } + continue + } + + // and message + if keyvals[i] == msgKey { + msgIndex = i + msg = keyvals[i+1].(string) + continue + } + + if lvlIndex > 0 && msgIndex > 0 { // found all we're looking for + break + } + } + + // 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)) + + for i := 0; i < len(keyvals)-1; i += 2 { + if i == lvlIndex || i == msgIndex { + continue + } + 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 +} diff --git a/log/tmfmt_logger_test.go b/log/tmfmt_logger_test.go new file mode 100644 index 00000000..ca5ee55e --- /dev/null +++ b/log/tmfmt_logger_test.go @@ -0,0 +1,110 @@ +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()) +} + +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" } diff --git a/logger/log.go b/logger/log.go index 84f71c34..2f4faef6 100644 --- a/logger/log.go +++ b/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...) } From 66c9401c0740ffff0f9f978328330a3f2728133b Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Tue, 2 May 2017 14:26:00 -0400 Subject: [PATCH 16/36] log: Tm -> TM --- log/tm_logger.go | 6 +++--- log/tm_logger_test.go | 12 ++++++------ log/tmfmt_logger.go | 4 ++-- log/tmfmt_logger_test.go | 16 ++++++++-------- 4 files changed, 19 insertions(+), 19 deletions(-) diff --git a/log/tm_logger.go b/log/tm_logger.go index 0d01a970..f12442db 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -17,10 +17,10 @@ type tmLogger struct { srcLogger kitlog.Logger } -// NewTmTermLogger returns a logger that encodes msg and keyvals to the Writer +// 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 { +func NewTMLogger(w io.Writer) Logger { // Color by level value colorFn := func(keyvals ...interface{}) term.FgBgColor { if keyvals[0] != level.Key() { @@ -36,7 +36,7 @@ func NewTmLogger(w io.Writer) Logger { } } - srcLogger := term.NewLogger(w, NewTmfmtLogger, colorFn) + srcLogger := term.NewLogger(w, NewTMFmtLogger, colorFn) srcLogger = level.NewFilter(srcLogger, level.AllowInfo()) return &tmLogger{srcLogger} } diff --git a/log/tm_logger_test.go b/log/tm_logger_test.go index f301c9fd..898316c4 100644 --- a/log/tm_logger_test.go +++ b/log/tm_logger_test.go @@ -7,9 +7,9 @@ import ( "github.com/tendermint/tmlibs/log" ) -func TestTmLogger(t *testing.T) { +func TestTMLogger(t *testing.T) { t.Parallel() - logger := log.NewTmLogger(ioutil.Discard) + logger := log.NewTMLogger(ioutil.Discard) if err := logger.Info("Hello", "abc", 123); err != nil { t.Error(err) } @@ -18,12 +18,12 @@ func TestTmLogger(t *testing.T) { } } -func BenchmarkTmLoggerSimple(b *testing.B) { - benchmarkRunner(b, log.NewTmLogger(ioutil.Discard), baseInfoMessage) +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 BenchmarkTMLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), withInfoMessage) } func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go index db689c08..2f299e27 100644 --- a/log/tmfmt_logger.go +++ b/log/tmfmt_logger.go @@ -34,13 +34,13 @@ type tmfmtLogger struct { w io.Writer } -// NewTmFmtLogger returns a logger that encodes keyvals to the Writer in +// 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 { +func NewTMFmtLogger(w io.Writer) kitlog.Logger { return &tmfmtLogger{w} } diff --git a/log/tmfmt_logger_test.go b/log/tmfmt_logger_test.go index ca5ee55e..c5ec4127 100644 --- a/log/tmfmt_logger_test.go +++ b/log/tmfmt_logger_test.go @@ -13,10 +13,10 @@ import ( "github.com/tendermint/tmlibs/log" ) -func TestTmfmtLogger(t *testing.T) { +func TestTMFmtLogger(t *testing.T) { t.Parallel() buf := &bytes.Buffer{} - logger := log.NewTmfmtLogger(buf) + logger := log.NewTMFmtLogger(buf) if err := logger.Log("hello", "world"); err != nil { t.Fatal(err) @@ -46,17 +46,17 @@ func TestTmfmtLogger(t *testing.T) { assert.Regexp(t, regexp.MustCompile(`N\[.+\] Hello \s+\n$`), buf.String()) } -func BenchmarkTmfmtLoggerSimple(b *testing.B) { - benchmarkRunnerKitlog(b, log.NewTmfmtLogger(ioutil.Discard), baseMessage) +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 BenchmarkTMFmtLoggerContextual(b *testing.B) { + benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), withMessage) } -func TestTmfmtLoggerConcurrency(t *testing.T) { +func TestTMFmtLoggerConcurrency(t *testing.T) { t.Parallel() - testConcurrency(t, log.NewTmfmtLogger(ioutil.Discard), 10000) + testConcurrency(t, log.NewTMFmtLogger(ioutil.Discard), 10000) } func benchmarkRunnerKitlog(b *testing.B, logger kitlog.Logger, f func(kitlog.Logger)) { From 520561e94a11040272fc64e5f338eacdc336ea3d Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Wed, 3 May 2017 11:06:30 +0400 Subject: [PATCH 17/36] add testing logger --- log/testing_logger.go | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+) create mode 100644 log/testing_logger.go diff --git a/log/testing_logger.go b/log/testing_logger.go new file mode 100644 index 00000000..7ab83e41 --- /dev/null +++ b/log/testing_logger.go @@ -0,0 +1,31 @@ +package log + +import ( + "os" + "testing" +) + +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(os.Stdout) + } else { + _testingLogger = NewNopLogger() + } + + return _testingLogger +} From 3420b389e93af28db6ba30d58db18fc5693fbba3 Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Fri, 5 May 2017 19:45:02 +0200 Subject: [PATCH 18/36] Add testify version for consistency --- glide.yaml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/glide.yaml b/glide.yaml index b0f22d1a..f9e8f29b 100644 --- a/glide.yaml +++ b/glide.yaml @@ -16,5 +16,7 @@ import: - package: github.com/spf13/viper testImport: - package: github.com/stretchr/testify + version: ^1.1.4 subpackages: - assert + - require From 6ff7b4395d7019a31cec66713aec15ed86cdb888 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Wed, 3 May 2017 11:18:50 +0400 Subject: [PATCH 19/36] update glide.yaml and glide.lock files --- Makefile | 2 -- glide.lock | 2 +- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/Makefile b/Makefile index cd1a5734..d5e5aa2c 100644 --- a/Makefile +++ b/Makefile @@ -4,8 +4,6 @@ GOTOOLS = \ github.com/Masterminds/glide REPO:=github.com/tendermint/tmlibs -all: install test - test: go test `glide novendor` diff --git a/glide.lock b/glide.lock index 37fe6ba4..b30f538a 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ hash: 69359a39dbb6957c9f09167520317ad72d4bfa75f37a614b347e2510768c8a42 -updated: 2017-05-05T17:40:30.424309209Z +updated: 2017-05-05T17:46:34.975369143Z imports: - name: github.com/fsnotify/fsnotify version: 4da3e2cfbabc9f751898f250b49f2439785783a1 From b2bd039923c20f59d13c7992a079d95e92f328fe Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Thu, 4 May 2017 17:33:32 +0400 Subject: [PATCH 20/36] correct impl of WithLevel --- log/logger.go | 22 ++++++++++++++++++++++ log/tm_logger.go | 14 -------------- 2 files changed, 22 insertions(+), 14 deletions(-) diff --git a/log/logger.go b/log/logger.go index 790bcad7..a895aed6 100644 --- a/log/logger.go +++ b/log/logger.go @@ -4,6 +4,7 @@ import ( "fmt" kitlog "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" ) // Logger is what any Tendermint library should take. @@ -25,3 +26,24 @@ func With(logger Logger, keyvals ...interface{}) Logger { panic(fmt.Sprintf("Unexpected logger of type %T", logger)) } } + +// WithLevel returns a copy of the logger with a level set to lvl. +func WithLevel(logger Logger, lvl string) Logger { + switch logger.(type) { + case *tmLogger: + switch lvl { + case "info": + return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowInfo())} + case "debug": + return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowDebug())} + case "error": + return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowError())} + default: + panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) + } + case *nopLogger: + return logger + default: + panic(fmt.Sprintf("Unexpected logger of type %T", logger)) + } +} diff --git a/log/tm_logger.go b/log/tm_logger.go index f12442db..d8550ea6 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -41,20 +41,6 @@ func NewTMLogger(w io.Writer) Logger { return &tmLogger{srcLogger} } -// WithLevel returns a copy of the logger with a level set to lvl. -func (l *tmLogger) WithLevel(lvl string) Logger { - switch lvl { - case "info": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowInfo())} - case "debug": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowDebug())} - case "error": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowError())} - default: - panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) - } -} - // Info logs a message at level Info. func (l *tmLogger) Info(msg string, keyvals ...interface{}) error { lWithLevel := level.Info(l.srcLogger) From ea01d003d1fe1a95a118913d3798544cce3869ac Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Thu, 4 May 2017 19:39:16 +0400 Subject: [PATCH 21/36] changes per @ethanfrey comments --- log/logger.go | 50 ++++++++++++++---------------------------- log/nop_logger.go | 11 ++++++++++ log/nop_logger_test.go | 2 +- log/testing_logger.go | 2 +- log/tm_logger.go | 25 +++++++++++++++++++++ log/tm_logger_test.go | 6 ++--- 6 files changed, 57 insertions(+), 39 deletions(-) diff --git a/log/logger.go b/log/logger.go index a895aed6..bf6a3ff6 100644 --- a/log/logger.go +++ b/log/logger.go @@ -1,10 +1,9 @@ package log import ( - "fmt" + "io" kitlog "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" ) // Logger is what any Tendermint library should take. @@ -12,38 +11,21 @@ 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 + WithLevel(lvl string) Logger } -// With returns a new contextual logger with keyvals prepended to those passed -// to calls to Info, Debug or Error. -func With(logger Logger, keyvals ...interface{}) Logger { - switch logger.(type) { - case *tmLogger: - return &tmLogger{kitlog.With(logger.(*tmLogger).srcLogger, keyvals...)} - case *nopLogger: - return logger - default: - panic(fmt.Sprintf("Unexpected logger of type %T", logger)) - } -} - -// WithLevel returns a copy of the logger with a level set to lvl. -func WithLevel(logger Logger, lvl string) Logger { - switch logger.(type) { - case *tmLogger: - switch lvl { - case "info": - return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowInfo())} - case "debug": - return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowDebug())} - case "error": - return &tmLogger{level.NewFilter(logger.(*tmLogger).srcLogger, level.AllowError())} - default: - panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) - } - case *nopLogger: - return logger - default: - panic(fmt.Sprintf("Unexpected logger of type %T", 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) } diff --git a/log/nop_logger.go b/log/nop_logger.go index b6e31263..21999817 100644 --- a/log/nop_logger.go +++ b/log/nop_logger.go @@ -2,6 +2,9 @@ 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{} } @@ -16,3 +19,11 @@ func (nopLogger) Debug(string, ...interface{}) error { func (nopLogger) Error(string, ...interface{}) error { return nil } + +func (l *nopLogger) With(...interface{}) Logger { + return l +} + +func (l *nopLogger) WithLevel(lvl string) Logger { + return l +} diff --git a/log/nop_logger_test.go b/log/nop_logger_test.go index 9757d4f1..d2009fdf 100644 --- a/log/nop_logger_test.go +++ b/log/nop_logger_test.go @@ -12,7 +12,7 @@ func TestNopLogger(t *testing.T) { if err := logger.Info("Hello", "abc", 123); err != nil { t.Error(err) } - if err := log.With(logger, "def", "ghi").Debug(""); err != nil { + if err := logger.With("def", "ghi").Debug(""); err != nil { t.Error(err) } } diff --git a/log/testing_logger.go b/log/testing_logger.go index 7ab83e41..31913633 100644 --- a/log/testing_logger.go +++ b/log/testing_logger.go @@ -22,7 +22,7 @@ func TestingLogger() Logger { } if testing.Verbose() { - _testingLogger = NewTMLogger(os.Stdout) + _testingLogger = NewTMLogger(NewSyncWriter(os.Stdout)) } else { _testingLogger = NewNopLogger() } diff --git a/log/tm_logger.go b/log/tm_logger.go index d8550ea6..3a3c9dde 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -17,9 +17,14 @@ 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. +// +// Default logging level is info. You can change it using SetLevel(). func NewTMLogger(w io.Writer) Logger { // Color by level value colorFn := func(keyvals ...interface{}) term.FgBgColor { @@ -58,3 +63,23 @@ func (l *tmLogger) Error(msg string, keyvals ...interface{}) error { lWithLevel := level.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...)} +} + +// WithLevel returns a new logger with the level set to lvl. +func (l *tmLogger) WithLevel(lvl string) Logger { + switch lvl { + case "info": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowInfo())} + case "debug": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowDebug())} + case "error": + return &tmLogger{level.NewFilter(l.srcLogger, level.AllowError())} + default: + panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) + } +} diff --git a/log/tm_logger_test.go b/log/tm_logger_test.go index 898316c4..15c940ce 100644 --- a/log/tm_logger_test.go +++ b/log/tm_logger_test.go @@ -13,7 +13,7 @@ func TestTMLogger(t *testing.T) { if err := logger.Info("Hello", "abc", 123); err != nil { t.Error(err) } - if err := log.With(logger, "def", "ghi").Debug(""); err != nil { + if err := logger.With("def", "ghi").Debug(""); err != nil { t.Error(err) } } @@ -27,7 +27,7 @@ func BenchmarkTMLoggerContextual(b *testing.B) { } func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - lc := log.With(logger, "common_key", "common_value") + lc := logger.With("common_key", "common_value") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -37,5 +37,5 @@ func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { var ( baseInfoMessage = func(logger log.Logger) { logger.Info("foo_message", "foo_key", "foo_value") } - withInfoMessage = func(logger log.Logger) { log.With(logger, "a", "b").Info("c", "d", "f") } + withInfoMessage = func(logger log.Logger) { logger.With("a", "b").Info("c", "d", "f") } ) From 2bf6ebf379bebebc456d755998e1bedd87ed9cae Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Fri, 5 May 2017 15:06:56 +0400 Subject: [PATCH 22/36] filter --- log/filter.go | 97 +++++++++++++++++++++++++++++++++++++++ log/filter_test.go | 103 ++++++++++++++++++++++++++++++++++++++++++ log/logger.go | 1 - log/nop_logger.go | 4 -- log/tm_json_logger.go | 15 ++++++ log/tm_logger.go | 32 +++---------- log/tmfmt_logger.go | 8 ++-- 7 files changed, 226 insertions(+), 34 deletions(-) create mode 100644 log/filter.go create mode 100644 log/filter_test.go create mode 100644 log/tm_json_logger.go diff --git a/log/filter.go b/log/filter.go new file mode 100644 index 00000000..e7bec982 --- /dev/null +++ b/log/filter.go @@ -0,0 +1,97 @@ +package log + +// 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, + } + for _, option := range options { + option(l) + } + return l +} + +type filter struct { + next Logger + allowed level + errNotAllowed error +} + +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...) +} + +func (l *filter) With(keyvals ...interface{}) Logger { + return l.next.With(keyvals...) +} + +// 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, warn, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelInfo | levelDebug) +} + +// AllowInfo allows error, warn 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 } +} + +type level byte + +const ( + levelDebug level = 1 << iota + levelInfo + levelError +) diff --git a/log/filter_test.go b/log/filter_test.go new file mode 100644 index 00000000..5e1fb167 --- /dev/null +++ b/log/filter_test.go @@ -0,0 +1,103 @@ +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.AllowAll()) + logger = logger.With("context", "value") + + logger.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) + } +} diff --git a/log/logger.go b/log/logger.go index bf6a3ff6..be273f48 100644 --- a/log/logger.go +++ b/log/logger.go @@ -13,7 +13,6 @@ type Logger interface { Error(msg string, keyvals ...interface{}) error With(keyvals ...interface{}) Logger - WithLevel(lvl string) Logger } // NewSyncWriter returns a new writer that is safe for concurrent use by diff --git a/log/nop_logger.go b/log/nop_logger.go index 21999817..306a8405 100644 --- a/log/nop_logger.go +++ b/log/nop_logger.go @@ -23,7 +23,3 @@ func (nopLogger) Error(string, ...interface{}) error { func (l *nopLogger) With(...interface{}) Logger { return l } - -func (l *nopLogger) WithLevel(lvl string) Logger { - return l -} diff --git a/log/tm_json_logger.go b/log/tm_json_logger.go new file mode 100644 index 00000000..a71ac103 --- /dev/null +++ b/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)} +} diff --git a/log/tm_logger.go b/log/tm_logger.go index 3a3c9dde..a6a6f6d3 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -5,7 +5,7 @@ import ( "io" kitlog "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" + kitlevel "github.com/go-kit/kit/log/level" "github.com/go-kit/kit/log/term" ) @@ -23,15 +23,13 @@ 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. -// -// Default logging level is info. You can change it using SetLevel(). func NewTMLogger(w io.Writer) Logger { // Color by level value colorFn := func(keyvals ...interface{}) term.FgBgColor { - if keyvals[0] != level.Key() { + if keyvals[0] != kitlevel.Key() { panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0])) } - switch keyvals[1].(level.Value).String() { + switch keyvals[1].(kitlevel.Value).String() { case "debug": return term.FgBgColor{Fg: term.DarkGray} case "error": @@ -41,26 +39,24 @@ func NewTMLogger(w io.Writer) Logger { } } - srcLogger := term.NewLogger(w, NewTMFmtLogger, colorFn) - srcLogger = level.NewFilter(srcLogger, level.AllowInfo()) - return &tmLogger{srcLogger} + return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} } // Info logs a message at level Info. func (l *tmLogger) Info(msg string, keyvals ...interface{}) error { - lWithLevel := level.Info(l.srcLogger) + 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 := level.Debug(l.srcLogger) + 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 := level.Error(l.srcLogger) + lWithLevel := kitlevel.Error(l.srcLogger) return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) } @@ -69,17 +65,3 @@ func (l *tmLogger) Error(msg string, keyvals ...interface{}) error { func (l *tmLogger) With(keyvals ...interface{}) Logger { return &tmLogger{kitlog.With(l.srcLogger, keyvals...)} } - -// WithLevel returns a new logger with the level set to lvl. -func (l *tmLogger) WithLevel(lvl string) Logger { - switch lvl { - case "info": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowInfo())} - case "debug": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowDebug())} - case "error": - return &tmLogger{level.NewFilter(l.srcLogger, level.AllowError())} - default: - panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl)) - } -} diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go index 2f299e27..4e36de89 100644 --- a/log/tmfmt_logger.go +++ b/log/tmfmt_logger.go @@ -8,7 +8,7 @@ import ( "time" kitlog "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" + kitlevel "github.com/go-kit/kit/log/level" "github.com/go-logfmt/logfmt" ) @@ -56,13 +56,13 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { for i := 0; i < len(keyvals)-1; i += 2 { // Extract level - if keyvals[i] == level.Key() { + if keyvals[i] == kitlevel.Key() { lvlIndex = i switch keyvals[i+1].(type) { case string: lvl = keyvals[i+1].(string) - case level.Value: - lvl = keyvals[i+1].(level.Value).String() + case kitlevel.Value: + lvl = keyvals[i+1].(kitlevel.Value).String() default: panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1])) } From f4be75cb1e5fc7259195f2a2ae5f4b995847b9f5 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Fri, 5 May 2017 20:33:15 +0400 Subject: [PATCH 23/36] remove warn mentions --- log/filter.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/log/filter.go b/log/filter.go index e7bec982..102e2d90 100644 --- a/log/filter.go +++ b/log/filter.go @@ -56,12 +56,12 @@ func AllowAll() Option { return AllowDebug() } -// AllowDebug allows error, warn, info and debug level log events to pass. +// AllowDebug allows error, info and debug level log events to pass. func AllowDebug() Option { return allowed(levelError | levelInfo | levelDebug) } -// AllowInfo allows error, warn and info level log events to pass. +// AllowInfo allows error and info level log events to pass. func AllowInfo() Option { return allowed(levelError | levelInfo) } From 240215f2aa26d53223c618a5a2127a08d37868f0 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Fri, 5 May 2017 21:52:01 +0400 Subject: [PATCH 24/36] return back all in Makefile --- Makefile | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Makefile b/Makefile index d5e5aa2c..8e43dd11 100644 --- a/Makefile +++ b/Makefile @@ -1,9 +1,11 @@ -.PHONY: 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: test + test: go test `glide novendor` @@ -14,5 +16,3 @@ get_vendor_deps: ensure_tools ensure_tools: go get $(GOTOOLS) - - From bc6baf677420b4d718848a6559ded96a97868a63 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Sat, 6 May 2017 11:21:07 +0400 Subject: [PATCH 25/36] [log] proper impl of With for filter --- log/filter.go | 2 +- log/filter_test.go | 10 ++++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/log/filter.go b/log/filter.go index 102e2d90..afb2e920 100644 --- a/log/filter.go +++ b/log/filter.go @@ -45,7 +45,7 @@ func (l *filter) Error(msg string, keyvals ...interface{}) error { } func (l *filter) With(keyvals ...interface{}) Logger { - return l.next.With(keyvals...) + return &filter{next: l.next.With(keyvals...), allowed: l.allowed, errNotAllowed: l.errNotAllowed} } // Option sets a parameter for the filter. diff --git a/log/filter_test.go b/log/filter_test.go index 5e1fb167..3840b12a 100644 --- a/log/filter_test.go +++ b/log/filter_test.go @@ -93,11 +93,17 @@ func TestLevelContext(t *testing.T) { var logger log.Logger logger = log.NewTMJSONLogger(&buf) - logger = log.NewFilter(logger, log.AllowAll()) + 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 := `{"_msg":"foo","bar":"baz","context":"value","level":"info"}`, strings.TrimSpace(buf.String()); want != have { + if want, have := ``, strings.TrimSpace(buf.String()); want != have { t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } From b2a116863cbf080a5f80201c9ea843c25919d061 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Mon, 8 May 2017 17:30:21 +0400 Subject: [PATCH 26/36] squash module key if multiple keyvals were provided last keyvalue wins --- log/tm_logger.go | 3 ++- log/tmfmt_logger.go | 38 ++++++++++++++++++++++---------------- log/tmfmt_logger_test.go | 6 ++++++ 3 files changed, 30 insertions(+), 17 deletions(-) diff --git a/log/tm_logger.go b/log/tm_logger.go index a6a6f6d3..370aa7c0 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -10,7 +10,8 @@ import ( ) const ( - msgKey = "_msg" // "_" prefixed to avoid collisions + msgKey = "_msg" // "_" prefixed to avoid collisions + moduleKey = "module" ) type tmLogger struct { diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go index 4e36de89..362fbf28 100644 --- a/log/tmfmt_logger.go +++ b/log/tmfmt_logger.go @@ -51,13 +51,15 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { lvl := "none" msg := "unknown" - lvlIndex := -1 - msgIndex := -1 + 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() { - lvlIndex = i + excludeIndexes = append(excludeIndexes, i) switch keyvals[i+1].(type) { case string: lvl = keyvals[i+1].(string) @@ -66,18 +68,14 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { default: panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1])) } - continue - } - - // and message - if keyvals[i] == msgKey { - msgIndex = i + // and message + } else if keyvals[i] == msgKey { + excludeIndexes = append(excludeIndexes, i) msg = keyvals[i+1].(string) - continue - } - - if lvlIndex > 0 && msgIndex > 0 { // found all we're looking for - break + // 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) } } @@ -92,10 +90,18 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { // 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 { - if i == lvlIndex || i == msgIndex { - continue + for _, j := range excludeIndexes { + if i == j { + continue KeyvalueLoop + } } + if err := enc.EncodeKeyval(keyvals[i], keyvals[i+1]); err != nil { return err } diff --git a/log/tmfmt_logger_test.go b/log/tmfmt_logger_test.go index c5ec4127..62eb32a0 100644 --- a/log/tmfmt_logger_test.go +++ b/log/tmfmt_logger_test.go @@ -44,6 +44,12 @@ func TestTMFmtLogger(t *testing.T) { 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) { From f202d02d0da8172c1d8e9d630cedf8c91f5fd4f8 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Fri, 12 May 2017 17:39:00 +0200 Subject: [PATCH 27/36] [log] add separator --- log/tmfmt_logger.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go index 362fbf28..14028d75 100644 --- a/log/tmfmt_logger.go +++ b/log/tmfmt_logger.go @@ -88,7 +88,7 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { // 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)) + 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 + " ") From 300766827437f4d4333b40e072fad26c21e19dc0 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Fri, 12 May 2017 22:47:02 +0200 Subject: [PATCH 28/36] [log] add NewFilterByLevel helper func --- log/filter.go | 18 ++++++++++++++++++ log/filter_test.go | 13 +++++++++++++ 2 files changed, 31 insertions(+) diff --git a/log/filter.go b/log/filter.go index afb2e920..a5d15c7e 100644 --- a/log/filter.go +++ b/log/filter.go @@ -1,5 +1,7 @@ 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 @@ -14,6 +16,22 @@ func NewFilter(next Logger, options ...Option) Logger { return l } +// NewFilterByLevel wraps next and implements filtering based on a given level. +func NewFilterByLevel(next Logger, lvl string) Logger { + var option Option + switch lvl { + case "info": + option = AllowInfo() + case "debug": + option = AllowDebug() + case "error": + option = AllowError() + default: + panic(fmt.Sprintf("Expected either \"info\", \"debug\" or \"error\" log level, given %v", lvl)) + } + return NewFilter(next, option) +} + type filter struct { next Logger allowed level diff --git a/log/filter_test.go b/log/filter_test.go index 3840b12a..cae10c14 100644 --- a/log/filter_test.go +++ b/log/filter_test.go @@ -6,6 +6,7 @@ import ( "strings" "testing" + "github.com/stretchr/testify/assert" "github.com/tendermint/tmlibs/log" ) @@ -107,3 +108,15 @@ func TestLevelContext(t *testing.T) { t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } + +func TestNewFilterByLevel(t *testing.T) { + assert := assert.New(t) + var logger log.Logger + logger = log.NewNopLogger() + assert.NotPanics(func() { + logger = log.NewFilterByLevel(logger, "info") + }) + assert.Panics(func() { + logger = log.NewFilterByLevel(logger, "smth") + }) +} From dd3e433d32da1faddf66183678f760ccb023e4a2 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Sat, 13 May 2017 15:54:11 +0200 Subject: [PATCH 29/36] [log] NewFilterByLevel returns an error --- log/filter.go | 7 ++++--- log/filter_test.go | 14 ++++++-------- 2 files changed, 10 insertions(+), 11 deletions(-) diff --git a/log/filter.go b/log/filter.go index a5d15c7e..f410d222 100644 --- a/log/filter.go +++ b/log/filter.go @@ -17,7 +17,8 @@ func NewFilter(next Logger, options ...Option) Logger { } // NewFilterByLevel wraps next and implements filtering based on a given level. -func NewFilterByLevel(next Logger, lvl string) Logger { +// Error is returned if level is not info, error or debug. +func NewFilterByLevel(next Logger, lvl string) (Logger, error) { var option Option switch lvl { case "info": @@ -27,9 +28,9 @@ func NewFilterByLevel(next Logger, lvl string) Logger { case "error": option = AllowError() default: - panic(fmt.Sprintf("Expected either \"info\", \"debug\" or \"error\" log level, given %v", lvl)) + return nil, fmt.Errorf("Expected either \"info\", \"debug\" or \"error\" log level, given %v", lvl) } - return NewFilter(next, option) + return NewFilter(next, option), nil } type filter struct { diff --git a/log/filter_test.go b/log/filter_test.go index cae10c14..edde8624 100644 --- a/log/filter_test.go +++ b/log/filter_test.go @@ -6,7 +6,6 @@ import ( "strings" "testing" - "github.com/stretchr/testify/assert" "github.com/tendermint/tmlibs/log" ) @@ -110,13 +109,12 @@ func TestLevelContext(t *testing.T) { } func TestNewFilterByLevel(t *testing.T) { - assert := assert.New(t) var logger log.Logger logger = log.NewNopLogger() - assert.NotPanics(func() { - logger = log.NewFilterByLevel(logger, "info") - }) - assert.Panics(func() { - logger = log.NewFilterByLevel(logger, "smth") - }) + if _, err := log.NewFilterByLevel(logger, "info"); err != nil { + t.Fatal(err) + } + if _, err := log.NewFilterByLevel(logger, "other"); err == nil { + t.Fatal(err) + } } From a5fcc94a3b8dc1260da7ec956d6111ddfc0c67c1 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Sun, 14 May 2017 12:03:45 +0200 Subject: [PATCH 30/36] [log] allow for custom color funcs --- log/testing_logger.go | 18 ++++++++++++++++++ log/tm_logger.go | 6 ++++++ 2 files changed, 24 insertions(+) diff --git a/log/testing_logger.go b/log/testing_logger.go index 31913633..81482bef 100644 --- a/log/testing_logger.go +++ b/log/testing_logger.go @@ -3,6 +3,8 @@ package log import ( "os" "testing" + + "github.com/go-kit/kit/log/term" ) var ( @@ -29,3 +31,19 @@ func TestingLogger() Logger { 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 +} diff --git a/log/tm_logger.go b/log/tm_logger.go index 370aa7c0..ae8f88c6 100644 --- a/log/tm_logger.go +++ b/log/tm_logger.go @@ -43,6 +43,12 @@ func NewTMLogger(w io.Writer) Logger { 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) From 74a7f8c92b66abe75fc04c7b0a17ba52e101caef Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Sat, 6 May 2017 22:48:08 +0400 Subject: [PATCH 31/36] [autofile] close file before renaming it this might fix our windows bug https://github.com/tendermint/tendermint/issues/444 https://github.com/Netflix-Skunkworks/go-jira/commit/0980f8e1972a942e505b1939935adf0f7a71f387 --- autofile/group.go | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/autofile/group.go b/autofile/group.go index 0f829309..39f274e0 100644 --- a/autofile/group.go +++ b/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 } From 812d9f9b84d1dfe4cb46ce021b3a2d97b48d1292 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Mon, 15 May 2017 09:09:42 -0400 Subject: [PATCH 32/36] add changelog --- CHANGELOG.md | 196 +++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 196 insertions(+) create mode 100644 CHANGELOG.md diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 00000000..34eeffc0 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,196 @@ +# Changelog + +## 0.2.0 (May 15, 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 + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + From 761b1553aa2316a41e102371ab3643dddc56608a Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Mon, 15 May 2017 20:08:02 +0200 Subject: [PATCH 33/36] [log] allow filtering with fields --- log/filter.go | 59 ++++++++++++++++++++++++++++++++++++++++++---- log/filter_test.go | 30 ++++++++++++++++++----- 2 files changed, 78 insertions(+), 11 deletions(-) diff --git a/log/filter.go b/log/filter.go index f410d222..9633d88a 100644 --- a/log/filter.go +++ b/log/filter.go @@ -8,7 +8,8 @@ import "fmt" // Error helper methods are squelched. func NewFilter(next Logger, options ...Option) Logger { l := &filter{ - next: next, + next: next, + allowedKeyvals: make(map[keyval]level), } for _, option := range options { option(l) @@ -34,9 +35,15 @@ func NewFilterByLevel(next Logger, lvl string) (Logger, error) { } type filter struct { - next Logger - allowed level - errNotAllowed error + 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 { @@ -63,8 +70,30 @@ func (l *filter) Error(msg string, keyvals ...interface{}) error { 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 { - return &filter{next: l.next.With(keyvals...), allowed: l.allowed, errNotAllowed: l.errNotAllowed} + 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. @@ -107,6 +136,26 @@ 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 ( diff --git a/log/filter_test.go b/log/filter_test.go index edde8624..4665db3d 100644 --- a/log/filter_test.go +++ b/log/filter_test.go @@ -108,13 +108,31 @@ func TestLevelContext(t *testing.T) { } } -func TestNewFilterByLevel(t *testing.T) { +func TestVariousAllowWith(t *testing.T) { + var buf bytes.Buffer + var logger log.Logger - logger = log.NewNopLogger() - if _, err := log.NewFilterByLevel(logger, "info"); err != nil { - t.Fatal(err) + 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) } - if _, err := log.NewFilterByLevel(logger, "other"); err == nil { - t.Fatal(err) + + 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) } } From d0cae7b6edb4896390fd5ff82aea1bac98994bd0 Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Tue, 16 May 2017 11:51:29 +0200 Subject: [PATCH 34/36] [log] change helper func --- log/filter.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/log/filter.go b/log/filter.go index 9633d88a..45108883 100644 --- a/log/filter.go +++ b/log/filter.go @@ -17,21 +17,21 @@ func NewFilter(next Logger, options ...Option) Logger { return l } -// NewFilterByLevel wraps next and implements filtering based on a given level. -// Error is returned if level is not info, error or debug. -func NewFilterByLevel(next Logger, lvl string) (Logger, error) { - var option Option +// 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 "info": - option = AllowInfo() case "debug": - option = AllowDebug() + return AllowDebug(), nil + case "info": + return AllowInfo(), nil case "error": - option = AllowError() + return AllowError(), nil + case "none": + return AllowNone(), nil default: - return nil, fmt.Errorf("Expected either \"info\", \"debug\" or \"error\" log level, given %v", lvl) + return nil, fmt.Errorf("Expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl) } - return NewFilter(next, option), nil } type filter struct { From 8af1c70a8be17543eb33e9bfbbcdd8371e3201cc Mon Sep 17 00:00:00 2001 From: Ethan Frey Date: Wed, 17 May 2017 12:03:26 +0200 Subject: [PATCH 35/36] Renamed --debug to --trace, used for light-client and basecoin --- cli/setup.go | 6 +++--- cli/setup_test.go | 18 +++++++++--------- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/cli/setup.go b/cli/setup.go index 7a4a2098..21b29a49 100644 --- a/cli/setup.go +++ b/cli/setup.go @@ -16,7 +16,7 @@ import ( const ( RootFlag = "root" HomeFlag = "home" - DebugFlag = "debug" + TraceFlag = "trace" OutputFlag = "output" EncodingFlag = "encoding" ) @@ -36,7 +36,7 @@ func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor { // 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(DebugFlag, false, "print out full stack trace on errors") + cmd.PersistentFlags().Bool(TraceFlag, false, "print out full stack trace on errors") cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) return Executor{cmd} } @@ -92,7 +92,7 @@ func (e Executor) Execute() error { err := e.Command.Execute() if err != nil { // TODO: something cooler with log-levels - if viper.GetBool(DebugFlag) { + if viper.GetBool(TraceFlag) { fmt.Printf("ERROR: %+v\n", err) } else { fmt.Println("ERROR:", err.Error()) diff --git a/cli/setup_test.go b/cli/setup_test.go index 6396b769..8fb4ce14 100644 --- a/cli/setup_test.go +++ b/cli/setup_test.go @@ -184,7 +184,7 @@ func TestSetupUnmarshal(t *testing.T) { } } -func TestSetupDebug(t *testing.T) { +func TestSetupTrace(t *testing.T) { assert, require := assert.New(t), require.New(t) cases := []struct { @@ -193,22 +193,22 @@ func TestSetupDebug(t *testing.T) { long bool expected string }{ - {nil, nil, false, "Debug flag = false"}, - {[]string{"--debug"}, nil, true, "Debug flag = true"}, + {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_DEBUG": "true"}, true, "Debug flag = true"}, + {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 - debug := &cobra.Command{ - Use: "debug", + trace := &cobra.Command{ + Use: "trace", RunE: func(cmd *cobra.Command, args []string) error { - return errors.Errorf("Debug flag = %t", viper.GetBool(DebugFlag)) + return errors.Errorf("Trace flag = %t", viper.GetBool(TraceFlag)) }, } - cmd := PrepareBaseCmd(debug, "DBG", "/qwerty/asdfgh") // some missing dir.. + cmd := PrepareBaseCmd(trace, "DBG", "/qwerty/asdfgh") // some missing dir.. viper.Reset() args := append([]string{cmd.Use}, tc.args...) @@ -219,7 +219,7 @@ func TestSetupDebug(t *testing.T) { 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], "TestSetupDebug", i) + assert.Contains(msg[1], "TestSetupTrace", i) assert.Contains(msg[2], "setup_test.go", i) } } From 2733f5a7381b17c6227c83f33bd23959076ed7e3 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Thu, 18 May 2017 11:27:26 +0200 Subject: [PATCH 36/36] CHANGELOG: update release date --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 34eeffc0..ab193688 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Changelog -## 0.2.0 (May 15, 2017) +## 0.2.0 (May 18, 2017) BREAKING CHANGES: