mirrors/tendermint
1
0
Fork 0
mirror of https://github.com/tendermint/tendermint.git synced 2026-04-26 10:41:11 +00:00
Code Issues Packages Projects Releases Wiki Activity

logger: refactor Tendermint logger by using zerolog (#6534)

Browse Source
This commit is contained in:
Aleksandr Bezobchuk
2021-06-07 08:30:48 -04:00
committed by GitHub
parent b28887e839
commit 3635c7a382
43 changed files with 316 additions and 1363 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
CHANGELOG_PENDING.md
View File

@@ -32,6 +32,8 @@ Friendly reminder: We have a [bug bounty program](https://hackerone.com/tendermi
- P2P Protocol
- Go API
- [logging] \#6534 Removed the existing custom Tendermint logger backed by go-kit. The logging interface, `Logger`, remains.
Tendermint still provides a default logger backed by the performant zerolog logger. (@alexanderbez)
- [mempool] \#6529 The `Context` field has been removed from the `TxInfo` type. `CheckTx` now requires a `Context` argument. (@alexanderbez)
- [abci/client, proxy] \#5673 `Async` funcs return an error, `Sync` and `Async` funcs accept `context.Context` (@melekes)
- [p2p] Removed unused function `MakePoWTarget`. (@erikgrinaker)

11
abci/cmd/abci-cli/abci-cli.go
View File

@@ -68,12 +68,9 @@ var RootCmd = &cobra.Command{
}
if logger == nil {
allowLevel, err := log.AllowLevel(flagLogLevel)
if err != nil {
return err
}
logger = log.NewFilter(log.NewTMLogger(log.NewSyncWriter(os.Stdout)), allowLevel)
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
}
if client == nil {
var err error
client, err = abcicli.NewClient(flagAddress, flagAbci, false)
@@ -598,7 +595,7 @@ func cmdQuery(cmd *cobra.Command, args []string) error {
func cmdCounter(cmd *cobra.Command, args []string) error {
app := counter.NewApplication(flagSerial)
logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger := log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
// Start the listener
srv, err := server.NewServer(flagAddress, flagAbci, app)
@@ -623,7 +620,7 @@ func cmdCounter(cmd *cobra.Command, args []string) error {
}
func cmdKVStore(cmd *cobra.Command, args []string) error {
logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger := log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
// Create the application - in memory or persisted to disk
var app types.Application

3
abci/tests/test_app/app.go
View File

@@ -4,7 +4,6 @@ import (
"bytes"
"context"
"fmt"
"os"
abcicli "github.com/tendermint/tendermint/abci/client"
"github.com/tendermint/tendermint/abci/types"
@@ -19,7 +18,7 @@ func startClient(abciType string) abcicli.Client {
if err != nil {
panic(err.Error())
}
logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger := log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
client.SetLogger(logger.With("module", "abcicli"))
if err := client.Start(); err != nil {
panicf("connecting to abci_app: %v", err.Error())

5
cmd/priv_val_server/main.go
View File

@@ -46,9 +46,8 @@ func main() {
rootCA = flag.String("rootcafile", "", "absolute path to root CA")
prometheusAddr = flag.String("prometheus-addr", "", "address for prometheus endpoint (host:port)")
logger = log.NewTMLogger(
log.NewSyncWriter(os.Stdout),
).With("module", "priv_val")
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false).
With("module", "priv_val")
)
flag.Parse()

4
cmd/tendermint/commands/debug/debug.go
View File

@@ -1,8 +1,6 @@
package debug
import (
"os"
"github.com/spf13/cobra"
"github.com/tendermint/tendermint/libs/log"
@@ -17,7 +15,7 @@ var (
flagProfAddr = "pprof-laddr"
flagFrequency = "frequency"
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
)
// DebugCmd defines the root command containing subcommands that assist in

17
cmd/tendermint/commands/light.go
View File

@@ -66,7 +66,8 @@ var (
trustedHash []byte
trustLevelStr string
verbose bool
logLevel string
logFormat string
primaryKey = []byte("primary")
witnessesKey = []byte("witnesses")
@@ -90,7 +91,8 @@ func init() {
"trusting period that headers can be verified within. Should be significantly less than the unbonding period")
LightCmd.Flags().Int64Var(&trustedHeight, "height", 1, "Trusted header's height")
LightCmd.Flags().BytesHexVar(&trustedHash, "hash", []byte{}, "Trusted header's hash")
LightCmd.Flags().BoolVar(&verbose, "verbose", false, "Verbose output")
LightCmd.Flags().StringVar(&logLevel, "log-level", log.LogLevelInfo, "The logging level (debug|info|warn|error|fatal)")
LightCmd.Flags().StringVar(&logFormat, "log-format", log.LogFormatPlain, "The logging format (text|json)")
LightCmd.Flags().StringVar(&trustLevelStr, "trust-level", "1/3",
"trust level. Must be between 1/3 and 3/3",
)
@@ -100,15 +102,10 @@ func init() {
}
func runProxy(cmd *cobra.Command, args []string) error {
// Initialize logger.
logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
var option log.Option
if verbose {
option, _ = log.AllowLevel("debug")
} else {
option, _ = log.AllowLevel("info")
logger, err := log.NewDefaultLogger(logFormat, logLevel, false)
if err != nil {
return err
}
logger = log.NewFilter(logger, option)
chainID = args[0]
logger.Info("Creating client...", "chainID", chainID)

15
cmd/tendermint/commands/root.go
View File

@@ -2,7 +2,6 @@ package commands
import (
"fmt"
"os"
"strings"
"time"
@@ -10,14 +9,12 @@ import (
"github.com/spf13/viper"
cfg "github.com/tendermint/tendermint/config"
"github.com/tendermint/tendermint/libs/cli"
tmflags "github.com/tendermint/tendermint/libs/cli/flags"
"github.com/tendermint/tendermint/libs/log"
)
var (
config = cfg.DefaultConfig()
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
ctxTimeout = 4 * time.Second
)
@@ -59,19 +56,11 @@ var RootCmd = &cobra.Command{
return err
}
if config.LogFormat == cfg.LogFormatJSON {
logger = log.NewTMJSONLogger(log.NewSyncWriter(os.Stdout))
}
logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel)
logger, err = log.NewDefaultLogger(config.LogFormat, config.LogLevel, false)
if err != nil {
return err
}
if viper.GetBool(cli.TraceFlag) {
logger = log.NewTracingLogger(logger)
}
logger = logger.With("module", "main")
return nil
},

8
cmd/tendermint/commands/root_test.go
View File

@@ -118,7 +118,7 @@ func TestRootFlagsEnv(t *testing.T) {
func TestRootConfig(t *testing.T) {
// write non-default config
nonDefaultLogLvl := "abc:debug"
nonDefaultLogLvl := "debug"
cvals := map[string]string{
"log-level": nonDefaultLogLvl,
}
@@ -129,9 +129,9 @@ func TestRootConfig(t *testing.T) {
logLvl string
}{
{nil, nil, nonDefaultLogLvl}, // should load config
{[]string{"--log-level=abc:info"}, nil, "abc:info"}, // flag over rides
{nil, map[string]string{"TM_LOG_LEVEL": "abc:info"}, "abc:info"}, // env over rides
{nil, nil, nonDefaultLogLvl}, // should load config
{[]string{"--log-level=info"}, nil, "info"}, // flag over rides
{nil, map[string]string{"TM_LOG_LEVEL": "info"}, "info"}, // env over rides
}
for i, tc := range cases {

16
config/config.go
View File

@@ -8,6 +8,8 @@ import (
"os"
"path/filepath"
"time"
"github.com/tendermint/tendermint/libs/log"
)
const (
@@ -16,11 +18,6 @@ const (
// FuzzModeDelay is a mode in which we randomly sleep
FuzzModeDelay
// LogFormatPlain is a format for colored text
LogFormatPlain = "plain"
// LogFormatJSON is a format for json output
LogFormatJSON = "json"
// DefaultLogLevel defines a default log level as INFO.
DefaultLogLevel = "info"
@@ -276,7 +273,7 @@ func DefaultBaseConfig() BaseConfig {
ProxyApp: "tcp://127.0.0.1:26658",
ABCI: "socket",
LogLevel: DefaultLogLevel,
LogFormat: LogFormatPlain,
LogFormat: log.LogFormatPlain,
FastSyncMode: true,
FilterPeers: false,
DBBackend: "goleveldb",
@@ -331,17 +328,20 @@ func (cfg Config) ArePrivValidatorClientSecurityOptionsPresent() bool {
// returns an error if any check fails.
func (cfg BaseConfig) ValidateBasic() error {
switch cfg.LogFormat {
case LogFormatPlain, LogFormatJSON:
case log.LogFormatJSON, log.LogFormatText, log.LogFormatPlain:
default:
return errors.New("unknown log format (must be 'plain' or 'json')")
return errors.New("unknown log format (must be 'plain', 'text' or 'json')")
}
switch cfg.Mode {
case ModeFull, ModeValidator, ModeSeed:
case "":
return errors.New("no mode has been set")
default:
return fmt.Errorf("unknown mode: %v", cfg.Mode)
}
return nil
}

10
consensus/common_test.go
View File

@@ -12,7 +12,6 @@ import (
"testing"
"time"
"github.com/go-kit/kit/log/term"
"github.com/stretchr/testify/require"
"path"
@@ -690,14 +689,7 @@ func ensureNewEventOnChannel(ch <-chan tmpubsub.Message) {
// consensusLogger is a TestingLogger which uses a different
// color for each validator ("validator" key must exist).
func consensusLogger() log.Logger {
return log.TestingLoggerWithColorFn(func(keyvals ...interface{}) term.FgBgColor {
for i := 0; i < len(keyvals)-1; i += 2 {
if keyvals[i] == "validator" {
return term.FgBgColor{Fg: term.Color(uint8(keyvals[i+1].(int) + 1))}
}
}
return term.FgBgColor{}
}).With("module", "consensus")
return log.TestingLogger().With("module", "consensus")
}
func randConsensusState(

1
go.mod
View File

@@ -31,6 +31,7 @@ require (
github.com/prometheus/client_golang v1.10.0
github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0
github.com/rs/cors v1.7.0
github.com/rs/zerolog v1.22.0
github.com/sasha-s/go-deadlock v0.2.1-0.20190427202633-1595213edefa
github.com/snikch/goodman v0.0.0-20171125024755-10e37e294daa
github.com/spf13/cobra v1.1.3

5
go.sum
View File

@@ -472,6 +472,9 @@ github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6L
github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
github.com/rs/cors v1.7.0 h1:+88SsELBHx5r+hZ8TCkggzSstaWNbDvThkVK8H6f9ik=
github.com/rs/cors v1.7.0/go.mod h1:gFx+x8UowdsKA9AchylcLynDq+nNFfI8FkUZdN/jGCU=
github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ=
github.com/rs/zerolog v1.22.0 h1:XrVUjV4K+izZpKXZHlPrYQiDtmdGiCylnT4i43AAWxg=
github.com/rs/zerolog v1.22.0/go.mod h1:ZPhntP/xmq1nnND05hhpAh2QMhSsA4UN3MGZ6O2J3hM=
github.com/russross/blackfriday v1.5.2/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g=
github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
@@ -695,6 +698,7 @@ golang.org/x/sys v0.0.0-20200625212154-ddb9806d33ae/go.mod h1:h1NjWce9XRLGQEsW7w
golang.org/x/sys v0.0.0-20200814200057-3d37ad5750ed/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20201015000850-e3ed0017c211/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210309074719-68d13333faf2 h1:46ULzRKLh1CwgRq2dC5SlBzEqqNCi8rreOZnNrbqcIY=
golang.org/x/sys v0.0.0-20210309074719-68d13333faf2/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
@@ -736,6 +740,7 @@ golang.org/x/tools v0.0.0-20200207183749-b753a1ba74fa/go.mod h1:TB2adYChydJhpapK
golang.org/x/tools v0.0.0-20200619180055-7c47624df98f/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE=
golang.org/x/tools v0.0.0-20201022035929-9cf592e881e9/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210106214847-113979e3529a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

89
libs/cli/flags/log_level.go
View File

@@ -1,89 +0,0 @@
package flags
import (
"errors"
"fmt"
"strings"
"github.com/tendermint/tendermint/libs/log"
)
const (
defaultLogLevelKey = "*"
)
// ParseLogLevel parses complex log level - comma-separated
// list of module:level pairs with an optional *:level pair (* means
// all other modules).
//
// Example:
// ParseLogLevel("consensus:debug,mempool:debug,*:error", log.NewTMLogger(os.Stdout), "info")
func ParseLogLevel(lvl string, logger log.Logger, defaultLogLevelValue string) (log.Logger, error) {
if lvl == "" {
return nil, errors.New("empty log level")
}
l := lvl
// prefix simple one word levels (e.g. "info") with "*"
if !strings.Contains(l, ":") {
l = defaultLogLevelKey + ":" + l
}
options := make([]log.Option, 0)
isDefaultLogLevelSet := false
var option log.Option
var err error
list := strings.Split(l, ",")
for _, item := range list {
moduleAndLevel := strings.Split(item, ":")
if len(moduleAndLevel) != 2 {
return nil, fmt.Errorf("expected list in a form of \"module:level\" pairs, given pair %s, list %s", item, list)
}
module := moduleAndLevel[0]
level := moduleAndLevel[1]
if module == defaultLogLevelKey {
option, err = log.AllowLevel(level)
if err != nil {
return nil, fmt.Errorf("failed to parse default log level (pair %s, list %s): %w", item, l, err)
}
options = append(options, option)
isDefaultLogLevelSet = true
} else {
switch level {
case "debug":
option = log.AllowDebugWith("module", module)
case "info":
option = log.AllowInfoWith("module", module)
case "error":
option = log.AllowErrorWith("module", module)
case "none":
option = log.AllowNoneWith("module", module)
default:
return nil,
fmt.Errorf("expected either \"info\", \"debug\", \"error\" or \"none\" log level, given %s (pair %s, list %s)",
level,
item,
list)
}
options = append(options, option)
}
}
// if "*" is not provided, set default global level
if !isDefaultLogLevelSet {
option, err = log.AllowLevel(defaultLogLevelValue)
if err != nil {
return nil, err
}
options = append(options, option)
}
return log.NewFilter(logger, options...), nil
}

94
libs/cli/flags/log_level_test.go
View File

@@ -1,94 +0,0 @@
package flags_test
import (
"bytes"
"strings"
"testing"
tmflags "github.com/tendermint/tendermint/libs/cli/flags"
"github.com/tendermint/tendermint/libs/log"
)
const (
defaultLogLevelValue = "info"
)
func TestParseLogLevel(t *testing.T) {
var buf bytes.Buffer
jsonLogger := log.NewTMJSONLoggerNoTS(&buf)
correctLogLevels := []struct {
lvl string
expectedLogLines []string
}{
{"mempool:error", []string{
``, // if no default is given, assume info
``,
`{"_msg":"Mesmero","level":"error","module":"mempool"}`,
`{"_msg":"Mind","level":"info","module":"state"}`, // if no default is given, assume info
``}},
{"mempool:error,*:debug", []string{
`{"_msg":"Kingpin","level":"debug","module":"wire"}`,
``,
`{"_msg":"Mesmero","level":"error","module":"mempool"}`,
`{"_msg":"Mind","level":"info","module":"state"}`,
`{"_msg":"Gideon","level":"debug"}`}},
{"*:debug,wire:none", []string{
``,
`{"_msg":"Kitty Pryde","level":"info","module":"mempool"}`,
`{"_msg":"Mesmero","level":"error","module":"mempool"}`,
`{"_msg":"Mind","level":"info","module":"state"}`,
`{"_msg":"Gideon","level":"debug"}`}},
}
for _, c := range correctLogLevels {
logger, err := tmflags.ParseLogLevel(c.lvl, jsonLogger, defaultLogLevelValue)
if err != nil {
t.Fatal(err)
}
buf.Reset()
logger.With("module", "mempool").With("module", "wire").Debug("Kingpin")
if have := strings.TrimSpace(buf.String()); c.expectedLogLines[0] != have {
t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[0], have, c.lvl)
}
buf.Reset()
logger.With("module", "mempool").Info("Kitty Pryde")
if have := strings.TrimSpace(buf.String()); c.expectedLogLines[1] != have {
t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[1], have, c.lvl)
}
buf.Reset()
logger.With("module", "mempool").Error("Mesmero")
if have := strings.TrimSpace(buf.String()); c.expectedLogLines[2] != have {
t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[2], have, c.lvl)
}
buf.Reset()
logger.With("module", "state").Info("Mind")
if have := strings.TrimSpace(buf.String()); c.expectedLogLines[3] != have {
t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[3], have, c.lvl)
}
buf.Reset()
logger.Debug("Gideon")
if have := strings.TrimSpace(buf.String()); c.expectedLogLines[4] != have {
t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[4], have, c.lvl)
}
}
incorrectLogLevel := []string{"some", "mempool:some", "*:some,mempool:error"}
for _, lvl := range incorrectLogLevel {
if _, err := tmflags.ParseLogLevel(lvl, jsonLogger, defaultLogLevelValue); err == nil {
t.Fatalf("Expected %s to produce error", lvl)
}
}
}

101
libs/log/default.go Normal file
View File

@@ -0,0 +1,101 @@
package log
import (
"fmt"
"io"
"os"
"strings"
"github.com/rs/zerolog"
)
var _ Logger = (*defaultLogger)(nil)
type defaultLogger struct {
zerolog.Logger
trace bool
}
// NewDefaultLogger returns a default logger that can be used within Tendermint
// and that fulfills the Logger interface. The underlying logging provider is a
// zerolog logger that supports typical log levels along with JSON and plain/text
// log formats.
//
// Since zerolog supports typed structured logging and it is difficult to reflect
// that in a generic interface, all logging methods accept a series of key/value
// pair tuples, where the key must be a string.
func NewDefaultLogger(format, level string, trace bool) (Logger, error) {
var logWriter io.Writer
switch strings.ToLower(format) {
case LogFormatPlain, LogFormatText:
logWriter = zerolog.ConsoleWriter{Out: os.Stderr}
case LogFormatJSON:
logWriter = os.Stderr
default:
return nil, fmt.Errorf("unsupported log format: %s", format)
}
logLevel, err := zerolog.ParseLevel(level)
if err != nil {
return nil, fmt.Errorf("failed to parse log level (%s): %w", level, err)
}
// make the writer thread-safe
logWriter = newSyncWriter(logWriter)
return defaultLogger{
Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger(),
trace: trace,
}, nil
}
// MustNewDefaultLogger delegates a call NewDefaultLogger where it panics on
// error.
func MustNewDefaultLogger(format, level string, trace bool) Logger {
logger, err := NewDefaultLogger(format, level, trace)
if err != nil {
panic(err)
}
return logger
}
func (l defaultLogger) Info(msg string, keyVals ...interface{}) {
l.Logger.Info().Fields(getLogFields(keyVals...)).Msg(msg)
}
func (l defaultLogger) Error(msg string, keyVals ...interface{}) {
e := l.Logger.Error()
if l.trace {
e = e.Stack()
}
e.Fields(getLogFields(keyVals...)).Msg(msg)
}
func (l defaultLogger) Debug(msg string, keyVals ...interface{}) {
l.Logger.Debug().Fields(getLogFields(keyVals...)).Msg(msg)
}
func (l defaultLogger) With(keyVals ...interface{}) Logger {
return defaultLogger{
Logger: l.Logger.With().Fields(getLogFields(keyVals...)).Logger(),
trace: l.trace,
}
}
func getLogFields(keyVals ...interface{}) map[string]interface{} {
if len(keyVals)%2 != 0 {
return nil
}
fields := make(map[string]interface{}, len(keyVals))
for i := 0; i < len(keyVals); i += 2 {
fields[fmt.Sprint(keyVals[i])] = keyVals[i+1]
}
return fields
}

48
libs/log/default_test.go Normal file
View File

@@ -0,0 +1,48 @@
package log_test
import (
"testing"
"github.com/stretchr/testify/require"
"github.com/tendermint/tendermint/libs/log"
)
func TestNewDefaultLogger(t *testing.T) {
testCases := map[string]struct {
format string
level string
expectErr bool
}{
"invalid format": {
format: "foo",
level: log.LogLevelInfo,
expectErr: true,
},
"invalid level": {
format: log.LogFormatJSON,
level: "foo",
expectErr: true,
},
"valid format and level": {
format: log.LogFormatJSON,
level: log.LogLevelInfo,
expectErr: false,
},
}
for name, tc := range testCases {
tc := tc
t.Run(name, func(t *testing.T) {
_, err := log.NewDefaultLogger(tc.format, tc.level, false)
if tc.expectErr {
require.Error(t, err)
require.Panics(t, func() {
_ = log.MustNewDefaultLogger(tc.format, tc.level, false)
})
} else {
require.NoError(t, err)
}
})
}
}

195
libs/log/filter.go
View File

@@ -1,195 +0,0 @@
package log
import "fmt"
type level byte
const (
levelDebug level = 1 << iota
levelInfo
levelError
)
type filter struct {
next Logger
allowed level // XOR'd levels for default case
initiallyAllowed level // XOR'd levels for initial case
allowedKeyvals map[keyval]level // When key-value match, use this level
}
type keyval struct {
key interface{}
value interface{}
}
// 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)
}
l.initiallyAllowed = l.allowed
return l
}
func (l *filter) Info(msg string, keyvals ...interface{}) {
levelAllowed := l.allowed&levelInfo != 0
if !levelAllowed {
return
}
l.next.Info(msg, keyvals...)
}
func (l *filter) Debug(msg string, keyvals ...interface{}) {
levelAllowed := l.allowed&levelDebug != 0
if !levelAllowed {
return
}
l.next.Debug(msg, keyvals...)
}
func (l *filter) Error(msg string, keyvals ...interface{}) {
levelAllowed := l.allowed&levelError != 0
if !levelAllowed {
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 {
keyInAllowedKeyvals := false
for i := len(keyvals) - 2; i >= 0; i -= 2 {
for kv, allowed := range l.allowedKeyvals {
if keyvals[i] == kv.key {
keyInAllowedKeyvals = true
// Example:
// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
// logger.With("module", "crypto")
if keyvals[i+1] == kv.value {
return &filter{
next: l.next.With(keyvals...),
allowed: allowed, // set the desired level
allowedKeyvals: l.allowedKeyvals,
initiallyAllowed: l.initiallyAllowed,
}
}
}
}
}
// Example:
// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
// logger.With("module", "main")
if keyInAllowedKeyvals {
return &filter{
next: l.next.With(keyvals...),
allowed: l.initiallyAllowed, // return back to initially allowed
allowedKeyvals: l.allowedKeyvals,
initiallyAllowed: l.initiallyAllowed,
}
}
return &filter{
next: l.next.With(keyvals...),
allowed: l.allowed, // simply continue with the current level
allowedKeyvals: l.allowedKeyvals,
initiallyAllowed: l.initiallyAllowed,
}
}
//--------------------------------------------------------------------------------
// Option sets a parameter for the filter.
type Option func(*filter)
// 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)
}
}
// 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 }
}
// 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 }
}

140
libs/log/filter_test.go
View File

@@ -1,140 +0,0 @@
package log_test
import (
"bytes"
"strings"
"testing"
"github.com/tendermint/tendermint/libs/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 {
tc := tc
t.Run(tc.name, func(t *testing.T) {
var buf bytes.Buffer
logger := log.NewFilter(log.NewTMJSONLoggerNoTS(&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 TestLevelContext(t *testing.T) {
var buf bytes.Buffer
logger := log.NewTMJSONLoggerNoTS(&buf)
logger = log.NewFilter(logger, log.AllowError())
logger = logger.With("context", "value")
logger.Error("foo", "bar", "baz")
want := `{"_msg":"foo","bar":"baz","context":"value","level":"error"}`
have := strings.TrimSpace(buf.String())
if 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
logger := log.NewTMJSONLoggerNoTS(&buf)
logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"))
logger1.With("context", "value").Info("foo", "bar", "baz")
want := `{"_msg":"foo","bar":"baz","context":"value","level":"info"}`
have := strings.TrimSpace(buf.String())
if 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")
want = `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`
have = strings.TrimSpace(buf.String())
if want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}

65
libs/log/logger.go
View File

@@ -2,29 +2,56 @@ package log
import (
"io"
kitlog "github.com/go-kit/kit/log"
"sync"
)
// Logger is what any Tendermint library should take.
const (
// LogFormatPlain defines a logging format used for human-readable text-based
// logging that is not structured. Typically, this format is used for development
// and testing purposes.
LogFormatPlain string = "plain"
// LogFormatText defines a logging format used for human-readable text-based
// logging that is not structured. Typically, this format is used for development
// and testing purposes.
LogFormatText string = "text"
// LogFormatJSON defines a logging format for structured JSON-based logging
// that is typically used in production environments, which can be sent to
// logging facilities that support complex log parsing and querying.
LogFormatJSON string = "json"
// Supported loging levels
LogLevelDebug = "debug"
LogLevelInfo = "info"
LogLevelWarn = "warn"
LogLevelError = "error"
)
// Logger defines a generic logging interface compatible with Tendermint.
type Logger interface {
Debug(msg string, keyvals ...interface{})
Info(msg string, keyvals ...interface{})
Error(msg string, keyvals ...interface{})
Debug(msg string, keyVals ...interface{})
Info(msg string, keyVals ...interface{})
Error(msg string, keyVals ...interface{})
With(keyvals ...interface{}) Logger
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)
// syncWriter wraps an io.Writer that can be used in a Logger that is safe for
// concurrent use by multiple goroutines.
type syncWriter struct {
sync.Mutex
io.Writer
}
func newSyncWriter(w io.Writer) io.Writer {
return &syncWriter{Writer: w}
}
// Write writes p to the underlying io.Writer. If another write is already in
// progress, the calling goroutine blocks until the syncWriter is available.
func (w *syncWriter) Write(p []byte) (int, error) {
w.Lock()
defer w.Unlock()
return w.Writer.Write(p)
}

12
libs/log/nop.go Normal file
View File

@@ -0,0 +1,12 @@
package log
import (
"github.com/rs/zerolog"
)
func NewNopLogger() Logger {
return defaultLogger{
Logger: zerolog.Nop(),
trace: false,
}
}

17
libs/log/nop_logger.go
View File

@@ -1,17 +0,0 @@
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{}) {}
func (nopLogger) Debug(string, ...interface{}) {}
func (nopLogger) Error(string, ...interface{}) {}
func (l *nopLogger) With(...interface{}) Logger {
return l
}

41
libs/log/testing.go Normal file
View File

@@ -0,0 +1,41 @@
package log
import (
"io"
"os"
"sync"
"testing"
)
var (
// reuse the same logger across all tests
testingLoggerMtx = sync.Mutex{}
testingLogger Logger
)
// TestingLogger returns a Logger which writes to STDOUT if test(s) are being
// run with the verbose (-v) flag, NopLogger otherwise.
//
// NOTE:
// - A call to NewTestingLogger() must be made inside a test (not in the init func)
// because verbose flag only set at the time of testing.
func TestingLogger() Logger {
return TestingLoggerWithOutput(os.Stdout)
}
func TestingLoggerWithOutput(w io.Writer) Logger {
testingLoggerMtx.Lock()
defer testingLoggerMtx.Unlock()
if testingLogger != nil {
return testingLogger
}
if testing.Verbose() {
testingLogger = MustNewDefaultLogger(LogFormatText, LogLevelDebug, true)
} else {
testingLogger = NewNopLogger()
}
return testingLogger
}

66
libs/log/testing_logger.go
View File

@@ -1,66 +0,0 @@
package log
import (
"io"
"os"
"sync"
"testing"
"github.com/go-kit/kit/log/term"
)
var (
// reuse the same logger across all tests
_testingLoggerMutex = sync.Mutex{}
_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 {
return TestingLoggerWithOutput(os.Stdout)
}
// TestingLoggerWOutput returns a TMLogger which writes to (w io.Writer) if testing being run
// with the verbose (-v) flag, NopLogger otherwise.
//
// Note that the call to TestingLoggerWithOutput(w io.Writer) must be made
// inside a test (not in the init func) because
// verbose flag only set at the time of testing.
func TestingLoggerWithOutput(w io.Writer) Logger {
_testingLoggerMutex.Lock()
defer _testingLoggerMutex.Unlock()
if _testingLogger != nil {
return _testingLogger
}
if testing.Verbose() {
_testingLogger = NewTMLogger(NewSyncWriter(w))
} 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 {
_testingLoggerMutex.Lock()
defer _testingLoggerMutex.Unlock()
if _testingLogger != nil {
return _testingLogger
}
if testing.Verbose() {
_testingLogger = NewTMLoggerWithColorFn(NewSyncWriter(os.Stdout), colorFn)
} else {
_testingLogger = NewNopLogger()
}
return _testingLogger
}

24
libs/log/tm_json_logger.go
View File

@@ -1,24 +0,0 @@
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 {
logger := kitlog.NewJSONLogger(w)
logger = kitlog.With(logger, "ts", kitlog.DefaultTimestampUTC)
return &tmLogger{logger}
}
// NewTMJSONLoggerNoTS is the same as NewTMJSONLogger, but without the
// timestamp.
func NewTMJSONLoggerNoTS(w io.Writer) Logger {
logger := kitlog.NewJSONLogger(w)
return &tmLogger{logger}
}

86
libs/log/tm_logger.go
View File

@@ -1,86 +0,0 @@
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)
// NewTMLogger 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 allows you to provide your own color function. See
// NewTMLogger for documentation.
func NewTMLoggerWithColorFn(w io.Writer, colorFn func(keyvals ...interface{}) term.FgBgColor) Logger {
return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)}
}
// Info logs a message at level Info.
func (l *tmLogger) Info(msg string, keyvals ...interface{}) {
lWithLevel := kitlevel.Info(l.srcLogger)
if err := kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...); err != nil {
errLogger := kitlevel.Error(l.srcLogger)
kitlog.With(errLogger, msgKey, msg).Log("err", err) //nolint:errcheck // no need to check error again
}
}
// Debug logs a message at level Debug.
func (l *tmLogger) Debug(msg string, keyvals ...interface{}) {
lWithLevel := kitlevel.Debug(l.srcLogger)
if err := kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...); err != nil {
errLogger := kitlevel.Error(l.srcLogger)
kitlog.With(errLogger, msgKey, msg).Log("err", err) //nolint:errcheck // no need to check error again
}
}
// Error logs a message at level Error.
func (l *tmLogger) Error(msg string, keyvals ...interface{}) {
lWithLevel := kitlevel.Error(l.srcLogger)
lWithMsg := kitlog.With(lWithLevel, msgKey, msg)
if err := lWithMsg.Log(keyvals...); err != nil {
lWithMsg.Log("err", err) //nolint:errcheck // no need to check error again
}
}
// 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...)}
}

112
libs/log/tm_logger_test.go
View File

@@ -1,112 +0,0 @@
package log_test
import (
"bytes"
"io/ioutil"
"strings"
"testing"
"github.com/tendermint/tendermint/libs/log"
)
func TestLoggerLogsItsErrors(t *testing.T) {
var buf bytes.Buffer
logger := log.NewTMLogger(&buf)
logger.Info("foo", "baz baz", "bar")
msg := strings.TrimSpace(buf.String())
if !strings.Contains(msg, "foo") {
t.Errorf("expected logger msg to contain ErrInvalidKey, got %s", msg)
}
}
func TestInfo(t *testing.T) {
var bufInfo bytes.Buffer
l := log.NewTMLogger(&bufInfo)
l.Info("Client initialized with old header (trusted is more recent)",
"old", 42,
"trustedHeight", "forty two",
"trustedHash", []byte("test me"))
msg := strings.TrimSpace(bufInfo.String())
// Remove the timestamp information to allow
// us to test against the expected message.
receivedmsg := strings.Split(msg, "] ")[1]
const expectedmsg = `Client initialized with old header
(trusted is more recent) old=42 trustedHeight="forty two"
trustedHash=74657374206D65`
if strings.EqualFold(receivedmsg, expectedmsg) {
t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
}
}
func TestDebug(t *testing.T) {
var bufDebug bytes.Buffer
ld := log.NewTMLogger(&bufDebug)
ld.Debug("Client initialized with old header (trusted is more recent)",
"old", 42,
"trustedHeight", "forty two",
"trustedHash", []byte("test me"))
msg := strings.TrimSpace(bufDebug.String())
// Remove the timestamp information to allow
// us to test against the expected message.
receivedmsg := strings.Split(msg, "] ")[1]
const expectedmsg = `Client initialized with old header
(trusted is more recent) old=42 trustedHeight="forty two"
trustedHash=74657374206D65`
if strings.EqualFold(receivedmsg, expectedmsg) {
t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
}
}
func TestError(t *testing.T) {
var bufErr bytes.Buffer
le := log.NewTMLogger(&bufErr)
le.Error("Client initialized with old header (trusted is more recent)",
"old", 42,
"trustedHeight", "forty two",
"trustedHash", []byte("test me"))
msg := strings.TrimSpace(bufErr.String())
// Remove the timestamp information to allow
// us to test against the expected message.
receivedmsg := strings.Split(msg, "] ")[1]
const expectedmsg = `Client initialized with old header
(trusted is more recent) old=42 trustedHeight="forty two"
trustedHash=74657374206D65`
if strings.EqualFold(receivedmsg, expectedmsg) {
t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
}
}
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") }
)

135
libs/log/tmfmt_logger.go
View File

@@ -1,135 +0,0 @@
package log
import (
"bytes"
"encoding/hex"
"fmt"
"io"
"strings"
"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. Note complex types (structs, maps, slices)
// formatted as "%+v".
//
// 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)
const unknown = "unknown"
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
switch keyvals[i] {
case kitlevel.Key():
excludeIndexes = append(excludeIndexes, i)
switch keyvals[i+1].(type) { // nolint:gocritic
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
case msgKey:
excludeIndexes = append(excludeIndexes, i)
msg = keyvals[i+1].(string)
// and module (could be multiple keyvals; if such case last keyvalue wins)
case moduleKey:
excludeIndexes = append(excludeIndexes, i)
module = keyvals[i+1].(string)
}
// Print []byte as a hexadecimal string (uppercased)
if b, ok := keyvals[i+1].([]byte); ok {
keyvals[i+1] = strings.ToUpper(hex.EncodeToString(b))
}
}
// Form a custom Tendermint line
//
// Example:
// D[2016-05-02|11:06:44.322] Stopping AddrBook (ignoring: already stopped)
//
// Description:
// D - first character of the level, uppercase (ASCII only)
// [2016-05-02|11:06:44.322] - our time format (see https://golang.org/src/time/format.go)
// Stopping ... - message
fmt.Fprintf(&enc.buf, "%c[%s] %-44s ", lvl[0]-32, time.Now().Format("2006-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
}
}
err := enc.EncodeKeyval(keyvals[i], keyvals[i+1])
if err == logfmt.ErrUnsupportedValueType {
enc.EncodeKeyval(keyvals[i], fmt.Sprintf("%+v", keyvals[i+1])) //nolint:errcheck // no need to check error again
} else if 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
}

126
libs/log/tmfmt_logger_test.go
View File

@@ -1,126 +0,0 @@
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/tendermint/libs/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()
if err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}); err != nil {
t.Fatal(err)
}
assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ std_map=map\[1:2\] my_map=special_behavior\n$`), buf.String())
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())
buf.Reset()
if err := logger.Log("hash", []byte("test me")); err != nil {
t.Fatal(err)
}
assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ hash=74657374206D65\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)
}
}
//nolint: errcheck // ignore errors
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" }

76
libs/log/tracing_logger.go
View File

@@ -1,76 +0,0 @@
package log
import (
"fmt"
"github.com/pkg/errors"
)
// NewTracingLogger enables tracing by wrapping all errors (if they
// implement stackTracer interface) in tracedError.
//
// All errors returned by https://github.com/pkg/errors implement stackTracer
// interface.
//
// For debugging purposes only as it doubles the amount of allocations.
func NewTracingLogger(next Logger) Logger {
return &tracingLogger{
next: next,
}
}
type stackTracer interface {
error
StackTrace() errors.StackTrace
}
type tracingLogger struct {
next Logger
}
func (l *tracingLogger) Info(msg string, keyvals ...interface{}) {
l.next.Info(msg, formatErrors(keyvals)...)
}
func (l *tracingLogger) Debug(msg string, keyvals ...interface{}) {
l.next.Debug(msg, formatErrors(keyvals)...)
}
func (l *tracingLogger) Error(msg string, keyvals ...interface{}) {
l.next.Error(msg, formatErrors(keyvals)...)
}
func (l *tracingLogger) With(keyvals ...interface{}) Logger {
return &tracingLogger{next: l.next.With(formatErrors(keyvals)...)}
}
func formatErrors(keyvals []interface{}) []interface{} {
newKeyvals := make([]interface{}, len(keyvals))
copy(newKeyvals, keyvals)
for i := 0; i < len(newKeyvals)-1; i += 2 {
if err, ok := newKeyvals[i+1].(stackTracer); ok {
newKeyvals[i+1] = tracedError{err}
}
}
return newKeyvals
}
// tracedError wraps a stackTracer and just makes the Error() result
// always return a full stack trace.
type tracedError struct {
wrapped stackTracer
}
var _ stackTracer = tracedError{}
func (t tracedError) StackTrace() errors.StackTrace {
return t.wrapped.StackTrace()
}
func (t tracedError) Cause() error {
return t.wrapped
}
func (t tracedError) Error() string {
return fmt.Sprintf("%+v", t.wrapped)
}

65
libs/log/tracing_logger_test.go
View File

@@ -1,65 +0,0 @@
package log_test
import (
"bytes"
stderr "errors"
"fmt"
"strings"
"testing"
"github.com/pkg/errors"
"github.com/tendermint/tendermint/libs/log"
)
func TestTracingLogger(t *testing.T) {
var buf bytes.Buffer
logger := log.NewTMJSONLoggerNoTS(&buf)
logger1 := log.NewTracingLogger(logger)
err1 := errors.New("courage is grace under pressure")
err2 := errors.New("it does not matter how slowly you go, so long as you do not stop")
logger1.With("err1", err1).Info("foo", "err2", err2)
want := strings.ReplaceAll(
strings.ReplaceAll(
`{"_msg":"foo","err1":"`+
fmt.Sprintf("%+v", err1)+
`","err2":"`+
fmt.Sprintf("%+v", err2)+
`","level":"info"}`,
"\t", "",
), "\n", "")
have := strings.ReplaceAll(strings.ReplaceAll(strings.TrimSpace(buf.String()), "\\n", ""), "\\t", "")
if want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
buf.Reset()
logger.With(
"err1", stderr.New("opportunities don't happen. You create them"),
).Info(
"foo", "err2", stderr.New("once you choose hope, anything's possible"),
)
want = `{"_msg":"foo",` +
`"err1":"opportunities don't happen. You create them",` +
`"err2":"once you choose hope, anything's possible",` +
`"level":"info"}`
have = strings.TrimSpace(buf.String())
if want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
buf.Reset()
logger.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz")
want = `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`
have = strings.TrimSpace(buf.String())
if want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}

27
libs/service/service.go
View File

@@ -133,22 +133,22 @@ func (bs *BaseService) SetLogger(l log.Logger) {
func (bs *BaseService) Start() error {
if atomic.CompareAndSwapUint32(&bs.started, 0, 1) {
if atomic.LoadUint32(&bs.stopped) == 1 {
bs.Logger.Error(fmt.Sprintf("Not starting %v service -- already stopped", bs.name),
"impl", bs.impl)
// revert flag
bs.Logger.Error("not starting service; already stopped", "service", bs.name, "impl", bs.impl.String())
atomic.StoreUint32(&bs.started, 0)
return ErrAlreadyStopped
}
bs.Logger.Info(fmt.Sprintf("Starting %v service", bs.name), "impl", bs.impl.String())
err := bs.impl.OnStart()
if err != nil {
bs.Logger.Info("starting service", "service", bs.name, "impl", bs.impl.String())
if err := bs.impl.OnStart(); err != nil {
// revert flag
atomic.StoreUint32(&bs.started, 0)
return err
}
return nil
}
bs.Logger.Debug(fmt.Sprintf("Not starting %v service -- already started", bs.name), "impl", bs.impl)
bs.Logger.Debug("not starting service; already started", "service", bs.name, "impl", bs.impl.String())
return ErrAlreadyStarted
}
@@ -162,18 +162,19 @@ func (bs *BaseService) OnStart() error { return nil }
func (bs *BaseService) Stop() error {
if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) {
if atomic.LoadUint32(&bs.started) == 0 {
bs.Logger.Error(fmt.Sprintf("Not stopping %v service -- has not been started yet", bs.name),
"impl", bs.impl)
// revert flag
bs.Logger.Error("not stopping service; not started yet", "service", bs.name, "impl", bs.impl.String())
atomic.StoreUint32(&bs.stopped, 0)
return ErrNotStarted
}
bs.Logger.Info(fmt.Sprintf("Stopping %v service", bs.name), "impl", bs.impl)
bs.Logger.Info("stopping service", "service", bs.name, "impl", bs.impl.String())
bs.impl.OnStop()
close(bs.quit)
return nil
}
bs.Logger.Debug(fmt.Sprintf("Stopping %v service (already stopped)", bs.name), "impl", bs.impl)
bs.Logger.Debug("not stopping service; already stopped", "service", bs.name, "impl", bs.impl.String())
return ErrAlreadyStopped
}
@@ -186,7 +187,7 @@ func (bs *BaseService) OnStop() {}
// will be returned if the service is running.
func (bs *BaseService) Reset() error {
if !atomic.CompareAndSwapUint32(&bs.stopped, 1, 0) {
bs.Logger.Debug(fmt.Sprintf("Can't reset %v service. Not stopped", bs.name), "impl", bs.impl)
bs.Logger.Debug("cannot reset service; not stopped", "service", bs.name, "impl", bs.impl.String())
return fmt.Errorf("can't reset running %s", bs.name)
}

16
rpc/jsonrpc/jsonrpc_test.go
View File

@@ -13,7 +13,6 @@ import (
"testing"
"time"
"github.com/go-kit/kit/log/term"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
@@ -91,22 +90,9 @@ func TestMain(m *testing.M) {
os.Exit(code)
}
var colorFn = func(keyvals ...interface{}) term.FgBgColor {
for i := 0; i < len(keyvals)-1; i += 2 {
if keyvals[i] == "socket" {
if keyvals[i+1] == "tcp" {
return term.FgBgColor{Fg: term.DarkBlue}
} else if keyvals[i+1] == "unix" {
return term.FgBgColor{Fg: term.DarkCyan}
}
}
}
return term.FgBgColor{}
}
// launch unix and tcp servers
func setup() {
logger := log.NewTMLoggerWithColorFn(log.NewSyncWriter(os.Stdout), colorFn)
logger := log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
cmd := exec.Command("rm", "-f", unixSocket)
err := cmd.Start()

4
rpc/jsonrpc/server/http_json_handler_test.go
View File

@@ -1,7 +1,6 @@
package server
import (
"bytes"
"encoding/json"
"io/ioutil"
"net/http"
@@ -22,8 +21,7 @@ func testMux() *http.ServeMux {
"block": NewRPCFunc(func(ctx *types.Context, h int) (string, error) { return "block", nil }, "height", true),
}
mux := http.NewServeMux()
buf := new(bytes.Buffer)
logger := log.NewTMLogger(buf)
logger := log.NewNopLogger()
RegisterRPCFuncs(mux, funcMap, logger)
return mux

3
rpc/jsonrpc/test/main.go
View File

@@ -3,7 +3,6 @@ package main
import (
"fmt"
"net/http"
"os"
"github.com/tendermint/tendermint/libs/log"
tmos "github.com/tendermint/tendermint/libs/os"
@@ -26,7 +25,7 @@ type Result struct {
func main() {
var (
mux = http.NewServeMux()
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
)
// Stop upon receiving SIGTERM or CTRL-C.

3
rpc/test/helpers.go
View File

@@ -113,8 +113,7 @@ func StartTendermint(ctx context.Context,
if nodeOpts.suppressStdout {
logger = log.NewNopLogger()
} else {
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.NewFilter(logger, log.AllowError())
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
}
papp := proxy.NewLocalClientCreator(app)
node, err := nm.New(conf, logger, papp, nil)

7
store/store_test.go
View File

@@ -1,7 +1,6 @@
package store
import (
"bytes"
"fmt"
"os"
"runtime/debug"
@@ -87,7 +86,7 @@ var (
func TestMain(m *testing.M) {
var cleanup cleanupFunc
state, _, cleanup = makeStateAndBlockStore(log.NewTMLogger(new(bytes.Buffer)))
state, _, cleanup = makeStateAndBlockStore(log.NewNopLogger())
block = makeBlock(1, state, new(types.Commit))
partSet = block.MakePartSet(2)
part1 = partSet.GetPart(0)
@@ -100,7 +99,7 @@ func TestMain(m *testing.M) {
// TODO: This test should be simplified ...
func TestBlockStoreSaveLoadBlock(t *testing.T) {
state, bs, cleanup := makeStateAndBlockStore(log.NewTMLogger(new(bytes.Buffer)))
state, bs, cleanup := makeStateAndBlockStore(log.NewNopLogger())
defer cleanup()
require.Equal(t, bs.Base(), int64(0), "initially the base should be zero")
require.Equal(t, bs.Height(), int64(0), "initially the height should be zero")
@@ -483,7 +482,7 @@ func TestLoadBlockMeta(t *testing.T) {
}
func TestBlockFetchAtHeight(t *testing.T) {
state, bs, cleanup := makeStateAndBlockStore(log.NewTMLogger(new(bytes.Buffer)))
state, bs, cleanup := makeStateAndBlockStore(log.NewNopLogger())
defer cleanup()
require.Equal(t, bs.Height(), int64(0), "initially the height should be zero")
block := makeBlock(bs.Height()+1, state, new(types.Commit))

3
test/e2e/app/app.go
View File

@@ -5,7 +5,6 @@ import (
"encoding/base64"
"errors"
"fmt"
"os"
"path/filepath"
"strconv"
@@ -39,7 +38,7 @@ func NewApplication(cfg *Config) (*Application, error) {
return nil, err
}
return &Application{
logger: log.NewTMLogger(log.NewSyncWriter(os.Stdout)),
logger: log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false),
state: state,
snapshots: snapshots,
cfg: cfg,

13
test/e2e/app/main.go
View File

@@ -17,7 +17,6 @@ import (
"github.com/tendermint/tendermint/abci/server"
"github.com/tendermint/tendermint/config"
"github.com/tendermint/tendermint/crypto/ed25519"
tmflags "github.com/tendermint/tendermint/libs/cli/flags"
"github.com/tendermint/tendermint/libs/log"
tmnet "github.com/tendermint/tendermint/libs/net"
"github.com/tendermint/tendermint/light"
@@ -34,7 +33,7 @@ import (
e2e "github.com/tendermint/tendermint/test/e2e/pkg"
)
var logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
var logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
// main is the binary entrypoint.
func main() {
@@ -287,18 +286,12 @@ func setupNode() (*config.Config, log.Logger, error) {
return nil, nil, fmt.Errorf("error in config file: %w", err)
}
if tmcfg.LogFormat == config.LogFormatJSON {
logger = log.NewTMJSONLogger(log.NewSyncWriter(os.Stdout))
}
nodeLogger, err := tmflags.ParseLogLevel(tmcfg.LogLevel, logger, config.DefaultLogLevel)
nodeLogger, err := log.NewDefaultLogger(tmcfg.LogFormat, tmcfg.LogLevel, false)
if err != nil {
return nil, nil, err
}
nodeLogger = nodeLogger.With("module", "main")
return tmcfg, nodeLogger, nil
return tmcfg, nodeLogger.With("module", "main"), nil
}
// rpcEndpoints takes a list of persistent peers and splits them into a list of rpc endpoints

2
test/e2e/generator/main.go
View File

@@ -17,7 +17,7 @@ const (
randomSeed int64 = 4827085738
)
var logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
var logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
func main() {
NewCLI().Run()

2
test/e2e/runner/main.go
View File

@@ -13,7 +13,7 @@ import (
)
var (
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
)
func main() {

3
test/fuzz/p2p/pex/reactor_receive.go
View File

@@ -2,7 +2,6 @@ package pex
import (
"net"
"os"
"github.com/tendermint/tendermint/config"
"github.com/tendermint/tendermint/crypto/ed25519"
@@ -16,7 +15,7 @@ import (
var (
pexR *pex.Reactor
peer p2p.Peer
logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
)
func init() {

3
test/fuzz/rpc/jsonrpc/server/handler.go
View File

@@ -6,7 +6,6 @@ import (
"io/ioutil"
"net/http"
"net/http/httptest"
"os"
"github.com/tendermint/tendermint/libs/log"
rs "github.com/tendermint/tendermint/rpc/jsonrpc/server"
@@ -20,7 +19,7 @@ var mux *http.ServeMux
func init() {
mux = http.NewServeMux()
lgr := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
lgr := log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
rs.RegisterRPCFuncs(mux, rpcFuncMap, lgr)
}

4
tools/tm-signer-harness/main.go
View File

@@ -25,7 +25,7 @@ const (
var defaultTMHome string
var logger = log.NewTMLogger(log.NewSyncWriter(os.Stdout))
var logger = log.MustNewDefaultLogger(log.LogFormatPlain, log.LogLevelInfo, false)
// Command line flags
var (
@@ -166,8 +166,6 @@ func main() {
os.Exit(0)
}
logger = log.NewFilter(logger, log.AllowInfo())
switch rootCmd.Arg(0) {
case "help":
switch rootCmd.Arg(1) {