diff --git a/.github/dependabot.yml b/.github/dependabot.yml index 23e73e745..cdd714771 100644 --- a/.github/dependabot.yml +++ b/.github/dependabot.yml @@ -4,7 +4,6 @@ updates: directory: "/" schedule: interval: weekly - day: monday target-branch: "master" open-pull-requests-limit: 10 labels: @@ -15,7 +14,6 @@ updates: directory: "/" schedule: interval: weekly - day: monday target-branch: "v0.34.x" open-pull-requests-limit: 10 labels: @@ -26,7 +24,6 @@ updates: directory: "/" schedule: interval: weekly - day: monday target-branch: "v0.35.x" open-pull-requests-limit: 10 labels: @@ -37,7 +34,6 @@ updates: directory: "/" schedule: interval: weekly - day: monday target-branch: "v0.36.x" open-pull-requests-limit: 10 labels: @@ -48,7 +44,6 @@ updates: directory: "/docs" schedule: interval: weekly - day: monday open-pull-requests-limit: 10 ################################### @@ -58,7 +53,7 @@ updates: - package-ecosystem: gomod directory: "/" schedule: - interval: daily + interval: weekly target-branch: "master" open-pull-requests-limit: 10 labels: @@ -68,7 +63,7 @@ updates: - package-ecosystem: gomod directory: "/" schedule: - interval: daily + interval: weekly target-branch: "v0.34.x" open-pull-requests-limit: 10 labels: @@ -78,7 +73,7 @@ updates: - package-ecosystem: gomod directory: "/" schedule: - interval: daily + interval: weekly target-branch: "v0.35.x" open-pull-requests-limit: 10 labels: @@ -88,7 +83,7 @@ updates: - package-ecosystem: gomod directory: "/" schedule: - interval: daily + interval: weekly target-branch: "v0.36.x" open-pull-requests-limit: 10 labels: diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index 0a006f9b9..73f682089 100644 --- a/.github/workflows/docker.yml +++ b/.github/workflows/docker.yml @@ -49,7 +49,7 @@ jobs: password: ${{ secrets.DOCKERHUB_TOKEN }} - name: Publish to Docker Hub - uses: docker/build-push-action@v3.0.0 + uses: docker/build-push-action@v3.1.0 with: context: . file: ./DOCKER/Dockerfile diff --git a/RELEASES.md b/RELEASES.md index f3bfd20d5..803fc0d95 100644 --- a/RELEASES.md +++ b/RELEASES.md @@ -1,8 +1,9 @@ # Releases -Tendermint uses [semantic versioning](https://semver.org/) with each release following -a `vX.Y.Z` format. The `master` branch is used for active development and thus it's -advisable not to build against it. +Tendermint uses modified [semantic versioning](https://semver.org/) with each +release following a `vX.Y.Z` format. Tendermint is currently on major version +0 and uses the minor version to signal breaking changes. The `master` branch is +used for active development and thus it is not advisable to build against it. The latest changes are always initially merged into `master`. Releases are specified using tags and are built from long-lived "backport" branches @@ -29,8 +30,8 @@ merging the pull request. ### Creating a backport branch -If this is the first release candidate for a major release, you get to have the -honor of creating the backport branch! +If this is the first release candidate for a minor version release, e.g. +v0.25.0, you get to have the honor of creating the backport branch! Note that, after creating the backport branch, you'll also need to update the tags on `master` so that `go mod` is able to order the branches correctly. You @@ -77,7 +78,8 @@ the 0.35.x line. After doing these steps, go back to `master` and do the following: -1. Tag `master` as the dev branch for the _next_ major release and push it up to GitHub. +1. Tag `master` as the dev branch for the _next_ minor version release and push + it up to GitHub. For example: ```sh git tag -a v0.36.0-dev -m "Development base for Tendermint v0.36." @@ -99,7 +101,7 @@ After doing these steps, go back to `master` and do the following: ## Release candidates -Before creating an official release, especially a major release, we may want to create a +Before creating an official release, especially a minor release, we may want to create a release candidate (RC) for our friends and partners to test out. We use git tags to create RCs, and we build them off of backport branches. @@ -109,7 +111,7 @@ Tags for RCs should follow the "standard" release naming conventions, with `-rcX (Note that branches and tags _cannot_ have the same names, so it's important that these branches have distinct names from the tags/release names.) -If this is the first RC for a major release, you'll have to make a new backport branch (see above). +If this is the first RC for a minor release, you'll have to make a new backport branch (see above). Otherwise: 1. Start from the backport branch (e.g. `v0.35.x`). @@ -140,11 +142,13 @@ Note that this process should only be used for "true" RCs-- release candidates that, if successful, will be the next release. For more experimental "RCs," create a new, short-lived branch and tag that instead. -## Major release +## Minor release -This major release process assumes that this release was preceded by release candidates. +This minor release process assumes that this release was preceded by release candidates. If there were no release candidates, begin by creating a backport branch, as described above. +Before performing these steps, be sure the [Minor Release Checklist](#minor-release-checklist) has been completed. + 1. Start on the backport branch (e.g. `v0.35.x`) 2. Run integration tests (`make test_integrations`) and the e2e nightlies. 3. Prepare the release: @@ -176,16 +180,16 @@ If there were no release candidates, begin by creating a backport branch, as des - Commit these changes to `master` and backport them into the backport branch for this release. -## Minor release (point releases) +## Patch release -Minor releases are done differently from major releases: They are built off of +Patch releases are done differently from minor releases: They are built off of long-lived backport branches, rather than from master. As non-breaking changes land on `master`, they should also be backported into these backport branches. -Minor releases don't have release candidates by default, although any tricky +Patch releases don't have release candidates by default, although any tricky changes may merit a release candidate. -To create a minor release: +To create a patch release: 1. Checkout the long-lived backport branch: `git checkout v0.35.x` 2. Run integration tests (`make test_integrations`) and the nightlies. @@ -197,11 +201,143 @@ To create a minor release: - Bump the TMDefaultVersion in `version.go` - Bump the ABCI version number, if necessary. (Note that ABCI follows semver, and that ABCI versions are the only versions - which can change during minor releases, and only field additions are valid minor changes.) + which can change during patch releases, and only field additions are valid patch changes.) 4. Open a PR with these changes that will land them back on `v0.35.x` 5. Once this change has landed on the backport branch, make sure to pull it locally, then push a tag. - `git tag -a v0.35.1 -m 'Release v0.35.1'` - `git push origin v0.35.1` 6. Create a pull request back to master with the CHANGELOG & version changes from the latest release. - - Remove all `R:minor` labels from the pull requests that were included in the release. + - Remove all `R:patch` labels from the pull requests that were included in the release. - Do not merge the backport branch into master. + +## Minor Release Checklist + +The following set of steps are performed on all releases that increment the +_minor_ version, e.g. v0.25 to v0.26. These steps ensure that Tendermint is +well tested, stable, and suitable for adoption by the various diverse projects +that rely on Tendermint. + +### Feature Freeze + +Ahead of any minor version release of Tendermint, the software enters 'Feature +Freeze' for at least two weeks. A feature freeze means that _no_ new features +are added to the code being prepared for release. No code changes should be made +to the code being released that do not directly improve pressing issues of code +quality. The following must not be merged during a feature freeze: + +* Refactors that are not related to specific bug fixes. +* Dependency upgrades. +* New test code that does not test a discovered regression. +* New features of any kind. +* Documentation or spec improvements that are not related to the newly developed +code. + +This period directly follows the creation of the [backport +branch](#creating-a-backport-branch). The Tendermint team instead directs all +attention to ensuring that the existing code is stable and reliable. Broken +tests are fixed, flakey-tests are remedied, end-to-end test failures are +thoroughly diagnosed and all efforts of the team are aimed at improving the +quality of the code. During this period, the upgrade harness tests are run +repeatedly and a variety of in-house testnets are run to ensure Tendermint +functions at the scale it will be used by application developers and node +operators. + +### Nightly End-To-End Tests + +The Tendermint team maintains [a set of end-to-end +tests](https://github.com/tendermint/tendermint/blob/master/test/e2e/README.md#L1) +that run each night on the latest commit of the project and on the code in the +tip of each supported backport branch. These tests start a network of containerized +Tendermint processes and run automated checks that the network functions as +expected in both stable and unstable conditions. During the feature freeze, +these tests are run nightly and must pass consistently for a release of +Tendermint to be considered stable. + +### Upgrade Harness + +> TODO(williambanfield): Change to past tense and clarify this section once +> upgrade harness is complete. + +The Tendermint team is creating an upgrade test harness to exercise the +workflow of stopping an instance of Tendermint running one version of the +software and starting up the same application running the next version. To +support upgrade testing, we will add the ability to terminate the Tendermint +process at specific pre-defined points in its execution so that we can verify +upgrades work in a representative sample of stop conditions. + +### Large Scale Testnets + +The Tendermint end-to-end tests run a small network (~10s of nodes) to exercise +basic consensus interactions. Real world deployments of Tendermint often have over +a hundred nodes just in the validator set, with many others acting as full +nodes and sentry nodes. To gain more assurance before a release, we will also run +larger-scale test networks to shake out emergent behaviors at scale. + +Large-scale test networks are run on a set of virtual machines (VMs). Each VM +is equipped with 4 Gigabytes of RAM and 2 CPU cores. The network runs a very +simple key-value store application. The application adds artificial delays to +different ABCI calls to simulate a slow application. Each testnet is briefly +run with no load being generated to collect a baseline performance. Once +baseline is captured, a consistent load is applied across the network. This +load takes the form of 10% of the running nodes all receiving a consistent +stream of two hundred transactions per minute each. + +During each test net, the following metrics are monitored and collected on each +node: + +* Consensus rounds per height +* Maximum connected peers, Minimum connected peers, Rate of change of peer connections +* Memory resident set size +* CPU utilization +* Blocks produced per minute +* Seconds for each step of consensus (Propose, Prevote, Precommit, Commit) +* Latency to receive block proposals + +For these tests we intentionally target low-powered host machines (with low core +counts and limited memory) to ensure we observe similar kinds of resource contention +and limitation that real-world deployments of Tendermint experience in production. + +#### 200 Node Testnet + +To test the stability and performance of Tendermint in a real world scenario, +a 200 node test network is run. The network comprises 5 seed nodes, 100 +validators and 95 non-validating full nodes. All nodes begin by dialing +a subset of the seed nodes to discover peers. The network is run for several +days, with metrics being collected continuously. In cases of changes to performance +critical systems, testnets of larger sizes should be considered. + +#### Rotating Node Testnet + +Real-world deployments of Tendermint frequently see new nodes arrive and old +nodes exit the network. The rotating node testnet ensures that Tendermint is +able to handle this reliably. In this test, a network with 10 validators and +3 seed nodes is started. A rolling set of 25 full nodes are started and each +connects to the network by dialing one of the seed nodes. Once the node is able +to blocksync to the head of the chain and begins producing blocks using +Tendermint consensus it is stopped. Once stopped, a new node is started and +takes its place. This network is run for several days. + +#### Network Partition Testnet + +Tendermint is expected to recover from network partitions. A partition where no +subset of the nodes is left with the super-majority of the stake is expected to +stop making blocks. Upon alleviation of the partition, the network is expected +to once again become fully connected and capable of producing blocks. The +network partition testnet ensures that Tendermint is able to handle this +reliably at scale. In this test, a network with 100 validators and 95 full +nodes is started. All validators have equal stake. Once the network is +producing blocks, a set of firewall rules is deployed to create a partitioned +network with 50% of the stake on one side and 50% on the other. Once the +network stops producing blocks, the firewall rules are removed and the nodes +are monitored to ensure they reconnect and that the network again begins +producing blocks. + +#### Absent Stake Testnet + +Tendermint networks often run with _some_ portion of the voting power offline. +The absent stake testnet ensures that large networks are able to handle this +reliably. A set of 150 validator nodes and three seed nodes is started. The set +of 150 validators is configured to only possess a cumulative stake of 67% of +the total stake. The remaining 33% of the stake is configured to belong to +a validator that is never actually run in the test network. The network is run +for multiple days, ensuring that it is able to produce blocks without issue. diff --git a/abci/client/grpc_client.go b/abci/client/grpc_client.go index 1e163056d..bd255bebe 100644 --- a/abci/client/grpc_client.go +++ b/abci/client/grpc_client.go @@ -3,7 +3,6 @@ package abciclient import ( "context" "errors" - "fmt" "net" "sync" "time" @@ -65,7 +64,7 @@ RETRY_LOOP: if cli.mustConnect { return err } - cli.logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err) + cli.logger.Error("abci.grpcClient failed to connect, Retrying...", "addr", cli.addr, "err", err) timer.Reset(time.Second * dialRetryIntervalSeconds) select { case <-ctx.Done(): diff --git a/abci/client/socket_client.go b/abci/client/socket_client.go index 7dfcf76cc..d023e7074 100644 --- a/abci/client/socket_client.go +++ b/abci/client/socket_client.go @@ -67,8 +67,11 @@ func (cli *socketClient) OnStart(ctx context.Context) error { if cli.mustConnect { return err } - cli.logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...", - cli.addr, dialRetryIntervalSeconds), "err", err) + + cli.logger.Error("abci.socketClient failed to connect, retrying after", + "retry_after", dialRetryIntervalSeconds, + "target", cli.addr, + "err", err) timer.Reset(time.Second * dialRetryIntervalSeconds) select { @@ -77,7 +80,6 @@ func (cli *socketClient) OnStart(ctx context.Context) error { case <-timer.C: continue } - } cli.conn = conn diff --git a/docs/tutorials/go-built-in.md b/docs/tutorials/go-built-in.md index 456024ebf..35f0cbca9 100644 --- a/docs/tutorials/go-built-in.md +++ b/docs/tutorials/go-built-in.md @@ -23,8 +23,6 @@ yourself with the syntax. By following along with this guide, you'll create a Tendermint Core project called kvstore, a (very) simple distributed BFT key-value store. -> Note: please use a released version of Tendermint with this guide. The guides will work with the latest version. Please, do not use master. - ## Built-in app vs external app Running your application inside the same process as Tendermint Core will give @@ -36,28 +34,27 @@ through a TCP, Unix domain socket or gRPC. ## 1.1 Installing Go Please refer to [the official guide for installing -Go](https://golang.org/doc/install). +Go](https://go.dev/doc/install). Verify that you have the latest version of Go installed: -```bash +```sh $ go version -go version go1.16.x darwin/amd64 +go version go1.18.x darwin/amd64 ``` ## 1.2 Creating a new Go project -We'll start by creating a new Go project. +We'll start by creating a new Go project. First, initialize the project folder with `go mod init`. Running this command should create the `go.mod` file. -```bash -mkdir kvstore -cd kvstore -go mod init github.com// +```sh +$ mkdir kvstore +$ cd kvstore +$ go mod init github.com//kvstore +go: creating new go.mod: module github.com//kvstore ``` -Inside the example directory create a `main.go` file with the following content: - -> Note: there is no need to clone or fork Tendermint in this tutorial. +Inside the project directory, create a `main.go` file with the following content: ```go package main @@ -73,7 +70,7 @@ func main() { When run, this should print "Hello, Tendermint Core" to the standard output. -```bash +```sh $ go run main.go Hello, Tendermint Core ``` @@ -152,16 +149,43 @@ func (KVStoreApplication) ApplySnapshotChunk(abcitypes.RequestApplySnapshotChunk } ``` -Now I will go through each method explaining when it's called and adding +Now, we will go through each method and explain when it is executed while adding required business logic. -### 1.3.1 CheckTx +### 1.3.1 Key-value store setup -When a new transaction is added to the Tendermint Core, it will ask the -application to check it (validate the format, signatures, etc.). +For the underlying key-value store we'll use the latest version of [badger](https://github.com/dgraph-io/badger), which is an embeddable, persistent and fast key-value (KV) database. + +```sh +$ go get github.com/dgraph-io/badger/v3 +go: added github.com/dgraph-io/badger/v3 v3.2103.2 +``` ```go -import "bytes" +import "github.com/dgraph-io/badger/v3" + +type KVStoreApplication struct { + db *badger.DB + currentBatch *badger.Txn +} + +func NewKVStoreApplication(db *badger.DB) *KVStoreApplication { + return &KVStoreApplication{ + db: db, + } +} +``` + +### 1.3.2 CheckTx + +When a new transaction is added to the Tendermint Core, it will ask the application to check it (validate the format, signatures, etc.). + +```go +import ( + "bytes" + + ... +) func (app *KVStoreApplication) isValid(tx []byte) (code uint32) { // check format @@ -214,26 +238,7 @@ Valid transactions will eventually be committed given they are not too big and have enough gas. To learn more about gas, check out ["the specification"](https://github.com/tendermint/tendermint/blob/master/spec/abci/apps.md#gas). -For the underlying key-value store we'll use -[badger](https://github.com/dgraph-io/badger), which is an embeddable, -persistent and fast key-value (KV) database. - -```go -import "github.com/dgraph-io/badger" - -type KVStoreApplication struct { - db *badger.DB - currentBatch *badger.Txn -} - -func NewKVStoreApplication(db *badger.DB) *KVStoreApplication { - return &KVStoreApplication{ - db: db, - } -} -``` - -### 1.3.2 BeginBlock -> DeliverTx -> EndBlock -> Commit +### 1.3.3 BeginBlock -> DeliverTx -> EndBlock -> Commit When Tendermint Core has decided on the block, it's transfered to the application in 3 parts: `BeginBlock`, one `DeliverTx` per transaction and @@ -290,7 +295,7 @@ func (app *KVStoreApplication) Commit() abcitypes.ResponseCommit { } ``` -### 1.3.3 Query +### 1.3.4 Query Now, when the client wants to know whenever a particular key/value exist, it will call Tendermint Core RPC `/abci_query` endpoint, which in turn will call @@ -348,17 +353,15 @@ import ( "path/filepath" "syscall" - "github.com/dgraph-io/badger" + "github.com/dgraph-io/badger/v3" "github.com/spf13/viper" - abci "github.com/tendermint/tendermint/abci/types" - cfg "github.com/tendermint/tendermint/config" - tmflags "github.com/tendermint/tendermint/libs/cli/flags" - "github.com/tendermint/tendermint/libs/log" - nm "github.com/tendermint/tendermint/node" - "github.com/tendermint/tendermint/internal/p2p" - "github.com/tendermint/tendermint/privval" - "github.com/tendermint/tendermint/proxy" + abciclient "github.com/tendermint/tendermint/abci/client" + abcitypes "github.com/tendermint/tendermint/abci/types" + tmconfig "github.com/tendermint/tendermint/config" + tmlog "github.com/tendermint/tendermint/libs/log" + tmservice "github.com/tendermint/tendermint/libs/service" + tmnode "github.com/tendermint/tendermint/node" ) var configFile string @@ -395,57 +398,42 @@ func main() { <-c } -func newTendermint(app abci.Application, configFile string) (*nm.Node, error) { - // read config - config := cfg.DefaultValidatorConfig() - config.RootDir = filepath.Dir(filepath.Dir(configFile)) - viper.SetConfigFile(configFile) - if err := viper.ReadInConfig(); err != nil { - return nil, fmt.Errorf("viper failed to read config file: %w", err) - } - if err := viper.Unmarshal(config); err != nil { - return nil, fmt.Errorf("viper failed to unmarshal config: %w", err) - } - if err := config.ValidateBasic(); err != nil { - return nil, fmt.Errorf("config is invalid: %w", err) - } +func newTendermint(app abcitypes.Application, configFile string) (tmservice.Service, error) { + // read config + config := tmconfig.DefaultValidatorConfig() + config.SetRoot(filepath.Dir(filepath.Dir(configFile))) - // create logger - logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout)) - var err error - logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel) - if err != nil { - return nil, fmt.Errorf("failed to parse log level: %w", err) - } + viper.SetConfigFile(configFile) + if err := viper.ReadInConfig(); err != nil { + return nil, fmt.Errorf("viper failed to read config file: %w", err) + } + if err := viper.Unmarshal(config); err != nil { + return nil, fmt.Errorf("viper failed to unmarshal config: %w", err) + } + if err := config.ValidateBasic(); err != nil { + return nil, fmt.Errorf("config is invalid: %w", err) + } - // read private validator - pv := privval.LoadFilePV( - config.PrivValidatorKeyFile(), - config.PrivValidatorStateFile(), - ) + // create logger + logger, err := tmlog.NewDefaultLogger(tmlog.LogFormatPlain, config.LogLevel, false) + if err != nil { + return nil, fmt.Errorf("failed to create logger: %w", err) + } - // read node key - nodeKey, err := p2p.LoadNodeKey(config.NodeKeyFile()) - if err != nil { - return nil, fmt.Errorf("failed to load node's key: %w", err) - } + // create node + node, err := tmnode.New( + config, + logger, + abciclient.NewLocalCreator(app), + nil, + ) + if err != nil { + return nil, fmt.Errorf("failed to create new Tendermint node: %w", err) + } - // create node - node, err := nm.NewNode( - config, - pv, - nodeKey, - abcicli.NewLocalClientCreator(app), - nm.DefaultGenesisDocProviderFunc(config), - nm.DefaultDBProvider, - nm.DefaultMetricsProvider(config.Instrumentation), - logger) - if err != nil { - return nil, fmt.Errorf("failed to create new Tendermint node: %w", err) - } - - return node, nil + return node, nil } + ``` This is a huge blob of code, so let's break it down into pieces. @@ -469,7 +457,7 @@ This can be avoided by setting the truncate option to true, like this: db, err := badger.Open(badger.DefaultOptions("/tmp/badger").WithTruncate(true)) ``` -Then we use it to create a Tendermint Core `Node` instance: +Then we use it to create a Tendermint Core [Service](https://github.com/tendermint/tendermint/blob/v0.35.8/libs/service/service.go#L24) instance: ```go flag.Parse() @@ -483,75 +471,48 @@ if err != nil { ... // create node -node, err := nm.NewNode( - config, - pv, - nodeKey, - abcicli.NewLocalClientCreator(app), - nm.DefaultGenesisDocProviderFunc(config), - nm.DefaultDBProvider, - nm.DefaultMetricsProvider(config.Instrumentation), - logger) +node, err := tmnode.New( + config, + logger, + abciclient.NewLocalCreator(app), + nil, +) if err != nil { - return nil, fmt.Errorf("failed to create new Tendermint node: %w", err) + return nil, fmt.Errorf("failed to create new Tendermint node: %w", err) } ``` -`NewNode` requires a few things including a configuration file, a private -validator, a node key and a few others in order to construct the full node. +[tmnode.New](https://github.com/tendermint/tendermint/blob/v0.35.8/node/public.go#L29) requires a few things including a configuration file, a logger and a few others in order to construct the full node. -Note we use `abcicli.NewLocalClientCreator` here to create a local client instead -of one communicating through a socket or gRPC. +Note that we use [abciclient.NewLocalCreator](https://github.com/tendermint/tendermint/blob/v0.35.8/abci/client/creators.go#L15) here to create a local client instead of one communicating through a socket or gRPC. [viper](https://github.com/spf13/viper) is being used for reading the config, which we will generate later using the `tendermint init` command. ```go -config := cfg.DefaultValidatorConfig() -config.RootDir = filepath.Dir(filepath.Dir(configFile)) +// read config +config := tmconfig.DefaultValidatorConfig() +config.SetRoot(filepath.Dir(filepath.Dir(configFile))) viper.SetConfigFile(configFile) if err := viper.ReadInConfig(); err != nil { - return nil, fmt.Errorf("viper failed to read config file: %w", err) + return nil, fmt.Errorf("viper failed to read config file: %w", err) } if err := viper.Unmarshal(config); err != nil { - return nil, fmt.Errorf("viper failed to unmarshal config: %w", err) + return nil, fmt.Errorf("viper failed to unmarshal config: %w", err) } if err := config.ValidateBasic(); err != nil { - return nil, fmt.Errorf("config is invalid: %w", err) + return nil, fmt.Errorf("config is invalid: %w", err) } ``` -We use `FilePV`, which is a private validator (i.e. thing which signs consensus -messages). Normally, you would use `SignerRemote` to connect to an external -[HSM](https://kb.certus.one/hsm.html). +As for the logger, we use the built-in library, which provides a nice +abstraction over [zerolog](https://github.com/rs/zerolog). ```go -pv := privval.LoadFilePV( - config.PrivValidatorKeyFile(), - config.PrivValidatorStateFile(), -) - -``` - -`nodeKey` is needed to identify the node in a p2p network. - -```go -nodeKey, err := p2p.LoadNodeKey(config.NodeKeyFile()) +// create logger +logger, err := tmlog.NewDefaultLogger(tmlog.LogFormatPlain, config.LogLevel, true) if err != nil { - return nil, fmt.Errorf("failed to load node's key: %w", err) -} -``` - -As for the logger, we use the build-in library, which provides a nice -abstraction over [go-kit's -logger](https://github.com/go-kit/kit/tree/master/log). - -```go -logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout)) -var err error -logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel()) -if err != nil { - return nil, fmt.Errorf("failed to parse log level: %w", err) + return nil, fmt.Errorf("failed to create logger: %w", err) } ``` @@ -570,40 +531,41 @@ signal.Notify(c, os.Interrupt, syscall.SIGTERM) <-c ``` -## 1.5 Getting Up and Running +## 1.5 Getting up and running -We are going to use [Go modules](https://github.com/golang/go/wiki/Modules) for -dependency management. - -```bash -export GO111MODULE=on -go mod init github.com/me/example -``` - -This should create a `go.mod` file. The current tutorial only works with -the master branch of Tendermint. so let's make sure we're using the latest version: +Make sure to enable [Go modules](https://github.com/golang/go/wiki/Modules). Run `go mod tidy` to download and add dependencies in `go.mod` file. ```sh -go get github.com/tendermint/tendermint@master +$ go mod tidy +... +``` + +Let's make sure we're using the latest version of Tendermint (currently `v0.35.8`). + +```sh +$ go get github.com/tendermint/tendermint@latest +... ``` This will populate the `go.mod` with a release number followed by a hash for Tendermint. ```go -module github.com/me/example +module github.com//kvstore -go 1.15 +go 1.18 require ( - github.com/dgraph-io/badger v1.6.2 - github.com/tendermint/tendermint + github.com/dgraph-io/badger/v3 v3.2103.2 + github.com/tendermint/tendermint v0.35.8 + ... ) ``` -Now we can build the binary: +Now, we can build the binary: -```bash -go build +```sh +$ go build +... ``` To create a default configuration, nodeKey and private validator files, let's @@ -614,66 +576,87 @@ installing from source, don't forget to checkout the latest release (`git checkout vX.Y.Z`). Don't forget to check that the application uses the same major version. -```bash -$ rm -rf /tmp/example -$ TMHOME="/tmp/example" tendermint init validator +```sh +$ rm -rf /tmp/kvstore /tmp/badger +$ TMHOME="/tmp/kvstore" tendermint init validator -I[2019-07-16|18:40:36.480] Generated private validator module=main keyFile=/tmp/example/config/priv_validator_key.json stateFile=/tmp/example2/data/priv_validator_state.json -I[2019-07-16|18:40:36.481] Generated node key module=main path=/tmp/example/config/node_key.json -I[2019-07-16|18:40:36.482] Generated genesis file module=main path=/tmp/example/config/genesis.json -I[2019-07-16|18:40:36.483] Generated config module=main mode=validator +2022-07-20T17:04:41+08:00 INFO Generated private validator keyFile=/tmp/kvstore/config/priv_validator_key.json module=main stateFile=/tmp/kvstore/data/priv_validator_state.json +2022-07-20T17:04:41+08:00 INFO Generated node key module=main path=/tmp/kvstore/config/node_key.json +2022-07-20T17:04:41+08:00 INFO Generated genesis file module=main path=/tmp/kvstore/config/genesis.json +2022-07-20T17:04:41+08:00 INFO Generated config mode=validator module=main ``` +Feel free to explore the generated files, which can be found at +`/tmp/kvstore/config` directory. Documentation on the config can be found +[here](https://docs.tendermint.com/master/tendermint-core/configuration.html). + We are ready to start our application: -```bash -$ ./example -config "/tmp/example/config/config.toml" +```sh +$ ./kvstore -config "/tmp/kvstore/config/config.toml" -badger 2019/07/16 18:42:25 INFO: All 0 tables opened in 0s -badger 2019/07/16 18:42:25 INFO: Replaying file id: 0 at offset: 0 -badger 2019/07/16 18:42:25 INFO: Replay took: 695.227s -E[2019-07-16|18:42:25.818] Couldn't connect to any seeds module=p2p -I[2019-07-16|18:42:26.853] Executed block module=state height=1 validTxs=0 invalidTxs=0 -I[2019-07-16|18:42:26.865] Committed state module=state height=1 txs=0 appHash= +badger 2022/07/16 13:55:59 INFO: All 0 tables opened in 0s +badger 2022/07/16 13:55:59 INFO: Replaying file id: 0 at offset: 0 +badger 2022/07/16 13:55:59 INFO: Replay took: 3.052µs +badger 2022/07/16 13:55:59 DEBUG: Value log discard stats empty +2022-07-16T13:55:59+08:00 INFO starting service impl=multiAppConn module=proxy service=multiAppConn +2022-07-16T13:55:59+08:00 INFO starting service connection=query impl=localClient module=abci-client service=localClient +2022-07-16T13:55:59+08:00 INFO starting service connection=snapshot impl=localClient module=abci-client service=localClient +2022-07-16T13:55:59+08:00 INFO starting service connection=mempool impl=localClient module=abci-client service=localClient +2022-07-16T13:55:59+08:00 INFO starting service connection=consensus impl=localClient module=abci-client service=localClient +2022-07-16T13:55:59+08:00 INFO starting service impl=EventBus module=events service=EventBus +2022-07-16T13:55:59+08:00 INFO starting service impl=PubSub module=pubsub service=PubSub +2022-07-16T13:55:59+08:00 INFO starting service impl=IndexerService module=txindex service=IndexerService +2022-07-16T13:55:59+08:00 INFO ABCI Handshake App Info hash= height=0 module=consensus protocol-version=0 software-version= +2022-07-16T13:55:59+08:00 INFO ABCI Replay Blocks appHeight=0 module=consensus stateHeight=0 storeHeight=0 +2022-07-16T13:55:59+08:00 INFO Completed ABCI Handshake - Tendermint and App are synced appHash= appHeight=0 module=consensus +2022-07-16T13:55:59+08:00 INFO Version info block=11 mode=validator p2p=8 tmVersion=0.35.8 ``` -Now open another tab in your terminal and try sending a transaction: +Let's try sending a transaction. Open another terminal and execute the below command. -```bash +```sh $ curl -s 'localhost:26657/broadcast_tx_commit?tx="tendermint=rocks"' { - "check_tx": { - "gasWanted": "1", - ... - }, - "deliver_tx": { ... }, - "hash": "1B3C5A1093DB952C331B1749A21DCCBB0F6C7F4E0055CD04D16346472FC60EC6", - "height": "128" + ... + "result": { + "check_tx": { + ... + "gas_wanted": "1", + ... + }, + "deliver_tx": {...}, + "hash": "1B3C5A1093DB952C331B1749A21DCCBB0F6C7F4E0055CD04D16346472FC60EC6", + "height": "91" + } } ``` Response should contain the height where this transaction was committed. -Now let's check if the given key now exists and its value: +Let's check if the given key now exists and its value: -```json +```sh $ curl -s 'localhost:26657/abci_query?data="tendermint"' { - "response": { - "code": 0, - "log": "exists", - "info": "", - "index": "0", - "key": "dGVuZGVybWludA==", - "value": "cm9ja3M=", - "proofOps": null, - "height": "6", - "codespace": "" + ... + "result": { + "response": { + "code": 0, + "log": "exists", + "info": "", + "index": "0", + "key": "dGVuZGVybWludA==", + "value": "cm9ja3M=", + "proofOps": null, + "height": "0", + "codespace": "" + } } } ``` -"dGVuZGVybWludA==" and "cm9ja3M=" are the base64-encoding of the ASCII of +`dGVuZGVybWludA==` and `cm9ja3M=` are the base64-encoding of the ASCII of "tendermint" and "rocks" accordingly. ## Outro diff --git a/docs/tutorials/go.md b/docs/tutorials/go.md index ff85bd069..908c63c74 100644 --- a/docs/tutorials/go.md +++ b/docs/tutorials/go.md @@ -37,25 +37,27 @@ Core will not have access to application's state. ## 1.1 Installing Go Please refer to [the official guide for installing -Go](https://golang.org/doc/install). +Go](https://go.dev/doc/install). Verify that you have the latest version of Go installed: -```bash +```sh $ go version -go version go1.16.x darwin/amd64 +go version go1.18.x darwin/amd64 ``` ## 1.2 Creating a new Go project -We'll start by creating a new Go project. +We'll start by creating a new Go project. Initialize the folder with `go mod init`. Running this command should create the `go.mod` file. -```bash -mkdir kvstore -cd kvstore +```sh +$ mkdir kvstore +$ cd kvstore +$ go mod init github.com//kvstore +go: creating new go.mod: module github.com//kvstore ``` -Inside the example directory create a `main.go` file with the following content: +Inside the project directory, create a `main.go` file with the following content: ```go package main @@ -71,8 +73,8 @@ func main() { When run, this should print "Hello, Tendermint Core" to the standard output. -```bash -go run main.go +```sh +$ go run main.go Hello, Tendermint Core ``` @@ -150,10 +152,34 @@ func (KVStoreApplication) ApplySnapshotChunk(abcitypes.RequestApplySnapshotChunk } ``` -Now I will go through each method explaining when it's called and adding +Now, we will go through each method and explain when it is executed while adding required business logic. -### 1.3.1 CheckTx +### 1.3.1 Key-value store setup + +For the underlying key-value store we'll use the latest version of [badger](https://github.com/dgraph-io/badger), which is an embeddable, persistent and fast key-value (KV) database. + +```sh +$ go get github.com/dgraph-io/badger/v3 +go: added github.com/dgraph-io/badger/v3 v3.2103.2 +``` + +```go +import "github.com/dgraph-io/badger/v3" + +type KVStoreApplication struct { + db *badger.DB + currentBatch *badger.Txn +} + +func NewKVStoreApplication(db *badger.DB) *KVStoreApplication { + return &KVStoreApplication{ + db: db, + } +} +``` + +### 1.3.2 CheckTx When a new transaction is added to the Tendermint Core, it will ask the application to check it (validate the format, signatures, etc.). @@ -212,26 +238,8 @@ Valid transactions will eventually be committed given they are not too big and have enough gas. To learn more about gas, check out ["the specification"](https://github.com/tendermint/tendermint/blob/master/spec/abci/apps.md#gas). -For the underlying key-value store we'll use -[badger](https://github.com/dgraph-io/badger), which is an embeddable, -persistent and fast key-value (KV) database. -```go -import "github.com/dgraph-io/badger" - -type KVStoreApplication struct { - db *badger.DB - currentBatch *badger.Txn -} - -func NewKVStoreApplication(db *badger.DB) *KVStoreApplication { - return &KVStoreApplication{ - db: db, - } -} -``` - -### 1.3.2 BeginBlock -> DeliverTx -> EndBlock -> Commit +### 1.3.3 BeginBlock -> DeliverTx -> EndBlock -> Commit When Tendermint Core has decided on the block, it's transferred to the application in 3 parts: `BeginBlock`, one `DeliverTx` per transaction and @@ -287,7 +295,7 @@ func (app *KVStoreApplication) Commit() abcitypes.ResponseCommit { } ``` -### 1.3.3 Query +### 1.3.4 Query Now, when the client wants to know whenever a particular key/value exist, it will call Tendermint Core RPC `/abci_query` endpoint, which in turn will call @@ -344,7 +352,7 @@ import ( "os/signal" "syscall" - "github.com/dgraph-io/badger" + "github.com/dgraph-io/badger/v3" abciserver "github.com/tendermint/tendermint/abci/server" "github.com/tendermint/tendermint/libs/log" @@ -353,7 +361,7 @@ import ( var socketAddr string func init() { - flag.StringVar(&socketAddr, "socket-addr", "unix://example.sock", "Unix domain socket address") + flag.StringVar(&socketAddr, "socket-addr", "unix://kvstore.sock", "Unix domain socket address") } func main() { @@ -426,40 +434,41 @@ signal.Notify(c, os.Interrupt, syscall.SIGTERM) <-c ``` -## 1.5 Getting Up and Running +## 1.5 Getting up and running -We are going to use [Go modules](https://github.com/golang/go/wiki/Modules) for -dependency management. - -```bash -export GO111MODULE=on -go mod init github.com/me/example -``` - -This should create a `go.mod` file. The current tutorial only works with -the master branch of Tendermint, so let's make sure we're using the latest version: +Make sure to enable [Go modules](https://github.com/golang/go/wiki/Modules). Run `go mod tidy` to download and add dependencies in `go.mod` file. ```sh -go get github.com/tendermint/tendermint@97a3e44e0724f2017079ce24d36433f03124c09e +$ go mod tidy +... +``` + +Let's make sure we're using the latest version of Tendermint (currently `v0.35.8`). + +```sh +$ go get github.com/tendermint/tendermint@latest +... ``` This will populate the `go.mod` with a release number followed by a hash for Tendermint. ```go -module github.com/me/example +module github.com//kvstore -go 1.16 +go 1.18 require ( - github.com/dgraph-io/badger v1.6.2 - github.com/tendermint/tendermint + github.com/dgraph-io/badger/v3 v3.2103.2 + github.com/tendermint/tendermint v0.35.8 + ... ) ``` -Now we can build the binary: +Now, we can build the binary: -```bash -go build +```sh +$ go build +... ``` To create a default configuration, nodeKey and private validator files, let's @@ -470,94 +479,112 @@ installing from source, don't forget to checkout the latest release (`git checkout vX.Y.Z`). Don't forget to check that the application uses the same major version. -```bash -rm -rf /tmp/example -TMHOME="/tmp/example" tendermint init validator +```sh +$ rm -rf /tmp/kvstore /tmp/badger +$ TMHOME="/tmp/kvstore" tendermint init validator -I[2019-07-16|18:20:36.480] Generated private validator module=main keyFile=/tmp/example/config/priv_validator_key.json stateFile=/tmp/example2/data/priv_validator_state.json -I[2019-07-16|18:20:36.481] Generated node key module=main path=/tmp/example/config/node_key.json -I[2019-07-16|18:20:36.482] Generated genesis file module=main path=/tmp/example/config/genesis.json -I[2019-07-16|18:20:36.483] Generated config module=main mode=validator +2022-07-20T17:04:41+08:00 INFO Generated private validator keyFile=/tmp/kvstore/config/priv_validator_key.json module=main stateFile=/tmp/kvstore/data/priv_validator_state.json +2022-07-20T17:04:41+08:00 INFO Generated node key module=main path=/tmp/kvstore/config/node_key.json +2022-07-20T17:04:41+08:00 INFO Generated genesis file module=main path=/tmp/kvstore/config/genesis.json +2022-07-20T17:04:41+08:00 INFO Generated config mode=validator module=main ``` Feel free to explore the generated files, which can be found at -`/tmp/example/config` directory. Documentation on the config can be found +`/tmp/kvstore/config` directory. Documentation on the config can be found [here](https://docs.tendermint.com/master/tendermint-core/configuration.html). We are ready to start our application: -```bash -rm example.sock -./example +```sh +$ rm kvstore.sock +$ ./kvstore -badger 2019/07/16 18:25:11 INFO: All 0 tables opened in 0s -badger 2019/07/16 18:25:11 INFO: Replaying file id: 0 at offset: 0 -badger 2019/07/16 18:25:11 INFO: Replay took: 300.4s -I[2019-07-16|18:25:11.523] Starting ABCIServer impl=ABCIServ +badger 2022/07/20 17:07:17 INFO: All 1 tables opened in 9ms +badger 2022/07/20 17:07:17 INFO: Replaying file id: 0 at offset: 256 +badger 2022/07/20 17:07:17 INFO: Replay took: 9.077µs +badger 2022/07/20 17:07:17 DEBUG: Value log discard stats empty +2022-07-20T17:07:17+08:00 INFO starting service impl=ABCIServer service=ABCIServer +2022-07-20T17:07:17+08:00 INFO Waiting for new connection... ``` -Then we need to start Tendermint Core and point it to our application. Staying -within the application directory execute: +Then, we need to start Tendermint Core and point it to our application. Staying +within the project directory, open another terminal and execute the command below: -```bash -TMHOME="/tmp/example" tendermint node --proxy-app=unix://example.sock +```sh +$ TMHOME="/tmp/kvstore" tendermint node --proxy-app=unix://kvstore.sock -I[2019-07-16|18:26:20.362] Version info module=main software=0.32.1 block=10 p2p=7 -I[2019-07-16|18:26:20.383] Starting Node module=main impl=Node -E[2019-07-16|18:26:20.392] Couldn't connect to any seeds module=p2p -I[2019-07-16|18:26:20.394] Started node module=main nodeInfo="{ProtocolVersion:{P2P:7 Block:10 App:0} ID_:8dab80770ae8e295d4ce905d86af78c4ff634b79 ListenAddr:tcp://0.0.0.0:26656 Network:test-chain-nIO96P Version:0.32.1 Channels:4020212223303800 Moniker:app48.fun-box.ru Other:{TxIndex:on RPCAddress:tcp://127.0.0.1:26657}}" -I[2019-07-16|18:26:21.440] Executed block module=state height=1 validTxs=0 invalidTxs=0 -I[2019-07-16|18:26:21.446] Committed state module=state height=1 txs=0 appHash= +2022-07-20T17:10:22+08:00 INFO starting service impl=multiAppConn module=proxy service=multiAppConn +2022-07-20T17:10:22+08:00 INFO starting service connection=query impl=socketClient module=abci-client service=socketClient +2022-07-20T17:10:22+08:00 INFO starting service connection=snapshot impl=socketClient module=abci-client service=socketClient +2022-07-20T17:10:22+08:00 INFO starting service connection=mempool impl=socketClient module=abci-client service=socketClient +2022-07-20T17:10:22+08:00 INFO starting service connection=consensus impl=socketClient module=abci-client service=socketClient +2022-07-20T17:10:22+08:00 INFO starting service impl=EventBus module=events service=EventBus +2022-07-20T17:10:22+08:00 INFO starting service impl=PubSub module=pubsub service=PubSub +2022-07-20T17:10:22+08:00 INFO starting service impl=IndexerService module=txindex service=IndexerService +... +2022-07-20T17:10:22+08:00 INFO starting service impl=Node module=main service=Node +2022-07-20T17:10:22+08:00 INFO Starting RPC HTTP server on 127.0.0.1:26657 module=rpc-server +2022-07-20T17:10:22+08:00 INFO p2p service legacy_enabled=false module=main +2022-07-20T17:10:22+08:00 INFO starting service impl=router module=p2p service=router +2022-07-20T17:10:22+08:00 INFO starting router channels=402021222330386061626300 listen_addr=tcp://0.0.0.0:26656 module=p2p net_addr={"id":"715727499e94f8fcaef1763192ebcc8460f44666","ip":"0.0.0.0","port":26656} node_id=715727499e94f8fcaef1763192ebcc8460f44666 +... ``` This should start the full node and connect to our ABCI application. ```sh -I[2019-07-16|18:25:11.525] Waiting for new connection... -I[2019-07-16|18:26:20.329] Accepted a new connection -I[2019-07-16|18:26:20.329] Waiting for new connection... -I[2019-07-16|18:26:20.330] Accepted a new connection -I[2019-07-16|18:26:20.330] Waiting for new connection... -I[2019-07-16|18:26:20.330] Accepted a new connection +2022-07-20T17:09:55+08:00 INFO Waiting for new connection... +2022-07-20T17:10:22+08:00 INFO Accepted a new connection +2022-07-20T17:10:22+08:00 INFO Waiting for new connection... +2022-07-20T17:10:22+08:00 INFO Accepted a new connection +2022-07-20T17:10:22+08:00 INFO Waiting for new connection... +2022-07-20T17:10:22+08:00 INFO Accepted a new connection ``` -Now open another tab in your terminal and try sending a transaction: +Let's try sending a transaction. Open another terminal and execute the below command. -```json +```sh $ curl -s 'localhost:26657/broadcast_tx_commit?tx="tendermint=rocks"' { - "check_tx": { - "gasWanted": "1", - ... - }, - "deliver_tx": { ... }, - "hash": "CDD3C6DFA0A08CAEDF546F9938A2EEC232209C24AA0E4201194E0AFB78A2C2BB", - "height": "33" + ... + "result": { + "check_tx": { + ... + "gas_wanted": "1", + ... + }, + "deliver_tx": { ... }, + "hash": "1B3C5A1093DB952C331B1749A21DCCBB0F6C7F4E0055CD04D16346472FC60EC6", + "height": "15" + } } ``` Response should contain the height where this transaction was committed. -Now let's check if the given key now exists and its value: +Let's check if the given key now exists and its value: -```json +```sh $ curl -s 'localhost:26657/abci_query?data="tendermint"' { - "response": { - "code": 0, - "log": "exists", - "info": "", - "index": "0", - "key": "dGVuZGVybWludA==", - "value": "cm9ja3M=", - "proofOps": null, - "height": "6", - "codespace": "" + ... + "result": { + "response": { + "code": 0, + "log": "exists", + "info": "", + "index": "0", + "key": "dGVuZGVybWludA==", + "value": "cm9ja3M=", + "proofOps": null, + "height": "0", + "codespace": "" + } } } ``` -"dGVuZGVybWludA==" and "cm9ja3M=" are the base64-encoding of the ASCII of +`dGVuZGVybWludA==` and `cm9ja3M=` are the base64-encoding of the ASCII of "tendermint" and "rocks" accordingly. ## Outro diff --git a/go.mod b/go.mod index eb3419b1d..f238b242e 100644 --- a/go.mod +++ b/go.mod @@ -40,7 +40,7 @@ require ( github.com/bufbuild/buf v1.4.0 github.com/creachadair/atomicfile v0.2.6 github.com/creachadair/taskgroup v0.3.2 - github.com/golangci/golangci-lint v1.47.1 + github.com/golangci/golangci-lint v1.47.2 github.com/google/go-cmp v0.5.8 github.com/vektra/mockery/v2 v2.14.0 gotest.tools v2.2.0+incompatible @@ -240,7 +240,7 @@ require ( ) require ( - github.com/creachadair/tomledit v0.0.22 + github.com/creachadair/tomledit v0.0.23 github.com/prometheus/client_model v0.2.0 github.com/prometheus/common v0.37.0 github.com/syndtr/goleveldb v1.0.1-0.20200815110645-5c35d600f0ca diff --git a/go.sum b/go.sum index cf38631bd..c95d3a810 100644 --- a/go.sum +++ b/go.sum @@ -245,8 +245,8 @@ github.com/creachadair/atomicfile v0.2.6/go.mod h1:BRq8Une6ckFneYXZQ+kO7p1ZZP3I2 github.com/creachadair/command v0.0.0-20220426235536-a748effdf6a1/go.mod h1:bAM+qFQb/KwWyCc9MLC4U1jvn3XyakqP5QRkds5T6cY= github.com/creachadair/taskgroup v0.3.2 h1:zlfutDS+5XG40AOxcHDSThxKzns8Tnr9jnr6VqkYlkM= github.com/creachadair/taskgroup v0.3.2/go.mod h1:wieWwecHVzsidg2CsUnFinW1faVN4+kq+TDlRJQ0Wbk= -github.com/creachadair/tomledit v0.0.22 h1:lRtepmrwhzDq+g1gv5ftVn5itgo7CjYbm6abKTToqJ4= -github.com/creachadair/tomledit v0.0.22/go.mod h1:cIu/4x5L855oSRejIqr+WRFh+mv9g4fWLiUFaApYn/Y= +github.com/creachadair/tomledit v0.0.23 h1:ohYJjMsxwzj4dDzKaBWFbWH5J+3LO/8CYnlVY+baBWA= +github.com/creachadair/tomledit v0.0.23/go.mod h1:cIu/4x5L855oSRejIqr+WRFh+mv9g4fWLiUFaApYn/Y= github.com/creack/pty v1.1.7/go.mod h1:lj5s0c3V2DBrqTV7llrYr5NG6My20zk30Fl46Y7DoTY= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/creack/pty v1.1.11/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= @@ -449,8 +449,8 @@ github.com/golangci/go-misc v0.0.0-20220329215616-d24fe342adfe h1:6RGUuS7EGotKx6 github.com/golangci/go-misc v0.0.0-20220329215616-d24fe342adfe/go.mod h1:gjqyPShc/m8pEMpk0a3SeagVb0kaqvhscv+i9jI5ZhQ= github.com/golangci/gofmt v0.0.0-20190930125516-244bba706f1a h1:iR3fYXUjHCR97qWS8ch1y9zPNsgXThGwjKPrYfqMPks= github.com/golangci/gofmt v0.0.0-20190930125516-244bba706f1a/go.mod h1:9qCChq59u/eW8im404Q2WWTrnBUQKjpNYKMbU4M7EFU= -github.com/golangci/golangci-lint v1.47.1 h1:hbubHskV2Ppwz4ZZE2lc0/Pw9ZhqLuzm2dT7ZVpLA6Y= -github.com/golangci/golangci-lint v1.47.1/go.mod h1:lpS2pjBZtRyXewUcOY7yUL3K4KfpoWz072yRN8AuhHg= +github.com/golangci/golangci-lint v1.47.2 h1:qvMDVv49Hrx3PSEXZ0bD/yhwSbhsOihQjFYCKieegIw= +github.com/golangci/golangci-lint v1.47.2/go.mod h1:lpS2pjBZtRyXewUcOY7yUL3K4KfpoWz072yRN8AuhHg= github.com/golangci/lint-1 v0.0.0-20191013205115-297bf364a8e0 h1:MfyDlzVjl1hoaPzPD4Gpb/QgoRfSBR0jdhwGyAWwMSA= github.com/golangci/lint-1 v0.0.0-20191013205115-297bf364a8e0/go.mod h1:66R6K6P6VWk9I95jvqGxkqJxVWGFy9XlDwLwVz1RCFg= github.com/golangci/maligned v0.0.0-20180506175553-b1d89398deca h1:kNY3/svz5T29MYHubXix4aDDuE3RWHkPvopM/EDv/MA= diff --git a/internal/blocksync/reactor.go b/internal/blocksync/reactor.go index c1b032b03..9f0a76089 100644 --- a/internal/blocksync/reactor.go +++ b/internal/blocksync/reactor.go @@ -469,12 +469,10 @@ func (r *Reactor) poolRoutine(ctx context.Context, stateSynced bool, blockSyncCh lastAdvance = r.pool.LastAdvance() ) - r.logger.Debug( - "consensus ticker", + r.logger.Debug("consensus ticker", "num_pending", numPending, "total", lenRequesters, - "height", height, - ) + "height", height) switch { diff --git a/internal/consensus/reactor.go b/internal/consensus/reactor.go index 3ba95c836..12317a9b4 100644 --- a/internal/consensus/reactor.go +++ b/internal/consensus/reactor.go @@ -10,6 +10,7 @@ import ( cstypes "github.com/tendermint/tendermint/internal/consensus/types" "github.com/tendermint/tendermint/internal/eventbus" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/internal/p2p" sm "github.com/tendermint/tendermint/internal/state" "github.com/tendermint/tendermint/libs/bits" @@ -1113,7 +1114,7 @@ func (r *Reactor) handleDataMessage(ctx context.Context, envelope *p2p.Envelope, } if r.WaitSync() { - logger.Info("ignoring message received during sync", "msg", fmt.Sprintf("%T", msgI)) + logger.Info("ignoring message received during sync", "msg", tmstrings.LazySprintf("%T", msgI)) return nil } diff --git a/internal/consensus/state.go b/internal/consensus/state.go index a7a0b8fed..5b10d4b50 100644 --- a/internal/consensus/state.go +++ b/internal/consensus/state.go @@ -21,6 +21,7 @@ import ( "github.com/tendermint/tendermint/internal/eventbus" "github.com/tendermint/tendermint/internal/jsontypes" "github.com/tendermint/tendermint/internal/libs/autofile" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" sm "github.com/tendermint/tendermint/internal/state" tmevents "github.com/tendermint/tendermint/libs/events" "github.com/tendermint/tendermint/libs/log" @@ -778,11 +779,9 @@ func (cs *State) updateToState(state sm.State) { // signal the new round step, because other services (eg. txNotifier) // depend on having an up-to-date peer state! if state.LastBlockHeight <= cs.state.LastBlockHeight { - cs.logger.Debug( - "ignoring updateToState()", + cs.logger.Debug("ignoring updateToState()", "new_height", state.LastBlockHeight+1, - "old_height", cs.state.LastBlockHeight+1, - ) + "old_height", cs.state.LastBlockHeight+1) cs.newStep() return } @@ -1038,12 +1037,10 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) { } if err != nil && msg.Round != cs.Round { - cs.logger.Debug( - "received block part from wrong round", + cs.logger.Debug("received block part from wrong round", "height", cs.Height, "cs_round", cs.Round, - "block_round", msg.Round, - ) + "block_round", msg.Round) err = nil } @@ -1073,7 +1070,7 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) { // We could make note of this and help filter in broadcastHasVoteMessage(). default: - cs.logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg)) + cs.logger.Error("unknown msg type", "type", tmstrings.LazySprintf("%T", msg)) return } @@ -1184,10 +1181,10 @@ func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) { logger := cs.logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) { - logger.Debug( - "entering new round with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering new round with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1195,7 +1192,10 @@ func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) { logger.Debug("need to set a buffer and log message here for sanity", "start_time", cs.StartTime, "now", now) } - logger.Debug("entering new round", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering new round", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) // increment validators if necessary validators := cs.Validators @@ -1274,10 +1274,10 @@ func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { logger := cs.logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) { - logger.Debug( - "entering propose step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering propose step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1291,7 +1291,10 @@ func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { } } - logger.Debug("entering propose step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering propose step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPropose: @@ -1333,17 +1336,13 @@ func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { } if cs.isProposer(addr) { - logger.Debug( - "propose step; our turn to propose", - "proposer", addr, - ) + logger.Debug("propose step; our turn to propose", + "proposer", addr) cs.decideProposal(ctx, height, round) } else { - logger.Debug( - "propose step; not our turn to propose", - "proposer", cs.Validators.GetProposer().Address, - ) + logger.Debug("propose step; not our turn to propose", + "proposer", cs.Validators.GetProposer().Address) } } @@ -1480,10 +1479,10 @@ func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) { logger := cs.logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) { - logger.Debug( - "entering prevote step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering prevote step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1493,7 +1492,10 @@ func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) { cs.newStep() }() - logger.Debug("entering prevote step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering prevote step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) // Sign and broadcast vote as necessary cs.doPrevote(ctx, height, round) @@ -1533,14 +1535,10 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 //TODO: Remove this temporary fix when the complete solution is ready. See #8739 if !cs.replayMode && cs.Proposal.POLRound == -1 && cs.LockedRound == -1 && !cs.proposalIsTimely() { logger.Debug("prevote step: Proposal is not timely; prevoting nil", - "proposed", - tmtime.Canonical(cs.Proposal.Timestamp).Format(time.RFC3339Nano), - "received", - tmtime.Canonical(cs.ProposalReceiveTime).Format(time.RFC3339Nano), - "msg_delay", - sp.MessageDelay, - "precision", - sp.Precision) + "proposed", tmtime.Canonical(cs.Proposal.Timestamp).Format(time.RFC3339Nano), + "received", tmtime.Canonical(cs.ProposalReceiveTime).Format(time.RFC3339Nano), + "msg_delay", sp.MessageDelay, + "precision", sp.Precision) cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{}) return } @@ -1625,8 +1623,8 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 blockID, ok := cs.Votes.Prevotes(cs.Proposal.POLRound).TwoThirdsMajority() if ok && cs.ProposalBlock.HashesTo(blockID.Hash) && cs.Proposal.POLRound >= 0 && cs.Proposal.POLRound < cs.Round { if cs.LockedRound <= cs.Proposal.POLRound { - logger.Debug("prevote step: ProposalBlock is valid and received a 2/3" + - "majority in a round later than the locked round; prevoting the proposal") + logger.Debug("prevote step: ProposalBlock is valid and received a 2/3 majority in a round later than the locked round", + "outcome", "prevoting the proposal") cs.signAddVote(ctx, tmproto.PrevoteType, cs.ProposalBlock.Hash(), cs.ProposalBlockParts.Header()) return } @@ -1637,8 +1635,8 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 } } - logger.Debug("prevote step: ProposalBlock is valid but was not our locked block or " + - "did not receive a more recent majority; prevoting nil") + logger.Debug("prevote step: ProposalBlock is valid but was not our locked block or did not receive a more recent majority", + "outcome", "prevoting nil") cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{}) } @@ -1647,10 +1645,10 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { logger := cs.logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) { - logger.Debug( - "entering prevote wait step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering prevote wait step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1661,7 +1659,10 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { )) } - logger.Debug("entering prevote wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering prevote wait step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrevoteWait: @@ -1679,17 +1680,21 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { // Lock & precommit the ProposalBlock if we have enough prevotes for it (a POL in this round) // else, precommit nil otherwise. func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) { - logger := cs.logger.With("height", height, "round", round) + logger := cs.logger.With("new_height", height, "new_round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) { - logger.Debug( - "entering precommit step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering precommit step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) + return } - logger.Debug("entering precommit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering precommit step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrecommit: @@ -1796,14 +1801,13 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) // Enter: any +2/3 precommits for next round. func (cs *State) enterPrecommitWait(height int64, round int32) { - logger := cs.logger.With("height", height, "round", round) + logger := cs.logger.With("new_height", height, "new_round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) { - logger.Debug( - "entering precommit wait step with invalid args", + logger.Debug("entering precommit wait step with invalid args", "triggered_timeout", cs.TriggeredTimeoutPrecommit, - "current", fmt.Sprintf("%v/%v", cs.Height, cs.Round), - ) + "height", cs.Height, + "round", cs.Round) return } @@ -1814,7 +1818,10 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { )) } - logger.Debug("entering precommit wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering precommit wait step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrecommitWait: @@ -1828,17 +1835,20 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { // Enter: +2/3 precommits for block func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int32) { - logger := cs.logger.With("height", height, "commit_round", commitRound) + logger := cs.logger.With("new_height", height, "commit_round", commitRound) if cs.Height != height || cstypes.RoundStepCommit <= cs.Step { - logger.Debug( - "entering commit step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering commit step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } - logger.Debug("entering commit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering commit step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterCommit: @@ -1892,12 +1902,12 @@ func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int3 // If we have the block AND +2/3 commits for it, finalize. func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) { - logger := cs.logger.With("height", height) - if cs.Height != height { panic(fmt.Sprintf("tryFinalizeCommit() cs.Height: %v vs height: %v", cs.Height, height)) } + logger := cs.logger.With("height", height) + blockID, ok := cs.Votes.Precommits(cs.CommitRound).TwoThirdsMajority() if !ok || blockID.IsNil() { logger.Error("failed attempt to finalize commit; there was no +2/3 majority or +2/3 was for nil") @@ -1907,9 +1917,8 @@ func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) { if !cs.ProposalBlock.HashesTo(blockID.Hash) { // TODO: this happens every time if we're not a validator (ugly logs) // TODO: ^^ wait, why does it matter that we're a validator? - logger.Debug( - "failed attempt to finalize commit; we do not have the commit block", - "proposal_block", cs.ProposalBlock.Hash(), + logger.Debug("failed attempt to finalize commit; we do not have the commit block", + "proposal_block", tmstrings.LazyBlockHash(cs.ProposalBlock), "commit_block", blockID.Hash, ) return @@ -1951,11 +1960,10 @@ func (cs *State) finalizeCommit(ctx context.Context, height int64) { logger.Info( "finalizing commit of block", - "hash", block.Hash(), + "hash", tmstrings.LazyBlockHash(block), "root", block.AppHash, "num_txs", len(block.Txs), ) - logger.Debug(fmt.Sprintf("%v", block)) // Save to blockStore. if cs.blockStore.Height() < block.Height { @@ -2052,8 +2060,11 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) { address types.Address ) if commitSize != valSetLen { - cs.logger.Error(fmt.Sprintf("commit size (%d) doesn't match valset length (%d) at height %d\n\n%v\n\n%v", - commitSize, valSetLen, block.Height, block.LastCommit.Signatures, cs.LastValidators.Validators)) + cs.logger.Error("commit size doesn't match valset", + "size", commitSize, + "valset_len", valSetLen, + "height", block.Height, + "extra", tmstrings.LazySprintf("\n%v\n\n%v", block.LastCommit.Signatures, cs.LastValidators.Validators)) return } @@ -2187,8 +2198,7 @@ func (cs *State) addProposalBlockPart( cs.metrics.BlockGossipPartsReceived.With("matches_current", "false").Add(1) // NOTE: this can happen when we've gone to a higher round and // then receive parts from the previous round - not necessarily a bad peer. - cs.logger.Debug( - "received a block part when we are not expecting any", + cs.logger.Debug("received a block part when we are not expecting any", "height", height, "round", round, "index", part.Index, @@ -2248,11 +2258,9 @@ func (cs *State) handleCompleteProposal(ctx context.Context, height int64) { blockID, hasTwoThirds := prevotes.TwoThirdsMajority() if hasTwoThirds && !blockID.IsNil() && (cs.ValidRound < cs.Round) { if cs.ProposalBlock.HashesTo(blockID.Hash) { - cs.logger.Debug( - "updating valid block to new proposal block", + cs.logger.Debug("updating valid block to new proposal block", "valid_round", cs.Round, - "valid_block_hash", cs.ProposalBlock.Hash(), - ) + "valid_block_hash", tmstrings.LazyBlockHash(cs.ProposalBlock)) cs.ValidRound = cs.Round cs.ValidBlock = cs.ProposalBlock @@ -2291,23 +2299,19 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types. } if bytes.Equal(vote.ValidatorAddress, cs.privValidatorPubKey.Address()) { - cs.logger.Error( - "found conflicting vote from ourselves; did you unsafe_reset a validator?", + cs.logger.Error("found conflicting vote from ourselves; did you unsafe_reset a validator?", "height", vote.Height, "round", vote.Round, - "type", vote.Type, - ) + "type", vote.Type) return added, err } // report conflicting votes to the evidence pool cs.evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB) - cs.logger.Debug( - "found and sent conflicting votes to the evidence pool", + cs.logger.Debug("found and sent conflicting votes to the evidence pool", "vote_a", voteErr.VoteA, - "vote_b", voteErr.VoteB, - ) + "vote_b", voteErr.VoteB) return added, err } else if errors.Is(err, types.ErrVoteNonDeterministicSignature) { @@ -2331,13 +2335,11 @@ func (cs *State) addVote( vote *types.Vote, peerID types.NodeID, ) (added bool, err error) { - cs.logger.Debug( - "adding vote", + cs.logger.Debug("adding vote", "vote_height", vote.Height, "vote_type", vote.Type, "val_index", vote.ValidatorIndex, - "cs_height", cs.Height, - ) + "cs_height", cs.Height) if vote.Height < cs.Height || (vote.Height == cs.Height && vote.Round < cs.Round) { cs.metrics.MarkLateVote(vote.Type) @@ -2458,11 +2460,9 @@ func (cs *State) addVote( cs.ValidBlock = cs.ProposalBlock cs.ValidBlockParts = cs.ProposalBlockParts } else { - cs.logger.Debug( - "valid block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), - "block_id", blockID.Hash, - ) + cs.logger.Debug("valid block we do not know about; set ProposalBlock=nil", + "proposal", tmstrings.LazyBlockHash(cs.ProposalBlock), + "block_id", blockID.Hash) // we're getting the wrong block cs.ProposalBlock = nil diff --git a/internal/libs/strings/string.go b/internal/libs/strings/string.go index 95ea03b5a..067f31ffc 100644 --- a/internal/libs/strings/string.go +++ b/internal/libs/strings/string.go @@ -3,8 +3,94 @@ package strings import ( "fmt" "strings" + + tmbytes "github.com/tendermint/tendermint/libs/bytes" ) +type lazyStringf struct { + tmpl string + args []interface{} + out string +} + +func (s *lazyStringf) String() string { + if s.out == "" && s.tmpl != "" { + s.out = fmt.Sprintf(s.tmpl, s.args) + s.args = nil + s.tmpl = "" + } + return s.out +} + +// LazySprintf creates a fmt.Stringer implementation with similar +// semantics as fmt.Sprintf, *except* that the string is built when +// String() is called on the object. This means that format arguments +// are resolved/captured into string format when String() is called, +// and not, as in fmt.Sprintf when that function returns. +// +// As a result, if you use this type in go routines or defer +// statements it's possible to pass an argument to LazySprintf which +// has one value at the call site and a different value when the +// String() is evaluated, which may lead to unexpected outcomes. In +// these situations, either be *extremely* careful about the arguments +// passed to this function or use fmt.Sprintf. +// +// The implementation also caches the output of the underlying +// fmt.Sprintf statement when String() is called, so subsequent calls +// will produce the same result. +func LazySprintf(t string, args ...interface{}) fmt.Stringer { + return &lazyStringf{tmpl: t, args: args} +} + +type lazyStringer struct { + val fmt.Stringer + out string +} + +func (l *lazyStringer) String() string { + if l.out == "" && l.val != nil { + l.out = l.val.String() + l.val = nil + } + return l.out +} + +// LazyStringer captures a fmt.Stringer implementation resolving the +// underlying string *only* when the String() method is called and +// caching the result for future use. +func LazyStringer(v fmt.Stringer) fmt.Stringer { return &lazyStringer{val: v} } + +type lazyBlockHash struct { + block interface{ Hash() tmbytes.HexBytes } + out string +} + +// LazyBlockHash defers block Hash until the Stringer interface is invoked. +// This is particularly useful for avoiding calling Sprintf when debugging is not +// active. +// +// As a result, if you use this type in go routines or defer +// statements it's possible to pass an argument to LazyBlockHash that +// has one value at the call site and a different value when the +// String() is evaluated, which may lead to unexpected outcomes. In +// these situations, either be *extremely* careful about the arguments +// passed to this function or use fmt.Sprintf. +// +// The implementation also caches the output of the string form of the +// block hash when String() is called, so subsequent calls will +// produce the same result. +func LazyBlockHash(block interface{ Hash() tmbytes.HexBytes }) fmt.Stringer { + return &lazyBlockHash{block: block} +} + +func (l *lazyBlockHash) String() string { + if l.out == "" && l.block != nil { + l.out = l.block.Hash().String() + l.block = nil + } + return l.out +} + // SplitAndTrimEmpty slices s into all subslices separated by sep and returns a // slice of the string s with all leading and trailing Unicode code points // contained in cutset removed. If sep is empty, SplitAndTrim splits after each diff --git a/internal/mempool/mempool.go b/internal/mempool/mempool.go index 0354eb28a..c0da7cef2 100644 --- a/internal/mempool/mempool.go +++ b/internal/mempool/mempool.go @@ -14,6 +14,7 @@ import ( abci "github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/internal/libs/clist" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/types" ) @@ -540,7 +541,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon } txmp.logger.Debug("evicting lower-priority transactions", - "new_tx", fmt.Sprintf("%X", wtx.tx.Hash()), + "new_tx", tmstrings.LazySprintf("%X", wtx.tx.Hash()), "new_priority", priority, ) @@ -562,7 +563,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon txmp.logger.Debug( "evicted valid existing transaction; mempool full", - "old_tx", fmt.Sprintf("%X", w.tx.Hash()), + "old_tx", tmstrings.LazySprintf("%X", w.tx.Hash()), "old_priority", w.priority, ) txmp.removeTxByElement(vic) @@ -588,7 +589,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon txmp.logger.Debug( "inserted new valid transaction", "priority", wtx.Priority(), - "tx", fmt.Sprintf("%X", wtx.tx.Hash()), + "tx", tmstrings.LazySprintf("%X", wtx.tx.Hash()), "height", txmp.height, "num_txs", txmp.Size(), ) diff --git a/internal/mempool/reactor.go b/internal/mempool/reactor.go index 1f4b3f78a..18124f82b 100644 --- a/internal/mempool/reactor.go +++ b/internal/mempool/reactor.go @@ -9,6 +9,7 @@ import ( "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/internal/libs/clist" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/internal/p2p" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" @@ -330,9 +331,8 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, m return } - r.logger.Debug( - "gossiped tx to peer", - "tx", fmt.Sprintf("%X", memTx.tx.Hash()), + r.logger.Debug("gossiped tx to peer", + "tx", tmstrings.LazySprintf("%X", memTx.tx.Hash()), "peer", peerID, ) } diff --git a/internal/p2p/conn/connection.go b/internal/p2p/conn/connection.go index 8f8453e71..adc287328 100644 --- a/internal/p2p/conn/connection.go +++ b/internal/p2p/conn/connection.go @@ -313,7 +313,7 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool { // Send message to channel. channel, ok := c.channelsIdx[chID] if !ok { - c.logger.Error(fmt.Sprintf("Cannot send bytes, unknown channel %X", chID)) + c.logger.Error("Cannot send bytes to unknown channel", "channel", chID) return false } diff --git a/internal/p2p/pex/reactor.go b/internal/p2p/pex/reactor.go index 87677799d..9618433f4 100644 --- a/internal/p2p/pex/reactor.go +++ b/internal/p2p/pex/reactor.go @@ -358,7 +358,8 @@ func (r *Reactor) calculateNextRequestTime(added int) time.Duration { // If the peer store is nearly full, wait the maximum interval. if ratio := r.peerManager.PeerRatio(); ratio >= 0.95 { r.logger.Debug("Peer manager is nearly full", - "sleep_period", fullCapacityInterval, "ratio", ratio) + "sleep_period", fullCapacityInterval, + "ratio", ratio) return fullCapacityInterval } diff --git a/internal/p2p/pqueue.go b/internal/p2p/pqueue.go index 3cd1c897a..f53c988a6 100644 --- a/internal/p2p/pqueue.go +++ b/internal/p2p/pqueue.go @@ -208,13 +208,11 @@ func (s *pqScheduler) process(ctx context.Context) { } else { pqEnvTmpChIDStr := strconv.Itoa(int(pqEnvTmp.envelope.ChannelID)) s.metrics.PeerQueueDroppedMsgs.With("ch_id", pqEnvTmpChIDStr).Add(1) - s.logger.Debug( - "dropped envelope", + s.logger.Debug("dropped envelope", "ch_id", pqEnvTmpChIDStr, "priority", pqEnvTmp.priority, "msg_size", pqEnvTmp.size, - "capacity", s.capacity, - ) + "capacity", s.capacity) s.metrics.PeerPendingSendBytes.With("peer_id", string(pqEnvTmp.envelope.To)).Add(float64(-pqEnvTmp.size)) @@ -238,13 +236,11 @@ func (s *pqScheduler) process(ctx context.Context) { // There is not sufficient capacity to drop lower priority Envelopes, // so we drop the incoming Envelope. s.metrics.PeerQueueDroppedMsgs.With("ch_id", chIDStr).Add(1) - s.logger.Debug( - "dropped envelope", + s.logger.Debug("dropped envelope", "ch_id", chIDStr, "priority", pqEnv.priority, "msg_size", pqEnv.size, - "capacity", s.capacity, - ) + "capacity", s.capacity) } } diff --git a/internal/p2p/router.go b/internal/p2p/router.go index 4f3af1346..f10691715 100644 --- a/internal/p2p/router.go +++ b/internal/p2p/router.go @@ -13,6 +13,7 @@ import ( "github.com/gogo/protobuf/proto" "github.com/tendermint/tendermint/crypto" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/types" @@ -461,7 +462,7 @@ func (r *Router) acceptPeers(ctx context.Context, transport Transport) { closeErr := conn.Close() r.logger.Debug("rate limiting incoming peer", "err", err, - "ip", incomingIP.String(), + "ip", tmstrings.LazyStringer(incomingIP), "close_err", closeErr, ) diff --git a/internal/statesync/reactor.go b/internal/statesync/reactor.go index deed8d0d3..ffd863dda 100644 --- a/internal/statesync/reactor.go +++ b/internal/statesync/reactor.go @@ -686,37 +686,31 @@ func (r *Reactor) handleSnapshotMessage(ctx context.Context, envelope *p2p.Envel func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope, chunkCh p2p.Channel) error { switch msg := envelope.Message.(type) { case *ssproto.ChunkRequest: - r.logger.Debug( - "received chunk request", + r.logger.Debug("received chunk request", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) resp, err := r.conn.LoadSnapshotChunk(ctx, &abci.RequestLoadSnapshotChunk{ Height: msg.Height, Format: msg.Format, Chunk: msg.Index, }) if err != nil { - r.logger.Error( - "failed to load chunk", + r.logger.Error("failed to load chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, "err", err, - "peer", envelope.From, - ) + "peer", envelope.From) return nil } - r.logger.Debug( - "sending chunk", + r.logger.Debug("sending chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) if err := chunkCh.Send(ctx, p2p.Envelope{ To: envelope.From, Message: &ssproto.ChunkResponse{ @@ -739,13 +733,11 @@ func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope return nil } - r.logger.Debug( - "received chunk; adding to sync", + r.logger.Debug("received chunk; adding to sync", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) _, err := r.syncer.AddChunk(&chunk{ Height: msg.Height, Format: msg.Format, @@ -754,14 +746,12 @@ func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope Sender: envelope.From, }) if err != nil { - r.logger.Error( - "failed to add chunk", + r.logger.Error("failed to add chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, "err", err, - "peer", envelope.From, - ) + "peer", envelope.From) return nil } diff --git a/internal/statesync/syncer.go b/internal/statesync/syncer.go index a09b55892..591639fcd 100644 --- a/internal/statesync/syncer.go +++ b/internal/statesync/syncer.go @@ -84,11 +84,9 @@ func (s *syncer) AddChunk(chunk *chunk) (bool, error) { return false, err } if added { - s.logger.Debug("Added chunk to queue", "height", chunk.Height, "format", chunk.Format, - "chunk", chunk.Index) + s.logger.Debug("Added chunk to queue", "height", chunk.Height, "format", chunk.Format, "chunk", chunk.Index) } else { - s.logger.Debug("Ignoring duplicate chunk in queue", "height", chunk.Height, "format", chunk.Format, - "chunk", chunk.Index) + s.logger.Debug("Ignoring duplicate chunk in queue", "height", chunk.Height, "format", chunk.Format, "chunk", chunk.Index) } return added, nil } @@ -137,12 +135,20 @@ func (s *syncer) SyncAny( discoveryTime = minimumDiscoveryTime } + timer := time.NewTimer(discoveryTime) + defer timer.Stop() + if discoveryTime > 0 { if err := requestSnapshots(); err != nil { return sm.State{}, nil, err } - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) - time.Sleep(discoveryTime) + s.logger.Info("discovering snapshots", + "interval", discoveryTime) + select { + case <-ctx.Done(): + return sm.State{}, nil, ctx.Err() + case <-timer.C: + } } // The app may ask us to retry a snapshot restoration, in which case we need to reuse @@ -151,8 +157,11 @@ func (s *syncer) SyncAny( snapshot *snapshot chunks *chunkQueue err error + iters int ) + for { + iters++ // If not nil, we're going to retry restoration of the same snapshot. if snapshot == nil { snapshot = s.snapshots.Best() @@ -162,9 +171,16 @@ func (s *syncer) SyncAny( if discoveryTime == 0 { return sm.State{}, nil, errNoSnapshots } - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) - time.Sleep(discoveryTime) - continue + s.logger.Info("discovering snapshots", + "iterations", iters, + "interval", discoveryTime) + timer.Reset(discoveryTime) + select { + case <-ctx.Done(): + return sm.State{}, nil, ctx.Err() + case <-timer.C: + continue + } } if chunks == nil { chunks, err = newChunkQueue(snapshot, s.tempDir) @@ -494,13 +510,11 @@ func (s *syncer) requestChunk(ctx context.Context, snapshot *snapshot, chunk uin return nil } - s.logger.Debug( - "Requesting snapshot chunk", + s.logger.Debug("Requesting snapshot chunk", "height", snapshot.Height, "format", snapshot.Format, "chunk", chunk, - "peer", peer, - ) + "peer", peer) msg := p2p.Envelope{ To: peer, diff --git a/libs/log/default.go b/libs/log/default.go index 557ba6551..a6e829639 100644 --- a/libs/log/default.go +++ b/libs/log/default.go @@ -55,9 +55,7 @@ func NewDefaultLogger(format, level string) (Logger, error) { // make the writer thread-safe logWriter = newSyncWriter(logWriter) - return &defaultLogger{ - Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger(), - }, nil + return &defaultLogger{Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger()}, nil } func (l defaultLogger) Info(msg string, keyVals ...interface{}) { @@ -73,9 +71,7 @@ func (l defaultLogger) Debug(msg string, keyVals ...interface{}) { } func (l defaultLogger) With(keyVals ...interface{}) Logger { - return &defaultLogger{ - Logger: l.Logger.With().Fields(keyVals).Logger(), - } + return &defaultLogger{Logger: l.Logger.With().Fields(keyVals).Logger()} } // OverrideWithNewLogger replaces an existing logger's internal with diff --git a/light/client.go b/light/client.go index f38e9d59d..3c32f5c69 100644 --- a/light/client.go +++ b/light/client.go @@ -9,6 +9,7 @@ import ( "sync" "time" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" tmmath "github.com/tendermint/tendermint/libs/math" "github.com/tendermint/tendermint/light/provider" @@ -475,7 +476,8 @@ func (c *Client) VerifyHeader(ctx context.Context, newHeader *types.Header, now return fmt.Errorf("existing trusted header %X does not match newHeader %X", l.Hash(), newHeader.Hash()) } c.logger.Debug("header has already been verified", - "height", newHeader.Height, "hash", newHeader.Hash()) + "height", newHeader.Height, + "hash", tmstrings.LazyBlockHash(newHeader)) return nil } @@ -576,7 +578,7 @@ func (c *Client) verifySequential( // 2) Verify them c.logger.Debug("verify adjacent newLightBlock against verifiedBlock", "trustedHeight", verifiedBlock.Height, - "trustedHash", verifiedBlock.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedBlock), "newHeight", interimBlock.Height, "newHash", interimBlock.Hash()) @@ -663,9 +665,9 @@ func (c *Client) verifySkipping( for { c.logger.Debug("verify non-adjacent newHeader against verifiedBlock", "trustedHeight", verifiedBlock.Height, - "trustedHash", verifiedBlock.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedBlock), "newHeight", blockCache[depth].Height, - "newHash", blockCache[depth].Hash()) + "newHash", tmstrings.LazyBlockHash(blockCache[depth])) // Verify the untrusted header. This function is equivalent to // ValidAndVerified in the spec @@ -897,9 +899,9 @@ func (c *Client) backwards( interimHeader = interimBlock.Header c.logger.Debug("verify newHeader against verifiedHeader", "trustedHeight", verifiedHeader.Height, - "trustedHash", verifiedHeader.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedHeader), "newHeight", interimHeader.Height, - "newHash", interimHeader.Hash()) + "newHash", tmstrings.LazyBlockHash(interimHeader)) if err := VerifyBackwards(interimHeader, verifiedHeader); err != nil { // verification has failed c.logger.Info("backwards verification failed, replacing primary...", "err", err, "primary", c.primary) diff --git a/light/detector.go b/light/detector.go index a5ac35a02..a0afdca89 100644 --- a/light/detector.go +++ b/light/detector.go @@ -39,8 +39,10 @@ func (c *Client) detectDivergence(ctx context.Context, primaryTrace []*types.Lig lastVerifiedHeader = primaryTrace[len(primaryTrace)-1].SignedHeader witnessesToRemove = make([]int, 0) ) - c.logger.Debug("running detector against trace", "finalizeBlockHeight", lastVerifiedHeader.Height, - "finalizeBlockHash", lastVerifiedHeader.Hash, "length", len(primaryTrace)) + c.logger.Debug("running detector against trace", + "finalizeBlockHeight", lastVerifiedHeader.Height, + "finalizeBlockHash", lastVerifiedHeader.Hash, + "length", len(primaryTrace)) // launch one goroutine per witness to retrieve the light block of the target height // and compare it with the header from the primary diff --git a/rpc/jsonrpc/server/http_server.go b/rpc/jsonrpc/server/http_server.go index 50a37158e..fffc002f3 100644 --- a/rpc/jsonrpc/server/http_server.go +++ b/rpc/jsonrpc/server/http_server.go @@ -58,7 +58,7 @@ func DefaultConfig() *Config { // Serve creates a http.Server and calls Serve with the given listener. It // wraps handler to recover panics and limit the request body size. func Serve(ctx context.Context, listener net.Listener, handler http.Handler, logger log.Logger, config *Config) error { - logger.Info(fmt.Sprintf("Starting RPC HTTP server on %s", listener.Addr())) + logger.Info("Starting RPC HTTP server on", "addr", listener.Addr()) h := recoverAndLogHandler(MaxBytesHandler(handler, config.MaxBodyBytes), logger) s := &http.Server{ Handler: h, diff --git a/test/e2e/app/app.go b/test/e2e/app/app.go index 1f66e95cc..4a18a54a4 100644 --- a/test/e2e/app/app.go +++ b/test/e2e/app/app.go @@ -18,6 +18,7 @@ import ( "github.com/tendermint/tendermint/abci/example/code" abci "github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/crypto" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/proto/tendermint/types" "github.com/tendermint/tendermint/version" @@ -484,7 +485,10 @@ func (app *Application) ExtendVote(_ context.Context, req *abci.RequestExtendVot time.Sleep(time.Duration(app.cfg.VoteExtensionDelayMS) * time.Millisecond) } - app.logger.Info("generated vote extension", "num", num, "ext", fmt.Sprintf("%x", ext[:extLen]), "state.Height", app.state.Height) + app.logger.Info("generated vote extension", + "num", num, + "ext", tmstrings.LazySprintf("%x", ext[:extLen]), + "state.Height", app.state.Height) return &abci.ResponseExtendVote{ VoteExtension: ext[:extLen], }, nil diff --git a/test/e2e/runner/cleanup.go b/test/e2e/runner/cleanup.go index 25a1008e6..5332af29c 100644 --- a/test/e2e/runner/cleanup.go +++ b/test/e2e/runner/cleanup.go @@ -3,7 +3,6 @@ package main import ( "context" "errors" - "fmt" "os" "github.com/tendermint/tendermint/libs/log" @@ -27,6 +26,6 @@ func Cleanup(ctx context.Context, logger log.Logger, testnetDir string, ti infra return err } - logger.Info(fmt.Sprintf("Removing testnet directory %q", testnetDir)) + logger.Info("Removing testnet", "directory", testnetDir) return os.RemoveAll(testnetDir) }