Browse Source

service: remove exported logger from base implemenation (#7381)

wb/remove-vector-tests
Sam Kleinman 2 years ago
committed by GitHub
parent
commit
a62ac27047
No known key found for this signature in database GPG Key ID: 4AEE18F83AFDEB23
40 changed files with 498 additions and 426 deletions
  1. +9
    -6
      abci/client/grpc_client.go
  2. +10
    -9
      abci/client/socket_client.go
  3. +4
    -2
      abci/server/grpc_server.go
  4. +13
    -11
      abci/server/socket_server.go
  5. +13
    -13
      internal/blocksync/pool.go
  6. +19
    -17
      internal/blocksync/reactor.go
  7. +12
    -12
      internal/consensus/byzantine_test.go
  8. +2
    -2
      internal/consensus/invalid_test.go
  9. +1
    -1
      internal/consensus/mempool_test.go
  10. +37
    -35
      internal/consensus/reactor.go
  11. +1
    -1
      internal/consensus/reactor_test.go
  12. +9
    -9
      internal/consensus/replay.go
  13. +6
    -6
      internal/consensus/replay_file.go
  14. +76
    -74
      internal/consensus/state.go
  15. +7
    -5
      internal/consensus/ticker.go
  16. +11
    -9
      internal/consensus/wal.go
  17. +1
    -4
      internal/eventbus/event_bus.go
  18. +11
    -9
      internal/evidence/reactor.go
  19. +2
    -1
      internal/libs/autofile/cmd/logjack.go
  20. +11
    -8
      internal/libs/autofile/group.go
  21. +22
    -9
      internal/libs/autofile/group_test.go
  22. +12
    -10
      internal/mempool/reactor.go
  23. +31
    -29
      internal/p2p/conn/connection.go
  24. +12
    -10
      internal/p2p/pex/reactor.go
  25. +3
    -3
      internal/p2p/router.go
  26. +0
    -1
      internal/p2p/transport_mconn.go
  27. +8
    -6
      internal/proxy/multi_app_conn.go
  28. +8
    -6
      internal/state/indexer/indexer_service.go
  29. +40
    -38
      internal/statesync/reactor.go
  30. +3
    -1
      libs/pubsub/example_test.go
  31. +8
    -7
      libs/pubsub/pubsub.go
  32. +32
    -21
      libs/pubsub/pubsub_test.go
  33. +10
    -10
      libs/service/service.go
  34. +25
    -22
      node/node.go
  35. +8
    -2
      privval/signer_client.go
  36. +2
    -2
      privval/signer_client_test.go
  37. +4
    -3
      privval/signer_dialer_endpoint.go
  38. +4
    -2
      privval/signer_endpoint.go
  39. +6
    -5
      privval/signer_listener_endpoint.go
  40. +5
    -5
      privval/signer_server.go

+ 9
- 6
abci/client/grpc_client.go View File

@ -19,6 +19,8 @@ import (
// A gRPC client. // A gRPC client.
type grpcClient struct { type grpcClient struct {
service.BaseService service.BaseService
logger log.Logger
mustConnect bool mustConnect bool
client types.ABCIApplicationClient client types.ABCIApplicationClient
@ -45,6 +47,7 @@ var _ Client = (*grpcClient)(nil)
// hopefully not :D // hopefully not :D
func NewGRPCClient(logger log.Logger, addr string, mustConnect bool) Client { func NewGRPCClient(logger log.Logger, addr string, mustConnect bool) Client {
cli := &grpcClient{ cli := &grpcClient{
logger: logger,
addr: addr, addr: addr,
mustConnect: mustConnect, mustConnect: mustConnect,
// Buffering the channel is needed to make calls appear asynchronous, // Buffering the channel is needed to make calls appear asynchronous,
@ -92,7 +95,7 @@ func (cli *grpcClient) OnStart(ctx context.Context) error {
if reqres != nil { if reqres != nil {
callCb(reqres) callCb(reqres)
} else { } else {
cli.Logger.Error("Received nil reqres")
cli.logger.Error("Received nil reqres")
} }
case <-ctx.Done(): case <-ctx.Done():
return return
@ -108,12 +111,12 @@ RETRY_LOOP:
if cli.mustConnect { if cli.mustConnect {
return err return err
} }
cli.Logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err)
cli.logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err)
time.Sleep(time.Second * dialRetryIntervalSeconds) time.Sleep(time.Second * dialRetryIntervalSeconds)
continue RETRY_LOOP continue RETRY_LOOP
} }
cli.Logger.Info("Dialed server. Waiting for echo.", "addr", cli.addr)
cli.logger.Info("Dialed server. Waiting for echo.", "addr", cli.addr)
client := types.NewABCIApplicationClient(conn) client := types.NewABCIApplicationClient(conn)
cli.conn = conn cli.conn = conn
@ -123,7 +126,7 @@ RETRY_LOOP:
if err == nil { if err == nil {
break ENSURE_CONNECTED break ENSURE_CONNECTED
} }
cli.Logger.Error("Echo failed", "err", err)
cli.logger.Error("Echo failed", "err", err)
time.Sleep(time.Second * echoRetryIntervalSeconds) time.Sleep(time.Second * echoRetryIntervalSeconds)
} }
@ -150,9 +153,9 @@ func (cli *grpcClient) StopForError(err error) {
} }
cli.mtx.Unlock() cli.mtx.Unlock()
cli.Logger.Error(fmt.Sprintf("Stopping abci.grpcClient for error: %v", err.Error()))
cli.logger.Error(fmt.Sprintf("Stopping abci.grpcClient for error: %v", err.Error()))
if err := cli.Stop(); err != nil { if err := cli.Stop(); err != nil {
cli.Logger.Error("Error stopping abci.grpcClient", "err", err)
cli.logger.Error("Error stopping abci.grpcClient", "err", err)
} }
} }


+ 10
- 9
abci/client/socket_client.go View File

