Bor: increase client timeout from 5 to 10sec (to cover remote server case) (#8801)

I using `https://heimdall-api-testnet.polygon.technology/` and seems
5sec timeout is not enough sometime - even that remote service working
well (node syncing well)

most of timeouts comes from same endpoint: 
```
 [bor.heimdall] request canceled          reason="context deadline exceeded" path=/milestone/lastNoAck attempt=2
```
This commit is contained in:
Alex Sharov 2023-11-23 23:32:30 +07:00 committed by GitHub
parent 34b9a70b02
commit fdc75df6b5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 30 additions and 34 deletions

View File

@ -59,13 +59,13 @@ func borVerify(ctx context.Context, config *config, start uint64, end uint64, ha
// check if we have the given blocks
currentBlock := rawdb.ReadCurrentBlockNumber(roTx)
if currentBlock == nil {
log.Debug("[bor] Failed to fetch current block while verifying", "incoming", str)
log.Debug("[bor] no current block marker yet: syncing...", "incoming", str)
return hash, errMissingBlocks
}
head := *currentBlock
if head < end {
log.Debug("[bor] Current head block behind incoming", "block", str, "head", head, "end block", end)
log.Debug("[bor] current head block behind incoming", "block", str, "head", head, "end block", end)
return hash, errMissingBlocks
}

View File

@ -33,18 +33,18 @@ func fetchWhitelistCheckpoint(ctx context.Context, heimdallClient heimdall.IHeim
// fetch the latest checkpoint from Heimdall
checkpoint, err := heimdallClient.FetchCheckpoint(ctx, -1)
if err != nil {
config.logger.Debug("[heimdall] Failed to fetch latest checkpoint for whitelisting", "err", err)
config.logger.Debug("[bor.heimdall] Failed to fetch latest checkpoint for whitelisting", "err", err)
return blockNum, blockHash, errCheckpoint
}
config.logger.Info("[heimdall] Got new checkpoint", "start", checkpoint.StartBlock.Uint64(), "end", checkpoint.EndBlock.Uint64(), "rootHash", checkpoint.RootHash.String())
config.logger.Info("[bor.heimdall] Got new checkpoint", "start", checkpoint.StartBlock.Uint64(), "end", checkpoint.EndBlock.Uint64(), "rootHash", checkpoint.RootHash.String())
// Verify if the checkpoint fetched can be added to the local whitelist entry or not
// If verified, it returns the hash of the end block of the checkpoint. If not,
// it will return appropriate error.
hash, err := verifier.verify(ctx, config, checkpoint.StartBlock.Uint64(), checkpoint.EndBlock.Uint64(), checkpoint.RootHash.String()[2:], true)
if err != nil {
config.logger.Warn("[heimdall] Failed to whitelist checkpoint", "err", err)
config.logger.Warn("[bor.heimdall] Failed to whitelist checkpoint", "err", err)
return blockNum, blockHash, err
}
@ -65,16 +65,16 @@ func fetchWhitelistMilestone(ctx context.Context, heimdallClient heimdall.IHeimd
// fetch latest milestone
milestone, err := heimdallClient.FetchMilestone(ctx)
if errors.Is(err, heimdall.ErrServiceUnavailable) {
config.logger.Debug("[heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
config.logger.Debug("[bor.heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
return num, hash, err
}
if err != nil {
config.logger.Error("[heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
config.logger.Warn("[bor.heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
return num, hash, errMilestone
}
config.logger.Debug("[heimdall] Got new milestone", "start", milestone.StartBlock.Uint64(), "end", milestone.EndBlock.Uint64(), "hash", milestone.Hash.String())
config.logger.Debug("[bor.heimdall] Got new milestone", "start", milestone.StartBlock.Uint64(), "end", milestone.EndBlock.Uint64())
num = milestone.EndBlock.Uint64()
hash = milestone.Hash
@ -98,12 +98,12 @@ func fetchNoAckMilestone(ctx context.Context, heimdallClient heimdall.IHeimdallC
milestoneID, err := heimdallClient.FetchLastNoAckMilestone(ctx)
if errors.Is(err, heimdall.ErrServiceUnavailable) {
logger.Debug("[heimdall] Failed to fetch latest no-ack milestone", "err", err)
logger.Debug("[bor.heimdall] Failed to fetch latest no-ack milestone", "err", err)
return milestoneID, err
}
if err != nil {
logger.Error("[heimdall] Failed to fetch latest no-ack milestone", "err", err)
logger.Warn("[bor.heimdall] Failed to fetch latest no-ack milestone", "err", err)
return milestoneID, errMilestone
}
@ -113,18 +113,18 @@ func fetchNoAckMilestone(ctx context.Context, heimdallClient heimdall.IHeimdallC
func fetchNoAckMilestoneByID(ctx context.Context, heimdallClient heimdall.IHeimdallClient, milestoneID string, logger log.Logger) error {
err := heimdallClient.FetchNoAckMilestone(ctx, milestoneID)
if errors.Is(err, heimdall.ErrServiceUnavailable) {
logger.Debug("[heimdall] Failed to fetch no-ack milestone by ID", "milestoneID", milestoneID, "err", err)
logger.Debug("[bor.heimdall] Failed to fetch no-ack milestone by ID", "milestoneID", milestoneID, "err", err)
return err
}
// fixme: handle different types of errors
if errors.Is(err, ErrNotInRejectedList) {
logger.Warn("[heimdall] MilestoneID not in rejected list", "milestoneID", milestoneID, "err", err)
logger.Warn("[bor.heimdall] MilestoneID not in rejected list", "milestoneID", milestoneID, "err", err)
return err
}
if err != nil {
logger.Error("[heimdall] Failed to fetch no-ack milestone by ID ", "milestoneID", milestoneID, "err", err)
logger.Warn("[bor.heimdall] Failed to fetch no-ack milestone by ID ", "milestoneID", milestoneID, "err", err)
return errMilestone
}

View File

@ -32,7 +32,7 @@ var (
const (
stateFetchLimit = 50
apiHeimdallTimeout = 5 * time.Second
apiHeimdallTimeout = 10 * time.Second
retryCall = 5 * time.Second
)
@ -96,7 +96,7 @@ func (h *HeimdallClient) StateSyncEvents(ctx context.Context, fromID uint64, to
return nil, err
}
h.logger.Debug("[heimdall] Fetching state sync events", "queryParams", url.RawQuery)
h.logger.Debug("[bor.heimdall] Fetching state sync events", "queryParams", url.RawQuery)
ctx = withRequestType(ctx, stateSyncRequest)
@ -276,7 +276,6 @@ func FetchWithRetry[T any](ctx context.Context, client http.Client, url *url.URL
// request data once
request := &Request{client: client, url: url, start: time.Now()}
result, err := Fetch[T](ctx, request)
if err == nil {
return result, nil
}
@ -285,14 +284,14 @@ func FetchWithRetry[T any](ctx context.Context, client http.Client, url *url.URL
// yet in heimdall. E.g. when the hardfork hasn't hit yet but heimdall
// is upgraded.
if errors.Is(err, ErrServiceUnavailable) {
logger.Debug("Heimdall service unavailable at the moment", "path", url.Path, "error", err)
logger.Debug("[bor.heimdall] service unavailable at the moment", "path", url.Path, "error", err)
return nil, err
}
// attempt counter
attempt := 1
logger.Warn("an error while trying fetching from Heimdall", "path", url.Path, "attempt", attempt, "error", err)
logger.Warn("[bor.heimdall] an error while fetching", "path", url.Path, "attempt", attempt, "error", err)
// create a new ticker for retrying the request
ticker := time.NewTicker(retryCall)
@ -302,17 +301,14 @@ func FetchWithRetry[T any](ctx context.Context, client http.Client, url *url.URL
retryLoop:
for {
logger.Info("Retrying again in 5 seconds to fetch data from Heimdall", "path", url.Path, "attempt", attempt)
attempt++
select {
case <-ctx.Done():
logger.Debug("Shutdown detected, terminating request", "err", ctx.Err())
logger.Debug("[bor.heimdall] request canceled", "reason", ctx.Err(), "path", url.Path, "attempt", attempt)
return nil, ctx.Err()
case <-closeCh:
logger.Debug("Shutdown detected, terminating request by closing")
logger.Debug("[bor.heimdall] shutdown detected, terminating request", "path", url.Path)
return nil, ErrShutdownDetected
case <-ticker.C:
@ -320,13 +316,13 @@ retryLoop:
result, err = Fetch[T](ctx, request)
if errors.Is(err, ErrServiceUnavailable) {
logger.Debug("Heimdall service unavailable at the moment", "path", url.Path, "error", err)
logger.Debug("[bor.heimdall] service unavailable at the moment", "path", url.Path, "attempt", attempt, "error", err)
return nil, err
}
if err != nil {
if attempt%logEach == 0 {
logger.Warn("an error while trying fetching from Heimdall", "path", url.Path, "attempt", attempt, "error", err)
logger.Warn("[bor.heimdall] an error while trying fetching", "path", url.Path, "attempt", attempt, "error", err)
}
continue retryLoop

View File

@ -27,7 +27,7 @@ func (h *HeimdallGRPCServer) Span(ctx context.Context, in *proto.SpanRequest) (*
result, err := h.heimdall.Span(ctx, in.ID)
if err != nil {
h.logger.Error("[heimdall] Error while fetching span")
h.logger.Error("[bor.heimdall] Error while fetching span")
return nil, err
}
@ -106,7 +106,7 @@ func (h *HeimdallGRPCServer) FetchCheckpointCount(ctx context.Context, in *empty
count, err := h.heimdall.FetchCheckpointCount(ctx)
if err != nil {
h.logger.Error("[heimdall] Error while fetching checkpoint count")
h.logger.Error("[bor.heimdall] Error while fetching checkpoint count")
return nil, err
}
@ -121,7 +121,7 @@ func (h *HeimdallGRPCServer) FetchCheckpoint(ctx context.Context, in *proto.Fetc
_ /*checkpoint*/, err := h.heimdall.FetchCheckpoint(ctx, in.ID)
if err != nil {
h.logger.Error("[heimdall] Error while fetching checkpoint")
h.logger.Error("[bor.heimdall] Error while fetching checkpoint")
return nil, err
}
@ -159,7 +159,7 @@ func (h *HeimdallGRPCServer) StateSyncEvents(req *proto.StateSyncEventsRequest,
height, events, err := h.heimdall.StateSyncEvents(context.Background(), fromId, int64(req.ToTime), int(req.Limit))
if err != nil {
h.logger.Error("[heimdall] Error while fetching event records", "error", err)
h.logger.Error("[bor.heimdall] Error while fetching event records", "error", err)
return status.Errorf(codes.Internal, err.Error())
}
@ -187,7 +187,7 @@ func (h *HeimdallGRPCServer) StateSyncEvents(req *proto.StateSyncEventsRequest,
})
if err != nil {
h.logger.Error("[heimdall] Error while sending event record", "error", err)
h.logger.Error("[bor.heimdall] Error while sending event record", "error", err)
return status.Errorf(codes.Internal, err.Error())
}
@ -219,16 +219,16 @@ func StartHeimdallServer(shutDownCtx context.Context, heimdall heimdall.Heimdall
go func() {
if err := grpcServer.Serve(lis); err != nil {
logger.Error("[heimdall] failed to serve grpc server", "err", err)
logger.Error("[bor.heimdall] failed to serve grpc server", "err", err)
}
<-shutDownCtx.Done()
grpcServer.Stop()
lis.Close()
logger.Info("[heimdall] GRPC Server stopped", "addr", addr)
logger.Info("[bor.heimdall] GRPC Server stopped", "addr", addr)
}()
logger.Info("[heimdall] GRPC Server started", "addr", addr)
logger.Info("[bor.heimdall] GRPC Server started", "addr", addr)
return nil
}
@ -242,7 +242,7 @@ func withLoggingUnaryInterceptor(logger log.Logger) grpc.ServerOption {
err = status.Errorf(codes.Internal, err.Error())
}
logger.Debug("[heimdall] Request", "method", info.FullMethod, "duration", time.Since(start), "error", err)
logger.Debug("[bor.heimdall] Request", "method", info.FullMethod, "duration", time.Since(start), "error", err)
return h, err
})