fix(requestid): print requestids as string uuids in logs

Author: rvagg

impl/graphsync_test.go

@@ -1183,11 +1183,12 @@ func TestGraphsyncRoundTripMultipleAlternatePersistence(t *testing.T) {
 	progressChan1, errChan1 := requestor.Request(ctx, td.host2.ID(), blockChain.TipLink, blockChain.Selector(), extension1)
 	progressChan2, errChan2 := requestor.Request(ctx, td.host2.ID(), blockChain.TipLink, blockChain.Selector(), extension2)
 
-	blockChain.VerifyWholeChain(ctx, progressChan1)
+	// todo
 	testutil.VerifyEmptyErrors(ctx, t, errChan1)
+	blockChain.VerifyWholeChain(ctx, progressChan1)
 	require.Len(t, altStore1, blockChainLength, "did not store all blocks in alternate store 1")
-	blockChain.VerifyWholeChain(ctx, progressChan2)
 	testutil.VerifyEmptyErrors(ctx, t, errChan2)
+	blockChain.VerifyWholeChain(ctx, progressChan2)
 	require.Len(t, altStore1, blockChainLength, "did not store all blocks in alternate store 2")
 
 	drain(requestor)

requestmanager/asyncloader/responsecache/responsecache.go

@@ -78,7 +78,7 @@ func (rc *ResponseCache) ProcessResponse(responses map[graphsync.RequestID]metad
 
 	for requestID, md := range responses {
 		for _, item := range md {
-			log.Debugf("Traverse link %s on request ID %d", item.Link.String(), requestID)
+			log.Debugf("Traverse link %s on request ID %s", item.Link.String(), requestID.String())
 			rc.linkTracker.RecordLinkTraversal(requestID, cidlink.Link{Cid: item.Link}, item.BlockPresent)
 		}
 	}

requestmanager/server.go

@@ -62,7 +62,7 @@ func (rm *RequestManager) newRequest(parentSpan trace.Span, p peer.ID, root ipld
 	ctx, span := otel.Tracer("graphsync").Start(trace.ContextWithSpan(rm.ctx, parentSpan), "newRequest")
 	defer span.End()
 
-	log.Infow("graphsync request initiated", "request id", requestID, "peer", p, "root", root)
+	log.Infow("graphsync request initiated", "request id", requestID.String(), "peer", p, "root", root)
 
 	request, hooksResult, err := rm.validateRequest(requestID, p, root, selector, extensions)
 	if err != nil {
@@ -114,7 +114,7 @@ func (rm *RequestManager) requestTask(requestID graphsync.RequestID) executor.Re
 	if !ok {
 		return executor.RequestTask{Empty: true}
 	}
-	log.Infow("graphsync request processing begins", "request id", requestID, "peer", ipr.p, "total time", time.Since(ipr.startTime))
+	log.Infow("graphsync request processing begins", "request id", requestID.String(), "peer", ipr.p, "total time", time.Since(ipr.startTime))
 
 	var initialRequest bool
 	if ipr.traverser == nil {
@@ -227,7 +227,7 @@ func (rm *RequestManager) releaseRequestTask(p peer.ID, task *peertask.Task, err
 		ipr.state = graphsync.Paused
 		return
 	}
-	log.Infow("graphsync request complete", "request id", requestID, "peer", ipr.p, "total time", time.Since(ipr.startTime))
+	log.Infow("graphsync request complete", "request id", requestID.String(), "peer", ipr.p, "total time", time.Since(ipr.startTime))
 	rm.terminateRequest(requestID, ipr)
 }
 

requestmanager/utils.go

@@ -13,12 +13,12 @@ func metadataForResponses(responses []gsmsg.GraphSyncResponse) map[graphsync.Req
 	for _, response := range responses {
 		mdRaw, found := response.Extension(graphsync.ExtensionMetadata)
 		if !found {
-			log.Warnf("Unable to decode metadata in response for request id: %d", response.RequestID())
+			log.Warnf("Unable to decode metadata in response for request id: %s", response.RequestID().String())
 			continue
 		}
 		md, err := metadata.DecodeMetadata(mdRaw)
 		if err != nil {
-			log.Warnf("Unable to decode metadata in response for request id: %d", response.RequestID())
+			log.Warnf("Unable to decode metadata in response for request id: %s", response.RequestID().String())
 			continue
 		}
 		responseMetadata[response.RequestID()] = md

responsemanager/server.go

@@ -60,7 +60,7 @@ func (rm *ResponseManager) terminateRequest(key responseKey) {
 func (rm *ResponseManager) processUpdate(key responseKey, update gsmsg.GraphSyncRequest) {
 	response, ok := rm.inProgressResponses[key]
 	if !ok || response.state == graphsync.CompletingSend {
-		log.Warnf("received update for non existent request, peer %s, request ID %d", key.p.Pretty(), key.requestID)
+		log.Warnf("received update for non existent request, peer %s, request ID %s", key.p.Pretty(), key.requestID.String())
 		return
 	}
 
@@ -196,10 +196,10 @@ func (rm *ResponseManager) processRequests(p peer.ID, requests []gsmsg.GraphSync
 			networkErrorListeners: rm.networkErrorListeners,
 			connManager:           rm.connManager,
 		})
-		log.Infow("graphsync request initiated", "request id", request.ID(), "peer", p, "root", request.Root())
+		log.Infow("graphsync request initiated", "request id", request.ID().String(), "peer", p, "root", request.Root())
 		ipr, ok := rm.inProgressResponses[key]
 		if ok && ipr.state == graphsync.Running {
-			log.Warnf("there is an identical request already in progress", "request id", request.ID(), "peer", p)
+			log.Warnf("there is an identical request already in progress", "request id", request.ID().String(), "peer", p)
 		}
 
 		rm.inProgressResponses[key] =
@@ -228,7 +228,7 @@ func (rm *ResponseManager) taskDataForKey(key responseKey) queryexecutor.Respons
 	if !hasResponse || response.state == graphsync.CompletingSend {
 		return queryexecutor.ResponseTask{Empty: true}
 	}
-	log.Infow("graphsync response processing begins", "request id", key.requestID, "peer", key.p, "total time", time.Since(response.startTime))
+	log.Infow("graphsync response processing begins", "request id", key.requestID.String(), "peer", key.p, "total time", time.Since(response.startTime))
 
 	if response.loader == nil || response.traverser == nil {
 		loader, traverser, isPaused, err := (&queryPreparer{rm.requestHooks, rm.responseAssembler, rm.linkSystem, rm.maxLinksPerRequest}).prepareQuery(response.ctx, key.p, response.request, response.signals, response.subscriber)
@@ -279,7 +279,7 @@ func (rm *ResponseManager) finishTask(task *peertask.Task, err error) {
 		response.state = graphsync.Paused
 		return
 	}
-	log.Infow("graphsync response processing complete (messages stil sending)", "request id", key.requestID, "peer", key.p, "total time", time.Since(response.startTime))
+	log.Infow("graphsync response processing complete (messages stil sending)", "request id", key.requestID.String(), "peer", key.p, "total time", time.Since(response.startTime))
 
 	if err != nil {
 		response.span.RecordError(err)