From b0e14033ebedef1d23bcd39ca307bca455c89f27 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Wed, 10 Apr 2024 10:05:57 +0200 Subject: [PATCH] beacon/light, beacon/blsync: add debug logs --- beacon/blsync/block_sync.go | 1 + beacon/blsync/engineclient.go | 3 +++ beacon/light/api/api_server.go | 1 + beacon/light/api/light_api.go | 19 +++++++++++++++++++ beacon/light/sync/update_sync.go | 3 ++- 5 files changed, 26 insertions(+), 1 deletion(-) diff --git a/beacon/blsync/block_sync.go b/beacon/blsync/block_sync.go index e847e64f6d..7aef86190d 100755 --- a/beacon/blsync/block_sync.go +++ b/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)) } diff --git a/beacon/blsync/engineclient.go b/beacon/blsync/engineclient.go index 5a2d292a7d..97ef6f5cb8 100644 --- a/beacon/blsync/engineclient.go +++ b/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 { diff --git a/beacon/light/api/api_server.go b/beacon/light/api/api_server.go index 9802e5ee47..bd26052d9a 100755 --- a/beacon/light/api/api_server.go +++ b/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}}) } }() diff --git a/beacon/light/api/light_api.go b/beacon/light/api/light_api.go index 3da8310dab..75aa3b5763 100755 --- a/beacon/light/api/light_api.go +++ b/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 diff --git a/beacon/light/sync/update_sync.go b/beacon/light/sync/update_sync.go index af1176c2f1..379a760f97 100644 --- a/beacon/light/sync/update_sync.go +++ b/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") } }