Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

chore: optimize debug logging a bit #598

Merged
merged 1 commit into from
Apr 21, 2020
Merged

chore: optimize debug logging a bit #598

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
10 changes: 8 additions & 2 deletions dht.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ import (
"github.com/libp2p/go-libp2p-core/peerstore"
"github.com/libp2p/go-libp2p-core/protocol"
"github.com/libp2p/go-libp2p-core/routing"
"go.uber.org/zap"

"go.opencensus.io/tag"

Expand All @@ -34,7 +35,10 @@ import (
"github.com/multiformats/go-multihash"
)

var logger = logging.Logger("dht")
var (
logger = logging.Logger("dht")
baseLogger = logger.Desugar()
)

// BaseConnMgrScore is the base of the score set on the connection manager "kbucket" tag.
// It is added with the common prefix length between two peer IDs.
Expand Down Expand Up @@ -464,7 +468,9 @@ func (dht *IpfsDHT) putLocal(key string, rec *recpb.Record) error {
// If we connect to a peer we already have in the RT but do not exchange a query (rare)
// Do Nothing.
func (dht *IpfsDHT) peerFound(ctx context.Context, p peer.ID, queryPeer bool) {
logger.Debugw("peer found", "peer", p)
if c := baseLogger.Check(zap.DebugLevel, "peer found"); c != nil {
c.Write(zap.String("peer", p.String()))
}
b, err := dht.validRTPeer(p)
if err != nil {
logger.Errorw("failed to validate if peer is a DHT peer", "peer", p, "error", err)
Expand Down
76 changes: 41 additions & 35 deletions dht_net.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"github.com/libp2p/go-msgio"
"go.opencensus.io/stats"
"go.opencensus.io/tag"
"go.uber.org/zap"
)

var dhtReadMessageTimeout = 10 * time.Second
Expand Down Expand Up @@ -97,8 +98,9 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
}
// This string test is necessary because there isn't a single stream reset error
// instance in use.
if err.Error() != "stream reset" {
logger.Debugf("error reading message: %#v", err)
if c := baseLogger.Check(zap.DebugLevel, "error reading message"); c != nil && err.Error() != "stream reset" {
c.Write(zap.String("from", mPeer.String()),
zap.Error(err))
}
if msgLen > 0 {
_ = stats.RecordWithTags(ctx,
Expand All @@ -113,7 +115,10 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
err = req.Unmarshal(msgbytes)
r.ReleaseMsg(msgbytes)
if err != nil {
logger.Debugf("error unmarshaling message: %#v", err)
if c := baseLogger.Check(zap.DebugLevel, "error unmarshaling message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Error(err))
}
_ = stats.RecordWithTags(ctx,
[]tag.Mutator{tag.Upsert(metrics.KeyMessageType, "UNKNOWN")},
metrics.ReceivedMessages.M(1),
Expand All @@ -138,37 +143,39 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
handler := dht.handlerForMsgType(req.GetType())
if handler == nil {
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
logger.Warnw("can't handle received message", "from", mPeer, "type", req.GetType())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reduced log level because we shouldn't warn based on received messages.

if c := baseLogger.Check(zap.DebugLevel, "can't handle received message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())))
}
return false
}

// a peer has queried us, let's add it to RT
dht.peerFound(dht.ctx, mPeer, true)

logger.Debugw("handling message",
"type", req.GetType(),
"key", req.GetKey(),
"from", mPeer,
)
if c := baseLogger.Check(zap.DebugLevel, "handling message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())),
zap.Binary("key", req.GetKey()))
}
resp, err := handler(ctx, mPeer, &req)
if err != nil {
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
logger.Debugw(
"error handling message",
"type", req.GetType(),
"key", req.GetKey(),
"from", mPeer,
"error", err)
if c := baseLogger.Check(zap.DebugLevel, "error handling message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())),
zap.Binary("key", req.GetKey()),
zap.Error(err))
}
return false
}

logger.Debugw(
"handled message",
"type", req.GetType(),
"key", req.GetKey(),
"from", mPeer,
"time", time.Since(startTime),
)
if c := baseLogger.Check(zap.DebugLevel, "handled message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())),
zap.Binary("key", req.GetKey()),
zap.Duration("time", time.Since(startTime)))
}

if resp == nil {
continue
Expand All @@ -178,24 +185,23 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
err = writeMsg(s, resp)
if err != nil {
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
logger.Debugw(
"error writing response",
"type", req.GetType(),
"key", req.GetKey(),
"from", mPeer,
"error", err)
if c := baseLogger.Check(zap.DebugLevel, "error writing response"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())),
zap.Binary("key", req.GetKey()),
zap.Error(err))
}
return false
}

elapsedTime := time.Since(startTime)

logger.Debugw(
"responded to message",
"type", req.GetType(),
"key", req.GetKey(),
"from", mPeer,
"time", elapsedTime,
)
if c := baseLogger.Check(zap.DebugLevel, "responded to message"); c != nil {
c.Write(zap.String("from", mPeer.String()),
zap.Int32("type", int32(req.GetType())),
zap.Binary("key", req.GetKey()),
zap.Duration("time", elapsedTime))
}

latencyMillis := float64(elapsedTime) / float64(time.Millisecond)
stats.Record(ctx, metrics.InboundRequestLatency.M(latencyMillis))
Expand Down
1 change: 1 addition & 0 deletions go.mod
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,4 +34,5 @@ require (
github.com/stretchr/testify v1.5.1
github.com/whyrusleeping/go-keyspace v0.0.0-20160322163242-5b898ac5add1
go.opencensus.io v0.22.3
go.uber.org/zap v1.10.0
)
3 changes: 0 additions & 3 deletions go.sum
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,6 @@ github.com/gxed/hashland/murmur3 v0.0.1 h1:SheiaIt0sda5K+8FLz952/1iWS9zrnKsEJaOJ
github.com/gxed/hashland/murmur3 v0.0.1/go.mod h1:KjXop02n4/ckmZSnY2+HKcLud/tcmvhST0bie/0lS48=
github.com/hashicorp/errwrap v1.0.0 h1:hLrqtEDnRye3+sgx6z4qVLNuviH3MR5aQ0ykNJa/UYA=
github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
github.com/hashicorp/go-multierror v1.0.0/go.mod h1:dHtQlpGsu+cZNNAkkCN/P3hoUDHhCYQXV3UM06sGGrk=
github.com/hashicorp/go-multierror v1.1.0 h1:B9UzwGQJehnUY1yNrnwREHc3fGbC2xefo8g4TbElacI=
github.com/hashicorp/go-multierror v1.1.0/go.mod h1:spPvp8C1qA32ftKqdAHm4hHTbPw+vmowP0z+KUhOZdA=
github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8=
Expand Down Expand Up @@ -279,8 +278,6 @@ github.com/libp2p/go-libp2p-pnet v0.2.0 h1:J6htxttBipJujEjz1y0a5+eYoiPcFHhSYHH6n
github.com/libp2p/go-libp2p-pnet v0.2.0/go.mod h1:Qqvq6JH/oMZGwqs3N1Fqhv8NVhrdYcO0BW4wssv21LA=
github.com/libp2p/go-libp2p-record v0.1.2 h1:M50VKzWnmUrk/M5/Dz99qO9Xh4vs8ijsK+7HkJvRP+0=
github.com/libp2p/go-libp2p-record v0.1.2/go.mod h1:pal0eNcT5nqZaTV7UGhqeGqxFgGdsU/9W//C8dqjQDk=
github.com/libp2p/go-libp2p-routing-helpers v0.2.0 h1:+QKTsx2Bg0q3oueQ9CopTwKN5NsnF+qEC+sbkSVXnsU=
github.com/libp2p/go-libp2p-routing-helpers v0.2.0/go.mod h1:Db+7LRSPImkV9fOKsNWVW5IXyy9XDse92lUtO3O+jlo=
github.com/libp2p/go-libp2p-routing-helpers v0.2.1 h1:tV5fxxkl1cEEFXIv9yl5OGbLjEwngtq1qf5G/beLRvQ=
github.com/libp2p/go-libp2p-routing-helpers v0.2.1/go.mod h1:rTLUHlGDZbXHANJAWP2xW7ruPNJLj41/GnCBiR+qgjU=
github.com/libp2p/go-libp2p-secio v0.1.0/go.mod h1:tMJo2w7h3+wN4pgU2LSYeiKPrfqBgkOsdiKK77hE7c8=
Expand Down