diff --git a/.gitignore b/.gitignore index 38193138..62f28681 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,2 @@ -*.swp -*.swo +vendor +.glide diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 00000000..ab193688 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,196 @@ +# Changelog + +## 0.2.0 (May 18, 2017) + +BREAKING CHANGES: + +- [common] NewBaseService takes the new logger + + +FEATURES: + +- [cli] New library to standardize building command line tools +- [log] New logging library + +BUG FIXES: + +- [autofile] Close file before rotating + +## 0.1.0 (May 1, 2017) + +Initial release, combines what were previously independent repos: + +- go-autofile +- go-clist +- go-common +- go-db +- go-events +- go-flowrate +- go-logger +- go-merkle +- go-process + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/Makefile b/Makefile index 49acb091..8e43dd11 100644 --- a/Makefile +++ b/Makefile @@ -1,10 +1,10 @@ -.PHONEY: all test install get_vendor_deps ensure_tools +.PHONY: all test get_vendor_deps ensure_tools GOTOOLS = \ github.com/Masterminds/glide REPO:=github.com/tendermint/tmlibs -all: install test +all: test test: go test `glide novendor` @@ -16,5 +16,3 @@ get_vendor_deps: ensure_tools ensure_tools: go get $(GOTOOLS) - - 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 } diff --git a/cli/helper.go b/cli/helper.go new file mode 100644 index 00000000..79654bc3 --- /dev/null +++ b/cli/helper.go @@ -0,0 +1,84 @@ +package cli + +import ( + "bytes" + "fmt" + "io" + "io/ioutil" + "os" + "path/filepath" +) + +// WriteDemoConfig writes a toml file with the given values. +// It returns the RootDir the config.toml file is stored in, +// or an error if writing was impossible +func WriteDemoConfig(vals map[string]string) (string, error) { + cdir, err := ioutil.TempDir("", "test-cli") + if err != nil { + return "", err + } + data := "" + for k, v := range vals { + data = data + fmt.Sprintf("%s = \"%s\"\n", k, v) + } + cfile := filepath.Join(cdir, "config.toml") + err = ioutil.WriteFile(cfile, []byte(data), 0666) + return cdir, err +} + +// RunWithArgs executes the given command with the specified command line args +// and environmental variables set. It returns any error returned from cmd.Execute() +func RunWithArgs(cmd Executable, args []string, env map[string]string) error { + oargs := os.Args + oenv := map[string]string{} + // defer returns the environment back to normal + defer func() { + os.Args = oargs + for k, v := range oenv { + os.Setenv(k, v) + } + }() + + // set the args and env how we want them + os.Args = args + for k, v := range env { + // backup old value if there, to restore at end + oenv[k] = os.Getenv(k) + err := os.Setenv(k, v) + if err != nil { + return err + } + } + + // and finally run the command + return cmd.Execute() +} + +// RunCaptureWithArgs executes the given command with the specified command line args +// and environmental variables set. It returns whatever was writen to +// stdout along with any error returned from cmd.Execute() +func RunCaptureWithArgs(cmd Executable, args []string, env map[string]string) (output string, err error) { + old := os.Stdout // keep backup of the real stdout + r, w, _ := os.Pipe() + os.Stdout = w + defer func() { + os.Stdout = old // restoring the real stdout + }() + + outC := make(chan string) + // copy the output in a separate goroutine so printing can't block indefinitely + go func() { + var buf bytes.Buffer + // io.Copy will end when we call w.Close() below + io.Copy(&buf, r) + outC <- buf.String() + }() + + // now run the command + err = RunWithArgs(cmd, args, env) + + // and grab the stdout to return + w.Close() + output = <-outC + return output, err +} diff --git a/cli/setup.go b/cli/setup.go new file mode 100644 index 00000000..21b29a49 --- /dev/null +++ b/cli/setup.go @@ -0,0 +1,178 @@ +package cli + +import ( + "fmt" + "os" + "strings" + + "github.com/pkg/errors" + "github.com/spf13/cobra" + "github.com/spf13/viper" + + data "github.com/tendermint/go-wire/data" + "github.com/tendermint/go-wire/data/base58" +) + +const ( + RootFlag = "root" + HomeFlag = "home" + TraceFlag = "trace" + OutputFlag = "output" + EncodingFlag = "encoding" +) + +// Executable is the minimal interface to *corba.Command, so we can +// wrap if desired before the test +type Executable interface { + Execute() error +} + +// PrepareBaseCmd is meant for tendermint and other servers +func PrepareBaseCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor { + cobra.OnInitialize(func() { initEnv(envPrefix) }) + cmd.PersistentFlags().StringP(RootFlag, "r", defautRoot, "DEPRECATED. Use --home") + // -h is already reserved for --help as part of the cobra framework + // do you want to try something else?? + // also, default must be empty, so we can detect this unset and fall back + // to --root / TM_ROOT / TMROOT + cmd.PersistentFlags().String(HomeFlag, "", "root directory for config and data") + cmd.PersistentFlags().Bool(TraceFlag, false, "print out full stack trace on errors") + cmd.PersistentPreRunE = concatCobraCmdFuncs(bindFlagsLoadViper, cmd.PersistentPreRunE) + return Executor{cmd} +} + +// PrepareMainCmd is meant for client side libs that want some more flags +// +// This adds --encoding (hex, btc, base64) and --output (text, json) to +// the command. These only really make sense in interactive commands. +func PrepareMainCmd(cmd *cobra.Command, envPrefix, defautRoot string) Executor { + cmd.PersistentFlags().StringP(EncodingFlag, "e", "hex", "Binary encoding (hex|b64|btc)") + cmd.PersistentFlags().StringP(OutputFlag, "o", "text", "Output format (text|json)") + cmd.PersistentPreRunE = concatCobraCmdFuncs(setEncoding, validateOutput, cmd.PersistentPreRunE) + return PrepareBaseCmd(cmd, envPrefix, defautRoot) +} + +// initEnv sets to use ENV variables if set. +func initEnv(prefix string) { + copyEnvVars(prefix) + + // env variables with TM prefix (eg. TM_ROOT) + viper.SetEnvPrefix(prefix) + viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) + viper.AutomaticEnv() +} + +// This copies all variables like TMROOT to TM_ROOT, +// so we can support both formats for the user +func copyEnvVars(prefix string) { + prefix = strings.ToUpper(prefix) + ps := prefix + "_" + for _, e := range os.Environ() { + kv := strings.SplitN(e, "=", 2) + if len(kv) == 2 { + k, v := kv[0], kv[1] + if strings.HasPrefix(k, prefix) && !strings.HasPrefix(k, ps) { + k2 := strings.Replace(k, prefix, ps, 1) + os.Setenv(k2, v) + } + } + } +} + +// Executor wraps the cobra Command with a nicer Execute method +type Executor struct { + *cobra.Command +} + +// execute adds all child commands to the root command sets flags appropriately. +// This is called by main.main(). It only needs to happen once to the rootCmd. +func (e Executor) Execute() error { + e.SilenceUsage = true + e.SilenceErrors = true + err := e.Command.Execute() + if err != nil { + // TODO: something cooler with log-levels + if viper.GetBool(TraceFlag) { + fmt.Printf("ERROR: %+v\n", err) + } else { + fmt.Println("ERROR:", err.Error()) + } + } + return err +} + +type cobraCmdFunc func(cmd *cobra.Command, args []string) error + +// Returns a single function that calls each argument function in sequence +// RunE, PreRunE, PersistentPreRunE, etc. all have this same signature +func concatCobraCmdFuncs(fs ...cobraCmdFunc) cobraCmdFunc { + return func(cmd *cobra.Command, args []string) error { + for _, f := range fs { + if f != nil { + if err := f(cmd, args); err != nil { + return err + } + } + } + return nil + } +} + +// Bind all flags and read the config into viper +func bindFlagsLoadViper(cmd *cobra.Command, args []string) error { + // cmd.Flags() includes flags from this command and all persistent flags from the parent + if err := viper.BindPFlags(cmd.Flags()); err != nil { + return err + } + + // rootDir is command line flag, env variable, or default $HOME/.tlc + // NOTE: we support both --root and --home for now, but eventually only --home + // Also ensure we set the correct rootDir under HomeFlag so we dont need to + // repeat this logic elsewhere. + rootDir := viper.GetString(HomeFlag) + if rootDir == "" { + rootDir = viper.GetString(RootFlag) + viper.Set(HomeFlag, rootDir) + } + viper.SetConfigName("config") // name of config file (without extension) + viper.AddConfigPath(rootDir) // search root directory + + // If a config file is found, read it in. + if err := viper.ReadInConfig(); err == nil { + // stderr, so if we redirect output to json file, this doesn't appear + // fmt.Fprintln(os.Stderr, "Using config file:", viper.ConfigFileUsed()) + } else if _, ok := err.(viper.ConfigFileNotFoundError); !ok { + // we ignore not found error, only parse error + // stderr, so if we redirect output to json file, this doesn't appear + fmt.Fprintf(os.Stderr, "%#v", err) + } + return nil +} + +// setEncoding reads the encoding flag +func setEncoding(cmd *cobra.Command, args []string) error { + // validate and set encoding + enc := viper.GetString("encoding") + switch enc { + case "hex": + data.Encoder = data.HexEncoder + case "b64": + data.Encoder = data.B64Encoder + case "btc": + data.Encoder = base58.BTCEncoder + default: + return errors.Errorf("Unsupported encoding: %s", enc) + } + return nil +} + +func validateOutput(cmd *cobra.Command, args []string) error { + // validate output format + output := viper.GetString(OutputFlag) + switch output { + case "text", "json": + default: + return errors.Errorf("Unsupported output format: %s", output) + } + return nil +} diff --git a/cli/setup_test.go b/cli/setup_test.go new file mode 100644 index 00000000..8fb4ce14 --- /dev/null +++ b/cli/setup_test.go @@ -0,0 +1,226 @@ +package cli + +import ( + "fmt" + "strconv" + "strings" + "testing" + + "github.com/pkg/errors" + "github.com/spf13/cobra" + "github.com/spf13/viper" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestSetupEnv(t *testing.T) { + assert, require := assert.New(t), require.New(t) + + cases := []struct { + args []string + env map[string]string + expected string + }{ + {nil, nil, ""}, + {[]string{"--foobar", "bang!"}, nil, "bang!"}, + // make sure reset is good + {nil, nil, ""}, + // test both variants of the prefix + {nil, map[string]string{"DEMO_FOOBAR": "good"}, "good"}, + {nil, map[string]string{"DEMOFOOBAR": "silly"}, "silly"}, + // and that cli overrides env... + {[]string{"--foobar", "important"}, + map[string]string{"DEMO_FOOBAR": "ignored"}, "important"}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + var foo string + demo := &cobra.Command{ + Use: "demo", + RunE: func(cmd *cobra.Command, args []string) error { + foo = viper.GetString("foobar") + return nil + }, + } + demo.Flags().String("foobar", "", "Some test value from config") + cmd := PrepareBaseCmd(demo, "DEMO", "/qwerty/asdfgh") // some missing dir.. + + viper.Reset() + args := append([]string{cmd.Use}, tc.args...) + err := RunWithArgs(cmd, args, tc.env) + require.Nil(err, i) + assert.Equal(tc.expected, foo, i) + } +} + +func TestSetupConfig(t *testing.T) { + assert, require := assert.New(t), require.New(t) + + // we pre-create two config files we can refer to in the rest of + // the test cases. + cval1, cval2 := "fubble", "wubble" + conf1, err := WriteDemoConfig(map[string]string{"boo": cval1}) + require.Nil(err) + // even with some ignored fields, should be no problem + conf2, err := WriteDemoConfig(map[string]string{"boo": cval2, "foo": "bar"}) + require.Nil(err) + + cases := []struct { + args []string + env map[string]string + expected string + }{ + {nil, nil, ""}, + // setting on the command line + {[]string{"--boo", "haha"}, nil, "haha"}, + {[]string{"--root", conf1}, nil, cval1}, + // test both variants of the prefix + {nil, map[string]string{"RD_BOO": "bang"}, "bang"}, + {nil, map[string]string{"RD_ROOT": conf1}, cval1}, + {nil, map[string]string{"RDROOT": conf2}, cval2}, + {nil, map[string]string{"RDHOME": conf1}, cval1}, + // and when both are set??? HOME wins every time! + {[]string{"--root", conf1}, map[string]string{"RDHOME": conf2}, cval2}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + var foo string + boo := &cobra.Command{ + Use: "reader", + RunE: func(cmd *cobra.Command, args []string) error { + foo = viper.GetString("boo") + return nil + }, + } + boo.Flags().String("boo", "", "Some test value from config") + cmd := PrepareBaseCmd(boo, "RD", "/qwerty/asdfgh") // some missing dir... + + viper.Reset() + args := append([]string{cmd.Use}, tc.args...) + err := RunWithArgs(cmd, args, tc.env) + require.Nil(err, i) + assert.Equal(tc.expected, foo, i) + } +} + +type DemoConfig struct { + Name string `mapstructure:"name"` + Age int `mapstructure:"age"` + Unused int `mapstructure:"unused"` +} + +func TestSetupUnmarshal(t *testing.T) { + assert, require := assert.New(t), require.New(t) + + // we pre-create two config files we can refer to in the rest of + // the test cases. + cval1, cval2 := "someone", "else" + conf1, err := WriteDemoConfig(map[string]string{"name": cval1}) + require.Nil(err) + // even with some ignored fields, should be no problem + conf2, err := WriteDemoConfig(map[string]string{"name": cval2, "foo": "bar"}) + require.Nil(err) + + // unused is not declared on a flag and remains from base + base := DemoConfig{ + Name: "default", + Age: 42, + Unused: -7, + } + c := func(name string, age int) DemoConfig { + r := base + // anything set on the flags as a default is used over + // the default config object + r.Name = "from-flag" + if name != "" { + r.Name = name + } + if age != 0 { + r.Age = age + } + return r + } + + cases := []struct { + args []string + env map[string]string + expected DemoConfig + }{ + {nil, nil, c("", 0)}, + // setting on the command line + {[]string{"--name", "haha"}, nil, c("haha", 0)}, + {[]string{"--root", conf1}, nil, c(cval1, 0)}, + // test both variants of the prefix + {nil, map[string]string{"MR_AGE": "56"}, c("", 56)}, + {nil, map[string]string{"MR_ROOT": conf1}, c(cval1, 0)}, + {[]string{"--age", "17"}, map[string]string{"MRHOME": conf2}, c(cval2, 17)}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + cfg := base + marsh := &cobra.Command{ + Use: "marsh", + RunE: func(cmd *cobra.Command, args []string) error { + return viper.Unmarshal(&cfg) + }, + } + marsh.Flags().String("name", "from-flag", "Some test value from config") + // if we want a flag to use the proper default, then copy it + // from the default config here + marsh.Flags().Int("age", base.Age, "Some test value from config") + cmd := PrepareBaseCmd(marsh, "MR", "/qwerty/asdfgh") // some missing dir... + + viper.Reset() + args := append([]string{cmd.Use}, tc.args...) + err := RunWithArgs(cmd, args, tc.env) + require.Nil(err, i) + assert.Equal(tc.expected, cfg, i) + } +} + +func TestSetupTrace(t *testing.T) { + assert, require := assert.New(t), require.New(t) + + cases := []struct { + args []string + env map[string]string + long bool + expected string + }{ + {nil, nil, false, "Trace flag = false"}, + {[]string{"--trace"}, nil, true, "Trace flag = true"}, + {[]string{"--no-such-flag"}, nil, false, "unknown flag: --no-such-flag"}, + {nil, map[string]string{"DBG_TRACE": "true"}, true, "Trace flag = true"}, + } + + for idx, tc := range cases { + i := strconv.Itoa(idx) + // test command that store value of foobar in local variable + trace := &cobra.Command{ + Use: "trace", + RunE: func(cmd *cobra.Command, args []string) error { + return errors.Errorf("Trace flag = %t", viper.GetBool(TraceFlag)) + }, + } + cmd := PrepareBaseCmd(trace, "DBG", "/qwerty/asdfgh") // some missing dir.. + + viper.Reset() + args := append([]string{cmd.Use}, tc.args...) + out, err := RunCaptureWithArgs(cmd, args, tc.env) + require.NotNil(err, i) + msg := strings.Split(out, "\n") + desired := fmt.Sprintf("ERROR: %s", tc.expected) + assert.Equal(desired, msg[0], i) + if tc.long && assert.True(len(msg) > 2, i) { + // the next line starts the stack trace... + assert.Contains(msg[1], "TestSetupTrace", i) + assert.Contains(msg[2], "setup_test.go", i) + } + } +} 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 003e3d61..b30f538a 100644 --- a/glide.lock +++ b/glide.lock @@ -1,18 +1,67 @@ -hash: 47e715510d6b57cff8dc4750b6b9d89a41469a8330a7a8bea1c044b2ac61e581 -updated: 2017-04-21T16:04:25.798163098-04:00 +hash: 69359a39dbb6957c9f09167520317ad72d4bfa75f37a614b347e2510768c8a42 +updated: 2017-05-05T17:46:34.975369143Z imports: +- name: github.com/fsnotify/fsnotify + version: 4da3e2cfbabc9f751898f250b49f2439785783a1 +- name: github.com/go-kit/kit + version: 0873e56b0faeae3a1d661b10d629135508ea5504 + subpackages: + - log + - log/level + - log/term +- name: github.com/go-logfmt/logfmt + version: 390ab7935ee28ec6b286364bba9b4dd6410cb3d5 - name: github.com/go-stack/stack - version: 100eb0c0a9c5b306ca2fb4f165df21d80ada4b82 + version: 7a2f19628aabfe68f0766b59e74d6315f8347d22 - name: github.com/golang/snappy - version: d9eb7a3d35ec988b8585d4a0068e462c27d28380 + version: 553a641470496b2327abcac10b36396bd98e45c9 +- name: github.com/hashicorp/hcl + version: a4b07c25de5ff55ad3b8936cea69a79a3d95a855 + subpackages: + - hcl/ast + - hcl/parser + - hcl/scanner + - hcl/strconv + - hcl/token + - json/parser + - json/scanner + - json/token +- name: github.com/inconshreveable/mousetrap + version: 76626ae9c91c4f2a10f34cad8ce83ea42c93bb75 - name: github.com/jmhodges/levigo version: c42d9e0ca023e2198120196f842701bb4c55d7b9 +- name: github.com/kr/logfmt + version: b84e30acd515aadc4b783ad4ff83aff3299bdfe0 +- name: github.com/magiconair/properties + version: 51463bfca2576e06c62a8504b5c0f06d61312647 - name: github.com/mattn/go-colorable - version: d228849504861217f796da67fae4f6e347643f15 + version: ded68f7a9561c023e790de24279db7ebf473ea80 - name: github.com/mattn/go-isatty - version: 30a891c33c7cde7b02a981314b4228ec99380cca + version: fc9e8d8ef48496124e79ae0df75490096eccf6fe +- name: github.com/mitchellh/mapstructure + version: cc8532a8e9a55ea36402aa21efdf403a60d34096 +- name: github.com/pelletier/go-buffruneio + version: c37440a7cf42ac63b919c752ca73a85067e05992 +- name: github.com/pelletier/go-toml + version: 97253b98df84f9eef872866d079e74b8265150f1 +- name: github.com/pkg/errors + version: c605e284fe17294bda444b34710735b29d1a9d90 +- name: github.com/spf13/afero + version: 9be650865eab0c12963d8753212f4f9c66cdcf12 + subpackages: + - mem +- name: github.com/spf13/cast + version: acbeb36b902d72a7a4c18e8f3241075e7ab763e4 +- name: github.com/spf13/cobra + version: db6b9a8b3f3f400c8ecb4a4d7d02245b8facad66 +- name: github.com/spf13/jwalterweatherman + version: fa7ca7e836cf3a8bb4ebf799f472c12d7e903d66 +- name: github.com/spf13/pflag + version: 80fe0fb4eba54167e2ccae1c6c950e72abf61b73 +- name: github.com/spf13/viper + version: 0967fc9aceab2ce9da34061253ac10fb99bba5b2 - name: github.com/syndtr/goleveldb - version: 23851d93a2292dcc56e71a18ec9e0624d84a0f65 + version: 8c81ea47d4c41a385645e133e15510fc6a2a74b4 subpackages: - leveldb - leveldb/cache @@ -27,22 +76,32 @@ imports: - leveldb/table - leveldb/util - name: github.com/tendermint/go-wire - version: 4325edc613ad1e9286c8bb770ed40ad3fe647e6c + version: b53add0b622662731985485f3a19be7f684660b8 + subpackages: + - data + - data/base58 - name: github.com/tendermint/log15 - version: ae0f3d6450da9eac7074b439c8e1c3cabf0d5ce6 + version: f91285dece9f4875421b481da3e613d83d44f29b subpackages: - term - name: golang.org/x/crypto - version: 7c6cc321c680f03b9ef0764448e780704f486b51 + version: 5a033cc77e57eca05bdb50522851d29e03569cbe subpackages: - ripemd160 - name: golang.org/x/sys - version: d75a52659825e75fff6158388dddc6a5b04f9ba5 + version: 9ccfe848b9db8435a24c424abbc07a921adf1df5 subpackages: - unix +- name: golang.org/x/text + version: 470f45bf29f4147d6fbd7dfd0a02a848e49f5bf4 + subpackages: + - transform + - unicode/norm +- name: gopkg.in/yaml.v2 + version: cd8b52f8269e0feb286dfeef29f8fe4d5b397e0b testImports: - name: github.com/davecgh/go-spew - version: 6d212800a42e8ab5c146b8ace3490ee17e5225f9 + version: 04cdfd42973bb9c8589fd6a731800cf222fde1a9 subpackages: - spew - name: github.com/pmezard/go-difflib @@ -50,6 +109,7 @@ testImports: subpackages: - difflib - name: github.com/stretchr/testify - version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0 + version: 4d4bfba8f1d1027c4fdbe371823030df51419987 subpackages: - assert + - require diff --git a/glide.yaml b/glide.yaml index a4c5dd2b..d8bdd587 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,17 +1,31 @@ package: github.com/tendermint/tmlibs import: +- package: github.com/go-kit/kit + subpackages: + - log + - log/level + - log/term +- package: github.com/go-logfmt/logfmt - package: github.com/jmhodges/levigo +- package: github.com/pkg/errors +- package: github.com/spf13/cobra +- package: github.com/spf13/viper - package: github.com/syndtr/goleveldb subpackages: - leveldb - leveldb/errors - leveldb/opt - package: github.com/tendermint/go-wire + subpackages: + - data + - data/base58 - package: github.com/tendermint/log15 - package: golang.org/x/crypto subpackages: - ripemd160 testImport: - package: github.com/stretchr/testify + version: ^1.1.4 subpackages: - assert + - require diff --git a/log/filter.go b/log/filter.go new file mode 100644 index 00000000..45108883 --- /dev/null +++ b/log/filter.go @@ -0,0 +1,165 @@ +package log + +import "fmt" + +// NewFilter wraps next and implements filtering. See the commentary on the +// Option functions for a detailed description of how to configure levels. If +// no options are provided, all leveled log events created with Debug, Info or +// Error helper methods are squelched. +func NewFilter(next Logger, options ...Option) Logger { + l := &filter{ + next: next, + allowedKeyvals: make(map[keyval]level), + } + for _, option := range options { + option(l) + } + return l +} + +// AllowLevel returns an option for the given level or error if no option exist +// for such level. +func AllowLevel(lvl string) (Option, error) { + switch lvl { + case "debug": + return AllowDebug(), nil + case "info": + return AllowInfo(), nil + case "error": + return AllowError(), nil + case "none": + return AllowNone(), nil + default: + return nil, fmt.Errorf("Expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl) + } +} + +type filter struct { + next Logger + allowed level + allowedKeyvals map[keyval]level + errNotAllowed error +} + +type keyval struct { + key interface{} + value interface{} +} + +func (l *filter) Info(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelInfo != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Info(msg, keyvals...) +} + +func (l *filter) Debug(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelDebug != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Debug(msg, keyvals...) +} + +func (l *filter) Error(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelError != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Error(msg, keyvals...) +} + +// With implements Logger by constructing a new filter with a keyvals appended +// to the logger. +// +// If custom level was set for a keyval pair using one of the +// Allow*With methods, it is used as the logger's level. +// +// Examples: +// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto")) +// logger.With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto" +// +// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam")) +// logger.With("module", "crypto", "user", "Sam").Info("Hello") # returns nil +// +// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam")) +// logger.With("user", "Sam").With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto user=Sam" +func (l *filter) With(keyvals ...interface{}) Logger { + for i := len(keyvals) - 2; i >= 0; i -= 2 { + for kv, allowed := range l.allowedKeyvals { + if keyvals[i] == kv.key && keyvals[i+1] == kv.value { + return &filter{next: l.next.With(keyvals...), allowed: allowed, errNotAllowed: l.errNotAllowed, allowedKeyvals: l.allowedKeyvals} + } + } + } + return &filter{next: l.next.With(keyvals...), allowed: l.allowed, errNotAllowed: l.errNotAllowed, allowedKeyvals: l.allowedKeyvals} +} + +// Option sets a parameter for the filter. +type Option func(*filter) + +// AllowAll is an alias for AllowDebug. +func AllowAll() Option { + return AllowDebug() +} + +// AllowDebug allows error, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelInfo | levelDebug) +} + +// AllowInfo allows error and info level log events to pass. +func AllowInfo() Option { + return allowed(levelError | levelInfo) +} + +// AllowError allows only error level log events to pass. +func AllowError() Option { + return allowed(levelError) +} + +// AllowNone allows no leveled log events to pass. +func AllowNone() Option { + return allowed(0) +} + +func allowed(allowed level) Option { + return func(l *filter) { l.allowed = allowed } +} + +// ErrNotAllowed sets the error to return from Log when it squelches a log +// event disallowed by the configured Allow[Level] option. By default, +// ErrNotAllowed is nil; in this case the log event is squelched with no +// error. +func ErrNotAllowed(err error) Option { + return func(l *filter) { l.errNotAllowed = err } +} + +// AllowDebugWith allows error, info and debug level log events to pass for a specific key value pair. +func AllowDebugWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo | levelDebug } +} + +// AllowInfoWith allows error and info level log events to pass for a specific key value pair. +func AllowInfoWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo } +} + +// AllowErrorWith allows only error level log events to pass for a specific key value pair. +func AllowErrorWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError } +} + +// AllowNoneWith allows no leveled log events to pass for a specific key value pair. +func AllowNoneWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = 0 } +} + +type level byte + +const ( + levelDebug level = 1 << iota + levelInfo + levelError +) diff --git a/log/filter_test.go b/log/filter_test.go new file mode 100644 index 00000000..4665db3d --- /dev/null +++ b/log/filter_test.go @@ -0,0 +1,138 @@ +package log_test + +import ( + "bytes" + "errors" + "strings" + "testing" + + "github.com/tendermint/tmlibs/log" +) + +func TestVariousLevels(t *testing.T) { + testCases := []struct { + name string + allowed log.Option + want string + }{ + { + "AllowAll", + log.AllowAll(), + strings.Join([]string{ + `{"_msg":"here","level":"debug","this is":"debug log"}`, + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowDebug", + log.AllowDebug(), + strings.Join([]string{ + `{"_msg":"here","level":"debug","this is":"debug log"}`, + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowInfo", + log.AllowInfo(), + strings.Join([]string{ + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowError", + log.AllowError(), + strings.Join([]string{ + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowNone", + log.AllowNone(), + ``, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := log.NewFilter(log.NewTMJSONLogger(&buf), tc.allowed) + + logger.Debug("here", "this is", "debug log") + logger.Info("here", "this is", "info log") + logger.Error("here", "this is", "error log") + + if want, have := tc.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant:\n%s\nhave:\n%s", want, have) + } + }) + } +} + +func TestErrNotAllowed(t *testing.T) { + myError := errors.New("squelched!") + opts := []log.Option{ + log.AllowError(), + log.ErrNotAllowed(myError), + } + logger := log.NewFilter(log.NewNopLogger(), opts...) + + if want, have := myError, logger.Info("foo", "bar", "baz"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } + + if want, have := error(nil), logger.Error("foo", "bar", "baz"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } +} + +func TestLevelContext(t *testing.T) { + var buf bytes.Buffer + + var logger log.Logger + logger = log.NewTMJSONLogger(&buf) + logger = log.NewFilter(logger, log.AllowError()) + logger = logger.With("context", "value") + + logger.Error("foo", "bar", "baz") + if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"error"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + logger.Info("foo", "bar", "baz") + if want, have := ``, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} + +func TestVariousAllowWith(t *testing.T) { + var buf bytes.Buffer + + var logger log.Logger + logger = log.NewTMJSONLogger(&buf) + + logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value")) + logger1.With("context", "value").Info("foo", "bar", "baz") + if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger2 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam")) + logger2.With("context", "value", "user", "Sam").Info("foo", "bar", "baz") + if want, have := ``, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger3 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam")) + logger3.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz") + if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} diff --git a/log/logger.go b/log/logger.go new file mode 100644 index 00000000..be273f48 --- /dev/null +++ b/log/logger.go @@ -0,0 +1,30 @@ +package log + +import ( + "io" + + kitlog "github.com/go-kit/kit/log" +) + +// Logger is what any Tendermint library should take. +type Logger interface { + Debug(msg string, keyvals ...interface{}) error + Info(msg string, keyvals ...interface{}) error + Error(msg string, keyvals ...interface{}) error + + With(keyvals ...interface{}) Logger +} + +// NewSyncWriter returns a new writer that is safe for concurrent use by +// multiple goroutines. Writes to the returned writer are passed on to w. If +// another write is already in progress, the calling goroutine blocks until +// the writer is available. +// +// If w implements the following interface, so does the returned writer. +// +// interface { +// Fd() uintptr +// } +func NewSyncWriter(w io.Writer) io.Writer { + return kitlog.NewSyncWriter(w) +} diff --git a/log/nop_logger.go b/log/nop_logger.go new file mode 100644 index 00000000..306a8405 --- /dev/null +++ b/log/nop_logger.go @@ -0,0 +1,25 @@ +package log + +type nopLogger struct{} + +// Interface assertions +var _ Logger = (*nopLogger)(nil) + +// NewNopLogger returns a logger that doesn't do anything. +func NewNopLogger() Logger { return &nopLogger{} } + +func (nopLogger) Info(string, ...interface{}) error { + return nil +} + +func (nopLogger) Debug(string, ...interface{}) error { + return nil +} + +func (nopLogger) Error(string, ...interface{}) error { + return nil +} + +func (l *nopLogger) With(...interface{}) Logger { + return l +} diff --git a/log/nop_logger_test.go b/log/nop_logger_test.go new file mode 100644 index 00000000..d2009fdf --- /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 := logger.With("def", "ghi").Debug(""); err != nil { + t.Error(err) + } +} diff --git a/log/testing_logger.go b/log/testing_logger.go new file mode 100644 index 00000000..81482bef --- /dev/null +++ b/log/testing_logger.go @@ -0,0 +1,49 @@ +package log + +import ( + "os" + "testing" + + "github.com/go-kit/kit/log/term" +) + +var ( + // reuse the same logger across all tests + _testingLogger Logger +) + +// TestingLogger returns a TMLogger which writes to STDOUT if testing being run +// with the verbose (-v) flag, NopLogger otherwise. +// +// Note that the call to TestingLogger() must be made +// inside a test (not in the init func) because +// verbose flag only set at the time of testing. +func TestingLogger() Logger { + if _testingLogger != nil { + return _testingLogger + } + + if testing.Verbose() { + _testingLogger = NewTMLogger(NewSyncWriter(os.Stdout)) + } else { + _testingLogger = NewNopLogger() + } + + return _testingLogger +} + +// TestingLoggerWithColorFn allow you to provide your own color function. See +// TestingLogger for documentation. +func TestingLoggerWithColorFn(colorFn func(keyvals ...interface{}) term.FgBgColor) Logger { + if _testingLogger != nil { + return _testingLogger + } + + if testing.Verbose() { + _testingLogger = NewTMLoggerWithColorFn(NewSyncWriter(os.Stdout), colorFn) + } else { + _testingLogger = NewNopLogger() + } + + return _testingLogger +} 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 new file mode 100644 index 00000000..ae8f88c6 --- /dev/null +++ b/log/tm_logger.go @@ -0,0 +1,74 @@ +package log + +import ( + "fmt" + "io" + + kitlog "github.com/go-kit/kit/log" + kitlevel "github.com/go-kit/kit/log/level" + "github.com/go-kit/kit/log/term" +) + +const ( + msgKey = "_msg" // "_" prefixed to avoid collisions + moduleKey = "module" +) + +type tmLogger struct { + srcLogger kitlog.Logger +} + +// Interface assertions +var _ Logger = (*tmLogger)(nil) + +// NewTMTermLogger returns a logger that encodes msg and keyvals to the Writer +// using go-kit's log as an underlying logger and our custom formatter. Note +// that underlying logger could be swapped with something else. +func NewTMLogger(w io.Writer) Logger { + // Color by level value + colorFn := func(keyvals ...interface{}) term.FgBgColor { + if keyvals[0] != kitlevel.Key() { + panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0])) + } + switch keyvals[1].(kitlevel.Value).String() { + case "debug": + return term.FgBgColor{Fg: term.DarkGray} + case "error": + return term.FgBgColor{Fg: term.Red} + default: + return term.FgBgColor{} + } + } + + return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} +} + +// NewTMLoggerWithColorFn allow you to provide your own color function. See +// NewTMLogger for documentation. +func NewTMLoggerWithColorFn(w io.Writer, colorFn func(keyvals ...interface{}) term.FgBgColor) Logger { + return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} +} + +// Info logs a message at level Info. +func (l *tmLogger) Info(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Info(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// Debug logs a message at level Debug. +func (l *tmLogger) Debug(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Debug(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// Error logs a message at level Error. +func (l *tmLogger) Error(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Error(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// With returns a new contextual logger with keyvals prepended to those passed +// to calls to Info, Debug or Error. +func (l *tmLogger) With(keyvals ...interface{}) Logger { + return &tmLogger{kitlog.With(l.srcLogger, keyvals...)} +} diff --git a/log/tm_logger_test.go b/log/tm_logger_test.go new file mode 100644 index 00000000..15c940ce --- /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 := logger.With("def", "ghi").Debug(""); err != nil { + t.Error(err) + } +} + +func BenchmarkTMLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), baseInfoMessage) +} + +func BenchmarkTMLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), withInfoMessage) +} + +func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { + lc := logger.With("common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(lc) + } +} + +var ( + baseInfoMessage = func(logger log.Logger) { logger.Info("foo_message", "foo_key", "foo_value") } + withInfoMessage = func(logger log.Logger) { logger.With("a", "b").Info("c", "d", "f") } +) diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go new file mode 100644 index 00000000..14028d75 --- /dev/null +++ b/log/tmfmt_logger.go @@ -0,0 +1,122 @@ +package log + +import ( + "bytes" + "fmt" + "io" + "sync" + "time" + + kitlog "github.com/go-kit/kit/log" + kitlevel "github.com/go-kit/kit/log/level" + "github.com/go-logfmt/logfmt" +) + +type tmfmtEncoder struct { + *logfmt.Encoder + buf bytes.Buffer +} + +func (l *tmfmtEncoder) Reset() { + l.Encoder.Reset() + l.buf.Reset() +} + +var tmfmtEncoderPool = sync.Pool{ + New: func() interface{} { + var enc tmfmtEncoder + enc.Encoder = logfmt.NewEncoder(&enc.buf) + return &enc + }, +} + +type tmfmtLogger struct { + w io.Writer +} + +// NewTMFmtLogger returns a logger that encodes keyvals to the Writer in +// Tendermint custom format. +// +// Each log event produces no more than one call to w.Write. +// The passed Writer must be safe for concurrent use by multiple goroutines if +// the returned Logger will be used concurrently. +func NewTMFmtLogger(w io.Writer) kitlog.Logger { + return &tmfmtLogger{w} +} + +func (l tmfmtLogger) Log(keyvals ...interface{}) error { + enc := tmfmtEncoderPool.Get().(*tmfmtEncoder) + enc.Reset() + defer tmfmtEncoderPool.Put(enc) + + lvl := "none" + msg := "unknown" + module := "unknown" + + // indexes of keys to skip while encoding later + excludeIndexes := make([]int, 0) + + for i := 0; i < len(keyvals)-1; i += 2 { + // Extract level + if keyvals[i] == kitlevel.Key() { + excludeIndexes = append(excludeIndexes, i) + switch keyvals[i+1].(type) { + case string: + lvl = keyvals[i+1].(string) + case kitlevel.Value: + lvl = keyvals[i+1].(kitlevel.Value).String() + default: + panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1])) + } + // and message + } else if keyvals[i] == msgKey { + excludeIndexes = append(excludeIndexes, i) + msg = keyvals[i+1].(string) + // and module (could be multiple keyvals; if such case last keyvalue wins) + } else if keyvals[i] == moduleKey { + excludeIndexes = append(excludeIndexes, i) + module = keyvals[i+1].(string) + } + } + + // Form a custom Tendermint line + // + // Example: + // D[05-02|11:06:44.322] Stopping AddrBook (ignoring: already stopped) + // + // Description: + // D - first character of the level, uppercase (ASCII only) + // [05-02|11:06:44.322] - our time format (see https://golang.org/src/time/format.go) + // Stopping ... - message + enc.buf.WriteString(fmt.Sprintf("%c[%s] %-44s ", lvl[0]-32, time.Now().UTC().Format("01-02|15:04:05.000"), msg)) + + if module != "unknown" { + enc.buf.WriteString("module=" + module + " ") + } + +KeyvalueLoop: + for i := 0; i < len(keyvals)-1; i += 2 { + for _, j := range excludeIndexes { + if i == j { + continue KeyvalueLoop + } + } + + if err := enc.EncodeKeyval(keyvals[i], keyvals[i+1]); err != nil { + return err + } + } + + // Add newline to the end of the buffer + if err := enc.EndRecord(); err != nil { + return err + } + + // The Logger interface requires implementations to be safe for concurrent + // use by multiple goroutines. For this implementation that means making + // only one call to l.w.Write() for each call to Log. + if _, err := l.w.Write(enc.buf.Bytes()); err != nil { + return err + } + return nil +} diff --git a/log/tmfmt_logger_test.go b/log/tmfmt_logger_test.go new file mode 100644 index 00000000..62eb32a0 --- /dev/null +++ b/log/tmfmt_logger_test.go @@ -0,0 +1,116 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "math" + "regexp" + "testing" + + kitlog "github.com/go-kit/kit/log" + "github.com/stretchr/testify/assert" + "github.com/tendermint/tmlibs/log" +) + +func TestTMFmtLogger(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewTMFmtLogger(buf) + + if err := logger.Log("hello", "world"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ hello=world\n$`), buf.String()) + + buf.Reset() + if err := logger.Log("a", 1, "err", errors.New("error")); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ a=1 err=error\n$`), buf.String()) + + buf.Reset() + err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}) + assert.NotNil(t, err) + + buf.Reset() + if err := logger.Log("level", "error"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`E\[.+\] unknown \s+\n$`), buf.String()) + + buf.Reset() + if err := logger.Log("_msg", "Hello"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] Hello \s+\n$`), buf.String()) + + buf.Reset() + if err := logger.Log("module", "main", "module", "crypto", "module", "wire"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+module=wire\s+\n$`), buf.String()) +} + +func BenchmarkTMFmtLoggerSimple(b *testing.B) { + benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkTMFmtLoggerContextual(b *testing.B) { + benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), withMessage) +} + +func TestTMFmtLoggerConcurrency(t *testing.T) { + t.Parallel() + testConcurrency(t, log.NewTMFmtLogger(ioutil.Discard), 10000) +} + +func benchmarkRunnerKitlog(b *testing.B, logger kitlog.Logger, f func(kitlog.Logger)) { + lc := kitlog.With(logger, "common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(lc) + } +} + +var ( + baseMessage = func(logger kitlog.Logger) { logger.Log("foo_key", "foo_value") } + withMessage = func(logger kitlog.Logger) { kitlog.With(logger, "a", "b").Log("d", "f") } +) + +// These test are designed to be run with the race detector. + +func testConcurrency(t *testing.T, logger kitlog.Logger, total int) { + n := int(math.Sqrt(float64(total))) + share := total / n + + errC := make(chan error, n) + + for i := 0; i < n; i++ { + go func() { + errC <- spam(logger, share) + }() + } + + for i := 0; i < n; i++ { + err := <-errC + if err != nil { + t.Fatalf("concurrent logging error: %v", err) + } + } +} + +func spam(logger kitlog.Logger, count int) error { + for i := 0; i < count; i++ { + err := logger.Log("key", i) + if err != nil { + return err + } + } + return nil +} + +type mymap map[int]int + +func (m mymap) String() string { return "special_behavior" } 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...) }