@ -33,6 +33,7 @@ type reqResWithContext struct {
// general is not meant to be interfaced with concurrent callers. // general is not meant to be interfaced with concurrent callers.
type socketClient struct { type socketClient struct {
service.BaseService service.BaseService
logger log.Logger
addr string addr string
mustConnect bool mustConnect bool
@ -53,12 +54,12 @@ var _ Client = (*socketClient)(nil)
// if it fails to connect. // if it fails to connect.
func NewSocketClient(logger log.Logger, addr string, mustConnect bool) Client { func NewSocketClient(logger log.Logger, addr string, mustConnect bool) Client {
cli := &socketClient{ cli := &socketClient{
logger: logger,
reqQueue: make(chan *reqResWithContext, reqQueueSize), reqQueue: make(chan *reqResWithContext, reqQueueSize),
mustConnect: mustConnect, mustConnect: mustConnect,
addr: addr,
reqSent: list.New(),
resCb: nil,
addr: addr,
reqSent: list.New(),
resCb: nil,
} }
cli.BaseService = *service.NewBaseService(logger, "socketClient", cli) cli.BaseService = *service.NewBaseService(logger, "socketClient", cli)
return cli return cli
@ -78,7 +79,7 @@ func (cli *socketClient) OnStart(ctx context.Context) error {
if cli.mustConnect { if cli.mustConnect {
return err return err
} }
cli.Logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...",
cli.logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...",
cli.addr, dialRetryIntervalSeconds), "err", err) cli.addr, dialRetryIntervalSeconds), "err", err)
time.Sleep(time.Second * dialRetryIntervalSeconds) time.Sleep(time.Second * dialRetryIntervalSeconds)
continue continue
@ -132,7 +133,7 @@ func (cli *socketClient) sendRequestsRoutine(ctx context.Context, conn io.Writer
} }
if reqres.C.Err() != nil { if reqres.C.Err() != nil {
cli.Logger.Debug("Request's context is done", "req", reqres.R, "err", reqres.C.Err())
cli.logger.Debug("Request's context is done", "req", reqres.R, "err", reqres.C.Err())
continue continue
} }
cli.willSendReq(reqres.R) cli.willSendReq(reqres.R)
@ -162,7 +163,7 @@ func (cli *socketClient) recvResponseRoutine(ctx context.Context, conn io.Reader
return return
} }
// cli.Logger.Debug("Received response", "responseType", reflect.TypeOf(res), "response", res)
// cli.logger.Debug("Received response", "responseType", reflect.TypeOf(res), "response", res)
switch r := res.Value.(type) { switch r := res.Value.(type) {
case *types.Response_Exception: // app responded with error case *types.Response_Exception: // app responded with error
@ -589,8 +590,8 @@ func (cli *socketClient) stopForError(err error) {
cli.err = err cli.err = err
cli.mtx.Unlock() cli.mtx.Unlock()
cli.Logger.Info("Stopping abci.socketClient", "reason", err)
cli.logger.Info("Stopping abci.socketClient", "reason", err)
if err := cli.Stop(); err != nil { if err := cli.Stop(); err != nil {
cli.Logger.Error("Error stopping abci.socketClient", "err", err)
cli.logger.Error("Error stopping abci.socketClient", "err", err)
} }
} }

+ 4
- 2
abci/server/grpc_server.go View File

@ -14,6 +14,7 @@ import (
type GRPCServer struct { type GRPCServer struct {
service.BaseService service.BaseService
logger log.Logger
proto string proto string
addr string addr string
@ -27,6 +28,7 @@ type GRPCServer struct {
func NewGRPCServer(logger log.Logger, protoAddr string, app types.ABCIApplicationServer) service.Service { func NewGRPCServer(logger log.Logger, protoAddr string, app types.ABCIApplicationServer) service.Service {
proto, addr := tmnet.ProtocolAndAddress(protoAddr) proto, addr := tmnet.ProtocolAndAddress(protoAddr)
s := &GRPCServer{ s := &GRPCServer{
logger: logger,
proto: proto, proto: proto,
addr: addr, addr: addr,
listener: nil, listener: nil,
@ -48,7 +50,7 @@ func (s *GRPCServer) OnStart(ctx context.Context) error {
s.server = grpc.NewServer() s.server = grpc.NewServer()
types.RegisterABCIApplicationServer(s.server, s.app) types.RegisterABCIApplicationServer(s.server, s.app)
s.Logger.Info("Listening", "proto", s.proto, "addr", s.addr)
s.logger.Info("Listening", "proto", s.proto, "addr", s.addr)
go func() { go func() {
go func() { go func() {
<-ctx.Done() <-ctx.Done()
@ -56,7 +58,7 @@ func (s *GRPCServer) OnStart(ctx context.Context) error {
}() }()
if err := s.server.Serve(s.listener); err != nil { if err := s.server.Serve(s.listener); err != nil {
s.Logger.Error("Error serving gRPC server", "err", err)
s.logger.Error("Error serving gRPC server", "err", err)
} }
}() }()
return nil return nil


+ 13
- 11
abci/server/socket_server.go View File

@ -10,7 +10,7 @@ import (
"github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/abci/types"
tmsync "github.com/tendermint/tendermint/internal/libs/sync" tmsync "github.com/tendermint/tendermint/internal/libs/sync"
tmlog "github.com/tendermint/tendermint/libs/log"
"github.com/tendermint/tendermint/libs/log"
tmnet "github.com/tendermint/tendermint/libs/net" tmnet "github.com/tendermint/tendermint/libs/net"
"github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/libs/service"
) )
@ -19,6 +19,7 @@ import (
type SocketServer struct { type SocketServer struct {
service.BaseService service.BaseService
logger log.Logger
proto string proto string
addr string addr string
@ -32,9 +33,10 @@ type SocketServer struct {
app types.Application app types.Application
} }
func NewSocketServer(logger tmlog.Logger, protoAddr string, app types.Application) service.Service {
func NewSocketServer(logger log.Logger, protoAddr string, app types.Application) service.Service {
proto, addr := tmnet.ProtocolAndAddress(protoAddr) proto, addr := tmnet.ProtocolAndAddress(protoAddr)
s := &SocketServer{ s := &SocketServer{
logger: logger,
proto: proto, proto: proto,
addr: addr, addr: addr,
listener: nil, listener: nil,
@ -59,7 +61,7 @@ func (s *SocketServer) OnStart(ctx context.Context) error {
func (s *SocketServer) OnStop() { func (s *SocketServer) OnStop() {
if err := s.listener.Close(); err != nil { if err := s.listener.Close(); err != nil {
s.Logger.Error("Error closing listener", "err", err)
s.logger.Error("Error closing listener", "err", err)
} }
s.connsMtx.Lock() s.connsMtx.Lock()
@ -68,7 +70,7 @@ func (s *SocketServer) OnStop() {
for id, conn := range s.conns { for id, conn := range s.conns {
delete(s.conns, id) delete(s.conns, id)
if err := conn.Close(); err != nil { if err := conn.Close(); err != nil {
s.Logger.Error("Error closing connection", "id", id, "conn", conn, "err", err)
s.logger.Error("Error closing connection", "id", id, "conn", conn, "err", err)
} }
} }
} }
@ -106,17 +108,17 @@ func (s *SocketServer) acceptConnectionsRoutine(ctx context.Context) {
} }
// Accept a connection // Accept a connection
s.Logger.Info("Waiting for new connection...")
s.logger.Info("Waiting for new connection...")
conn, err := s.listener.Accept() conn, err := s.listener.Accept()
if err != nil { if err != nil {
if !s.IsRunning() { if !s.IsRunning() {
return // Ignore error from listener closing. return // Ignore error from listener closing.
} }
s.Logger.Error("Failed to accept connection", "err", err)
s.logger.Error("Failed to accept connection", "err", err)
continue continue
} }
s.Logger.Info("Accepted a new connection")
s.logger.Info("Accepted a new connection")
connID := s.addConn(conn) connID := s.addConn(conn)
@ -137,7 +139,7 @@ func (s *SocketServer) waitForClose(ctx context.Context, closeConn chan error, c
defer func() { defer func() {
// Close the connection // Close the connection
if err := s.rmConn(connID); err != nil { if err := s.rmConn(connID); err != nil {
s.Logger.Error("Error closing connection", "err", err)
s.logger.Error("Error closing connection", "err", err)
} }
}() }()
@ -147,12 +149,12 @@ func (s *SocketServer) waitForClose(ctx context.Context, closeConn chan error, c
case err := <-closeConn: case err := <-closeConn:
switch { switch {
case err == io.EOF: case err == io.EOF:
s.Logger.Error("Connection was closed by client")
s.logger.Error("Connection was closed by client")
case err != nil: case err != nil:
s.Logger.Error("Connection error", "err", err)
s.logger.Error("Connection error", "err", err)
default: default:
// never happens // never happens
s.Logger.Error("Connection was closed")
s.logger.Error("Connection was closed")
} }
} }
} }


+ 13
- 13
internal/blocksync/pool.go View File

@ -69,6 +69,8 @@ type BlockRequest struct {
// BlockPool keeps track of the block sync peers, block requests and block responses. // BlockPool keeps track of the block sync peers, block requests and block responses.
type BlockPool struct { type BlockPool struct {
service.BaseService service.BaseService
logger log.Logger
lastAdvance time.Time lastAdvance time.Time
mtx tmsync.RWMutex mtx tmsync.RWMutex
@ -101,8 +103,8 @@ func NewBlockPool(
) *BlockPool { ) *BlockPool {
bp := &BlockPool{ bp := &BlockPool{
peers: make(map[types.NodeID]*bpPeer),
logger: logger,
peers: make(map[types.NodeID]*bpPeer),
requesters: make(map[int64]*bpRequester), requesters: make(map[int64]*bpRequester),
height: start, height: start,
startHeight: start, startHeight: start,
@ -171,7 +173,7 @@ func (pool *BlockPool) removeTimedoutPeers() {
if curRate != 0 && curRate < minRecvRate { if curRate != 0 && curRate < minRecvRate {
err := errors.New("peer is not sending us data fast enough") err := errors.New("peer is not sending us data fast enough")
pool.sendError(err, peer.id) pool.sendError(err, peer.id)
pool.Logger.Error("SendTimeout", "peer", peer.id,
pool.logger.Error("SendTimeout", "peer", peer.id,
"reason", err, "reason", err,
"curRate", fmt.Sprintf("%d KB/s", curRate/1024), "curRate", fmt.Sprintf("%d KB/s", curRate/1024),
"minRate", fmt.Sprintf("%d KB/s", minRecvRate/1024)) "minRate", fmt.Sprintf("%d KB/s", minRecvRate/1024))
@ -234,7 +236,7 @@ func (pool *BlockPool) PopRequest() {
if r := pool.requesters[pool.height]; r != nil { if r := pool.requesters[pool.height]; r != nil {
if err := r.Stop(); err != nil { if err := r.Stop(); err != nil {
pool.Logger.Error("Error stopping requester", "err", err)
pool.logger.Error("Error stopping requester", "err", err)
} }
delete(pool.requesters, pool.height) delete(pool.requesters, pool.height)
pool.height++ pool.height++
@ -281,7 +283,7 @@ func (pool *BlockPool) AddBlock(peerID types.NodeID, block *types.Block, blockSi
requester := pool.requesters[block.Height] requester := pool.requesters[block.Height]
if requester == nil { if requester == nil {
pool.Logger.Error("peer sent us a block we didn't expect",
pool.logger.Error("peer sent us a block we didn't expect",
"peer", peerID, "curHeight", pool.height, "blockHeight", block.Height) "peer", peerID, "curHeight", pool.height, "blockHeight", block.Height)
diff := pool.height - block.Height diff := pool.height - block.Height
if diff < 0 { if diff < 0 {
@ -301,7 +303,7 @@ func (pool *BlockPool) AddBlock(peerID types.NodeID, block *types.Block, blockSi
} }
} else { } else {
err := errors.New("requester is different or block already exists") err := errors.New("requester is different or block already exists")
pool.Logger.Error(err.Error(), "peer", peerID, "requester", requester.getPeerID(), "blockHeight", block.Height)
pool.logger.Error(err.Error(), "peer", peerID, "requester", requester.getPeerID(), "blockHeight", block.Height)
pool.sendError(err, peerID) pool.sendError(err, peerID)
} }
} }
@ -332,7 +334,7 @@ func (pool *BlockPool) SetPeerRange(peerID types.NodeID, base int64, height int6
peer.height = height peer.height = height
} else { } else {
peer = newBPPeer(pool, peerID, base, height) peer = newBPPeer(pool, peerID, base, height)
peer.setLogger(pool.Logger.With("peer", peerID))
peer.logger = pool.logger.With("peer", peerID)
pool.peers[peerID] = peer pool.peers[peerID] = peer
} }
@ -423,7 +425,7 @@ func (pool *BlockPool) makeNextRequester(ctx context.Context) {
err := request.Start(ctx) err := request.Start(ctx)
if err != nil { if err != nil {
request.Logger.Error("Error starting request", "err", err)
request.logger.Error("Error starting request", "err", err)
} }
} }
@ -506,10 +508,6 @@ func newBPPeer(pool *BlockPool, peerID types.NodeID, base int64, height int64) *
return peer return peer
} }
func (peer *bpPeer) setLogger(l log.Logger) {
peer.logger = l
}
func (peer *bpPeer) resetMonitor() { func (peer *bpPeer) resetMonitor() {
peer.recvMonitor = flowrate.New(time.Second, time.Second*40) peer.recvMonitor = flowrate.New(time.Second, time.Second*40)
initialValue := float64(minRecvRate) * math.E initialValue := float64(minRecvRate) * math.E
@ -556,6 +554,7 @@ func (peer *bpPeer) onTimeout() {
type bpRequester struct { type bpRequester struct {
service.BaseService service.BaseService
logger log.Logger
pool *BlockPool pool *BlockPool
height int64 height int64
gotBlockCh chan struct{} gotBlockCh chan struct{}
@ -568,6 +567,7 @@ type bpRequester struct {
func newBPRequester(pool *BlockPool, height int64) *bpRequester { func newBPRequester(pool *BlockPool, height int64) *bpRequester {
bpr := &bpRequester{ bpr := &bpRequester{
logger: pool.logger,
pool: pool, pool: pool,
height: height, height: height,
gotBlockCh: make(chan struct{}, 1), gotBlockCh: make(chan struct{}, 1),
@ -677,7 +677,7 @@ OUTER_LOOP:
return return
case <-bpr.pool.exitedCh: case <-bpr.pool.exitedCh:
if err := bpr.Stop(); err != nil { if err := bpr.Stop(); err != nil {
bpr.Logger.Error("Error stopped requester", "err", err)
bpr.logger.Error("Error stopped requester", "err", err)
} }
return return
case peerID := <-bpr.redoCh: case peerID := <-bpr.redoCh:


+ 19
- 17
internal/blocksync/reactor.go View File

@ -65,6 +65,7 @@ func (e peerError) Error() string {
// Reactor handles long-term catchup syncing. // Reactor handles long-term catchup syncing.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
// immutable // immutable
initialState sm.State initialState sm.State
@ -125,6 +126,7 @@ func NewReactor(
errorsCh := make(chan peerError, maxPeerErrBuffer) // NOTE: The capacity should be larger than the peer count. errorsCh := make(chan peerError, maxPeerErrBuffer) // NOTE: The capacity should be larger than the peer count.
r := &Reactor{ r := &Reactor{
logger: logger,
initialState: state, initialState: state,
blockExec: blockExec, blockExec: blockExec,
store: store, store: store,
@ -175,7 +177,7 @@ func (r *Reactor) OnStart(ctx context.Context) error {
func (r *Reactor) OnStop() { func (r *Reactor) OnStop() {
if r.blockSync.IsSet() { if r.blockSync.IsSet() {
if err := r.pool.Stop(); err != nil { if err := r.pool.Stop(); err != nil {
r.Logger.Error("failed to stop pool", "err", err)
r.logger.Error("failed to stop pool", "err", err)
} }
} }
@ -196,7 +198,7 @@ func (r *Reactor) respondToPeer(msg *bcproto.BlockRequest, peerID types.NodeID)
if block != nil { if block != nil {
blockProto, err := block.ToProto() blockProto, err := block.ToProto()
if err != nil { if err != nil {
r.Logger.Error("failed to convert msg to protobuf", "err", err)
r.logger.Error("failed to convert msg to protobuf", "err", err)
return return
} }
@ -208,7 +210,7 @@ func (r *Reactor) respondToPeer(msg *bcproto.BlockRequest, peerID types.NodeID)
return return
} }
r.Logger.Info("peer requesting a block we do not have", "peer", peerID, "height", msg.Height)
r.logger.Info("peer requesting a block we do not have", "peer", peerID, "height", msg.Height)
r.blockSyncCh.Out <- p2p.Envelope{ r.blockSyncCh.Out <- p2p.Envelope{
To: peerID, To: peerID,
Message: &bcproto.NoBlockResponse{Height: msg.Height}, Message: &bcproto.NoBlockResponse{Height: msg.Height},
@ -219,7 +221,7 @@ func (r *Reactor) respondToPeer(msg *bcproto.BlockRequest, peerID types.NodeID)
// BlockSyncChannel. It returns an error only if the Envelope.Message is unknown // BlockSyncChannel. It returns an error only if the Envelope.Message is unknown
// for this channel. This should never be called outside of handleMessage. // for this channel. This should never be called outside of handleMessage.
func (r *Reactor) handleBlockSyncMessage(envelope p2p.Envelope) error { func (r *Reactor) handleBlockSyncMessage(envelope p2p.Envelope) error {
logger := r.Logger.With("peer", envelope.From)
logger := r.logger.With("peer", envelope.From)
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *bcproto.BlockRequest: case *bcproto.BlockRequest:
@ -263,7 +265,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
defer func() { defer func() {
if e := recover(); e != nil { if e := recover(); e != nil {
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -271,7 +273,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
} }
}() }()
r.Logger.Debug("received message", "message", envelope.Message, "peer", envelope.From)
r.logger.Debug("received message", "message", envelope.Message, "peer", envelope.From)
switch chID { switch chID {
case BlockSyncChannel: case BlockSyncChannel:
@ -296,7 +298,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) {
return return
case envelope := <-r.blockSyncCh.In: case envelope := <-r.blockSyncCh.In:
if err := r.handleMessage(r.blockSyncCh.ID, envelope); err != nil { if err := r.handleMessage(r.blockSyncCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.blockSyncCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.blockSyncCh.ID, "envelope", envelope, "err", err)
r.blockSyncCh.Error <- p2p.PeerError{ r.blockSyncCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -307,7 +309,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) {
r.blockSyncCh.Out <- envelope r.blockSyncCh.Out <- envelope
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on block sync channel; closing...")
r.logger.Debug("stopped listening on block sync channel; closing...")
return return
} }
@ -316,7 +318,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) {
// processPeerUpdate processes a PeerUpdate. // processPeerUpdate processes a PeerUpdate.
func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
r.Logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
// XXX: Pool#RedoRequest can sometimes give us an empty peer. // XXX: Pool#RedoRequest can sometimes give us an empty peer.
if len(peerUpdate.NodeID) == 0 { if len(peerUpdate.NodeID) == 0 {
@ -353,7 +355,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
r.processPeerUpdate(peerUpdate) r.processPeerUpdate(peerUpdate)
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -459,7 +461,7 @@ FOR_LOOP:
lastAdvance = r.pool.LastAdvance() lastAdvance = r.pool.LastAdvance()
) )
r.Logger.Debug(
r.logger.Debug(
"consensus ticker", "consensus ticker",
"num_pending", numPending, "num_pending", numPending,
"total", lenRequesters, "total", lenRequesters,
@ -468,13 +470,13 @@ FOR_LOOP:
switch { switch {
case r.pool.IsCaughtUp(): case r.pool.IsCaughtUp():
r.Logger.Info("switching to consensus reactor", "height", height)
r.logger.Info("switching to consensus reactor", "height", height)
case time.Since(lastAdvance) > syncTimeout: case time.Since(lastAdvance) > syncTimeout:
r.Logger.Error("no progress since last advance", "last_advance", lastAdvance)
r.logger.Error("no progress since last advance", "last_advance", lastAdvance)
default: default:
r.Logger.Info(
r.logger.Info(
"not caught up yet", "not caught up yet",
"height", height, "height", height,
"max_peer_height", r.pool.MaxPeerHeight(), "max_peer_height", r.pool.MaxPeerHeight(),
@ -484,7 +486,7 @@ FOR_LOOP:
} }
if err := r.pool.Stop(); err != nil { if err := r.pool.Stop(); err != nil {
r.Logger.Error("failed to stop pool", "err", err)
r.logger.Error("failed to stop pool", "err", err)
} }
r.blockSync.UnSet() r.blockSync.UnSet()
@ -535,7 +537,7 @@ FOR_LOOP:
err := state.Validators.VerifyCommitLight(chainID, firstID, first.Height, second.LastCommit) err := state.Validators.VerifyCommitLight(chainID, firstID, first.Height, second.LastCommit)
if err != nil { if err != nil {
err = fmt.Errorf("invalid last commit: %w", err) err = fmt.Errorf("invalid last commit: %w", err)
r.Logger.Error(
r.logger.Error(
err.Error(), err.Error(),
"last_commit", second.LastCommit, "last_commit", second.LastCommit,
"block_id", firstID, "block_id", firstID,
@ -581,7 +583,7 @@ FOR_LOOP:
if blocksSynced%100 == 0 { if blocksSynced%100 == 0 {
lastRate = 0.9*lastRate + 0.1*(100/time.Since(lastHundred).Seconds()) lastRate = 0.9*lastRate + 0.1*(100/time.Since(lastHundred).Seconds())
r.Logger.Info(
r.logger.Info(
"block sync rate", "block sync rate",
"height", r.pool.height, "height", r.pool.height,
"max_peer_height", r.pool.MaxPeerHeight(), "max_peer_height", r.pool.MaxPeerHeight(),


+ 12
- 12
internal/consensus/byzantine_test.go View File

@ -140,7 +140,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
i := 0 i := 0
for _, ps := range bzReactor.peers { for _, ps := range bzReactor.peers {
if i < len(bzReactor.peers)/2 { if i < len(bzReactor.peers)/2 {
bzNodeState.Logger.Info("signed and pushed vote", "vote", prevote1, "peer", ps.peerID)
bzNodeState.logger.Info("signed and pushed vote", "vote", prevote1, "peer", ps.peerID)
bzReactor.voteCh.Out <- p2p.Envelope{ bzReactor.voteCh.Out <- p2p.Envelope{
To: ps.peerID, To: ps.peerID,
Message: &tmcons.Vote{ Message: &tmcons.Vote{
@ -148,7 +148,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
}, },
} }
} else { } else {
bzNodeState.Logger.Info("signed and pushed vote", "vote", prevote2, "peer", ps.peerID)
bzNodeState.logger.Info("signed and pushed vote", "vote", prevote2, "peer", ps.peerID)
bzReactor.voteCh.Out <- p2p.Envelope{ bzReactor.voteCh.Out <- p2p.Envelope{
To: ps.peerID, To: ps.peerID,
Message: &tmcons.Vote{ Message: &tmcons.Vote{
@ -160,7 +160,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
i++ i++
} }
} else { } else {
bzNodeState.Logger.Info("behaving normally")
bzNodeState.logger.Info("behaving normally")
bzNodeState.defaultDoPrevote(ctx, height, round) bzNodeState.defaultDoPrevote(ctx, height, round)
} }
} }
@ -172,7 +172,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
lazyNodeState := states[1] lazyNodeState := states[1]
lazyNodeState.decideProposal = func(height int64, round int32) { lazyNodeState.decideProposal = func(height int64, round int32) {
lazyNodeState.Logger.Info("Lazy Proposer proposing condensed commit")
lazyNodeState.logger.Info("Lazy Proposer proposing condensed commit")
require.NotNil(t, lazyNodeState.privValidator) require.NotNil(t, lazyNodeState.privValidator)
var commit *types.Commit var commit *types.Commit
@ -185,7 +185,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
// Make the commit from LastCommit // Make the commit from LastCommit
commit = lazyNodeState.LastCommit.MakeCommit() commit = lazyNodeState.LastCommit.MakeCommit()
default: // This shouldn't happen. default: // This shouldn't happen.
lazyNodeState.Logger.Error("enterPropose: Cannot propose anything: No commit for the previous block")
lazyNodeState.logger.Error("enterPropose: Cannot propose anything: No commit for the previous block")
return return
} }
@ -195,7 +195,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
if lazyNodeState.privValidatorPubKey == nil { if lazyNodeState.privValidatorPubKey == nil {
// If this node is a validator & proposer in the current round, it will // If this node is a validator & proposer in the current round, it will
// miss the opportunity to create a block. // miss the opportunity to create a block.
lazyNodeState.Logger.Error(fmt.Sprintf("enterPropose: %v", errPubKeyIsNotSet))
lazyNodeState.logger.Error(fmt.Sprintf("enterPropose: %v", errPubKeyIsNotSet))
return return
} }
proposerAddr := lazyNodeState.privValidatorPubKey.Address() proposerAddr := lazyNodeState.privValidatorPubKey.Address()
@ -207,7 +207,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
// Flush the WAL. Otherwise, we may not recompute the same proposal to sign, // Flush the WAL. Otherwise, we may not recompute the same proposal to sign,
// and the privValidator will refuse to sign anything. // and the privValidator will refuse to sign anything.
if err := lazyNodeState.wal.FlushAndSync(); err != nil { if err := lazyNodeState.wal.FlushAndSync(); err != nil {
lazyNodeState.Logger.Error("Error flushing to disk")
lazyNodeState.logger.Error("Error flushing to disk")
} }
// Make proposal // Make proposal
@ -225,10 +225,10 @@ func TestByzantinePrevoteEquivocation(t *testing.T) {
lazyNodeState.Height, lazyNodeState.Round, part, lazyNodeState.Height, lazyNodeState.Round, part,
}, ""}) }, ""})
} }
lazyNodeState.Logger.Info("Signed proposal", "height", height, "round", round, "proposal", proposal)
lazyNodeState.Logger.Debug(fmt.Sprintf("Signed proposal block: %v", block))
lazyNodeState.logger.Info("Signed proposal", "height", height, "round", round, "proposal", proposal)
lazyNodeState.logger.Debug(fmt.Sprintf("Signed proposal block: %v", block))
} else if !lazyNodeState.replayMode { } else if !lazyNodeState.replayMode {
lazyNodeState.Logger.Error("enterPropose: Error signing proposal", "height", height, "round", round, "err", err)
lazyNodeState.logger.Error("enterPropose: Error signing proposal", "height", height, "round", round, "err", err)
} }
} }
@ -303,7 +303,7 @@ func TestByzantineConflictingProposalsWithPartition(t *testing.T) {
// // give the byzantine validator a normal ticker // // give the byzantine validator a normal ticker
// ticker := NewTimeoutTicker() // ticker := NewTimeoutTicker()
// ticker.SetLogger(states[0].Logger)
// ticker.SetLogger(states[0].logger)
// states[0].SetTimeoutTicker(ticker) // states[0].SetTimeoutTicker(ticker)
// p2pLogger := logger.With("module", "p2p") // p2pLogger := logger.With("module", "p2p")
@ -529,7 +529,7 @@ func TestByzantineConflictingProposalsWithPartition(t *testing.T) {
// } // }
// // Create peerState for peer // // Create peerState for peer
// peerState := NewPeerState(peer).SetLogger(br.reactor.Logger)
// peerState := NewPeerState(peer).SetLogger(br.reactor.logger)
// peer.Set(types.PeerStateKey, peerState) // peer.Set(types.PeerStateKey, peerState)
// // Send our state to peer. // // Send our state to peer.


+ 2
- 2
internal/consensus/invalid_test.go View File

@ -29,7 +29,7 @@ func TestReactorInvalidPrecommit(t *testing.T) {
t.Cleanup(cleanup) t.Cleanup(cleanup)
for i := 0; i < 4; i++ { for i := 0; i < 4; i++ {
ticker := NewTimeoutTicker(states[i].Logger)
ticker := NewTimeoutTicker(states[i].logger)
states[i].SetTimeoutTicker(ticker) states[i].SetTimeoutTicker(ticker)
} }
@ -123,7 +123,7 @@ func invalidDoPrevoteFunc(
cs.mtx.Unlock() cs.mtx.Unlock()
for _, ps := range r.peers { for _, ps := range r.peers {
cs.Logger.Info("sending bad vote", "block", blockHash, "peer", ps.peerID)
cs.logger.Info("sending bad vote", "block", blockHash, "peer", ps.peerID)
r.voteCh.Out <- p2p.Envelope{ r.voteCh.Out <- p2p.Envelope{
To: ps.peerID, To: ps.peerID,


+ 1
- 1
internal/consensus/mempool_test.go View File

@ -96,7 +96,7 @@ func TestMempoolProgressInHigherRound(t *testing.T) {
if cs.Height == 2 && cs.Round == 0 { if cs.Height == 2 && cs.Round == 0 {
// dont set the proposal in round 0 so we timeout and // dont set the proposal in round 0 so we timeout and
// go to next round // go to next round
cs.Logger.Info("Ignoring set proposal at height 2, round 0")
cs.logger.Info("Ignoring set proposal at height 2, round 0")
return nil return nil
} }
return cs.defaultSetProposal(proposal) return cs.defaultSetProposal(proposal)


+ 37
- 35
internal/consensus/reactor.go View File

@ -111,6 +111,7 @@ type ConsSyncReactor interface {
// Reactor defines a reactor for the consensus service. // Reactor defines a reactor for the consensus service.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
state *State state *State
eventBus *eventbus.EventBus eventBus *eventbus.EventBus
@ -151,6 +152,7 @@ func NewReactor(
) *Reactor { ) *Reactor {
r := &Reactor{ r := &Reactor{
logger: logger,
state: cs, state: cs,
waitSync: waitSync, waitSync: waitSync,
peers: make(map[types.NodeID]*PeerState), peers: make(map[types.NodeID]*PeerState),
@ -177,7 +179,7 @@ func NewReactor(
// messages on that p2p channel accordingly. The caller must be sure to execute // messages on that p2p channel accordingly. The caller must be sure to execute
// OnStop to ensure the outbound p2p Channels are closed. // OnStop to ensure the outbound p2p Channels are closed.
func (r *Reactor) OnStart(ctx context.Context) error { func (r *Reactor) OnStart(ctx context.Context) error {
r.Logger.Debug("consensus wait sync", "wait_sync", r.WaitSync())
r.logger.Debug("consensus wait sync", "wait_sync", r.WaitSync())
// start routine that computes peer statistics for evaluating peer quality // start routine that computes peer statistics for evaluating peer quality
// //
@ -210,7 +212,7 @@ func (r *Reactor) OnStop() {
if err := r.state.Stop(); err != nil { if err := r.state.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
r.Logger.Error("failed to stop consensus state", "err", err)
r.logger.Error("failed to stop consensus state", "err", err)
} }
} }
@ -261,7 +263,7 @@ func ReactorMetrics(metrics *Metrics) ReactorOption {
// SwitchToConsensus switches from block-sync mode to consensus mode. It resets // SwitchToConsensus switches from block-sync mode to consensus mode. It resets
// the state, turns off block-sync, and starts the consensus state-machine. // the state, turns off block-sync, and starts the consensus state-machine.
func (r *Reactor) SwitchToConsensus(ctx context.Context, state sm.State, skipWAL bool) { func (r *Reactor) SwitchToConsensus(ctx context.Context, state sm.State, skipWAL bool) {
r.Logger.Info("switching to consensus")
r.logger.Info("switching to consensus")
// we have no votes, so reconstruct LastCommit from SeenCommit // we have no votes, so reconstruct LastCommit from SeenCommit
if state.LastBlockHeight > 0 { if state.LastBlockHeight > 0 {
@ -295,7 +297,7 @@ conR:
d := types.EventDataBlockSyncStatus{Complete: true, Height: state.LastBlockHeight} d := types.EventDataBlockSyncStatus{Complete: true, Height: state.LastBlockHeight}
if err := r.eventBus.PublishEventBlockSyncStatus(ctx, d); err != nil { if err := r.eventBus.PublishEventBlockSyncStatus(ctx, d); err != nil {
r.Logger.Error("failed to emit the blocksync complete event", "err", err)
r.logger.Error("failed to emit the blocksync complete event", "err", err)
} }
} }
@ -383,7 +385,7 @@ func (r *Reactor) subscribeToBroadcastEvents() {
}, },
) )
if err != nil { if err != nil {
r.Logger.Error("failed to add listener for events", "err", err)
r.logger.Error("failed to add listener for events", "err", err)
} }
err = r.state.evsw.AddListenerForEvent( err = r.state.evsw.AddListenerForEvent(
@ -394,7 +396,7 @@ func (r *Reactor) subscribeToBroadcastEvents() {
}, },
) )
if err != nil { if err != nil {
r.Logger.Error("failed to add listener for events", "err", err)
r.logger.Error("failed to add listener for events", "err", err)
} }
err = r.state.evsw.AddListenerForEvent( err = r.state.evsw.AddListenerForEvent(
@ -405,7 +407,7 @@ func (r *Reactor) subscribeToBroadcastEvents() {
}, },
) )
if err != nil { if err != nil {
r.Logger.Error("failed to add listener for events", "err", err)
r.logger.Error("failed to add listener for events", "err", err)
} }
} }
@ -436,7 +438,7 @@ func (r *Reactor) sendNewRoundStepMessage(ctx context.Context, peerID types.Node
} }
func (r *Reactor) gossipDataForCatchup(rs *cstypes.RoundState, prs *cstypes.PeerRoundState, ps *PeerState) { func (r *Reactor) gossipDataForCatchup(rs *cstypes.RoundState, prs *cstypes.PeerRoundState, ps *PeerState) {
logger := r.Logger.With("height", prs.Height).With("peer", ps.peerID)
logger := r.logger.With("height", prs.Height).With("peer", ps.peerID)
if index, ok := prs.ProposalBlockParts.Not().PickRandom(); ok { if index, ok := prs.ProposalBlockParts.Not().PickRandom(); ok {
// ensure that the peer's PartSetHeader is correct // ensure that the peer's PartSetHeader is correct
@ -500,7 +502,7 @@ func (r *Reactor) gossipDataForCatchup(rs *cstypes.RoundState, prs *cstypes.Peer
} }
func (r *Reactor) gossipDataRoutine(ctx context.Context, ps *PeerState) { func (r *Reactor) gossipDataRoutine(ctx context.Context, ps *PeerState) {
logger := r.Logger.With("peer", ps.peerID)
logger := r.logger.With("peer", ps.peerID)
defer ps.broadcastWG.Done() defer ps.broadcastWG.Done()
@ -659,7 +661,7 @@ OUTER_LOOP:
// there is a vote to send and false otherwise. // there is a vote to send and false otherwise.
func (r *Reactor) pickSendVote(ctx context.Context, ps *PeerState, votes types.VoteSetReader) bool { func (r *Reactor) pickSendVote(ctx context.Context, ps *PeerState, votes types.VoteSetReader) bool {
if vote, ok := ps.PickVoteToSend(votes); ok { if vote, ok := ps.PickVoteToSend(votes); ok {
r.Logger.Debug("sending vote message", "ps", ps, "vote", vote)
r.logger.Debug("sending vote message", "ps", ps, "vote", vote)
select { select {
case <-ctx.Done(): case <-ctx.Done():
case r.voteCh.Out <- p2p.Envelope{ case r.voteCh.Out <- p2p.Envelope{
@ -683,7 +685,7 @@ func (r *Reactor) gossipVotesForHeight(
prs *cstypes.PeerRoundState, prs *cstypes.PeerRoundState,
ps *PeerState, ps *PeerState,
) bool { ) bool {
logger := r.Logger.With("height", prs.Height).With("peer", ps.peerID)
logger := r.logger.With("height", prs.Height).With("peer", ps.peerID)
// if there are lastCommits to send... // if there are lastCommits to send...
if prs.Step == cstypes.RoundStepNewHeight { if prs.Step == cstypes.RoundStepNewHeight {
@ -741,7 +743,7 @@ func (r *Reactor) gossipVotesForHeight(
} }
func (r *Reactor) gossipVotesRoutine(ctx context.Context, ps *PeerState) { func (r *Reactor) gossipVotesRoutine(ctx context.Context, ps *PeerState) {
logger := r.Logger.With("peer", ps.peerID)
logger := r.logger.With("peer", ps.peerID)
defer ps.broadcastWG.Done() defer ps.broadcastWG.Done()
@ -982,7 +984,7 @@ OUTER_LOOP:
// the peer. During peer removal, we remove the peer for our set of peers and // the peer. During peer removal, we remove the peer for our set of peers and
// signal to all spawned goroutines to gracefully exit in a non-blocking manner. // signal to all spawned goroutines to gracefully exit in a non-blocking manner.
func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) {
r.Logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.mtx.Lock() r.mtx.Lock()
defer r.mtx.Unlock() defer r.mtx.Unlock()
@ -1004,7 +1006,7 @@ func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpda
ps, ok = r.peers[peerUpdate.NodeID] ps, ok = r.peers[peerUpdate.NodeID]
if !ok { if !ok {
ps = NewPeerState(r.Logger, peerUpdate.NodeID)
ps = NewPeerState(r.logger, peerUpdate.NodeID)
r.peers[peerUpdate.NodeID] = ps r.peers[peerUpdate.NodeID] = ps
} }
@ -1057,7 +1059,7 @@ func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpda
func (r *Reactor) handleStateMessage(envelope p2p.Envelope, msgI Message) error { func (r *Reactor) handleStateMessage(envelope p2p.Envelope, msgI Message) error {
ps, ok := r.GetPeerState(envelope.From) ps, ok := r.GetPeerState(envelope.From)
if !ok || ps == nil { if !ok || ps == nil {
r.Logger.Debug("failed to find peer state", "peer", envelope.From, "ch_id", "StateChannel")
r.logger.Debug("failed to find peer state", "peer", envelope.From, "ch_id", "StateChannel")
return nil return nil
} }
@ -1068,7 +1070,7 @@ func (r *Reactor) handleStateMessage(envelope p2p.Envelope, msgI Message) error
r.state.mtx.RUnlock() r.state.mtx.RUnlock()
if err := msgI.(*NewRoundStepMessage).ValidateHeight(initialHeight); err != nil { if err := msgI.(*NewRoundStepMessage).ValidateHeight(initialHeight); err != nil {
r.Logger.Error("peer sent us an invalid msg", "msg", msg, "err", err)
r.logger.Error("peer sent us an invalid msg", "msg", msg, "err", err)
return err return err
} }
@ -1139,11 +1141,11 @@ func (r *Reactor) handleStateMessage(envelope p2p.Envelope, msgI Message) error
// return. This can happen when we process the envelope after the peer is // return. This can happen when we process the envelope after the peer is
// removed. // removed.
func (r *Reactor) handleDataMessage(envelope p2p.Envelope, msgI Message) error { func (r *Reactor) handleDataMessage(envelope p2p.Envelope, msgI Message) error {
logger := r.Logger.With("peer", envelope.From, "ch_id", "DataChannel")
logger := r.logger.With("peer", envelope.From, "ch_id", "DataChannel")
ps, ok := r.GetPeerState(envelope.From) ps, ok := r.GetPeerState(envelope.From)
if !ok || ps == nil { if !ok || ps == nil {
r.Logger.Debug("failed to find peer state")
r.logger.Debug("failed to find peer state")
return nil return nil
} }
@ -1181,11 +1183,11 @@ func (r *Reactor) handleDataMessage(envelope p2p.Envelope, msgI Message) error {
// return. This can happen when we process the envelope after the peer is // return. This can happen when we process the envelope after the peer is
// removed. // removed.
func (r *Reactor) handleVoteMessage(envelope p2p.Envelope, msgI Message) error { func (r *Reactor) handleVoteMessage(envelope p2p.Envelope, msgI Message) error {
logger := r.Logger.With("peer", envelope.From, "ch_id", "VoteChannel")
logger := r.logger.With("peer", envelope.From, "ch_id", "VoteChannel")
ps, ok := r.GetPeerState(envelope.From) ps, ok := r.GetPeerState(envelope.From)
if !ok || ps == nil { if !ok || ps == nil {
r.Logger.Debug("failed to find peer state")
r.logger.Debug("failed to find peer state")
return nil return nil
} }
@ -1220,11 +1222,11 @@ func (r *Reactor) handleVoteMessage(envelope p2p.Envelope, msgI Message) error {
// we perform a no-op and return. This can happen when we process the envelope // we perform a no-op and return. This can happen when we process the envelope
// after the peer is removed. // after the peer is removed.
func (r *Reactor) handleVoteSetBitsMessage(envelope p2p.Envelope, msgI Message) error { func (r *Reactor) handleVoteSetBitsMessage(envelope p2p.Envelope, msgI Message) error {
logger := r.Logger.With("peer", envelope.From, "ch_id", "VoteSetBitsChannel")
logger := r.logger.With("peer", envelope.From, "ch_id", "VoteSetBitsChannel")
ps, ok := r.GetPeerState(envelope.From) ps, ok := r.GetPeerState(envelope.From)
if !ok || ps == nil { if !ok || ps == nil {
r.Logger.Debug("failed to find peer state")
r.logger.Debug("failed to find peer state")
return nil return nil
} }
@ -1281,7 +1283,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
defer func() { defer func() {
if e := recover(); e != nil { if e := recover(); e != nil {
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -1304,7 +1306,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
return err return err
} }
r.Logger.Debug("received message", "ch_id", chID, "message", msgI, "peer", envelope.From)
r.logger.Debug("received message", "ch_id", chID, "message", msgI, "peer", envelope.From)
switch chID { switch chID {
case StateChannel: case StateChannel:
@ -1338,7 +1340,7 @@ func (r *Reactor) processStateCh(ctx context.Context) {
return return
case envelope := <-r.stateCh.In: case envelope := <-r.stateCh.In:
if err := r.handleMessage(r.stateCh.ID, envelope); err != nil { if err := r.handleMessage(r.stateCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.stateCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.stateCh.ID, "envelope", envelope, "err", err)
r.stateCh.Error <- p2p.PeerError{ r.stateCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -1346,7 +1348,7 @@ func (r *Reactor) processStateCh(ctx context.Context) {
} }
case <-r.stateCloseCh: case <-r.stateCloseCh:
r.Logger.Debug("stopped listening on StateChannel; closing...")
r.logger.Debug("stopped listening on StateChannel; closing...")
return return
} }
} }
@ -1364,7 +1366,7 @@ func (r *Reactor) processDataCh(ctx context.Context) {
return return
case envelope := <-r.dataCh.In: case envelope := <-r.dataCh.In:
if err := r.handleMessage(r.dataCh.ID, envelope); err != nil { if err := r.handleMessage(r.dataCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.dataCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.dataCh.ID, "envelope", envelope, "err", err)
r.dataCh.Error <- p2p.PeerError{ r.dataCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -1372,7 +1374,7 @@ func (r *Reactor) processDataCh(ctx context.Context) {
} }
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on DataChannel; closing...")
r.logger.Debug("stopped listening on DataChannel; closing...")
return return
} }
} }
@ -1390,7 +1392,7 @@ func (r *Reactor) processVoteCh(ctx context.Context) {
return return
case envelope := <-r.voteCh.In: case envelope := <-r.voteCh.In:
if err := r.handleMessage(r.voteCh.ID, envelope); err != nil { if err := r.handleMessage(r.voteCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.voteCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.voteCh.ID, "envelope", envelope, "err", err)
r.voteCh.Error <- p2p.PeerError{ r.voteCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -1398,7 +1400,7 @@ func (r *Reactor) processVoteCh(ctx context.Context) {
} }
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on VoteChannel; closing...")
r.logger.Debug("stopped listening on VoteChannel; closing...")
return return
} }
} }
@ -1416,7 +1418,7 @@ func (r *Reactor) processVoteSetBitsCh(ctx context.Context) {
return return
case envelope := <-r.voteSetBitsCh.In: case envelope := <-r.voteSetBitsCh.In:
if err := r.handleMessage(r.voteSetBitsCh.ID, envelope); err != nil { if err := r.handleMessage(r.voteSetBitsCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.voteSetBitsCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.voteSetBitsCh.ID, "envelope", envelope, "err", err)
r.voteSetBitsCh.Error <- p2p.PeerError{ r.voteSetBitsCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -1424,7 +1426,7 @@ func (r *Reactor) processVoteSetBitsCh(ctx context.Context) {
} }
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on VoteSetBitsChannel; closing...")
r.logger.Debug("stopped listening on VoteSetBitsChannel; closing...")
return return
} }
} }
@ -1444,7 +1446,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
r.processPeerUpdate(ctx, peerUpdate) r.processPeerUpdate(ctx, peerUpdate)
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -1453,7 +1455,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
func (r *Reactor) peerStatsRoutine(ctx context.Context) { func (r *Reactor) peerStatsRoutine(ctx context.Context) {
for { for {
if !r.IsRunning() { if !r.IsRunning() {
r.Logger.Info("stopping peerStatsRoutine")
r.logger.Info("stopping peerStatsRoutine")
return return
} }
@ -1461,7 +1463,7 @@ func (r *Reactor) peerStatsRoutine(ctx context.Context) {
case msg := <-r.state.statsMsgQueue: case msg := <-r.state.statsMsgQueue:
ps, ok := r.GetPeerState(msg.PeerID) ps, ok := r.GetPeerState(msg.PeerID)
if !ok || ps == nil { if !ok || ps == nil {
r.Logger.Debug("attempt to update stats for non-existent peer", "peer", msg.PeerID)
r.logger.Debug("attempt to update stats for non-existent peer", "peer", msg.PeerID)
continue continue
} }


+ 1
- 1
internal/consensus/reactor_test.go View File

@ -89,7 +89,7 @@ func setup(
state := states[i] state := states[i]
reactor := NewReactor( reactor := NewReactor(
state.Logger.With("node", nodeID),
state.logger.With("node", nodeID),
state, state,
rts.stateChannels[nodeID], rts.stateChannels[nodeID],
rts.dataChannels[nodeID], rts.dataChannels[nodeID],


+ 9
- 9
internal/consensus/replay.go View File

@ -47,7 +47,7 @@ func (cs *State) readReplayMessage(ctx context.Context, msg *TimedWALMessage, ne
// for logging // for logging
switch m := msg.Msg.(type) { switch m := msg.Msg.(type) {
case types.EventDataRoundState: case types.EventDataRoundState:
cs.Logger.Info("Replay: New Step", "height", m.Height, "round", m.Round, "step", m.Step)
cs.logger.Info("Replay: New Step", "height", m.Height, "round", m.Round, "step", m.Step)
// these are playback checks // these are playback checks
if newStepSub != nil { if newStepSub != nil {
ctx, cancel := context.WithTimeout(ctx, 2*time.Second) ctx, cancel := context.WithTimeout(ctx, 2*time.Second)
@ -71,19 +71,19 @@ func (cs *State) readReplayMessage(ctx context.Context, msg *TimedWALMessage, ne
switch msg := m.Msg.(type) { switch msg := m.Msg.(type) {
case *ProposalMessage: case *ProposalMessage:
p := msg.Proposal p := msg.Proposal
cs.Logger.Info("Replay: Proposal", "height", p.Height, "round", p.Round, "header",
cs.logger.Info("Replay: Proposal", "height", p.Height, "round", p.Round, "header",
p.BlockID.PartSetHeader, "pol", p.POLRound, "peer", peerID) p.BlockID.PartSetHeader, "pol", p.POLRound, "peer", peerID)
case *BlockPartMessage: case *BlockPartMessage:
cs.Logger.Info("Replay: BlockPart", "height", msg.Height, "round", msg.Round, "peer", peerID)
cs.logger.Info("Replay: BlockPart", "height", msg.Height, "round", msg.Round, "peer", peerID)
case *VoteMessage: case *VoteMessage:
v := msg.Vote v := msg.Vote
cs.Logger.Info("Replay: Vote", "height", v.Height, "round", v.Round, "type", v.Type,
cs.logger.Info("Replay: Vote", "height", v.Height, "round", v.Round, "type", v.Type,
"blockID", v.BlockID, "peer", peerID) "blockID", v.BlockID, "peer", peerID)
} }
cs.handleMsg(ctx, m) cs.handleMsg(ctx, m)
case timeoutInfo: case timeoutInfo:
cs.Logger.Info("Replay: Timeout", "height", m.Height, "round", m.Round, "step", m.Step, "dur", m.Duration)
cs.logger.Info("Replay: Timeout", "height", m.Height, "round", m.Round, "step", m.Step, "dur", m.Duration)
cs.handleTimeout(ctx, m, cs.RoundState) cs.handleTimeout(ctx, m, cs.RoundState)
default: default:
return fmt.Errorf("replay: Unknown TimedWALMessage type: %v", reflect.TypeOf(msg.Msg)) return fmt.Errorf("replay: Unknown TimedWALMessage type: %v", reflect.TypeOf(msg.Msg))
@ -130,7 +130,7 @@ func (cs *State) catchupReplay(ctx context.Context, csHeight int64) error {
} }
gr, found, err = cs.wal.SearchForEndHeight(endHeight, &WALSearchOptions{IgnoreDataCorruptionErrors: true}) gr, found, err = cs.wal.SearchForEndHeight(endHeight, &WALSearchOptions{IgnoreDataCorruptionErrors: true})
if err == io.EOF { if err == io.EOF {
cs.Logger.Error("Replay: wal.group.Search returned EOF", "#ENDHEIGHT", endHeight)
cs.logger.Error("Replay: wal.group.Search returned EOF", "#ENDHEIGHT", endHeight)
} else if err != nil { } else if err != nil {
return err return err
} }
@ -139,7 +139,7 @@ func (cs *State) catchupReplay(ctx context.Context, csHeight int64) error {
} }
defer gr.Close() defer gr.Close()
cs.Logger.Info("Catchup by replaying consensus messages", "height", csHeight)
cs.logger.Info("Catchup by replaying consensus messages", "height", csHeight)
var msg *TimedWALMessage var msg *TimedWALMessage
dec := WALDecoder{gr} dec := WALDecoder{gr}
@ -151,7 +151,7 @@ LOOP:
case err == io.EOF: case err == io.EOF:
break LOOP break LOOP
case IsDataCorruptionError(err): case IsDataCorruptionError(err):
cs.Logger.Error("data has been corrupted in last height of consensus WAL", "err", err, "height", csHeight)
cs.logger.Error("data has been corrupted in last height of consensus WAL", "err", err, "height", csHeight)
return err return err
case err != nil: case err != nil:
return err return err
@ -164,7 +164,7 @@ LOOP:
return err return err
} }
} }
cs.Logger.Info("Replay: Done")
cs.logger.Info("Replay: Done")
return nil return nil
} }


+ 6
- 6
internal/consensus/replay_file.go View File

@ -74,7 +74,7 @@ func (cs *State) ReplayFile(ctx context.Context, file string, console bool) erro
defer func() { defer func() {
args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep} args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep}
if err := cs.eventBus.Unsubscribe(ctx, args); err != nil { if err := cs.eventBus.Unsubscribe(ctx, args); err != nil {
cs.Logger.Error("Error unsubscribing to event bus", "err", err)
cs.logger.Error("Error unsubscribing to event bus", "err", err)
} }
}() }()
@ -147,7 +147,7 @@ func (pb *playback) replayReset(ctx context.Context, count int, newStepSub event
} }
pb.cs.Wait() pb.cs.Wait()
newCS := NewState(ctx, pb.cs.Logger, pb.cs.config, pb.genesisState.Copy(), pb.cs.blockExec,
newCS := NewState(ctx, pb.cs.logger, pb.cs.config, pb.genesisState.Copy(), pb.cs.blockExec,
pb.cs.blockStore, pb.cs.txNotifier, pb.cs.evpool) pb.cs.blockStore, pb.cs.txNotifier, pb.cs.evpool)
newCS.SetEventBus(pb.cs.eventBus) newCS.SetEventBus(pb.cs.eventBus)
newCS.startForReplay() newCS.startForReplay()
@ -182,7 +182,7 @@ func (pb *playback) replayReset(ctx context.Context, count int, newStepSub event
} }
func (cs *State) startForReplay() { func (cs *State) startForReplay() {
cs.Logger.Error("Replay commands are disabled until someone updates them and writes tests")
cs.logger.Error("Replay commands are disabled until someone updates them and writes tests")
} }
// console function for parsing input and running commands. The integer // console function for parsing input and running commands. The integer
@ -238,13 +238,13 @@ func (pb *playback) replayConsoleLoop() (int, error) {
defer func() { defer func() {
args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep} args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep}
if err := pb.cs.eventBus.Unsubscribe(ctx, args); err != nil { if err := pb.cs.eventBus.Unsubscribe(ctx, args); err != nil {
pb.cs.Logger.Error("Error unsubscribing from eventBus", "err", err)
pb.cs.logger.Error("Error unsubscribing from eventBus", "err", err)
} }
}() }()
if len(tokens) == 1 { if len(tokens) == 1 {
if err := pb.replayReset(ctx, 1, newStepSub); err != nil { if err := pb.replayReset(ctx, 1, newStepSub); err != nil {
pb.cs.Logger.Error("Replay reset error", "err", err)
pb.cs.logger.Error("Replay reset error", "err", err)
} }
} else { } else {
i, err := strconv.Atoi(tokens[1]) i, err := strconv.Atoi(tokens[1])
@ -253,7 +253,7 @@ func (pb *playback) replayConsoleLoop() (int, error) {
} else if i > pb.count { } else if i > pb.count {
fmt.Printf("argument to back must not be larger than the current count (%d)\n", pb.count) fmt.Printf("argument to back must not be larger than the current count (%d)\n", pb.count)
} else if err := pb.replayReset(ctx, i, newStepSub); err != nil { } else if err := pb.replayReset(ctx, i, newStepSub); err != nil {
pb.cs.Logger.Error("Replay reset error", "err", err)
pb.cs.logger.Error("Replay reset error", "err", err)
} }
} }


+ 76
- 74
internal/consensus/state.go View File

@ -79,6 +79,7 @@ type evidencePool interface {
// The internal state machine receives input from peers, the internal validator, and from a timer. // The internal state machine receives input from peers, the internal validator, and from a timer.
type State struct { type State struct {
service.BaseService service.BaseService
logger log.Logger
// config details // config details
config *config.ConsensusConfig config *config.ConsensusConfig
@ -164,6 +165,7 @@ func NewState(
options ...StateOption, options ...StateOption,
) *State { ) *State {
cs := &State{ cs := &State{
logger: logger,
config: cfg, config: cfg,
blockExec: blockExec, blockExec: blockExec,
blockStore: blockStore, blockStore: blockStore,
@ -291,13 +293,13 @@ func (cs *State) SetPrivValidator(priv types.PrivValidator) {
case *types.ErroringMockPV: case *types.ErroringMockPV:
cs.privValidatorType = types.ErrorMockSignerClient cs.privValidatorType = types.ErrorMockSignerClient
default: default:
cs.Logger.Error("unsupported priv validator type", "err",
cs.logger.Error("unsupported priv validator type", "err",
fmt.Errorf("error privValidatorType %s", t)) fmt.Errorf("error privValidatorType %s", t))
} }
} }
if err := cs.updatePrivValidatorPubKey(); err != nil { if err := cs.updatePrivValidatorPubKey(); err != nil {
cs.Logger.Error("failed to get private validator pubkey", "err", err)
cs.logger.Error("failed to get private validator pubkey", "err", err)
} }
} }
@ -352,14 +354,14 @@ func (cs *State) OnStart(ctx context.Context) error {
break LOOP break LOOP
case !IsDataCorruptionError(err): case !IsDataCorruptionError(err):
cs.Logger.Error("error on catchup replay; proceeding to start state anyway", "err", err)
cs.logger.Error("error on catchup replay; proceeding to start state anyway", "err", err)
break LOOP break LOOP
case repairAttempted: case repairAttempted:
return err return err
} }
cs.Logger.Error("the WAL file is corrupted; attempting repair", "err", err)
cs.logger.Error("the WAL file is corrupted; attempting repair", "err", err)
// 1) prep work // 1) prep work
if err := cs.wal.Stop(); err != nil { if err := cs.wal.Stop(); err != nil {
@ -375,15 +377,15 @@ func (cs *State) OnStart(ctx context.Context) error {
return err return err
} }
cs.Logger.Debug("backed up WAL file", "src", cs.config.WalFile(), "dst", corruptedFile)
cs.logger.Debug("backed up WAL file", "src", cs.config.WalFile(), "dst", corruptedFile)
// 3) try to repair (WAL file will be overwritten!) // 3) try to repair (WAL file will be overwritten!)
if err := repairWalFile(corruptedFile, cs.config.WalFile()); err != nil { if err := repairWalFile(corruptedFile, cs.config.WalFile()); err != nil {
cs.Logger.Error("the WAL repair failed", "err", err)
cs.logger.Error("the WAL repair failed", "err", err)
return err return err
} }
cs.Logger.Info("successful WAL repair")
cs.logger.Info("successful WAL repair")
// reload WAL file // reload WAL file
if err := cs.loadWalFile(ctx); err != nil { if err := cs.loadWalFile(ctx); err != nil {
@ -427,7 +429,7 @@ func (cs *State) OnStart(ctx context.Context) error {
func (cs *State) startRoutines(ctx context.Context, maxSteps int) { func (cs *State) startRoutines(ctx context.Context, maxSteps int) {
err := cs.timeoutTicker.Start(ctx) err := cs.timeoutTicker.Start(ctx)
if err != nil { if err != nil {
cs.Logger.Error("failed to start timeout ticker", "err", err)
cs.logger.Error("failed to start timeout ticker", "err", err)
return return
} }
@ -438,7 +440,7 @@ func (cs *State) startRoutines(ctx context.Context, maxSteps int) {
func (cs *State) loadWalFile(ctx context.Context) error { func (cs *State) loadWalFile(ctx context.Context) error {
wal, err := cs.OpenWAL(ctx, cs.config.WalFile()) wal, err := cs.OpenWAL(ctx, cs.config.WalFile())
if err != nil { if err != nil {
cs.Logger.Error("failed to load state WAL", "err", err)
cs.logger.Error("failed to load state WAL", "err", err)
return err return err
} }
@ -453,7 +455,7 @@ func (cs *State) OnStop() {
select { select {
case <-cs.onStopCh: case <-cs.onStopCh:
case <-time.After(cs.config.TimeoutCommit): case <-time.After(cs.config.TimeoutCommit):
cs.Logger.Error("OnStop: timeout waiting for commit to finish", "time", cs.config.TimeoutCommit)
cs.logger.Error("OnStop: timeout waiting for commit to finish", "time", cs.config.TimeoutCommit)
} }
} }
@ -462,7 +464,7 @@ func (cs *State) OnStop() {
if cs.evsw.IsRunning() { if cs.evsw.IsRunning() {
if err := cs.evsw.Stop(); err != nil { if err := cs.evsw.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
cs.Logger.Error("failed trying to stop eventSwitch", "error", err)
cs.logger.Error("failed trying to stop eventSwitch", "error", err)
} }
} }
} }
@ -470,7 +472,7 @@ func (cs *State) OnStop() {
if cs.timeoutTicker.IsRunning() { if cs.timeoutTicker.IsRunning() {
if err := cs.timeoutTicker.Stop(); err != nil { if err := cs.timeoutTicker.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
cs.Logger.Error("failed trying to stop timeoutTicket", "error", err)
cs.logger.Error("failed trying to stop timeoutTicket", "error", err)
} }
} }
} }
@ -487,14 +489,14 @@ func (cs *State) Wait() {
// OpenWAL opens a file to log all consensus messages and timeouts for // OpenWAL opens a file to log all consensus messages and timeouts for
// deterministic accountability. // deterministic accountability.
func (cs *State) OpenWAL(ctx context.Context, walFile string) (WAL, error) { func (cs *State) OpenWAL(ctx context.Context, walFile string) (WAL, error) {
wal, err := NewWAL(cs.Logger.With("wal", walFile), walFile)
wal, err := NewWAL(cs.logger.With("wal", walFile), walFile)
if err != nil { if err != nil {
cs.Logger.Error("failed to open WAL", "file", walFile, "err", err)
cs.logger.Error("failed to open WAL", "file", walFile, "err", err)
return nil, err return nil, err
} }
if err := wal.Start(ctx); err != nil { if err := wal.Start(ctx); err != nil {
cs.Logger.Error("failed to start WAL", "err", err)
cs.logger.Error("failed to start WAL", "err", err)
return nil, err return nil, err
} }
@ -583,7 +585,7 @@ func (cs *State) updateRoundStep(round int32, step cstypes.RoundStepType) {
// enterNewRound(height, 0) at cs.StartTime. // enterNewRound(height, 0) at cs.StartTime.
func (cs *State) scheduleRound0(rs *cstypes.RoundState) { func (cs *State) scheduleRound0(rs *cstypes.RoundState) {
// cs.Logger.Info("scheduleRound0", "now", tmtime.Now(), "startTime", cs.StartTime)
// cs.logger.Info("scheduleRound0", "now", tmtime.Now(), "startTime", cs.StartTime)
sleepDuration := rs.StartTime.Sub(tmtime.Now()) sleepDuration := rs.StartTime.Sub(tmtime.Now())
cs.scheduleTimeout(sleepDuration, rs.Height, 0, cstypes.RoundStepNewHeight) cs.scheduleTimeout(sleepDuration, rs.Height, 0, cstypes.RoundStepNewHeight)
} }
@ -603,7 +605,7 @@ func (cs *State) sendInternalMessage(ctx context.Context, mi msgInfo) {
// be processed out of order. // be processed out of order.
// TODO: use CList here for strict determinism and // TODO: use CList here for strict determinism and
// attempt push to internalMsgQueue in receiveRoutine // attempt push to internalMsgQueue in receiveRoutine
cs.Logger.Debug("internal msg queue is full; using a go-routine")
cs.logger.Debug("internal msg queue is full; using a go-routine")
go func() { go func() {
select { select {
case <-ctx.Done(): case <-ctx.Done():
@ -668,7 +670,7 @@ func (cs *State) updateToState(ctx context.Context, state sm.State) {
// signal the new round step, because other services (eg. txNotifier) // signal the new round step, because other services (eg. txNotifier)
// depend on having an up-to-date peer state! // depend on having an up-to-date peer state!
if state.LastBlockHeight <= cs.state.LastBlockHeight { if state.LastBlockHeight <= cs.state.LastBlockHeight {
cs.Logger.Debug(
cs.logger.Debug(
"ignoring updateToState()", "ignoring updateToState()",
"new_height", state.LastBlockHeight+1, "new_height", state.LastBlockHeight+1,
"old_height", cs.state.LastBlockHeight+1, "old_height", cs.state.LastBlockHeight+1,
@ -748,7 +750,7 @@ func (cs *State) updateToState(ctx context.Context, state sm.State) {
func (cs *State) newStep(ctx context.Context) { func (cs *State) newStep(ctx context.Context) {
rs := cs.RoundStateEvent() rs := cs.RoundStateEvent()
if err := cs.wal.Write(rs); err != nil { if err := cs.wal.Write(rs); err != nil {
cs.Logger.Error("failed writing to WAL", "err", err)
cs.logger.Error("failed writing to WAL", "err", err)
} }
cs.nSteps++ cs.nSteps++
@ -756,7 +758,7 @@ func (cs *State) newStep(ctx context.Context) {
// newStep is called by updateToState in NewState before the eventBus is set! // newStep is called by updateToState in NewState before the eventBus is set!
if cs.eventBus != nil { if cs.eventBus != nil {
if err := cs.eventBus.PublishEventNewRoundStep(ctx, rs); err != nil { if err := cs.eventBus.PublishEventNewRoundStep(ctx, rs); err != nil {
cs.Logger.Error("failed publishing new round step", "err", err)
cs.logger.Error("failed publishing new round step", "err", err)
} }
cs.evsw.FireEvent(types.EventNewRoundStepValue, &cs.RoundState) cs.evsw.FireEvent(types.EventNewRoundStepValue, &cs.RoundState)
@ -780,7 +782,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) {
// close wal now that we're done writing to it // close wal now that we're done writing to it
if err := cs.wal.Stop(); err != nil { if err := cs.wal.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
cs.Logger.Error("failed trying to stop WAL", "error", err)
cs.logger.Error("failed trying to stop WAL", "error", err)
} }
} }
@ -790,7 +792,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) {
defer func() { defer func() {
if r := recover(); r != nil { if r := recover(); r != nil {
cs.Logger.Error("CONSENSUS FAILURE!!!", "err", r, "stack", string(debug.Stack()))
cs.logger.Error("CONSENSUS FAILURE!!!", "err", r, "stack", string(debug.Stack()))
// stop gracefully // stop gracefully
// //
// NOTE: We most probably shouldn't be running any further when there is // NOTE: We most probably shouldn't be running any further when there is
@ -806,7 +808,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) {
for { for {
if maxSteps > 0 { if maxSteps > 0 {
if cs.nSteps >= maxSteps { if cs.nSteps >= maxSteps {
cs.Logger.Debug("reached max steps; exiting receive routine")
cs.logger.Debug("reached max steps; exiting receive routine")
cs.nSteps = 0 cs.nSteps = 0
return return
} }
@ -821,7 +823,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) {
case mi = <-cs.peerMsgQueue: case mi = <-cs.peerMsgQueue:
if err := cs.wal.Write(mi); err != nil { if err := cs.wal.Write(mi); err != nil {
cs.Logger.Error("failed writing to WAL", "err", err)
cs.logger.Error("failed writing to WAL", "err", err)
} }
// handles proposals, block parts, votes // handles proposals, block parts, votes
@ -850,7 +852,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) {
case ti := <-cs.timeoutTicker.Chan(): // tockChan: case ti := <-cs.timeoutTicker.Chan(): // tockChan:
if err := cs.wal.Write(ti); err != nil { if err := cs.wal.Write(ti); err != nil {
cs.Logger.Error("failed writing to WAL", "err", err)
cs.logger.Error("failed writing to WAL", "err", err)
} }
// if the timeout is relevant to the rs // if the timeout is relevant to the rs
@ -896,7 +898,7 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) {
} }
if err != nil && msg.Round != cs.Round { if err != nil && msg.Round != cs.Round {
cs.Logger.Debug(
cs.logger.Debug(
"received block part from wrong round", "received block part from wrong round",
"height", cs.Height, "height", cs.Height,
"cs_round", cs.Round, "cs_round", cs.Round,
@ -933,12 +935,12 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) {
// We could make note of this and help filter in broadcastHasVoteMessage(). // We could make note of this and help filter in broadcastHasVoteMessage().
default: default:
cs.Logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg))
cs.logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg))
return return
} }
if err != nil { if err != nil {
cs.Logger.Error(
cs.logger.Error(
"failed to process message", "failed to process message",
"height", cs.Height, "height", cs.Height,
"round", cs.Round, "round", cs.Round,
@ -954,11 +956,11 @@ func (cs *State) handleTimeout(
ti timeoutInfo, ti timeoutInfo,
rs cstypes.RoundState, rs cstypes.RoundState,
) { ) {
cs.Logger.Debug("received tock", "timeout", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
cs.logger.Debug("received tock", "timeout", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
// timeouts must be for current height, round, step // timeouts must be for current height, round, step
if ti.Height != rs.Height || ti.Round < rs.Round || (ti.Round == rs.Round && ti.Step < rs.Step) { if ti.Height != rs.Height || ti.Round < rs.Round || (ti.Round == rs.Round && ti.Step < rs.Step) {
cs.Logger.Debug("ignoring tock because we are ahead", "height", rs.Height, "round", rs.Round, "step", rs.Step)
cs.logger.Debug("ignoring tock because we are ahead", "height", rs.Height, "round", rs.Round, "step", rs.Step)
return return
} }
@ -977,21 +979,21 @@ func (cs *State) handleTimeout(
case cstypes.RoundStepPropose: case cstypes.RoundStepPropose:
if err := cs.eventBus.PublishEventTimeoutPropose(ctx, cs.RoundStateEvent()); err != nil { if err := cs.eventBus.PublishEventTimeoutPropose(ctx, cs.RoundStateEvent()); err != nil {
cs.Logger.Error("failed publishing timeout propose", "err", err)
cs.logger.Error("failed publishing timeout propose", "err", err)
} }
cs.enterPrevote(ctx, ti.Height, ti.Round) cs.enterPrevote(ctx, ti.Height, ti.Round)
case cstypes.RoundStepPrevoteWait: case cstypes.RoundStepPrevoteWait:
if err := cs.eventBus.PublishEventTimeoutWait(ctx, cs.RoundStateEvent()); err != nil { if err := cs.eventBus.PublishEventTimeoutWait(ctx, cs.RoundStateEvent()); err != nil {
cs.Logger.Error("failed publishing timeout wait", "err", err)
cs.logger.Error("failed publishing timeout wait", "err", err)
} }
cs.enterPrecommit(ctx, ti.Height, ti.Round) cs.enterPrecommit(ctx, ti.Height, ti.Round)
case cstypes.RoundStepPrecommitWait: case cstypes.RoundStepPrecommitWait:
if err := cs.eventBus.PublishEventTimeoutWait(ctx, cs.RoundStateEvent()); err != nil { if err := cs.eventBus.PublishEventTimeoutWait(ctx, cs.RoundStateEvent()); err != nil {
cs.Logger.Error("failed publishing timeout wait", "err", err)
cs.logger.Error("failed publishing timeout wait", "err", err)
} }
cs.enterPrecommit(ctx, ti.Height, ti.Round) cs.enterPrecommit(ctx, ti.Height, ti.Round)
@ -1039,7 +1041,7 @@ func (cs *State) handleTxsAvailable(ctx context.Context) {
// Enter: +2/3 prevotes any or +2/3 precommits for block or any from (height, round) // Enter: +2/3 prevotes any or +2/3 precommits for block or any from (height, round)
// NOTE: cs.StartTime was already set for height. // NOTE: cs.StartTime was already set for height.
func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) { func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) { if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) {
logger.Debug( logger.Debug(
@ -1082,7 +1084,7 @@ func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) {
cs.TriggeredTimeoutPrecommit = false cs.TriggeredTimeoutPrecommit = false
if err := cs.eventBus.PublishEventNewRound(ctx, cs.NewRoundEvent()); err != nil { if err := cs.eventBus.PublishEventNewRound(ctx, cs.NewRoundEvent()); err != nil {
cs.Logger.Error("failed publishing new round", "err", err)
cs.logger.Error("failed publishing new round", "err", err)
} }
cs.metrics.Rounds.Set(float64(round)) cs.metrics.Rounds.Set(float64(round))
@ -1121,7 +1123,7 @@ func (cs *State) needProofBlock(height int64) bool {
// after enterNewRound(height,round), after timeout of CreateEmptyBlocksInterval // after enterNewRound(height,round), after timeout of CreateEmptyBlocksInterval
// Enter (!CreateEmptyBlocks) : after enterNewRound(height,round), once txs are in the mempool // Enter (!CreateEmptyBlocks) : after enterNewRound(height,round), once txs are in the mempool
func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { func (cs *State) enterPropose(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) {
logger.Debug( logger.Debug(
@ -1210,7 +1212,7 @@ func (cs *State) defaultDecideProposal(height int64, round int32) {
// Flush the WAL. Otherwise, we may not recompute the same proposal to sign, // Flush the WAL. Otherwise, we may not recompute the same proposal to sign,
// and the privValidator will refuse to sign anything. // and the privValidator will refuse to sign anything.
if err := cs.wal.FlushAndSync(); err != nil { if err := cs.wal.FlushAndSync(); err != nil {
cs.Logger.Error("failed flushing WAL to disk")
cs.logger.Error("failed flushing WAL to disk")
} }
// Make proposal // Make proposal
@ -1232,9 +1234,9 @@ func (cs *State) defaultDecideProposal(height int64, round int32) {
cs.sendInternalMessage(ctx, msgInfo{&BlockPartMessage{cs.Height, cs.Round, part}, ""}) cs.sendInternalMessage(ctx, msgInfo{&BlockPartMessage{cs.Height, cs.Round, part}, ""})
} }
cs.Logger.Debug("signed proposal", "height", height, "round", round, "proposal", proposal)
cs.logger.Debug("signed proposal", "height", height, "round", round, "proposal", proposal)
} else if !cs.replayMode { } else if !cs.replayMode {
cs.Logger.Error("propose step; failed signing proposal", "height", height, "round", round, "err", err)
cs.logger.Error("propose step; failed signing proposal", "height", height, "round", round, "err", err)
} }
} }
@ -1278,14 +1280,14 @@ func (cs *State) createProposalBlock() (block *types.Block, blockParts *types.Pa
commit = cs.LastCommit.MakeCommit() commit = cs.LastCommit.MakeCommit()
default: // This shouldn't happen. default: // This shouldn't happen.
cs.Logger.Error("propose step; cannot propose anything without commit for the previous block")
cs.logger.Error("propose step; cannot propose anything without commit for the previous block")
return return
} }
if cs.privValidatorPubKey == nil { if cs.privValidatorPubKey == nil {
// If this node is a validator & proposer in the current round, it will // If this node is a validator & proposer in the current round, it will
// miss the opportunity to create a block. // miss the opportunity to create a block.
cs.Logger.Error("propose step; empty priv validator public key", "err", errPubKeyIsNotSet)
cs.logger.Error("propose step; empty priv validator public key", "err", errPubKeyIsNotSet)
return return
} }
@ -1299,7 +1301,7 @@ func (cs *State) createProposalBlock() (block *types.Block, blockParts *types.Pa
// Prevote for LockedBlock if we're locked, or ProposalBlock if valid. // Prevote for LockedBlock if we're locked, or ProposalBlock if valid.
// Otherwise vote nil. // Otherwise vote nil.
func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) { func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) {
logger.Debug( logger.Debug(
@ -1325,7 +1327,7 @@ func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) {
} }
func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32) { func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
// If a block is locked, prevote that. // If a block is locked, prevote that.
if cs.LockedBlock != nil { if cs.LockedBlock != nil {
@ -1359,7 +1361,7 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32
// Enter: any +2/3 prevotes at next round. // Enter: any +2/3 prevotes at next round.
func (cs *State) enterPrevoteWait(ctx context.Context, height int64, round int32) { func (cs *State) enterPrevoteWait(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) {
logger.Debug( logger.Debug(
@ -1395,7 +1397,7 @@ func (cs *State) enterPrevoteWait(ctx context.Context, height int64, round int32
// else, unlock an existing lock and precommit nil if +2/3 of prevotes were nil, // else, unlock an existing lock and precommit nil if +2/3 of prevotes were nil,
// else, precommit nil otherwise. // else, precommit nil otherwise.
func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) { func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) {
logger.Debug( logger.Debug(
@ -1517,7 +1519,7 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
// Enter: any +2/3 precommits for next round. // Enter: any +2/3 precommits for next round.
func (cs *State) enterPrecommitWait(ctx context.Context, height int64, round int32) { func (cs *State) enterPrecommitWait(ctx context.Context, height int64, round int32) {
logger := cs.Logger.With("height", height, "round", round)
logger := cs.logger.With("height", height, "round", round)
if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) { if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) {
logger.Debug( logger.Debug(
@ -1549,7 +1551,7 @@ func (cs *State) enterPrecommitWait(ctx context.Context, height int64, round int
// Enter: +2/3 precommits for block // Enter: +2/3 precommits for block
func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int32) { func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int32) {
logger := cs.Logger.With("height", height, "commit_round", commitRound)
logger := cs.logger.With("height", height, "commit_round", commitRound)
if cs.Height != height || cstypes.RoundStepCommit <= cs.Step { if cs.Height != height || cstypes.RoundStepCommit <= cs.Step {
logger.Debug( logger.Debug(
@ -1612,7 +1614,7 @@ func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int3
// If we have the block AND +2/3 commits for it, finalize. // If we have the block AND +2/3 commits for it, finalize.
func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) { func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) {
logger := cs.Logger.With("height", height)
logger := cs.logger.With("height", height)
if cs.Height != height { if cs.Height != height {
panic(fmt.Sprintf("tryFinalizeCommit() cs.Height: %v vs height: %v", cs.Height, height)) panic(fmt.Sprintf("tryFinalizeCommit() cs.Height: %v vs height: %v", cs.Height, height))
@ -1640,7 +1642,7 @@ func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) {
// Increment height and goto cstypes.RoundStepNewHeight // Increment height and goto cstypes.RoundStepNewHeight
func (cs *State) finalizeCommit(ctx context.Context, height int64) { func (cs *State) finalizeCommit(ctx context.Context, height int64) {
logger := cs.Logger.With("height", height)
logger := cs.logger.With("height", height)
if cs.Height != height || cs.Step != cstypes.RoundStepCommit { if cs.Height != height || cs.Step != cstypes.RoundStepCommit {
logger.Debug( logger.Debug(
@ -1777,7 +1779,7 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) {
address types.Address address types.Address
) )
if commitSize != valSetLen { 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",
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)) commitSize, valSetLen, block.Height, block.LastCommit.Signatures, cs.LastValidators.Validators))
return return
} }
@ -1785,7 +1787,7 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) {
if cs.privValidator != nil { if cs.privValidator != nil {
if cs.privValidatorPubKey == nil { if cs.privValidatorPubKey == nil {
// Metrics won't be updated, but it's not critical. // Metrics won't be updated, but it's not critical.
cs.Logger.Error(fmt.Sprintf("recordMetrics: %v", errPubKeyIsNotSet))
cs.logger.Error(fmt.Sprintf("recordMetrics: %v", errPubKeyIsNotSet))
} else { } else {
address = cs.privValidatorPubKey.Address() address = cs.privValidatorPubKey.Address()
} }
@ -1884,7 +1886,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal) error {
cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader) cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader)
} }
cs.Logger.Info("received proposal", "proposal", proposal)
cs.logger.Info("received proposal", "proposal", proposal)
return nil return nil
} }
@ -1900,7 +1902,7 @@ func (cs *State) addProposalBlockPart(
// Blocks might be reused, so round mismatch is OK // Blocks might be reused, so round mismatch is OK
if cs.Height != height { if cs.Height != height {
cs.Logger.Debug("received block part from wrong height", "height", height, "round", round)
cs.logger.Debug("received block part from wrong height", "height", height, "round", round)
return false, nil return false, nil
} }
@ -1908,7 +1910,7 @@ func (cs *State) addProposalBlockPart(
if cs.ProposalBlockParts == nil { if cs.ProposalBlockParts == nil {
// NOTE: this can happen when we've gone to a higher round and // 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. // then receive parts from the previous round - not necessarily a bad peer.
cs.Logger.Debug(
cs.logger.Debug(
"received a block part when we are not expecting any", "received a block part when we are not expecting any",
"height", height, "height", height,
"round", round, "round", round,
@ -1947,10 +1949,10 @@ func (cs *State) addProposalBlockPart(
cs.ProposalBlock = block cs.ProposalBlock = block
// NOTE: it's possible to receive complete proposal blocks for future rounds without having the proposal // NOTE: it's possible to receive complete proposal blocks for future rounds without having the proposal
cs.Logger.Info("received complete proposal block", "height", cs.ProposalBlock.Height, "hash", cs.ProposalBlock.Hash())
cs.logger.Info("received complete proposal block", "height", cs.ProposalBlock.Height, "hash", cs.ProposalBlock.Hash())
if err := cs.eventBus.PublishEventCompleteProposal(ctx, cs.CompleteProposalEvent()); err != nil { if err := cs.eventBus.PublishEventCompleteProposal(ctx, cs.CompleteProposalEvent()); err != nil {
cs.Logger.Error("failed publishing event complete proposal", "err", err)
cs.logger.Error("failed publishing event complete proposal", "err", err)
} }
// Update Valid* if we can. // Update Valid* if we can.
@ -1958,7 +1960,7 @@ func (cs *State) addProposalBlockPart(
blockID, hasTwoThirds := prevotes.TwoThirdsMajority() blockID, hasTwoThirds := prevotes.TwoThirdsMajority()
if hasTwoThirds && !blockID.IsZero() && (cs.ValidRound < cs.Round) { if hasTwoThirds && !blockID.IsZero() && (cs.ValidRound < cs.Round) {
if cs.ProposalBlock.HashesTo(blockID.Hash) { if cs.ProposalBlock.HashesTo(blockID.Hash) {
cs.Logger.Debug(
cs.logger.Debug(
"updating valid block to new proposal block", "updating valid block to new proposal block",
"valid_round", cs.Round, "valid_round", cs.Round,
"valid_block_hash", cs.ProposalBlock.Hash(), "valid_block_hash", cs.ProposalBlock.Hash(),
@ -2006,7 +2008,7 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types.
} }
if bytes.Equal(vote.ValidatorAddress, cs.privValidatorPubKey.Address()) { if bytes.Equal(vote.ValidatorAddress, cs.privValidatorPubKey.Address()) {
cs.Logger.Error(
cs.logger.Error(
"found conflicting vote from ourselves; did you unsafe_reset a validator?", "found conflicting vote from ourselves; did you unsafe_reset a validator?",
"height", vote.Height, "height", vote.Height,
"round", vote.Round, "round", vote.Round,
@ -2018,7 +2020,7 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types.
// report conflicting votes to the evidence pool // report conflicting votes to the evidence pool
cs.evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB) cs.evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB)
cs.Logger.Debug(
cs.logger.Debug(
"found and sent conflicting votes to the evidence pool", "found and sent conflicting votes to the evidence pool",
"vote_a", voteErr.VoteA, "vote_a", voteErr.VoteA,
"vote_b", voteErr.VoteB, "vote_b", voteErr.VoteB,
@ -2026,14 +2028,14 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types.
return added, err return added, err
} else if errors.Is(err, types.ErrVoteNonDeterministicSignature) { } else if errors.Is(err, types.ErrVoteNonDeterministicSignature) {
cs.Logger.Debug("vote has non-deterministic signature", "err", err)
cs.logger.Debug("vote has non-deterministic signature", "err", err)
} else { } else {
// Either // Either
// 1) bad peer OR // 1) bad peer OR
// 2) not a bad peer? this can also err sometimes with "Unexpected step" OR // 2) not a bad peer? this can also err sometimes with "Unexpected step" OR
// 3) tmkms use with multiple validators connecting to a single tmkms instance // 3) tmkms use with multiple validators connecting to a single tmkms instance
// (https://github.com/tendermint/tendermint/issues/3839). // (https://github.com/tendermint/tendermint/issues/3839).
cs.Logger.Info("failed attempting to add vote", "err", err)
cs.logger.Info("failed attempting to add vote", "err", err)
return added, ErrAddingVote return added, ErrAddingVote
} }
} }
@ -2046,7 +2048,7 @@ func (cs *State) addVote(
vote *types.Vote, vote *types.Vote,
peerID types.NodeID, peerID types.NodeID,
) (added bool, err error) { ) (added bool, err error) {
cs.Logger.Debug(
cs.logger.Debug(
"adding vote", "adding vote",
"vote_height", vote.Height, "vote_height", vote.Height,
"vote_type", vote.Type, "vote_type", vote.Type,
@ -2059,7 +2061,7 @@ func (cs *State) addVote(
if vote.Height+1 == cs.Height && vote.Type == tmproto.PrecommitType { if vote.Height+1 == cs.Height && vote.Type == tmproto.PrecommitType {
if cs.Step != cstypes.RoundStepNewHeight { if cs.Step != cstypes.RoundStepNewHeight {
// Late precommit at prior height is ignored // Late precommit at prior height is ignored
cs.Logger.Debug("precommit vote came in after commit timeout and has been ignored", "vote", vote)
cs.logger.Debug("precommit vote came in after commit timeout and has been ignored", "vote", vote)
return return
} }
@ -2068,7 +2070,7 @@ func (cs *State) addVote(
return return
} }
cs.Logger.Debug("added vote to last precommits", "last_commit", cs.LastCommit.StringShort())
cs.logger.Debug("added vote to last precommits", "last_commit", cs.LastCommit.StringShort())
if err := cs.eventBus.PublishEventVote(ctx, types.EventDataVote{Vote: vote}); err != nil { if err := cs.eventBus.PublishEventVote(ctx, types.EventDataVote{Vote: vote}); err != nil {
return added, err return added, err
} }
@ -2088,7 +2090,7 @@ func (cs *State) addVote(
// Height mismatch is ignored. // Height mismatch is ignored.
// Not necessarily a bad peer, but not favorable behavior. // Not necessarily a bad peer, but not favorable behavior.
if vote.Height != cs.Height { if vote.Height != cs.Height {
cs.Logger.Debug("vote ignored and not added", "vote_height", vote.Height, "cs_height", cs.Height, "peer", peerID)
cs.logger.Debug("vote ignored and not added", "vote_height", vote.Height, "cs_height", cs.Height, "peer", peerID)
return return
} }
@ -2107,7 +2109,7 @@ func (cs *State) addVote(
switch vote.Type { switch vote.Type {
case tmproto.PrevoteType: case tmproto.PrevoteType:
prevotes := cs.Votes.Prevotes(vote.Round) prevotes := cs.Votes.Prevotes(vote.Round)
cs.Logger.Debug("added vote to prevote", "vote", vote, "prevotes", prevotes.StringShort())
cs.logger.Debug("added vote to prevote", "vote", vote, "prevotes", prevotes.StringShort())
// If +2/3 prevotes for a block or nil for *any* round: // If +2/3 prevotes for a block or nil for *any* round:
if blockID, ok := prevotes.TwoThirdsMajority(); ok { if blockID, ok := prevotes.TwoThirdsMajority(); ok {
@ -2122,7 +2124,7 @@ func (cs *State) addVote(
(vote.Round <= cs.Round) && (vote.Round <= cs.Round) &&
!cs.LockedBlock.HashesTo(blockID.Hash) { !cs.LockedBlock.HashesTo(blockID.Hash) {
cs.Logger.Debug("unlocking because of POL", "locked_round", cs.LockedRound, "pol_round", vote.Round)
cs.logger.Debug("unlocking because of POL", "locked_round", cs.LockedRound, "pol_round", vote.Round)
cs.LockedRound = -1 cs.LockedRound = -1
cs.LockedBlock = nil cs.LockedBlock = nil
@ -2137,12 +2139,12 @@ func (cs *State) addVote(
// NOTE: our proposal block may be nil or not what received a polka.. // NOTE: our proposal block may be nil or not what received a polka..
if len(blockID.Hash) != 0 && (cs.ValidRound < vote.Round) && (vote.Round == cs.Round) { if len(blockID.Hash) != 0 && (cs.ValidRound < vote.Round) && (vote.Round == cs.Round) {
if cs.ProposalBlock.HashesTo(blockID.Hash) { if cs.ProposalBlock.HashesTo(blockID.Hash) {
cs.Logger.Debug("updating valid block because of POL", "valid_round", cs.ValidRound, "pol_round", vote.Round)
cs.logger.Debug("updating valid block because of POL", "valid_round", cs.ValidRound, "pol_round", vote.Round)
cs.ValidRound = vote.Round cs.ValidRound = vote.Round
cs.ValidBlock = cs.ProposalBlock cs.ValidBlock = cs.ProposalBlock
cs.ValidBlockParts = cs.ProposalBlockParts cs.ValidBlockParts = cs.ProposalBlockParts
} else { } else {
cs.Logger.Debug(
cs.logger.Debug(
"valid block we do not know about; set ProposalBlock=nil", "valid block we do not know about; set ProposalBlock=nil",
"proposal", cs.ProposalBlock.Hash(), "proposal", cs.ProposalBlock.Hash(),
"block_id", blockID.Hash, "block_id", blockID.Hash,
@ -2186,7 +2188,7 @@ func (cs *State) addVote(
case tmproto.PrecommitType: case tmproto.PrecommitType:
precommits := cs.Votes.Precommits(vote.Round) precommits := cs.Votes.Precommits(vote.Round)
cs.Logger.Debug("added vote to precommit",
cs.logger.Debug("added vote to precommit",
"height", vote.Height, "height", vote.Height,
"round", vote.Round, "round", vote.Round,
"validator", vote.ValidatorAddress.String(), "validator", vote.ValidatorAddress.String(),
@ -2305,7 +2307,7 @@ func (cs *State) signAddVote(ctx context.Context, msgType tmproto.SignedMsgType,
if cs.privValidatorPubKey == nil { if cs.privValidatorPubKey == nil {
// Vote won't be signed, but it's not critical. // Vote won't be signed, but it's not critical.
cs.Logger.Error(fmt.Sprintf("signAddVote: %v", errPubKeyIsNotSet))
cs.logger.Error(fmt.Sprintf("signAddVote: %v", errPubKeyIsNotSet))
return nil return nil
} }
@ -2318,11 +2320,11 @@ func (cs *State) signAddVote(ctx context.Context, msgType tmproto.SignedMsgType,
vote, err := cs.signVote(msgType, hash, header) vote, err := cs.signVote(msgType, hash, header)
if err == nil { if err == nil {
cs.sendInternalMessage(ctx, msgInfo{&VoteMessage{vote}, ""}) cs.sendInternalMessage(ctx, msgInfo{&VoteMessage{vote}, ""})
cs.Logger.Debug("signed and pushed vote", "height", cs.Height, "round", cs.Round, "vote", vote)
cs.logger.Debug("signed and pushed vote", "height", cs.Height, "round", cs.Round, "vote", vote)
return vote return vote
} }
cs.Logger.Error("failed signing vote", "height", cs.Height, "round", cs.Round, "vote", vote, "err", err)
cs.logger.Error("failed signing vote", "height", cs.Height, "round", cs.Round, "vote", vote, "err", err)
return nil return nil
} }
@ -2372,7 +2374,7 @@ func (cs *State) checkDoubleSigningRisk(height int64) error {
if lastCommit != nil { if lastCommit != nil {
for sigIdx, s := range lastCommit.Signatures { for sigIdx, s := range lastCommit.Signatures {
if s.BlockIDFlag == types.BlockIDFlagCommit && bytes.Equal(s.ValidatorAddress, valAddr) { if s.BlockIDFlag == types.BlockIDFlagCommit && bytes.Equal(s.ValidatorAddress, valAddr) {
cs.Logger.Info("found signature from the same key", "sig", s, "idx", sigIdx, "height", height-i)
cs.logger.Info("found signature from the same key", "sig", s, "idx", sigIdx, "height", height-i)
return ErrSignatureFoundInPastBlocks return ErrSignatureFoundInPastBlocks
} }
} }


+ 7
- 5
internal/consensus/ticker.go View File

@ -30,6 +30,7 @@ type TimeoutTicker interface {
// and fired on the tockChan. // and fired on the tockChan.
type timeoutTicker struct { type timeoutTicker struct {
service.BaseService service.BaseService
logger log.Logger
timer *time.Timer timer *time.Timer
tickChan chan timeoutInfo // for scheduling timeouts tickChan chan timeoutInfo // for scheduling timeouts
@ -39,6 +40,7 @@ type timeoutTicker struct {
// NewTimeoutTicker returns a new TimeoutTicker. // NewTimeoutTicker returns a new TimeoutTicker.
func NewTimeoutTicker(logger log.Logger) TimeoutTicker { func NewTimeoutTicker(logger log.Logger) TimeoutTicker {
tt := &timeoutTicker{ tt := &timeoutTicker{
logger: logger,
timer: time.NewTimer(0), timer: time.NewTimer(0),
tickChan: make(chan timeoutInfo, tickTockBufferSize), tickChan: make(chan timeoutInfo, tickTockBufferSize),
tockChan: make(chan timeoutInfo, tickTockBufferSize), tockChan: make(chan timeoutInfo, tickTockBufferSize),
@ -79,7 +81,7 @@ func (t *timeoutTicker) stopTimer() {
select { select {
case <-t.timer.C: case <-t.timer.C:
default: default:
t.Logger.Debug("Timer already stopped")
t.logger.Debug("Timer already stopped")
} }
} }
} }
@ -88,12 +90,12 @@ func (t *timeoutTicker) stopTimer() {
// timers are interupted and replaced by new ticks from later steps // timers are interupted and replaced by new ticks from later steps
// timeouts of 0 on the tickChan will be immediately relayed to the tockChan // timeouts of 0 on the tickChan will be immediately relayed to the tockChan
func (t *timeoutTicker) timeoutRoutine(ctx context.Context) { func (t *timeoutTicker) timeoutRoutine(ctx context.Context) {
t.Logger.Debug("Starting timeout routine")
t.logger.Debug("Starting timeout routine")
var ti timeoutInfo var ti timeoutInfo
for { for {
select { select {
case newti := <-t.tickChan: case newti := <-t.tickChan:
t.Logger.Debug("Received tick", "old_ti", ti, "new_ti", newti)
t.logger.Debug("Received tick", "old_ti", ti, "new_ti", newti)
// ignore tickers for old height/round/step // ignore tickers for old height/round/step
if newti.Height < ti.Height { if newti.Height < ti.Height {
@ -115,9 +117,9 @@ func (t *timeoutTicker) timeoutRoutine(ctx context.Context) {
// NOTE time.Timer allows duration to be non-positive // NOTE time.Timer allows duration to be non-positive
ti = newti ti = newti
t.timer.Reset(ti.Duration) t.timer.Reset(ti.Duration)
t.Logger.Debug("Scheduled timeout", "dur", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
t.logger.Debug("Scheduled timeout", "dur", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
case <-t.timer.C: case <-t.timer.C:
t.Logger.Info("Timed out", "dur", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
t.logger.Info("Timed out", "dur", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step)
// go routine here guarantees timeoutRoutine doesn't block. // go routine here guarantees timeoutRoutine doesn't block.
// Determinism comes from playback in the receiveRoutine. // Determinism comes from playback in the receiveRoutine.
// We can eliminate it by merging the timeoutRoutine into receiveRoutine // We can eliminate it by merging the timeoutRoutine into receiveRoutine


+ 11
- 9
internal/consensus/wal.go View File

@ -76,6 +76,7 @@ type WAL interface {
// again. // again.
type BaseWAL struct { type BaseWAL struct {
service.BaseService service.BaseService
logger log.Logger
group *auto.Group group *auto.Group
@ -95,11 +96,12 @@ func NewWAL(logger log.Logger, walFile string, groupOptions ...func(*auto.Group)
return nil, fmt.Errorf("failed to ensure WAL directory is in place: %w", err) return nil, fmt.Errorf("failed to ensure WAL directory is in place: %w", err)
} }
group, err := auto.OpenGroup(walFile, groupOptions...)
group, err := auto.OpenGroup(logger, walFile, groupOptions...)
if err != nil { if err != nil {
return nil, err return nil, err
} }
wal := &BaseWAL{ wal := &BaseWAL{
logger: logger,
group: group, group: group,
enc: NewWALEncoder(group), enc: NewWALEncoder(group),
flushInterval: walDefaultFlushInterval, flushInterval: walDefaultFlushInterval,
@ -140,7 +142,7 @@ func (wal *BaseWAL) processFlushTicks(ctx context.Context) {
select { select {
case <-wal.flushTicker.C: case <-wal.flushTicker.C:
if err := wal.FlushAndSync(); err != nil { if err := wal.FlushAndSync(); err != nil {
wal.Logger.Error("Periodic WAL flush failed", "err", err)
wal.logger.Error("Periodic WAL flush failed", "err", err)
} }
case <-ctx.Done(): case <-ctx.Done():
return return
@ -161,12 +163,12 @@ func (wal *BaseWAL) OnStop() {
wal.flushTicker.Stop() wal.flushTicker.Stop()
if err := wal.FlushAndSync(); err != nil { if err := wal.FlushAndSync(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
wal.Logger.Error("error on flush data to disk", "error", err)
wal.logger.Error("error on flush data to disk", "error", err)
} }
} }
if err := wal.group.Stop(); err != nil { if err := wal.group.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
wal.Logger.Error("error trying to stop wal", "error", err)
wal.logger.Error("error trying to stop wal", "error", err)
} }
} }
wal.group.Close() wal.group.Close()
@ -192,7 +194,7 @@ func (wal *BaseWAL) Write(msg WALMessage) error {
} }
if err := wal.enc.Encode(&TimedWALMessage{tmtime.Now(), msg}); err != nil { if err := wal.enc.Encode(&TimedWALMessage{tmtime.Now(), msg}); err != nil {
wal.Logger.Error("Error writing msg to consensus wal. WARNING: recover may not be possible for the current height",
wal.logger.Error("Error writing msg to consensus wal. WARNING: recover may not be possible for the current height",
"err", err, "msg", msg) "err", err, "msg", msg)
return err return err
} }
@ -213,7 +215,7 @@ func (wal *BaseWAL) WriteSync(msg WALMessage) error {
} }
if err := wal.FlushAndSync(); err != nil { if err := wal.FlushAndSync(); err != nil {
wal.Logger.Error(`WriteSync failed to flush consensus wal.
wal.logger.Error(`WriteSync failed to flush consensus wal.
WARNING: may result in creating alternative proposals / votes for the current height iff the node restarted`, WARNING: may result in creating alternative proposals / votes for the current height iff the node restarted`,
"err", err) "err", err)
return err return err
@ -245,7 +247,7 @@ func (wal *BaseWAL) SearchForEndHeight(
// NOTE: starting from the last file in the group because we're usually // NOTE: starting from the last file in the group because we're usually
// searching for the last height. See replay.go // searching for the last height. See replay.go
min, max := wal.group.MinIndex(), wal.group.MaxIndex() min, max := wal.group.MinIndex(), wal.group.MaxIndex()
wal.Logger.Info("Searching for height", "height", height, "min", min, "max", max)
wal.logger.Info("Searching for height", "height", height, "min", min, "max", max)
for index := max; index >= min; index-- { for index := max; index >= min; index-- {
gr, err = wal.group.NewReader(index) gr, err = wal.group.NewReader(index)
if err != nil { if err != nil {
@ -265,7 +267,7 @@ func (wal *BaseWAL) SearchForEndHeight(
break break
} }
if options.IgnoreDataCorruptionErrors && IsDataCorruptionError(err) { if options.IgnoreDataCorruptionErrors && IsDataCorruptionError(err) {
wal.Logger.Error("Corrupted entry. Skipping...", "err", err)
wal.logger.Error("Corrupted entry. Skipping...", "err", err)
// do nothing // do nothing
continue continue
} else if err != nil { } else if err != nil {
@ -276,7 +278,7 @@ func (wal *BaseWAL) SearchForEndHeight(
if m, ok := msg.Msg.(EndHeightMessage); ok { if m, ok := msg.Msg.(EndHeightMessage); ok {
lastHeightFound = m.Height lastHeightFound = m.Height
if m.Height == height { // found if m.Height == height { // found
wal.Logger.Info("Found", "height", height, "index", index)
wal.logger.Info("Found", "height", height, "index", index)
return gr, true, nil return gr, true, nil
} }
} }


+ 1
- 4
internal/eventbus/event_bus.go View File

@ -29,10 +29,7 @@ type EventBus struct {
// NewDefault returns a new event bus with default options. // NewDefault returns a new event bus with default options.
func NewDefault(l log.Logger) *EventBus { func NewDefault(l log.Logger) *EventBus {
logger := l.With("module", "eventbus") logger := l.With("module", "eventbus")
pubsub := tmpubsub.NewServer(tmpubsub.BufferCapacity(0),
func(s *tmpubsub.Server) {
s.Logger = logger
})
pubsub := tmpubsub.NewServer(l, tmpubsub.BufferCapacity(0))
b := &EventBus{pubsub: pubsub} b := &EventBus{pubsub: pubsub}
b.BaseService = *service.NewBaseService(logger, "EventBus", b) b.BaseService = *service.NewBaseService(logger, "EventBus", b)
return b return b


+ 11
- 9
internal/evidence/reactor.go View File

@ -45,6 +45,7 @@ func GetChannelDescriptor() *p2p.ChannelDescriptor {
// Reactor handles evpool evidence broadcasting amongst peers. // Reactor handles evpool evidence broadcasting amongst peers.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
evpool *Pool evpool *Pool
evidenceCh *p2p.Channel evidenceCh *p2p.Channel
@ -67,6 +68,7 @@ func NewReactor(
evpool *Pool, evpool *Pool,
) *Reactor { ) *Reactor {
r := &Reactor{ r := &Reactor{
logger: logger,
evpool: evpool, evpool: evpool,
evidenceCh: evidenceCh, evidenceCh: evidenceCh,
peerUpdates: peerUpdates, peerUpdates: peerUpdates,
@ -120,7 +122,7 @@ func (r *Reactor) OnStop() {
// or if the given evidence is invalid. This should never be called outside of // or if the given evidence is invalid. This should never be called outside of
// handleMessage. // handleMessage.
func (r *Reactor) handleEvidenceMessage(envelope p2p.Envelope) error { func (r *Reactor) handleEvidenceMessage(envelope p2p.Envelope) error {
logger := r.Logger.With("peer", envelope.From)
logger := r.logger.With("peer", envelope.From)
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *tmproto.EvidenceList: case *tmproto.EvidenceList:
@ -159,7 +161,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
defer func() { defer func() {
if e := recover(); e != nil { if e := recover(); e != nil {
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -167,7 +169,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
} }
}() }()
r.Logger.Debug("received message", "message", envelope.Message, "peer", envelope.From)
r.logger.Debug("received message", "message", envelope.Message, "peer", envelope.From)
switch chID { switch chID {
case EvidenceChannel: case EvidenceChannel:
@ -189,7 +191,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) {
return return
case envelope := <-r.evidenceCh.In: case envelope := <-r.evidenceCh.In:
if err := r.handleMessage(r.evidenceCh.ID, envelope); err != nil { if err := r.handleMessage(r.evidenceCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.evidenceCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.evidenceCh.ID, "envelope", envelope, "err", err)
r.evidenceCh.Error <- p2p.PeerError{ r.evidenceCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -197,7 +199,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) {
} }
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on evidence channel; closing...")
r.logger.Debug("stopped listening on evidence channel; closing...")
return return
} }
} }
@ -215,7 +217,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) {
// //
// REF: https://github.com/tendermint/tendermint/issues/4727 // REF: https://github.com/tendermint/tendermint/issues/4727
func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) {
r.Logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.mtx.Lock() r.mtx.Lock()
defer r.mtx.Unlock() defer r.mtx.Unlock()
@ -268,7 +270,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
case <-ctx.Done(): case <-ctx.Done():
return return
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -296,7 +298,7 @@ func (r *Reactor) broadcastEvidenceLoop(ctx context.Context, peerID types.NodeID
r.peerWG.Done() r.peerWG.Done()
if e := recover(); e != nil { if e := recover(); e != nil {
r.Logger.Error(
r.logger.Error(
"recovering from broadcasting evidence loop", "recovering from broadcasting evidence loop",
"err", e, "err", e,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -349,7 +351,7 @@ func (r *Reactor) broadcastEvidenceLoop(ctx context.Context, peerID types.NodeID
}, },
}: }:
} }
r.Logger.Debug("gossiped evidence to peer", "evidence", ev, "peer", peerID)
r.logger.Debug("gossiped evidence to peer", "evidence", ev, "peer", peerID)
select { select {
case <-time.After(time.Second * broadcastEvidenceIntervalS): case <-time.After(time.Second * broadcastEvidenceIntervalS):


+ 2
- 1
internal/libs/autofile/cmd/logjack.go View File

@ -12,6 +12,7 @@ import (
"syscall" "syscall"
auto "github.com/tendermint/tendermint/internal/libs/autofile" auto "github.com/tendermint/tendermint/internal/libs/autofile"
"github.com/tendermint/tendermint/libs/log"
) )
const Version = "0.0.1" const Version = "0.0.1"
@ -47,7 +48,7 @@ func main() {
} }
// Open Group // Open Group
group, err := auto.OpenGroup(headPath, auto.GroupHeadSizeLimit(chopSize), auto.GroupTotalSizeLimit(limitSize))
group, err := auto.OpenGroup(log.NewNopLogger(), headPath, auto.GroupHeadSizeLimit(chopSize), auto.GroupTotalSizeLimit(limitSize))
if err != nil { if err != nil {
fmt.Printf("logjack couldn't create output file %v\n", headPath) fmt.Printf("logjack couldn't create output file %v\n", headPath)
os.Exit(1) os.Exit(1)


+ 11
- 8
internal/libs/autofile/group.go View File

@ -14,6 +14,7 @@ import (
"sync" "sync"
"time" "time"
"github.com/tendermint/tendermint/libs/log"
"github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/libs/service"
) )
@ -54,6 +55,7 @@ assuming that marker lines are written occasionally.
*/ */
type Group struct { type Group struct {
service.BaseService service.BaseService
logger log.Logger
ID string ID string
Head *AutoFile // The head AutoFile to write to Head *AutoFile // The head AutoFile to write to
@ -78,7 +80,7 @@ type Group struct {
// OpenGroup creates a new Group with head at headPath. It returns an error if // OpenGroup creates a new Group with head at headPath. It returns an error if
// it fails to open head file. // it fails to open head file.
func OpenGroup(headPath string, groupOptions ...func(*Group)) (*Group, error) {
func OpenGroup(logger log.Logger, headPath string, groupOptions ...func(*Group)) (*Group, error) {
dir, err := filepath.Abs(filepath.Dir(headPath)) dir, err := filepath.Abs(filepath.Dir(headPath))
if err != nil { if err != nil {
return nil, err return nil, err
@ -89,6 +91,7 @@ func OpenGroup(headPath string, groupOptions ...func(*Group)) (*Group, error) {
} }
g := &Group{ g := &Group{
logger: logger,
ID: "group:" + head.ID, ID: "group:" + head.ID,
Head: head, Head: head,
headBuf: bufio.NewWriterSize(head, 4096*10), headBuf: bufio.NewWriterSize(head, 4096*10),
@ -105,7 +108,7 @@ func OpenGroup(headPath string, groupOptions ...func(*Group)) (*Group, error) {
option(g) option(g)
} }
g.BaseService = *service.NewBaseService(nil, "Group", g)
g.BaseService = *service.NewBaseService(logger, "Group", g)
gInfo := g.readGroupInfo() gInfo := g.readGroupInfo()
g.minIndex = gInfo.MinIndex g.minIndex = gInfo.MinIndex
@ -147,7 +150,7 @@ func (g *Group) OnStart(ctx context.Context) error {
func (g *Group) OnStop() { func (g *Group) OnStop() {
g.ticker.Stop() g.ticker.Stop()
if err := g.FlushAndSync(); err != nil { if err := g.FlushAndSync(); err != nil {
g.Logger.Error("Error flushing to disk", "err", err)
g.logger.Error("Error flushing to disk", "err", err)
} }
} }
@ -161,7 +164,7 @@ func (g *Group) Wait() {
// Close closes the head file. The group must be stopped by this moment. // Close closes the head file. The group must be stopped by this moment.
func (g *Group) Close() { func (g *Group) Close() {
if err := g.FlushAndSync(); err != nil { if err := g.FlushAndSync(); err != nil {
g.Logger.Error("Error flushing to disk", "err", err)
g.logger.Error("Error flushing to disk", "err", err)
} }
g.mtx.Lock() g.mtx.Lock()
@ -259,7 +262,7 @@ func (g *Group) checkHeadSizeLimit() {
} }
size, err := g.Head.Size() size, err := g.Head.Size()
if err != nil { if err != nil {
g.Logger.Error("Group's head may grow without bound", "head", g.Head.Path, "err", err)
g.logger.Error("Group's head may grow without bound", "head", g.Head.Path, "err", err)
return return
} }
if size >= limit { if size >= limit {
@ -282,18 +285,18 @@ func (g *Group) checkTotalSizeLimit() {
} }
if index == gInfo.MaxIndex { if index == gInfo.MaxIndex {
// Special degenerate case, just do nothing. // Special degenerate case, just do nothing.
g.Logger.Error("Group's head may grow without bound", "head", g.Head.Path)
g.logger.Error("Group's head may grow without bound", "head", g.Head.Path)
return return
} }
pathToRemove := filePathForIndex(g.Head.Path, index, gInfo.MaxIndex) pathToRemove := filePathForIndex(g.Head.Path, index, gInfo.MaxIndex)
fInfo, err := os.Stat(pathToRemove) fInfo, err := os.Stat(pathToRemove)
if err != nil { if err != nil {
g.Logger.Error("Failed to fetch info for file", "file", pathToRemove)
g.logger.Error("Failed to fetch info for file", "file", pathToRemove)
continue continue
} }
err = os.Remove(pathToRemove) err = os.Remove(pathToRemove)
if err != nil { if err != nil {
g.Logger.Error("Failed to remove path", "path", pathToRemove)
g.logger.Error("Failed to remove path", "path", pathToRemove)
return return
} }
totalSize -= fInfo.Size() totalSize -= fInfo.Size()


+ 22
- 9
internal/libs/autofile/group_test.go View File

@ -9,18 +9,19 @@ import (
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"github.com/tendermint/tendermint/libs/log"
tmos "github.com/tendermint/tendermint/libs/os" tmos "github.com/tendermint/tendermint/libs/os"
tmrand "github.com/tendermint/tendermint/libs/rand" tmrand "github.com/tendermint/tendermint/libs/rand"
) )
func createTestGroupWithHeadSizeLimit(t *testing.T, headSizeLimit int64) *Group {
func createTestGroupWithHeadSizeLimit(t *testing.T, logger log.Logger, headSizeLimit int64) *Group {
testID := tmrand.Str(12) testID := tmrand.Str(12)
testDir := "_test_" + testID testDir := "_test_" + testID
err := tmos.EnsureDir(testDir, 0700) err := tmos.EnsureDir(testDir, 0700)
require.NoError(t, err, "Error creating dir") require.NoError(t, err, "Error creating dir")
headPath := testDir + "/myfile" headPath := testDir + "/myfile"
g, err := OpenGroup(headPath, GroupHeadSizeLimit(headSizeLimit))
g, err := OpenGroup(logger, headPath, GroupHeadSizeLimit(headSizeLimit))
require.NoError(t, err, "Error opening Group") require.NoError(t, err, "Error opening Group")
require.NotEqual(t, nil, g, "Failed to create Group") require.NotEqual(t, nil, g, "Failed to create Group")
@ -42,7 +43,9 @@ func assertGroupInfo(t *testing.T, gInfo GroupInfo, minIndex, maxIndex int, tota
} }
func TestCheckHeadSizeLimit(t *testing.T) { func TestCheckHeadSizeLimit(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 1000*1000)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 1000*1000)
// At first, there are no files. // At first, there are no files.
assertGroupInfo(t, g.ReadGroupInfo(), 0, 0, 0, 0) assertGroupInfo(t, g.ReadGroupInfo(), 0, 0, 0, 0)
@ -109,7 +112,9 @@ func TestCheckHeadSizeLimit(t *testing.T) {
} }
func TestRotateFile(t *testing.T) { func TestRotateFile(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
// Create a different temporary directory and move into it, to make sure // Create a different temporary directory and move into it, to make sure
// relative paths are resolved at Group creation // relative paths are resolved at Group creation
@ -173,7 +178,9 @@ func TestRotateFile(t *testing.T) {
} }
func TestWrite(t *testing.T) { func TestWrite(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
written := []byte("Medusa") written := []byte("Medusa")
_, err := g.Write(written) _, err := g.Write(written)
@ -196,7 +203,9 @@ func TestWrite(t *testing.T) {
// test that Read reads the required amount of bytes from all the files in the // test that Read reads the required amount of bytes from all the files in the
// group and returns no error if n == size of the given slice. // group and returns no error if n == size of the given slice.
func TestGroupReaderRead(t *testing.T) { func TestGroupReaderRead(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
professor := []byte("Professor Monster") professor := []byte("Professor Monster")
_, err := g.Write(professor) _, err := g.Write(professor)
@ -229,7 +238,9 @@ func TestGroupReaderRead(t *testing.T) {
// test that Read returns an error if number of bytes read < size of // test that Read returns an error if number of bytes read < size of
// the given slice. Subsequent call should return 0, io.EOF. // the given slice. Subsequent call should return 0, io.EOF.
func TestGroupReaderRead2(t *testing.T) { func TestGroupReaderRead2(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
professor := []byte("Professor Monster") professor := []byte("Professor Monster")
_, err := g.Write(professor) _, err := g.Write(professor)
@ -264,7 +275,8 @@ func TestGroupReaderRead2(t *testing.T) {
} }
func TestMinIndex(t *testing.T) { func TestMinIndex(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
assert.Zero(t, g.MinIndex(), "MinIndex should be zero at the beginning") assert.Zero(t, g.MinIndex(), "MinIndex should be zero at the beginning")
@ -273,7 +285,8 @@ func TestMinIndex(t *testing.T) {
} }
func TestMaxIndex(t *testing.T) { func TestMaxIndex(t *testing.T) {
g := createTestGroupWithHeadSizeLimit(t, 0)
logger := log.TestingLogger()
g := createTestGroupWithHeadSizeLimit(t, logger, 0)
assert.Zero(t, g.MaxIndex(), "MaxIndex should be zero at the beginning") assert.Zero(t, g.MaxIndex(), "MaxIndex should be zero at the beginning")


+ 12
- 10
internal/mempool/reactor.go View File

@ -35,6 +35,7 @@ type PeerManager interface {
// txs to the peers you received it from. // txs to the peers you received it from.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
cfg *config.MempoolConfig cfg *config.MempoolConfig
mempool *TxMempool mempool *TxMempool
@ -72,6 +73,7 @@ func NewReactor(
) *Reactor { ) *Reactor {
r := &Reactor{ r := &Reactor{
logger: logger,
cfg: cfg, cfg: cfg,
peerMgr: peerMgr, peerMgr: peerMgr,
mempool: txmp, mempool: txmp,
@ -114,7 +116,7 @@ func GetChannelDescriptor(cfg *config.MempoolConfig) *p2p.ChannelDescriptor {
// OnStop to ensure the outbound p2p Channels are closed. // OnStop to ensure the outbound p2p Channels are closed.
func (r *Reactor) OnStart(ctx context.Context) error { func (r *Reactor) OnStart(ctx context.Context) error {
if !r.cfg.Broadcast { if !r.cfg.Broadcast {
r.Logger.Info("tx broadcasting is disabled")
r.logger.Info("tx broadcasting is disabled")
} }
go r.processMempoolCh(ctx) go r.processMempoolCh(ctx)
@ -147,7 +149,7 @@ func (r *Reactor) OnStop() {
// empty set of txs are sent in an envelope or if we receive an unexpected // empty set of txs are sent in an envelope or if we receive an unexpected
// message type. // message type.
func (r *Reactor) handleMempoolMessage(envelope p2p.Envelope) error { func (r *Reactor) handleMempoolMessage(envelope p2p.Envelope) error {
logger := r.Logger.With("peer", envelope.From)
logger := r.logger.With("peer", envelope.From)
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *protomem.Txs: case *protomem.Txs:
@ -182,7 +184,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
if e := recover(); e != nil { if e := recover(); e != nil {
r.observePanic(e) r.observePanic(e)
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -190,7 +192,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
} }
}() }()
r.Logger.Debug("received message", "peer", envelope.From)
r.logger.Debug("received message", "peer", envelope.From)
switch chID { switch chID {
case MempoolChannel: case MempoolChannel:
@ -210,7 +212,7 @@ func (r *Reactor) processMempoolCh(ctx context.Context) {
select { select {
case envelope := <-r.mempoolCh.In: case envelope := <-r.mempoolCh.In:
if err := r.handleMessage(r.mempoolCh.ID, envelope); err != nil { if err := r.handleMessage(r.mempoolCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.mempoolCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.mempoolCh.ID, "envelope", envelope, "err", err)
r.mempoolCh.Error <- p2p.PeerError{ r.mempoolCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -219,7 +221,7 @@ func (r *Reactor) processMempoolCh(ctx context.Context) {
case <-ctx.Done(): case <-ctx.Done():
return return
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on mempool channel; closing...")
r.logger.Debug("stopped listening on mempool channel; closing...")
return return
} }
} }
@ -231,7 +233,7 @@ func (r *Reactor) processMempoolCh(ctx context.Context) {
// removed peers, we remove the peer from the mempool peer ID set and signal to // removed peers, we remove the peer from the mempool peer ID set and signal to
// stop the tx broadcasting goroutine. // stop the tx broadcasting goroutine.
func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate) {
r.Logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.mtx.Lock() r.mtx.Lock()
defer r.mtx.Unlock() defer r.mtx.Unlock()
@ -293,7 +295,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
r.processPeerUpdate(ctx, peerUpdate) r.processPeerUpdate(ctx, peerUpdate)
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -313,7 +315,7 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, c
if e := recover(); e != nil { if e := recover(); e != nil {
r.observePanic(e) r.observePanic(e)
r.Logger.Error(
r.logger.Error(
"recovering from broadcasting mempool loop", "recovering from broadcasting mempool loop",
"err", e, "err", e,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -376,7 +378,7 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, c
}: }:
case <-ctx.Done(): case <-ctx.Done():
} }
r.Logger.Debug(
r.logger.Debug(
"gossiped tx to peer", "gossiped tx to peer",
"tx", fmt.Sprintf("%X", memTx.tx.Hash()), "tx", fmt.Sprintf("%X", memTx.tx.Hash()),
"peer", peerID, "peer", peerID,


+ 31
- 29
internal/p2p/conn/connection.go View File

@ -74,6 +74,7 @@ Inbound message bytes are handled with an onReceive callback function.
*/ */
type MConnection struct { type MConnection struct {
service.BaseService service.BaseService
logger log.Logger
conn net.Conn conn net.Conn
bufConnReader *bufio.Reader bufConnReader *bufio.Reader
@ -178,6 +179,7 @@ func NewMConnectionWithConfig(
} }
mconn := &MConnection{ mconn := &MConnection{
logger: logger,
conn: conn, conn: conn,
bufConnReader: bufio.NewReaderSize(conn, minReadBufferSize), bufConnReader: bufio.NewReaderSize(conn, minReadBufferSize),
bufConnWriter: bufio.NewWriterSize(conn, minWriteBufferSize), bufConnWriter: bufio.NewWriterSize(conn, minWriteBufferSize),
@ -276,24 +278,24 @@ func (c *MConnection) String() string {
} }
func (c *MConnection) flush() { func (c *MConnection) flush() {
c.Logger.Debug("Flush", "conn", c)
c.logger.Debug("Flush", "conn", c)
err := c.bufConnWriter.Flush() err := c.bufConnWriter.Flush()
if err != nil { if err != nil {
c.Logger.Debug("MConnection flush failed", "err", err)
c.logger.Debug("MConnection flush failed", "err", err)
} }
} }
// Catch panics, usually caused by remote disconnects. // Catch panics, usually caused by remote disconnects.
func (c *MConnection) _recover() { func (c *MConnection) _recover() {
if r := recover(); r != nil { if r := recover(); r != nil {
c.Logger.Error("MConnection panicked", "err", r, "stack", string(debug.Stack()))
c.logger.Error("MConnection panicked", "err", r, "stack", string(debug.Stack()))
c.stopForError(fmt.Errorf("recovered from panic: %v", r)) c.stopForError(fmt.Errorf("recovered from panic: %v", r))
} }
} }
func (c *MConnection) stopForError(r interface{}) { func (c *MConnection) stopForError(r interface{}) {
if err := c.Stop(); err != nil { if err := c.Stop(); err != nil {
c.Logger.Error("Error stopping connection", "err", err)
c.logger.Error("Error stopping connection", "err", err)
} }
if atomic.CompareAndSwapUint32(&c.errored, 0, 1) { if atomic.CompareAndSwapUint32(&c.errored, 0, 1) {
@ -309,12 +311,12 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool {
return false return false
} }
c.Logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", msgBytes)
c.logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", msgBytes)
// Send message to channel. // Send message to channel.
channel, ok := c.channelsIdx[chID] channel, ok := c.channelsIdx[chID]
if !ok { if !ok {
c.Logger.Error(fmt.Sprintf("Cannot send bytes, unknown channel %X", chID))
c.logger.Error(fmt.Sprintf("Cannot send bytes, unknown channel %X", chID))
return false return false
} }
@ -326,7 +328,7 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool {
default: default:
} }
} else { } else {
c.Logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", msgBytes)
c.logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", msgBytes)
} }
return success return success
} }
@ -351,14 +353,14 @@ FOR_LOOP:
channel.updateStats() channel.updateStats()
} }
case <-c.pingTimer.C: case <-c.pingTimer.C:
c.Logger.Debug("Send Ping")
c.logger.Debug("Send Ping")
_n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPing{})) _n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPing{}))
if err != nil { if err != nil {
c.Logger.Error("Failed to send PacketPing", "err", err)
c.logger.Error("Failed to send PacketPing", "err", err)
break SELECTION break SELECTION
} }
c.sendMonitor.Update(_n) c.sendMonitor.Update(_n)
c.Logger.Debug("Starting pong timer", "dur", c.config.PongTimeout)
c.logger.Debug("Starting pong timer", "dur", c.config.PongTimeout)
c.pongTimer = time.AfterFunc(c.config.PongTimeout, func() { c.pongTimer = time.AfterFunc(c.config.PongTimeout, func() {
select { select {
case c.pongTimeoutCh <- true: case c.pongTimeoutCh <- true:
@ -368,16 +370,16 @@ FOR_LOOP:
c.flush() c.flush()
case timeout := <-c.pongTimeoutCh: case timeout := <-c.pongTimeoutCh:
if timeout { if timeout {
c.Logger.Debug("Pong timeout")
c.logger.Debug("Pong timeout")
err = errors.New("pong timeout") err = errors.New("pong timeout")
} else { } else {
c.stopPongTimer() c.stopPongTimer()
} }
case <-c.pong: case <-c.pong:
c.Logger.Debug("Send Pong")
c.logger.Debug("Send Pong")
_n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPong{})) _n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPong{}))
if err != nil { if err != nil {
c.Logger.Error("Failed to send PacketPong", "err", err)
c.logger.Error("Failed to send PacketPong", "err", err)
break SELECTION break SELECTION
} }
c.sendMonitor.Update(_n) c.sendMonitor.Update(_n)
@ -402,7 +404,7 @@ FOR_LOOP:
break FOR_LOOP break FOR_LOOP
} }
if err != nil { if err != nil {
c.Logger.Error("Connection failed @ sendRoutine", "conn", c, "err", err)
c.logger.Error("Connection failed @ sendRoutine", "conn", c, "err", err)
c.stopForError(err) c.stopForError(err)
break FOR_LOOP break FOR_LOOP
} }
@ -453,12 +455,12 @@ func (c *MConnection) sendPacketMsg() bool {
if leastChannel == nil { if leastChannel == nil {
return true return true
} }
// c.Logger.Info("Found a msgPacket to send")
// c.logger.Info("Found a msgPacket to send")
// Make & send a PacketMsg from this channel // Make & send a PacketMsg from this channel
_n, err := leastChannel.writePacketMsgTo(c.bufConnWriter) _n, err := leastChannel.writePacketMsgTo(c.bufConnWriter)
if err != nil { if err != nil {
c.Logger.Error("Failed to write PacketMsg", "err", err)
c.logger.Error("Failed to write PacketMsg", "err", err)
c.stopForError(err) c.stopForError(err)
return true return true
} }
@ -488,10 +490,10 @@ FOR_LOOP:
if err == nil { if err == nil {
// return // return
} else { } else {
c.Logger.Debug("Error peeking connection buffer", "err", err)
c.logger.Debug("Error peeking connection buffer", "err", err)
// return nil // return nil
} }
c.Logger.Info("Peek connection buffer", "numBytes", numBytes, "bz", bz)
c.logger.Info("Peek connection buffer", "numBytes", numBytes, "bz", bz)
} }
*/ */
@ -512,9 +514,9 @@ FOR_LOOP:
if c.IsRunning() { if c.IsRunning() {
if err == io.EOF { if err == io.EOF {
c.Logger.Info("Connection is closed @ recvRoutine (likely by the other side)", "conn", c)
c.logger.Info("Connection is closed @ recvRoutine (likely by the other side)", "conn", c)
} else { } else {
c.Logger.Debug("Connection failed @ recvRoutine (reading byte)", "conn", c, "err", err)
c.logger.Debug("Connection failed @ recvRoutine (reading byte)", "conn", c, "err", err)
} }
c.stopForError(err) c.stopForError(err)
} }
@ -526,14 +528,14 @@ FOR_LOOP:
case *tmp2p.Packet_PacketPing: case *tmp2p.Packet_PacketPing:
// TODO: prevent abuse, as they cause flush()'s. // TODO: prevent abuse, as they cause flush()'s.
// https://github.com/tendermint/tendermint/issues/1190 // https://github.com/tendermint/tendermint/issues/1190
c.Logger.Debug("Receive Ping")
c.logger.Debug("Receive Ping")
select { select {
case c.pong <- struct{}{}: case c.pong <- struct{}{}:
default: default:
// never block // never block
} }
case *tmp2p.Packet_PacketPong: case *tmp2p.Packet_PacketPong:
c.Logger.Debug("Receive Pong")
c.logger.Debug("Receive Pong")
select { select {
case c.pongTimeoutCh <- false: case c.pongTimeoutCh <- false:
default: default:
@ -544,7 +546,7 @@ FOR_LOOP:
channel, ok := c.channelsIdx[channelID] channel, ok := c.channelsIdx[channelID]
if pkt.PacketMsg.ChannelID < 0 || pkt.PacketMsg.ChannelID > math.MaxUint8 || !ok || channel == nil { if pkt.PacketMsg.ChannelID < 0 || pkt.PacketMsg.ChannelID > math.MaxUint8 || !ok || channel == nil {
err := fmt.Errorf("unknown channel %X", pkt.PacketMsg.ChannelID) err := fmt.Errorf("unknown channel %X", pkt.PacketMsg.ChannelID)
c.Logger.Debug("Connection failed @ recvRoutine", "conn", c, "err", err)
c.logger.Debug("Connection failed @ recvRoutine", "conn", c, "err", err)
c.stopForError(err) c.stopForError(err)
break FOR_LOOP break FOR_LOOP
} }
@ -552,19 +554,19 @@ FOR_LOOP:
msgBytes, err := channel.recvPacketMsg(*pkt.PacketMsg) msgBytes, err := channel.recvPacketMsg(*pkt.PacketMsg)
if err != nil { if err != nil {
if c.IsRunning() { if c.IsRunning() {
c.Logger.Debug("Connection failed @ recvRoutine", "conn", c, "err", err)
c.logger.Debug("Connection failed @ recvRoutine", "conn", c, "err", err)
c.stopForError(err) c.stopForError(err)
} }
break FOR_LOOP break FOR_LOOP
} }
if msgBytes != nil { if msgBytes != nil {
c.Logger.Debug("Received bytes", "chID", channelID, "msgBytes", msgBytes)
c.logger.Debug("Received bytes", "chID", channelID, "msgBytes", msgBytes)
// NOTE: This means the reactor.Receive runs in the same thread as the p2p recv routine // NOTE: This means the reactor.Receive runs in the same thread as the p2p recv routine
c.onReceive(channelID, msgBytes) c.onReceive(channelID, msgBytes)
} }
default: default:
err := fmt.Errorf("unknown message type %v", reflect.TypeOf(packet)) err := fmt.Errorf("unknown message type %v", reflect.TypeOf(packet))
c.Logger.Error("Connection failed @ recvRoutine", "conn", c, "err", err)
c.logger.Error("Connection failed @ recvRoutine", "conn", c, "err", err)
c.stopForError(err) c.stopForError(err)
break FOR_LOOP break FOR_LOOP
} }
@ -656,7 +658,7 @@ type channel struct {
maxPacketMsgPayloadSize int maxPacketMsgPayloadSize int
Logger log.Logger
logger log.Logger
} }
func newChannel(conn *MConnection, desc ChannelDescriptor) *channel { func newChannel(conn *MConnection, desc ChannelDescriptor) *channel {
@ -670,7 +672,7 @@ func newChannel(conn *MConnection, desc ChannelDescriptor) *channel {
sendQueue: make(chan []byte, desc.SendQueueCapacity), sendQueue: make(chan []byte, desc.SendQueueCapacity),
recving: make([]byte, 0, desc.RecvBufferCapacity), recving: make([]byte, 0, desc.RecvBufferCapacity),
maxPacketMsgPayloadSize: conn.config.MaxPacketMsgPayloadSize, maxPacketMsgPayloadSize: conn.config.MaxPacketMsgPayloadSize,
Logger: conn.Logger,
logger: conn.logger,
} }
} }
@ -730,7 +732,7 @@ func (ch *channel) writePacketMsgTo(w io.Writer) (n int, err error) {
// complete, which is owned by the caller and will not be modified. // complete, which is owned by the caller and will not be modified.
// Not goroutine-safe // Not goroutine-safe
func (ch *channel) recvPacketMsg(packet tmp2p.PacketMsg) ([]byte, error) { func (ch *channel) recvPacketMsg(packet tmp2p.PacketMsg) ([]byte, error) {
ch.Logger.Debug("Read PacketMsg", "conn", ch.conn, "packet", packet)
ch.logger.Debug("Read PacketMsg", "conn", ch.conn, "packet", packet)
var recvCap, recvReceived = ch.desc.RecvMessageCapacity, len(ch.recving) + len(packet.Data) var recvCap, recvReceived = ch.desc.RecvMessageCapacity, len(ch.recving) + len(packet.Data)
if recvCap < recvReceived { if recvCap < recvReceived {
return nil, fmt.Errorf("received message exceeds available capacity: %v < %v", recvCap, recvReceived) return nil, fmt.Errorf("received message exceeds available capacity: %v < %v", recvCap, recvReceived)


+ 12
- 10
internal/p2p/pex/reactor.go View File

@ -78,6 +78,7 @@ func ChannelDescriptor() *conn.ChannelDescriptor {
// adding it to the back of the list once a response is received. // adding it to the back of the list once a response is received.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
peerManager *p2p.PeerManager peerManager *p2p.PeerManager
pexCh *p2p.Channel pexCh *p2p.Channel
@ -123,6 +124,7 @@ func NewReactor(
) *Reactor { ) *Reactor {
r := &Reactor{ r := &Reactor{
logger: logger,
peerManager: peerManager, peerManager: peerManager,
pexCh: pexCh, pexCh: pexCh,
peerUpdates: peerUpdates, peerUpdates: peerUpdates,
@ -168,7 +170,7 @@ func (r *Reactor) processPexCh(ctx context.Context) {
case <-ctx.Done(): case <-ctx.Done():
return return
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on PEX channel; closing...")
r.logger.Debug("stopped listening on PEX channel; closing...")
return return
// outbound requests for new peers // outbound requests for new peers
@ -179,7 +181,7 @@ func (r *Reactor) processPexCh(ctx context.Context) {
// reactor // reactor
case envelope := <-r.pexCh.In: case envelope := <-r.pexCh.In:
if err := r.handleMessage(r.pexCh.ID, envelope); err != nil { if err := r.handleMessage(r.pexCh.ID, envelope); err != nil {
r.Logger.Error("failed to process message", "ch_id", r.pexCh.ID, "envelope", envelope, "err", err)
r.logger.Error("failed to process message", "ch_id", r.pexCh.ID, "envelope", envelope, "err", err)
r.pexCh.Error <- p2p.PeerError{ r.pexCh.Error <- p2p.PeerError{
NodeID: envelope.From, NodeID: envelope.From,
Err: err, Err: err,
@ -203,7 +205,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
r.processPeerUpdate(peerUpdate) r.processPeerUpdate(peerUpdate)
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -211,7 +213,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
// handlePexMessage handles envelopes sent from peers on the PexChannel. // handlePexMessage handles envelopes sent from peers on the PexChannel.
func (r *Reactor) handlePexMessage(envelope p2p.Envelope) error { func (r *Reactor) handlePexMessage(envelope p2p.Envelope) error {
logger := r.Logger.With("peer", envelope.From)
logger := r.logger.With("peer", envelope.From)
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *protop2p.PexRequest: case *protop2p.PexRequest:
@ -279,7 +281,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
defer func() { defer func() {
if e := recover(); e != nil { if e := recover(); e != nil {
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -287,7 +289,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
} }
}() }()
r.Logger.Debug("received PEX message", "peer", envelope.From)
r.logger.Debug("received PEX message", "peer", envelope.From)
switch chID { switch chID {
case p2p.ChannelID(PexChannel): case p2p.ChannelID(PexChannel):
@ -303,7 +305,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
// processPeerUpdate processes a PeerUpdate. For added peers, PeerStatusUp, we // processPeerUpdate processes a PeerUpdate. For added peers, PeerStatusUp, we
// send a request for addresses. // send a request for addresses.
func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
r.Logger.Debug("received PEX peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Debug("received PEX peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.mtx.Lock() r.mtx.Lock()
defer r.mtx.Unlock() defer r.mtx.Unlock()
@ -328,7 +330,7 @@ func (r *Reactor) sendRequestForPeers() {
defer r.mtx.Unlock() defer r.mtx.Unlock()
if len(r.availablePeers) == 0 { if len(r.availablePeers) == 0 {
// no peers are available // no peers are available
r.Logger.Debug("no available peers to send request to, waiting...")
r.logger.Debug("no available peers to send request to, waiting...")
r.nextRequestTime = time.Now().Add(noAvailablePeersWaitPeriod) r.nextRequestTime = time.Now().Add(noAvailablePeersWaitPeriod)
return return
@ -351,7 +353,7 @@ func (r *Reactor) sendRequestForPeers() {
r.requestsSent[peerID] = struct{}{} r.requestsSent[peerID] = struct{}{}
r.calculateNextRequestTime() r.calculateNextRequestTime()
r.Logger.Debug("peer request sent", "next_request_time", r.nextRequestTime)
r.logger.Debug("peer request sent", "next_request_time", r.nextRequestTime)
} }
// calculateNextRequestTime implements something of a proportional controller // calculateNextRequestTime implements something of a proportional controller
@ -368,7 +370,7 @@ func (r *Reactor) calculateNextRequestTime() {
// check if the peer store is full. If so then there is no need // check if the peer store is full. If so then there is no need
// to send peer requests too often // to send peer requests too often
if ratio := r.peerManager.PeerRatio(); ratio >= 0.95 { if ratio := r.peerManager.PeerRatio(); ratio >= 0.95 {
r.Logger.Debug("peer manager near full ratio, sleeping...",
r.logger.Debug("peer manager near full ratio, sleeping...",
"sleep_period", fullCapacityInterval, "ratio", ratio) "sleep_period", fullCapacityInterval, "ratio", ratio)
r.nextRequestTime = time.Now().Add(fullCapacityInterval) r.nextRequestTime = time.Now().Add(fullCapacityInterval)
return return


+ 3
- 3
internal/p2p/router.go View File

@ -146,8 +146,8 @@ func (o *RouterOptions) Validate() error {
// quality of service. // quality of service.
type Router struct { type Router struct {
*service.BaseService *service.BaseService
logger log.Logger
logger log.Logger
metrics *Metrics metrics *Metrics
options RouterOptions options RouterOptions
nodeInfo types.NodeInfo nodeInfo types.NodeInfo
@ -336,7 +336,7 @@ func (r *Router) routeChannel(
if wrapper != nil { if wrapper != nil {
msg := proto.Clone(wrapper) msg := proto.Clone(wrapper)
if err := msg.(Wrapper).Wrap(envelope.Message); err != nil { if err := msg.(Wrapper).Wrap(envelope.Message); err != nil {
r.Logger.Error("failed to wrap message", "channel", chID, "err", err)
r.logger.Error("failed to wrap message", "channel", chID, "err", err)
continue continue
} }
@ -958,7 +958,7 @@ func (r *Router) OnStart(ctx context.Context) error {
} }
} }
r.Logger.Info(
r.logger.Info(
"starting router", "starting router",
"node_id", r.nodeInfo.NodeID, "node_id", r.nodeInfo.NodeID,
"channels", r.nodeInfo.Channels, "channels", r.nodeInfo.Channels,


+ 0
- 1
internal/p2p/transport_mconn.go View File

@ -295,7 +295,6 @@ func (c *mConnConnection) Handshake(
return types.NodeInfo{}, nil, err return types.NodeInfo{}, nil, err
} }
c.mconn = mconn c.mconn = mconn
c.logger = mconn.Logger
if err = c.mconn.Start(ctx); err != nil { if err = c.mconn.Start(ctx); err != nil {
return types.NodeInfo{}, nil, err return types.NodeInfo{}, nil, err
} }


+ 8
- 6
internal/proxy/multi_app_conn.go View File

@ -46,6 +46,7 @@ func NewAppConns(clientCreator abciclient.Creator, logger log.Logger, metrics *M
// TODO: on app restart, clients must reboot together // TODO: on app restart, clients must reboot together
type multiAppConn struct { type multiAppConn struct {
service.BaseService service.BaseService
logger log.Logger
metrics *Metrics metrics *Metrics
consensusConn AppConnConsensus consensusConn AppConnConsensus
@ -72,6 +73,7 @@ type stoppableClient interface {
// NewMultiAppConn makes all necessary abci connections to the application. // NewMultiAppConn makes all necessary abci connections to the application.
func NewMultiAppConn(clientCreator abciclient.Creator, logger log.Logger, metrics *Metrics) AppConns { func NewMultiAppConn(clientCreator abciclient.Creator, logger log.Logger, metrics *Metrics) AppConns {
multiAppConn := &multiAppConn{ multiAppConn := &multiAppConn{
logger: logger,
metrics: metrics, metrics: metrics,
clientCreator: clientCreator, clientCreator: clientCreator,
} }
@ -181,7 +183,7 @@ func (app *multiAppConn) startWatchersForClientErrorToKillTendermint(ctx context
return return
} }
if err := client.Error(); err != nil { if err := client.Error(); err != nil {
killFn(name, err, app.Logger)
killFn(name, err, app.logger)
} }
}(client.name, client.connClient) }(client.name, client.connClient)
} }
@ -191,35 +193,35 @@ func (app *multiAppConn) stopAllClients() {
if app.consensusConnClient != nil { if app.consensusConnClient != nil {
if err := app.consensusConnClient.Stop(); err != nil { if err := app.consensusConnClient.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
app.Logger.Error("error while stopping consensus client", "error", err)
app.logger.Error("error while stopping consensus client", "error", err)
} }
} }
} }
if app.mempoolConnClient != nil { if app.mempoolConnClient != nil {
if err := app.mempoolConnClient.Stop(); err != nil { if err := app.mempoolConnClient.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
app.Logger.Error("error while stopping mempool client", "error", err)
app.logger.Error("error while stopping mempool client", "error", err)
} }
} }
} }
if app.queryConnClient != nil { if app.queryConnClient != nil {
if err := app.queryConnClient.Stop(); err != nil { if err := app.queryConnClient.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
app.Logger.Error("error while stopping query client", "error", err)
app.logger.Error("error while stopping query client", "error", err)
} }
} }
} }
if app.snapshotConnClient != nil { if app.snapshotConnClient != nil {
if err := app.snapshotConnClient.Stop(); err != nil { if err := app.snapshotConnClient.Stop(); err != nil {
if !errors.Is(err, service.ErrAlreadyStopped) { if !errors.Is(err, service.ErrAlreadyStopped) {
app.Logger.Error("error while stopping snapshot client", "error", err)
app.logger.Error("error while stopping snapshot client", "error", err)
} }
} }
} }
} }
func (app *multiAppConn) abciClientFor(ctx context.Context, conn string) (abciclient.Client, error) { func (app *multiAppConn) abciClientFor(ctx context.Context, conn string) (abciclient.Client, error) {
c, err := app.clientCreator(app.Logger.With(
c, err := app.clientCreator(app.logger.With(
"module", "abci-client", "module", "abci-client",
"connection", conn)) "connection", conn))
if err != nil { if err != nil {


+ 8
- 6
internal/state/indexer/indexer_service.go View File

@ -15,6 +15,7 @@ import (
// order to index transactions and blocks coming from the event bus. // order to index transactions and blocks coming from the event bus.
type Service struct { type Service struct {
service.BaseService service.BaseService
logger log.Logger
eventSinks []EventSink eventSinks []EventSink
eventBus *eventbus.EventBus eventBus *eventbus.EventBus
@ -30,6 +31,7 @@ type Service struct {
// NewService constructs a new indexer service from the given arguments. // NewService constructs a new indexer service from the given arguments.
func NewService(args ServiceArgs) *Service { func NewService(args ServiceArgs) *Service {
is := &Service{ is := &Service{
logger: args.Logger,
eventSinks: args.Sinks, eventSinks: args.Sinks,
eventBus: args.EventBus, eventBus: args.EventBus,
metrics: args.Metrics, metrics: args.Metrics,
@ -70,7 +72,7 @@ func (is *Service) publish(msg pubsub.Message) error {
// GATHER: Accumulate a transaction into the current block's batch. // GATHER: Accumulate a transaction into the current block's batch.
txResult := msg.Data().(types.EventDataTx).TxResult txResult := msg.Data().(types.EventDataTx).TxResult
if err := curr.Add(&txResult); err != nil { if err := curr.Add(&txResult); err != nil {
is.Logger.Error("failed to add tx to batch",
is.logger.Error("failed to add tx to batch",
"height", is.currentBlock.height, "index", txResult.Index, "err", err) "height", is.currentBlock.height, "index", txResult.Index, "err", err)
} }
@ -83,12 +85,12 @@ func (is *Service) publish(msg pubsub.Message) error {
for _, sink := range is.eventSinks { for _, sink := range is.eventSinks {
start := time.Now() start := time.Now()
if err := sink.IndexBlockEvents(is.currentBlock.header); err != nil { if err := sink.IndexBlockEvents(is.currentBlock.header); err != nil {
is.Logger.Error("failed to index block header",
is.logger.Error("failed to index block header",
"height", is.currentBlock.height, "err", err) "height", is.currentBlock.height, "err", err)
} else { } else {
is.metrics.BlockEventsSeconds.Observe(time.Since(start).Seconds()) is.metrics.BlockEventsSeconds.Observe(time.Since(start).Seconds())
is.metrics.BlocksIndexed.Add(1) is.metrics.BlocksIndexed.Add(1)
is.Logger.Debug("indexed block",
is.logger.Debug("indexed block",
"height", is.currentBlock.height, "sink", sink.Type()) "height", is.currentBlock.height, "sink", sink.Type())
} }
@ -96,12 +98,12 @@ func (is *Service) publish(msg pubsub.Message) error {
start := time.Now() start := time.Now()
err := sink.IndexTxEvents(curr.Ops) err := sink.IndexTxEvents(curr.Ops)
if err != nil { if err != nil {
is.Logger.Error("failed to index block txs",
is.logger.Error("failed to index block txs",
"height", is.currentBlock.height, "err", err) "height", is.currentBlock.height, "err", err)
} else { } else {
is.metrics.TxEventsSeconds.Observe(time.Since(start).Seconds()) is.metrics.TxEventsSeconds.Observe(time.Since(start).Seconds())
is.metrics.TransactionsIndexed.Add(float64(curr.Size())) is.metrics.TransactionsIndexed.Add(float64(curr.Size()))
is.Logger.Debug("indexed txs",
is.logger.Debug("indexed txs",
"height", is.currentBlock.height, "sink", sink.Type()) "height", is.currentBlock.height, "sink", sink.Type())
} }
} }
@ -133,7 +135,7 @@ func (is *Service) OnStart(ctx context.Context) error {
func (is *Service) OnStop() { func (is *Service) OnStop() {
for _, sink := range is.eventSinks { for _, sink := range is.eventSinks {
if err := sink.Stop(); err != nil { if err := sink.Stop(); err != nil {
is.Logger.Error("failed to close eventsink", "eventsink", sink.Type(), "err", err)
is.logger.Error("failed to close eventsink", "eventsink", sink.Type(), "err", err)
} }
} }
} }


+ 40
- 38
internal/statesync/reactor.go View File

@ -126,6 +126,7 @@ type Metricer interface {
// serving snapshots for other nodes. // serving snapshots for other nodes.
type Reactor struct { type Reactor struct {
service.BaseService service.BaseService
logger log.Logger
chainID string chainID string
initialHeight int64 initialHeight int64
@ -180,6 +181,7 @@ func NewReactor(
ssMetrics *Metrics, ssMetrics *Metrics,
) *Reactor { ) *Reactor {
r := &Reactor{ r := &Reactor{
logger: logger,
chainID: chainID, chainID: chainID,
initialHeight: initialHeight, initialHeight: initialHeight,
cfg: cfg, cfg: cfg,
@ -260,7 +262,7 @@ func (r *Reactor) Sync(ctx context.Context) (sm.State, error) {
r.syncer = newSyncer( r.syncer = newSyncer(
r.cfg, r.cfg,
r.Logger,
r.logger,
r.conn, r.conn,
r.connQuery, r.connQuery,
r.stateProvider, r.stateProvider,
@ -310,7 +312,7 @@ func (r *Reactor) Sync(ctx context.Context) (sm.State, error) {
err = r.Backfill(ctx, state) err = r.Backfill(ctx, state)
if err != nil { if err != nil {
r.Logger.Error("backfill failed. Proceeding optimistically...", "err", err)
r.logger.Error("backfill failed. Proceeding optimistically...", "err", err)
} }
return state, nil return state, nil
@ -348,7 +350,7 @@ func (r *Reactor) backfill(
trustedBlockID types.BlockID, trustedBlockID types.BlockID,
stopTime time.Time, stopTime time.Time,
) error { ) error {
r.Logger.Info("starting backfill process...", "startHeight", startHeight,
r.logger.Info("starting backfill process...", "startHeight", startHeight,
"stopHeight", stopHeight, "stopTime", stopTime, "trustedBlockID", trustedBlockID) "stopHeight", stopHeight, "stopTime", stopTime, "trustedBlockID", trustedBlockID)
r.backfillBlockTotal = startHeight - stopHeight + 1 r.backfillBlockTotal = startHeight - stopHeight + 1
@ -378,7 +380,7 @@ func (r *Reactor) backfill(
case height := <-queue.nextHeight(): case height := <-queue.nextHeight():
// pop the next peer of the list to send a request to // pop the next peer of the list to send a request to
peer := r.peers.Pop(ctx) peer := r.peers.Pop(ctx)
r.Logger.Debug("fetching next block", "height", height, "peer", peer)
r.logger.Debug("fetching next block", "height", height, "peer", peer)
subCtx, cancel := context.WithTimeout(ctxWithCancel, lightBlockResponseTimeout) subCtx, cancel := context.WithTimeout(ctxWithCancel, lightBlockResponseTimeout)
defer cancel() defer cancel()
lb, err := func() (*types.LightBlock, error) { lb, err := func() (*types.LightBlock, error) {
@ -394,18 +396,18 @@ func (r *Reactor) backfill(
if err != nil { if err != nil {
queue.retry(height) queue.retry(height)
if errors.Is(err, errNoConnectedPeers) { if errors.Is(err, errNoConnectedPeers) {
r.Logger.Info("backfill: no connected peers to fetch light blocks from; sleeping...",
r.logger.Info("backfill: no connected peers to fetch light blocks from; sleeping...",
"sleepTime", sleepTime) "sleepTime", sleepTime)
time.Sleep(sleepTime) time.Sleep(sleepTime)
} else { } else {
// we don't punish the peer as it might just have not responded in time // we don't punish the peer as it might just have not responded in time
r.Logger.Info("backfill: error with fetching light block",
r.logger.Info("backfill: error with fetching light block",
"height", height, "err", err) "height", height, "err", err)
} }
continue continue
} }
if lb == nil { if lb == nil {
r.Logger.Info("backfill: peer didn't have block, fetching from another peer", "height", height)
r.logger.Info("backfill: peer didn't have block, fetching from another peer", "height", height)
queue.retry(height) queue.retry(height)
// As we are fetching blocks backwards, if this node doesn't have the block it likely doesn't // As we are fetching blocks backwards, if this node doesn't have the block it likely doesn't
// have any prior ones, thus we remove it from the peer list. // have any prior ones, thus we remove it from the peer list.
@ -417,7 +419,7 @@ func (r *Reactor) backfill(
// hashes line up // hashes line up
err = lb.ValidateBasic(chainID) err = lb.ValidateBasic(chainID)
if err != nil || lb.Height != height { if err != nil || lb.Height != height {
r.Logger.Info("backfill: fetched light block failed validate basic, removing peer...",
r.logger.Info("backfill: fetched light block failed validate basic, removing peer...",
"err", err, "height", height) "err", err, "height", height)
queue.retry(height) queue.retry(height)
r.blockCh.Error <- p2p.PeerError{ r.blockCh.Error <- p2p.PeerError{
@ -432,7 +434,7 @@ func (r *Reactor) backfill(
block: lb, block: lb,
peer: peer, peer: peer,
}) })
r.Logger.Debug("backfill: added light block to processing queue", "height", height)
r.logger.Debug("backfill: added light block to processing queue", "height", height)
case <-queue.done(): case <-queue.done():
return return
@ -456,7 +458,7 @@ func (r *Reactor) backfill(
// we equate to. ValidatorsHash and CommitHash have already been // we equate to. ValidatorsHash and CommitHash have already been
// checked in the `ValidateBasic` // checked in the `ValidateBasic`
if w, g := trustedBlockID.Hash, resp.block.Hash(); !bytes.Equal(w, g) { if w, g := trustedBlockID.Hash, resp.block.Hash(); !bytes.Equal(w, g) {
r.Logger.Info("received invalid light block. header hash doesn't match trusted LastBlockID",
r.logger.Info("received invalid light block. header hash doesn't match trusted LastBlockID",
"trustedHash", w, "receivedHash", g, "height", resp.block.Height) "trustedHash", w, "receivedHash", g, "height", resp.block.Height)
r.blockCh.Error <- p2p.PeerError{ r.blockCh.Error <- p2p.PeerError{
NodeID: resp.peer, NodeID: resp.peer,
@ -486,7 +488,7 @@ func (r *Reactor) backfill(
trustedBlockID = resp.block.LastBlockID trustedBlockID = resp.block.LastBlockID
queue.success() queue.success()
r.Logger.Info("backfill: verified and stored light block", "height", resp.block.Height)
r.logger.Info("backfill: verified and stored light block", "height", resp.block.Height)
lastValidatorSet = resp.block.ValidatorSet lastValidatorSet = resp.block.ValidatorSet
@ -510,7 +512,7 @@ func (r *Reactor) backfill(
return err return err
} }
r.Logger.Info("successfully completed backfill process", "endHeight", queue.terminal.Height)
r.logger.Info("successfully completed backfill process", "endHeight", queue.terminal.Height)
return nil return nil
} }
} }
@ -520,7 +522,7 @@ func (r *Reactor) backfill(
// SnapshotChannel. It returns an error only if the Envelope.Message is unknown // SnapshotChannel. It returns an error only if the Envelope.Message is unknown
// for this channel. This should never be called outside of handleMessage. // for this channel. This should never be called outside of handleMessage.
func (r *Reactor) handleSnapshotMessage(envelope p2p.Envelope) error { func (r *Reactor) handleSnapshotMessage(envelope p2p.Envelope) error {
logger := r.Logger.With("peer", envelope.From)
logger := r.logger.With("peer", envelope.From)
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *ssproto.SnapshotsRequest: case *ssproto.SnapshotsRequest:
@ -591,7 +593,7 @@ func (r *Reactor) handleSnapshotMessage(envelope p2p.Envelope) error {
func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *ssproto.ChunkRequest: case *ssproto.ChunkRequest:
r.Logger.Debug(
r.logger.Debug(
"received chunk request", "received chunk request",
"height", msg.Height, "height", msg.Height,
"format", msg.Format, "format", msg.Format,
@ -604,7 +606,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
Chunk: msg.Index, Chunk: msg.Index,
}) })
if err != nil { if err != nil {
r.Logger.Error(
r.logger.Error(
"failed to load chunk", "failed to load chunk",
"height", msg.Height, "height", msg.Height,
"format", msg.Format, "format", msg.Format,
@ -615,7 +617,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
return nil return nil
} }
r.Logger.Debug(
r.logger.Debug(
"sending chunk", "sending chunk",
"height", msg.Height, "height", msg.Height,
"format", msg.Format, "format", msg.Format,
@ -638,11 +640,11 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
defer r.mtx.RUnlock() defer r.mtx.RUnlock()
if r.syncer == nil { if r.syncer == nil {
r.Logger.Debug("received unexpected chunk; no state sync in progress", "peer", envelope.From)
r.logger.Debug("received unexpected chunk; no state sync in progress", "peer", envelope.From)
return nil return nil
} }
r.Logger.Debug(
r.logger.Debug(
"received chunk; adding to sync", "received chunk; adding to sync",
"height", msg.Height, "height", msg.Height,
"format", msg.Format, "format", msg.Format,
@ -657,7 +659,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
Sender: envelope.From, Sender: envelope.From,
}) })
if err != nil { if err != nil {
r.Logger.Error(
r.logger.Error(
"failed to add chunk", "failed to add chunk",
"height", msg.Height, "height", msg.Height,
"format", msg.Format, "format", msg.Format,
@ -678,10 +680,10 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error { func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error {
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *ssproto.LightBlockRequest: case *ssproto.LightBlockRequest:
r.Logger.Info("received light block request", "height", msg.Height)
r.logger.Info("received light block request", "height", msg.Height)
lb, err := r.fetchLightBlock(msg.Height) lb, err := r.fetchLightBlock(msg.Height)
if err != nil { if err != nil {
r.Logger.Error("failed to retrieve light block", "err", err, "height", msg.Height)
r.logger.Error("failed to retrieve light block", "err", err, "height", msg.Height)
return err return err
} }
if lb == nil { if lb == nil {
@ -696,7 +698,7 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error {
lbproto, err := lb.ToProto() lbproto, err := lb.ToProto()
if err != nil { if err != nil {
r.Logger.Error("marshaling light block to proto", "err", err)
r.logger.Error("marshaling light block to proto", "err", err)
return nil return nil
} }
@ -714,9 +716,9 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error {
if msg.LightBlock != nil { if msg.LightBlock != nil {
height = msg.LightBlock.SignedHeader.Header.Height height = msg.LightBlock.SignedHeader.Header.Height
} }
r.Logger.Info("received light block response", "peer", envelope.From, "height", height)
r.logger.Info("received light block response", "peer", envelope.From, "height", height)
if err := r.dispatcher.Respond(msg.LightBlock, envelope.From); err != nil { if err := r.dispatcher.Respond(msg.LightBlock, envelope.From); err != nil {
r.Logger.Error("error processing light block response", "err", err, "height", height)
r.logger.Error("error processing light block response", "err", err, "height", height)
} }
default: default:
@ -729,10 +731,10 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error {
func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error { func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error {
switch msg := envelope.Message.(type) { switch msg := envelope.Message.(type) {
case *ssproto.ParamsRequest: case *ssproto.ParamsRequest:
r.Logger.Debug("received consensus params request", "height", msg.Height)
r.logger.Debug("received consensus params request", "height", msg.Height)
cp, err := r.stateStore.LoadConsensusParams(int64(msg.Height)) cp, err := r.stateStore.LoadConsensusParams(int64(msg.Height))
if err != nil { if err != nil {
r.Logger.Error("failed to fetch requested consensus params", "err", err, "height", msg.Height)
r.logger.Error("failed to fetch requested consensus params", "err", err, "height", msg.Height)
return nil return nil
} }
@ -748,7 +750,7 @@ func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error {
case *ssproto.ParamsResponse: case *ssproto.ParamsResponse:
r.mtx.RLock() r.mtx.RLock()
defer r.mtx.RUnlock() defer r.mtx.RUnlock()
r.Logger.Debug("received consensus params response", "height", msg.Height)
r.logger.Debug("received consensus params response", "height", msg.Height)
cp := types.ConsensusParamsFromProto(msg.ConsensusParams) cp := types.ConsensusParamsFromProto(msg.ConsensusParams)
@ -759,7 +761,7 @@ func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error {
return errors.New("failed to send consensus params, stateprovider not ready for response") return errors.New("failed to send consensus params, stateprovider not ready for response")
} }
} else { } else {
r.Logger.Debug("received unexpected params response; using RPC state provider", "peer", envelope.From)
r.logger.Debug("received unexpected params response; using RPC state provider", "peer", envelope.From)
} }
default: default:
@ -776,7 +778,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
defer func() { defer func() {
if e := recover(); e != nil { if e := recover(); e != nil {
err = fmt.Errorf("panic in processing message: %v", e) err = fmt.Errorf("panic in processing message: %v", e)
r.Logger.Error(
r.logger.Error(
"recovering from processing message panic", "recovering from processing message panic",
"err", err, "err", err,
"stack", string(debug.Stack()), "stack", string(debug.Stack()),
@ -784,7 +786,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err
} }
}() }()
r.Logger.Debug("received message", "message", reflect.TypeOf(envelope.Message), "peer", envelope.From)
r.logger.Debug("received message", "message", reflect.TypeOf(envelope.Message), "peer", envelope.From)
switch chID { switch chID {
case SnapshotChannel: case SnapshotChannel:
@ -817,7 +819,7 @@ func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string)
return return
case envelope := <-ch.In: case envelope := <-ch.In:
if err := r.handleMessage(ch.ID, envelope); err != nil { if err := r.handleMessage(ch.ID, envelope); err != nil {
r.Logger.Error("failed to process message",
r.logger.Error("failed to process message",
"err", err, "err", err,
"channel", chName, "channel", chName,
"ch_id", ch.ID, "ch_id", ch.ID,
@ -829,7 +831,7 @@ func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string)
} }
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("channel closed", "channel", chName)
r.logger.Debug("channel closed", "channel", chName)
return return
} }
} }
@ -838,7 +840,7 @@ func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string)
// processPeerUpdate processes a PeerUpdate, returning an error upon failing to // processPeerUpdate processes a PeerUpdate, returning an error upon failing to
// handle the PeerUpdate or if a panic is recovered. // handle the PeerUpdate or if a panic is recovered.
func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) { func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
r.Logger.Info("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Info("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
switch peerUpdate.Status { switch peerUpdate.Status {
case p2p.PeerStatusUp: case p2p.PeerStatusUp:
@ -859,7 +861,7 @@ func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
r.providers[peerUpdate.NodeID] = newProvider r.providers[peerUpdate.NodeID] = newProvider
err := r.syncer.AddPeer(peerUpdate.NodeID) err := r.syncer.AddPeer(peerUpdate.NodeID)
if err != nil { if err != nil {
r.Logger.Error("error adding peer to syncer", "error", err)
r.logger.Error("error adding peer to syncer", "error", err)
return return
} }
if sp, ok := r.stateProvider.(*stateProviderP2P); ok { if sp, ok := r.stateProvider.(*stateProviderP2P); ok {
@ -872,7 +874,7 @@ func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
delete(r.providers, peerUpdate.NodeID) delete(r.providers, peerUpdate.NodeID)
r.syncer.RemovePeer(peerUpdate.NodeID) r.syncer.RemovePeer(peerUpdate.NodeID)
} }
r.Logger.Info("processed peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
r.logger.Info("processed peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
} }
// processPeerUpdates initiates a blocking process where we listen for and handle // processPeerUpdates initiates a blocking process where we listen for and handle
@ -889,7 +891,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) {
r.processPeerUpdate(peerUpdate) r.processPeerUpdate(peerUpdate)
case <-r.closeCh: case <-r.closeCh:
r.Logger.Debug("stopped listening on peer updates channel; closing...")
r.logger.Debug("stopped listening on peer updates channel; closing...")
return return
} }
} }
@ -985,7 +987,7 @@ func (r *Reactor) waitForEnoughPeers(ctx context.Context, numPeers int) error {
case <-t.C: case <-t.C:
continue continue
case <-logT.C: case <-logT.C:
r.Logger.Info("waiting for sufficient peers to start statesync",
r.logger.Info("waiting for sufficient peers to start statesync",
"duration", time.Since(startAt).String(), "duration", time.Since(startAt).String(),
"target", numPeers, "target", numPeers,
"peers", r.peers.Len(), "peers", r.peers.Len(),
@ -1004,7 +1006,7 @@ func (r *Reactor) initStateProvider(ctx context.Context, chainID string, initial
Height: r.cfg.TrustHeight, Height: r.cfg.TrustHeight,
Hash: r.cfg.TrustHashBytes(), Hash: r.cfg.TrustHashBytes(),
} }
spLogger := r.Logger.With("module", "stateprovider")
spLogger := r.logger.With("module", "stateprovider")
spLogger.Info("initializing state provider", "trustPeriod", to.Period, spLogger.Info("initializing state provider", "trustPeriod", to.Period,
"trustHeight", to.Height, "useP2P", r.cfg.UseP2P) "trustHeight", to.Height, "useP2P", r.cfg.UseP2P)


+ 3
- 1
libs/pubsub/example_test.go View File

@ -7,6 +7,7 @@ import (
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
abci "github.com/tendermint/tendermint/abci/types" abci "github.com/tendermint/tendermint/abci/types"
"github.com/tendermint/tendermint/libs/log"
"github.com/tendermint/tendermint/libs/pubsub" "github.com/tendermint/tendermint/libs/pubsub"
"github.com/tendermint/tendermint/libs/pubsub/query" "github.com/tendermint/tendermint/libs/pubsub/query"
) )
@ -14,7 +15,8 @@ import (
func TestExample(t *testing.T) { func TestExample(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
s := newTestServer(ctx, t, log.TestingLogger())
sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: "example-client", ClientID: "example-client",


+ 8
- 7
libs/pubsub/pubsub.go View File

@ -41,6 +41,7 @@ import (
"sync" "sync"
"github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/abci/types"
"github.com/tendermint/tendermint/libs/log"
"github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/libs/service"
) )
@ -103,6 +104,7 @@ func (args UnsubscribeArgs) Validate() error {
// messages with or without events, and manages internal state. // messages with or without events, and manages internal state.
type Server struct { type Server struct {
service.BaseService service.BaseService
logger log.Logger
queue chan item queue chan item
done <-chan struct{} // closed when server should exit done <-chan struct{} // closed when server should exit
@ -133,9 +135,10 @@ type Option func(*Server)
// NewServer returns a new server. See the commentary on the Option functions // NewServer returns a new server. See the commentary on the Option functions
// for a detailed description of how to configure buffering. If no options are // for a detailed description of how to configure buffering. If no options are
// provided, the resulting server's queue is unbuffered. // provided, the resulting server's queue is unbuffered.
func NewServer(options ...Option) *Server {
s := new(Server)
s.BaseService = *service.NewBaseService(nil, "PubSub", s)
func NewServer(logger log.Logger, options ...Option) *Server {
s := &Server{logger: logger}
s.BaseService = *service.NewBaseService(logger, "PubSub", s)
for _, opt := range options { for _, opt := range options {
opt(s) opt(s)
} }
@ -167,9 +170,7 @@ func (s *Server) BufferCapacity() int { return cap(s.queue) }
// If len(capacities) > 0, its first value is used as the queue capacity. // If len(capacities) > 0, its first value is used as the queue capacity.
// //
// Deprecated: Use SubscribeWithArgs. This method will be removed in v0.36. // Deprecated: Use SubscribeWithArgs. This method will be removed in v0.36.
func (s *Server) Subscribe(ctx context.Context,
clientID string, query Query, capacities ...int) (*Subscription, error) {
func (s *Server) Subscribe(ctx context.Context, clientID string, query Query, capacities ...int) (*Subscription, error) {
args := SubscribeArgs{ args := SubscribeArgs{
ClientID: clientID, ClientID: clientID,
Query: query, Query: query,
@ -384,7 +385,7 @@ func (s *Server) run(ctx context.Context) {
// Sender: Service the queue and forward messages to subscribers. // Sender: Service the queue and forward messages to subscribers.
for it := range queue { for it := range queue {
if err := s.send(it.Data, it.Events); err != nil { if err := s.send(it.Data, it.Events); err != nil {
s.Logger.Error("Error sending event", "err", err)
s.logger.Error("Error sending event", "err", err)
} }
} }
// Terminate all subscribers before exit. // Terminate all subscribers before exit.


+ 32
- 21
libs/pubsub/pubsub_test.go View File

@ -22,7 +22,8 @@ func TestSubscribeWithArgs(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
t.Run("DefaultLimit", func(t *testing.T) { t.Run("DefaultLimit", func(t *testing.T) {
sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
@ -50,8 +51,9 @@ func TestSubscribeWithArgs(t *testing.T) {
func TestObserver(t *testing.T) { func TestObserver(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
logger := log.TestingLogger()
s := newTestServer(ctx, t)
s := newTestServer(ctx, t, logger)
done := make(chan struct{}) done := make(chan struct{})
var got interface{} var got interface{}
@ -71,7 +73,9 @@ func TestObserverErrors(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
require.Error(t, s.Observe(ctx, nil, query.All)) require.Error(t, s.Observe(ctx, nil, query.All))
require.NoError(t, s.Observe(ctx, func(pubsub.Message) error { return nil })) require.NoError(t, s.Observe(ctx, func(pubsub.Message) error { return nil }))
@ -82,7 +86,9 @@ func TestPublishDoesNotBlock(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -110,7 +116,8 @@ func TestSubscribeErrors(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
t.Run("EmptyQueryErr", func(t *testing.T) { t.Run("EmptyQueryErr", func(t *testing.T) {
_, err := s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ClientID: clientID}) _, err := s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ClientID: clientID})
@ -130,7 +137,8 @@ func TestSlowSubscriber(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -151,7 +159,8 @@ func TestDifferentClients(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: "client-1", ClientID: "client-1",
@ -205,7 +214,8 @@ func TestSubscribeDuplicateKeys(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
testCases := []struct { testCases := []struct {
query string query string
@ -260,7 +270,8 @@ func TestClientSubscribesTwice(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
q := query.MustCompile(`tm.events.type='NewBlock'`) q := query.MustCompile(`tm.events.type='NewBlock'`)
events := []abci.Event{{ events := []abci.Event{{
@ -295,7 +306,8 @@ func TestUnsubscribe(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -319,7 +331,8 @@ func TestClientUnsubscribesTwice(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -340,7 +353,8 @@ func TestResubscribe(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
args := pubsub.SubscribeArgs{ args := pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -363,7 +377,8 @@ func TestUnsubscribeAll(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
defer cancel() defer cancel()
s := newTestServer(ctx, t)
logger := log.TestingLogger()
s := newTestServer(ctx, t, logger)
sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{
ClientID: clientID, ClientID: clientID,
@ -383,10 +398,8 @@ func TestUnsubscribeAll(t *testing.T) {
} }
func TestBufferCapacity(t *testing.T) { func TestBufferCapacity(t *testing.T) {
s := pubsub.NewServer(pubsub.BufferCapacity(2),
func(s *pubsub.Server) {
s.Logger = log.TestingLogger()
})
logger := log.TestingLogger()
s := pubsub.NewServer(logger, pubsub.BufferCapacity(2))
require.Equal(t, 2, s.BufferCapacity()) require.Equal(t, 2, s.BufferCapacity())
@ -402,12 +415,10 @@ func TestBufferCapacity(t *testing.T) {
require.ErrorIs(t, s.Publish(ctx, "Ironclad"), context.DeadlineExceeded) require.ErrorIs(t, s.Publish(ctx, "Ironclad"), context.DeadlineExceeded)
} }
func newTestServer(ctx context.Context, t testing.TB) *pubsub.Server {
func newTestServer(ctx context.Context, t testing.TB, logger log.Logger) *pubsub.Server {
t.Helper() t.Helper()
s := pubsub.NewServer(func(s *pubsub.Server) {
s.Logger = log.TestingLogger()
})
s := pubsub.NewServer(logger)
require.NoError(t, s.Start(ctx)) require.NoError(t, s.Start(ctx))
t.Cleanup(s.Wait) t.Cleanup(s.Wait)


+ 10
- 10
libs/service/service.go View File

@ -92,7 +92,7 @@ Typical usage:
} }
*/ */
type BaseService struct { type BaseService struct {
Logger log.Logger
logger log.Logger
name string name string
started uint32 // atomic started uint32 // atomic
stopped uint32 // atomic stopped uint32 // atomic
@ -109,7 +109,7 @@ func NewBaseService(logger log.Logger, name string, impl Implementation) *BaseSe
} }
return &BaseService{ return &BaseService{
Logger: logger,
logger: logger,
name: name, name: name,
quit: make(chan struct{}), quit: make(chan struct{}),
impl: impl, impl: impl,
@ -122,12 +122,12 @@ func NewBaseService(logger log.Logger, name string, impl Implementation) *BaseSe
func (bs *BaseService) Start(ctx context.Context) error { func (bs *BaseService) Start(ctx context.Context) error {
if atomic.CompareAndSwapUint32(&bs.started, 0, 1) { if atomic.CompareAndSwapUint32(&bs.started, 0, 1) {
if atomic.LoadUint32(&bs.stopped) == 1 { if atomic.LoadUint32(&bs.stopped) == 1 {
bs.Logger.Error("not starting service; already stopped", "service", bs.name, "impl", bs.impl.String())
bs.logger.Error("not starting service; already stopped", "service", bs.name, "impl", bs.impl.String())
atomic.StoreUint32(&bs.started, 0) atomic.StoreUint32(&bs.started, 0)
return ErrAlreadyStopped return ErrAlreadyStopped
} }
bs.Logger.Info("starting service", "service", bs.name, "impl", bs.impl.String())
bs.logger.Info("starting service", "service", bs.name, "impl", bs.impl.String())
if err := bs.impl.OnStart(ctx); err != nil { if err := bs.impl.OnStart(ctx); err != nil {
// revert flag // revert flag
@ -151,13 +151,13 @@ func (bs *BaseService) Start(ctx context.Context) error {
// the context was cancel and we // the context was cancel and we
// should stop. // should stop.
if err := bs.Stop(); err != nil { if err := bs.Stop(); err != nil {
bs.Logger.Error("stopped service",
bs.logger.Error("stopped service",
"err", err.Error(), "err", err.Error(),
"service", bs.name, "service", bs.name,
"impl", bs.impl.String()) "impl", bs.impl.String())
} }
bs.Logger.Info("stopped service",
bs.logger.Info("stopped service",
"service", bs.name, "service", bs.name,
"impl", bs.impl.String()) "impl", bs.impl.String())
} }
@ -166,7 +166,7 @@ func (bs *BaseService) Start(ctx context.Context) error {
return nil return nil
} }
bs.Logger.Debug("not starting service; already started", "service", bs.name, "impl", bs.impl.String())
bs.logger.Debug("not starting service; already started", "service", bs.name, "impl", bs.impl.String())
return ErrAlreadyStarted return ErrAlreadyStarted
} }
@ -175,19 +175,19 @@ func (bs *BaseService) Start(ctx context.Context) error {
func (bs *BaseService) Stop() error { func (bs *BaseService) Stop() error {
if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) { if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) {
if atomic.LoadUint32(&bs.started) == 0 { if atomic.LoadUint32(&bs.started) == 0 {
bs.Logger.Error("not stopping service; not started yet", "service", bs.name, "impl", bs.impl.String())
bs.logger.Error("not stopping service; not started yet", "service", bs.name, "impl", bs.impl.String())
atomic.StoreUint32(&bs.stopped, 0) atomic.StoreUint32(&bs.stopped, 0)
return ErrNotStarted return ErrNotStarted
} }
bs.Logger.Info("stopping service", "service", bs.name, "impl", bs.impl.String())
bs.logger.Info("stopping service", "service", bs.name, "impl", bs.impl.String())
bs.impl.OnStop() bs.impl.OnStop()
close(bs.quit) close(bs.quit)
return nil return nil
} }
bs.Logger.Debug("not stopping service; already stopped", "service", bs.name, "impl", bs.impl.String())
bs.logger.Debug("not stopping service; already stopped", "service", bs.name, "impl", bs.impl.String())
return ErrAlreadyStopped return ErrAlreadyStopped
} }


+ 25
- 22
node/node.go View File

@ -46,6 +46,7 @@ import (
// It includes all configuration information and running services. // It includes all configuration information and running services.
type nodeImpl struct { type nodeImpl struct {
service.BaseService service.BaseService
logger log.Logger
// config // config
config *config.Config config *config.Config
@ -388,6 +389,7 @@ func makeNode(
node := &nodeImpl{ node := &nodeImpl{
config: cfg, config: cfg,
logger: logger,
genesisDoc: genDoc, genesisDoc: genDoc,
privValidator: privValidator, privValidator: privValidator,
@ -495,6 +497,7 @@ func makeSeedNode(
node := &nodeImpl{ node := &nodeImpl{
config: cfg, config: cfg,
logger: logger,
genesisDoc: genDoc, genesisDoc: genDoc,
nodeInfo: nodeInfo, nodeInfo: nodeInfo,
@ -527,10 +530,10 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
}() }()
go func() { go func() {
n.Logger.Info("Starting pprof server", "laddr", n.config.RPC.PprofListenAddress)
n.logger.Info("Starting pprof server", "laddr", n.config.RPC.PprofListenAddress)
if err := srv.ListenAndServe(); err != nil { if err := srv.ListenAndServe(); err != nil {
n.Logger.Error("pprof server error", "err", err)
n.logger.Error("pprof server error", "err", err)
rpcCancel() rpcCancel()
} }
}() }()
@ -539,7 +542,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
now := tmtime.Now() now := tmtime.Now()
genTime := n.genesisDoc.GenesisTime genTime := n.genesisDoc.GenesisTime
if genTime.After(now) { if genTime.After(now) {
n.Logger.Info("Genesis time is in the future. Sleeping until then...", "genTime", genTime)
n.logger.Info("Genesis time is in the future. Sleeping until then...", "genTime", genTime)
time.Sleep(genTime.Sub(now)) time.Sleep(genTime.Sub(now))
} }
@ -617,19 +620,19 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
// because of the statesync doesn't have the concreate state height before fetched the snapshot. // because of the statesync doesn't have the concreate state height before fetched the snapshot.
d := types.EventDataStateSyncStatus{Complete: false, Height: state.InitialHeight} d := types.EventDataStateSyncStatus{Complete: false, Height: state.InitialHeight}
if err := n.eventBus.PublishEventStateSyncStatus(ctx, d); err != nil { if err := n.eventBus.PublishEventStateSyncStatus(ctx, d); err != nil {
n.eventBus.Logger.Error("failed to emit the statesync start event", "err", err)
n.logger.Error("failed to emit the statesync start event", "err", err)
} }
// FIXME: We shouldn't allow state sync to silently error out without // FIXME: We shouldn't allow state sync to silently error out without
// bubbling up the error and gracefully shutting down the rest of the node // bubbling up the error and gracefully shutting down the rest of the node
go func() { go func() {
n.Logger.Info("starting state sync")
n.logger.Info("starting state sync")
state, err := n.stateSyncReactor.Sync(ctx) state, err := n.stateSyncReactor.Sync(ctx)
if err != nil { if err != nil {
n.Logger.Error("state sync failed; shutting down this node", "err", err)
n.logger.Error("state sync failed; shutting down this node", "err", err)
// stop the node // stop the node
if err := n.Stop(); err != nil { if err := n.Stop(); err != nil {
n.Logger.Error("failed to shut down node", "err", err)
n.logger.Error("failed to shut down node", "err", err)
} }
return return
} }
@ -642,7 +645,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
Height: state.LastBlockHeight, Height: state.LastBlockHeight,
}); err != nil { }); err != nil {
n.eventBus.Logger.Error("failed to emit the statesync start event", "err", err)
n.logger.Error("failed to emit the statesync start event", "err", err)
} }
// TODO: Some form of orchestrator is needed here between the state // TODO: Some form of orchestrator is needed here between the state
@ -651,7 +654,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
// FIXME Very ugly to have these metrics bleed through here. // FIXME Very ugly to have these metrics bleed through here.
n.consensusReactor.SetBlockSyncingMetrics(1) n.consensusReactor.SetBlockSyncingMetrics(1)
if err := bcR.SwitchToBlockSync(ctx, state); err != nil { if err := bcR.SwitchToBlockSync(ctx, state); err != nil {
n.Logger.Error("failed to switch to block sync", "err", err)
n.logger.Error("failed to switch to block sync", "err", err)
return return
} }
@ -661,7 +664,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
Height: state.LastBlockHeight, Height: state.LastBlockHeight,
}); err != nil { }); err != nil {
n.eventBus.Logger.Error("failed to emit the block sync starting event", "err", err)
n.logger.Error("failed to emit the block sync starting event", "err", err)
} }
}() }()
} }
@ -671,7 +674,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error {
// OnStop stops the Node. It implements service.Service. // OnStop stops the Node. It implements service.Service.
func (n *nodeImpl) OnStop() { func (n *nodeImpl) OnStop() {
n.Logger.Info("Stopping Node")
n.logger.Info("Stopping Node")
if n.eventBus != nil { if n.eventBus != nil {
n.eventBus.Wait() n.eventBus.Wait()
@ -682,7 +685,7 @@ func (n *nodeImpl) OnStop() {
for _, es := range n.eventSinks { for _, es := range n.eventSinks {
if err := es.Stop(); err != nil { if err := es.Stop(); err != nil {
n.Logger.Error("failed to stop event sink", "err", err)
n.logger.Error("failed to stop event sink", "err", err)
} }
} }
@ -699,9 +702,9 @@ func (n *nodeImpl) OnStop() {
// finally stop the listeners / external services // finally stop the listeners / external services
for _, l := range n.rpcListeners { for _, l := range n.rpcListeners {
n.Logger.Info("Closing rpc listener", "listener", l)
n.logger.Info("Closing rpc listener", "listener", l)
if err := l.Close(); err != nil { if err := l.Close(); err != nil {
n.Logger.Error("Error closing listener", "listener", l, "err", err)
n.logger.Error("Error closing listener", "listener", l, "err", err)
} }
} }
@ -712,23 +715,23 @@ func (n *nodeImpl) OnStop() {
if n.prometheusSrv != nil { if n.prometheusSrv != nil {
if err := n.prometheusSrv.Shutdown(context.Background()); err != nil { if err := n.prometheusSrv.Shutdown(context.Background()); err != nil {
// Error from closing listeners, or context timeout: // Error from closing listeners, or context timeout:
n.Logger.Error("Prometheus HTTP server Shutdown", "err", err)
n.logger.Error("Prometheus HTTP server Shutdown", "err", err)
} }
} }
if err := n.shutdownOps(); err != nil { if err := n.shutdownOps(); err != nil {
if strings.TrimSpace(err.Error()) != "" { if strings.TrimSpace(err.Error()) != "" {
n.Logger.Error("problem shutting down additional services", "err", err)
n.logger.Error("problem shutting down additional services", "err", err)
} }
} }
if n.blockStore != nil { if n.blockStore != nil {
if err := n.blockStore.Close(); err != nil { if err := n.blockStore.Close(); err != nil {
n.Logger.Error("problem closing blockstore", "err", err)
n.logger.Error("problem closing blockstore", "err", err)
} }
} }
if n.stateStore != nil { if n.stateStore != nil {
if err := n.stateStore.Close(); err != nil { if err := n.stateStore.Close(); err != nil {
n.Logger.Error("problem closing statestore", "err", err)
n.logger.Error("problem closing statestore", "err", err)
} }
} }
} }
@ -767,7 +770,7 @@ func (n *nodeImpl) startRPC(ctx context.Context) ([]net.Listener, error) {
listeners := make([]net.Listener, len(listenAddrs)) listeners := make([]net.Listener, len(listenAddrs))
for i, listenAddr := range listenAddrs { for i, listenAddr := range listenAddrs {
mux := http.NewServeMux() mux := http.NewServeMux()
rpcLogger := n.Logger.With("module", "rpc-server")
rpcLogger := n.logger.With("module", "rpc-server")
wmLogger := rpcLogger.With("protocol", "websocket") wmLogger := rpcLogger.With("protocol", "websocket")
wm := rpcserver.NewWebsocketManager(routes, wm := rpcserver.NewWebsocketManager(routes,
rpcserver.OnDisconnect(func(remoteAddr string) { rpcserver.OnDisconnect(func(remoteAddr string) {
@ -809,7 +812,7 @@ func (n *nodeImpl) startRPC(ctx context.Context) ([]net.Listener, error) {
rpcLogger, rpcLogger,
cfg, cfg,
); err != nil { ); err != nil {
n.Logger.Error("Error serving server with TLS", "err", err)
n.logger.Error("Error serving server with TLS", "err", err)
} }
}() }()
} else { } else {
@ -821,7 +824,7 @@ func (n *nodeImpl) startRPC(ctx context.Context) ([]net.Listener, error) {
rpcLogger, rpcLogger,
cfg, cfg,
); err != nil { ); err != nil {
n.Logger.Error("Error serving server", "err", err)
n.logger.Error("Error serving server", "err", err)
} }
}() }()
} }
@ -858,7 +861,7 @@ func (n *nodeImpl) startPrometheusServer(ctx context.Context, addr string) *http
go func() { go func() {
if err := srv.ListenAndServe(); err != nil { if err := srv.ListenAndServe(); err != nil {
n.Logger.Error("Prometheus HTTP server ListenAndServe", "err", err)
n.logger.Error("Prometheus HTTP server ListenAndServe", "err", err)
promCancel() promCancel()
} }
}() }()


+ 8
- 2
privval/signer_client.go View File

@ -7,6 +7,7 @@ import (
"github.com/tendermint/tendermint/crypto" "github.com/tendermint/tendermint/crypto"
"github.com/tendermint/tendermint/crypto/encoding" "github.com/tendermint/tendermint/crypto/encoding"
"github.com/tendermint/tendermint/libs/log"
privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval" privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval"
tmproto "github.com/tendermint/tendermint/proto/tendermint/types" tmproto "github.com/tendermint/tendermint/proto/tendermint/types"
"github.com/tendermint/tendermint/types" "github.com/tendermint/tendermint/types"
@ -15,6 +16,7 @@ import (
// SignerClient implements PrivValidator. // SignerClient implements PrivValidator.
// Handles remote validator connections that provide signing services // Handles remote validator connections that provide signing services
type SignerClient struct { type SignerClient struct {
logger log.Logger
endpoint *SignerListenerEndpoint endpoint *SignerListenerEndpoint
chainID string chainID string
} }
@ -30,7 +32,11 @@ func NewSignerClient(ctx context.Context, endpoint *SignerListenerEndpoint, chai
} }
} }
return &SignerClient{endpoint: endpoint, chainID: chainID}, nil
return &SignerClient{
logger: endpoint.logger,
endpoint: endpoint,
chainID: chainID,
}, nil
} }
// Close closes the underlying connection // Close closes the underlying connection
@ -55,7 +61,7 @@ func (sc *SignerClient) WaitForConnection(maxWait time.Duration) error {
func (sc *SignerClient) Ping() error { func (sc *SignerClient) Ping() error {
response, err := sc.endpoint.SendRequest(mustWrapMsg(&privvalproto.PingRequest{})) response, err := sc.endpoint.SendRequest(mustWrapMsg(&privvalproto.PingRequest{}))
if err != nil { if err != nil {
sc.endpoint.Logger.Error("SignerClient::Ping", "err", err)
sc.logger.Error("SignerClient::Ping", "err", err)
return nil return nil
} }


+ 2
- 2
privval/signer_client_test.go View File

@ -267,9 +267,9 @@ func TestSignerVoteKeepAlive(t *testing.T) {
// in this particular case, we use the dialer logger to ensure that // in this particular case, we use the dialer logger to ensure that
// test messages are properly interleaved in the test logs // test messages are properly interleaved in the test logs
tc.signerServer.Logger.Debug("TEST: Forced Wait -------------------------------------------------")
tc.signerServer.endpoint.logger.Debug("TEST: Forced Wait -------------------------------------------------")
time.Sleep(testTimeoutReadWrite * 3) time.Sleep(testTimeoutReadWrite * 3)
tc.signerServer.Logger.Debug("TEST: Forced Wait DONE---------------------------------------------")
tc.signerServer.endpoint.logger.Debug("TEST: Forced Wait DONE---------------------------------------------")
require.NoError(t, tc.mockPV.SignVote(ctx, tc.chainID, want.ToProto())) require.NoError(t, tc.mockPV.SignVote(ctx, tc.chainID, want.ToProto()))
require.NoError(t, tc.signerClient.SignVote(ctx, tc.chainID, have.ToProto())) require.NoError(t, tc.signerClient.SignVote(ctx, tc.chainID, have.ToProto()))


+ 4
- 3
privval/signer_dialer_endpoint.go View File

@ -59,6 +59,7 @@ func NewSignerDialerEndpoint(
retryWait: defaultRetryWaitMilliseconds * time.Millisecond, retryWait: defaultRetryWaitMilliseconds * time.Millisecond,
maxConnRetries: defaultMaxDialRetries, maxConnRetries: defaultMaxDialRetries,
} }
sd.signerEndpoint.logger = logger
sd.BaseService = *service.NewBaseService(logger, "SignerDialerEndpoint", sd) sd.BaseService = *service.NewBaseService(logger, "SignerDialerEndpoint", sd)
sd.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second sd.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second
@ -84,17 +85,17 @@ func (sd *SignerDialerEndpoint) ensureConnection() error {
if err != nil { if err != nil {
retries++ retries++
sd.Logger.Debug("SignerDialer: Reconnection failed", "retries", retries, "max", sd.maxConnRetries, "err", err)
sd.logger.Debug("SignerDialer: Reconnection failed", "retries", retries, "max", sd.maxConnRetries, "err", err)
// Wait between retries // Wait between retries
time.Sleep(sd.retryWait) time.Sleep(sd.retryWait)
} else { } else {
sd.SetConnection(conn) sd.SetConnection(conn)
sd.Logger.Debug("SignerDialer: Connection Ready")
sd.logger.Debug("SignerDialer: Connection Ready")
return nil return nil
} }
} }
sd.Logger.Debug("SignerDialer: Max retries exceeded", "retries", retries, "max", sd.maxConnRetries)
sd.logger.Debug("SignerDialer: Max retries exceeded", "retries", retries, "max", sd.maxConnRetries)
return ErrNoConnection return ErrNoConnection
} }

+ 4
- 2
privval/signer_endpoint.go View File

@ -7,6 +7,7 @@ import (
"github.com/tendermint/tendermint/internal/libs/protoio" "github.com/tendermint/tendermint/internal/libs/protoio"
tmsync "github.com/tendermint/tendermint/internal/libs/sync" tmsync "github.com/tendermint/tendermint/internal/libs/sync"
"github.com/tendermint/tendermint/libs/log"
"github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/libs/service"
privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval" privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval"
) )
@ -17,6 +18,7 @@ const (
type signerEndpoint struct { type signerEndpoint struct {
service.BaseService service.BaseService
logger log.Logger
connMtx tmsync.Mutex connMtx tmsync.Mutex
conn net.Conn conn net.Conn
@ -104,7 +106,7 @@ func (se *signerEndpoint) ReadMessage() (msg privvalproto.Message, err error) {
err = fmt.Errorf("empty error: %w", ErrReadTimeout) err = fmt.Errorf("empty error: %w", ErrReadTimeout)
} }
se.Logger.Debug("Dropping [read]", "obj", se)
se.logger.Debug("Dropping [read]", "obj", se)
se.dropConnection() se.dropConnection()
} }
@ -149,7 +151,7 @@ func (se *signerEndpoint) isConnected() bool {
func (se *signerEndpoint) dropConnection() { func (se *signerEndpoint) dropConnection() {
if se.conn != nil { if se.conn != nil {
if err := se.conn.Close(); err != nil { if err := se.conn.Close(); err != nil {
se.Logger.Error("signerEndpoint::dropConnection", "err", err)
se.logger.Error("signerEndpoint::dropConnection", "err", err)
} }
se.conn = nil se.conn = nil
} }


+ 6
- 5
privval/signer_listener_endpoint.go View File

@ -53,6 +53,7 @@ func NewSignerListenerEndpoint(
timeoutAccept: defaultTimeoutAcceptSeconds * time.Second, timeoutAccept: defaultTimeoutAcceptSeconds * time.Second,
} }
sl.signerEndpoint.logger = logger
sl.BaseService = *service.NewBaseService(logger, "SignerListenerEndpoint", sl) sl.BaseService = *service.NewBaseService(logger, "SignerListenerEndpoint", sl)
sl.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second sl.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second
@ -89,7 +90,7 @@ func (sl *SignerListenerEndpoint) OnStop() {
// Stop listening // Stop listening
if sl.listener != nil { if sl.listener != nil {
if err := sl.listener.Close(); err != nil { if err := sl.listener.Close(); err != nil {
sl.Logger.Error("Closing Listener", "err", err)
sl.logger.Error("Closing Listener", "err", err)
sl.listener = nil sl.listener = nil
} }
} }
@ -141,7 +142,7 @@ func (sl *SignerListenerEndpoint) ensureConnection(maxWait time.Duration) error
} }
// block until connected or timeout // block until connected or timeout
sl.Logger.Info("SignerListener: Blocking for connection")
sl.logger.Info("SignerListener: Blocking for connection")
sl.triggerConnect() sl.triggerConnect()
return sl.WaitConnection(sl.connectionAvailableCh, maxWait) return sl.WaitConnection(sl.connectionAvailableCh, maxWait)
} }
@ -152,7 +153,7 @@ func (sl *SignerListenerEndpoint) acceptNewConnection() (net.Conn, error) {
} }
// wait for a new conn // wait for a new conn
sl.Logger.Info("SignerListener: Listening for new connection")
sl.logger.Info("SignerListener: Listening for new connection")
conn, err := sl.listener.Accept() conn, err := sl.listener.Accept()
if err != nil { if err != nil {
return nil, err return nil, err
@ -180,7 +181,7 @@ func (sl *SignerListenerEndpoint) serviceLoop(ctx context.Context) {
{ {
conn, err := sl.acceptNewConnection() conn, err := sl.acceptNewConnection()
if err == nil { if err == nil {
sl.Logger.Info("SignerListener: Connected")
sl.logger.Info("SignerListener: Connected")
// We have a good connection, wait for someone that needs one otherwise cancellation // We have a good connection, wait for someone that needs one otherwise cancellation
select { select {
@ -208,7 +209,7 @@ func (sl *SignerListenerEndpoint) pingLoop(ctx context.Context) {
{ {
_, err := sl.SendRequest(mustWrapMsg(&privvalproto.PingRequest{})) _, err := sl.SendRequest(mustWrapMsg(&privvalproto.PingRequest{}))
if err != nil { if err != nil {
sl.Logger.Error("SignerListener: Ping timeout")
sl.logger.Error("SignerListener: Ping timeout")
sl.triggerReconnect() sl.triggerReconnect()
} }
} }


+ 5
- 5
privval/signer_server.go View File

@ -36,7 +36,7 @@ func NewSignerServer(endpoint *SignerDialerEndpoint, chainID string, privVal typ
validationRequestHandler: DefaultValidationRequestHandler, validationRequestHandler: DefaultValidationRequestHandler,
} }
ss.BaseService = *service.NewBaseService(endpoint.Logger, "SignerServer", ss)
ss.BaseService = *service.NewBaseService(endpoint.logger, "SignerServer", ss)
return ss return ss
} }
@ -49,7 +49,7 @@ func (ss *SignerServer) OnStart(ctx context.Context) error {
// OnStop implements service.Service. // OnStop implements service.Service.
func (ss *SignerServer) OnStop() { func (ss *SignerServer) OnStop() {
ss.endpoint.Logger.Debug("SignerServer: OnStop calling Close")
ss.endpoint.logger.Debug("SignerServer: OnStop calling Close")
_ = ss.endpoint.Close() _ = ss.endpoint.Close()
} }
@ -68,7 +68,7 @@ func (ss *SignerServer) servicePendingRequest() {
req, err := ss.endpoint.ReadMessage() req, err := ss.endpoint.ReadMessage()
if err != nil { if err != nil {
if err != io.EOF { if err != io.EOF {
ss.Logger.Error("SignerServer: HandleMessage", "err", err)
ss.endpoint.logger.Error("SignerServer: HandleMessage", "err", err)
} }
return return
} }
@ -81,13 +81,13 @@ func (ss *SignerServer) servicePendingRequest() {
res, err = ss.validationRequestHandler(context.TODO(), ss.privVal, req, ss.chainID) // todo res, err = ss.validationRequestHandler(context.TODO(), ss.privVal, req, ss.chainID) // todo
if err != nil { if err != nil {
// only log the error; we'll reply with an error in res // only log the error; we'll reply with an error in res
ss.Logger.Error("SignerServer: handleMessage", "err", err)
ss.endpoint.logger.Error("SignerServer: handleMessage", "err", err)
} }
} }
err = ss.endpoint.WriteMessage(res) err = ss.endpoint.WriteMessage(res)
if err != nil { if err != nil {
ss.Logger.Error("SignerServer: writeMessage", "err", err)
ss.endpoint.logger.Error("SignerServer: writeMessage", "err", err)
} }
} }


Loading…
Cancel
Save