lower log verbosity for recoverable errors (show warning only)

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))
 	}

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

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)

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()

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())

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

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
+}

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()))
+	}
+}