From 88fd4717f09c5b2a6f73e7a12315423af15cbcd4 Mon Sep 17 00:00:00 2001 From: pk910 Date: Fri, 25 Aug 2023 10:31:10 +0200 Subject: [PATCH] lower log verbosity for recoverable errors (show warning only) --- indexer/cacheLogic.go | 9 ++------- indexer/client.go | 12 +++++++----- indexer/epochStats.go | 27 +++++++++------------------ indexer/synchronizer.go | 7 +------ rpc/beaconapi.go | 17 ++--------------- rpc/beaconstream.go | 5 +++-- utils/logging.go | 12 ++++++++++++ utils/process.go | 9 +++++++++ 8 files changed, 45 insertions(+), 53 deletions(-) diff --git a/indexer/cacheLogic.go b/indexer/cacheLogic.go index 6de3233d..ddf3a120 100644 --- a/indexer/cacheLogic.go +++ b/indexer/cacheLogic.go @@ -1,7 +1,6 @@ package indexer import ( - "runtime/debug" "time" "github.com/pk910/light-beaconchain-explorer/db" @@ -10,11 +9,7 @@ import ( ) func (cache *indexerCache) runCacheLoop() { - defer func() { - if err := recover(); err != nil { - logger.WithError(err.(error)).Errorf("uncaught panic in runCacheLoop subroutine: %v, stack: %v", err, string(debug.Stack())) - } - }() + defer utils.HandleSubroutinePanic("runCacheLoop") for { select { @@ -225,7 +220,7 @@ func (cache *indexerCache) processOrphanedBlocks(processedEpoch int64) error { if blockRef.Orphaned { logger.Debugf("processed duplicate orphaned block: 0x%x", blockRef.Root) } else { - logger.Warnf("processed duplicate canonical block in orphaned handler: 0x%x", blockRef.Root) + logger.Debugf("processed duplicate canonical block in orphaned handler: 0x%x", blockRef.Root) } delete(orphanedBlocks, string(blockRef.Root)) } diff --git a/indexer/client.go b/indexer/client.go index 5ee20474..364c6b19 100644 --- a/indexer/client.go +++ b/indexer/client.go @@ -81,6 +81,8 @@ func (client *IndexerClient) GetStatus() string { } func (client *IndexerClient) runIndexerClientLoop() { + defer utils.HandleSubroutinePanic("runIndexerClientLoop") + for { err := client.runIndexerClient() if err != nil { @@ -91,7 +93,7 @@ func (client *IndexerClient) runIndexerClientLoop() { } else if client.retryCounter > 5 { waitTime = 60 } - logger.WithField("client", client.clientName).Errorf("indexer client error: %v, retrying in %v sec...", err, waitTime) + logger.WithField("client", client.clientName).Warnf("indexer client error: %v, retrying in %v sec...", err, waitTime) time.Sleep(time.Duration(waitTime) * time.Second) } else { return @@ -204,19 +206,19 @@ func (client *IndexerClient) runIndexerClient() error { case rpc.StreamFinalizedEvent: client.processFinalizedEvent(evt.Data.(*rpctypes.StandardV1StreamedFinalizedCheckpointEvent)) } - logger.WithField("client", client.clientName).Debugf("event (%v) processing time: %v ms", evt.Event, time.Since(now).Milliseconds()) + logger.WithField("client", client.clientName).Tracef("event (%v) processing time: %v ms", evt.Event, time.Since(now).Milliseconds()) client.lastStreamEvent = time.Now() case ready := <-blockStream.ReadyChan: if client.isConnected != ready { client.isConnected = ready if ready { - logger.WithField("client", client.clientName).Info("RPC event stream connected") + logger.WithField("client", client.clientName).Debug("RPC event stream connected") } else { - logger.WithField("client", client.clientName).Info("RPC event stream disconnected") + logger.WithField("client", client.clientName).Debug("RPC event stream disconnected") } } case <-time.After(eventTimeout): - logger.WithField("client", client.clientName).Info("no head event since 30 secs, polling chain head") + logger.WithField("client", client.clientName).Debug("no head event since 30 secs, polling chain head") err := client.pollLatestBlocks() if err != nil { client.isConnected = false diff --git a/indexer/epochStats.go b/indexer/epochStats.go index b22a3135..7d5b791c 100644 --- a/indexer/epochStats.go +++ b/indexer/epochStats.go @@ -3,7 +3,6 @@ package indexer import ( "bytes" "fmt" - "runtime/debug" "strconv" "strings" "sync" @@ -166,11 +165,7 @@ func (client *IndexerClient) ensureEpochStats(epoch uint64, head []byte) error { } func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, proposerRsp *rpctypes.StandardV1ProposerDutiesResponse) { - defer func() { - if err := recover(); err != nil { - logger.WithField("client", client.clientName).Errorf("uncaught panic in ensureEpochStats subroutine: %v, stack: %v", err, string(debug.Stack())) - } - }() + defer utils.HandleSubroutinePanic("ensureEpochStatsLazy") epochStats.dutiesMutex.Lock() defer epochStats.dutiesMutex.Unlock() @@ -187,11 +182,11 @@ func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, propos logger.WithField("client", client.clientName).Warnf("could not lazy load proposer duties for epoch %v: %v", epochStats.Epoch, err) } if proposerRsp == nil { - logger.WithField("client", client.clientName).Errorf("could not find proposer duties for epoch %v", epochStats.Epoch) + logger.WithField("client", client.clientName).Warnf("could not find proposer duties for epoch %v", epochStats.Epoch) return } if !bytes.Equal(proposerRsp.DependentRoot, epochStats.DependentRoot) { - logger.WithField("client", client.clientName).Errorf("got unexpected dependend root for proposer duties %v (got: %v, expected: 0x%x)", epochStats.Epoch, proposerRsp.DependentRoot.String(), epochStats.DependentRoot) + logger.WithField("client", client.clientName).Warnf("got unexpected dependend root for proposer duties %v (got: %v, expected: 0x%x)", epochStats.Epoch, proposerRsp.DependentRoot.String(), epochStats.DependentRoot) return } } @@ -216,7 +211,7 @@ func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, propos } else { parsedHeader, err := client.rpcClient.GetBlockHeaderByBlockroot(epochStats.DependentRoot) if err != nil { - logger.WithField("client", client.clientName).Errorf("could not get dependent block header for epoch %v (0x%x)", epochStats.Epoch, epochStats.DependentRoot) + logger.WithField("client", client.clientName).Warnf("could not get dependent block header for epoch %v (0x%x)", epochStats.Epoch, epochStats.DependentRoot) } if parsedHeader.Data.Header.Message.Slot == 0 { epochStats.dependentStateRef = "genesis" @@ -238,7 +233,7 @@ func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, propos } parsedCommittees, err := client.rpcClient.GetCommitteeDuties(epochStats.dependentStateRef, epochStats.Epoch) if err != nil { - logger.WithField("client", client.clientName).Errorf("error retrieving committees data: %v", err) + logger.WithField("client", client.clientName).Warnf("error retrieving committees data: %v", err) return } epochStats.attestorAssignments = map[string][]uint64{} @@ -269,13 +264,13 @@ func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, propos } parsedSyncCommittees, err := client.rpcClient.GetSyncCommitteeDuties(syncCommitteeState, epochStats.Epoch) if err != nil { - logger.WithField("client", client.clientName).Errorf("error retrieving sync_committees for epoch %v (state: %v): %v", epochStats.Epoch, syncCommitteeState, err) + logger.WithField("client", client.clientName).Warnf("error retrieving sync_committees for epoch %v (state: %v): %v", epochStats.Epoch, syncCommitteeState, err) } epochStats.syncAssignments = make([]uint64, len(parsedSyncCommittees.Data.Validators)) for i, valIndexStr := range parsedSyncCommittees.Data.Validators { valIndexU64, err := strconv.ParseUint(valIndexStr, 10, 64) if err != nil { - logger.WithField("client", client.clientName).Errorf("in sync_committee for epoch %d validator %d has bad validator index: %q", epochStats.Epoch, i, valIndexStr) + logger.WithField("client", client.clientName).Warnf("in sync_committee for epoch %d validator %d has bad validator index: %q", epochStats.Epoch, i, valIndexStr) continue } epochStats.syncAssignments[i] = valIndexU64 @@ -284,11 +279,7 @@ func (epochStats *EpochStats) ensureEpochStatsLazy(client *IndexerClient, propos } func (epochStats *EpochStats) ensureValidatorStatsLazy(client *IndexerClient, stateRef string) { - defer func() { - if err := recover(); err != nil { - logger.WithField("client", client.clientName).Errorf("uncaught panic in ensureValidatorStats subroutine: %v, stack: %v", err, string(debug.Stack())) - } - }() + defer utils.HandleSubroutinePanic("ensureValidatorStatsLazy") epochStats.loadValidatorStats(client, stateRef) } @@ -314,7 +305,7 @@ func (epochStats *EpochStats) loadValidatorStats(client *IndexerClient, stateRef <-client.indexerCache.validatorLoadingLimiter if err != nil { - logger.Errorf("error fetching epoch %v validators: %v", epochStats.Epoch, err) + logger.Warnf("error fetching epoch %v validators: %v", epochStats.Epoch, err) return } client.indexerCache.setLastValidators(epochStats.Epoch, epochValidators) diff --git a/indexer/synchronizer.go b/indexer/synchronizer.go index 43856054..da2638e1 100644 --- a/indexer/synchronizer.go +++ b/indexer/synchronizer.go @@ -2,7 +2,6 @@ package indexer import ( "fmt" - "runtime/debug" "sync" "time" @@ -67,11 +66,7 @@ func (sync *synchronizerState) startSync(startEpoch uint64) { } func (sync *synchronizerState) runSync() { - defer func() { - if err := recover(); err != nil { - synclogger.Errorf("uncaught panic in runSync subroutine: %v, stack: %v", err, string(debug.Stack())) - } - }() + defer utils.HandleSubroutinePanic("runSync") sync.runMutex.Lock() defer sync.runMutex.Unlock() diff --git a/rpc/beaconapi.go b/rpc/beaconapi.go index b0585665..314db5eb 100644 --- a/rpc/beaconapi.go +++ b/rpc/beaconapi.go @@ -6,7 +6,6 @@ import ( "fmt" "io" "net/http" - "net/url" "strconv" "time" @@ -38,13 +37,7 @@ func NewBeaconClient(endpoint string, name string, headers map[string]string) (* var errNotFound = errors.New("not found 404") func (bc *BeaconClient) get(requrl string) ([]byte, error) { - urlData, _ := url.Parse(requrl) - var logurl string - if urlData != nil { - logurl = urlData.Redacted() - } else { - logurl = requrl - } + logurl := utils.GetRedactedUrl(requrl) t0 := time.Now() defer func() { logger.WithField("client", bc.name).Debugf("RPC call (byte): %v [%v ms]", logurl, time.Since(t0).Milliseconds()) @@ -79,13 +72,7 @@ func (bc *BeaconClient) get(requrl string) ([]byte, error) { } func (bc *BeaconClient) getJson(requrl string, returnValue interface{}) error { - urlData, _ := url.Parse(requrl) - var logurl string - if urlData != nil { - logurl = urlData.Redacted() - } else { - logurl = requrl - } + logurl := utils.GetRedactedUrl(requrl) t0 := time.Now() defer func() { logger.WithField("client", bc.name).Debugf("RPC call (json): %v [%v ms]", logurl, time.Since(t0).Milliseconds()) diff --git a/rpc/beaconstream.go b/rpc/beaconstream.go index 390a7acd..03241754 100644 --- a/rpc/beaconstream.go +++ b/rpc/beaconstream.go @@ -12,6 +12,7 @@ import ( "github.com/pk910/light-beaconchain-explorer/rpc/eventstream" "github.com/pk910/light-beaconchain-explorer/rpctypes" + "github.com/pk910/light-beaconchain-explorer/utils" ) const ( @@ -91,7 +92,7 @@ func (bs *BeaconStream) startStream() { case <-stream.Ready: bs.ReadyChan <- true case err := <-stream.Errors: - logger.WithField("client", bs.client.name).Errorf("beacon block stream error: %v", err) + logger.WithField("client", bs.client.name).Warnf("beacon block stream error: %v", err) bs.ReadyChan <- false } } @@ -138,7 +139,7 @@ func (bs *BeaconStream) subscribeStream(endpoint string, events uint16) *eventst stream, err = eventstream.SubscribeWithRequest("", req) } if err != nil { - logger.WithField("client", bs.client.name).Errorf("Error while subscribing beacon event stream %v: %v", url, err) + logger.WithField("client", bs.client.name).Warnf("Error while subscribing beacon event stream %v: %v", utils.GetRedactedUrl(url), err) select { case <-bs.killChan: return nil diff --git a/utils/logging.go b/utils/logging.go index 0409f7fa..bab5c71d 100644 --- a/utils/logging.go +++ b/utils/logging.go @@ -4,6 +4,7 @@ import ( "errors" "fmt" "io" + "net/url" "os" "path/filepath" "runtime" @@ -264,3 +265,14 @@ func logErrorInfo(err error, callerSkip int, additionalInfos ...map[string]inter return logFields } + +func GetRedactedUrl(requrl string) string { + urlData, _ := url.Parse(requrl) + var logurl string + if urlData != nil { + logurl = urlData.Redacted() + } else { + logurl = requrl + } + return logurl +} diff --git a/utils/process.go b/utils/process.go index 97d43eae..0db3db61 100644 --- a/utils/process.go +++ b/utils/process.go @@ -3,6 +3,9 @@ package utils import ( "os" "os/signal" + "runtime/debug" + + "github.com/sirupsen/logrus" ) // WaitForCtrlC will block/wait until a control-c is pressed @@ -11,3 +14,9 @@ func WaitForCtrlC() { signal.Notify(c, os.Interrupt) <-c } + +func HandleSubroutinePanic(identifier string) { + if err := recover(); err != nil { + logrus.WithError(err.(error)).Errorf("uncaught panic in %v subroutine: %v, stack: %v", identifier, err, string(debug.Stack())) + } +}