Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Refactor Logging using Zerolog #8072

Merged
merged 14 commits into from
Dec 3, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 10 additions & 3 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -37,13 +37,21 @@ Ref: https://keepachangelog.com/en/1.0.0/
## [Unreleased]

### Improvements

* (logging) [\#8072](https://github.com/cosmos/cosmos-sdk/pull/8072) Refactor logging:
* Use [zerolog](https://github.com/rs/zerolog) over Tendermint's go-kit logging wrapper.
* Introduce Tendermint's `--log_format=plain|json` flag. Using format `json` allows for emitting structured JSON
logs which can be consumed by an external logging facility (e.g. Loggly). Both formats log to STDERR.
* The existing `--log_level` flag and it's default value now solely relates to the global logging
level (e.g. `info`, `debug`, etc...) instead of `<module>:<level>`.
* (crypto) [\#7987](https://github.com/cosmos/cosmos-sdk/pull/7987) Fix the inconsistency of CryptoCdc, only use `codec/legacy.Cdc`.
* (SDK) [\#7925](https://github.com/cosmos/cosmos-sdk/pull/7925) Updated dependencies to use gRPC v1.33.2
* Updated gRPC dependency to v1.33.2
* Updated iavl dependency to v0.15-rc2
* (version) [\#7848](https://github.com/cosmos/cosmos-sdk/pull/7848) [\#7941](https://github.com/cosmos/cosmos-sdk/pull/7941) `version --long` output now shows the list of build dependencies and replaced build dependencies.

### State Machine Breaking Changes

* (x/upgrade) [\#7979](https://github.com/cosmos/cosmos-sdk/pull/7979) keeper pubkey storage serialization migration from bech32 to protobuf.

### Bug Fixes
Expand All @@ -57,6 +65,7 @@ Ref: https://keepachangelog.com/en/1.0.0/
* (x/staking) [\#7419](https://github.com/cosmos/cosmos-sdk/pull/7419) The `TmConsPubKey` method on ValidatorI has been removed and replaced instead by `ConsPubKey` (which returns a SDK `cryptotypes.PubKey`) and `TmConsPublicKey` (which returns a Tendermint proto PublicKey).

### Improvements

* (tendermint) [\#7828](https://github.com/cosmos/cosmos-sdk/pull/7828) Update tendermint dependency to v0.34.0-rc6

## [v0.40.0-rc2](https://github.com/cosmos/cosmos-sdk/releases/tag/v0.40.0-rc2) - 2020-11-02
Expand Down Expand Up @@ -89,18 +98,16 @@ Ref: https://keepachangelog.com/en/1.0.0/
* __Modules__
* `x/crisis` has a new function: `AddModuleInitFlags`, which will register optional crisis module flags for the start command.


### Bug Fixes

* (client) [\#7699](https://github.com/cosmos/cosmos-sdk/pull/7699) Fix panic in context when setting invalid nodeURI. `WithNodeURI` does not set the `Client` in the context.
* (x/gov) [#7641](https://github.com/cosmos/cosmos-sdk/pull/7641) Fix tally calculation precision error.

### Improvements
### Improvements

* (rest) [#7649](https://github.com/cosmos/cosmos-sdk/pull/7649) Return an unsigned tx in legacy GET /tx endpoint when signature conversion fails
* (cli) [#7764](https://github.com/cosmos/cosmos-sdk/pull/7764) Update x/banking and x/crisis InitChain to improve node startup time


## [v0.40.0-rc1](https://github.com/cosmos/cosmos-sdk/releases/tag/v0.40.0-rc1) - 2020-10-19

### Client Breaking Changes
Expand Down
63 changes: 44 additions & 19 deletions baseapp/abci.go
Original file line number Diff line number Diff line change
Expand Up @@ -291,7 +291,7 @@ func (app *BaseApp) Commit() (res abci.ResponseCommit) {
// MultiStore (app.cms) so when Commit() is called is persists those values.
app.deliverState.ms.Write()
commitID := app.cms.Commit()
app.logger.Debug("Commit synced", "commit", fmt.Sprintf("%X", commitID))
app.logger.Info("commit synced", "commit", fmt.Sprintf("%X", commitID))

// Reset the Check state to the latest committed.
//
Expand Down Expand Up @@ -358,22 +358,27 @@ func (app *BaseApp) snapshot(height int64) {
app.logger.Info("snapshot manager not configured")
return
}
app.logger.Info("Creating state snapshot", "height", height)

app.logger.Info("creating state snapshot", "height", height)

snapshot, err := app.snapshotManager.Create(uint64(height))
if err != nil {
app.logger.Error("Failed to create state snapshot", "height", height, "err", err)
app.logger.Error("failed to create state snapshot", "height", height, "err", err)
return
}
app.logger.Info("Completed state snapshot", "height", height, "format", snapshot.Format)

app.logger.Info("completed state snapshot", "height", height, "format", snapshot.Format)

if app.snapshotKeepRecent > 0 {
app.logger.Debug("Pruning state snapshots")
app.logger.Debug("pruning state snapshots")

pruned, err := app.snapshotManager.Prune(app.snapshotKeepRecent)
if err != nil {
app.logger.Error("Failed to prune state snapshots", "err", err)
return
}
app.logger.Debug("Pruned state snapshots", "pruned", pruned)

app.logger.Debug("pruned state snapshots", "pruned", pruned)
}
}

Expand Down Expand Up @@ -433,13 +438,14 @@ func (app *BaseApp) ListSnapshots(req abci.RequestListSnapshots) abci.ResponseLi

snapshots, err := app.snapshotManager.List()
if err != nil {
app.logger.Error("Failed to list snapshots", "err", err)
app.logger.Error("failed to list snapshots", "err", err)
return resp
}

for _, snapshot := range snapshots {
abciSnapshot, err := snapshot.ToABCI()
if err != nil {
app.logger.Error("Failed to list snapshots", "err", err)
app.logger.Error("failed to list snapshots", "err", err)
return resp
}
resp.Snapshots = append(resp.Snapshots, &abciSnapshot)
Expand All @@ -455,8 +461,13 @@ func (app *BaseApp) LoadSnapshotChunk(req abci.RequestLoadSnapshotChunk) abci.Re
}
chunk, err := app.snapshotManager.LoadChunk(req.Height, req.Format, req.Chunk)
if err != nil {
app.logger.Error("Failed to load snapshot chunk", "height", req.Height, "format", req.Format,
"chunk", req.Chunk, "err")
app.logger.Error(
"failed to load snapshot chunk",
"height", req.Height,
"format", req.Format,
"chunk", req.Chunk,
"err", err,
)
return abci.ResponseLoadSnapshotChunk{}
}
return abci.ResponseLoadSnapshotChunk{Chunk: chunk}
Expand All @@ -470,15 +481,16 @@ func (app *BaseApp) OfferSnapshot(req abci.RequestOfferSnapshot) abci.ResponseOf
}

if req.Snapshot == nil {
app.logger.Error("Received nil snapshot")
app.logger.Error("received nil snapshot")
return abci.ResponseOfferSnapshot{Result: abci.ResponseOfferSnapshot_REJECT}
}

snapshot, err := snapshottypes.SnapshotFromABCI(req.Snapshot)
if err != nil {
app.logger.Error("Failed to decode snapshot metadata", "err", err)
app.logger.Error("failed to decode snapshot metadata", "err", err)
return abci.ResponseOfferSnapshot{Result: abci.ResponseOfferSnapshot_REJECT}
}

err = app.snapshotManager.Restore(snapshot)
switch {
case err == nil:
Expand All @@ -488,13 +500,22 @@ func (app *BaseApp) OfferSnapshot(req abci.RequestOfferSnapshot) abci.ResponseOf
return abci.ResponseOfferSnapshot{Result: abci.ResponseOfferSnapshot_REJECT_FORMAT}

case errors.Is(err, snapshottypes.ErrInvalidMetadata):
app.logger.Error("Rejecting invalid snapshot", "height", req.Snapshot.Height,
"format", req.Snapshot.Format, "err", err)
app.logger.Error(
"rejecting invalid snapshot",
"height", req.Snapshot.Height,
"format", req.Snapshot.Format,
"err", err,
)
return abci.ResponseOfferSnapshot{Result: abci.ResponseOfferSnapshot_REJECT}

default:
app.logger.Error("Failed to restore snapshot", "height", req.Snapshot.Height,
"format", req.Snapshot.Format, "err", err)
app.logger.Error(
"failed to restore snapshot",
"height", req.Snapshot.Height,
"format", req.Snapshot.Format,
"err", err,
)

// We currently don't support resetting the IAVL stores and retrying a different snapshot,
// so we ask Tendermint to abort all snapshot restoration.
return abci.ResponseOfferSnapshot{Result: abci.ResponseOfferSnapshot_ABORT}
Expand All @@ -514,16 +535,20 @@ func (app *BaseApp) ApplySnapshotChunk(req abci.RequestApplySnapshotChunk) abci.
return abci.ResponseApplySnapshotChunk{Result: abci.ResponseApplySnapshotChunk_ACCEPT}

case errors.Is(err, snapshottypes.ErrChunkHashMismatch):
app.logger.Error("Chunk checksum mismatch, rejecting sender and requesting refetch",
"chunk", req.Index, "sender", req.Sender, "err", err)
app.logger.Error(
"chunk checksum mismatch; rejecting sender and requesting refetch",
"chunk", req.Index,
"sender", req.Sender,
"err", err,
)
return abci.ResponseApplySnapshotChunk{
Result: abci.ResponseApplySnapshotChunk_RETRY,
RefetchChunks: []uint32{req.Index},
RejectSenders: []string{req.Sender},
}

default:
app.logger.Error("Failed to restore snapshot", "err", err)
app.logger.Error("failed to restore snapshot", "err", err)
return abci.ResponseApplySnapshotChunk{Result: abci.ResponseApplySnapshotChunk_ABORT}
}
}
Expand Down
4 changes: 4 additions & 0 deletions client/flags/flags.go
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,10 @@ const (
FlagCountTotal = "count-total"
FlagTimeoutHeight = "timeout-height"
FlagKeyAlgorithm = "algo"

// Tendermint logging flags
FlagLogLevel = "log_level"
FlagLogFormat = "log_format"
)

// LineBreak can be included in a command list to provide a blank line
Expand Down
2 changes: 1 addition & 1 deletion contrib/images/simd-env/Dockerfile
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ VOLUME [ /simd ]
WORKDIR /simd
EXPOSE 26656 26657
ENTRYPOINT ["/usr/bin/wrapper.sh"]
CMD ["start"]
CMD ["start", "--log_format", "plain"]
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For local networks that are used for testing, human readable/friendly logs are preferable.

STOPSIGNAL SIGTERM

COPY wrapper.sh /usr/bin/wrapper.sh
1 change: 1 addition & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ require (
github.com/prometheus/common v0.15.0
github.com/rakyll/statik v0.1.7
github.com/regen-network/cosmos-proto v0.3.0
github.com/rs/zerolog v1.20.0
github.com/spf13/afero v1.2.2 // indirect
github.com/spf13/cast v1.3.1
github.com/spf13/cobra v1.1.1
Expand Down
4 changes: 4 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -481,6 +481,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.20.0 h1:38k9hgtUBdxFwE34yS8rTHmHBa4eN16E4DJlv177LNs=
github.com/rs/zerolog v1.20.0/go.mod h1:IzD0RJ65iWH0w97OQQebJEvTZYvsCUm9WVLWBQrJRjo=
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=
Expand Down Expand Up @@ -726,6 +729,7 @@ golang.org/x/tools v0.0.0-20190606124116-d0a3d012864b/go.mod h1:/rFqwRUd4F7ZHNgw
golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
golang.org/x/tools v0.0.0-20190628153133-6cdbf07be9d0/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
golang.org/x/tools v0.0.0-20190816200558-6889da9d5479/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.0.0-20190828213141-aed303cbaa74/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.0.0-20190911174233-4f2ddba30aff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
Expand Down
55 changes: 55 additions & 0 deletions server/logger.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,55 @@
package server
alessio marked this conversation as resolved.
Show resolved Hide resolved

import (
"github.com/rs/zerolog"
tmlog "github.com/tendermint/tendermint/libs/log"
)

var _ tmlog.Logger = (*ZeroLogWrapper)(nil)

// ZeroLogWrapper provides a wrapper around a zerolog.Logger instance. It implements
// Tendermint's Logger interface.
type ZeroLogWrapper struct {
zerolog.Logger
}

// Info implements Tendermint's Logger interface and logs with level INFO. A set
// of key/value tuples may be provided to add context to the log. The number of
// tuples must be even and the key of the tuple must be a string.
func (z ZeroLogWrapper) Info(msg string, keyVals ...interface{}) {
z.Logger.Info().Fields(getLogFields(keyVals...)).Msg(msg)
}

// Error implements Tendermint's Logger interface and logs with level ERR. A set
// of key/value tuples may be provided to add context to the log. The number of
// tuples must be even and the key of the tuple must be a string.
func (z ZeroLogWrapper) Error(msg string, keyVals ...interface{}) {
z.Logger.Error().Fields(getLogFields(keyVals...)).Msg(msg)
}

// Debug implements Tendermint's Logger interface and logs with level DEBUG. A set
// of key/value tuples may be provided to add context to the log. The number of
// tuples must be even and the key of the tuple must be a string.
func (z ZeroLogWrapper) Debug(msg string, keyVals ...interface{}) {
z.Logger.Debug().Fields(getLogFields(keyVals...)).Msg(msg)
}

// With returns a new wrapped logger with additional context provided by a set
// of key/value tuples. The number of tuples must be even and the key of the
// tuple must be a string.
func (z ZeroLogWrapper) With(keyVals ...interface{}) tmlog.Logger {
return ZeroLogWrapper{z.Logger.With().Fields(getLogFields(keyVals...)).Logger()}
}

func getLogFields(keyVals ...interface{}) map[string]interface{} {
if len(keyVals)%2 != 0 {
return nil
}

fields := make(map[string]interface{})
for i := 0; i < len(keyVals); i += 2 {
fields[keyVals[i].(string)] = keyVals[i+1]
}

return fields
}
6 changes: 3 additions & 3 deletions server/start.go
Original file line number Diff line number Diff line change
Expand Up @@ -240,17 +240,17 @@ func startInProcess(ctx *Context, clientCtx client.Context, appCreator types.App
genDocProvider,
node.DefaultDBProvider,
node.DefaultMetricsProvider(cfg.Instrumentation),
ctx.Logger.With("module", "node"),
ctx.Logger,
)
if err != nil {
return err
}
ctx.Logger.Debug("Initialization: tmNode created")

ctx.Logger.Debug("initialization: tmNode created")
if err := tmNode.Start(); err != nil {
return err
}
ctx.Logger.Debug("Initialization: tmNode started")
ctx.Logger.Debug("initialization: tmNode started")

config := config.GetConfig(ctx.Viper)

Expand Down
Loading