diff --git a/assertions/BUILD.bazel b/assertions/BUILD.bazel index dd36786c3..55aee2ddc 100644 --- a/assertions/BUILD.bazel +++ b/assertions/BUILD.bazel @@ -23,6 +23,7 @@ go_library( "//runtime", "//solgen/go/rollupgen", "//util/stopwaiter", + "//util/log", "@com_github_ethereum_go_ethereum//accounts/abi/bind", "@com_github_ethereum_go_ethereum//common", "@com_github_ethereum_go_ethereum//core/types", diff --git a/assertions/confirmation.go b/assertions/confirmation.go index d1d34af10..e4986f9ef 100644 --- a/assertions/confirmation.go +++ b/assertions/confirmation.go @@ -11,6 +11,7 @@ import ( "github.com/OffchainLabs/bold/challenge-manager/types" "github.com/OffchainLabs/bold/containers/option" retry "github.com/OffchainLabs/bold/runtime" + utillog "github.com/OffchainLabs/bold/util/log" "github.com/ethereum/go-ethereum/accounts/abi/bind" "github.com/ethereum/go-ethereum/log" ) @@ -55,6 +56,10 @@ func (m *Manager) keepTryingAssertionConfirmation(ctx context.Context, assertion log.Error("Could not get prev assertion creation info", "err", err) return } + + backoffLogLevel := time.Second + exceedsMaxMempoolSizeEphemeralErrorHandler := utillog.NewEphemeralErrorHandler(10*time.Minute, "posting this transaction will exceed max mempool size", 0) + ticker := time.NewTicker(m.confirmationAttemptInterval) defer ticker.Stop() for { @@ -83,11 +88,24 @@ func (m *Manager) keepTryingAssertionConfirmation(ctx context.Context, assertion confirmed, err := solimpl.TryConfirmingAssertion(ctx, creationInfo.AssertionHash, prevCreationInfo.ConfirmPeriodBlocks+creationInfo.CreationBlock, m.chain, m.averageTimeForBlockCreation, option.None[protocol.EdgeId]()) if err != nil { if !strings.Contains(err.Error(), "PREV_NOT_LATEST_CONFIRMED") { - log.Error("Could not confirm assertion", "err", err, "assertionHash", assertionHash.Hash) + backoffLogLevel *= 2 + logLevel := log.Error + if backoffLogLevel > time.Minute { + backoffLogLevel = time.Minute + } else { + logLevel = log.Warn + } + logLevel = exceedsMaxMempoolSizeEphemeralErrorHandler.LogLevel(err, logLevel) + + logLevel("Could not confirm assertion", "err", err, "assertionHash", assertionHash.Hash) errorConfirmingAssertionByTimeCounter.Inc(1) } continue } + + exceedsMaxMempoolSizeEphemeralErrorHandler.Reset() + backoffLogLevel = time.Second + if confirmed { assertionConfirmedCounter.Inc(1) log.Info("Confirmed assertion by time", "assertionHash", creationInfo.AssertionHash) diff --git a/assertions/poster.go b/assertions/poster.go index cf68f7f08..0e8b1cbd6 100644 --- a/assertions/poster.go +++ b/assertions/poster.go @@ -14,6 +14,7 @@ import ( "github.com/OffchainLabs/bold/containers" "github.com/OffchainLabs/bold/containers/option" l2stateprovider "github.com/OffchainLabs/bold/layer2-state-provider" + utillog "github.com/OffchainLabs/bold/util/log" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/pkg/errors" @@ -30,10 +31,18 @@ func (m *Manager) postAssertionRoutine(ctx context.Context) { log.Warn("Staker strategy not configured to stake on latest assertions") return } + + backoffLogLevel := time.Second + exceedsMaxMempoolSizeEphemeralErrorHandler := utillog.NewEphemeralErrorHandler(10*time.Minute, "posting this transaction will exceed max mempool size", 0) + log.Info("Ready to post") if _, err := m.PostAssertion(ctx); err != nil { if !errors.Is(err, solimpl.ErrAlreadyExists) { - log.Error("Could not submit latest assertion to L1", "err", err) + backoffLogLevel *= 2 + logLevel := log.Warn + logLevel = exceedsMaxMempoolSizeEphemeralErrorHandler.LogLevel(err, logLevel) + + logLevel("Could not submit latest assertion to L1", "err", err) errorPostingAssertionCounter.Inc(1) } } @@ -49,9 +58,21 @@ func (m *Manager) postAssertionRoutine(ctx context.Context) { case errors.Is(err, solimpl.ErrBatchNotYetFound): log.Info("Waiting for more batches to post assertions about them onchain") default: - log.Error("Could not submit latest assertion", "err", err, "validatorName", m.validatorName) + backoffLogLevel *= 2 + logLevel := log.Error + if backoffLogLevel > time.Minute { + backoffLogLevel = time.Minute + } else { + logLevel = log.Warn + } + logLevel = exceedsMaxMempoolSizeEphemeralErrorHandler.LogLevel(err, logLevel) + + logLevel("Could not submit latest assertion", "err", err, "validatorName", m.validatorName) errorPostingAssertionCounter.Inc(1) } + } else { + exceedsMaxMempoolSizeEphemeralErrorHandler.Reset() + backoffLogLevel = time.Second } case <-ctx.Done(): return diff --git a/challenge-manager/chain-watcher/BUILD.bazel b/challenge-manager/chain-watcher/BUILD.bazel index 90378b3e5..953144649 100644 --- a/challenge-manager/chain-watcher/BUILD.bazel +++ b/challenge-manager/chain-watcher/BUILD.bazel @@ -17,6 +17,7 @@ go_library( "//runtime", "//solgen/go/challengeV2gen", "//util/stopwaiter", + "//util/log", "@com_github_ethereum_go_ethereum//accounts/abi/bind", "@com_github_ethereum_go_ethereum//common", "@com_github_ethereum_go_ethereum//log", diff --git a/challenge-manager/chain-watcher/watcher.go b/challenge-manager/chain-watcher/watcher.go index b6d9e7ac2..12c35ea20 100644 --- a/challenge-manager/chain-watcher/watcher.go +++ b/challenge-manager/chain-watcher/watcher.go @@ -25,6 +25,7 @@ import ( l2stateprovider "github.com/OffchainLabs/bold/layer2-state-provider" retry "github.com/OffchainLabs/bold/runtime" "github.com/OffchainLabs/bold/solgen/go/challengeV2gen" + utillog "github.com/OffchainLabs/bold/util/log" "github.com/OffchainLabs/bold/util/stopwaiter" "github.com/ethereum/go-ethereum/accounts/abi/bind" @@ -866,6 +867,9 @@ func (w *Watcher) confirmAssertionByChallengeWinner(ctx context.Context, edge pr challengeGracePeriodBlocks, ) + backoffLogLevel := time.Second + exceedsMaxMempoolSizeEphemeralErrorHandler := utillog.NewEphemeralErrorHandler(10*time.Minute, "posting this transaction will exceed max mempool size", 0) + // Compute the number of blocks until we reach the assertion's // deadline for confirmation. ticker := time.NewTicker(w.assertionConfirmingInterval) @@ -884,10 +888,23 @@ func (w *Watcher) confirmAssertionByChallengeWinner(ctx context.Context, edge pr option.Some(edge.Id()), ) if err != nil { - log.Error("Could not confirm assertion", "err", err, "assertionHash", common.Hash(claimId)) + backoffLogLevel *= 2 + logLevel := log.Error + if backoffLogLevel > time.Minute { + backoffLogLevel = time.Minute + } else { + logLevel = log.Warn + } + logLevel = exceedsMaxMempoolSizeEphemeralErrorHandler.LogLevel(err, logLevel) + + logLevel("Could not confirm assertion", "err", err, "assertionHash", common.Hash(claimId)) errorConfirmingAssertionByWinnerCounter.Inc(1) continue } + + exceedsMaxMempoolSizeEphemeralErrorHandler.Reset() + backoffLogLevel = time.Second + if confirmed { assertionConfirmedCounter.Inc(1) w.challenges.Delete(challengeParentAssertionHash) diff --git a/util/log/BUILD.bazel b/util/log/BUILD.bazel new file mode 100644 index 000000000..86872a561 --- /dev/null +++ b/util/log/BUILD.bazel @@ -0,0 +1,9 @@ +load("@io_bazel_rules_go//go:def.bzl", "go_library") + +go_library( + name = "log", + srcs = ["log.go"], + importpath = "github.com/OffchainLabs/bold/util/log", + visibility = ["//visibility:public"], + deps = ["@com_github_ethereum_go_ethereum//log"], +) diff --git a/util/log/log.go b/util/log/log.go new file mode 100644 index 000000000..3a5e2cedc --- /dev/null +++ b/util/log/log.go @@ -0,0 +1,67 @@ +package log + +import ( + "strings" + "time" + + "github.com/ethereum/go-ethereum/log" +) + +// EphemeralErrorHandler handles errors that are ephemeral in nature i.h these are errors +// that we would like to log as a warning unless they repeat for more than a certain duration of time. +type EphemeralErrorHandler struct { + Duration time.Duration + ErrorString string + FirstOccurrence *time.Time + + IgnoreDuration time.Duration + IgnoredErrLogLevel func(string, ...interface{}) // Default IgnoredErrLogLevel is log.Debug +} + +func NewEphemeralErrorHandler(duration time.Duration, errorString string, ignoreDuration time.Duration) *EphemeralErrorHandler { + return &EphemeralErrorHandler{ + Duration: duration, + ErrorString: errorString, + FirstOccurrence: &time.Time{}, + IgnoreDuration: ignoreDuration, + IgnoredErrLogLevel: log.Debug, + } +} + +// LogLevel method defaults to returning the input currentLogLevel if the given error doesnt contain the errorSubstring, +// but if it does, then returns one of the corresponding loglevels as follows +// - IgnoredErrLogLevel - if the error has been repeating for less than the IgnoreDuration of time. Defaults to log.Debug +// - log.Warn - if the error has been repeating for less than the given duration of time +// - log.Error - Otherwise +// +// # Usage Examples +// +// ephemeralErrorHandler.Loglevel(err, log.Error)("msg") +// ephemeralErrorHandler.Loglevel(err, log.Error)("msg", "key1", val1, "key2", val2) +// ephemeralErrorHandler.Loglevel(err, log.Error)("msg", "key1", val1) +func (h *EphemeralErrorHandler) LogLevel(err error, currentLogLevel func(msg string, ctx ...interface{})) func(string, ...interface{}) { + if h.ErrorString != "" && !strings.Contains(err.Error(), h.ErrorString) { + h.Reset() + return currentLogLevel + } + + if *h.FirstOccurrence == (time.Time{}) { + *h.FirstOccurrence = time.Now() + } + + if h.IgnoreDuration != 0 && time.Since(*h.FirstOccurrence) < h.IgnoreDuration { + if h.IgnoredErrLogLevel != nil { + return h.IgnoredErrLogLevel + } + return log.Debug + } + + if time.Since(*h.FirstOccurrence) < h.Duration { + return log.Warn + } + return log.Error +} + +func (h *EphemeralErrorHandler) Reset() { + *h.FirstOccurrence = time.Time{} +} diff --git a/util/log/log_test.go b/util/log/log_test.go new file mode 100644 index 000000000..5e8611d57 --- /dev/null +++ b/util/log/log_test.go @@ -0,0 +1,70 @@ +package log + +import ( + "errors" + "reflect" + "testing" + "time" + + "github.com/ethereum/go-ethereum/log" +) + +func compareFunctions(f1, f2 func(msg string, ctx ...interface{})) bool { + return reflect.ValueOf(f1).Pointer() == reflect.ValueOf(f2).Pointer() +} +func TestSimple(t *testing.T) { + allErrHandler := NewEphemeralErrorHandler(2500*time.Millisecond, "", time.Second) + err := errors.New("sample error") + logLevel := allErrHandler.LogLevel(err, log.Error) + if !compareFunctions(log.Debug, logLevel) { + t.Fatalf("incorrect loglevel output. Want: Debug") + } + + time.Sleep(1 * time.Second) + logLevel = allErrHandler.LogLevel(err, log.Error) + if !compareFunctions(log.Warn, logLevel) { + t.Fatalf("incorrect loglevel output. Want: Warn") + } + + time.Sleep(2 * time.Second) + logLevel = allErrHandler.LogLevel(err, log.Error) + if !compareFunctions(log.Error, logLevel) { + t.Fatalf("incorrect loglevel output. Want: Error") + } +} + +func TestComplex(t *testing.T) { + // Simulation: errorA happens continuously for 2 seconds and then errorB happens + errorAHandler := NewEphemeralErrorHandler(time.Second, "errorA", 0) + errorBHandler := NewEphemeralErrorHandler(1500*time.Millisecond, "errorB", 0) + + // Computes result of chaining two ephemeral error handlers for a given recurring error + chainingErrHandlers := func(err error) func(string, ...interface{}) { + logLevel := log.Error + logLevel = errorAHandler.LogLevel(err, logLevel) + logLevel = errorBHandler.LogLevel(err, logLevel) + return logLevel + } + + errA := errors.New("this is a sample errorA") + if !compareFunctions(log.Warn, chainingErrHandlers(errA)) { + t.Fatalf("incorrect loglevel output. Want: Warn") + } + time.Sleep(2 * time.Second) + if !compareFunctions(log.Error, chainingErrHandlers(errA)) { + t.Fatalf("incorrect loglevel output. Want: Error") + } + + errB := errors.New("this is a sample errorB") + if !compareFunctions(log.Warn, chainingErrHandlers(errB)) { + t.Fatalf("incorrect loglevel output. Want: Warn") + } + if !compareFunctions(log.Warn, chainingErrHandlers(errA)) { + t.Fatalf("incorrect loglevel output. Want: Warn") + } + + errC := errors.New("random error") + if !compareFunctions(log.Error, chainingErrHandlers(errC)) { + t.Fatalf("incorrect loglevel output. Want: Error") + } +}