feat: better logging (#155)

events.go

@@ -74,13 +74,15 @@ const (
 	// DataQueued is emitted when data is read and queued for sending to the remote peer
 	DataQueued
 
-	// DataQueuedProgress is emitted the first time a block is queued for
-	// sending to the remote peer. It is used to measure progress of how much
-	// of the total data has been queued.
+	// DataQueuedProgress is emitted when a block is queued for sending to the
+	// remote peer. It is not emitted when the block is resent.
+	// It is used to measure progress of how much of the total data has been
+	// queued.
 	DataQueuedProgress
 
-	// DataSentProgress is emitted the first time a block is sent to the remote
-	// peer. It is used to measure progress of how much of the total data has
+	// DataSentProgress is emitted when a block is sent to the remote peer.
+	// It is not emitted when the block is resent.
+	// It is used to measure progress of how much of the total data has
 	// been sent.
 	DataSentProgress
 

impl/events.go

@@ -288,15 +288,17 @@ func (m *manager) OnRequestDisconnected(ctx context.Context, chid datatransfer.C
 
 func (m *manager) OnChannelCompleted(chid datatransfer.ChannelID, completeErr error) error {
 	if completeErr == nil {
+		// If the channel was initiated by the other peer
 		if chid.Initiator != m.peerID {
 			msg, err := m.completeMessage(chid)
 			if err != nil {
 				return nil
 			}
 			if msg != nil {
-				log.Infof("channel %s: sending completion message", chid)
+				// Send the other peer a message that the transfer has completed
+				log.Infof("channel %s: sending completion message to initiator", chid)
 				if err := m.dataTransferNetwork.SendMessage(context.Background(), chid.Initiator, msg); err != nil {
-					log.Warnf("channel %s: failed to send completion message: %s", chid, err)
+					log.Warnf("channel %s: failed to send completion message to initiator: %s", chid, err)
 					return m.OnRequestDisconnected(context.TODO(), chid)
 				}
 			}
@@ -308,6 +310,9 @@ func (m *manager) OnChannelCompleted(chid datatransfer.ChannelID, completeErr er
 			}
 			return m.channels.Error(chid, err)
 		}
+
+		// The channel was initiated by this node, so move to the finished state
+		log.Infof("channel %s: transfer initiated by local node is complete", chid)
 		return m.channels.FinishTransfer(chid)
 	}
 	chst, err := m.channels.GetByID(context.TODO(), chid)

network/libp2p_impl.go

@@ -115,6 +115,7 @@ func (impl *libp2pDataTransferNetwork) openStream(ctx context.Context, id peer.I
 		Jitter: true,
 	}
 
+	start := time.Now()
 	for {
 		tctx, cancel := context.WithTimeout(ctx, impl.openStreamTimeout)
 		defer cancel()
@@ -123,6 +124,11 @@ func (impl *libp2pDataTransferNetwork) openStream(ctx context.Context, id peer.I
 		at := time.Now()
 		s, err := impl.host.NewStream(tctx, id, protocols...)
 		if err == nil {
+			nAttempts := b.Attempt() + 1
+			if b.Attempt() > 0 {
+				log.Debugf("opened stream to %s on attempt %g of %g after %s",
+					id, nAttempts, impl.maxStreamOpenAttempts, time.Since(start))
+			}
 			return s, err
 		}