From fee814109d21e3e8e0b46c043c28f7aa9d5a60ca Mon Sep 17 00:00:00 2001
From: Aarsh Shah <aarshkshah1992@gmail.com>
Date: Mon, 26 Apr 2021 19:53:10 +0530
Subject: [PATCH] Better logging for Graphsync traversal (#167)

* log gs traversal

* Apply suggestions from code review

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

* add debug logs

* add debug logs

Co-authored-by: dirkmc <dirkmdev@gmail.com>
---
 go.mod                                       |  1 +
 responsemanager/runtraversal/runtraversal.go | 19 +++++++++++++++++--
 2 files changed, 18 insertions(+), 2 deletions(-)

diff --git a/go.mod b/go.mod
index 91a6131f..da7302a1 100644
--- a/go.mod
+++ b/go.mod
@@ -24,6 +24,7 @@ require (
 	github.com/ipfs/go-ipld-cbor v0.0.4 // indirect
 	github.com/ipfs/go-ipld-format v0.2.0
 	github.com/ipfs/go-log v1.0.4
+	github.com/ipfs/go-log/v2 v2.1.1
 	github.com/ipfs/go-merkledag v0.3.1
 	github.com/ipfs/go-peertaskqueue v0.2.0
 	github.com/ipfs/go-unixfs v0.2.4
diff --git a/responsemanager/runtraversal/runtraversal.go b/responsemanager/runtraversal/runtraversal.go
index fc30f062..3afb3bfc 100644
--- a/responsemanager/runtraversal/runtraversal.go
+++ b/responsemanager/runtraversal/runtraversal.go
@@ -4,12 +4,14 @@ import (
 	"bytes"
 	"io"
 
+	"github.com/ipfs/go-graphsync/ipldutil"
+	logging "github.com/ipfs/go-log/v2"
 	ipld "github.com/ipld/go-ipld-prime"
 	"github.com/ipld/go-ipld-prime/traversal"
-
-	"github.com/ipfs/go-graphsync/ipldutil"
 )
 
+var logger = logging.Logger("gs-traversal")
+
 // ResponseSender sends responses over the network
 type ResponseSender func(
 	link ipld.Link,
@@ -22,15 +24,24 @@ 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)
+			} else {
+				logger.Infof("traversal completed successfully, nBlocksRead=%d", nBlocksRead)
+			}
 			return err
 		}
 		lnk, lnkCtx := traverser.CurrentRequest()
+		logger.Debugf("will load link=%s", lnk)
 		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)
 			traverser.Error(traversal.SkipMe{})
 		} else {
 			blockBuffer, ok := result.(*bytes.Buffer)
@@ -39,14 +50,18 @@ 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)
 				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)
 					return err
 				}
 			}
+			nBlocksRead++
+			logger.Debugf("successfully loaded link=%s, nBlocksRead=%d", lnk, nBlocksRead)
 		}
 		err = sendResponse(lnk, data)
 		if err != nil {