beacon/light, beacon/blsync: add debug logs

beacon/blsync/block_sync.go

@@ -66,6 +66,7 @@ func (s *beaconBlockSync) Process(requester request.Requester, events []request.
 		case request.EvResponse, request.EvFail, request.EvTimeout:
 			sid, req, resp := event.RequestInfo()
 			blockRoot := common.Hash(req.(sync.ReqBeaconBlock))
+			log.Debug("Beacon block event", "type", event.Type.Name, "hash", blockRoot)
 			if resp != nil {
 				s.recentBlocks.Add(blockRoot, resp.(*types.BeaconBlock))
 			}

beacon/blsync/engineclient.go

@@ -62,6 +62,7 @@ func (ec *engineClient) updateLoop(headCh <-chan types.ChainHeadEvent) {
 	for {
 		select {
 		case <-ec.rootCtx.Done():
+			log.Debug("Stopping engine API update loop")
 			return
 
 		case event := <-headCh:
@@ -73,12 +74,14 @@ func (ec *engineClient) updateLoop(headCh <-chan types.ChainHeadEvent) {
 			fork := ec.config.ForkAtEpoch(event.BeaconHead.Epoch())
 			forkName := strings.ToLower(fork.Name)
 
+			log.Debug("Calling NewPayload", "number", event.Block.NumberU64(), "hash", event.Block.Hash())
 			if status, err := ec.callNewPayload(forkName, event); err == nil {
 				log.Info("Successful NewPayload", "number", event.Block.NumberU64(), "hash", event.Block.Hash(), "status", status)
 			} else {
 				log.Error("Failed NewPayload", "number", event.Block.NumberU64(), "hash", event.Block.Hash(), "error", err)
 			}
 
+			log.Debug("Calling ForkchoiceUpdated", "head", event.Block.Hash())
 			if status, err := ec.callForkchoiceUpdated(forkName, event); err == nil {
 				log.Info("Successful ForkchoiceUpdated", "head", event.Block.Hash(), "status", status)
 			} else {

beacon/light/api/api_server.go

@@ -88,6 +88,7 @@ func (s *ApiServer) SendRequest(id request.ID, req request.Request) {
 			log.Warn("Beacon API request failed", "type", reflect.TypeOf(req), "reqid", id, "err", err)
 			s.eventCallback(request.Event{Type: request.EvFail, Data: request.RequestResponse{ID: id, Request: req}})
 		} else {
+			log.Debug("Beacon API request answered", "type", reflect.TypeOf(req), "reqid", id)
 			s.eventCallback(request.Event{Type: request.EvResponse, Data: request.RequestResponse{ID: id, Request: req, Response: resp}})
 		}
 	}()

beacon/light/api/light_api.go

@@ -32,6 +32,7 @@ import (
 	"github.com/ethereum/go-ethereum/beacon/types"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
+	"github.com/ethereum/go-ethereum/log"
 )
 
 var (
@@ -456,21 +457,35 @@ func (api *BeaconLightApi) StartHeadListener(listener HeadEventListener) func()
 		defer wg.Done()
 
 		// Request initial data.
+		log.Debug("Requesting initial head header")
 		if head, err := api.GetHeader(common.Hash{}); err == nil {
+			log.Debug("Successfully retrieved initial head header", "slot", head.Slot, "hash", head.Hash())
 			listener.OnNewHead(head.Slot, head.Hash())
+		} else {
+			log.Debug("Failed to retrieve initial head header", "error", err)
 		}
+		log.Debug("Requesting initial optimistic update")
 		if optimisticUpdate, err := api.GetOptimisticUpdate(); err == nil {
+			log.Debug("Successfully retrieved initial optimistic update", "slot", optimisticUpdate.Attested.Slot, "hash", optimisticUpdate.Attested.Hash())
 			listener.OnOptimistic(optimisticUpdate)
+		} else {
+			log.Debug("Failed to retrieve initial optimistic update", "error", err)
 		}
+		log.Debug("Requesting initial finality update")
 		if finalityUpdate, err := api.GetFinalityUpdate(); err == nil {
+			log.Debug("Successfully retrieved initial finality update", "slot", finalityUpdate.Finalized.Slot, "hash", finalityUpdate.Finalized.Hash())
 			listener.OnFinality(finalityUpdate)
+		} else {
+			log.Debug("Failed to retrieve initial finality update", "error", err)
 		}
 
+		log.Debug("Starting event stream processing loop")
 		// Receive the stream.
 		var stream *eventsource.Stream
 		select {
 		case stream = <-streamCh:
 		case <-ctx.Done():
+			log.Debug("Stopping event stream processing loop")
 			return
 		}
 
@@ -481,8 +496,10 @@ func (api *BeaconLightApi) StartHeadListener(listener HeadEventListener) func()
 
 			case event, ok := <-stream.Events:
 				if !ok {
+					log.Debug("Event stream closed")
 					return
 				}
+				log.Debug("New event received from event stream", "type", event.Event())
 				switch event.Event() {
 				case "head":
 					slot, blockRoot, err := decodeHeadEvent([]byte(event.Data()))
@@ -529,6 +546,7 @@ func (api *BeaconLightApi) StartHeadListener(listener HeadEventListener) func()
 func (api *BeaconLightApi) startEventStream(ctx context.Context, listener *HeadEventListener) *eventsource.Stream {
 	for retry := true; retry; retry = ctxSleep(ctx, 5*time.Second) {
 		path := "/eth/v1/events?topics=head&topics=light_client_optimistic_update&topics=light_client_finality_update"
+		log.Debug("Sending event subscription request")
 		req, err := http.NewRequestWithContext(ctx, "GET", api.url+path, nil)
 		if err != nil {
 			listener.OnError(fmt.Errorf("error creating event subscription request: %v", err))
@@ -542,6 +560,7 @@ func (api *BeaconLightApi) startEventStream(ctx context.Context, listener *HeadE
 			listener.OnError(fmt.Errorf("error creating event subscription: %v", err))
 			continue
 		}
+		log.Debug("Successfully created event stream")
 		return stream
 	}
 	return nil

beacon/light/sync/update_sync.go

@@ -64,11 +64,12 @@ func (s *CheckpointInit) Process(requester request.Requester, events []request.E
 		}
 		if resp != nil {
 			if checkpoint := resp.(*types.BootstrapData); checkpoint.Header.Hash() == common.Hash(req.(ReqCheckpointData)) {
+				log.Debug("Successful checkpoint init")
 				s.chain.CheckpointInit(*checkpoint)
 				s.initialized = true
 				return
 			}
-
+			log.Debug("Failed checkpoint init")
 			requester.Fail(event.Server, "invalid checkpoint data")
 		}
 	}