diff --git a/exchange/bitswap/bitswap.go b/exchange/bitswap/bitswap.go index 79e5a576c..4ba099860 100644 --- a/exchange/bitswap/bitswap.go +++ b/exchange/bitswap/bitswap.go @@ -3,7 +3,6 @@ package bitswap import ( - "fmt" "math" "sync" "time" @@ -172,14 +171,14 @@ func (bs *bitswap) HasBlock(ctx context.Context, blk *blocks.Block) error { } func (bs *bitswap) sendWantlistMsgToPeer(ctx context.Context, m bsmsg.BitSwapMessage, p peer.ID) error { - logd := fmt.Sprintf("%s bitswap.sendWantlistMsgToPeer(%d, %s)", bs.self, len(m.Wantlist()), p) + log := log.Prefix("bitswap(%s).bitswap.sendWantlistMsgToPeer(%d, %s)", bs.self, len(m.Wantlist()), p) - log.Debugf("%s sending wantlist", logd) + log.Debug("sending wantlist") if err := bs.send(ctx, p, m); err != nil { - log.Errorf("%s send wantlist error: %s", logd, err) + log.Errorf("send wantlist error: %s", err) return err } - log.Debugf("%s send wantlist success", logd) + log.Debugf("send wantlist success") return nil } @@ -188,20 +187,20 @@ func (bs *bitswap) sendWantlistMsgToPeers(ctx context.Context, m bsmsg.BitSwapMe panic("Cant send wantlist to nil peerchan") } - logd := fmt.Sprintf("%s bitswap.sendWantlistMsgTo(%d)", bs.self, len(m.Wantlist())) - log.Debugf("%s begin", logd) - defer log.Debugf("%s end", logd) + log := log.Prefix("bitswap(%s).sendWantlistMsgToPeers(%d)", bs.self, len(m.Wantlist())) + log.Debugf("begin") + defer log.Debugf("end") set := pset.New() wg := sync.WaitGroup{} for peerToQuery := range peers { log.Event(ctx, "PeerToQuery", peerToQuery) - logd := fmt.Sprintf("%sto(%s)", logd, peerToQuery) if !set.TryAdd(peerToQuery) { //Do once per peer - log.Debugf("%s skipped (already sent)", logd) + log.Debugf("%s skipped (already sent)", peerToQuery) continue } + log.Debugf("%s sending", peerToQuery) wg.Add(1) go func(p peer.ID) { @@ -223,9 +222,9 @@ func (bs *bitswap) sendWantlistToPeers(ctx context.Context, peers <-chan peer.ID } func (bs *bitswap) sendWantlistToProviders(ctx context.Context) { - logd := fmt.Sprintf("%s bitswap.sendWantlistToProviders", bs.self) - log.Debugf("%s begin", logd) - defer log.Debugf("%s end", logd) + log := log.Prefix("bitswap(%s).sendWantlistToProviders ", bs.self) + log.Debugf("begin") + defer log.Debugf("end") ctx, cancel := context.WithCancel(ctx) defer cancel() @@ -240,13 +239,13 @@ func (bs *bitswap) sendWantlistToProviders(ctx context.Context) { go func(k u.Key) { defer wg.Done() - logd := fmt.Sprintf("%s(entry: %s)", logd, k) - log.Debugf("%s asking dht for providers", logd) + log := log.Prefix("(entry: %s) ", k) + log.Debug("asking dht for providers") child, _ := context.WithTimeout(ctx, providerRequestTimeout) providers := bs.network.FindProvidersAsync(child, k, maxProvidersPerRequest) for prov := range providers { - log.Debugf("%s dht returned provider %s. send wantlist", logd, prov) + log.Debugf("dht returned provider %s. send wantlist", prov) sendToPeers <- prov } }(e.Key) @@ -259,7 +258,7 @@ func (bs *bitswap) sendWantlistToProviders(ctx context.Context) { err := bs.sendWantlistToPeers(ctx, sendToPeers) if err != nil { - log.Errorf("%s sendWantlistToPeers error: %s", logd, err) + log.Errorf("sendWantlistToPeers error: %s", err) } } diff --git a/exchange/bitswap/decision/engine.go b/exchange/bitswap/decision/engine.go index 80a6e2fab..cd3ebac31 100644 --- a/exchange/bitswap/decision/engine.go +++ b/exchange/bitswap/decision/engine.go @@ -8,7 +8,7 @@ import ( bsmsg "github.com/jbenet/go-ipfs/exchange/bitswap/message" wl "github.com/jbenet/go-ipfs/exchange/bitswap/wantlist" peer "github.com/jbenet/go-ipfs/p2p/peer" - u "github.com/jbenet/go-ipfs/util" + eventlog "github.com/jbenet/go-ipfs/util/eventlog" ) // TODO consider taking responsibility for other types of requests. For @@ -41,7 +41,7 @@ import ( // whatever it sees fit to produce desired outcomes (get wanted keys // quickly, maintain good relationships with peers, etc). -var log = u.Logger("engine") +var log = eventlog.Logger("engine") const ( sizeOutboxChan = 4 @@ -140,6 +140,10 @@ func (e *Engine) Peers() []peer.ID { // MessageReceived performs book-keeping. Returns error if passed invalid // arguments. func (e *Engine) MessageReceived(p peer.ID, m bsmsg.BitSwapMessage) error { + log := log.Prefix("Engine.MessageReceived(%s)", p) + log.Debugf("enter") + defer log.Debugf("exit") + newWorkExists := false defer func() { if newWorkExists { @@ -156,9 +160,11 @@ func (e *Engine) MessageReceived(p peer.ID, m bsmsg.BitSwapMessage) error { } for _, entry := range m.Wantlist() { if entry.Cancel { + log.Debug("cancel", entry.Key) l.CancelWant(entry.Key) e.peerRequestQueue.Remove(entry.Key, p) } else { + log.Debug("wants", entry.Key, entry.Priority) l.Wants(entry.Key, entry.Priority) if exists, err := e.bs.Has(entry.Key); err == nil && exists { newWorkExists = true @@ -169,6 +175,7 @@ func (e *Engine) MessageReceived(p peer.ID, m bsmsg.BitSwapMessage) error { for _, block := range m.Blocks() { // FIXME extract blocks.NumBytes(block) or block.NumBytes() method + log.Debug("got block %s %d bytes", block.Key(), len(block.Data)) l.ReceivedBytes(len(block.Data)) for _, l := range e.ledgerMap { if l.WantListContains(block.Key()) { diff --git a/exchange/bitswap/network/ipfs_impl.go b/exchange/bitswap/network/ipfs_impl.go index 4e349dbed..c2a87ce0a 100644 --- a/exchange/bitswap/network/ipfs_impl.go +++ b/exchange/bitswap/network/ipfs_impl.go @@ -55,6 +55,7 @@ func (bsnet *impl) SendRequest( p peer.ID, outgoing bsmsg.BitSwapMessage) (bsmsg.BitSwapMessage, error) { + log.Debugf("bsnet SendRequest to %s", p) s, err := bsnet.host.NewStream(ProtocolBitswap, p) if err != nil { return nil, err diff --git a/routing/dht/dht_net.go b/routing/dht/dht_net.go index fd088e02c..2b857ce2b 100644 --- a/routing/dht/dht_net.go +++ b/routing/dht/dht_net.go @@ -87,15 +87,11 @@ func (dht *IpfsDHT) sendRequest(ctx context.Context, p peer.ID, pmes *pb.Message start := time.Now() - log.Debugf("%s writing", dht.self) if err := w.WriteMsg(pmes); err != nil { return nil, err } log.Event(ctx, "dhtSentMessage", dht.self, p, pmes) - log.Debugf("%s reading", dht.self) - defer log.Debugf("%s done", dht.self) - rpmes := new(pb.Message) if err := r.ReadMsg(rpmes); err != nil { return nil, err @@ -125,12 +121,10 @@ func (dht *IpfsDHT) sendMessage(ctx context.Context, p peer.ID, pmes *pb.Message cw := ctxutil.NewWriter(ctx, s) // ok to use. we defer close stream in this func w := ggio.NewDelimitedWriter(cw) - log.Debugf("%s writing", dht.self) if err := w.WriteMsg(pmes); err != nil { return err } log.Event(ctx, "dhtSentMessage", dht.self, p, pmes) - log.Debugf("%s done", dht.self) return nil }