Merge pull request #31 from EspressoSystems/jh/remove-log

Add the log helper

client/client.go

@@ -10,24 +10,20 @@ import (
 	"strings"
 
 	"github.com/EspressoSystems/espresso-sequencer-go/types"
-
-	"github.com/ethereum/go-ethereum/log"
 )
 
 type Client struct {
 	baseUrl string
 	client  *http.Client
-	log     log.Logger
 }
 
-func NewClient(log log.Logger, url string) *Client {
+func NewClient(url string) *Client {
 	if !strings.HasSuffix(url, "/") {
 		url += "/"
 	}
 	return &Client{
 		baseUrl: url,
 		client:  http.DefaultClient,
-		log:     log,
 	}
 }
 
@@ -130,15 +126,12 @@ type NamespaceResponse struct {
 func (c *Client) get(ctx context.Context, out any, format string, args ...any) error {
 	url := c.baseUrl + fmt.Sprintf(format, args...)
 
-	c.log.Debug("get", "url", url)
 	req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
 	if err != nil {
-		c.log.Error("failed to build request", "err", err, "url", url)
 		return err
 	}
 	res, err := c.client.Do(req)
 	if err != nil {
-		c.log.Error("error in request", "err", err, "url", url)
 		return err
 	}
 	defer res.Body.Close()
@@ -148,22 +141,18 @@ func (c *Client) get(ctx context.Context, out any, format string, args ...any) e
 		// information about why the request failed. If this call fails, the response will be `nil`,
 		// which is fine to include in the log, so we can ignore errors.
 		body, _ := io.ReadAll(res.Body)
-		c.log.Error("request failed", "err", err, "url", url, "status", res.StatusCode, "response", string(body))
-		return fmt.Errorf("request failed with status %d", res.StatusCode)
+		return fmt.Errorf("request failed with status %d and body %s", res.StatusCode, string(body))
 	}
 
 	// Read the response body into memory before we unmarshal it, rather than passing the io.Reader
 	// to the json decoder, so that we still have the body and can inspect it if unmarshalling
 	// failed.
 	body, err := io.ReadAll(res.Body)
 	if err != nil {
-		c.log.Error("failed to read response body", "err", err, "url", url)
 		return err
 	}
 	if err := json.Unmarshal(body, out); err != nil {
-		c.log.Error("failed to parse body as json", "err", err, "url", url, "response", string(body))
 		return err
 	}
-	c.log.Debug("request completed successfully", "url", url, "res", res, "body", string(body), "out", out)
 	return nil
 }

go.mod

@@ -3,6 +3,7 @@ module github.com/EspressoSystems/espresso-sequencer-go
 go 1.21
 
 require (
+	github.com/benbjohnson/clock v1.3.5
 	github.com/ethereum/go-ethereum v1.13.5
 	github.com/sigurn/crc8 v0.0.0-20220107193325-2243fe600f9f
 	github.com/stretchr/testify v1.8.4

go.sum

@@ -6,6 +6,8 @@ github.com/StackExchange/wmi v1.2.1 h1:VIkavFPXSjcnS+O8yTq7NI32k0R5Aj+v39y29VYDO
 github.com/StackExchange/wmi v1.2.1/go.mod h1:rcmrprowKIVzvc+NUiLncP2uuArMWLCbu9SBzvHz7e8=
 github.com/VictoriaMetrics/fastcache v1.12.1 h1:i0mICQuojGDL3KblA7wUNlY5lOK6a4bwt3uRKnkZU40=
 github.com/VictoriaMetrics/fastcache v1.12.1/go.mod h1:tX04vaqcNoQeGLD+ra5pU5sWkuxnzWhEzLwhP9w653o=
+github.com/benbjohnson/clock v1.3.5 h1:VvXlSJBzZpA/zum6Sj74hxwYI2DIxRWuNIoXAzHZz5o=
+github.com/benbjohnson/clock v1.3.5/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
 github.com/bits-and-blooms/bitset v1.7.0 h1:YjAGVd3XmtK9ktAbX8Zg2g2PwLIMjGREZJHlV4j7NEo=

log_helper/log_helper.go

@@ -0,0 +1,45 @@
+package log_helper
+
+import (
+	"time"
+)
+
+type Channel string
+
+// This is used for cleaning up log outputs.
+// The scenario is that rollup will query hotshot blocks that are not yet ready,
+// which generates a lot of logs. However, these logs don't contain much useful
+// information and actually make debugging more difficult.
+type LogHelper struct {
+	strategies map[Channel]Strategy
+}
+
+func NewLogger() LogHelper {
+	return LogHelper{strategies: map[Channel]Strategy{}}
+}
+
+func (l *LogHelper) AddStrategy(channel Channel, strategy Strategy) {
+	l.strategies[channel] = strategy
+}
+
+func (l *LogHelper) AddLogAfterRetryStrategy(channel Channel, id string, retryTimes uint32) {
+	s := NewLogAfterRetryStrategy(id, retryTimes)
+	l.AddStrategy(channel, s)
+}
+
+func (l *LogHelper) AddLogAfterDurationStrategy(channel Channel, id string, duration time.Duration) {
+	s := NewLogAfterDurationStrategy(id, duration)
+	l.AddStrategy(channel, s)
+}
+
+func (l *LogHelper) Attempt(channel Channel, id string, logFunc func()) {
+	strategy, ok := l.strategies[channel]
+	if !ok {
+		// Can not find the strategy, log it
+		logFunc()
+		return
+	}
+
+	result := strategy.attempt(id, logFunc)
+	l.strategies[channel] = result
+}

log_helper/log_helper_test.go

@@ -0,0 +1,91 @@
+package log_helper
+
+import (
+	"testing"
+	"time"
+
+	"github.com/benbjohnson/clock"
+)
+
+func TestLogAfterRetry(t *testing.T) {
+	helper := NewLogger()
+
+	channel := Channel("test1")
+	id := "id1"
+	retryTimes := 5
+	helper.AddLogAfterRetryStrategy(channel, id, uint32(retryTimes))
+
+	cnt := 0
+	for i := 0; i < retryTimes; i += 1 {
+		helper.Attempt(channel, id, func() { cnt += 1 })
+		if cnt > 0 {
+			t.Error("should be zero")
+		}
+	}
+
+	expect := 10
+	helper.Attempt(channel, id, func() { cnt += expect })
+	if cnt != expect {
+		t.Errorf("expect %d, but got %d", expect, cnt)
+	}
+
+	// A new id should set the haveRetried to 1.
+	cnt = 0
+	id2 := "id2"
+	for i := 0; i < retryTimes; i += 1 {
+		helper.Attempt(channel, id2, func() { cnt += 1 })
+		if cnt > 0 {
+			t.Error("should be zero")
+		}
+	}
+
+	helper.Attempt(channel, id2, func() { cnt += expect })
+	if cnt != expect {
+		t.Errorf("expect %d, but got %d", expect, cnt)
+	}
+
+}
+
+func TestLogAfterDuration(t *testing.T) {
+	mockClock := clock.NewMock()
+	clk = mockClock
+	helper := NewLogger()
+
+	channel := Channel("test1")
+	id := "id1"
+
+	cnt := 0
+
+	retryDuration := time.Hour
+	helper.AddLogAfterDurationStrategy(channel, id, retryDuration)
+	for i := 0; i < 5; i += 1 {
+		helper.Attempt(channel, id, func() { cnt += 1 })
+		if cnt > 0 {
+			t.Error("should be zero")
+		}
+	}
+
+	mockClock.Add(retryDuration + time.Minute)
+	expect := 10
+	helper.Attempt(channel, id, func() { cnt += expect })
+	if cnt != expect {
+		t.Errorf("expect %d, but got %d", expect, cnt)
+	}
+
+	// A new id should set the startTime to now.
+	cnt = 0
+
+	id2 := "id2"
+	for i := 0; i < 5; i += 1 {
+		helper.Attempt(channel, id2, func() { cnt += 1 })
+		if cnt > 0 {
+			t.Error("should be zero")
+		}
+	}
+
+	mockClock.Add(retryDuration + time.Minute)
+	helper.Attempt(channel, id2, func() { cnt += expect })
+	if cnt != expect {
+		t.Errorf("expect %d, but got %d", expect, cnt)
+	}
+}

log_helper/strategy.go

@@ -0,0 +1,72 @@
+package log_helper
+
+import (
+	"time"
+
+	"github.com/benbjohnson/clock"
+)
+
+type Strategy interface {
+	attempt(id string, logFunc func()) Strategy
+}
+
+type LogAfterRetryStrategy struct {
+	Id          string
+	Limit       uint32
+	haveRetried uint32
+}
+
+func NewLogAfterRetryStrategy(id string, retryTimes uint32) LogAfterRetryStrategy {
+	return LogAfterRetryStrategy{
+		Id:          id,
+		Limit:       retryTimes,
+		haveRetried: 0,
+	}
+}
+
+func (s LogAfterRetryStrategy) attempt(id string, logFunc func()) Strategy {
+	if s.Id != id {
+		s.Id = id
+		s.haveRetried = 1
+		return s
+	}
+
+	s.haveRetried += 1
+
+	if s.haveRetried <= s.Limit {
+		return s
+	}
+
+	logFunc()
+	return s
+}
+
+var clk clock.Clock = clock.New()
+
+type LogAfterDurationStrategy struct {
+	Id            string
+	RetryDuration time.Duration
+	StartTime     time.Time
+}
+
+func NewLogAfterDurationStrategy(id string, retryDuration time.Duration) LogAfterDurationStrategy {
+	return LogAfterDurationStrategy{
+		Id:            id,
+		RetryDuration: retryDuration,
+		StartTime:     clk.Now(),
+	}
+}
+
+func (s LogAfterDurationStrategy) attempt(id string, logFunc func()) Strategy {
+	if s.Id != id {
+		s.Id = id
+		s.StartTime = clk.Now()
+		return s
+	}
+
+	if clk.Since(s.StartTime) > s.RetryDuration {
+		logFunc()
+		return s
+	}
+	return s
+}