order |
---|
7 |
Logging adds detail and allows the node operator to better identify what they are looking for. Tendermint supports log levels on a global and per-module basis. This allows the node operator to see only the information they need and the developer to hone in on specific changes they are working on.
There are three log levels, info
, debug
and error
. These can be configured either through the command line via tendermint start --log-level ""
or within the config.toml
file.
info
Info represents an informational message. It is used to show that modules have started, stopped and how they are functioning.debug
Debug is used to trace various calls or problems. Debug is used widely throughout a codebase and can lead to overly verbose logging.error
Error represents something that has gone wrong. An error log can represent a potential problem that can lead to a node halt.Within the config.toml
:
# Output level for logging, including package level options
log-level = "info"
Via the command line:
tendermint start --log-level "info"
Here is the list of modules you may encounter in Tendermint's log and a little overview what they do.
abci-client
As mentioned in Application Development Guide, Tendermint acts as an ABCI
client with respect to the application and maintains 3 connections:
mempool, consensus and query. The code used by Tendermint Core can
be found here.blockchain
Provides storage, pool (a group of peers), and reactor
for both storing and exchanging blocks between peers.consensus
The heart of Tendermint core, which is the
implementation of the consensus algorithm. Includes two
"submodules": wal
(write-ahead logging) for ensuring data
integrity and replay
to replay blocks and messages on recovery
from a crash.
here.
You can subscribe to them by calling subscribe
RPC method. Refer
to RPC docs for additional information.mempool
Mempool module handles all incoming transactions, whenever
they are coming from peers or the application.p2p
Provides an abstraction around peer-to-peer communication. For
more details, please check out the
README.rpc-server
RPC server. For implementation details, please read the
doc.go.state
Represents the latest state and execution submodule, which
executes blocks against the application.statesync
Provides a way to quickly sync a node with pruned history.We first create three connections (mempool, consensus and query) to the
application (running kvstore
locally in this case).
I[10-04|13:54:27.364] Starting multiAppConn module=proxy impl=multiAppConn
I[10-04|13:54:27.366] Starting localClient module=abci-client connection=query impl=localClient
I[10-04|13:54:27.366] Starting localClient module=abci-client connection=mempool impl=localClient
I[10-04|13:54:27.367] Starting localClient module=abci-client connection=consensus impl=localClient
Then Tendermint Core and the application perform a handshake.
I[10-04|13:54:27.367] ABCI Handshake module=consensus appHeight=90 appHash=E0FBAFBF6FCED8B9786DDFEB1A0D4FA2501BADAD
I[10-04|13:54:27.368] ABCI Replay Blocks module=consensus appHeight=90 storeHeight=90 stateHeight=90
I[10-04|13:54:27.368] Completed ABCI Handshake - Tendermint and App are synced module=consensus appHeight=90 appHash=E0FBAFBF6FCED8B9786DDFEB1A0D4FA2501BADAD
After that, we start a few more things like the event switch, reactors, and perform UPNP discover in order to detect the IP address.
I[10-04|13:54:27.374] Starting EventSwitch module=types impl=EventSwitch
I[10-04|13:54:27.375] This node is a validator module=consensus
I[10-04|13:54:27.379] Starting Node module=main impl=Node
I[10-04|13:54:27.381] Local listener module=p2p ip=:: port=26656
I[10-04|13:54:27.382] Getting UPNP external address module=p2p
I[10-04|13:54:30.386] Could not perform UPNP discover module=p2p err="write udp4 0.0.0.0:38238->239.255.255.250:1900: i/o timeout"
I[10-04|13:54:30.386] Starting DefaultListener module=p2p impl=Listener(@10.0.2.15:26656)
I[10-04|13:54:30.387] Starting P2P Switch module=p2p impl="P2P Switch"
I[10-04|13:54:30.387] Starting MempoolReactor module=mempool impl=MempoolReactor
I[10-04|13:54:30.387] Starting BlockchainReactor module=blockchain impl=BlockchainReactor
I[10-04|13:54:30.387] Starting ConsensusReactor module=consensus impl=ConsensusReactor
I[10-04|13:54:30.387] ConsensusReactor module=consensus fastSync=false
I[10-04|13:54:30.387] Starting ConsensusState module=consensus impl=ConsensusState
I[10-04|13:54:30.387] Starting WAL module=consensus wal=/home/vagrant/.tendermint/data/cs.wal/wal impl=WAL
I[10-04|13:54:30.388] Starting TimeoutTicker module=consensus impl=TimeoutTicker
Notice the second row where Tendermint Core reports that "This node is a validator". It also could be just an observer (regular node).
Next we replay all the messages from the WAL.
I[10-04|13:54:30.390] Catchup by replaying consensus messages module=consensus height=91
I[10-04|13:54:30.390] Replay: New Step module=consensus height=91 round=0 step=RoundStepNewHeight
I[10-04|13:54:30.390] Replay: Done module=consensus
"Started node" message signals that everything is ready for work.
I[10-04|13:54:30.391] Starting RPC HTTP server on tcp socket 0.0.0.0:26657 module=rpc-server
I[10-04|13:54:30.392] Started node module=main nodeInfo="NodeInfo{id: DF22D7C92C91082324A1312F092AA1DA197FA598DBBFB6526E, moniker: anonymous, network: test-chain-3MNw2N [remote , listen 10.0.2.15:26656], version: 0.11.0-10f361fc ([wire_version=0.6.2 p2p_version=0.5.0 consensus_version=v1/0.2.2 rpc_version=0.7.0/3 tx_index=on rpc_addr=tcp://0.0.0.0:26657])}"
Next follows a standard block creation cycle, where we enter a new round, propose a block, receive more than 2/3 of prevotes, then precommits and finally have a chance to commit a block. For details, please refer to Byzantine Consensus Algorithm.
I[10-04|13:54:30.393] enterNewRound(91/0). Current: 91/0/RoundStepNewHeight module=consensus
I[10-04|13:54:30.393] enterPropose(91/0). Current: 91/0/RoundStepNewRound module=consensus
I[10-04|13:54:30.393] enterPropose: Our turn to propose module=consensus proposer=125B0E3C5512F5C2B0E1109E31885C4511570C42 privValidator="PrivValidator{125B0E3C5512F5C2B0E1109E31885C4511570C42 LH:90, LR:0, LS:3}"
I[10-04|13:54:30.394] Signed proposal module=consensus height=91 round=0 proposal="Proposal{91/0 1:21B79872514F (-1,:0:000000000000) {/10EDEDD7C84E.../}}"
I[10-04|13:54:30.397] Received complete proposal block module=consensus height=91 hash=F671D562C7B9242900A286E1882EE64E5556FE9E
I[10-04|13:54:30.397] enterPrevote(91/0). Current: 91/0/RoundStepPropose module=consensus
I[10-04|13:54:30.397] enterPrevote: ProposalBlock is valid module=consensus height=91 round=0
I[10-04|13:54:30.398] Signed and pushed vote module=consensus height=91 round=0 vote="Vote{0:125B0E3C5512 91/00/1(Prevote) F671D562C7B9 {/89047FFC21D8.../}}" err=null
I[10-04|13:54:30.401] Added to prevote module=consensus vote="Vote{0:125B0E3C5512 91/00/1(Prevote) F671D562C7B9 {/89047FFC21D8.../}}" prevotes="VoteSet{H:91 R:0 T:1 +2/3:F671D562C7B9242900A286E1882EE64E5556FE9E:1:21B79872514F BA{1:X} map[]}"
I[10-04|13:54:30.401] enterPrecommit(91/0). Current: 91/0/RoundStepPrevote module=consensus
I[10-04|13:54:30.401] enterPrecommit: +2/3 prevoted proposal block. Locking module=consensus hash=F671D562C7B9242900A286E1882EE64E5556FE9E
I[10-04|13:54:30.402] Signed and pushed vote module=consensus height=91 round=0 vote="Vote{0:125B0E3C5512 91/00/2(Precommit) F671D562C7B9 {/80533478E41A.../}}" err=null
I[10-04|13:54:30.404] Added to precommit module=consensus vote="Vote{0:125B0E3C5512 91/00/2(Precommit) F671D562C7B9 {/80533478E41A.../}}" precommits="VoteSet{H:91 R:0 T:2 +2/3:F671D562C7B9242900A286E1882EE64E5556FE9E:1:21B79872514F BA{1:X} map[]}"
I[10-04|13:54:30.404] enterCommit(91/0). Current: 91/0/RoundStepPrecommit module=consensus
I[10-04|13:54:30.405] Finalizing commit of block with 0 txs module=consensus height=91 hash=F671D562C7B9242900A286E1882EE64E5556FE9E root=E0FBAFBF6FCED8B9786DDFEB1A0D4FA2501BADAD
I[10-04|13:54:30.405] Block{
Header{
ChainID: test-chain-3MNw2N
Height: 91
Time: 2017-10-04 13:54:30.393 +0000 UTC
NumTxs: 0
LastBlockID: F15AB8BEF9A6AAB07E457A6E16BC410546AA4DC6:1:D505DA273544
LastCommit: 56FEF2EFDB8B37E9C6E6D635749DF3169D5F005D
Data:
Validators: CE25FBFF2E10C0D51AA1A07C064A96931BC8B297
App: E0FBAFBF6FCED8B9786DDFEB1A0D4FA2501BADAD
}#F671D562C7B9242900A286E1882EE64E5556FE9E
Data{
}#
Commit{
BlockID: F15AB8BEF9A6AAB07E457A6E16BC410546AA4DC6:1:D505DA273544
Precommits: Vote{0:125B0E3C5512 90/00/2(Precommit) F15AB8BEF9A6 {/FE98E2B956F0.../}}
}#56FEF2EFDB8B37E9C6E6D635749DF3169D5F005D
}#F671D562C7B9242900A286E1882EE64E5556FE9E module=consensus
I[10-04|13:54:30.408] Executed block module=state height=91 validTxs=0 invalidTxs=0
I[10-04|13:54:30.410] Committed state module=state height=91 txs=0 hash=E0FBAFBF6FCED8B9786DDFEB1A0D4FA2501BADAD
I[10-04|13:54:30.410] Recheck txs module=mempool numtxs=0 height=91