From 6c94e4652ee05e16530aba3c248f2b4b81c92b19 Mon Sep 17 00:00:00 2001
From: Kevin Wan <wanjunfeng@gmail.com>
Date: Sat, 4 Jun 2022 16:11:31 +0800
Subject: [PATCH] chore: better mongo logs (#1965)

* chore: better mongo logs

* chore: add comments
---
 core/logx/rotatelogger.go          |  6 +++++-
 core/stores/mon/collection.go      | 24 +++++++++++++++++++-----
 core/stores/mon/collection_test.go | 29 ++++++++++++++++++++++++-----
 3 files changed, 48 insertions(+), 11 deletions(-)

diff --git a/core/logx/rotatelogger.go b/core/logx/rotatelogger.go
index 07a03dd1..869637a7 100644
--- a/core/logx/rotatelogger.go
+++ b/core/logx/rotatelogger.go
@@ -328,5 +328,9 @@ func gzipFile(file string) error {
 		return err
 	}
 
-	return os.Remove(file)
+	// ignore errors on remove, it most happens on unit tests,
+	// it caused lots of troubles on GitHub actions.
+	// and even on production, remove errors are not important.
+	_ = os.Remove(file)
+	return nil
 }
diff --git a/core/stores/mon/collection.go b/core/stores/mon/collection.go
index 8a205a2e..556ad31d 100644
--- a/core/stores/mon/collection.go
+++ b/core/stores/mon/collection.go
@@ -500,14 +500,28 @@ func (c *decoratedCollection) UpdateOne(ctx context.Context, filter interface{},
 	return
 }
 
-func (c *decoratedCollection) logDuration(ctx context.Context, method string, startTime time.Duration, err error,
-	docs ...interface{}) {
+func (c *decoratedCollection) logDuration(ctx context.Context, method string,
+	startTime time.Duration, err error, docs ...interface{}) {
 	duration := timex.Since(startTime)
 	logger := logx.WithContext(ctx).WithDuration(duration)
 
-	content, e := json.Marshal(docs)
-	if e != nil {
-		logger.Error(e)
+	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",
diff --git a/core/stores/mon/collection_test.go b/core/stores/mon/collection_test.go
index 4e2e9d1d..75ddc493 100644
--- a/core/stores/mon/collection_test.go
+++ b/core/stores/mon/collection_test.go
@@ -5,12 +5,12 @@ import (
 	"errors"
 	"strings"
 	"testing"
-	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/zeromicro/go-zero/core/breaker"
 	"github.com/zeromicro/go-zero/core/logx"
 	"github.com/zeromicro/go-zero/core/stringx"
+	"github.com/zeromicro/go-zero/core/timex"
 	"go.mongodb.org/mongo-driver/bson"
 	"go.mongodb.org/mongo-driver/bson/primitive"
 	"go.mongodb.org/mongo-driver/mongo"
@@ -588,21 +588,40 @@ func Test_DecoratedCollectionLogDuration(t *testing.T) {
 	}()
 
 	buf.Reset()
-	c.logDuration(context.Background(), "foo", time.Millisecond, nil, "bar")
+	c.logDuration(context.Background(), "foo", timex.Now(), nil, "bar")
 	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "bar")
 
 	buf.Reset()
-	c.logDuration(context.Background(), "foo", time.Millisecond, errors.New("bar"), make(chan int))
+	c.logDuration(context.Background(), "foo", timex.Now(), errors.New("bar"), make(chan int))
+	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "bar")
 
 	buf.Reset()
-	c.logDuration(context.Background(), "foo", slowThreshold.Load()+time.Millisecond, errors.New("bar"))
+	c.logDuration(context.Background(), "foo", timex.Now(), nil, make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+
+	buf.Reset()
+	c.logDuration(context.Background(), "foo", timex.Now()-slowThreshold.Load()*2,
+		nil, make(chan int))
+	assert.Contains(t, buf.String(), "foo")
+	assert.Contains(t, buf.String(), "slowcall")
+
+	buf.Reset()
+	c.logDuration(context.Background(), "foo", timex.Now()-slowThreshold.Load()*2,
+		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", slowThreshold.Load()+time.Millisecond, nil)
+	c.logDuration(context.Background(), "foo", timex.Now()-slowThreshold.Load()*2, nil)
 	assert.Contains(t, buf.String(), "foo")
 	assert.Contains(t, buf.String(), "slowcall")
 }