From a62ac2704750447b35bc465d4203cdf22c828d85 Mon Sep 17 00:00:00 2001 From: Sam Kleinman Date: Mon, 6 Dec 2021 10:16:42 -0500 Subject: [PATCH] service: remove exported logger from base implemenation (#7381) --- abci/client/grpc_client.go | 15 ++- abci/client/socket_client.go | 19 +-- abci/server/grpc_server.go | 6 +- abci/server/socket_server.go | 24 ++-- internal/blocksync/pool.go | 26 ++-- internal/blocksync/reactor.go | 36 +++--- internal/consensus/byzantine_test.go | 24 ++-- internal/consensus/invalid_test.go | 4 +- internal/consensus/mempool_test.go | 2 +- internal/consensus/reactor.go | 72 ++++++----- internal/consensus/reactor_test.go | 2 +- internal/consensus/replay.go | 18 +-- internal/consensus/replay_file.go | 12 +- internal/consensus/state.go | 150 +++++++++++----------- internal/consensus/ticker.go | 12 +- internal/consensus/wal.go | 20 +-- internal/eventbus/event_bus.go | 5 +- internal/evidence/reactor.go | 20 +-- internal/libs/autofile/cmd/logjack.go | 3 +- internal/libs/autofile/group.go | 19 +-- internal/libs/autofile/group_test.go | 31 +++-- internal/mempool/reactor.go | 22 ++-- internal/p2p/conn/connection.go | 60 ++++----- internal/p2p/pex/reactor.go | 22 ++-- internal/p2p/router.go | 6 +- internal/p2p/transport_mconn.go | 1 - internal/proxy/multi_app_conn.go | 14 +- internal/state/indexer/indexer_service.go | 14 +- internal/statesync/reactor.go | 78 +++++------ libs/pubsub/example_test.go | 4 +- libs/pubsub/pubsub.go | 15 ++- libs/pubsub/pubsub_test.go | 53 +++++--- libs/service/service.go | 20 +-- node/node.go | 47 +++---- privval/signer_client.go | 10 +- privval/signer_client_test.go | 4 +- privval/signer_dialer_endpoint.go | 7 +- privval/signer_endpoint.go | 6 +- privval/signer_listener_endpoint.go | 11 +- privval/signer_server.go | 10 +- 40 files changed, 498 insertions(+), 426 deletions(-) diff --git a/abci/client/grpc_client.go b/abci/client/grpc_client.go index 0a4bdab34..3f5da63f7 100644 --- a/abci/client/grpc_client.go +++ b/abci/client/grpc_client.go @@ -19,6 +19,8 @@ import ( // A gRPC client. type grpcClient struct { service.BaseService + logger log.Logger + mustConnect bool client types.ABCIApplicationClient @@ -45,6 +47,7 @@ var _ Client = (*grpcClient)(nil) // hopefully not :D func NewGRPCClient(logger log.Logger, addr string, mustConnect bool) Client { cli := &grpcClient{ + logger: logger, addr: addr, mustConnect: mustConnect, // 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 { callCb(reqres) } else { - cli.Logger.Error("Received nil reqres") + cli.logger.Error("Received nil reqres") } case <-ctx.Done(): return @@ -108,12 +111,12 @@ RETRY_LOOP: if cli.mustConnect { return err } - cli.Logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err) + cli.logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err) time.Sleep(time.Second * dialRetryIntervalSeconds) 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) cli.conn = conn @@ -123,7 +126,7 @@ RETRY_LOOP: if err == nil { break ENSURE_CONNECTED } - cli.Logger.Error("Echo failed", "err", err) + cli.logger.Error("Echo failed", "err", err) time.Sleep(time.Second * echoRetryIntervalSeconds) } @@ -150,9 +153,9 @@ func (cli *grpcClient) StopForError(err error) { } 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 { - cli.Logger.Error("Error stopping abci.grpcClient", "err", err) + cli.logger.Error("Error stopping abci.grpcClient", "err", err) } } diff --git a/abci/client/socket_client.go b/abci/client/socket_client.go index 9173475c6..562124e6c 100644 --- a/abci/client/socket_client.go +++ b/abci/client/socket_client.go @@ -33,6 +33,7 @@ type reqResWithContext struct { // general is not meant to be interfaced with concurrent callers. type socketClient struct { service.BaseService + logger log.Logger addr string mustConnect bool @@ -53,12 +54,12 @@ var _ Client = (*socketClient)(nil) // if it fails to connect. func NewSocketClient(logger log.Logger, addr string, mustConnect bool) Client { cli := &socketClient{ + logger: logger, reqQueue: make(chan *reqResWithContext, reqQueueSize), mustConnect: mustConnect, - - addr: addr, - reqSent: list.New(), - resCb: nil, + addr: addr, + reqSent: list.New(), + resCb: nil, } cli.BaseService = *service.NewBaseService(logger, "socketClient", cli) return cli @@ -78,7 +79,7 @@ func (cli *socketClient) OnStart(ctx context.Context) error { if cli.mustConnect { return err } - cli.Logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...", + cli.logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...", cli.addr, dialRetryIntervalSeconds), "err", err) time.Sleep(time.Second * dialRetryIntervalSeconds) continue @@ -132,7 +133,7 @@ func (cli *socketClient) sendRequestsRoutine(ctx context.Context, conn io.Writer } 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 } cli.willSendReq(reqres.R) @@ -162,7 +163,7 @@ func (cli *socketClient) recvResponseRoutine(ctx context.Context, conn io.Reader 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) { case *types.Response_Exception: // app responded with error @@ -589,8 +590,8 @@ func (cli *socketClient) stopForError(err error) { cli.err = err 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 { - cli.Logger.Error("Error stopping abci.socketClient", "err", err) + cli.logger.Error("Error stopping abci.socketClient", "err", err) } } diff --git a/abci/server/grpc_server.go b/abci/server/grpc_server.go index b4e314182..479df52a9 100644 --- a/abci/server/grpc_server.go +++ b/abci/server/grpc_server.go @@ -14,6 +14,7 @@ import ( type GRPCServer struct { service.BaseService + logger log.Logger proto string addr string @@ -27,6 +28,7 @@ type GRPCServer struct { func NewGRPCServer(logger log.Logger, protoAddr string, app types.ABCIApplicationServer) service.Service { proto, addr := tmnet.ProtocolAndAddress(protoAddr) s := &GRPCServer{ + logger: logger, proto: proto, addr: addr, listener: nil, @@ -48,7 +50,7 @@ func (s *GRPCServer) OnStart(ctx context.Context) error { s.server = grpc.NewServer() 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() { <-ctx.Done() @@ -56,7 +58,7 @@ func (s *GRPCServer) OnStart(ctx context.Context) error { }() 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 diff --git a/abci/server/socket_server.go b/abci/server/socket_server.go index 29d912671..dd71a5df8 100644 --- a/abci/server/socket_server.go +++ b/abci/server/socket_server.go @@ -10,7 +10,7 @@ import ( "github.com/tendermint/tendermint/abci/types" 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" "github.com/tendermint/tendermint/libs/service" ) @@ -19,6 +19,7 @@ import ( type SocketServer struct { service.BaseService + logger log.Logger proto string addr string @@ -32,9 +33,10 @@ type SocketServer struct { 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) s := &SocketServer{ + logger: logger, proto: proto, addr: addr, listener: nil, @@ -59,7 +61,7 @@ func (s *SocketServer) OnStart(ctx context.Context) error { func (s *SocketServer) OnStop() { 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() @@ -68,7 +70,7 @@ func (s *SocketServer) OnStop() { for id, conn := range s.conns { delete(s.conns, id) 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 - s.Logger.Info("Waiting for new connection...") + s.logger.Info("Waiting for new connection...") conn, err := s.listener.Accept() if err != nil { if !s.IsRunning() { 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 } - s.Logger.Info("Accepted a new connection") + s.logger.Info("Accepted a new connection") connID := s.addConn(conn) @@ -137,7 +139,7 @@ func (s *SocketServer) waitForClose(ctx context.Context, closeConn chan error, c defer func() { // Close the connection 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: switch { case err == io.EOF: - s.Logger.Error("Connection was closed by client") + s.logger.Error("Connection was closed by client") case err != nil: - s.Logger.Error("Connection error", "err", err) + s.logger.Error("Connection error", "err", err) default: // never happens - s.Logger.Error("Connection was closed") + s.logger.Error("Connection was closed") } } } diff --git a/internal/blocksync/pool.go b/internal/blocksync/pool.go index a83a119a6..4db0fd900 100644 --- a/internal/blocksync/pool.go +++ b/internal/blocksync/pool.go @@ -69,6 +69,8 @@ type BlockRequest struct { // BlockPool keeps track of the block sync peers, block requests and block responses. type BlockPool struct { service.BaseService + logger log.Logger + lastAdvance time.Time mtx tmsync.RWMutex @@ -101,8 +103,8 @@ func NewBlockPool( ) *BlockPool { bp := &BlockPool{ - peers: make(map[types.NodeID]*bpPeer), - + logger: logger, + peers: make(map[types.NodeID]*bpPeer), requesters: make(map[int64]*bpRequester), height: start, startHeight: start, @@ -171,7 +173,7 @@ func (pool *BlockPool) removeTimedoutPeers() { if curRate != 0 && curRate < minRecvRate { err := errors.New("peer is not sending us data fast enough") pool.sendError(err, peer.id) - pool.Logger.Error("SendTimeout", "peer", peer.id, + pool.logger.Error("SendTimeout", "peer", peer.id, "reason", err, "curRate", fmt.Sprintf("%d KB/s", curRate/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 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) pool.height++ @@ -281,7 +283,7 @@ func (pool *BlockPool) AddBlock(peerID types.NodeID, block *types.Block, blockSi requester := pool.requesters[block.Height] 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) diff := pool.height - block.Height if diff < 0 { @@ -301,7 +303,7 @@ func (pool *BlockPool) AddBlock(peerID types.NodeID, block *types.Block, blockSi } } else { 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) } } @@ -332,7 +334,7 @@ func (pool *BlockPool) SetPeerRange(peerID types.NodeID, base int64, height int6 peer.height = height } else { peer = newBPPeer(pool, peerID, base, height) - peer.setLogger(pool.Logger.With("peer", peerID)) + peer.logger = pool.logger.With("peer", peerID) pool.peers[peerID] = peer } @@ -423,7 +425,7 @@ func (pool *BlockPool) makeNextRequester(ctx context.Context) { err := request.Start(ctx) 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 } -func (peer *bpPeer) setLogger(l log.Logger) { - peer.logger = l -} - func (peer *bpPeer) resetMonitor() { peer.recvMonitor = flowrate.New(time.Second, time.Second*40) initialValue := float64(minRecvRate) * math.E @@ -556,6 +554,7 @@ func (peer *bpPeer) onTimeout() { type bpRequester struct { service.BaseService + logger log.Logger pool *BlockPool height int64 gotBlockCh chan struct{} @@ -568,6 +567,7 @@ type bpRequester struct { func newBPRequester(pool *BlockPool, height int64) *bpRequester { bpr := &bpRequester{ + logger: pool.logger, pool: pool, height: height, gotBlockCh: make(chan struct{}, 1), @@ -677,7 +677,7 @@ OUTER_LOOP: return case <-bpr.pool.exitedCh: if err := bpr.Stop(); err != nil { - bpr.Logger.Error("Error stopped requester", "err", err) + bpr.logger.Error("Error stopped requester", "err", err) } return case peerID := <-bpr.redoCh: diff --git a/internal/blocksync/reactor.go b/internal/blocksync/reactor.go index 994c01991..f6ea48839 100644 --- a/internal/blocksync/reactor.go +++ b/internal/blocksync/reactor.go @@ -65,6 +65,7 @@ func (e peerError) Error() string { // Reactor handles long-term catchup syncing. type Reactor struct { service.BaseService + logger log.Logger // immutable initialState sm.State @@ -125,6 +126,7 @@ func NewReactor( errorsCh := make(chan peerError, maxPeerErrBuffer) // NOTE: The capacity should be larger than the peer count. r := &Reactor{ + logger: logger, initialState: state, blockExec: blockExec, store: store, @@ -175,7 +177,7 @@ func (r *Reactor) OnStart(ctx context.Context) error { func (r *Reactor) OnStop() { if r.blockSync.IsSet() { 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 { blockProto, err := block.ToProto() 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 } @@ -208,7 +210,7 @@ func (r *Reactor) respondToPeer(msg *bcproto.BlockRequest, peerID types.NodeID) 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{ To: peerID, 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 // for this channel. This should never be called outside of handleMessage. 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) { case *bcproto.BlockRequest: @@ -263,7 +265,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err defer func() { if e := recover(); e != nil { err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "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 { case BlockSyncChannel: @@ -296,7 +298,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) { return case envelope := <-r.blockSyncCh.In: 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{ NodeID: envelope.From, Err: err, @@ -307,7 +309,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) { r.blockSyncCh.Out <- envelope case <-r.closeCh: - r.Logger.Debug("stopped listening on block sync channel; closing...") + r.logger.Debug("stopped listening on block sync channel; closing...") return } @@ -316,7 +318,7 @@ func (r *Reactor) processBlockSyncCh(ctx context.Context) { // processPeerUpdate processes a 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. if len(peerUpdate.NodeID) == 0 { @@ -353,7 +355,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { r.processPeerUpdate(peerUpdate) case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -459,7 +461,7 @@ FOR_LOOP: lastAdvance = r.pool.LastAdvance() ) - r.Logger.Debug( + r.logger.Debug( "consensus ticker", "num_pending", numPending, "total", lenRequesters, @@ -468,13 +470,13 @@ FOR_LOOP: switch { 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: - r.Logger.Error("no progress since last advance", "last_advance", lastAdvance) + r.logger.Error("no progress since last advance", "last_advance", lastAdvance) default: - r.Logger.Info( + r.logger.Info( "not caught up yet", "height", height, "max_peer_height", r.pool.MaxPeerHeight(), @@ -484,7 +486,7 @@ FOR_LOOP: } 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() @@ -535,7 +537,7 @@ FOR_LOOP: err := state.Validators.VerifyCommitLight(chainID, firstID, first.Height, second.LastCommit) if err != nil { err = fmt.Errorf("invalid last commit: %w", err) - r.Logger.Error( + r.logger.Error( err.Error(), "last_commit", second.LastCommit, "block_id", firstID, @@ -581,7 +583,7 @@ FOR_LOOP: if blocksSynced%100 == 0 { lastRate = 0.9*lastRate + 0.1*(100/time.Since(lastHundred).Seconds()) - r.Logger.Info( + r.logger.Info( "block sync rate", "height", r.pool.height, "max_peer_height", r.pool.MaxPeerHeight(), diff --git a/internal/consensus/byzantine_test.go b/internal/consensus/byzantine_test.go index b53f3181d..9526f4ae1 100644 --- a/internal/consensus/byzantine_test.go +++ b/internal/consensus/byzantine_test.go @@ -140,7 +140,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { i := 0 for _, ps := range bzReactor.peers { 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{ To: ps.peerID, Message: &tmcons.Vote{ @@ -148,7 +148,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { }, } } 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{ To: ps.peerID, Message: &tmcons.Vote{ @@ -160,7 +160,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { i++ } } else { - bzNodeState.Logger.Info("behaving normally") + bzNodeState.logger.Info("behaving normally") bzNodeState.defaultDoPrevote(ctx, height, round) } } @@ -172,7 +172,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { lazyNodeState := states[1] 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) var commit *types.Commit @@ -185,7 +185,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { // Make the commit from LastCommit commit = lazyNodeState.LastCommit.MakeCommit() 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 } @@ -195,7 +195,7 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { if lazyNodeState.privValidatorPubKey == nil { // If this node is a validator & proposer in the current round, it will // miss the opportunity to create a block. - lazyNodeState.Logger.Error(fmt.Sprintf("enterPropose: %v", errPubKeyIsNotSet)) + lazyNodeState.logger.Error(fmt.Sprintf("enterPropose: %v", errPubKeyIsNotSet)) return } 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, // and the privValidator will refuse to sign anything. if err := lazyNodeState.wal.FlushAndSync(); err != nil { - lazyNodeState.Logger.Error("Error flushing to disk") + lazyNodeState.logger.Error("Error flushing to disk") } // Make proposal @@ -225,10 +225,10 @@ func TestByzantinePrevoteEquivocation(t *testing.T) { 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 { - 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 // ticker := NewTimeoutTicker() - // ticker.SetLogger(states[0].Logger) + // ticker.SetLogger(states[0].logger) // states[0].SetTimeoutTicker(ticker) // p2pLogger := logger.With("module", "p2p") @@ -529,7 +529,7 @@ func TestByzantineConflictingProposalsWithPartition(t *testing.T) { // } // // Create peerState for peer -// peerState := NewPeerState(peer).SetLogger(br.reactor.Logger) +// peerState := NewPeerState(peer).SetLogger(br.reactor.logger) // peer.Set(types.PeerStateKey, peerState) // // Send our state to peer. diff --git a/internal/consensus/invalid_test.go b/internal/consensus/invalid_test.go index 053f92264..0c0528d6f 100644 --- a/internal/consensus/invalid_test.go +++ b/internal/consensus/invalid_test.go @@ -29,7 +29,7 @@ func TestReactorInvalidPrecommit(t *testing.T) { t.Cleanup(cleanup) for i := 0; i < 4; i++ { - ticker := NewTimeoutTicker(states[i].Logger) + ticker := NewTimeoutTicker(states[i].logger) states[i].SetTimeoutTicker(ticker) } @@ -123,7 +123,7 @@ func invalidDoPrevoteFunc( cs.mtx.Unlock() 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{ To: ps.peerID, diff --git a/internal/consensus/mempool_test.go b/internal/consensus/mempool_test.go index e24cb1160..06cecc6bb 100644 --- a/internal/consensus/mempool_test.go +++ b/internal/consensus/mempool_test.go @@ -96,7 +96,7 @@ func TestMempoolProgressInHigherRound(t *testing.T) { if cs.Height == 2 && cs.Round == 0 { // dont set the proposal in round 0 so we timeout and // 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 cs.defaultSetProposal(proposal) diff --git a/internal/consensus/reactor.go b/internal/consensus/reactor.go index 5f9a7ff73..803834d96 100644 --- a/internal/consensus/reactor.go +++ b/internal/consensus/reactor.go @@ -111,6 +111,7 @@ type ConsSyncReactor interface { // Reactor defines a reactor for the consensus service. type Reactor struct { service.BaseService + logger log.Logger state *State eventBus *eventbus.EventBus @@ -151,6 +152,7 @@ func NewReactor( ) *Reactor { r := &Reactor{ + logger: logger, state: cs, waitSync: waitSync, 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 // OnStop to ensure the outbound p2p Channels are closed. 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 // @@ -210,7 +212,7 @@ func (r *Reactor) OnStop() { if err := r.state.Stop(); err != nil { 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 // the state, turns off block-sync, and starts the consensus state-machine. 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 if state.LastBlockHeight > 0 { @@ -295,7 +297,7 @@ conR: d := types.EventDataBlockSyncStatus{Complete: true, Height: state.LastBlockHeight} 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 { - 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( @@ -394,7 +396,7 @@ func (r *Reactor) subscribeToBroadcastEvents() { }, ) 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( @@ -405,7 +407,7 @@ func (r *Reactor) subscribeToBroadcastEvents() { }, ) 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) { - 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 { // 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) { - logger := r.Logger.With("peer", ps.peerID) + logger := r.logger.With("peer", ps.peerID) defer ps.broadcastWG.Done() @@ -659,7 +661,7 @@ OUTER_LOOP: // there is a vote to send and false otherwise. func (r *Reactor) pickSendVote(ctx context.Context, ps *PeerState, votes types.VoteSetReader) bool { 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 { case <-ctx.Done(): case r.voteCh.Out <- p2p.Envelope{ @@ -683,7 +685,7 @@ func (r *Reactor) gossipVotesForHeight( prs *cstypes.PeerRoundState, ps *PeerState, ) 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 prs.Step == cstypes.RoundStepNewHeight { @@ -741,7 +743,7 @@ func (r *Reactor) gossipVotesForHeight( } 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() @@ -982,7 +984,7 @@ OUTER_LOOP: // 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. 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() defer r.mtx.Unlock() @@ -1004,7 +1006,7 @@ func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpda ps, ok = r.peers[peerUpdate.NodeID] if !ok { - ps = NewPeerState(r.Logger, peerUpdate.NodeID) + ps = NewPeerState(r.logger, peerUpdate.NodeID) 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 { ps, ok := r.GetPeerState(envelope.From) 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 } @@ -1068,7 +1070,7 @@ func (r *Reactor) handleStateMessage(envelope p2p.Envelope, msgI Message) error r.state.mtx.RUnlock() 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 } @@ -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 // removed. 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) if !ok || ps == nil { - r.Logger.Debug("failed to find peer state") + r.logger.Debug("failed to find peer state") 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 // removed. 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) if !ok || ps == nil { - r.Logger.Debug("failed to find peer state") + r.logger.Debug("failed to find peer state") 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 // after the peer is removed. 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) if !ok || ps == nil { - r.Logger.Debug("failed to find peer state") + r.logger.Debug("failed to find peer state") return nil } @@ -1281,7 +1283,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err defer func() { if e := recover(); e != nil { err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "stack", string(debug.Stack()), @@ -1304,7 +1306,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (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 { case StateChannel: @@ -1338,7 +1340,7 @@ func (r *Reactor) processStateCh(ctx context.Context) { return case envelope := <-r.stateCh.In: 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{ NodeID: envelope.From, Err: err, @@ -1346,7 +1348,7 @@ func (r *Reactor) processStateCh(ctx context.Context) { } case <-r.stateCloseCh: - r.Logger.Debug("stopped listening on StateChannel; closing...") + r.logger.Debug("stopped listening on StateChannel; closing...") return } } @@ -1364,7 +1366,7 @@ func (r *Reactor) processDataCh(ctx context.Context) { return case envelope := <-r.dataCh.In: 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{ NodeID: envelope.From, Err: err, @@ -1372,7 +1374,7 @@ func (r *Reactor) processDataCh(ctx context.Context) { } case <-r.closeCh: - r.Logger.Debug("stopped listening on DataChannel; closing...") + r.logger.Debug("stopped listening on DataChannel; closing...") return } } @@ -1390,7 +1392,7 @@ func (r *Reactor) processVoteCh(ctx context.Context) { return case envelope := <-r.voteCh.In: 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{ NodeID: envelope.From, Err: err, @@ -1398,7 +1400,7 @@ func (r *Reactor) processVoteCh(ctx context.Context) { } case <-r.closeCh: - r.Logger.Debug("stopped listening on VoteChannel; closing...") + r.logger.Debug("stopped listening on VoteChannel; closing...") return } } @@ -1416,7 +1418,7 @@ func (r *Reactor) processVoteSetBitsCh(ctx context.Context) { return case envelope := <-r.voteSetBitsCh.In: 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{ NodeID: envelope.From, Err: err, @@ -1424,7 +1426,7 @@ func (r *Reactor) processVoteSetBitsCh(ctx context.Context) { } case <-r.closeCh: - r.Logger.Debug("stopped listening on VoteSetBitsChannel; closing...") + r.logger.Debug("stopped listening on VoteSetBitsChannel; closing...") return } } @@ -1444,7 +1446,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { r.processPeerUpdate(ctx, peerUpdate) case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -1453,7 +1455,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { func (r *Reactor) peerStatsRoutine(ctx context.Context) { for { if !r.IsRunning() { - r.Logger.Info("stopping peerStatsRoutine") + r.logger.Info("stopping peerStatsRoutine") return } @@ -1461,7 +1463,7 @@ func (r *Reactor) peerStatsRoutine(ctx context.Context) { case msg := <-r.state.statsMsgQueue: ps, ok := r.GetPeerState(msg.PeerID) 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 } diff --git a/internal/consensus/reactor_test.go b/internal/consensus/reactor_test.go index f0bb8b53c..1788c0d20 100644 --- a/internal/consensus/reactor_test.go +++ b/internal/consensus/reactor_test.go @@ -89,7 +89,7 @@ func setup( state := states[i] reactor := NewReactor( - state.Logger.With("node", nodeID), + state.logger.With("node", nodeID), state, rts.stateChannels[nodeID], rts.dataChannels[nodeID], diff --git a/internal/consensus/replay.go b/internal/consensus/replay.go index b797eabae..3ee88337d 100644 --- a/internal/consensus/replay.go +++ b/internal/consensus/replay.go @@ -47,7 +47,7 @@ func (cs *State) readReplayMessage(ctx context.Context, msg *TimedWALMessage, ne // for logging switch m := msg.Msg.(type) { 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 if newStepSub != nil { 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) { case *ProposalMessage: 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) 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: 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) } cs.handleMsg(ctx, m) 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) default: 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}) 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 { return err } @@ -139,7 +139,7 @@ func (cs *State) catchupReplay(ctx context.Context, csHeight int64) error { } 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 dec := WALDecoder{gr} @@ -151,7 +151,7 @@ LOOP: case err == io.EOF: break LOOP 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 case err != nil: return err @@ -164,7 +164,7 @@ LOOP: return err } } - cs.Logger.Info("Replay: Done") + cs.logger.Info("Replay: Done") return nil } diff --git a/internal/consensus/replay_file.go b/internal/consensus/replay_file.go index d54c77fe3..2c848a9f2 100644 --- a/internal/consensus/replay_file.go +++ b/internal/consensus/replay_file.go @@ -74,7 +74,7 @@ func (cs *State) ReplayFile(ctx context.Context, file string, console bool) erro defer func() { args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep} 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() - 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) newCS.SetEventBus(pb.cs.eventBus) newCS.startForReplay() @@ -182,7 +182,7 @@ func (pb *playback) replayReset(ctx context.Context, count int, newStepSub event } 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 @@ -238,13 +238,13 @@ func (pb *playback) replayConsoleLoop() (int, error) { defer func() { args := tmpubsub.UnsubscribeArgs{Subscriber: subscriber, Query: types.EventQueryNewRoundStep} 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 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 { i, err := strconv.Atoi(tokens[1]) @@ -253,7 +253,7 @@ func (pb *playback) replayConsoleLoop() (int, error) { } else if i > 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 { - pb.cs.Logger.Error("Replay reset error", "err", err) + pb.cs.logger.Error("Replay reset error", "err", err) } } diff --git a/internal/consensus/state.go b/internal/consensus/state.go index 2c358a213..02ab2ae54 100644 --- a/internal/consensus/state.go +++ b/internal/consensus/state.go @@ -79,6 +79,7 @@ type evidencePool interface { // The internal state machine receives input from peers, the internal validator, and from a timer. type State struct { service.BaseService + logger log.Logger // config details config *config.ConsensusConfig @@ -164,6 +165,7 @@ func NewState( options ...StateOption, ) *State { cs := &State{ + logger: logger, config: cfg, blockExec: blockExec, blockStore: blockStore, @@ -291,13 +293,13 @@ func (cs *State) SetPrivValidator(priv types.PrivValidator) { case *types.ErroringMockPV: cs.privValidatorType = types.ErrorMockSignerClient default: - cs.Logger.Error("unsupported priv validator type", "err", + cs.logger.Error("unsupported priv validator type", "err", fmt.Errorf("error privValidatorType %s", t)) } } 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 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 case repairAttempted: 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 if err := cs.wal.Stop(); err != nil { @@ -375,15 +377,15 @@ func (cs *State) OnStart(ctx context.Context) error { 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!) 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 } - cs.Logger.Info("successful WAL repair") + cs.logger.Info("successful WAL repair") // reload WAL file 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) { err := cs.timeoutTicker.Start(ctx) if err != nil { - cs.Logger.Error("failed to start timeout ticker", "err", err) + cs.logger.Error("failed to start timeout ticker", "err", err) return } @@ -438,7 +440,7 @@ func (cs *State) startRoutines(ctx context.Context, maxSteps int) { func (cs *State) loadWalFile(ctx context.Context) error { wal, err := cs.OpenWAL(ctx, cs.config.WalFile()) 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 } @@ -453,7 +455,7 @@ func (cs *State) OnStop() { select { case <-cs.onStopCh: 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 err := cs.evsw.Stop(); err != nil { 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 err := cs.timeoutTicker.Stop(); err != nil { 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 // deterministic accountability. 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 { - 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 } 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 } @@ -583,7 +585,7 @@ func (cs *State) updateRoundStep(round int32, step cstypes.RoundStepType) { // enterNewRound(height, 0) at cs.StartTime. 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()) 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. // TODO: use CList here for strict determinism and // 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() { select { 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) // depend on having an up-to-date peer state! if state.LastBlockHeight <= cs.state.LastBlockHeight { - cs.Logger.Debug( + cs.logger.Debug( "ignoring updateToState()", "new_height", 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) { rs := cs.RoundStateEvent() 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++ @@ -756,7 +758,7 @@ func (cs *State) newStep(ctx context.Context) { // newStep is called by updateToState in NewState before the eventBus is set! if cs.eventBus != 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) @@ -780,7 +782,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) { // close wal now that we're done writing to it if err := cs.wal.Stop(); err != nil { 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() { 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 // // 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 { if maxSteps > 0 { 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 return } @@ -821,7 +823,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) { case mi = <-cs.peerMsgQueue: 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 @@ -850,7 +852,7 @@ func (cs *State) receiveRoutine(ctx context.Context, maxSteps int) { case ti := <-cs.timeoutTicker.Chan(): // tockChan: 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 @@ -896,7 +898,7 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) { } if err != nil && msg.Round != cs.Round { - cs.Logger.Debug( + cs.logger.Debug( "received block part from wrong round", "height", cs.Height, "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(). default: - cs.Logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg)) + cs.logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg)) return } if err != nil { - cs.Logger.Error( + cs.logger.Error( "failed to process message", "height", cs.Height, "round", cs.Round, @@ -954,11 +956,11 @@ func (cs *State) handleTimeout( ti timeoutInfo, 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 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 } @@ -977,21 +979,21 @@ func (cs *State) handleTimeout( case cstypes.RoundStepPropose: 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) case cstypes.RoundStepPrevoteWait: 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) case cstypes.RoundStepPrecommitWait: 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) @@ -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) // NOTE: cs.StartTime was already set for height. 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) { logger.Debug( @@ -1082,7 +1084,7 @@ func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) { cs.TriggeredTimeoutPrecommit = false 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)) @@ -1121,7 +1123,7 @@ func (cs *State) needProofBlock(height int64) bool { // after enterNewRound(height,round), after timeout of CreateEmptyBlocksInterval // Enter (!CreateEmptyBlocks) : after enterNewRound(height,round), once txs are in the mempool 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) { 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, // and the privValidator will refuse to sign anything. 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 @@ -1232,9 +1234,9 @@ func (cs *State) defaultDecideProposal(height int64, round int32) { 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 { - 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() 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 } if cs.privValidatorPubKey == nil { // If this node is a validator & proposer in the current round, it will // 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 } @@ -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. // Otherwise vote nil. 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) { 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) { - logger := cs.Logger.With("height", height, "round", round) + logger := cs.logger.With("height", height, "round", round) // If a block is locked, prevote that. 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. 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) { 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, precommit nil otherwise. func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) { - logger := cs.Logger.With("height", height, "round", round) + logger := cs.logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) { 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. 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) { logger.Debug( @@ -1549,7 +1551,7 @@ func (cs *State) enterPrecommitWait(ctx context.Context, height int64, round int // Enter: +2/3 precommits for block func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int32) { - logger := cs.Logger.With("height", height, "commit_round", commitRound) + logger := cs.logger.With("height", height, "commit_round", commitRound) if cs.Height != height || cstypes.RoundStepCommit <= cs.Step { 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. 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 { 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 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 { logger.Debug( @@ -1777,7 +1779,7 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) { address types.Address ) if commitSize != valSetLen { - cs.Logger.Error(fmt.Sprintf("commit size (%d) doesn't match valset length (%d) at height %d\n\n%v\n\n%v", + 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)) return } @@ -1785,7 +1787,7 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) { if cs.privValidator != nil { if cs.privValidatorPubKey == nil { // 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 { address = cs.privValidatorPubKey.Address() } @@ -1884,7 +1886,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal) error { cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader) } - cs.Logger.Info("received proposal", "proposal", proposal) + cs.logger.Info("received proposal", "proposal", proposal) return nil } @@ -1900,7 +1902,7 @@ func (cs *State) addProposalBlockPart( // Blocks might be reused, so round mismatch is OK 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 } @@ -1908,7 +1910,7 @@ func (cs *State) addProposalBlockPart( if cs.ProposalBlockParts == nil { // NOTE: this can happen when we've gone to a higher round and // then receive parts from the previous round - not necessarily a bad peer. - cs.Logger.Debug( + cs.logger.Debug( "received a block part when we are not expecting any", "height", height, "round", round, @@ -1947,10 +1949,10 @@ func (cs *State) addProposalBlockPart( cs.ProposalBlock = block // 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 { - 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. @@ -1958,7 +1960,7 @@ func (cs *State) addProposalBlockPart( blockID, hasTwoThirds := prevotes.TwoThirdsMajority() if hasTwoThirds && !blockID.IsZero() && (cs.ValidRound < cs.Round) { if cs.ProposalBlock.HashesTo(blockID.Hash) { - cs.Logger.Debug( + cs.logger.Debug( "updating valid block to new proposal block", "valid_round", cs.Round, "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()) { - cs.Logger.Error( + cs.logger.Error( "found conflicting vote from ourselves; did you unsafe_reset a validator?", "height", vote.Height, "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 cs.evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB) - cs.Logger.Debug( + cs.logger.Debug( "found and sent conflicting votes to the evidence pool", "vote_a", voteErr.VoteA, "vote_b", voteErr.VoteB, @@ -2026,14 +2028,14 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types. return added, err } 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 { // Either // 1) bad peer 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 // (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 } } @@ -2046,7 +2048,7 @@ func (cs *State) addVote( vote *types.Vote, peerID types.NodeID, ) (added bool, err error) { - cs.Logger.Debug( + cs.logger.Debug( "adding vote", "vote_height", vote.Height, "vote_type", vote.Type, @@ -2059,7 +2061,7 @@ func (cs *State) addVote( if vote.Height+1 == cs.Height && vote.Type == tmproto.PrecommitType { if cs.Step != cstypes.RoundStepNewHeight { // 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 } @@ -2068,7 +2070,7 @@ func (cs *State) addVote( 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 { return added, err } @@ -2088,7 +2090,7 @@ func (cs *State) addVote( // Height mismatch is ignored. // Not necessarily a bad peer, but not favorable behavior. 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 } @@ -2107,7 +2109,7 @@ func (cs *State) addVote( switch vote.Type { case tmproto.PrevoteType: 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 blockID, ok := prevotes.TwoThirdsMajority(); ok { @@ -2122,7 +2124,7 @@ func (cs *State) addVote( (vote.Round <= cs.Round) && !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.LockedBlock = nil @@ -2137,12 +2139,12 @@ func (cs *State) addVote( // 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 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.ValidBlock = cs.ProposalBlock cs.ValidBlockParts = cs.ProposalBlockParts } else { - cs.Logger.Debug( + cs.logger.Debug( "valid block we do not know about; set ProposalBlock=nil", "proposal", cs.ProposalBlock.Hash(), "block_id", blockID.Hash, @@ -2186,7 +2188,7 @@ func (cs *State) addVote( case tmproto.PrecommitType: precommits := cs.Votes.Precommits(vote.Round) - cs.Logger.Debug("added vote to precommit", + cs.logger.Debug("added vote to precommit", "height", vote.Height, "round", vote.Round, "validator", vote.ValidatorAddress.String(), @@ -2305,7 +2307,7 @@ func (cs *State) signAddVote(ctx context.Context, msgType tmproto.SignedMsgType, if cs.privValidatorPubKey == nil { // 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 } @@ -2318,11 +2320,11 @@ func (cs *State) signAddVote(ctx context.Context, msgType tmproto.SignedMsgType, vote, err := cs.signVote(msgType, hash, header) if err == nil { 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 } - 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 } @@ -2372,7 +2374,7 @@ func (cs *State) checkDoubleSigningRisk(height int64) error { if lastCommit != nil { for sigIdx, s := range lastCommit.Signatures { 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 } } diff --git a/internal/consensus/ticker.go b/internal/consensus/ticker.go index 84814f33d..686ca6b7a 100644 --- a/internal/consensus/ticker.go +++ b/internal/consensus/ticker.go @@ -30,6 +30,7 @@ type TimeoutTicker interface { // and fired on the tockChan. type timeoutTicker struct { service.BaseService + logger log.Logger timer *time.Timer tickChan chan timeoutInfo // for scheduling timeouts @@ -39,6 +40,7 @@ type timeoutTicker struct { // NewTimeoutTicker returns a new TimeoutTicker. func NewTimeoutTicker(logger log.Logger) TimeoutTicker { tt := &timeoutTicker{ + logger: logger, timer: time.NewTimer(0), tickChan: make(chan timeoutInfo, tickTockBufferSize), tockChan: make(chan timeoutInfo, tickTockBufferSize), @@ -79,7 +81,7 @@ func (t *timeoutTicker) stopTimer() { select { case <-t.timer.C: 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 // timeouts of 0 on the tickChan will be immediately relayed to the tockChan func (t *timeoutTicker) timeoutRoutine(ctx context.Context) { - t.Logger.Debug("Starting timeout routine") + t.logger.Debug("Starting timeout routine") var ti timeoutInfo for { select { 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 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 ti = newti 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: - 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. // Determinism comes from playback in the receiveRoutine. // We can eliminate it by merging the timeoutRoutine into receiveRoutine diff --git a/internal/consensus/wal.go b/internal/consensus/wal.go index e89cf0992..dd8c220f6 100644 --- a/internal/consensus/wal.go +++ b/internal/consensus/wal.go @@ -76,6 +76,7 @@ type WAL interface { // again. type BaseWAL struct { service.BaseService + logger log.Logger 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) } - group, err := auto.OpenGroup(walFile, groupOptions...) + group, err := auto.OpenGroup(logger, walFile, groupOptions...) if err != nil { return nil, err } wal := &BaseWAL{ + logger: logger, group: group, enc: NewWALEncoder(group), flushInterval: walDefaultFlushInterval, @@ -140,7 +142,7 @@ func (wal *BaseWAL) processFlushTicks(ctx context.Context) { select { case <-wal.flushTicker.C: 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(): return @@ -161,12 +163,12 @@ func (wal *BaseWAL) OnStop() { wal.flushTicker.Stop() if err := wal.FlushAndSync(); err != nil { 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 !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() @@ -192,7 +194,7 @@ func (wal *BaseWAL) Write(msg WALMessage) error { } 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) return err } @@ -213,7 +215,7 @@ func (wal *BaseWAL) WriteSync(msg WALMessage) error { } 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`, "err", err) return err @@ -245,7 +247,7 @@ func (wal *BaseWAL) SearchForEndHeight( // NOTE: starting from the last file in the group because we're usually // searching for the last height. See replay.go 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-- { gr, err = wal.group.NewReader(index) if err != nil { @@ -265,7 +267,7 @@ func (wal *BaseWAL) SearchForEndHeight( break } if options.IgnoreDataCorruptionErrors && IsDataCorruptionError(err) { - wal.Logger.Error("Corrupted entry. Skipping...", "err", err) + wal.logger.Error("Corrupted entry. Skipping...", "err", err) // do nothing continue } else if err != nil { @@ -276,7 +278,7 @@ func (wal *BaseWAL) SearchForEndHeight( if m, ok := msg.Msg.(EndHeightMessage); ok { lastHeightFound = m.Height 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 } } diff --git a/internal/eventbus/event_bus.go b/internal/eventbus/event_bus.go index 0eb44c37b..3272fe8d7 100644 --- a/internal/eventbus/event_bus.go +++ b/internal/eventbus/event_bus.go @@ -29,10 +29,7 @@ type EventBus struct { // NewDefault returns a new event bus with default options. func NewDefault(l log.Logger) *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.BaseService = *service.NewBaseService(logger, "EventBus", b) return b diff --git a/internal/evidence/reactor.go b/internal/evidence/reactor.go index 5b093dc15..b559f0a2c 100644 --- a/internal/evidence/reactor.go +++ b/internal/evidence/reactor.go @@ -45,6 +45,7 @@ func GetChannelDescriptor() *p2p.ChannelDescriptor { // Reactor handles evpool evidence broadcasting amongst peers. type Reactor struct { service.BaseService + logger log.Logger evpool *Pool evidenceCh *p2p.Channel @@ -67,6 +68,7 @@ func NewReactor( evpool *Pool, ) *Reactor { r := &Reactor{ + logger: logger, evpool: evpool, evidenceCh: evidenceCh, peerUpdates: peerUpdates, @@ -120,7 +122,7 @@ func (r *Reactor) OnStop() { // or if the given evidence is invalid. This should never be called outside of // handleMessage. 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) { case *tmproto.EvidenceList: @@ -159,7 +161,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err defer func() { if e := recover(); e != nil { err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "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 { case EvidenceChannel: @@ -189,7 +191,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) { return case envelope := <-r.evidenceCh.In: 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{ NodeID: envelope.From, Err: err, @@ -197,7 +199,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) { } case <-r.closeCh: - r.Logger.Debug("stopped listening on evidence channel; closing...") + r.logger.Debug("stopped listening on evidence channel; closing...") return } } @@ -215,7 +217,7 @@ func (r *Reactor) processEvidenceCh(ctx context.Context) { // // REF: https://github.com/tendermint/tendermint/issues/4727 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() defer r.mtx.Unlock() @@ -268,7 +270,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { case <-ctx.Done(): return case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -296,7 +298,7 @@ func (r *Reactor) broadcastEvidenceLoop(ctx context.Context, peerID types.NodeID r.peerWG.Done() if e := recover(); e != nil { - r.Logger.Error( + r.logger.Error( "recovering from broadcasting evidence loop", "err", e, "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 { case <-time.After(time.Second * broadcastEvidenceIntervalS): diff --git a/internal/libs/autofile/cmd/logjack.go b/internal/libs/autofile/cmd/logjack.go index 72d816fcf..c246871dc 100644 --- a/internal/libs/autofile/cmd/logjack.go +++ b/internal/libs/autofile/cmd/logjack.go @@ -12,6 +12,7 @@ import ( "syscall" auto "github.com/tendermint/tendermint/internal/libs/autofile" + "github.com/tendermint/tendermint/libs/log" ) const Version = "0.0.1" @@ -47,7 +48,7 @@ func main() { } // 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 { fmt.Printf("logjack couldn't create output file %v\n", headPath) os.Exit(1) diff --git a/internal/libs/autofile/group.go b/internal/libs/autofile/group.go index 969d101c3..19e88d87e 100644 --- a/internal/libs/autofile/group.go +++ b/internal/libs/autofile/group.go @@ -14,6 +14,7 @@ import ( "sync" "time" + "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" ) @@ -54,6 +55,7 @@ assuming that marker lines are written occasionally. */ type Group struct { service.BaseService + logger log.Logger ID string 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 // 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)) if err != nil { return nil, err @@ -89,6 +91,7 @@ func OpenGroup(headPath string, groupOptions ...func(*Group)) (*Group, error) { } g := &Group{ + logger: logger, ID: "group:" + head.ID, Head: head, headBuf: bufio.NewWriterSize(head, 4096*10), @@ -105,7 +108,7 @@ func OpenGroup(headPath string, groupOptions ...func(*Group)) (*Group, error) { option(g) } - g.BaseService = *service.NewBaseService(nil, "Group", g) + g.BaseService = *service.NewBaseService(logger, "Group", g) gInfo := g.readGroupInfo() g.minIndex = gInfo.MinIndex @@ -147,7 +150,7 @@ func (g *Group) OnStart(ctx context.Context) error { func (g *Group) OnStop() { g.ticker.Stop() 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. func (g *Group) Close() { 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() @@ -259,7 +262,7 @@ func (g *Group) checkHeadSizeLimit() { } size, err := g.Head.Size() 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 } if size >= limit { @@ -282,18 +285,18 @@ func (g *Group) checkTotalSizeLimit() { } if index == gInfo.MaxIndex { // 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 } pathToRemove := filePathForIndex(g.Head.Path, index, gInfo.MaxIndex) fInfo, err := os.Stat(pathToRemove) 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 } err = os.Remove(pathToRemove) if err != nil { - g.Logger.Error("Failed to remove path", "path", pathToRemove) + g.logger.Error("Failed to remove path", "path", pathToRemove) return } totalSize -= fInfo.Size() diff --git a/internal/libs/autofile/group_test.go b/internal/libs/autofile/group_test.go index ffdb70013..c4e068af9 100644 --- a/internal/libs/autofile/group_test.go +++ b/internal/libs/autofile/group_test.go @@ -9,18 +9,19 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/tendermint/tendermint/libs/log" tmos "github.com/tendermint/tendermint/libs/os" 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) testDir := "_test_" + testID err := tmos.EnsureDir(testDir, 0700) require.NoError(t, err, "Error creating dir") headPath := testDir + "/myfile" - g, err := OpenGroup(headPath, GroupHeadSizeLimit(headSizeLimit)) + g, err := OpenGroup(logger, headPath, GroupHeadSizeLimit(headSizeLimit)) require.NoError(t, err, "Error opening 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) { - g := createTestGroupWithHeadSizeLimit(t, 1000*1000) + logger := log.TestingLogger() + + g := createTestGroupWithHeadSizeLimit(t, logger, 1000*1000) // At first, there are no files. assertGroupInfo(t, g.ReadGroupInfo(), 0, 0, 0, 0) @@ -109,7 +112,9 @@ func TestCheckHeadSizeLimit(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 // relative paths are resolved at Group creation @@ -173,7 +178,9 @@ func TestRotateFile(t *testing.T) { } func TestWrite(t *testing.T) { - g := createTestGroupWithHeadSizeLimit(t, 0) + logger := log.TestingLogger() + + g := createTestGroupWithHeadSizeLimit(t, logger, 0) written := []byte("Medusa") _, 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 // group and returns no error if n == size of the given slice. func TestGroupReaderRead(t *testing.T) { - g := createTestGroupWithHeadSizeLimit(t, 0) + logger := log.TestingLogger() + + g := createTestGroupWithHeadSizeLimit(t, logger, 0) professor := []byte("Professor Monster") _, 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 // the given slice. Subsequent call should return 0, io.EOF. func TestGroupReaderRead2(t *testing.T) { - g := createTestGroupWithHeadSizeLimit(t, 0) + logger := log.TestingLogger() + + g := createTestGroupWithHeadSizeLimit(t, logger, 0) professor := []byte("Professor Monster") _, err := g.Write(professor) @@ -264,7 +275,8 @@ func TestGroupReaderRead2(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") @@ -273,7 +285,8 @@ func TestMinIndex(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") diff --git a/internal/mempool/reactor.go b/internal/mempool/reactor.go index 44f9c4df9..00345ccf8 100644 --- a/internal/mempool/reactor.go +++ b/internal/mempool/reactor.go @@ -35,6 +35,7 @@ type PeerManager interface { // txs to the peers you received it from. type Reactor struct { service.BaseService + logger log.Logger cfg *config.MempoolConfig mempool *TxMempool @@ -72,6 +73,7 @@ func NewReactor( ) *Reactor { r := &Reactor{ + logger: logger, cfg: cfg, peerMgr: peerMgr, mempool: txmp, @@ -114,7 +116,7 @@ func GetChannelDescriptor(cfg *config.MempoolConfig) *p2p.ChannelDescriptor { // OnStop to ensure the outbound p2p Channels are closed. func (r *Reactor) OnStart(ctx context.Context) error { if !r.cfg.Broadcast { - r.Logger.Info("tx broadcasting is disabled") + r.logger.Info("tx broadcasting is disabled") } 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 // message type. 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) { case *protomem.Txs: @@ -182,7 +184,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err if e := recover(); e != nil { r.observePanic(e) err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "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 { case MempoolChannel: @@ -210,7 +212,7 @@ func (r *Reactor) processMempoolCh(ctx context.Context) { select { case envelope := <-r.mempoolCh.In: 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{ NodeID: envelope.From, Err: err, @@ -219,7 +221,7 @@ func (r *Reactor) processMempoolCh(ctx context.Context) { case <-ctx.Done(): return case <-r.closeCh: - r.Logger.Debug("stopped listening on mempool channel; closing...") + r.logger.Debug("stopped listening on mempool channel; closing...") 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 // stop the tx broadcasting goroutine. 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() defer r.mtx.Unlock() @@ -293,7 +295,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { r.processPeerUpdate(ctx, peerUpdate) case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -313,7 +315,7 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, c if e := recover(); e != nil { r.observePanic(e) - r.Logger.Error( + r.logger.Error( "recovering from broadcasting mempool loop", "err", e, "stack", string(debug.Stack()), @@ -376,7 +378,7 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, c }: case <-ctx.Done(): } - r.Logger.Debug( + r.logger.Debug( "gossiped tx to peer", "tx", fmt.Sprintf("%X", memTx.tx.Hash()), "peer", peerID, diff --git a/internal/p2p/conn/connection.go b/internal/p2p/conn/connection.go index 67d7a42f0..a2808f216 100644 --- a/internal/p2p/conn/connection.go +++ b/internal/p2p/conn/connection.go @@ -74,6 +74,7 @@ Inbound message bytes are handled with an onReceive callback function. */ type MConnection struct { service.BaseService + logger log.Logger conn net.Conn bufConnReader *bufio.Reader @@ -178,6 +179,7 @@ func NewMConnectionWithConfig( } mconn := &MConnection{ + logger: logger, conn: conn, bufConnReader: bufio.NewReaderSize(conn, minReadBufferSize), bufConnWriter: bufio.NewWriterSize(conn, minWriteBufferSize), @@ -276,24 +278,24 @@ func (c *MConnection) String() string { } func (c *MConnection) flush() { - c.Logger.Debug("Flush", "conn", c) + c.logger.Debug("Flush", "conn", c) err := c.bufConnWriter.Flush() 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. func (c *MConnection) _recover() { 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)) } } func (c *MConnection) stopForError(r interface{}) { 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) { @@ -309,12 +311,12 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool { 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. channel, ok := c.channelsIdx[chID] 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 } @@ -326,7 +328,7 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool { default: } } 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 } @@ -351,14 +353,14 @@ FOR_LOOP: channel.updateStats() } case <-c.pingTimer.C: - c.Logger.Debug("Send Ping") + c.logger.Debug("Send Ping") _n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPing{})) if err != nil { - c.Logger.Error("Failed to send PacketPing", "err", err) + c.logger.Error("Failed to send PacketPing", "err", err) break SELECTION } 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() { select { case c.pongTimeoutCh <- true: @@ -368,16 +370,16 @@ FOR_LOOP: c.flush() case timeout := <-c.pongTimeoutCh: if timeout { - c.Logger.Debug("Pong timeout") + c.logger.Debug("Pong timeout") err = errors.New("pong timeout") } else { c.stopPongTimer() } case <-c.pong: - c.Logger.Debug("Send Pong") + c.logger.Debug("Send Pong") _n, err = protoWriter.WriteMsg(mustWrapPacket(&tmp2p.PacketPong{})) if err != nil { - c.Logger.Error("Failed to send PacketPong", "err", err) + c.logger.Error("Failed to send PacketPong", "err", err) break SELECTION } c.sendMonitor.Update(_n) @@ -402,7 +404,7 @@ FOR_LOOP: break FOR_LOOP } 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) break FOR_LOOP } @@ -453,12 +455,12 @@ func (c *MConnection) sendPacketMsg() bool { if leastChannel == nil { 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 _n, err := leastChannel.writePacketMsgTo(c.bufConnWriter) if err != nil { - c.Logger.Error("Failed to write PacketMsg", "err", err) + c.logger.Error("Failed to write PacketMsg", "err", err) c.stopForError(err) return true } @@ -488,10 +490,10 @@ FOR_LOOP: if err == nil { // return } else { - c.Logger.Debug("Error peeking connection buffer", "err", err) + c.logger.Debug("Error peeking connection buffer", "err", err) // 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 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 { - 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) } @@ -526,14 +528,14 @@ FOR_LOOP: case *tmp2p.Packet_PacketPing: // TODO: prevent abuse, as they cause flush()'s. // https://github.com/tendermint/tendermint/issues/1190 - c.Logger.Debug("Receive Ping") + c.logger.Debug("Receive Ping") select { case c.pong <- struct{}{}: default: // never block } case *tmp2p.Packet_PacketPong: - c.Logger.Debug("Receive Pong") + c.logger.Debug("Receive Pong") select { case c.pongTimeoutCh <- false: default: @@ -544,7 +546,7 @@ FOR_LOOP: channel, ok := c.channelsIdx[channelID] if pkt.PacketMsg.ChannelID < 0 || pkt.PacketMsg.ChannelID > math.MaxUint8 || !ok || channel == nil { 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) break FOR_LOOP } @@ -552,19 +554,19 @@ FOR_LOOP: msgBytes, err := channel.recvPacketMsg(*pkt.PacketMsg) if err != nil { 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) } break FOR_LOOP } 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 c.onReceive(channelID, msgBytes) } default: 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) break FOR_LOOP } @@ -656,7 +658,7 @@ type channel struct { maxPacketMsgPayloadSize int - Logger log.Logger + logger log.Logger } func newChannel(conn *MConnection, desc ChannelDescriptor) *channel { @@ -670,7 +672,7 @@ func newChannel(conn *MConnection, desc ChannelDescriptor) *channel { sendQueue: make(chan []byte, desc.SendQueueCapacity), recving: make([]byte, 0, desc.RecvBufferCapacity), 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. // Not goroutine-safe 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) if recvCap < recvReceived { return nil, fmt.Errorf("received message exceeds available capacity: %v < %v", recvCap, recvReceived) diff --git a/internal/p2p/pex/reactor.go b/internal/p2p/pex/reactor.go index 609d86e4c..69ff5206c 100644 --- a/internal/p2p/pex/reactor.go +++ b/internal/p2p/pex/reactor.go @@ -78,6 +78,7 @@ func ChannelDescriptor() *conn.ChannelDescriptor { // adding it to the back of the list once a response is received. type Reactor struct { service.BaseService + logger log.Logger peerManager *p2p.PeerManager pexCh *p2p.Channel @@ -123,6 +124,7 @@ func NewReactor( ) *Reactor { r := &Reactor{ + logger: logger, peerManager: peerManager, pexCh: pexCh, peerUpdates: peerUpdates, @@ -168,7 +170,7 @@ func (r *Reactor) processPexCh(ctx context.Context) { case <-ctx.Done(): return case <-r.closeCh: - r.Logger.Debug("stopped listening on PEX channel; closing...") + r.logger.Debug("stopped listening on PEX channel; closing...") return // outbound requests for new peers @@ -179,7 +181,7 @@ func (r *Reactor) processPexCh(ctx context.Context) { // reactor case envelope := <-r.pexCh.In: 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{ NodeID: envelope.From, Err: err, @@ -203,7 +205,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { r.processPeerUpdate(peerUpdate) case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -211,7 +213,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { // handlePexMessage handles envelopes sent from peers on the PexChannel. 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) { case *protop2p.PexRequest: @@ -279,7 +281,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err defer func() { if e := recover(); e != nil { err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "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 { 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 // send a request for addresses. 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() defer r.mtx.Unlock() @@ -328,7 +330,7 @@ func (r *Reactor) sendRequestForPeers() { defer r.mtx.Unlock() if len(r.availablePeers) == 0 { // 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) return @@ -351,7 +353,7 @@ func (r *Reactor) sendRequestForPeers() { r.requestsSent[peerID] = struct{}{} 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 @@ -368,7 +370,7 @@ func (r *Reactor) calculateNextRequestTime() { // check if the peer store is full. If so then there is no need // to send peer requests too often 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) r.nextRequestTime = time.Now().Add(fullCapacityInterval) return diff --git a/internal/p2p/router.go b/internal/p2p/router.go index 10f996442..7d1529ace 100644 --- a/internal/p2p/router.go +++ b/internal/p2p/router.go @@ -146,8 +146,8 @@ func (o *RouterOptions) Validate() error { // quality of service. type Router struct { *service.BaseService + logger log.Logger - logger log.Logger metrics *Metrics options RouterOptions nodeInfo types.NodeInfo @@ -336,7 +336,7 @@ func (r *Router) routeChannel( if wrapper != nil { msg := proto.Clone(wrapper) 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 } @@ -958,7 +958,7 @@ func (r *Router) OnStart(ctx context.Context) error { } } - r.Logger.Info( + r.logger.Info( "starting router", "node_id", r.nodeInfo.NodeID, "channels", r.nodeInfo.Channels, diff --git a/internal/p2p/transport_mconn.go b/internal/p2p/transport_mconn.go index b5c89502f..b89671670 100644 --- a/internal/p2p/transport_mconn.go +++ b/internal/p2p/transport_mconn.go @@ -295,7 +295,6 @@ func (c *mConnConnection) Handshake( return types.NodeInfo{}, nil, err } c.mconn = mconn - c.logger = mconn.Logger if err = c.mconn.Start(ctx); err != nil { return types.NodeInfo{}, nil, err } diff --git a/internal/proxy/multi_app_conn.go b/internal/proxy/multi_app_conn.go index 6196992ff..56b70b7b3 100644 --- a/internal/proxy/multi_app_conn.go +++ b/internal/proxy/multi_app_conn.go @@ -46,6 +46,7 @@ func NewAppConns(clientCreator abciclient.Creator, logger log.Logger, metrics *M // TODO: on app restart, clients must reboot together type multiAppConn struct { service.BaseService + logger log.Logger metrics *Metrics consensusConn AppConnConsensus @@ -72,6 +73,7 @@ type stoppableClient interface { // NewMultiAppConn makes all necessary abci connections to the application. func NewMultiAppConn(clientCreator abciclient.Creator, logger log.Logger, metrics *Metrics) AppConns { multiAppConn := &multiAppConn{ + logger: logger, metrics: metrics, clientCreator: clientCreator, } @@ -181,7 +183,7 @@ func (app *multiAppConn) startWatchersForClientErrorToKillTendermint(ctx context return } if err := client.Error(); err != nil { - killFn(name, err, app.Logger) + killFn(name, err, app.logger) } }(client.name, client.connClient) } @@ -191,35 +193,35 @@ func (app *multiAppConn) stopAllClients() { if app.consensusConnClient != nil { if err := app.consensusConnClient.Stop(); err != nil { 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 err := app.mempoolConnClient.Stop(); err != nil { 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 err := app.queryConnClient.Stop(); err != nil { 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 err := app.snapshotConnClient.Stop(); err != nil { 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) { - c, err := app.clientCreator(app.Logger.With( + c, err := app.clientCreator(app.logger.With( "module", "abci-client", "connection", conn)) if err != nil { diff --git a/internal/state/indexer/indexer_service.go b/internal/state/indexer/indexer_service.go index 80c4adf02..83810953b 100644 --- a/internal/state/indexer/indexer_service.go +++ b/internal/state/indexer/indexer_service.go @@ -15,6 +15,7 @@ import ( // order to index transactions and blocks coming from the event bus. type Service struct { service.BaseService + logger log.Logger eventSinks []EventSink eventBus *eventbus.EventBus @@ -30,6 +31,7 @@ type Service struct { // NewService constructs a new indexer service from the given arguments. func NewService(args ServiceArgs) *Service { is := &Service{ + logger: args.Logger, eventSinks: args.Sinks, eventBus: args.EventBus, 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. txResult := msg.Data().(types.EventDataTx).TxResult 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) } @@ -83,12 +85,12 @@ func (is *Service) publish(msg pubsub.Message) error { for _, sink := range is.eventSinks { start := time.Now() 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) } else { is.metrics.BlockEventsSeconds.Observe(time.Since(start).Seconds()) is.metrics.BlocksIndexed.Add(1) - is.Logger.Debug("indexed block", + is.logger.Debug("indexed block", "height", is.currentBlock.height, "sink", sink.Type()) } @@ -96,12 +98,12 @@ func (is *Service) publish(msg pubsub.Message) error { start := time.Now() err := sink.IndexTxEvents(curr.Ops) 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) } else { is.metrics.TxEventsSeconds.Observe(time.Since(start).Seconds()) is.metrics.TransactionsIndexed.Add(float64(curr.Size())) - is.Logger.Debug("indexed txs", + is.logger.Debug("indexed txs", "height", is.currentBlock.height, "sink", sink.Type()) } } @@ -133,7 +135,7 @@ func (is *Service) OnStart(ctx context.Context) error { func (is *Service) OnStop() { for _, sink := range is.eventSinks { 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) } } } diff --git a/internal/statesync/reactor.go b/internal/statesync/reactor.go index 10edd3827..cd3dde3ea 100644 --- a/internal/statesync/reactor.go +++ b/internal/statesync/reactor.go @@ -126,6 +126,7 @@ type Metricer interface { // serving snapshots for other nodes. type Reactor struct { service.BaseService + logger log.Logger chainID string initialHeight int64 @@ -180,6 +181,7 @@ func NewReactor( ssMetrics *Metrics, ) *Reactor { r := &Reactor{ + logger: logger, chainID: chainID, initialHeight: initialHeight, cfg: cfg, @@ -260,7 +262,7 @@ func (r *Reactor) Sync(ctx context.Context) (sm.State, error) { r.syncer = newSyncer( r.cfg, - r.Logger, + r.logger, r.conn, r.connQuery, r.stateProvider, @@ -310,7 +312,7 @@ func (r *Reactor) Sync(ctx context.Context) (sm.State, error) { err = r.Backfill(ctx, state) if err != nil { - r.Logger.Error("backfill failed. Proceeding optimistically...", "err", err) + r.logger.Error("backfill failed. Proceeding optimistically...", "err", err) } return state, nil @@ -348,7 +350,7 @@ func (r *Reactor) backfill( trustedBlockID types.BlockID, stopTime time.Time, ) error { - r.Logger.Info("starting backfill process...", "startHeight", startHeight, + r.logger.Info("starting backfill process...", "startHeight", startHeight, "stopHeight", stopHeight, "stopTime", stopTime, "trustedBlockID", trustedBlockID) r.backfillBlockTotal = startHeight - stopHeight + 1 @@ -378,7 +380,7 @@ func (r *Reactor) backfill( case height := <-queue.nextHeight(): // pop the next peer of the list to send a request to 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) defer cancel() lb, err := func() (*types.LightBlock, error) { @@ -394,18 +396,18 @@ func (r *Reactor) backfill( if err != nil { queue.retry(height) 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) time.Sleep(sleepTime) } else { // 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) } continue } 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) // 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. @@ -417,7 +419,7 @@ func (r *Reactor) backfill( // hashes line up err = lb.ValidateBasic(chainID) 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) queue.retry(height) r.blockCh.Error <- p2p.PeerError{ @@ -432,7 +434,7 @@ func (r *Reactor) backfill( block: lb, 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(): return @@ -456,7 +458,7 @@ func (r *Reactor) backfill( // we equate to. ValidatorsHash and CommitHash have already been // checked in the `ValidateBasic` 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) r.blockCh.Error <- p2p.PeerError{ NodeID: resp.peer, @@ -486,7 +488,7 @@ func (r *Reactor) backfill( trustedBlockID = resp.block.LastBlockID 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 @@ -510,7 +512,7 @@ func (r *Reactor) backfill( 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 } } @@ -520,7 +522,7 @@ func (r *Reactor) backfill( // SnapshotChannel. It returns an error only if the Envelope.Message is unknown // for this channel. This should never be called outside of handleMessage. 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) { case *ssproto.SnapshotsRequest: @@ -591,7 +593,7 @@ func (r *Reactor) handleSnapshotMessage(envelope p2p.Envelope) error { func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { switch msg := envelope.Message.(type) { case *ssproto.ChunkRequest: - r.Logger.Debug( + r.logger.Debug( "received chunk request", "height", msg.Height, "format", msg.Format, @@ -604,7 +606,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { Chunk: msg.Index, }) if err != nil { - r.Logger.Error( + r.logger.Error( "failed to load chunk", "height", msg.Height, "format", msg.Format, @@ -615,7 +617,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { return nil } - r.Logger.Debug( + r.logger.Debug( "sending chunk", "height", msg.Height, "format", msg.Format, @@ -638,11 +640,11 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { defer r.mtx.RUnlock() 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 } - r.Logger.Debug( + r.logger.Debug( "received chunk; adding to sync", "height", msg.Height, "format", msg.Format, @@ -657,7 +659,7 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { Sender: envelope.From, }) if err != nil { - r.Logger.Error( + r.logger.Error( "failed to add chunk", "height", msg.Height, "format", msg.Format, @@ -678,10 +680,10 @@ func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error { func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error { switch msg := envelope.Message.(type) { 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) 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 } if lb == nil { @@ -696,7 +698,7 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error { lbproto, err := lb.ToProto() 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 } @@ -714,9 +716,9 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error { if msg.LightBlock != nil { 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 { - 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: @@ -729,10 +731,10 @@ func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error { func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error { switch msg := envelope.Message.(type) { 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)) 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 } @@ -748,7 +750,7 @@ func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error { case *ssproto.ParamsResponse: r.mtx.RLock() 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) @@ -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") } } 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: @@ -776,7 +778,7 @@ func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err defer func() { if e := recover(); e != nil { err = fmt.Errorf("panic in processing message: %v", e) - r.Logger.Error( + r.logger.Error( "recovering from processing message panic", "err", err, "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 { case SnapshotChannel: @@ -817,7 +819,7 @@ func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string) return case envelope := <-ch.In: 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, "channel", chName, "ch_id", ch.ID, @@ -829,7 +831,7 @@ func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string) } case <-r.closeCh: - r.Logger.Debug("channel closed", "channel", chName) + r.logger.Debug("channel closed", "channel", chName) 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 // handle the PeerUpdate or if a panic is recovered. 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 { case p2p.PeerStatusUp: @@ -859,7 +861,7 @@ func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) { r.providers[peerUpdate.NodeID] = newProvider err := r.syncer.AddPeer(peerUpdate.NodeID) if err != nil { - r.Logger.Error("error adding peer to syncer", "error", err) + r.logger.Error("error adding peer to syncer", "error", err) return } if sp, ok := r.stateProvider.(*stateProviderP2P); ok { @@ -872,7 +874,7 @@ func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) { delete(r.providers, 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 @@ -889,7 +891,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context) { r.processPeerUpdate(peerUpdate) case <-r.closeCh: - r.Logger.Debug("stopped listening on peer updates channel; closing...") + r.logger.Debug("stopped listening on peer updates channel; closing...") return } } @@ -985,7 +987,7 @@ func (r *Reactor) waitForEnoughPeers(ctx context.Context, numPeers int) error { case <-t.C: continue 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(), "target", numPeers, "peers", r.peers.Len(), @@ -1004,7 +1006,7 @@ func (r *Reactor) initStateProvider(ctx context.Context, chainID string, initial Height: r.cfg.TrustHeight, Hash: r.cfg.TrustHashBytes(), } - spLogger := r.Logger.With("module", "stateprovider") + spLogger := r.logger.With("module", "stateprovider") spLogger.Info("initializing state provider", "trustPeriod", to.Period, "trustHeight", to.Height, "useP2P", r.cfg.UseP2P) diff --git a/libs/pubsub/example_test.go b/libs/pubsub/example_test.go index 0d608ceff..0cf7b5853 100644 --- a/libs/pubsub/example_test.go +++ b/libs/pubsub/example_test.go @@ -7,6 +7,7 @@ import ( "github.com/stretchr/testify/require" 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/query" ) @@ -14,7 +15,8 @@ import ( func TestExample(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + + s := newTestServer(ctx, t, log.TestingLogger()) sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: "example-client", diff --git a/libs/pubsub/pubsub.go b/libs/pubsub/pubsub.go index 3ac2c1940..cd37a17ee 100644 --- a/libs/pubsub/pubsub.go +++ b/libs/pubsub/pubsub.go @@ -41,6 +41,7 @@ import ( "sync" "github.com/tendermint/tendermint/abci/types" + "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" ) @@ -103,6 +104,7 @@ func (args UnsubscribeArgs) Validate() error { // messages with or without events, and manages internal state. type Server struct { service.BaseService + logger log.Logger queue chan item 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 // for a detailed description of how to configure buffering. If no options are // 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 { 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. // // 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{ ClientID: clientID, Query: query, @@ -384,7 +385,7 @@ func (s *Server) run(ctx context.Context) { // Sender: Service the queue and forward messages to subscribers. for it := range queue { 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. diff --git a/libs/pubsub/pubsub_test.go b/libs/pubsub/pubsub_test.go index 926a263a4..601e48823 100644 --- a/libs/pubsub/pubsub_test.go +++ b/libs/pubsub/pubsub_test.go @@ -22,7 +22,8 @@ func TestSubscribeWithArgs(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) t.Run("DefaultLimit", func(t *testing.T) { sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ @@ -50,8 +51,9 @@ func TestSubscribeWithArgs(t *testing.T) { func TestObserver(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() + logger := log.TestingLogger() - s := newTestServer(ctx, t) + s := newTestServer(ctx, t, logger) done := make(chan struct{}) var got interface{} @@ -71,7 +73,9 @@ func TestObserverErrors(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + + s := newTestServer(ctx, t, logger) require.Error(t, s.Observe(ctx, nil, query.All)) 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()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + + s := newTestServer(ctx, t, logger) sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: clientID, @@ -110,7 +116,8 @@ func TestSubscribeErrors(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) t.Run("EmptyQueryErr", func(t *testing.T) { _, err := s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ClientID: clientID}) @@ -130,7 +137,8 @@ func TestSlowSubscriber(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: clientID, @@ -151,7 +159,8 @@ func TestDifferentClients(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: "client-1", @@ -205,7 +214,8 @@ func TestSubscribeDuplicateKeys(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) testCases := []struct { query string @@ -260,7 +270,8 @@ func TestClientSubscribesTwice(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) q := query.MustCompile(`tm.events.type='NewBlock'`) events := []abci.Event{{ @@ -295,7 +306,8 @@ func TestUnsubscribe(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) sub := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: clientID, @@ -319,7 +331,8 @@ func TestClientUnsubscribesTwice(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: clientID, @@ -340,7 +353,8 @@ func TestResubscribe(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) args := pubsub.SubscribeArgs{ ClientID: clientID, @@ -363,7 +377,8 @@ func TestUnsubscribeAll(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - s := newTestServer(ctx, t) + logger := log.TestingLogger() + s := newTestServer(ctx, t, logger) sub1 := newTestSub(t).must(s.SubscribeWithArgs(ctx, pubsub.SubscribeArgs{ ClientID: clientID, @@ -383,10 +398,8 @@ func TestUnsubscribeAll(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()) @@ -402,12 +415,10 @@ func TestBufferCapacity(t *testing.T) { 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() - s := pubsub.NewServer(func(s *pubsub.Server) { - s.Logger = log.TestingLogger() - }) + s := pubsub.NewServer(logger) require.NoError(t, s.Start(ctx)) t.Cleanup(s.Wait) diff --git a/libs/service/service.go b/libs/service/service.go index ad88ccf16..81c885ae5 100644 --- a/libs/service/service.go +++ b/libs/service/service.go @@ -92,7 +92,7 @@ Typical usage: } */ type BaseService struct { - Logger log.Logger + logger log.Logger name string started uint32 // atomic stopped uint32 // atomic @@ -109,7 +109,7 @@ func NewBaseService(logger log.Logger, name string, impl Implementation) *BaseSe } return &BaseService{ - Logger: logger, + logger: logger, name: name, quit: make(chan struct{}), impl: impl, @@ -122,12 +122,12 @@ func NewBaseService(logger log.Logger, name string, impl Implementation) *BaseSe func (bs *BaseService) Start(ctx context.Context) error { if atomic.CompareAndSwapUint32(&bs.started, 0, 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) 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 { // revert flag @@ -151,13 +151,13 @@ func (bs *BaseService) Start(ctx context.Context) error { // the context was cancel and we // should stop. if err := bs.Stop(); err != nil { - bs.Logger.Error("stopped service", + bs.logger.Error("stopped service", "err", err.Error(), "service", bs.name, "impl", bs.impl.String()) } - bs.Logger.Info("stopped service", + bs.logger.Info("stopped service", "service", bs.name, "impl", bs.impl.String()) } @@ -166,7 +166,7 @@ func (bs *BaseService) Start(ctx context.Context) error { 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 } @@ -175,19 +175,19 @@ func (bs *BaseService) Start(ctx context.Context) error { func (bs *BaseService) Stop() error { if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) { 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) 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() close(bs.quit) 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 } diff --git a/node/node.go b/node/node.go index 10ade3ce7..6ad02fbee 100644 --- a/node/node.go +++ b/node/node.go @@ -46,6 +46,7 @@ import ( // It includes all configuration information and running services. type nodeImpl struct { service.BaseService + logger log.Logger // config config *config.Config @@ -388,6 +389,7 @@ func makeNode( node := &nodeImpl{ config: cfg, + logger: logger, genesisDoc: genDoc, privValidator: privValidator, @@ -495,6 +497,7 @@ func makeSeedNode( node := &nodeImpl{ config: cfg, + logger: logger, genesisDoc: genDoc, nodeInfo: nodeInfo, @@ -527,10 +530,10 @@ func (n *nodeImpl) OnStart(ctx context.Context) error { }() 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 { - n.Logger.Error("pprof server error", "err", err) + n.logger.Error("pprof server error", "err", err) rpcCancel() } }() @@ -539,7 +542,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error { now := tmtime.Now() genTime := n.genesisDoc.GenesisTime 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)) } @@ -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. d := types.EventDataStateSyncStatus{Complete: false, Height: state.InitialHeight} 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 // bubbling up the error and gracefully shutting down the rest of the node go func() { - n.Logger.Info("starting state sync") + n.logger.Info("starting state sync") state, err := n.stateSyncReactor.Sync(ctx) 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 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 } @@ -642,7 +645,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error { Height: state.LastBlockHeight, }); 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 @@ -651,7 +654,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error { // FIXME Very ugly to have these metrics bleed through here. n.consensusReactor.SetBlockSyncingMetrics(1) 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 } @@ -661,7 +664,7 @@ func (n *nodeImpl) OnStart(ctx context.Context) error { Height: state.LastBlockHeight, }); 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. func (n *nodeImpl) OnStop() { - n.Logger.Info("Stopping Node") + n.logger.Info("Stopping Node") if n.eventBus != nil { n.eventBus.Wait() @@ -682,7 +685,7 @@ func (n *nodeImpl) OnStop() { for _, es := range n.eventSinks { 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 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 { - 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 err := n.prometheusSrv.Shutdown(context.Background()); err != nil { // 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 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 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 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)) for i, listenAddr := range listenAddrs { mux := http.NewServeMux() - rpcLogger := n.Logger.With("module", "rpc-server") + rpcLogger := n.logger.With("module", "rpc-server") wmLogger := rpcLogger.With("protocol", "websocket") wm := rpcserver.NewWebsocketManager(routes, rpcserver.OnDisconnect(func(remoteAddr string) { @@ -809,7 +812,7 @@ func (n *nodeImpl) startRPC(ctx context.Context) ([]net.Listener, error) { rpcLogger, cfg, ); err != nil { - n.Logger.Error("Error serving server with TLS", "err", err) + n.logger.Error("Error serving server with TLS", "err", err) } }() } else { @@ -821,7 +824,7 @@ func (n *nodeImpl) startRPC(ctx context.Context) ([]net.Listener, error) { rpcLogger, cfg, ); 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() { 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() } }() diff --git a/privval/signer_client.go b/privval/signer_client.go index ec6d95ca6..981b4e175 100644 --- a/privval/signer_client.go +++ b/privval/signer_client.go @@ -7,6 +7,7 @@ import ( "github.com/tendermint/tendermint/crypto" "github.com/tendermint/tendermint/crypto/encoding" + "github.com/tendermint/tendermint/libs/log" privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval" tmproto "github.com/tendermint/tendermint/proto/tendermint/types" "github.com/tendermint/tendermint/types" @@ -15,6 +16,7 @@ import ( // SignerClient implements PrivValidator. // Handles remote validator connections that provide signing services type SignerClient struct { + logger log.Logger endpoint *SignerListenerEndpoint 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 @@ -55,7 +61,7 @@ func (sc *SignerClient) WaitForConnection(maxWait time.Duration) error { func (sc *SignerClient) Ping() error { response, err := sc.endpoint.SendRequest(mustWrapMsg(&privvalproto.PingRequest{})) if err != nil { - sc.endpoint.Logger.Error("SignerClient::Ping", "err", err) + sc.logger.Error("SignerClient::Ping", "err", err) return nil } diff --git a/privval/signer_client_test.go b/privval/signer_client_test.go index 7ff353dcd..2e3fbcb2d 100644 --- a/privval/signer_client_test.go +++ b/privval/signer_client_test.go @@ -267,9 +267,9 @@ func TestSignerVoteKeepAlive(t *testing.T) { // in this particular case, we use the dialer logger to ensure that // 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) - 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.signerClient.SignVote(ctx, tc.chainID, have.ToProto())) diff --git a/privval/signer_dialer_endpoint.go b/privval/signer_dialer_endpoint.go index cc605617f..76b3bd501 100644 --- a/privval/signer_dialer_endpoint.go +++ b/privval/signer_dialer_endpoint.go @@ -59,6 +59,7 @@ func NewSignerDialerEndpoint( retryWait: defaultRetryWaitMilliseconds * time.Millisecond, maxConnRetries: defaultMaxDialRetries, } + sd.signerEndpoint.logger = logger sd.BaseService = *service.NewBaseService(logger, "SignerDialerEndpoint", sd) sd.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second @@ -84,17 +85,17 @@ func (sd *SignerDialerEndpoint) ensureConnection() error { if err != nil { 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 time.Sleep(sd.retryWait) } else { sd.SetConnection(conn) - sd.Logger.Debug("SignerDialer: Connection Ready") + sd.logger.Debug("SignerDialer: Connection Ready") 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 } diff --git a/privval/signer_endpoint.go b/privval/signer_endpoint.go index 0d46ca692..b48e79f94 100644 --- a/privval/signer_endpoint.go +++ b/privval/signer_endpoint.go @@ -7,6 +7,7 @@ import ( "github.com/tendermint/tendermint/internal/libs/protoio" tmsync "github.com/tendermint/tendermint/internal/libs/sync" + "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" privvalproto "github.com/tendermint/tendermint/proto/tendermint/privval" ) @@ -17,6 +18,7 @@ const ( type signerEndpoint struct { service.BaseService + logger log.Logger connMtx tmsync.Mutex conn net.Conn @@ -104,7 +106,7 @@ func (se *signerEndpoint) ReadMessage() (msg privvalproto.Message, err error) { err = fmt.Errorf("empty error: %w", ErrReadTimeout) } - se.Logger.Debug("Dropping [read]", "obj", se) + se.logger.Debug("Dropping [read]", "obj", se) se.dropConnection() } @@ -149,7 +151,7 @@ func (se *signerEndpoint) isConnected() bool { func (se *signerEndpoint) dropConnection() { if se.conn != 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 } diff --git a/privval/signer_listener_endpoint.go b/privval/signer_listener_endpoint.go index a825f635d..15622925d 100644 --- a/privval/signer_listener_endpoint.go +++ b/privval/signer_listener_endpoint.go @@ -53,6 +53,7 @@ func NewSignerListenerEndpoint( timeoutAccept: defaultTimeoutAcceptSeconds * time.Second, } + sl.signerEndpoint.logger = logger sl.BaseService = *service.NewBaseService(logger, "SignerListenerEndpoint", sl) sl.signerEndpoint.timeoutReadWrite = defaultTimeoutReadWriteSeconds * time.Second @@ -89,7 +90,7 @@ func (sl *SignerListenerEndpoint) OnStop() { // Stop listening if sl.listener != 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 } } @@ -141,7 +142,7 @@ func (sl *SignerListenerEndpoint) ensureConnection(maxWait time.Duration) error } // block until connected or timeout - sl.Logger.Info("SignerListener: Blocking for connection") + sl.logger.Info("SignerListener: Blocking for connection") sl.triggerConnect() return sl.WaitConnection(sl.connectionAvailableCh, maxWait) } @@ -152,7 +153,7 @@ func (sl *SignerListenerEndpoint) acceptNewConnection() (net.Conn, error) { } // 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() if err != nil { return nil, err @@ -180,7 +181,7 @@ func (sl *SignerListenerEndpoint) serviceLoop(ctx context.Context) { { conn, err := sl.acceptNewConnection() 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 select { @@ -208,7 +209,7 @@ func (sl *SignerListenerEndpoint) pingLoop(ctx context.Context) { { _, err := sl.SendRequest(mustWrapMsg(&privvalproto.PingRequest{})) if err != nil { - sl.Logger.Error("SignerListener: Ping timeout") + sl.logger.Error("SignerListener: Ping timeout") sl.triggerReconnect() } } diff --git a/privval/signer_server.go b/privval/signer_server.go index dd924f0eb..4c4d6282a 100644 --- a/privval/signer_server.go +++ b/privval/signer_server.go @@ -36,7 +36,7 @@ func NewSignerServer(endpoint *SignerDialerEndpoint, chainID string, privVal typ validationRequestHandler: DefaultValidationRequestHandler, } - ss.BaseService = *service.NewBaseService(endpoint.Logger, "SignerServer", ss) + ss.BaseService = *service.NewBaseService(endpoint.logger, "SignerServer", ss) return ss } @@ -49,7 +49,7 @@ func (ss *SignerServer) OnStart(ctx context.Context) error { // OnStop implements service.Service. func (ss *SignerServer) OnStop() { - ss.endpoint.Logger.Debug("SignerServer: OnStop calling Close") + ss.endpoint.logger.Debug("SignerServer: OnStop calling Close") _ = ss.endpoint.Close() } @@ -68,7 +68,7 @@ func (ss *SignerServer) servicePendingRequest() { req, err := ss.endpoint.ReadMessage() if err != nil { if err != io.EOF { - ss.Logger.Error("SignerServer: HandleMessage", "err", err) + ss.endpoint.logger.Error("SignerServer: HandleMessage", "err", err) } return } @@ -81,13 +81,13 @@ func (ss *SignerServer) servicePendingRequest() { res, err = ss.validationRequestHandler(context.TODO(), ss.privVal, req, ss.chainID) // todo if err != nil { // 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) if err != nil { - ss.Logger.Error("SignerServer: writeMessage", "err", err) + ss.endpoint.logger.Error("SignerServer: writeMessage", "err", err) } }