From 6a9a37f9e9eb07bd8700b417839e84c80ee47da4 Mon Sep 17 00:00:00 2001 From: Kayhan Alizadeh Date: Sun, 8 Oct 2023 16:40:36 +0330 Subject: [PATCH] feat(logger): short stringer for loggers (#732) --- consensus/commit.go | 2 +- consensus/cp_mainvote.go | 4 ++-- consensus/precommit.go | 4 ++-- consensus/prepare.go | 2 +- consensus/propose.go | 4 ++-- network/gossip.go | 2 +- network/notifee.go | 6 +++--- network/stream.go | 12 ++++++------ state/state.go | 2 +- sync/firewall/firewall.go | 2 +- sync/handler_blocks_request.go | 4 ++-- sync/handler_blocks_response.go | 4 ++-- sync/handler_hello.go | 6 +++--- sync/handler_hello_ack.go | 4 ++-- sync/sync.go | 16 ++++++++-------- types/tx/payload/bond.go | 4 ++-- types/tx/payload/bond_test.go | 4 ++-- types/tx/payload/sortition.go | 2 +- types/tx/payload/sortition_test.go | 2 +- types/tx/payload/transfer.go | 4 ++-- types/tx/payload/transfer_test.go | 4 ++-- types/tx/payload/withdraw.go | 4 ++-- types/tx/tx_test.go | 2 +- util/logger/logger.go | 10 ++++++++++ util/logger/logger_test.go | 23 +++++++++++++++++++++++ 25 files changed, 83 insertions(+), 50 deletions(-) diff --git a/consensus/commit.go b/consensus/commit.go index 4bb924bfa..eb8e51b41 100644 --- a/consensus/commit.go +++ b/consensus/commit.go @@ -23,7 +23,7 @@ func (s *commitState) decide() { if err != nil { s.logger.Error("committing block failed", "block", certBlock, "error", err) } else { - s.logger.Info("block committed, schedule new height", "hash", certBlock.Hash().ShortString()) + s.logger.Info("block committed, schedule new height", "hash", certBlock.Hash()) } // Now we can announce the committed block and certificate diff --git a/consensus/cp_mainvote.go b/consensus/cp_mainvote.go index 6b060e67a..3b7141e3a 100644 --- a/consensus/cp_mainvote.go +++ b/consensus/cp_mainvote.go @@ -76,8 +76,8 @@ func (s *cpMainVoteState) detectByzantineProposal() { if roundProposal != nil && roundProposal.Block().Hash() != *s.cpWeakValidity { s.logger.Warn("double proposal detected", - "prepared", s.cpWeakValidity.ShortString(), - "roundProposal", roundProposal.Block().Hash().ShortString()) + "prepared", s.cpWeakValidity, + "roundProposal", roundProposal.Block().Hash()) s.log.SetRoundProposal(s.round, nil) s.queryProposal() diff --git a/consensus/precommit.go b/consensus/precommit.go index d97ac8310..df21f4815 100644 --- a/consensus/precommit.go +++ b/consensus/precommit.go @@ -22,13 +22,13 @@ func (s *precommitState) decide() { precommits := s.log.PrecommitVoteSet(s.round) precommitQH := precommits.QuorumHash() if precommitQH != nil { - s.logger.Debug("pre-commit has quorum", "hash", precommitQH.ShortString()) + s.logger.Debug("pre-commit has quorum", "hash", precommitQH) roundProposal := s.log.RoundProposal(s.round) if roundProposal == nil { // There is a consensus about a proposal that we don't have yet. // Ask peers for this proposal. - s.logger.Info("query for a decided proposal", "hash", precommitQH.ShortString()) + s.logger.Info("query for a decided proposal", "hash", precommitQH) s.queryProposal() } else { // To ensure we have voted and won't be absent from the certificate diff --git a/consensus/prepare.go b/consensus/prepare.go index 7ef93aec6..ea96c4be8 100644 --- a/consensus/prepare.go +++ b/consensus/prepare.go @@ -27,7 +27,7 @@ func (s *prepareState) decide() { prepares := s.log.PrepareVoteSet(s.round) prepareQH := prepares.QuorumHash() if prepareQH != nil { - s.logger.Debug("prepare has quorum", "hash", prepareQH.ShortString()) + s.logger.Debug("prepare has quorum", "hash", prepareQH) s.enterNewState(s.precommitState) } else { // diff --git a/consensus/propose.go b/consensus/propose.go index 615f2b6d5..f12f838e2 100644 --- a/consensus/propose.go +++ b/consensus/propose.go @@ -16,10 +16,10 @@ func (s *proposeState) enter() { func (s *proposeState) decide() { proposer := s.proposer(s.round) if proposer.Address() == s.valKey.Address() { - s.logger.Info("our turn to propose", "proposer", proposer.Address().ShortString()) + s.logger.Info("our turn to propose", "proposer", proposer.Address()) s.createProposal(s.height, s.round) } else { - s.logger.Debug("not our turn to propose", "proposer", proposer.Address().ShortString()) + s.logger.Debug("not our turn to propose", "proposer", proposer.Address()) } s.cpRound = 0 diff --git a/network/gossip.go b/network/gossip.go index 3eb3f8e29..442d68ef4 100644 --- a/network/gossip.go +++ b/network/gossip.go @@ -101,7 +101,7 @@ func (g *gossipService) onReceiveMessage(m *lp2pps.Message) { } g.logger.Debug("receiving new gossip message", - "source", m.GetFrom().ShortString(), "from", m.ReceivedFrom.ShortString()) + "source", m.GetFrom(), "from", m.ReceivedFrom) event := &GossipMessage{ Source: m.GetFrom(), From: m.ReceivedFrom, diff --git a/network/notifee.go b/network/notifee.go index ebea700e2..3a638a1b5 100644 --- a/network/notifee.go +++ b/network/notifee.go @@ -39,20 +39,20 @@ func (n *NotifeeService) Connected(lp2pn lp2pnetwork.Network, conn lp2pnetwork.C protocols, _ := lp2pn.Peerstore().SupportsProtocols(peerID, n.protocolID) if len(protocols) > 0 { - n.logger.Info("connected to peer", "pid", peerID.ShortString()) + n.logger.Info("connected to peer", "pid", peerID) n.eventChannel <- &ConnectEvent{PeerID: peerID} return } } - n.logger.Info("this node doesn't support stream protocol", "pid", peerID.ShortString()) + n.logger.Info("this node doesn't support stream protocol", "pid", peerID) }() } func (n *NotifeeService) Disconnected(_ lp2pnetwork.Network, conn lp2pnetwork.Conn) { peerID := conn.RemotePeer() - n.logger.Info("disconnected from peer", "pid", peerID.ShortString()) + n.logger.Info("disconnected from peer", "pid", peerID) n.eventChannel <- &DisconnectEvent{PeerID: peerID} } diff --git a/network/stream.go b/network/stream.go index 06b4fd435..3c8acf880 100644 --- a/network/stream.go +++ b/network/stream.go @@ -47,7 +47,7 @@ func (s *streamService) Stop() { func (s *streamService) handleStream(stream lp2pnetwork.Stream) { from := stream.Conn().RemotePeer() - s.logger.Debug("receiving stream", "from", from.ShortString()) + s.logger.Debug("receiving stream", "from", from) event := &StreamMessage{ Source: from, Reader: stream, @@ -60,7 +60,7 @@ func (s *streamService) handleStream(stream lp2pnetwork.Stream) { // If a direct connection can't be established, it attempts to connect via a relay node. // Returns an error if the sending process fails. func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error { - s.logger.Trace("sending stream", "to", pid.ShortString()) + s.logger.Trace("sending stream", "to", pid) _, err := s.host.Peerstore().SupportsProtocols(pid, s.protocolID) if err != nil { return LibP2PError{Err: err} @@ -70,7 +70,7 @@ func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error { stream, err := s.host.NewStream( lp2pnetwork.WithNoDial(s.ctx, "should already have connection"), pid, s.protocolID) if err != nil { - s.logger.Debug("unable to open direct stream", "pid", pid.ShortString(), "error", err) + s.logger.Debug("unable to open direct stream", "pid", pid, "error", err) if len(s.relayAddrs) == 0 { return err } @@ -100,17 +100,17 @@ func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error { if err := s.host.Connect(s.ctx, unreachableRelayInfo); err != nil { // There is no relay connection to peer as well - s.logger.Warn("unable to connect to peer using relay", "pid", pid.ShortString(), "error", err) + s.logger.Warn("unable to connect to peer using relay", "pid", pid, "error", err) return LibP2PError{Err: err} } - s.logger.Debug("connected to peer using relay", "pid", pid.ShortString()) + s.logger.Debug("connected to peer using relay", "pid", pid) // Try to open a new stream to the target peer using the relay connection. // The connection is marked as transient. stream, err = s.host.NewStream( lp2pnetwork.WithUseTransient(s.ctx, string(s.protocolID)), pid, s.protocolID) if err != nil { - s.logger.Warn("unable to open relay stream", "pid", pid.ShortString(), "error", err) + s.logger.Warn("unable to open relay stream", "pid", pid, "error", err) return LibP2PError{Err: err} } } diff --git a/state/state.go b/state/state.go index 9c24f3e2e..c82689ffc 100644 --- a/state/state.go +++ b/state/state.go @@ -92,7 +92,7 @@ func LoadOrNewState( txPool.SetNewSandboxAndRecheck(st.concreteSandbox()) - st.logger.Debug("last info", "committers", st.committee.Committers(), "state_root", st.stateRoot().ShortString()) + st.logger.Debug("last info", "committers", st.committee.Committers(), "state_root", st.stateRoot()) return st, nil } diff --git a/sync/firewall/firewall.go b/sync/firewall/firewall.go index d5441cf96..f94509f80 100644 --- a/sync/firewall/firewall.go +++ b/sync/firewall/firewall.go @@ -40,7 +40,7 @@ func (f *Firewall) OpenGossipBundle(data []byte, source peer.ID, from peer.ID) * if from != source { f.peerSet.UpdateLastReceived(from) if f.isPeerBanned(from) { - f.logger.Warn("firewall: from peer banned", "from", from.ShortString()) + f.logger.Warn("firewall: from peer banned", "from", from) f.closeConnection(from) return nil } diff --git a/sync/handler_blocks_request.go b/sync/handler_blocks_request.go index 47ee6f298..4ce3adf8a 100644 --- a/sync/handler_blocks_request.go +++ b/sync/handler_blocks_request.go @@ -96,11 +96,11 @@ func (handler *blocksRequestHandler) PrepareBundle(m message.Message) *bundle.Bu func (handler *blocksRequestHandler) respond(msg *message.BlocksResponseMessage, to peer.ID) error { if msg.ResponseCode == message.ResponseCodeRejected { handler.logger.Error("rejecting block request message", "message", msg, - "to", to.ShortString(), "reason", msg.Reason) + "to", to, "reason", msg.Reason) handler.network.CloseConnection(to) } else { handler.logger.Info("responding block request message", "message", msg, - "to", to.ShortString()) + "to", to) } return handler.sendTo(msg, to) diff --git a/sync/handler_blocks_response.go b/sync/handler_blocks_response.go index cc772915d..df044cc65 100644 --- a/sync/handler_blocks_response.go +++ b/sync/handler_blocks_response.go @@ -22,7 +22,7 @@ func (handler *blocksResponseHandler) ParseMessage(m message.Message, initiator handler.logger.Trace("parsing BlocksResponse message", "message", msg) if msg.IsRequestRejected() { - handler.logger.Warn("blocks request is rejected", "pid", initiator.ShortString(), "reason", msg.Reason) + handler.logger.Warn("blocks request is rejected", "pid", initiator, "reason", msg.Reason) } else { // TODO: // It is good to check the latest height before adding blocks to the cache. @@ -67,7 +67,7 @@ func (handler *blocksResponseHandler) updateSession(sessionID int, pid peer.ID, if s.PeerID() != pid { // TODO: test me - handler.logger.Warn("unknown peer", "session-id", sessionID, "pid", pid.ShortString()) + handler.logger.Warn("unknown peer", "session-id", sessionID, "pid", pid) return } diff --git a/sync/handler_hello.go b/sync/handler_hello.go index 83518778d..6142ae371 100644 --- a/sync/handler_hello.go +++ b/sync/handler_hello.go @@ -54,7 +54,7 @@ func (handler *helloHandler) ParseMessage(m message.Message, initiator peer.ID) } handler.logger.Debug("updating peer info", - "pid", initiator.ShortString(), + "pid", initiator, "moniker", msg.Moniker, "services", msg.Services) @@ -76,10 +76,10 @@ func (handler *helloHandler) acknowledge(msg *message.HelloAckMessage, to peer.I handler.peerSet.UpdateStatus(to, peerset.StatusCodeBanned) handler.logger.Warn("rejecting hello message", "message", msg, - "to", to.ShortString(), "reason", msg.Reason) + "to", to, "reason", msg.Reason) } else { handler.logger.Info("acknowledging hello message", "message", msg, - "to", to.ShortString()) + "to", to) } return handler.sendTo(msg, to) diff --git a/sync/handler_hello_ack.go b/sync/handler_hello_ack.go index f6c4b3608..fe25306ef 100644 --- a/sync/handler_hello_ack.go +++ b/sync/handler_hello_ack.go @@ -24,14 +24,14 @@ func (handler *helloAckHandler) ParseMessage(m message.Message, initiator peer.I if msg.ResponseCode != message.ResponseCodeOK { handler.logger.Warn("hello message rejected", - "from", initiator.ShortString(), "reason", msg.Reason) + "from", initiator, "reason", msg.Reason) handler.network.CloseConnection(initiator) return nil } handler.peerSet.UpdateStatus(initiator, peerset.StatusCodeKnown) handler.logger.Debug("hello message acknowledged", - "from", initiator.ShortString()) + "from", initiator) return nil } diff --git a/sync/sync.go b/sync/sync.go index 38e720216..3d37705c5 100644 --- a/sync/sync.go +++ b/sync/sync.go @@ -140,7 +140,7 @@ func (sync *synchronizer) sayHello(to peer.ID) error { sync.peerSet.UpdateStatus(to, peerset.StatusCodeConnected) - sync.logger.Info("sending Hello message", "to", to.ShortString()) + sync.logger.Info("sending Hello message", "to", to) return sync.sendTo(msg, to) } @@ -171,7 +171,7 @@ func (sync *synchronizer) receiveLoop() { err := sync.processIncomingBundle(bdl) if err != nil { sync.logger.Warn("error on parsing a Gossip bundle", - "initiator", bdl.Initiator.ShortString(), "bundle", bdl, "error", err) + "initiator", bdl.Initiator, "bundle", bdl, "error", err) sync.peerSet.IncreaseInvalidBundlesCounter(bdl.Initiator) } @@ -185,14 +185,14 @@ func (sync *synchronizer) receiveLoop() { err := sync.processIncomingBundle(bdl) if err != nil { sync.logger.Warn("error on parsing a Stream bundle", - "initiator", bdl.Initiator.ShortString(), "bundle", bdl, "error", err) + "initiator", bdl.Initiator, "bundle", bdl, "error", err) sync.peerSet.IncreaseInvalidBundlesCounter(bdl.Initiator) } case network.EventTypeConnect: ce := e.(*network.ConnectEvent) if err := sync.sayHello(ce.PeerID); err != nil { sync.logger.Warn("sending Hello message failed", - "to", ce.PeerID.ShortString(), "error", err) + "to", ce.PeerID, "error", err) } case network.EventTypeDisconnect: de := e.(*network.DisconnectEvent) @@ -208,7 +208,7 @@ func (sync *synchronizer) processIncomingBundle(bdl *bundle.Bundle) error { } sync.logger.Info("received a bundle", - "initiator", bdl.Initiator.ShortString(), "bundle", bdl) + "initiator", bdl.Initiator, "bundle", bdl) h := sync.handlers[bdl.Message.Type()] if h == nil { return errors.Errorf(errors.ErrInvalidMessage, "invalid message type: %v", bdl.Message.Type()) @@ -298,12 +298,12 @@ func (sync *synchronizer) sendTo(msg message.Message, to peer.ID) error { err := sync.network.SendTo(data, to) if err != nil { sync.logger.Warn("error on sending bundle", - "bundle", bdl, "to", to.ShortString(), "error", err) + "bundle", bdl, "to", to, "error", err) return err } sync.logger.Info("sending bundle to a peer", - "bundle", bdl, "to", to.ShortString()) + "bundle", bdl, "to", to) } return nil } @@ -360,7 +360,7 @@ func (sync *synchronizer) downloadBlocks(from uint32, onlyNodeNetwork bool) { } count := LatestBlockInterval - sync.logger.Debug("sending download request", "from", from+1, "count", count, "pid", p.PeerID.ShortString()) + sync.logger.Debug("sending download request", "from", from+1, "count", count, "pid", p.PeerID) session := sync.peerSet.OpenSession(p.PeerID) msg := message.NewBlocksRequestMessage(session.SessionID(), from+1, count) err := sync.sendTo(msg, p.PeerID) diff --git a/types/tx/payload/bond.go b/types/tx/payload/bond.go index fdf745714..77944115b 100644 --- a/types/tx/payload/bond.go +++ b/types/tx/payload/bond.go @@ -31,13 +31,13 @@ func (p *BondPayload) Value() int64 { func (p *BondPayload) BasicCheck() error { if !p.From.IsAccountAddress() { return BasicCheckError{ - Reason: "sender is not an account address: " + p.From.ShortString(), + Reason: "sender is not an account address: " + p.From.String(), } } if !p.To.IsValidatorAddress() { return BasicCheckError{ - Reason: "receiver is not a validator address: " + p.To.ShortString(), + Reason: "receiver is not a validator address: " + p.To.String(), } } diff --git a/types/tx/payload/bond_test.go b/types/tx/payload/bond_test.go index 661bcbacf..232ba3219 100644 --- a/types/tx/payload/bond_test.go +++ b/types/tx/payload/bond_test.go @@ -93,7 +93,7 @@ func TestBondDecoding(t *testing.T) { value: 0x200000, readErr: nil, basicErr: BasicCheckError{ - Reason: "sender is not an account address: pc1pqgpsgpgx", + Reason: "sender is not an account address: pc1pqgpsgpgxquyqjzstpsxsurcszyfpx9q4vllmut", }, }, { @@ -110,7 +110,7 @@ func TestBondDecoding(t *testing.T) { value: 0x200000, readErr: nil, basicErr: BasicCheckError{ - Reason: "receiver is not a validator address: pc1zzgf3g9gk", + Reason: "receiver is not a validator address: pc1zzgf3g9gkzuvpjxsmrsw3u8eqyyfzxfp9yd9g68", }, }, { diff --git a/types/tx/payload/sortition.go b/types/tx/payload/sortition.go index a89093aa3..6eaf89550 100644 --- a/types/tx/payload/sortition.go +++ b/types/tx/payload/sortition.go @@ -29,7 +29,7 @@ func (p *SortitionPayload) Value() int64 { func (p *SortitionPayload) BasicCheck() error { if !p.Validator.IsValidatorAddress() { return BasicCheckError{ - Reason: "address is not a validator address: " + p.Validator.ShortString(), + Reason: "address is not a validator address: " + p.Validator.String(), } } diff --git a/types/tx/payload/sortition_test.go b/types/tx/payload/sortition_test.go index f1c161d94..9d0eacafa 100644 --- a/types/tx/payload/sortition_test.go +++ b/types/tx/payload/sortition_test.go @@ -84,7 +84,7 @@ func TestSortitionDecoding(t *testing.T) { value: 0, readErr: nil, basicErr: BasicCheckError{ - Reason: "address is not a validator address: pc1zqgpsgpgx", + Reason: "address is not a validator address: pc1zqgpsgpgxquyqjzstpsxsurcszyfpx9q4350xtk", }, }, } diff --git a/types/tx/payload/transfer.go b/types/tx/payload/transfer.go index 7a8726094..a39de21cf 100644 --- a/types/tx/payload/transfer.go +++ b/types/tx/payload/transfer.go @@ -29,12 +29,12 @@ func (p *TransferPayload) Value() int64 { func (p *TransferPayload) BasicCheck() error { if !p.From.IsAccountAddress() { return BasicCheckError{ - Reason: "sender is not an account address: " + p.From.ShortString(), + Reason: "sender is not an account address: " + p.From.String(), } } if !p.To.IsAccountAddress() { return BasicCheckError{ - Reason: "receiver is not an account address: " + p.To.ShortString(), + Reason: "receiver is not an account address: " + p.To.String(), } } return nil diff --git a/types/tx/payload/transfer_test.go b/types/tx/payload/transfer_test.go index ccc325bd8..f9c788549 100644 --- a/types/tx/payload/transfer_test.go +++ b/types/tx/payload/transfer_test.go @@ -73,7 +73,7 @@ func TestTransferDecoding(t *testing.T) { value: 0x200000, readErr: nil, basicErr: BasicCheckError{ - Reason: "sender is not an account address: pc1pqgpsgpgx", + Reason: "sender is not an account address: pc1pqgpsgpgxquyqjzstpsxsurcszyfpx9q4vllmut", }, }, { @@ -89,7 +89,7 @@ func TestTransferDecoding(t *testing.T) { value: 0x200000, readErr: nil, basicErr: BasicCheckError{ - Reason: "receiver is not an account address: pc1pzgf3g9gk", + Reason: "receiver is not an account address: pc1pzgf3g9gkzuvpjxsmrsw3u8eqyyfzxfp9ex44d6", }, }, { diff --git a/types/tx/payload/withdraw.go b/types/tx/payload/withdraw.go index 9b652551e..d2e3c9cd2 100644 --- a/types/tx/payload/withdraw.go +++ b/types/tx/payload/withdraw.go @@ -30,12 +30,12 @@ func (p *WithdrawPayload) Value() int64 { func (p *WithdrawPayload) BasicCheck() error { if !p.From.IsValidatorAddress() { return BasicCheckError{ - Reason: "sender is not a validator address: " + p.From.ShortString(), + Reason: "sender is not a validator address: " + p.From.String(), } } if !p.To.IsAccountAddress() { return BasicCheckError{ - Reason: "receiver is not an account address: " + p.To.ShortString(), + Reason: "receiver is not an account address: " + p.To.String(), } } diff --git a/types/tx/tx_test.go b/types/tx/tx_test.go index 416f2f957..cec685c79 100644 --- a/types/tx/tx_test.go +++ b/types/tx/tx_test.go @@ -119,7 +119,7 @@ func TestBasicCheck(t *testing.T) { err := trx.BasicCheck() assert.ErrorIs(t, err, tx.BasicCheckError{ - Reason: "invalid payload: receiver is not an account address: " + invAddr.ShortString(), + Reason: "invalid payload: receiver is not an account address: " + invAddr.String(), }) }) diff --git a/util/logger/logger.go b/util/logger/logger.go index 9ba4a5b58..3e3c9f988 100644 --- a/util/logger/logger.go +++ b/util/logger/logger.go @@ -13,6 +13,10 @@ import ( "gopkg.in/natefinch/lumberjack.v2" ) +type ShortStringer interface { + ShortString() string +} + var ( LogFilename = "pactus.log" MaxLogSize = 10 // 10MB to rotate a log file @@ -92,6 +96,12 @@ func addFields(event *zerolog.Event, keyvals ...interface{}) *zerolog.Event { } else { event.Stringer(key, v) } + case ShortStringer: + if isNil(v) { + event.Any(key, v) + } else { + event.Str(key, v.ShortString()) + } case error: event.AnErr(key, v) case []byte: diff --git a/util/logger/logger_test.go b/util/logger/logger_test.go index 9db9c4499..566cfbfc4 100644 --- a/util/logger/logger_test.go +++ b/util/logger/logger_test.go @@ -15,6 +15,12 @@ func (f Foo) String() string { return "foo" } +type Bar struct{} + +func (f Bar) ShortString() string { + return "bar" +} + func TestNilObjLogger(t *testing.T) { l := NewSubLogger("test", nil) var buf bytes.Buffer @@ -132,3 +138,20 @@ func TestInvalidLevel(t *testing.T) { assert.NotContains(t, out2, "error") assert.NotContains(t, out2, "message") } + +func TestShortStringer(t *testing.T) { + globalInst = nil + c := DefaultConfig() + c.Colorful = false + InitGlobalLogger(c) + + l := NewSubLogger("test", &Foo{}) + var buf bytes.Buffer + l.logger = l.logger.Output(&buf) + + l.Info("msg", "f", Bar{}) + + out := buf.String() + + assert.Contains(t, out, "bar") +}