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

feat(*): more comprehensive log output #198

Closed
wants to merge 1 commit into from
Closed

feat(*): more comprehensive log output #198

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.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
34 changes: 28 additions & 6 deletions dht_net.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ import (
pb "github.com/libp2p/go-libp2p-kad-dht/pb"
inet "github.com/libp2p/go-libp2p-net"
peer "github.com/libp2p/go-libp2p-peer"
b58 "github.com/mr-tron/base58/base58"
)

var dhtReadMessageTimeout = time.Minute
Expand Down Expand Up @@ -70,6 +71,9 @@ func (dht *IpfsDHT) handleNewMessage(s inet.Stream) {
return
}

// log the received message
log.Event(ctx, "handleNewMessage", mPeer, pmes)
Copy link
Member

Choose a reason for hiding this comment

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

This should probably be a span event, like the others. That is, use log.Start and log.Finish. Really, we may want to break the rest of this function out into a separate function (so we can use defer to end the event).


// update the peer (on valid msgs only)
dht.updateFromMessage(ctx, mPeer, pmes)

Expand Down Expand Up @@ -108,41 +112,60 @@ func (dht *IpfsDHT) handleNewMessage(s inet.Stream) {
}
}

func tagWithMessage(ctx context.Context, name string, msg *pb.Message) {
log.SetTag(ctx, name+".key", b58.Encode([]byte(msg.GetKey())))
Copy link
Member

Choose a reason for hiding this comment

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

This is going to be a bit expensive. Let's wait for #200, then we can use the loggableKey helper type to format lazily and on-demand.

log.SetTag(ctx, name+".type", msg.GetType().String())
}

// sendRequest sends out a request, but also makes sure to
// measure the RTT for latency measurements.
func (dht *IpfsDHT) sendRequest(ctx context.Context, p peer.ID, pmes *pb.Message) (*pb.Message, error) {
ctx = log.Start(ctx, "sendRequest")
defer log.Finish(ctx)
log.SetTag(ctx, "peer.address", p.Pretty())
log.SetTag(ctx, "self.address", dht.self.Pretty())
tagWithMessage(ctx, "request", pmes)

ms, err := dht.messageSenderForPeer(p)
if err != nil {
log.SetErr(ctx, err)
return nil, err
}

start := time.Now()

rpmes, err := ms.SendRequest(ctx, pmes)
if err != nil {
log.SetErr(ctx, err)
return nil, err
}
tagWithMessage(ctx, "response", rpmes)
Copy link
Member

Choose a reason for hiding this comment

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

I don't see the benefit of tagging the response and request differently. The key and type should be identical.

Copy link
Author

Choose a reason for hiding this comment

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

The reason for this is the request/response are part of the same span, so if we tag them the same, one will overwrite the other. We could convert this to span events, but that'll be ugly as well since span events only support single k/v (no nesting) AFAIK.


// update the peer (on valid msgs only)
dht.updateFromMessage(ctx, p, rpmes)

dht.peerstore.RecordLatency(p, time.Since(start))
log.Event(ctx, "dhtReceivedMessage", dht.self, p, rpmes)
return rpmes, nil
}

// sendMessage sends out a message
func (dht *IpfsDHT) sendMessage(ctx context.Context, p peer.ID, pmes *pb.Message) error {
ctx = log.Start(ctx, "sendMessage")
defer log.Finish(ctx)
log.SetTag(ctx, "peer.address", p.Pretty())
log.SetTag(ctx, "self.address", dht.self.Pretty())
tagWithMessage(ctx, "request", pmes)

ms, err := dht.messageSenderForPeer(p)
if err != nil {
log.SetErr(ctx, err)
return err
}

if err := ms.SendMessage(ctx, pmes); err != nil {
log.SetErr(ctx, err)
return err
}
log.Event(ctx, "dhtSentMessage", dht.self, p, pmes)
return nil
}

Expand Down Expand Up @@ -267,8 +290,7 @@ func (ms *messageSender) SendMessage(ctx context.Context, pmes *pb.Message) erro
continue
}
}

log.Event(ctx, "dhtSentMessage", ms.dht.self, ms.p, pmes)
log.LogKV(ctx, "event", "sent", "message", "dht message sent")

if ms.singleMes > streamReuseTries {
go inet.FullClose(ms.s)
Expand Down Expand Up @@ -303,6 +325,7 @@ func (ms *messageSender) SendRequest(ctx context.Context, pmes *pb.Message) (*pb
continue
}
}
log.LogKV(ctx, "event", "sent", "message", "dht request sent")

mes := new(pb.Message)
if err := ms.ctxReadMsg(ctx, mes); err != nil {
Expand All @@ -318,8 +341,7 @@ func (ms *messageSender) SendRequest(ctx context.Context, pmes *pb.Message) (*pb
continue
}
}

log.Event(ctx, "dhtSentMessage", ms.dht.self, ms.p, pmes)
log.LogKV(ctx, "event", "received", "message", "dht request response received")

if ms.singleMes > streamReuseTries {
go inet.FullClose(ms.s)
Expand Down