feat: support for disable mon logs like sqlx (#3606)

Co-authored-by: Kevin Wan <wanjunfeng@gmail.com>

core/stores/mon/collection.go

@@ -2,12 +2,10 @@ package mon
 
 import (
 	"context"
-	"encoding/json"
 	"errors"
 	"time"
 
 	"github.com/zeromicro/go-zero/core/breaker"
-	"github.com/zeromicro/go-zero/core/logx"
 	"github.com/zeromicro/go-zero/core/timex"
 	"go.mongodb.org/mongo-driver/mongo"
 	mopt "go.mongodb.org/mongo-driver/mongo/options"
@@ -503,42 +501,7 @@ func (c *decoratedCollection) UpdateOne(ctx context.Context, filter, update any,
 
 func (c *decoratedCollection) logDuration(ctx context.Context, method string,
 	startTime time.Duration, err error, docs ...any) {
-	duration := timex.Since(startTime)
+	logDurationWithDoc(ctx, c.name, method, startTime, err, docs...)
-	logger := logx.WithContext(ctx).WithDuration(duration)
-
-	content, jerr := json.Marshal(docs)
-	// jerr should not be non-nil, but we don't care much on this,
-	// if non-nil, we just log without docs.
-	if jerr != nil {
-		if err != nil {
-			if duration > slowThreshold.Load() {
-				logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - fail(%s)", c.name, method, err.Error())
-			} else {
-				logger.Infof("mongo(%s) - %s - fail(%s)", c.name, method, err.Error())
-			}
-		} else {
-			if duration > slowThreshold.Load() {
-				logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - ok", c.name, method)
-			} else {
-				logger.Infof("mongo(%s) - %s - ok", c.name, method)
-			}
-		}
-	} else if err != nil {
-		if duration > slowThreshold.Load() {
-			logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - fail(%s) - %s",
-				c.name, method, err.Error(), string(content))
-		} else {
-			logger.Infof("mongo(%s) - %s - fail(%s) - %s",
-				c.name, method, err.Error(), string(content))
-		}
-	} else {
-		if duration > slowThreshold.Load() {
-			logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - ok - %s",
-				c.name, method, string(content))
-		} else {
-			logger.Infof("mongo(%s) - %s - ok - %s", c.name, method, string(content))
-		}
-	}
 }
 
 func (c *decoratedCollection) logDurationSimple(ctx context.Context, method string, startTime time.Duration, err error) {

core/stores/mon/collection_test.go

@@ -599,13 +599,11 @@ func TestDecoratedCollection_LogDuration(t *testing.T) {
 		errors.New("bar"), make(chan int))
 	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "bar")
-	assert.Contains(t, buf.String(), "slowcall")
 
 	buf.Reset()
 	c.logDuration(context.Background(), "foo", timex.Now()-slowThreshold.Load()*2,
 		errors.New("bar"))
 	assert.Contains(t, buf.String(), "foo")
-	assert.Contains(t, buf.String(), "slowcall")
 
 	buf.Reset()
 	c.logDuration(context.Background(), "foo", timex.Now()-slowThreshold.Load()*2, nil)

core/stores/mon/options.go

@@ -9,7 +9,11 @@ import (
 
 const defaultTimeout = time.Second * 3
 
-var slowThreshold = syncx.ForAtomicDuration(defaultSlowThreshold)
+var (
+	slowThreshold = syncx.ForAtomicDuration(defaultSlowThreshold)
+	logMon        = syncx.ForAtomicBool(true)
+	logSlowMon    = syncx.ForAtomicBool(true)
+)
 
 type (
 	options = mopt.ClientOptions
@@ -18,6 +22,17 @@ type (
 	Option func(opts *options)
 )
 
+// DisableLog disables logging of mongo command, includes info and slow logs.
+func DisableLog() {
+	logMon.Set(false)
+	logSlowMon.Set(false)
+}
+
+// DisableInfoLog disables info logging of mongo command, but keeps slow logs.
+func DisableInfoLog() {
+	logMon.Set(false)
+}
+
 // SetSlowThreshold sets the slow threshold.
 func SetSlowThreshold(threshold time.Duration) {
 	slowThreshold.Set(threshold)

core/stores/mon/options_test.go

@@ -25,3 +25,29 @@ func TestWithTimeout(t *testing.T) {
 	WithTimeout(time.Second)(opts)
 	assert.Equal(t, time.Second, *opts.Timeout)
 }
+
+func TestDisableLog(t *testing.T) {
+	assert.True(t, logMon.True())
+	assert.True(t, logSlowMon.True())
+	defer func() {
+		logMon.Set(true)
+		logSlowMon.Set(true)
+	}()
+
+	DisableLog()
+	assert.False(t, logMon.True())
+	assert.False(t, logSlowMon.True())
+}
+
+func TestDisableInfoLog(t *testing.T) {
+	assert.True(t, logMon.True())
+	assert.True(t, logSlowMon.True())
+	defer func() {
+		logMon.Set(true)
+		logSlowMon.Set(true)
+	}()
+
+	DisableInfoLog()
+	assert.False(t, logMon.True())
+	assert.True(t, logSlowMon.True())
+}

core/stores/mon/util.go

@@ -2,6 +2,8 @@ package mon
 
 import (
 	"context"
+	"encoding/json"
+	"errors"
 	"strings"
 	"time"
 
@@ -11,17 +13,53 @@ import (
 
 const mongoAddrSep = ","
 
+var errPlaceholder = errors.New("placeholder")
+
 // FormatAddr formats mongo hosts to a string.
 func FormatAddr(hosts []string) string {
 	return strings.Join(hosts, mongoAddrSep)
 }
 
 func logDuration(ctx context.Context, name, method string, startTime time.Duration, err error) {
+	logDurationWithDoc(ctx, name, method, startTime, err)
+}
+
+func logDurationWithDoc(ctx context.Context, name, method string,
+	startTime time.Duration, err error, docs ...any) {
 	duration := timex.Since(startTime)
 	logger := logx.WithContext(ctx).WithDuration(duration)
-	if err != nil {
+	var content []byte
-		logger.Infof("mongo(%s) - %s - fail(%s)", name, method, err.Error())
+	jerr := errPlaceholder
-	} else {
+	if len(docs) > 0 {
+		content, jerr = json.Marshal(docs)
+	}
+
+	if err == nil {
+		// jerr should not be non-nil, but we don't care much on this,
+		// if non-nil, we just log without docs.
+		if jerr != nil {
+			if logSlowMon.True() && duration > slowThreshold.Load() {
+				logger.Slowf("mongo(%s) - slowcall - %s - ok", name, method)
+			} else if logMon.True() {
 				logger.Infof("mongo(%s) - %s - ok", name, method)
 			}
+		} else {
+			if logSlowMon.True() && duration > slowThreshold.Load() {
+				logger.Slowf("mongo(%s) - slowcall - %s - ok - %s",
+					name, method, string(content))
+			} else if logMon.True() {
+				logger.Infof("mongo(%s) - %s - ok - %s",
+					name, method, string(content))
+			}
+		}
+
+		return
+	}
+
+	if jerr != nil {
+		logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error())
+	} else {
+		logger.Errorf("mongo(%s) - %s - fail(%s) - %s",
+			name, method, err.Error(), string(content))
+	}
 }

core/stores/mon/util_test.go

@@ -4,10 +4,10 @@ import (
 	"context"
 	"errors"
 	"testing"
-	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/zeromicro/go-zero/core/logx/logtest"
+	"github.com/zeromicro/go-zero/core/timex"
 )
 
 func TestFormatAddrs(t *testing.T) {
@@ -42,13 +42,148 @@ func Test_logDuration(t *testing.T) {
 	buf := logtest.NewCollector(t)
 
 	buf.Reset()
-	logDuration(context.Background(), "foo", "bar", time.Millisecond, nil)
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil)
 	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
 
 	buf.Reset()
-	logDuration(context.Background(), "foo", "bar", time.Millisecond, errors.New("bar"))
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil)
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "fail")
+
+	defer func() {
+		logMon.Set(true)
+		logSlowMon.Set(true)
+	}()
+
+	buf.Reset()
+	DisableInfoLog()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil)
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil)
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
+
+	buf.Reset()
+	DisableLog()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil)
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil)
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "fail")
+}
+
+func Test_logDurationWithDoc(t *testing.T) {
+	buf := logtest.NewCollector(t)
+	buf.Reset()
+
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, "{'json': ''}")
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
+	assert.Contains(t, buf.String(), "json")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, "{'json': ''}")
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "json")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"), make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "fail")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"), "{'json': ''}")
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "fail")
+	assert.Contains(t, buf.String(), "json")
+
+	defer func() {
+		logMon.Set(true)
+		logSlowMon.Set(true)
+	}()
+
+	buf.Reset()
+	DisableInfoLog()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, make(chan int))
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, "{'json': ''}")
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, "{'json': ''}")
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "slow")
+	assert.Contains(t, buf.String(), "json")
+
+	buf.Reset()
+	DisableLog()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, make(chan int))
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, "{'json': ''}")
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, make(chan int))
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil, "{'json': ''}")
+	assert.Empty(t, buf.String())
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"), make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "bar")
+	assert.Contains(t, buf.String(), "fail")
+
+	buf.Reset()
+	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), errors.New("bar"), "{'json': ''}")
 	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "bar")
 	assert.Contains(t, buf.String(), "fail")
+	assert.Contains(t, buf.String(), "json")
 }