events(bitswap) try the new event logger in the bitswap GetBlock method

@jbenet
@whyrusleeping

Let me know if you want to direct the eventlog output to _both_ the file
and stderr. Right now it goes to file. Perhaps this is just a minor bip
in the larger discussion around log levels.

https://github.com/jbenet/go-ipfs/issues/292

License: MIT
Signed-off-by: Brian Tiger Chow <brian@perfmode.com>

bitswap.go

@@ -17,9 +17,10 @@ import (
 	strategy "github.com/jbenet/go-ipfs/exchange/bitswap/strategy"
 	peer "github.com/jbenet/go-ipfs/peer"
 	u "github.com/jbenet/go-ipfs/util"
+	"github.com/jbenet/go-ipfs/util/eventlog"
 )
 
-var log = u.Logger("bitswap")
+var log = eventlog.Logger("bitswap")
 
 // New initializes a BitSwap instance that communicates over the
 // provided BitSwapNetwork. This function registers the returned instance as
@@ -80,15 +81,21 @@ type bitswap struct {
 //
 // TODO ensure only one active request per key
 func (bs *bitswap) GetBlock(parent context.Context, k u.Key) (*blocks.Block, error) {
-	log.Debugf("Get Block %v", k)
-	now := time.Now()
-	defer func() {
-		log.Debugf("GetBlock took %f secs", time.Now().Sub(now).Seconds())
-	}()
+
+	// make sure to derive a new |ctx| and pass it to children. It's correct to
+	// listen on |parent| here, but incorrect to pass |parent| to new async
+	// functions. This is difficult to enforce. May this comment keep you safe.
 
 	ctx, cancelFunc := context.WithCancel(parent)
 	defer cancelFunc()
 
+	ctx = eventlog.ContextWithMetadata(ctx, eventlog.Uuid("BitswapGetBlockRequest"))
+	log.Event(ctx, "BitswapGetBlockRequestBegin", &k)
+
+	defer func() {
+		log.Event(ctx, "BitSwapGetBlockRequestEnd", &k)
+	}()
+
 	bs.wantlist.Add(k)
 	promise := bs.notifications.Subscribe(ctx, k)