From 673975b5fad2abb9421a54668e24fdfab1d30b72 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 | 4 ++++ 5 files changed, 28 insertions(+) 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 cde317af56..f37c474e97 100755 --- a/beacon/light/api/api_server.go +++ b/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}}) } }() diff --git a/beacon/light/api/light_api.go b/beacon/light/api/light_api.go index 2bee61cde1..8719a2624b 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 ( @@ -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 diff --git a/beacon/light/sync/update_sync.go b/beacon/light/sync/update_sync.go index bbf7e19d4e..9549ee5992 100644 --- a/beacon/light/sync/update_sync.go +++ b/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 {