bor: logs prefix, grep-friendly (#8787)

This commit is contained in:
Alex Sharov 2023-11-20 12:16:06 +07:00 committed by GitHub
parent 06c508c02c
commit 2f17848b76
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 64 additions and 62 deletions

View File

@ -998,19 +998,19 @@ func (c *Bor) Finalize(config *chain.Config, header *types.Header, state *state.
if c.blockReader != nil {
// check and commit span
if err := c.checkAndCommitSpan(state, header, cx, syscall); err != nil {
c.logger.Error("Error while committing span", "err", err)
c.logger.Error("[bor] Error while committing span", "err", err)
return nil, types.Receipts{}, err
}
// commit states
if err := c.CommitStates(state, header, cx, syscall); err != nil {
c.logger.Error("Error while committing states", "err", err)
c.logger.Error("[bor] Error while committing states", "err", err)
return nil, types.Receipts{}, err
}
}
}
if err := c.changeContractCodeIfNeeded(headerNumber, state); err != nil {
c.logger.Error("Error changing contract code", "err", err)
c.logger.Error("[bor] Error changing contract code", "err", err)
return nil, types.Receipts{}, err
}
@ -1033,7 +1033,7 @@ func (c *Bor) changeContractCodeIfNeeded(headerNumber uint64, state *state.Intra
}
for addr, account := range allocs {
c.logger.Trace("change contract code", "address", addr)
c.logger.Trace("[bor] change contract code", "address", addr)
state.SetCode(addr, account.Code)
}
}
@ -1062,19 +1062,19 @@ func (c *Bor) FinalizeAndAssemble(chainConfig *chain.Config, header *types.Heade
if c.blockReader != nil {
// check and commit span
if err := c.checkAndCommitSpan(state, header, cx, syscall); err != nil {
c.logger.Error("Error while committing span", "err", err)
c.logger.Error("[bor] Error while committing span", "err", err)
return nil, nil, types.Receipts{}, err
}
// commit states
if err := c.CommitStates(state, header, cx, syscall); err != nil {
c.logger.Error("Error while committing states", "err", err)
c.logger.Error("[bor] Error while committing states", "err", err)
return nil, nil, types.Receipts{}, err
}
}
}
if err := c.changeContractCodeIfNeeded(headerNumber, state); err != nil {
c.logger.Error("Error changing contract code", "err", err)
c.logger.Error("[bor] Error changing contract code", "err", err)
return nil, nil, types.Receipts{}, err
}
@ -1123,7 +1123,7 @@ func (c *Bor) Seal(chain consensus.ChainHeaderReader, block *types.Block, result
// For 0-period chains, refuse to seal empty blocks (no reward but would spin sealing)
if c.config.CalculatePeriod(number) == 0 && len(block.Transactions()) == 0 {
c.logger.Trace("Sealing paused, waiting for transactions")
c.logger.Trace("[bor] Sealing paused, waiting for transactions")
return nil
}
@ -1161,11 +1161,11 @@ func (c *Bor) Seal(chain consensus.ChainHeaderReader, block *types.Block, result
go func() {
// Wait until sealing is terminated or delay timeout.
c.logger.Info("Waiting for slot to sign and propagate", "number", number, "hash", header.Hash, "delay", common.PrettyDuration(delay), "TxCount", block.Transactions().Len(), "Signer", signer)
c.logger.Info("[bor] Waiting for slot to sign and propagate", "number", number, "hash", header.Hash, "delay", common.PrettyDuration(delay), "TxCount", block.Transactions().Len(), "Signer", signer)
select {
case <-stop:
c.logger.Info("Stopped sealing operation for block", "number", number)
c.logger.Info("[bor] Stopped sealing operation for block", "number", number)
return
case <-time.After(delay):
@ -1176,7 +1176,7 @@ func (c *Bor) Seal(chain consensus.ChainHeaderReader, block *types.Block, result
if wiggle > 0 {
c.logger.Info(
"Sealed out-of-turn",
"[bor] Sealed out-of-turn",
"number", number,
"wiggle", common.PrettyDuration(wiggle),
"delay", delay,
@ -1185,7 +1185,7 @@ func (c *Bor) Seal(chain consensus.ChainHeaderReader, block *types.Block, result
)
} else {
c.logger.Info(
"Sealed in-turn",
"[bor] Sealed in-turn",
"number", number,
"delay", delay,
"headerDifficulty", header.Difficulty,
@ -1572,7 +1572,7 @@ func getUpdatedValidatorSet(oldValidatorSet *valset.ValidatorSet, newVals []*val
}
if err := v.UpdateWithChangeSet(changes, logger); err != nil {
logger.Error("Error while updating change set", "error", err)
logger.Error("[bor] Error while updating change set", "error", err)
}
return v

View File

@ -65,7 +65,7 @@ func (gc *GenesisContractsClient) LastStateId(syscall consensus.SystemCall) (*bi
data, err := gc.stateReceiverABI.Pack(method)
if err != nil {
gc.logger.Error("Unable to pack tx for LastStateId", "err", err)
gc.logger.Error("[bor] Unable to pack tx for LastStateId", "err", err)
return nil, err
}

View File

@ -5,6 +5,7 @@ import (
"context"
"errors"
"fmt"
"github.com/ledgerwatch/erigon-lib/metrics"
"github.com/ledgerwatch/erigon/consensus/bor/finality/generics"
@ -58,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(fmt.Sprintf("Failed to fetch current block from blockchain while verifying incoming %s", str))
log.Debug("[bor] Failed to fetch current block from blockchain while verifying incoming", "str", str)
return hash, errMissingBlocks
}
head := *currentBlock
if head < end {
log.Debug(fmt.Sprintf("Current head block behind incoming %s 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
}
@ -78,14 +79,14 @@ func borVerify(ctx context.Context, config *config, start uint64, end uint64, ha
localHash, err = config.borAPI.GetRootHash(start, end)
if err != nil {
log.Debug("Failed to get root hash of given block range while whitelisting checkpoint", "start", start, "end", end, "err", err)
log.Debug("[bor] Failed to get root hash of given block range while whitelisting checkpoint", "start", start, "end", end, "err", err)
return hash, errRootHash
}
} else {
// in case of milestone(isCheckpoint==false) get the hash of endBlock
block, err := config.blockReader.BlockByNumber(context.Background(), roTx, end)
if err != nil {
log.Debug("Failed to get end block hash while whitelisting milestone", "number", end, "err", err)
log.Debug("[bor] Failed to get end block hash while whitelisting milestone", "number", end, "err", err)
return hash, errEndBlock
}
@ -96,9 +97,9 @@ func borVerify(ctx context.Context, config *config, start uint64, end uint64, ha
if localHash != hash {
if isCheckpoint {
log.Warn("Root hash mismatch while whitelisting checkpoint", "expected", localHash, "got", hash)
log.Warn("[bor] Root hash mismatch while whitelisting checkpoint", "expected", localHash, "got", hash)
} else {
log.Warn("End block hash mismatch while whitelisting milestone", "expected", localHash, "got", hash)
log.Warn("[bor] End block hash mismatch while whitelisting milestone", "expected", localHash, "got", hash)
}
var (
@ -123,9 +124,9 @@ func borVerify(ctx context.Context, config *config, start uint64, end uint64, ha
}
if isCheckpoint {
log.Warn("Rewinding chain due to checkpoint root hash mismatch", "number", rewindTo)
log.Warn("[bor] Rewinding chain due to checkpoint root hash mismatch", "number", rewindTo)
} else {
log.Warn("Rewinding chain due to milestone endblock hash mismatch", "number", rewindTo)
log.Warn("[bor] Rewinding chain due to milestone endblock hash mismatch", "number", rewindTo)
}
rewindBack(head, rewindTo)
@ -136,11 +137,11 @@ func borVerify(ctx context.Context, config *config, start uint64, end uint64, ha
// fetch the end block hash
block, err := config.blockReader.BlockByNumber(context.Background(), roTx, end)
if err != nil {
log.Debug("Failed to get end block hash while whitelisting", "err", err)
log.Debug("[bor] Failed to get end block hash while whitelisting", "err", err)
return hash, errEndBlock
}
if block == nil {
log.Debug("Current header behind the end block", "block", end)
log.Debug("[bor] Current header behind the end block", "block", end)
return hash, errEndBlock
}

View File

@ -109,7 +109,7 @@ func retryHeimdallHandler(fn heimdallHandler, config *config, tickerDuration tim
}
if config.heimdall == nil {
config.logger.Error("bor engine not available")
config.logger.Error("[bor] engine not available")
return
}
@ -120,7 +120,7 @@ func retryHeimdallHandler(fn heimdallHandler, config *config, tickerDuration tim
cancel()
if err != nil {
config.logger.Warn(fmt.Sprintf("unable to start the %s service - first run", fnName), "err", err)
config.logger.Warn(fmt.Sprintf("[bor] unable to start the %s service - first run", fnName), "err", err)
}
ticker := time.NewTicker(tickerDuration)
@ -130,7 +130,7 @@ func retryHeimdallHandler(fn heimdallHandler, config *config, tickerDuration tim
defer func() {
r := recover()
if r != nil {
log.Warn(fmt.Sprintf("service %s- run failed with panic", fnName), "err", r)
log.Warn(fmt.Sprintf("[bor] service %s- run failed with panic", fnName), "err", r)
}
}()
@ -142,7 +142,7 @@ func retryHeimdallHandler(fn heimdallHandler, config *config, tickerDuration tim
cancel()
if err != nil {
config.logger.Warn(fmt.Sprintf("unable to handle %s", fnName), "err", err)
config.logger.Warn(fmt.Sprintf("[bor] unable to handle %s", fnName), "err", err)
}
case <-config.closeCh:
return

View File

@ -112,12 +112,12 @@ func (m *milestone) LockMutex(endBlockNum uint64) bool {
m.finality.Lock()
if m.doExist && endBlockNum <= m.Number { //if endNum is less than whitelisted milestone, then we won't lock the sprint
log.Debug("endBlockNumber is less than or equal to latesMilestoneNumber", "endBlock Number", endBlockNum, "LatestMilestone Number", m.Number)
log.Debug("[bor] endBlockNumber is less than or equal to latesMilestoneNumber", "endBlock Number", endBlockNum, "LatestMilestone Number", m.Number)
return false
}
if m.Locked && endBlockNum < m.LockedMilestoneNumber {
log.Debug("endBlockNum is less than locked milestone number", "endBlock Number", endBlockNum, "Locked Milestone Number", m.LockedMilestoneNumber)
log.Debug("[bor] endBlockNum is less than locked milestone number", "endBlock Number", endBlockNum, "Locked Milestone Number", m.LockedMilestoneNumber)
return false
}
@ -159,7 +159,7 @@ func (m *milestone) UnlockSprint(endBlockNum uint64) {
err := rawdb.WriteLockField(m.db, m.Locked, m.LockedMilestoneNumber, m.LockedMilestoneHash, m.LockedMilestoneIDs)
if err != nil {
log.Error("Error in writing lock data of milestone to db", "err", err)
log.Error("[bor] Error in writing lock data of milestone to db", "err", err)
}
}
@ -177,7 +177,7 @@ func (m *milestone) RemoveMilestoneID(milestoneId string) {
err := rawdb.WriteLockField(m.db, m.Locked, m.LockedMilestoneNumber, m.LockedMilestoneHash, m.LockedMilestoneIDs)
if err != nil {
log.Error("Error in writing lock data of milestone to db", "err", err)
log.Error("[bor] Error in writing lock data of milestone to db", "err", err)
}
}
@ -255,25 +255,25 @@ func (m *milestone) ProcessFutureMilestone(num uint64, hash common.Hash) {
err := rawdb.WriteLockField(m.db, m.Locked, m.LockedMilestoneNumber, m.LockedMilestoneHash, m.LockedMilestoneIDs)
if err != nil {
log.Error("Error in writing lock data of milestone to db", "err", err)
log.Error("[bor] Error in writing lock data of milestone to db", "err", err)
}
}
// EnqueueFutureMilestone add the future milestone to the list
func (m *milestone) enqueueFutureMilestone(key uint64, hash common.Hash) {
if _, ok := m.FutureMilestoneList[key]; ok {
log.Debug("Future milestone already exist", "endBlockNumber", key, "futureMilestoneHash", hash)
log.Debug("[bor] Future milestone already exist", "endBlockNumber", key, "futureMilestoneHash", hash)
return
}
log.Debug("Enqueing new future milestone", "endBlockNumber", key, "futureMilestoneHash", hash)
log.Debug("[bor] Enqueing new future milestone", "endBlockNumber", key, "futureMilestoneHash", hash)
m.FutureMilestoneList[key] = hash
m.FutureMilestoneOrder = append(m.FutureMilestoneOrder, key)
err := rawdb.WriteFutureMilestoneList(m.db, m.FutureMilestoneOrder, m.FutureMilestoneList)
if err != nil {
log.Error("Error in writing future milestone data to db", "err", err)
log.Error("[bor] Error in writing future milestone data to db", "err", err)
}
FutureMilestoneMeter.Set(key)
@ -286,6 +286,6 @@ func (m *milestone) dequeueFutureMilestone() {
err := rawdb.WriteFutureMilestoneList(m.db, m.FutureMilestoneOrder, m.FutureMilestoneList)
if err != nil {
log.Error("Error in writing future milestone data to db", "err", err)
log.Error("[bor] Error in writing future milestone data to db", "err", err)
}
}

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("Failed to fetch latest checkpoint for whitelisting", "err", err)
config.logger.Debug("[heimdall] Failed to fetch latest checkpoint for whitelisting", "err", err)
return blockNum, blockHash, errCheckpoint
}
config.logger.Info("Got new checkpoint from heimdall", "start", checkpoint.StartBlock.Uint64(), "end", checkpoint.EndBlock.Uint64(), "rootHash", checkpoint.RootHash.String())
config.logger.Info("[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("Failed to whitelist checkpoint", "err", err)
config.logger.Warn("[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("Failed to fetch latest milestone for whitelisting", "err", err)
config.logger.Debug("[heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
return num, hash, err
}
if err != nil {
config.logger.Error("Failed to fetch latest milestone for whitelisting", "err", err)
config.logger.Error("[heimdall] Failed to fetch latest milestone for whitelisting", "err", err)
return num, hash, errMilestone
}
config.logger.Debug("Got new milestone from heimdall", "start", milestone.StartBlock.Uint64(), "end", milestone.EndBlock.Uint64(), "hash", milestone.Hash.String())
config.logger.Debug("[heimdall] Got new milestone", "start", milestone.StartBlock.Uint64(), "end", milestone.EndBlock.Uint64(), "hash", milestone.Hash.String())
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("Failed to fetch latest no-ack milestone", "err", err)
logger.Debug("[heimdall] Failed to fetch latest no-ack milestone", "err", err)
return milestoneID, err
}
if err != nil {
logger.Error("Failed to fetch latest no-ack milestone", "err", err)
logger.Error("[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("Failed to fetch no-ack milestone by ID", "milestoneID", milestoneID, "err", err)
logger.Debug("[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("MilestoneID not in rejected list", "milestoneID", milestoneID, "err", err)
logger.Warn("[heimdall] MilestoneID not in rejected list", "milestoneID", milestoneID, "err", err)
return err
}
if err != nil {
logger.Error("Failed to fetch no-ack milestone by ID ", "milestoneID", milestoneID, "err", err)
logger.Error("[heimdall] Failed to fetch no-ack milestone by ID ", "milestoneID", milestoneID, "err", err)
return errMilestone
}

View File

@ -5,13 +5,14 @@ import (
"encoding/json"
"errors"
"fmt"
"github.com/ledgerwatch/erigon-lib/metrics"
"io"
"net/http"
"net/url"
"sort"
"time"
"github.com/ledgerwatch/erigon-lib/metrics"
"github.com/ledgerwatch/erigon/consensus/bor/clerk"
"github.com/ledgerwatch/erigon/consensus/bor/heimdall/checkpoint"
"github.com/ledgerwatch/erigon/consensus/bor/heimdall/milestone"
@ -95,7 +96,7 @@ func (h *HeimdallClient) StateSyncEvents(ctx context.Context, fromID uint64, to
return nil, err
}
h.logger.Debug("Fetching state sync events", "queryParams", url.RawQuery)
h.logger.Debug("[heimdall] Fetching state sync events", "queryParams", url.RawQuery)
ctx = withRequestType(ctx, stateSyncRequest)

View File

@ -38,7 +38,7 @@ func (c *ChainSpanner) GetCurrentSpan(syscall consensus.SystemCall) (*Span, erro
data, err := c.validatorSet.Pack(method)
if err != nil {
c.logger.Error("Unable to pack tx for getCurrentSpan", "error", err)
c.logger.Error("[bor] Unable to pack tx for getCurrentSpan", "error", err)
return nil, err
}
@ -128,7 +128,7 @@ func (c *ChainSpanner) CommitSpan(heimdallSpan HeimdallSpan, syscall consensus.S
return err
}
c.logger.Debug("✅ Committing new span",
c.logger.Debug("[bor] ✅ Committing new span",
"id", heimdallSpan.ID,
"startBlock", heimdallSpan.StartBlock,
"endBlock", heimdallSpan.EndBlock,
@ -145,7 +145,7 @@ func (c *ChainSpanner) CommitSpan(heimdallSpan HeimdallSpan, syscall consensus.S
producerBytes,
)
if err != nil {
c.logger.Error("Unable to pack tx for commitSpan", "error", err)
c.logger.Error("[bor] Unable to pack tx for commitSpan", "error", err)
return err
}

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("Error while fetching span")
h.logger.Error("[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("Error while fetching checkpoint count")
h.logger.Error("[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("Error while fetching checkpoint")
h.logger.Error("[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("Error while fetching event records", "error", err)
h.logger.Error("[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("Error while sending event record", "error", err)
h.logger.Error("[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("failed to serve grpc server", "err", err)
logger.Error("[heimdall] failed to serve grpc server", "err", err)
}
<-shutDownCtx.Done()
grpcServer.Stop()
lis.Close()
logger.Info("GRPC Server stopped", "addr", addr)
logger.Info("[heimdall] GRPC Server stopped", "addr", addr)
}()
logger.Info("GRPC Server started", "addr", addr)
logger.Info("[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("Request", "method", info.FullMethod, "duration", time.Since(start), "error", err)
logger.Debug("[heimdall] Request", "method", info.FullMethod, "duration", time.Since(start), "error", err)
return h, err
})