feat(graphsync): improve logging (#225)

associate graphsync requests to dt requests, record channel sends as they happen

channels/channels.go

@@ -123,7 +123,7 @@ func (c *Channels) dispatch(eventName fsm.EventName, channel fsm.StateType) {
 		Message:   realChannel.Message,
 		Timestamp: time.Now(),
 	}
-
+	log.Debugw("process data transfer listeners", "name", datatransfer.Events[evtCode], "transfer ID", realChannel.TransferID)
 	c.notifier(evt, c.fromInternalChannelState(realChannel))
 
 	// When the channel has been cleaned up, remove the caches of seen cids
@@ -406,6 +406,7 @@ func (c *Channels) send(chid datatransfer.ChannelID, code datatransfer.EventCode
 	if err != nil {
 		return err
 	}
+	log.Debugw("send data transfer event", "name", datatransfer.Events[code], "transfer ID", chid.ID, "args", args)
 	return c.stateMachines.Send(chid, code, args...)
 }
 

transport/graphsync/graphsync.go

@@ -949,7 +949,7 @@ func (c *dtChannel) gsReqOpened(gsKey graphsyncKey, hookActions graphsync.Outgoi
 	if c.hasStore() {
 		hookActions.UsePersistenceOption("data-transfer-" + c.channelID.String())
 	}
-
+	log.Infow("outgoing graphsync request", "peer", gsKey.p, "graphsync request id", gsKey.requestID, "data transfer channel id", c.channelID)
 	// Save a mapping from the graphsync key to the channel ID so that
 	// subsequent graphsync callbacks are associated with this channel
 	c.gsKeyToChannelID.set(gsKey, c.channelID)
@@ -982,6 +982,7 @@ func (c *dtChannel) gsDataRequestRcvd(gsKey graphsyncKey, hookActions graphsync.
 	// Save a mapping from the graphsync key to the channel ID so that
 	// subsequent graphsync callbacks are associated with this channel
 	c.gsKey = gsKey
+	log.Infow("incoming graphsync request", "peer", gsKey.p, "graphsync request id", gsKey.requestID, "data transfer channel id", c.channelID)
 	c.gsKeyToChannelID.set(gsKey, c.channelID)
 
 	c.isOpen = true