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

@@ -90,6 +90,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 (
@@ -459,21 +460,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
 		}
 
@@ -484,8 +499,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()))
@@ -532,6 +549,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))
@@ -545,6 +563,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

@@ -84,6 +84,7 @@ func (s *CheckpointInit) Process(requester request.Requester, events []request.E
 	if s.initialized {
 		return
 	}
+
 	for _, event := range events {
 		switch event.Type {
 		case request.EvResponse, request.EvFail, request.EvTimeout:
@@ -132,10 +133,12 @@ func (s *CheckpointInit) Process(requester request.Requester, events []request.E
 				newState.state = ssPrintStatus
 				s.serverState[sid.Server] = newState
 			}
+
 		case request.EvUnregistered:
 			delete(s.serverState, event.Server)
 		}
 	}
+
 	// start a request if possible
 	for _, server := range requester.CanSendTo() {
 		switch s.serverState[server].state {
@@ -156,6 +159,7 @@ func (s *CheckpointInit) Process(requester request.Requester, events []request.E
 			s.serverState[server] = newState
 		}
 	}
+
 	// print log message if necessary
 	for server, state := range s.serverState {
 		if state.state != ssPrintStatus {