diff --git a/blockchain/v2/routine.go b/blockchain/v2/routine.go index e4ca52add..dad0e737f 100644 --- a/blockchain/v2/routine.go +++ b/blockchain/v2/routine.go @@ -58,7 +58,7 @@ func (rt *Routine) setMetrics(metrics *Metrics) { } func (rt *Routine) start() { - rt.logger.Info(fmt.Sprintf("%s: run", rt.name)) + rt.logger.Info("routine start", "msg", log.NewLazySprintf("%s: run", rt.name)) running := atomic.CompareAndSwapUint32(rt.running, uint32(0), uint32(1)) if !running { panic(fmt.Sprintf("%s is already running", rt.name)) @@ -98,7 +98,7 @@ func (rt *Routine) start() { return } rt.metrics.EventsOut.With("routine", rt.name).Add(1) - rt.logger.Debug(fmt.Sprintf("%s: produced %T %+v", rt.name, oEvent, oEvent)) + rt.logger.Debug("routine start", "msg", log.NewLazySprintf("%s: produced %T %+v", rt.name, oEvent, oEvent)) // Skip rTrySchedule and rProcessBlock events as they clutter the history // due to their frequency. @@ -118,7 +118,7 @@ func (rt *Routine) start() { // XXX: look into returning OpError in the net package func (rt *Routine) send(event Event) bool { - rt.logger.Debug(fmt.Sprintf("%s: received %T %+v", rt.name, event, event)) + rt.logger.Debug("routine send", "msg", log.NewLazySprintf("%s: received %T %+v", rt.name, event, event)) if !rt.isRunning() { return false } @@ -150,7 +150,7 @@ func (rt *Routine) stop() { return } - rt.logger.Info(fmt.Sprintf("%s: stop", rt.name)) + rt.logger.Info("routine stop", "msg", log.NewLazySprintf("%s: stop", rt.name)) rt.queue.Dispose() // this should block until all queue items are free? } diff --git a/consensus/reactor.go b/consensus/reactor.go index 73f190394..d6b22786b 100644 --- a/consensus/reactor.go +++ b/consensus/reactor.go @@ -1265,12 +1265,12 @@ func (ps *PeerState) SetHasVote(vote *types.Vote) { } func (ps *PeerState) setHasVote(height int64, round int32, voteType tmproto.SignedMsgType, index int32) { - logger := ps.logger.With( + ps.logger.Debug("setHasVote", "peerH/R", - fmt.Sprintf("%d/%d", ps.PRS.Height, ps.PRS.Round), + log.NewLazySprintf("%d/%d", ps.PRS.Height, ps.PRS.Round), "H/R", - fmt.Sprintf("%d/%d", height, round)) - logger.Debug("setHasVote", "type", voteType, "index", index) + log.NewLazySprintf("%d/%d", height, round), + "type", voteType, "index", index) // NOTE: some may be nil BitArrays -> no side effects. psVotes := ps.getVoteBitArray(height, round, voteType) diff --git a/consensus/state.go b/consensus/state.go index 0e74583f8..9e6d980a3 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -981,7 +981,7 @@ func (cs *State) enterNewRound(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) { logger.Debug( "entering new round with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } @@ -990,7 +990,7 @@ func (cs *State) enterNewRound(height int64, round int32) { logger.Debug("need to set a buffer and log message here for sanity", "start_time", cs.StartTime, "now", now) } - logger.Debug("entering new round", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering new round", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) // increment validators if necessary validators := cs.Validators @@ -1063,12 +1063,12 @@ func (cs *State) enterPropose(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) { logger.Debug( "entering propose step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } - logger.Debug("entering propose step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering propose step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPropose: @@ -1230,7 +1230,7 @@ func (cs *State) enterPrevote(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) { logger.Debug( "entering prevote step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } @@ -1241,7 +1241,7 @@ func (cs *State) enterPrevote(height int64, round int32) { cs.newStep() }() - logger.Debug("entering prevote step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering prevote step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) // Sign and broadcast vote as necessary cs.doPrevote(height, round) @@ -1290,7 +1290,7 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) { logger.Debug( "entering prevote wait step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } @@ -1302,7 +1302,7 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { )) } - logger.Debug("entering prevote wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering prevote wait step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrevoteWait: @@ -1326,12 +1326,12 @@ func (cs *State) enterPrecommit(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) { logger.Debug( "entering precommit step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } - logger.Debug("entering precommit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering precommit step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommit: @@ -1449,7 +1449,7 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { logger.Debug( "entering precommit wait step with invalid args", "triggered_timeout", cs.TriggeredTimeoutPrecommit, - "current", fmt.Sprintf("%v/%v", cs.Height, cs.Round), + "current", log.NewLazySprintf("%v/%v", cs.Height, cs.Round), ) return } @@ -1461,7 +1461,7 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { )) } - logger.Debug("entering precommit wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering precommit wait step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommitWait: @@ -1480,12 +1480,12 @@ func (cs *State) enterCommit(height int64, commitRound int32) { if cs.Height != height || cstypes.RoundStepCommit <= cs.Step { logger.Debug( "entering commit step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } - logger.Debug("entering commit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering commit step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) defer func() { // Done enterCommit: @@ -1518,7 +1518,7 @@ func (cs *State) enterCommit(height int64, commitRound int32) { if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) { logger.Info( "commit is for a block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), + "proposal", log.NewLazyBlockHash(cs.ProposalBlock), "commit", blockID.Hash, ) @@ -1555,7 +1555,7 @@ func (cs *State) tryFinalizeCommit(height int64) { // TODO: ^^ wait, why does it matter that we're a validator? logger.Debug( "failed attempt to finalize commit; we do not have the commit block", - "proposal_block", cs.ProposalBlock.Hash(), + "proposal_block", log.NewLazyBlockHash(cs.ProposalBlock), "commit_block", blockID.Hash, ) return @@ -1571,7 +1571,7 @@ func (cs *State) finalizeCommit(height int64) { if cs.Height != height || cs.Step != cstypes.RoundStepCommit { logger.Debug( "entering finalize commit step", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), + "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), ) return } @@ -1597,11 +1597,11 @@ func (cs *State) finalizeCommit(height int64) { logger.Info( "finalizing commit of block", - "hash", block.Hash(), + "hash", log.NewLazyBlockHash(block), "root", block.AppHash, "num_txs", len(block.Txs), ) - logger.Debug(fmt.Sprintf("%v", block)) + logger.Debug("committed block", "block", log.NewLazySprintf("%v", block)) fail.Fail() // XXX @@ -1918,7 +1918,7 @@ func (cs *State) handleCompleteProposal(blockHeight int64) { cs.Logger.Debug( "updating valid block to new proposal block", "valid_round", cs.Round, - "valid_block_hash", cs.ProposalBlock.Hash(), + "valid_block_hash", log.NewLazyBlockHash(cs.ProposalBlock), ) cs.ValidRound = cs.Round @@ -2092,7 +2092,7 @@ func (cs *State) addVote(vote *types.Vote, peerID p2p.ID) (added bool, err error } else { cs.Logger.Debug( "valid block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), + "proposal", log.NewLazyBlockHash(cs.ProposalBlock), "block_id", blockID.Hash, ) diff --git a/libs/log/lazy.go b/libs/log/lazy.go new file mode 100644 index 000000000..521fa1952 --- /dev/null +++ b/libs/log/lazy.go @@ -0,0 +1,42 @@ +package log + +import ( + "fmt" + + tmbytes "github.com/tendermint/tendermint/libs/bytes" +) + +type LazySprintf struct { + format string + args []interface{} +} + +// NewLazySprintf defers fmt.Sprintf until the Stringer interface is invoked. +// This is particularly useful for avoiding calling Sprintf when debugging is not +// active. +func NewLazySprintf(format string, args ...interface{}) *LazySprintf { + return &LazySprintf{format, args} +} + +func (l *LazySprintf) String() string { + return fmt.Sprintf(l.format, l.args...) +} + +type LazyBlockHash struct { + block hashable +} + +type hashable interface { + Hash() tmbytes.HexBytes +} + +// NewLazyBlockHash defers block Hash until the Stringer interface is invoked. +// This is particularly useful for avoiding calling Sprintf when debugging is not +// active. +func NewLazyBlockHash(block hashable) *LazyBlockHash { + return &LazyBlockHash{block} +} + +func (l *LazyBlockHash) String() string { + return l.block.Hash().String() +} diff --git a/libs/log/tmfmt_logger.go b/libs/log/tmfmt_logger.go index 01cf72192..391ae478a 100644 --- a/libs/log/tmfmt_logger.go +++ b/libs/log/tmfmt_logger.go @@ -87,6 +87,12 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { if b, ok := keyvals[i+1].([]byte); ok { keyvals[i+1] = strings.ToUpper(hex.EncodeToString(b)) } + + // Realize stringers + if s, ok := keyvals[i+1].(fmt.Stringer); ok { + keyvals[i+1] = s.String() + } + } // Form a custom Tendermint line diff --git a/libs/os/os.go b/libs/os/os.go index 79e340d19..a24e1ba7f 100644 --- a/libs/os/os.go +++ b/libs/os/os.go @@ -8,6 +8,8 @@ import ( "os" "os/signal" "syscall" + + "github.com/tendermint/tendermint/libs/log" ) type logger interface { @@ -21,7 +23,7 @@ func TrapSignal(logger logger, cb func()) { signal.Notify(c, os.Interrupt, syscall.SIGTERM) go func() { for sig := range c { - logger.Info(fmt.Sprintf("captured %v, exiting...", sig)) + logger.Info("signal trapped", "msg", log.NewLazySprintf("captured %v, exiting...", sig)) if cb != nil { cb() } diff --git a/libs/service/service.go b/libs/service/service.go index 5efd0f04d..a3f1b4cb6 100644 --- a/libs/service/service.go +++ b/libs/service/service.go @@ -136,7 +136,11 @@ func (bs *BaseService) Start() error { atomic.StoreUint32(&bs.started, 0) return ErrAlreadyStopped } - bs.Logger.Info(fmt.Sprintf("Starting %v service", bs.name), "impl", bs.impl.String()) + bs.Logger.Info("service start", + "msg", + log.NewLazySprintf("Starting %v service", bs.name), + "impl", + bs.impl.String()) err := bs.impl.OnStart() if err != nil { // revert flag @@ -145,7 +149,11 @@ func (bs *BaseService) Start() error { } return nil } - bs.Logger.Debug(fmt.Sprintf("Not starting %v service -- already started", bs.name), "impl", bs.impl) + bs.Logger.Debug("service start", + "msg", + log.NewLazySprintf("Not starting %v service -- already started", bs.name), + "impl", + bs.impl) return ErrAlreadyStarted } @@ -165,12 +173,20 @@ func (bs *BaseService) Stop() error { atomic.StoreUint32(&bs.stopped, 0) return ErrNotStarted } - bs.Logger.Info(fmt.Sprintf("Stopping %v service", bs.name), "impl", bs.impl) + bs.Logger.Info("service stop", + "msg", + log.NewLazySprintf("Stopping %v service", bs.name), + "impl", + bs.impl) bs.impl.OnStop() close(bs.quit) return nil } - bs.Logger.Debug(fmt.Sprintf("Stopping %v service (already stopped)", bs.name), "impl", bs.impl) + bs.Logger.Debug("service stop", + "msg", + log.NewLazySprintf("Stopping %v service (already stopped)", bs.name), + "impl", + bs.impl) return ErrAlreadyStopped } @@ -183,7 +199,11 @@ func (bs *BaseService) OnStop() {} // will be returned if the service is running. func (bs *BaseService) Reset() error { if !atomic.CompareAndSwapUint32(&bs.stopped, 1, 0) { - bs.Logger.Debug(fmt.Sprintf("Can't reset %v service. Not stopped", bs.name), "impl", bs.impl) + bs.Logger.Debug("service reset", + "msg", + log.NewLazySprintf("Can't reset %v service. Not stopped", bs.name), + "impl", + bs.impl) return fmt.Errorf("can't reset running %s", bs.name) } diff --git a/p2p/conn/connection.go b/p2p/conn/connection.go index dfbd76f0a..44ff83893 100644 --- a/p2p/conn/connection.go +++ b/p2p/conn/connection.go @@ -352,7 +352,7 @@ func (c *MConnection) Send(chID byte, msgBytes []byte) bool { return false } - c.Logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes)) + c.Logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes)) // Send message to channel. channel, ok := c.channelsIdx[chID] @@ -369,7 +369,7 @@ func (c *MConnection) Send(chID byte, msgBytes []byte) bool { default: } } else { - c.Logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes)) + c.Logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes)) } return success } @@ -381,7 +381,7 @@ func (c *MConnection) TrySend(chID byte, msgBytes []byte) bool { return false } - c.Logger.Debug("TrySend", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes)) + c.Logger.Debug("TrySend", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes)) // Send message to channel. channel, ok := c.channelsIdx[chID] diff --git a/p2p/pex/addrbook.go b/p2p/pex/addrbook.go index 76b21e8dc..95936a43c 100644 --- a/p2p/pex/addrbook.go +++ b/p2p/pex/addrbook.go @@ -17,6 +17,7 @@ import ( "github.com/minio/highwayhash" "github.com/tendermint/tendermint/crypto" + "github.com/tendermint/tendermint/libs/log" tmmath "github.com/tendermint/tendermint/libs/math" tmrand "github.com/tendermint/tendermint/libs/rand" "github.com/tendermint/tendermint/libs/service" @@ -739,7 +740,7 @@ func (a *addrBook) expireNew(bucketIdx int) { for addrStr, ka := range a.bucketsNew[bucketIdx] { // If an entry is bad, throw it away if ka.isBad() { - a.Logger.Info(fmt.Sprintf("expiring bad address %v", addrStr)) + a.Logger.Info("expire new", "msg", log.NewLazySprintf("expiring bad address %v", addrStr)) a.removeFromBucket(ka, bucketTypeNew, bucketIdx) return } diff --git a/p2p/switch.go b/p2p/switch.go index f4f335b32..fa87cbccd 100644 --- a/p2p/switch.go +++ b/p2p/switch.go @@ -8,6 +8,7 @@ import ( "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/libs/cmap" + "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/rand" "github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/p2p/conn" @@ -261,7 +262,7 @@ func (sw *Switch) OnStop() { // // NOTE: Broadcast uses goroutines, so order of broadcast may not be preserved. func (sw *Switch) Broadcast(chID byte, msgBytes []byte) chan bool { - sw.Logger.Debug("Broadcast", "channel", chID, "msgBytes", fmt.Sprintf("%X", msgBytes)) + sw.Logger.Debug("Broadcast", "channel", chID, "msgBytes", log.NewLazySprintf("%X", msgBytes)) peers := sw.peers.List() var wg sync.WaitGroup diff --git a/p2p/upnp/probe.go b/p2p/upnp/probe.go index ae641abbb..00047dac2 100644 --- a/p2p/upnp/probe.go +++ b/p2p/upnp/probe.go @@ -18,19 +18,19 @@ func makeUPNPListener(intPort int, extPort int, logger log.Logger) (NAT, net.Lis if err != nil { return nil, nil, nil, fmt.Errorf("nat upnp could not be discovered: %v", err) } - logger.Info(fmt.Sprintf("ourIP: %v", nat.(*upnpNAT).ourIP)) + logger.Info("make upnp listener", "msg", log.NewLazySprintf("ourIP: %v", nat.(*upnpNAT).ourIP)) ext, err := nat.GetExternalAddress() if err != nil { return nat, nil, nil, fmt.Errorf("external address error: %v", err) } - logger.Info(fmt.Sprintf("External address: %v", ext)) + logger.Info("make upnp listener", "msg", log.NewLazySprintf("External address: %v", ext)) port, err := nat.AddPortMapping("tcp", extPort, intPort, "Tendermint UPnP Probe", 0) if err != nil { return nat, nil, ext, fmt.Errorf("port mapping error: %v", err) } - logger.Info(fmt.Sprintf("Port mapping mapped: %v", port)) + logger.Info("make upnp listener", "msg", log.NewLazySprintf("Port mapping mapped: %v", port)) // also run the listener, open for all remote addresses. listener, err := net.Listen("tcp", fmt.Sprintf(":%v", intPort)) @@ -45,17 +45,23 @@ func testHairpin(listener net.Listener, extAddr string, logger log.Logger) (supp go func() { inConn, err := listener.Accept() if err != nil { - logger.Info(fmt.Sprintf("Listener.Accept() error: %v", err)) + logger.Info("test hair pin", "msg", log.NewLazySprintf("Listener.Accept() error: %v", err)) return } - logger.Info(fmt.Sprintf("Accepted incoming connection: %v -> %v", inConn.LocalAddr(), inConn.RemoteAddr())) + logger.Info("test hair pin", + "msg", + log.NewLazySprintf("Accepted incoming connection: %v -> %v", inConn.LocalAddr(), inConn.RemoteAddr())) buf := make([]byte, 1024) n, err := inConn.Read(buf) if err != nil { - logger.Info(fmt.Sprintf("Incoming connection read error: %v", err)) + logger.Info("test hair pin", + "msg", + log.NewLazySprintf("Incoming connection read error: %v", err)) return } - logger.Info(fmt.Sprintf("Incoming connection read %v bytes: %X", n, buf)) + logger.Info("test hair pin", + "msg", + log.NewLazySprintf("Incoming connection read %v bytes: %X", n, buf)) if string(buf) == "test data" { supportsHairpin = true return @@ -65,16 +71,16 @@ func testHairpin(listener net.Listener, extAddr string, logger log.Logger) (supp // Establish outgoing outConn, err := net.Dial("tcp", extAddr) if err != nil { - logger.Info(fmt.Sprintf("Outgoing connection dial error: %v", err)) + logger.Info("test hair pin", "msg", log.NewLazySprintf("Outgoing connection dial error: %v", err)) return } n, err := outConn.Write([]byte("test data")) if err != nil { - logger.Info(fmt.Sprintf("Outgoing connection write error: %v", err)) + logger.Info("test hair pin", "msg", log.NewLazySprintf("Outgoing connection write error: %v", err)) return } - logger.Info(fmt.Sprintf("Outgoing connection wrote %v bytes", n)) + logger.Info("test hair pin", "msg", log.NewLazySprintf("Outgoing connection wrote %v bytes", n)) // Wait for data receipt time.Sleep(1 * time.Second) diff --git a/rpc/jsonrpc/client/ws_client.go b/rpc/jsonrpc/client/ws_client.go index 1c7ade657..44bf5f098 100644 --- a/rpc/jsonrpc/client/ws_client.go +++ b/rpc/jsonrpc/client/ws_client.go @@ -12,6 +12,7 @@ import ( "github.com/gorilla/websocket" metrics "github.com/rcrowley/go-metrics" + "github.com/tendermint/tendermint/libs/log" tmrand "github.com/tendermint/tendermint/libs/rand" "github.com/tendermint/tendermint/libs/service" tmsync "github.com/tendermint/tendermint/libs/sync" @@ -511,7 +512,7 @@ func (c *WSClient) readRoutine() { // c.wg.Wait() in c.Stop(). Note we rely on Quit being closed so that it sends unlimited Quit signals to stop // both readRoutine and writeRoutine - c.Logger.Info("got response", "id", response.ID, "result", fmt.Sprintf("%X", response.Result)) + c.Logger.Info("got response", "id", response.ID, "result", log.NewLazySprintf("%X", response.Result)) select { case <-c.Quit(): diff --git a/rpc/jsonrpc/server/http_server.go b/rpc/jsonrpc/server/http_server.go index bc9785dea..f653e6cc6 100644 --- a/rpc/jsonrpc/server/http_server.go +++ b/rpc/jsonrpc/server/http_server.go @@ -51,7 +51,7 @@ func DefaultConfig() *Config { // // NOTE: This function blocks - you may want to call it in a go-routine. func Serve(listener net.Listener, handler http.Handler, logger log.Logger, config *Config) error { - logger.Info(fmt.Sprintf("Starting RPC HTTP server on %s", listener.Addr())) + logger.Info("serve", "msg", log.NewLazySprintf("Starting RPC HTTP server on %s", listener.Addr())) s := &http.Server{ Handler: RecoverAndLogHandler(maxBytesHandler{h: handler, n: config.MaxBodyBytes}, logger), ReadTimeout: config.ReadTimeout, @@ -75,7 +75,7 @@ func ServeTLS( logger log.Logger, config *Config, ) error { - logger.Info(fmt.Sprintf("Starting RPC HTTPS server on %s (cert: %q, key: %q)", + logger.Info("serve tls", "msg", log.NewLazySprintf("Starting RPC HTTPS server on %s (cert: %q, key: %q)", listener.Addr(), certFile, keyFile)) s := &http.Server{ Handler: RecoverAndLogHandler(maxBytesHandler{h: handler, n: config.MaxBodyBytes}, logger), diff --git a/statesync/syncer.go b/statesync/syncer.go index 115b98749..e4c02988b 100644 --- a/statesync/syncer.go +++ b/statesync/syncer.go @@ -144,7 +144,7 @@ func (s *syncer) SyncAny(discoveryTime time.Duration, retryHook func()) (sm.Stat } if discoveryTime > 0 { - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) + s.logger.Info("sync any", "msg", log.NewLazySprintf("Discovering snapshots for %v", discoveryTime)) time.Sleep(discoveryTime) } @@ -166,7 +166,7 @@ func (s *syncer) SyncAny(discoveryTime time.Duration, retryHook func()) (sm.Stat return sm.State{}, nil, errNoSnapshots } retryHook() - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) + s.logger.Info("sync any", "msg", log.NewLazySprintf("Discovering snapshots for %v", discoveryTime)) time.Sleep(discoveryTime) continue } diff --git a/test/e2e/node/main.go b/test/e2e/node/main.go index b7dbd96e9..b109d5397 100644 --- a/test/e2e/node/main.go +++ b/test/e2e/node/main.go @@ -111,7 +111,7 @@ func startApp(cfg *Config) error { if err != nil { return err } - logger.Info(fmt.Sprintf("Server listening on %v (%v protocol)", cfg.Listen, cfg.Protocol)) + logger.Info("start app", "msg", log.NewLazySprintf("Server listening on %v (%v protocol)", cfg.Listen, cfg.Protocol)) return nil } @@ -261,7 +261,7 @@ func startSigner(cfg *Config) error { if err != nil { return err } - logger.Info(fmt.Sprintf("Remote signer connecting to %v", cfg.PrivValServer)) + logger.Info("start signer", "msg", log.NewLazySprintf("Remote signer connecting to %v", cfg.PrivValServer)) return nil } diff --git a/test/e2e/runner/cleanup.go b/test/e2e/runner/cleanup.go index d99ca54cf..fbe7aa0b4 100644 --- a/test/e2e/runner/cleanup.go +++ b/test/e2e/runner/cleanup.go @@ -6,6 +6,7 @@ import ( "os" "path/filepath" + "github.com/tendermint/tendermint/libs/log" e2e "github.com/tendermint/tendermint/test/e2e/pkg" ) @@ -59,7 +60,7 @@ func cleanupDir(dir string) error { return err } - logger.Info(fmt.Sprintf("Removing testnet directory %q", dir)) + logger.Info("cleanup dir", "msg", log.NewLazySprintf("Removing testnet directory %q", dir)) // On Linux, some local files in the volume will be owned by root since Tendermint // runs as root inside the container, so we need to clean them up from within a diff --git a/test/e2e/runner/load.go b/test/e2e/runner/load.go index 4e1a6ebba..5f6d1e1ba 100644 --- a/test/e2e/runner/load.go +++ b/test/e2e/runner/load.go @@ -8,6 +8,7 @@ import ( "math" "time" + "github.com/tendermint/tendermint/libs/log" rpchttp "github.com/tendermint/tendermint/rpc/client/http" e2e "github.com/tendermint/tendermint/test/e2e/pkg" "github.com/tendermint/tendermint/types" @@ -35,7 +36,7 @@ func Load(ctx context.Context, testnet *e2e.Testnet, multiplier int) error { defer cancel() // Spawn job generator and processors. - logger.Info(fmt.Sprintf("Starting transaction load (%v workers)...", concurrency)) + logger.Info("load", "msg", log.NewLazySprintf("Starting transaction load (%v workers)...", concurrency)) started := time.Now() go loadGenerate(ctx, chTx, multiplier) @@ -58,7 +59,7 @@ func Load(ctx context.Context, testnet *e2e.Testnet, multiplier int) error { if success == 0 { return errors.New("failed to submit any transactions") } - logger.Info(fmt.Sprintf("Ending transaction load after %v txs (%.1f tx/s)...", + logger.Info("load", "msg", log.NewLazySprintf("Ending transaction load after %v txs (%.1f tx/s)...", success, float64(success)/time.Since(started).Seconds())) return nil } diff --git a/test/e2e/runner/perturb.go b/test/e2e/runner/perturb.go index 46019ef23..f47aa72bf 100644 --- a/test/e2e/runner/perturb.go +++ b/test/e2e/runner/perturb.go @@ -4,6 +4,7 @@ import ( "fmt" "time" + "github.com/tendermint/tendermint/libs/log" rpctypes "github.com/tendermint/tendermint/rpc/core/types" e2e "github.com/tendermint/tendermint/test/e2e/pkg" ) @@ -28,7 +29,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul testnet := node.Testnet switch perturbation { case e2e.PerturbationDisconnect: - logger.Info(fmt.Sprintf("Disconnecting node %v...", node.Name)) + logger.Info("perturb node", "msg", log.NewLazySprintf("Disconnecting node %v...", node.Name)) if err := execDocker("network", "disconnect", testnet.Name+"_"+testnet.Name, node.Name); err != nil { return nil, err } @@ -38,7 +39,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul } case e2e.PerturbationKill: - logger.Info(fmt.Sprintf("Killing node %v...", node.Name)) + logger.Info("perturb node", "msg", log.NewLazySprintf("Killing node %v...", node.Name)) if err := execCompose(testnet.Dir, "kill", "-s", "SIGKILL", node.Name); err != nil { return nil, err } @@ -47,7 +48,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul } case e2e.PerturbationPause: - logger.Info(fmt.Sprintf("Pausing node %v...", node.Name)) + logger.Info("perturb node", "msg", log.NewLazySprintf("Pausing node %v...", node.Name)) if err := execCompose(testnet.Dir, "pause", node.Name); err != nil { return nil, err } @@ -57,7 +58,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul } case e2e.PerturbationRestart: - logger.Info(fmt.Sprintf("Restarting node %v...", node.Name)) + logger.Info("perturb node", "msg", log.NewLazySprintf("Restarting node %v...", node.Name)) if err := execCompose(testnet.Dir, "restart", node.Name); err != nil { return nil, err } @@ -70,6 +71,8 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul if err != nil { return nil, err } - logger.Info(fmt.Sprintf("Node %v recovered at height %v", node.Name, status.SyncInfo.LatestBlockHeight)) + logger.Info("perturb node", + "msg", + log.NewLazySprintf("Node %v recovered at height %v", node.Name, status.SyncInfo.LatestBlockHeight)) return status, nil } diff --git a/test/e2e/runner/setup.go b/test/e2e/runner/setup.go index e1c82d589..34155f225 100644 --- a/test/e2e/runner/setup.go +++ b/test/e2e/runner/setup.go @@ -21,6 +21,7 @@ import ( "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/crypto/ed25519" + "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/p2p" "github.com/tendermint/tendermint/privval" e2e "github.com/tendermint/tendermint/test/e2e/pkg" @@ -41,7 +42,7 @@ const ( // Setup sets up the testnet configuration. func Setup(testnet *e2e.Testnet) error { - logger.Info(fmt.Sprintf("Generating testnet files in %q", testnet.Dir)) + logger.Info("setup", "msg", log.NewLazySprintf("Generating testnet files in %q", testnet.Dir)) err := os.MkdirAll(testnet.Dir, os.ModePerm) if err != nil { diff --git a/test/e2e/runner/start.go b/test/e2e/runner/start.go index 9a612d147..0dab98f22 100644 --- a/test/e2e/runner/start.go +++ b/test/e2e/runner/start.go @@ -5,6 +5,7 @@ import ( "sort" "time" + "github.com/tendermint/tendermint/libs/log" e2e "github.com/tendermint/tendermint/test/e2e/pkg" ) @@ -48,7 +49,7 @@ func Start(testnet *e2e.Testnet) error { if _, err := waitForNode(node, 0, 15*time.Second); err != nil { return err } - logger.Info(fmt.Sprintf("Node %v up on http://127.0.0.1:%v", node.Name, node.ProxyPort)) + logger.Info("start", "msg", log.NewLazySprintf("Node %v up on http://127.0.0.1:%v", node.Name, node.ProxyPort)) } networkHeight := testnet.InitialHeight @@ -103,7 +104,7 @@ func Start(testnet *e2e.Testnet) error { if err != nil { return err } - logger.Info(fmt.Sprintf("Node %v up on http://127.0.0.1:%v at height %v", + logger.Info("start", "msg", log.NewLazySprintf("Node %v up on http://127.0.0.1:%v at height %v", node.Name, node.ProxyPort, status.SyncInfo.LatestBlockHeight)) } diff --git a/test/e2e/runner/wait.go b/test/e2e/runner/wait.go index 232d230d9..d89a8baac 100644 --- a/test/e2e/runner/wait.go +++ b/test/e2e/runner/wait.go @@ -1,9 +1,9 @@ package main import ( - "fmt" "time" + "github.com/tendermint/tendermint/libs/log" e2e "github.com/tendermint/tendermint/test/e2e/pkg" ) @@ -19,7 +19,7 @@ func Wait(testnet *e2e.Testnet, blocks int64) error { // WaitUntil waits until a given height has been reached. func WaitUntil(testnet *e2e.Testnet, height int64) error { - logger.Info(fmt.Sprintf("Waiting for all nodes to reach height %v...", height)) + logger.Info("wait until", "msg", log.NewLazySprintf("Waiting for all nodes to reach height %v...", height)) _, err := waitForAllNodes(testnet, height, waitingTime(len(testnet.Nodes))) if err != nil { return err diff --git a/test/maverick/consensus/misbehavior.go b/test/maverick/consensus/misbehavior.go index db4f072ea..e8fe42f1d 100644 --- a/test/maverick/consensus/misbehavior.go +++ b/test/maverick/consensus/misbehavior.go @@ -5,6 +5,7 @@ import ( tmcon "github.com/tendermint/tendermint/consensus" cstypes "github.com/tendermint/tendermint/consensus/types" + "github.com/tendermint/tendermint/libs/log" tmproto "github.com/tendermint/tendermint/proto/tendermint/types" "github.com/tendermint/tendermint/types" ) @@ -300,7 +301,7 @@ func defaultReceivePrevote(cs *State, vote *types.Vote) { } else { cs.Logger.Info( "valid block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), + "proposal", log.NewLazyBlockHash(cs.ProposalBlock), "blockID", blockID.Hash, ) diff --git a/test/maverick/consensus/state.go b/test/maverick/consensus/state.go index e4ff82793..e67868214 100644 --- a/test/maverick/consensus/state.go +++ b/test/maverick/consensus/state.go @@ -242,7 +242,7 @@ func (cs *State) enterPropose(height int64, round int32) { logger := cs.Logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) { - logger.Debug(fmt.Sprintf( + logger.Debug("enter propose", "msg", log.NewLazySprintf( "enterPropose(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, @@ -251,7 +251,9 @@ func (cs *State) enterPropose(height int64, round int32) { cs.Step)) return } - logger.Info(fmt.Sprintf("enterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Info("enter propose", + "msg", + log.NewLazySprintf("enterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPropose: @@ -279,7 +281,7 @@ func (cs *State) enterPropose(height int64, round int32) { // Otherwise vote nil. func (cs *State) enterPrevote(height int64, round int32) { if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) { - cs.Logger.Debug(fmt.Sprintf( + cs.Logger.Debug("enter prevote", "msg", log.NewLazySprintf( "enterPrevote(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, @@ -295,7 +297,9 @@ func (cs *State) enterPrevote(height int64, round int32) { cs.newStep() }() - cs.Logger.Debug(fmt.Sprintf("enterPrevote(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + cs.Logger.Debug("enter prevote", + "msg", + log.NewLazySprintf("enterPrevote(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) // Sign and broadcast vote as necessary if b, ok := cs.misbehaviors[cs.Height]; ok { @@ -318,17 +322,20 @@ func (cs *State) enterPrecommit(height int64, round int32) { logger := cs.Logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) { - logger.Debug(fmt.Sprintf( - "enterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v", - height, - round, - cs.Height, - cs.Round, - cs.Step)) + logger.Debug("enter precommit", + "msg", + log.NewLazySprintf("enterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v", + height, + round, + cs.Height, + cs.Round, + cs.Step)) return } - logger.Info(fmt.Sprintf("enterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Info("enter precommit", + "msg", + log.NewLazySprintf("enterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommit: @@ -372,7 +379,9 @@ func (cs *State) addVote( return } - cs.Logger.Info(fmt.Sprintf("Added to lastPrecommits: %v", cs.LastCommit.StringShort())) + cs.Logger.Info("add vote", + "msg", + log.NewLazySprintf("Added to lastPrecommits: %v", cs.LastCommit.StringShort())) _ = cs.eventBus.PublishEventVote(types.EventDataVote{Vote: vote}) cs.evsw.FireEvent(types.EventVote, vote) @@ -1103,7 +1112,7 @@ func (cs *State) enterNewRound(height int64, round int32) { logger := cs.Logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) { - logger.Debug(fmt.Sprintf( + logger.Debug("enter new round", "msg", log.NewLazySprintf( "enterNewRound(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, @@ -1117,7 +1126,9 @@ func (cs *State) enterNewRound(height int64, round int32) { logger.Debug("need to set a buffer and log message here for sanity", "startTime", cs.StartTime, "now", now) } - logger.Info(fmt.Sprintf("enterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Info("enter new round", + "msg", + log.NewLazySprintf("enterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) // Increment validators if necessary validators := cs.Validators @@ -1217,7 +1228,9 @@ func (cs *State) defaultDecideProposal(height int64, round int32) { cs.sendInternalMessage(msgInfo{&tmcon.BlockPartMessage{Height: cs.Height, Round: cs.Round, Part: part}, ""}) } cs.Logger.Info("Signed proposal", "height", height, "round", round, "proposal", proposal) - cs.Logger.Debug(fmt.Sprintf("Signed proposal block: %v", block)) + cs.Logger.Debug("default decide proposal", + "msg", + log.NewLazySprintf("Signed proposal block: %v", block)) } else if !cs.replayMode { cs.Logger.Error("enterPropose: Error signing proposal", "height", height, "round", round, "err", err) } @@ -1281,20 +1294,24 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { logger := cs.Logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) { - logger.Debug(fmt.Sprintf( - "enterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v", - height, - round, - cs.Height, - cs.Round, - cs.Step)) + logger.Debug("enter prevote wait", + "msg", + log.NewLazySprintf( + "enterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v", + height, + round, + cs.Height, + cs.Round, + cs.Step)) return } if !cs.Votes.Prevotes(round).HasTwoThirdsAny() { panic(fmt.Sprintf("enterPrevoteWait(%v/%v), but Prevotes does not have any +2/3 votes", height, round)) } - logger.Debug(fmt.Sprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Debug("enter prevote wait", + "msg", + log.NewLazySprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrevoteWait: @@ -1311,8 +1328,9 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { logger := cs.Logger.With("height", height, "round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) { - logger.Debug( - fmt.Sprintf( + logger.Debug("state enter precommit wait", + "msg", + log.NewLazySprintf( "enterPrecommitWait(%v/%v): Invalid args. "+ "Current state is Height/Round: %v/%v/, TriggeredTimeoutPrecommit:%v", height, round, cs.Height, cs.Round, cs.TriggeredTimeoutPrecommit)) @@ -1321,7 +1339,9 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { if !cs.Votes.Precommits(round).HasTwoThirdsAny() { panic(fmt.Sprintf("enterPrecommitWait(%v/%v), but Precommits does not have any +2/3 votes", height, round)) } - logger.Info(fmt.Sprintf("enterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Info("enter precommit wait", + "msg", + log.NewLazySprintf("enterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommitWait: @@ -1338,16 +1358,19 @@ func (cs *State) enterCommit(height int64, commitRound int32) { logger := cs.Logger.With("height", height, "commitRound", commitRound) if cs.Height != height || cstypes.RoundStepCommit <= cs.Step { - logger.Debug(fmt.Sprintf( - "enterCommit(%v/%v): Invalid args. Current step: %v/%v/%v", - height, - commitRound, - cs.Height, - cs.Round, - cs.Step)) + logger.Debug("enter commit", + "msg", + log.NewLazySprintf("enterCommit(%v/%v): Invalid args. Current step: %v/%v/%v", + height, + commitRound, + cs.Height, + cs.Round, + cs.Step)) return } - logger.Info(fmt.Sprintf("enterCommit(%v/%v). Current: %v/%v/%v", height, commitRound, cs.Height, cs.Round, cs.Step)) + logger.Info("enter commit", + "msg", + log.NewLazySprintf("enterCommit(%v/%v). Current: %v/%v/%v", height, commitRound, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterCommit: @@ -1380,7 +1403,7 @@ func (cs *State) enterCommit(height int64, commitRound int32) { if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) { logger.Info( "commit is for a block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), + "proposal", log.NewLazyBlockHash(cs.ProposalBlock), "commit", blockID.Hash, ) @@ -1417,7 +1440,7 @@ func (cs *State) tryFinalizeCommit(height int64) { // TODO: ^^ wait, why does it matter that we're a validator? logger.Debug( "attempt to finalize failed; we do not have the commit block", - "proposal-block", cs.ProposalBlock.Hash(), + "proposal-block", log.NewLazyBlockHash(cs.ProposalBlock), "commit-block", blockID.Hash, ) return @@ -1430,12 +1453,13 @@ func (cs *State) tryFinalizeCommit(height int64) { // Increment height and goto cstypes.RoundStepNewHeight func (cs *State) finalizeCommit(height int64) { if cs.Height != height || cs.Step != cstypes.RoundStepCommit { - cs.Logger.Debug(fmt.Sprintf( - "finalizeCommit(%v): Invalid args. Current step: %v/%v/%v", - height, - cs.Height, - cs.Round, - cs.Step)) + cs.Logger.Debug("finalize commit", + "msg", + log.NewLazySprintf("finalizeCommit(%v): Invalid args. Current step: %v/%v/%v", + height, + cs.Height, + cs.Round, + cs.Step)) return } @@ -1461,7 +1485,7 @@ func (cs *State) finalizeCommit(height int64) { "root", block.AppHash, "N", len(block.Txs), ) - cs.Logger.Debug(fmt.Sprintf("%v", block)) + cs.Logger.Debug("finalize commit", "msg", log.NewLazySprintf("%v", block)) fail.Fail() // XXX