Skip to content

Commit 5ffe7cd

Browse files
StebalienStebalien
committed
chore: optimize debug logging a bit
These are all critical paths so we should try to do as little work as possible.
1 parent 7c7c46d commit 5ffe7cd

File tree

4 files changed

+50
-40
lines changed

4 files changed

+50
-40
lines changed

‎dht.go‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ import (
1515
"github.com/libp2p/go-libp2p-core/peerstore"
1616
"github.com/libp2p/go-libp2p-core/protocol"
1717
"github.com/libp2p/go-libp2p-core/routing"
18+
"go.uber.org/zap"
1819

1920
"go.opencensus.io/tag"
2021

@@ -34,7 +35,10 @@ import (
3435
"github.com/multiformats/go-multihash"
3536
)
3637

37-
var logger = logging.Logger("dht")
38+
var (
39+
logger = logging.Logger("dht")
40+
baseLogger = logger.Desugar()
41+
)
3842

3943
// BaseConnMgrScore is the base of the score set on the connection manager "kbucket" tag.
4044
// It is added with the common prefix length between two peer IDs.
@@ -464,7 +468,9 @@ func (dht *IpfsDHT) putLocal(key string, rec *recpb.Record) error {
464468
// If we connect to a peer we already have in the RT but do not exchange a query (rare)
465469
// Do Nothing.
466470
func (dht *IpfsDHT) peerFound(ctx context.Context, p peer.ID, queryPeer bool) {
467-
logger.Debugw("peer found", "peer", p)
471+
if c := baseLogger.Check(zap.DebugLevel, "peer found"); c != nil {
472+
c.Write(zap.String("peer", p.String()))
473+
}
468474
b, err := dht.validRTPeer(p)
469475
if err != nil {
470476
logger.Errorw("failed to validate if peer is a DHT peer", "peer", p, "error", err)

‎dht_net.go‎

Lines changed: 41 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ import (
2020
"github.com/libp2p/go-msgio"
2121
"go.opencensus.io/stats"
2222
"go.opencensus.io/tag"
23+
"go.uber.org/zap"
2324
)
2425

2526
var dhtReadMessageTimeout = 10 * time.Second
@@ -97,8 +98,9 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
9798
}
9899
// This string test is necessary because there isn't a single stream reset error
99100
// instance in use.
100-
if err.Error() != "stream reset" {
101-
logger.Debugf("error reading message: %#v", err)
101+
if c := baseLogger.Check(zap.DebugLevel, "error reading message"); c != nil && err.Error() != "stream reset" {
102+
c.Write(zap.String("from", mPeer.String()),
103+
zap.Error(err))
102104
}
103105
if msgLen > 0 {
104106
_ = stats.RecordWithTags(ctx,
@@ -113,7 +115,10 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
113115
err = req.Unmarshal(msgbytes)
114116
r.ReleaseMsg(msgbytes)
115117
if err != nil {
116-
logger.Debugf("error unmarshaling message: %#v", err)
118+
if c := baseLogger.Check(zap.DebugLevel, "error unmarshaling message"); c != nil {
119+
c.Write(zap.String("from", mPeer.String()),
120+
zap.Error(err))
121+
}
117122
_ = stats.RecordWithTags(ctx,
118123
[]tag.Mutator{tag.Upsert(metrics.KeyMessageType, "UNKNOWN")},
119124
metrics.ReceivedMessages.M(1),
@@ -138,37 +143,39 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
138143
handler := dht.handlerForMsgType(req.GetType())
139144
if handler == nil {
140145
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
141-
logger.Warnw("can't handle received message", "from", mPeer, "type", req.GetType())
146+
if c := baseLogger.Check(zap.DebugLevel, "can't handle received message"); c != nil {
147+
c.Write(zap.String("from", mPeer.String()),
148+
zap.Int32("type", int32(req.GetType())))
149+
}
142150
return false
143151
}
144152

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

148-
logger.Debugw("handling message",
149-
"type", req.GetType(),
150-
"key", req.GetKey(),
151-
"from", mPeer,
152-
)
156+
if c := baseLogger.Check(zap.DebugLevel, "handling message"); c != nil {
157+
c.Write(zap.String("from", mPeer.String()),
158+
zap.Int32("type", int32(req.GetType())),
159+
zap.Binary("key", req.GetKey()))
160+
}
153161
resp, err := handler(ctx, mPeer, &req)
154162
if err != nil {
155163
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
156-
logger.Debugw(
157-
"error handling message",
158-
"type", req.GetType(),
159-
"key", req.GetKey(),
160-
"from", mPeer,
161-
"error", err)
164+
if c := baseLogger.Check(zap.DebugLevel, "error handling message"); c != nil {
165+
c.Write(zap.String("from", mPeer.String()),
166+
zap.Int32("type", int32(req.GetType())),
167+
zap.Binary("key", req.GetKey()),
168+
zap.Error(err))
169+
}
162170
return false
163171
}
164172

165-
logger.Debugw(
166-
"handled message",
167-
"type", req.GetType(),
168-
"key", req.GetKey(),
169-
"from", mPeer,
170-
"time", time.Since(startTime),
171-
)
173+
if c := baseLogger.Check(zap.DebugLevel, "handled message"); c != nil {
174+
c.Write(zap.String("from", mPeer.String()),
175+
zap.Int32("type", int32(req.GetType())),
176+
zap.Binary("key", req.GetKey()),
177+
zap.Duration("time", time.Since(startTime)))
178+
}
172179

173180
if resp == nil {
174181
continue
@@ -178,24 +185,23 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
178185
err = writeMsg(s, resp)
179186
if err != nil {
180187
stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
181-
logger.Debugw(
182-
"error writing response",
183-
"type", req.GetType(),
184-
"key", req.GetKey(),
185-
"from", mPeer,
186-
"error", err)
188+
if c := baseLogger.Check(zap.DebugLevel, "error writing response"); c != nil {
189+
c.Write(zap.String("from", mPeer.String()),
190+
zap.Int32("type", int32(req.GetType())),
191+
zap.Binary("key", req.GetKey()),
192+
zap.Error(err))
193+
}
187194
return false
188195
}
189196

190197
elapsedTime := time.Since(startTime)
191198

192-
logger.Debugw(
193-
"responded to message",
194-
"type", req.GetType(),
195-
"key", req.GetKey(),
196-
"from", mPeer,
197-
"time", elapsedTime,
198-
)
199+
if c := baseLogger.Check(zap.DebugLevel, "responded to message"); c != nil {
200+
c.Write(zap.String("from", mPeer.String()),
201+
zap.Int32("type", int32(req.GetType())),
202+
zap.Binary("key", req.GetKey()),
203+
zap.Duration("time", elapsedTime))
204+
}
199205

200206
latencyMillis := float64(elapsedTime) / float64(time.Millisecond)
201207
stats.Record(ctx, metrics.InboundRequestLatency.M(latencyMillis))

‎go.mod‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,4 +34,5 @@ require (
3434
github.com/stretchr/testify v1.5.1
3535
github.com/whyrusleeping/go-keyspace v0.0.0-20160322163242-5b898ac5add1
3636
go.opencensus.io v0.22.3
37+
go.uber.org/zap v1.10.0
3738
)

‎go.sum‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,6 @@ github.com/gxed/hashland/murmur3 v0.0.1 h1:SheiaIt0sda5K+8FLz952/1iWS9zrnKsEJaOJ
8383
github.com/gxed/hashland/murmur3 v0.0.1/go.mod h1:KjXop02n4/ckmZSnY2+HKcLud/tcmvhST0bie/0lS48=
8484
github.com/hashicorp/errwrap v1.0.0 h1:hLrqtEDnRye3+sgx6z4qVLNuviH3MR5aQ0ykNJa/UYA=
8585
github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
86-
github.com/hashicorp/go-multierror v1.0.0/go.mod h1:dHtQlpGsu+cZNNAkkCN/P3hoUDHhCYQXV3UM06sGGrk=
8786
github.com/hashicorp/go-multierror v1.1.0 h1:B9UzwGQJehnUY1yNrnwREHc3fGbC2xefo8g4TbElacI=
8887
github.com/hashicorp/go-multierror v1.1.0/go.mod h1:spPvp8C1qA32ftKqdAHm4hHTbPw+vmowP0z+KUhOZdA=
8988
github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8=
@@ -279,8 +278,6 @@ github.com/libp2p/go-libp2p-pnet v0.2.0 h1:J6htxttBipJujEjz1y0a5+eYoiPcFHhSYHH6n
279278
github.com/libp2p/go-libp2p-pnet v0.2.0/go.mod h1:Qqvq6JH/oMZGwqs3N1Fqhv8NVhrdYcO0BW4wssv21LA=
280279
github.com/libp2p/go-libp2p-record v0.1.2 h1:M50VKzWnmUrk/M5/Dz99qO9Xh4vs8ijsK+7HkJvRP+0=
281280
github.com/libp2p/go-libp2p-record v0.1.2/go.mod h1:pal0eNcT5nqZaTV7UGhqeGqxFgGdsU/9W//C8dqjQDk=
282-
github.com/libp2p/go-libp2p-routing-helpers v0.2.0 h1:+QKTsx2Bg0q3oueQ9CopTwKN5NsnF+qEC+sbkSVXnsU=
283-
github.com/libp2p/go-libp2p-routing-helpers v0.2.0/go.mod h1:Db+7LRSPImkV9fOKsNWVW5IXyy9XDse92lUtO3O+jlo=
284281
github.com/libp2p/go-libp2p-routing-helpers v0.2.1 h1:tV5fxxkl1cEEFXIv9yl5OGbLjEwngtq1qf5G/beLRvQ=
285282
github.com/libp2p/go-libp2p-routing-helpers v0.2.1/go.mod h1:rTLUHlGDZbXHANJAWP2xW7ruPNJLj41/GnCBiR+qgjU=
286283
github.com/libp2p/go-libp2p-secio v0.1.0/go.mod h1:tMJo2w7h3+wN4pgU2LSYeiKPrfqBgkOsdiKK77hE7c8=

0 commit comments

Comments
 (0)