From 9270ac635869f10d2b365059d14d991c52f492d3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C5=81ukasz=20Magiera?= Date: Tue, 3 Nov 2020 13:28:31 +0100 Subject: [PATCH] Make some logs quieter --- chain/exchange/server.go | 2 +- chain/messagepool/messagepool.go | 4 ++-- chain/store/store.go | 2 +- chain/sub/incoming.go | 5 ++++- chain/sync.go | 2 +- node/hello/hello.go | 8 +++++--- 6 files changed, 14 insertions(+), 9 deletions(-) diff --git a/chain/exchange/server.go b/chain/exchange/server.go index dcdb5b3a5bf..fbabe5f66e9 100644 --- a/chain/exchange/server.go +++ b/chain/exchange/server.go @@ -49,7 +49,7 @@ func (s *server) HandleStream(stream inet.Stream) { log.Warnf("failed to read block sync request: %s", err) return } - log.Infow("block sync request", + log.Debugw("block sync request", "start", req.Head, "len", req.Length) resp, err := s.processRequest(ctx, &req) diff --git a/chain/messagepool/messagepool.go b/chain/messagepool/messagepool.go index 8c8a8af1538..d9a92073a17 100644 --- a/chain/messagepool/messagepool.go +++ b/chain/messagepool/messagepool.go @@ -264,7 +264,7 @@ func (ms *msgSet) add(m *types.SignedMessage, mp *MessagePool, strict, untrusted } if strict && nonceGap { - log.Warnf("adding nonce-gapped message from %s (nonce: %d, nextNonce: %d)", + log.Debugf("adding nonce-gapped message from %s (nonce: %d, nextNonce: %d)", m.Message.From, m.Message.Nonce, nextNonce) } @@ -1219,7 +1219,7 @@ func (mp *MessagePool) MessagesForBlocks(blks []*types.BlockHeader) ([]*types.Si if smsg != nil { out = append(out, smsg) } else { - log.Warnf("could not recover signature for bls message %s", msg.Cid()) + log.Debugf("could not recover signature for bls message %s", msg.Cid()) } } } diff --git a/chain/store/store.go b/chain/store/store.go index 00a78500ef9..a04953aa784 100644 --- a/chain/store/store.go +++ b/chain/store/store.go @@ -259,7 +259,7 @@ func (cs *ChainStore) SubHeadChanges(ctx context.Context) chan []*api.HeadChange log.Warn("chain head sub exit loop") return } - if len(out) > 0 { + if len(out) > 5 { log.Warnf("head change sub is slow, has %d buffered entries", len(out)) } select { diff --git a/chain/sub/incoming.go b/chain/sub/incoming.go index 1701866eb6f..a6557358e8a 100644 --- a/chain/sub/incoming.go +++ b/chain/sub/incoming.go @@ -95,7 +95,10 @@ func HandleIncomingBlocks(ctx context.Context, bsub *pubsub.Subscription, s *cha } took := build.Clock.Since(start) - log.Infow("new block over pubsub", "cid", blk.Header.Cid(), "source", msg.GetFrom(), "msgfetch", took) + log.Debugw("new block over pubsub", "cid", blk.Header.Cid(), "source", msg.GetFrom(), "msgfetch", took) + if took > 3*time.Second { + log.Warnw("Slow msg fetch", "cid", blk.Header.Cid(), "source", msg.GetFrom(), "msgfetch", took) + } if delay := build.Clock.Now().Unix() - int64(blk.Header.Timestamp); delay > 5 { log.Warnf("Received block with large delay %d from miner %s", delay, blk.Header.Miner) } diff --git a/chain/sync.go b/chain/sync.go index 5813b939e44..3e636bac423 100644 --- a/chain/sync.go +++ b/chain/sync.go @@ -278,7 +278,7 @@ func (syncer *Syncer) InformNewHead(from peer.ID, fts *store.FullTipSet) bool { for _, blk := range fts.TipSet().Blocks() { miners = append(miners, blk.Miner.String()) } - log.Infow("incoming tipset does not appear to be better than our best chain, ignoring for now", "miners", miners, "bestPweight", bestPweight, "bestTS", hts.Cids(), "incomingWeight", targetWeight, "incomingTS", fts.TipSet().Cids()) + log.Debugw("incoming tipset does not appear to be better than our best chain, ignoring for now", "miners", miners, "bestPweight", bestPweight, "bestTS", hts.Cids(), "incomingWeight", targetWeight, "incomingTS", fts.TipSet().Cids()) return false } diff --git a/node/hello/hello.go b/node/hello/hello.go index 05d53de06af..d4c6312069f 100644 --- a/node/hello/hello.go +++ b/node/hello/hello.go @@ -118,7 +118,7 @@ func (hs *Service) HandleStream(s inet.Stream) { hs.h.ConnManager().TagPeer(s.Conn().RemotePeer(), "fcpeer", 10) // don't bother informing about genesis - log.Infof("Got new tipset through Hello: %s from %s", ts.Cids(), s.Conn().RemotePeer()) + log.Debugf("Got new tipset through Hello: %s from %s", ts.Cids(), s.Conn().RemotePeer()) hs.syncer.InformNewHead(s.Conn().RemotePeer(), ts) } @@ -161,7 +161,7 @@ func (hs *Service) SayHello(ctx context.Context, pid peer.ID) error { _ = s.SetReadDeadline(build.Clock.Now().Add(10 * time.Second)) err := cborutil.ReadCborRPC(s, lmsg) if err != nil { - log.Infow("reading latency message", "error", err) + log.Debugw("reading latency message", "error", err) } t3 := build.Clock.Now() @@ -177,7 +177,9 @@ func (hs *Service) SayHello(ctx context.Context, pid peer.ID) error { t2 := time.Unix(0, lmsg.TSent) offset := t0.Sub(t1) + t3.Sub(t2) offset /= 2 - log.Infow("time offset", "offset", offset.Seconds(), "peerid", pid.String()) + if offset > 5*time.Second || offset < -5*time.Second { + log.Infow("time offset", "offset", offset.Seconds(), "peerid", pid.String()) + } } } }()