From 172ff407f30bdb2b84424c2c715de4fed182de67 Mon Sep 17 00:00:00 2001 From: Kevin Wan Date: Mon, 23 Oct 2023 11:03:55 +0800 Subject: [PATCH] chore: refactor mongo logs (#3660) --- core/stores/mon/collection.go | 5 ++- core/stores/mon/options.go | 4 +- core/stores/mon/util.go | 72 +++++++++++++++++------------------ core/stores/mon/util_test.go | 48 +++++++++++------------ 4 files changed, 63 insertions(+), 66 deletions(-) diff --git a/core/stores/mon/collection.go b/core/stores/mon/collection.go index 669d43f50..a909bb029 100644 --- a/core/stores/mon/collection.go +++ b/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) } diff --git a/core/stores/mon/options.go b/core/stores/mon/options.go index 9ce06ad60..4097328fa 100644 --- a/core/stores/mon/options.go +++ b/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) } diff --git a/core/stores/mon/util.go b/core/stores/mon/util.go index 43f0ac3e8..03e9a70c6 100644 --- a/core/stores/mon/util.go +++ b/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) -} - -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) - 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)) - } - } - + if err != nil { + logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error()) 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)) + 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 logDurationWithDocs(ctx context.Context, name, 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 { + logger.Errorf("mongo(%s) - %s - fail(%s)", name, method, err.Error()) + } else 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) + } + return + } + + if err != nil { + logger.Errorf("mongo(%s) - %s - fail(%s) - %s", name, method, err.Error(), string(content)) + } else if logSlowMon.True() && duration > slowThreshold.Load() { + logger.Slowf("[MONGO] 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)) } } diff --git a/core/stores/mon/util_test.go b/core/stores/mon/util_test.go index 521a619c5..be0c859e8 100644 --- a/core/stores/mon/util_test.go +++ b/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")