chore: refactor mongo logs (#3660)

core/stores/mon/collection.go

@@ -501,10 +501,11 @@ 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) {
-	logDurationWithDoc(ctx, c.name, method, startTime, err, docs...)
+	logDurationWithDocs(ctx, c.name, method, startTime, err, docs...)
 }
 
-func (c *decoratedCollection) logDurationSimple(ctx context.Context, method string, startTime time.Duration, err error) {
+func (c *decoratedCollection) logDurationSimple(ctx context.Context, method string,
+	startTime time.Duration, err error) {
 	logDuration(ctx, c.name, method, startTime, err)
 }
 

core/stores/mon/options.go

@@ -22,13 +22,13 @@ type (
 	Option func(opts *options)
 )
 
-// DisableLog disables logging of mongo command, includes info and slow logs.
+// DisableLog disables logging of mongo commands, includes info and slow logs.
 func DisableLog() {
 	logMon.Set(false)
 	logSlowMon.Set(false)
 }
 
-// DisableInfoLog disables info logging of mongo command, but keeps slow logs.
+// DisableInfoLog disables info logging of mongo commands, but keeps slow logs.
 func DisableInfoLog() {
 	logMon.Set(false)
 }

core/stores/mon/util.go

@@ -3,7 +3,6 @@ package mon
 import (
 	"context"
 	"encoding/json"
-	"errors"
 	"strings"
 	"time"
 
@@ -13,53 +12,50 @@ 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)
+	duration := timex.Since(startTime)
+	logger := logx.WithContext(ctx).WithDuration(duration)
+	if err != nil {
+		logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error())
+		return
+	}
+
+	if logSlowMon.True() && duration > slowThreshold.Load() {
+		logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - ok", name, method)
+	} else if logMon.True() {
+		logger.Infof("mongo(%s) - %s - ok", name, method)
+	}
 }
 
-func logDurationWithDoc(ctx context.Context, name, method string,
+func logDurationWithDocs(ctx context.Context, name, method string, startTime time.Duration,
-	startTime time.Duration, err error, docs ...any) {
+	err error, docs ...any) {
 	duration := timex.Since(startTime)
 	logger := logx.WithContext(ctx).WithDuration(duration)
-	var content []byte
-	jerr := errPlaceholder
-	if len(docs) > 0 {
-		content, jerr = json.Marshal(docs)
-	}
 
-	if err == nil {
+	content, jerr := json.Marshal(docs)
-		// jerr should not be non-nil, but we don't care much on this,
+	// jerr should not be non-nil, but we don't care much on this,
-		// if non-nil, we just log without docs.
+	// if non-nil, we just log without docs.
-		if jerr != nil {
+	if jerr != nil {
-			if logSlowMon.True() && duration > slowThreshold.Load() {
+		if err != nil {
-				logger.Slowf("mongo(%s) - slowcall - %s - ok", name, method)
+			logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error())
-			} else if logMon.True() {
+		} else if logSlowMon.True() && duration > slowThreshold.Load() {
-				logger.Infof("mongo(%s) - %s - ok", name, method)
+			logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - ok", name, method)
-			}
+		} else if logMon.True() {
-		} else {
+			logger.Infof("mongo(%s) - %s - ok", name, method)
-			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 {
+	if err != nil {
-		logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error())
+		logger.Errorf("mongo(%s) - %s - fail(%s) - %s", name, method, err.Error(), string(content))
-	} else {
+	} else if logSlowMon.True() && duration > slowThreshold.Load() {
-		logger.Errorf("mongo(%s) - %s - fail(%s) - %s",
+		logger.Slowf("[MONGO] mongo(%s) - slowcall - %s - ok - %s", name, method, string(content))
-			name, method, err.Error(), string(content))
+	} else if logMon.True() {
+		logger.Infof("mongo(%s) - %s - ok - %s", name, method, string(content))
 	}
 }

core/stores/mon/util_test.go

@@ -42,18 +42,18 @@ func Test_logDuration(t *testing.T) {
 	buf := logtest.NewCollector(t)
 
 	buf.Reset()
-	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now()-slowThreshold.Load()*2, nil)
+	logDuration(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()
-	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil)
+	logDuration(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"))
+	logDuration(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")
@@ -65,26 +65,26 @@ func Test_logDuration(t *testing.T) {
 
 	buf.Reset()
 	DisableInfoLog()
-	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil)
+	logDuration(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)
+	logDuration(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)
+	logDuration(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)
+	logDuration(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"))
+	logDuration(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")
@@ -94,37 +94,37 @@ 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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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")
@@ -137,21 +137,21 @@ func Test_logDurationWithDoc(t *testing.T) {
 
 	buf.Reset()
 	DisableInfoLog()
-	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, make(chan int))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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")
@@ -159,29 +159,29 @@ func Test_logDurationWithDoc(t *testing.T) {
 
 	buf.Reset()
 	DisableLog()
-	logDurationWithDoc(context.Background(), "foo", "bar", timex.Now(), nil, make(chan int))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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))
+	logDurationWithDocs(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': ''}")
+	logDurationWithDocs(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")