From a242fec5e1537b53c33e58775762eee2293d7540 Mon Sep 17 00:00:00 2001 From: shenbaise9527 Date: Sun, 22 Oct 2023 23:00:02 +0800 Subject: [PATCH] feat: support for disable mon logs like sqlx (#3606) Co-authored-by: Kevin Wan --- core/stores/mon/collection.go | 39 +------- core/stores/mon/collection_test.go | 2 - core/stores/mon/options.go | 17 +++- core/stores/mon/options_test.go | 26 ++++++ core/stores/mon/util.go | 44 ++++++++- core/stores/mon/util_test.go | 141 ++++++++++++++++++++++++++++- 6 files changed, 222 insertions(+), 47 deletions(-) diff --git a/core/stores/mon/collection.go b/core/stores/mon/collection.go index e052dcc7..669d43f5 100644 --- a/core/stores/mon/collection.go +++ b/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) - 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)) - } - } + logDurationWithDoc(ctx, c.name, method, startTime, err, docs...) } func (c *decoratedCollection) logDurationSimple(ctx context.Context, method string, startTime time.Duration, err error) { diff --git a/core/stores/mon/collection_test.go b/core/stores/mon/collection_test.go index 964ebb23..95402c63 100644 --- a/core/stores/mon/collection_test.go +++ b/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) diff --git a/core/stores/mon/options.go b/core/stores/mon/options.go index ca13bff8..9ce06ad6 100644 --- a/core/stores/mon/options.go +++ b/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) diff --git a/core/stores/mon/options_test.go b/core/stores/mon/options_test.go index 5582f492..ee944f94 100644 --- a/core/stores/mon/options_test.go +++ b/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()) +} diff --git a/core/stores/mon/util.go b/core/stores/mon/util.go index e401df31..43f0ac3e 100644 --- a/core/stores/mon/util.go +++ b/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 { - logger.Infof("mongo(%s) - %s - fail(%s)", name, method, err.Error()) + var content []byte + jerr := errPlaceholder + 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.Infof("mongo(%s) - %s - ok", name, method) + logger.Errorf("mongo(%s) - %s - fail(%s) - %s", + name, method, err.Error(), string(content)) } } diff --git a/core/stores/mon/util_test.go b/core/stores/mon/util_test.go index 3ab7cf2b..521a619c 100644 --- a/core/stores/mon/util_test.go +++ b/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") }