diff --git a/eth/downloader/downloader.go b/eth/downloader/downloader.go index 1ae7f9d8c57..d7a560c5353 100644 --- a/eth/downloader/downloader.go +++ b/eth/downloader/downloader.go @@ -338,7 +338,7 @@ func (d *Downloader) Synchronising() bool { // RegisterPeer injects a new download peer into the set of block source to be // used for fetching hashes and blocks from. func (d *Downloader) RegisterPeer(id string, version int, peer Peer) error { - logger := log.New("peer", id) + logger := peerLogger(id) logger.Trace("Registering sync peer") if err := d.peers.Register(newPeerConnection(id, version, peer, logger)); err != nil { logger.Error("Failed to register sync peer", "err", err) @@ -359,7 +359,7 @@ func (d *Downloader) RegisterLightPeer(id string, version int, peer LightPeer) e // the queue. func (d *Downloader) UnregisterPeer(id string) error { // Unregister the peer from the active peer set and revoke any fetch tasks - logger := log.New("peer", id) + logger := peerLogger(id) logger.Trace("Unregistering sync peer") if err := d.peers.Unregister(id); err != nil { logger.Warn("Failed to unregister sync peer", "err", err) @@ -383,11 +383,12 @@ func (d *Downloader) Synchronise(id string, head common.Hash, td *big.Int, mode if errors.Is(err, errInvalidChain) || errors.Is(err, errBadPeer) || errors.Is(err, errTimeout) || errors.Is(err, errStallingPeer) || errors.Is(err, errEmptyHeaderSet) || errors.Is(err, errPeersUnavailable) || errors.Is(err, errTooOld) || errors.Is(err, errInvalidAncestor) { - log.Warn("Synchronisation failed, dropping peer", "peer", id, "err", err) + logger := peerLogger(id) + logger.Warn("Synchronisation failed, dropping peer", "err", err) if d.dropPeer == nil { // The dropPeer method is nil when `--copydb` is used for a local copy. // Timeouts can occur if e.g. compaction hits at the wrong time, and can be ignored - log.Warn("Downloader wants to drop peer, but peerdrop-function is not set", "peer", id) + logger.Warn("Downloader wants to drop peer, but peerdrop-function is not set") } else { d.dropPeer(id) } diff --git a/eth/downloader/peer.go b/eth/downloader/peer.go index f7b3aed6f65..e6f5c703920 100644 --- a/eth/downloader/peer.go +++ b/eth/downloader/peer.go @@ -114,6 +114,15 @@ func (w *lightPeerWrapper) RequestNodeData([]common.Hash) error { panic("RequestNodeData not supported in light client mode sync") } +// peerLogger creates a logger tagged with the peer id, truncated to keep the +// sync logs readable. Short ids used by the tests are left untouched. +func peerLogger(id string) log.Logger { + if len(id) > 16 { + id = id[:16] + } + return log.New("peer", id) +} + // newPeerConnection creates a new downloader peer. func newPeerConnection(id string, version int, peer Peer, logger log.Logger) *peerConnection { return &peerConnection{ diff --git a/eth/downloader/queue.go b/eth/downloader/queue.go index 86c382697cd..80d9edc7a98 100644 --- a/eth/downloader/queue.go +++ b/eth/downloader/queue.go @@ -708,16 +708,18 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh headerReqTimer.UpdateSince(request.Time) delete(q.headerPendPool, id) + logger := peerLogger(id) + // Ensure headers can be mapped onto the skeleton chain target := q.headerTaskPool[request.From].Hash() accepted := len(headers) == MaxHeaderFetch if accepted { if headers[0].Number.Uint64() != request.From { - log.Trace("First header broke chain ordering", "peer", id, "number", headers[0].Number, "hash", headers[0].Hash(), request.From) + logger.Debug("First header broke chain ordering", "number", headers[0].Number, "hash", headers[0].Hash(), "expected", request.From) accepted = false } else if headers[len(headers)-1].Hash() != target { - log.Trace("Last header broke skeleton structure ", "peer", id, "number", headers[len(headers)-1].Number, "hash", headers[len(headers)-1].Hash(), "expected", target) + logger.Debug("Last header broke skeleton structure", "number", headers[len(headers)-1].Number, "hash", headers[len(headers)-1].Hash(), "expected", target) accepted = false } } @@ -725,12 +727,12 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh for i, header := range headers[1:] { hash := header.Hash() if want := request.From + 1 + uint64(i); header.Number.Uint64() != want { - log.Warn("Header broke chain ordering", "peer", id, "number", header.Number, "hash", hash, "expected", want) + logger.Warn("Header broke chain ordering", "number", header.Number, "hash", hash, "expected", want) accepted = false break } if headers[i].Hash() != header.ParentHash { - log.Warn("Header broke chain ancestry", "peer", id, "number", header.Number, "hash", hash) + logger.Warn("Header broke chain ancestry", "number", header.Number, "hash", hash) accepted = false break } @@ -738,7 +740,7 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh } // If the batch of headers wasn't accepted, mark as unavailable if !accepted { - log.Trace("Skeleton filling not accepted", "peer", id, "from", request.From) + logger.Debug("Skeleton filling not accepted", "from", request.From) miss := q.headerPeerMiss[id] if miss == nil { @@ -765,7 +767,7 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh select { case headerProcCh <- process: - log.Trace("Pre-scheduled new headers", "peer", id, "count", len(process), "from", process[0].Number) + logger.Trace("Pre-scheduled new headers", "count", len(process), "from", process[0].Number) q.headerProced += len(process) default: }