sentry: less sprintf in logs (#6851)

This commit is contained in:
Alex Sharov 2023-02-12 18:23:58 +07:00 committed by GitHub
parent d5bb42453a
commit 80b375b074
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 34 additions and 33 deletions

View File

@ -572,10 +572,10 @@ func NewGrpcServer(ctx context.Context, dialCandidates func() enode.Iterator, re
peerID := peer.Pubkey()
printablePeerID := hex.EncodeToString(peerID[:])[:20]
if ss.getPeer(peerID) != nil {
log.Trace(fmt.Sprintf("[%s] Peer already has connection", printablePeerID))
log.Trace("[p2p] peer already has connection", "peerId", printablePeerID)
return nil
}
log.Debug(fmt.Sprintf("[%s] Start with peer", printablePeerID))
log.Debug("[p2p] start with peer", "peerId", printablePeerID)
peerInfo := NewPeerInfo(peer, rw)
peerInfo.protocol = protocol
@ -588,10 +588,10 @@ func NewGrpcServer(ctx context.Context, dialCandidates func() enode.Iterator, re
return ss.startSync(ctx, bestHash, peerID)
})
if err != nil {
log.Debug("Handshake failure", "peer", printablePeerID, "err", err)
return fmt.Errorf("handshake to peer %s: %w", printablePeerID, err)
log.Debug("[p2p] Handshake failure", "peer", printablePeerID, "err", err)
return fmt.Errorf("[p2p]handshake to peer %s: %w", printablePeerID, err)
}
log.Trace(fmt.Sprintf("[%s] Received status message OK", printablePeerID), "name", peer.Name())
log.Trace("[p2p] Received status message OK", "peerId", printablePeerID, "name", peer.Name())
err = runPeer(
ctx,
@ -602,7 +602,7 @@ func NewGrpcServer(ctx context.Context, dialCandidates func() enode.Iterator, re
ss.send,
ss.hasSubscribers,
) // runPeer never returns a nil error
log.Trace(fmt.Sprintf("[%s] Error while running peer: %v", printablePeerID, err))
log.Trace("[p2p] error while running peer", "peerId", printablePeerID, "err", err)
ss.sendGonePeerToClients(gointerfaces.ConvertHashToH512(peerID))
return nil
},
@ -746,7 +746,8 @@ func (ss *GrpcServer) PeerUseless(_ context.Context, req *proto_sentry.PeerUsele
peerInfo := ss.getPeer(peerID)
if ss.statusData != nil && peerInfo != nil && !peerInfo.peer.Info().Network.Static && !peerInfo.peer.Info().Network.Trusted {
ss.removePeer(peerID)
log.Debug("Removed useless peer", "peerId", fmt.Sprintf("%x", peerID)[:8], "name", peerInfo.peer.Name())
printablePeerID := hex.EncodeToString(peerID[:])[:]
log.Debug("[p2p] Removed useless peer", "peerId", printablePeerID, "name", peerInfo.peer.Name())
}
return &emptypb.Empty{}, nil
}

View File

@ -755,7 +755,7 @@ func (cs *MultiClient) HandlePeerEvent(ctx context.Context, event *proto_sentry.
peerIDStr := hex.EncodeToString(peerID[:])
if !cs.logPeerInfo {
log.Trace(fmt.Sprintf("Sentry peer did %s", eventID), "peer", peerIDStr)
log.Trace("[p2p] Sentry peer did", "eventID", eventID, "peer", peerIDStr)
return nil
}
@ -774,7 +774,7 @@ func (cs *MultiClient) HandlePeerEvent(ctx context.Context, event *proto_sentry.
}
}
log.Trace(fmt.Sprintf("Sentry peer did %s", eventID), "peer", peerIDStr,
log.Trace("[p2p] Sentry peer did", "eventID", eventID, "peer", peerIDStr,
"nodeURL", nodeURL, "clientID", clientID, "capabilities", capabilities)
return nil
}

View File

@ -102,7 +102,7 @@ func (hd *HeaderDownload) SingleHeaderAsSegment(headerRaw []byte, header *types.
headerHash := types.RawRlpHash(headerRaw)
if _, bad := hd.badHeaders[headerHash]; bad {
log.Warn("[Downloader] Rejected header marked as bad", "hash", headerHash, "height", header.Number.Uint64())
log.Warn("[downloader] Rejected header marked as bad", "hash", headerHash, "height", header.Number.Uint64())
return nil, BadBlockPenalty, nil
}
if penalizePoSBlocks && header.Difficulty.Sign() == 0 {
@ -300,7 +300,7 @@ func (hd *HeaderDownload) logAnchorState() {
ss = append(ss, sb.String())
}
sort.Strings(ss)
log.Debug("[Downloader] Queue sizes", "anchors", hd.anchorTree.Len(), "links", hd.linkQueue.Len(), "persisted", hd.persistedLinkQueue.Len())
log.Debug("[downloader] Queue sizes", "anchors", hd.anchorTree.Len(), "links", hd.linkQueue.Len(), "persisted", hd.persistedLinkQueue.Len())
for _, s := range ss {
log.Debug(s)
}
@ -350,7 +350,7 @@ func (hd *HeaderDownload) RecoverFromDb(db kv.RoDB) error {
select {
case <-logEvery.C:
log.Info("[Downloader] recover headers from db", "left", hd.persistedLinkLimit-hd.persistedLinkQueue.Len())
log.Info("[downloader] recover headers from db", "left", hd.persistedLinkLimit-hd.persistedLinkQueue.Len())
default:
}
}
@ -377,7 +377,7 @@ func (hd *HeaderDownload) ReadProgressFromDb(tx kv.RwTx) (err error) {
}
func (hd *HeaderDownload) invalidateAnchor(anchor *Anchor, reason string) {
log.Debug("[Downloader] Invalidating anchor", "height", anchor.blockHeight, "hash", anchor.parentHash, "reason", reason)
log.Debug("[downloader] Invalidating anchor", "height", anchor.blockHeight, "hash", anchor.parentHash, "reason", reason)
hd.removeAnchor(anchor)
for child := anchor.fLink; child != nil; child, child.next = child.next, nil {
hd.removeUpwards(child)
@ -415,7 +415,7 @@ func (hd *HeaderDownload) RequestMoreHeaders(currentTime time.Time) (*HeaderRequ
func (hd *HeaderDownload) requestMoreHeadersForPOS(currentTime time.Time) (timeout bool, request *HeaderRequest, penalties []PenaltyItem) {
anchor := hd.posAnchor
if anchor == nil {
log.Debug("[Downloader] No PoS anchor")
log.Debug("[downloader] No PoS anchor")
return
}
@ -427,7 +427,7 @@ func (hd *HeaderDownload) requestMoreHeadersForPOS(currentTime time.Time) (timeo
// TODO: [pos-downloader-tweaks] - we could reduce this number, or config it
timeout = anchor.timeouts >= 3
if timeout {
log.Warn("[Downloader] Timeout", "requestId", hd.requestId, "peerID", common.Bytes2Hex(anchor.peerID[:]))
log.Warn("[downloader] Timeout", "requestId", hd.requestId, "peerID", common.Bytes2Hex(anchor.peerID[:]))
penalties = []PenaltyItem{{Penalty: AbandonedAnchorPenalty, PeerID: anchor.peerID}}
return
}
@ -480,7 +480,7 @@ func (hd *HeaderDownload) UpdateRetryTime(req *HeaderRequest, currentTime time.T
func (hd *HeaderDownload) RequestSkeleton() *HeaderRequest {
hd.lock.RLock()
defer hd.lock.RUnlock()
log.Debug("[Downloader] Request skeleton", "anchors", len(hd.anchors), "highestInDb", hd.highestInDb)
log.Debug("[downloader] Request skeleton", "anchors", len(hd.anchors), "highestInDb", hd.highestInDb)
var stride uint64
if hd.initialCycle {
stride = 192
@ -519,7 +519,7 @@ func (hd *HeaderDownload) InsertHeader(hf FeedHeaderFunc, terminalTotalDifficult
hd.moveLinkToQueue(link, NoQueue)
delete(hd.links, link.hash)
hd.removeUpwards(link)
log.Warn("[Downloader] Rejected header marked as bad", "hash", link.hash, "height", link.blockHeight)
log.Warn("[downloader] Rejected header marked as bad", "hash", link.hash, "height", link.blockHeight)
return true, false, 0, lastTime, nil
}
if !link.verified {
@ -527,10 +527,10 @@ func (hd *HeaderDownload) InsertHeader(hf FeedHeaderFunc, terminalTotalDifficult
hd.badPoSHeaders[link.hash] = link.header.ParentHash
if errors.Is(err, consensus.ErrFutureBlock) {
// This may become valid later
log.Warn("[Downloader] Added future link", "hash", link.hash, "height", link.blockHeight, "timestamp", link.header.Time)
log.Warn("[downloader] Added future link", "hash", link.hash, "height", link.blockHeight, "timestamp", link.header.Time)
return false, false, 0, lastTime, nil // prevent removal of the link from the hd.linkQueue
} else {
log.Debug("[Downloader] Verification failed for header", "hash", link.hash, "height", link.blockHeight, "err", err)
log.Debug("[downloader] Verification failed for header", "hash", link.hash, "height", link.blockHeight, "err", err)
hd.moveLinkToQueue(link, NoQueue)
delete(hd.links, link.hash)
hd.removeUpwards(link)
@ -569,7 +569,7 @@ func (hd *HeaderDownload) InsertHeader(hf FeedHeaderFunc, terminalTotalDifficult
if link.blockHeight > hd.highestInDb {
if hd.trace {
log.Info("[Downloader] Highest in DB change", "number", link.blockHeight, "hash", link.hash)
log.Info("[downloader] Highest in DB change", "number", link.blockHeight, "hash", link.hash)
}
hd.highestInDb = link.blockHeight
}
@ -636,7 +636,7 @@ func (hd *HeaderDownload) SetHeaderToDownloadPoS(hash libcommon.Hash, height uin
hd.lock.Lock()
defer hd.lock.Unlock()
log.Debug("[Downloader] Set posAnchor", "blockHeight", height+1)
log.Debug("[downloader] Set posAnchor", "blockHeight", height+1)
hd.posAnchor = &Anchor{
parentHash: hash,
blockHeight: height + 1,
@ -647,12 +647,12 @@ func (hd *HeaderDownload) ProcessHeadersPOS(csHeaders []ChainSegmentHeader, tx k
if len(csHeaders) == 0 {
return nil, nil
}
log.Debug("[Downloader] Collecting...", "from", csHeaders[0].Number, "to", csHeaders[len(csHeaders)-1].Number, "len", len(csHeaders))
log.Debug("[downloader] Collecting...", "from", csHeaders[0].Number, "to", csHeaders[len(csHeaders)-1].Number, "len", len(csHeaders))
hd.lock.Lock()
defer hd.lock.Unlock()
if hd.posAnchor == nil {
// May happen if peers are sending unrequested header packets after we've synced
log.Debug("[Downloader] posAnchor is nil")
log.Debug("[downloader] posAnchor is nil")
return nil, nil
}
@ -670,11 +670,11 @@ func (hd *HeaderDownload) ProcessHeadersPOS(csHeaders []ChainSegmentHeader, tx k
// With this code commented out, the sync proceeds but very slowly (getting 1 header from the response of 192 headers)
/*
if hd.posAnchor.blockHeight != 1 && sh.Number != hd.posAnchor.blockHeight-1 {
log.Debug("[Downloader] posAnchor", "blockHeight", hd.posAnchor.blockHeight)
log.Debug("[downloader] posAnchor", "blockHeight", hd.posAnchor.blockHeight)
//return nil, nil
}
*/
log.Debug("[Downloader] Unexpected header", "hash", headerHash, "expected", hd.posAnchor.parentHash, "peerID", common.Bytes2Hex(peerId[:]))
log.Debug("[downloader] Unexpected header", "hash", headerHash, "expected", hd.posAnchor.parentHash, "peerID", common.Bytes2Hex(peerId[:]))
// Not penalise because we might have sent request twice
continue
}
@ -689,7 +689,7 @@ func (hd *HeaderDownload) ProcessHeadersPOS(csHeaders []ChainSegmentHeader, tx k
return nil, err
}
if hh != nil {
log.Debug("[Downloader] Synced", "requestId", hd.requestId)
log.Debug("[downloader] Synced", "requestId", hd.requestId)
if headerNumber != hh.Number.Uint64()+1 {
hd.badPoSHeaders[headerHash] = header.ParentHash
return nil, fmt.Errorf("invalid PoS segment detected: invalid block number. got %d, expected %d", headerNumber, hh.Number.Uint64()+1)
@ -967,11 +967,11 @@ func (hd *HeaderDownload) ProcessHeader(sh ChainSegmentHeader, newBlock bool, pe
anchor, foundAnchor := hd.anchors[sh.Hash]
if !foundParent && !foundAnchor {
if sh.Number < hd.highestInDb {
log.Debug(fmt.Sprintf("[Downloader] new anchor too far in the past: %d, latest header in db: %d", sh.Number, hd.highestInDb))
log.Debug(fmt.Sprintf("[downloader] new anchor too far in the past: %d, latest header in db: %d", sh.Number, hd.highestInDb))
return false
}
if len(hd.anchors) >= hd.anchorLimit {
log.Debug(fmt.Sprintf("[Downloader] too many anchors: %d, limit %d", len(hd.anchors), hd.anchorLimit))
log.Debug(fmt.Sprintf("[downloader] too many anchors: %d, limit %d", len(hd.anchors), hd.anchorLimit))
return false
}
}
@ -999,7 +999,7 @@ func (hd *HeaderDownload) ProcessHeader(sh ChainSegmentHeader, newBlock bool, pe
} else {
// The link has not known parent, therefore it becomes an anchor, unless it is too far in the past
if sh.Number+params.FullImmutabilityThreshold < hd.highestInDb {
log.Debug("[Downloader] Remove upwards", "height", link.blockHeight, "hash", link.blockHeight)
log.Debug("[downloader] Remove upwards", "height", link.blockHeight, "hash", link.blockHeight)
hd.removeUpwards(link)
return false
}
@ -1028,9 +1028,9 @@ func (hd *HeaderDownload) ProcessHeaders(csHeaders []ChainSegmentHeader, newBloc
hd.lock.Lock()
defer hd.lock.Unlock()
hd.stats.Responses++
log.Trace("[Downloader] Link queue", "size", hd.linkQueue.Len())
log.Trace("[downloader] Link queue", "size", hd.linkQueue.Len())
if hd.linkQueue.Len() > hd.linkLimit {
log.Trace("[Downloader] Too many links, cutting down", "count", hd.linkQueue.Len(), "tried to add", len(csHeaders), "limit", hd.linkLimit)
log.Trace("[downloader] Too many links, cutting down", "count", hd.linkQueue.Len(), "tried to add", len(csHeaders), "limit", hd.linkLimit)
hd.pruneLinkQueue()
}
// Wake up stage loop if it is outside any of the stages
@ -1289,7 +1289,7 @@ func (hd *HeaderDownload) StartPoSDownloader(
if sentToPeer {
// If request was actually sent to a peer, we update retry time to be 5 seconds in the future
hd.UpdateRetryTime(req, currentTime, 30*time.Second /* timeout */)
log.Debug("[Downloader] Sent request", "height", req.Number)
log.Debug("[downloader] Sent request", "height", req.Number)
}
}
if len(penalties) > 0 {
@ -1312,7 +1312,7 @@ func (hd *HeaderDownload) StartPoSDownloader(
prevProgress = progress
} else if progress <= prevProgress {
diff := prevProgress - progress
log.Info("[Downloader] Downloaded PoS Headers", "now", progress,
log.Info("[downloader] Downloaded PoS Headers", "now", progress,
"blk/sec", float64(diff)/float64(logInterval/time.Second))
prevProgress = progress
}