Fix/log blockstore reads (#169)

* log gs traversal

* Apply suggestions from code review
Co-authored-by: dirkmc <dirkmdev@gmail.com>

* add debug logs

* fixed logging

* Apply suggestions from code review
Co-authored-by: dirkmc <dirkmdev@gmail.com>

* fixed error
Co-authored-by: dirkmc <dirkmdev@gmail.com>

ipldutil/traverser.go

@@ -41,6 +41,8 @@ type Traverser interface {
 	Error(err error)
 	// Shutdown cancels the traversal
 	Shutdown(ctx context.Context)
+	// NBlocksTraversed returns the number of blocks successfully traversed
+	NBlocksTraversed() int
 }
 
 type state struct {
@@ -60,6 +62,7 @@ type nextResponse struct {
 func (tb TraversalBuilder) Start(parentCtx context.Context) Traverser {
 	ctx, cancel := context.WithCancel(parentCtx)
 	t := &traverser{
+		blocksCount:  0,
 		parentCtx:    parentCtx,
 		ctx:          ctx,
 		cancel:       cancel,
@@ -85,6 +88,7 @@ func (tb TraversalBuilder) Start(parentCtx context.Context) Traverser {
 // traverser is a class to perform a selector traversal that stops every time a new block is loaded
 // and waits for manual input (in the form of advance or error)
 type traverser struct {
+	blocksCount    int
 	parentCtx      context.Context
 	ctx            context.Context
 	cancel         func()
@@ -102,6 +106,10 @@ type traverser struct {
 	stopped        chan struct{}
 }
 
+func (t *traverser) NBlocksTraversed() int {
+	return t.blocksCount
+}
+
 func (t *traverser) checkState() {
 	select {
 	case <-t.awaitRequest:
@@ -203,16 +211,20 @@ func (t *traverser) Advance(reader io.Reader) error {
 	if isComplete {
 		return errors.New("cannot advance when done")
 	}
+
 	select {
 	case <-t.ctx.Done():
 		return ContextCancelError{}
 	case t.awaitRequest <- struct{}{}:
 	}
+
 	select {
 	case <-t.ctx.Done():
 		return ContextCancelError{}
 	case t.responses <- nextResponse{reader, nil}:
 	}
+
+	t.blocksCount++
 	return nil
 }
 

responsemanager/runtraversal/runtraversal.go

@@ -24,15 +24,14 @@ func RunTraversal(
 	loader ipld.Loader,
 	traverser ipldutil.Traverser,
 	sendResponse ResponseSender) error {
-	nBlocksRead := 0
 
 	for {
 		isComplete, err := traverser.IsComplete()
 		if isComplete {
 			if err != nil {
-				logger.Infof("traversal completion check failed, nBlocksRead=%d, err=%s", nBlocksRead, err)
+				logger.Errorf("traversal completion check failed, nBlocksRead=%d, err=%s", traverser.NBlocksTraversed(), err)
 			} else {
-				logger.Infof("traversal completed successfully, nBlocksRead=%d", nBlocksRead)
+				logger.Debugf("traversal completed successfully, nBlocksRead=%d", traverser.NBlocksTraversed())
 			}
 			return err
 		}
@@ -41,7 +40,7 @@ func RunTraversal(
 		result, err := loader(lnk, lnkCtx)
 		var data []byte
 		if err != nil {
-			logger.Errorf("failed to load link=%s, nBlocksRead=%d, err=%s", lnk, nBlocksRead, err)
+			logger.Errorf("failed to load link=%s, nBlocksRead=%d, err=%s", lnk, traverser.NBlocksTraversed(), err)
 			traverser.Error(traversal.SkipMe{})
 		} else {
 			blockBuffer, ok := result.(*bytes.Buffer)
@@ -50,18 +49,17 @@ func RunTraversal(
 				_, err = io.Copy(blockBuffer, result)
 			}
 			if err != nil {
-				logger.Errorf("failed to write to buffer, link=%s, nBlocksRead=%d, err=%s", lnk, nBlocksRead, err)
+				logger.Errorf("failed to write to buffer, link=%s, nBlocksRead=%d, err=%s", lnk, traverser.NBlocksTraversed(), err)
 				traverser.Error(err)
 			} else {
 				data = blockBuffer.Bytes()
 				err = traverser.Advance(blockBuffer)
 				if err != nil {
-					logger.Errorf("failed to advance traversal, link=%s, nBlocksRead=%d, err=%s", lnk, nBlocksRead, err)
+					logger.Errorf("failed to advance traversal, link=%s, nBlocksRead=%d, err=%s", lnk, traverser.NBlocksTraversed(), err)
 					return err
 				}
 			}
-			nBlocksRead++
-			logger.Debugf("successfully loaded link=%s, nBlocksRead=%d", lnk, nBlocksRead)
+			logger.Debugf("successfully loaded link=%s, nBlocksRead=%d", lnk, traverser.NBlocksTraversed())
 		}
 		err = sendResponse(lnk, data)
 		if err != nil {

responsemanager/runtraversal/runtraversal_test.go

@@ -69,6 +69,10 @@ type fakeTraverser struct {
 	expectedOutcomes []traverseOutcome
 }
 
+func (ft *fakeTraverser) NBlocksTraversed() int {
+	return 0
+}
+
 // IsComplete returns the completion state (boolean) and if so, the final error result from IPLD
 func (ft *fakeTraverser) IsComplete() (bool, error) {
 	if ft.currentLink >= len(ft.loadedLinks) {