From 0b1884b6bd88fcc1ee157d503f882558f21cda28 Mon Sep 17 00:00:00 2001 From: Kevin Wan Date: Sat, 17 Sep 2022 22:48:24 +0800 Subject: [PATCH] feat: support caller skip in logx (#2401) * feat: support caller skip in logx * chore: remove debug prints * chore: remove debug prints * chore(deps): bump go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc (#2402) Bumps [go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc](https://github.com/open-telemetry/opentelemetry-go) from 1.9.0 to 1.10.0. - [Release notes](https://github.com/open-telemetry/opentelemetry-go/releases) - [Changelog](https://github.com/open-telemetry/opentelemetry-go/blob/main/CHANGELOG.md) - [Commits](https://github.com/open-telemetry/opentelemetry-go/compare/v1.9.0...v1.10.0) --- updated-dependencies: - dependency-name: go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc dependency-type: direct:production update-type: version-update:semver-minor ... Signed-off-by: dependabot[bot] Signed-off-by: dependabot[bot] Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * chore: simplify test code * chore: remove new WithFields in logx, and deprecated old WithFields * chore: simplify WithDuration Signed-off-by: dependabot[bot] Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> --- core/logx/contextlogger.go | 145 --------------- core/logx/durationlogger.go | 101 ---------- core/logx/durationlogger_test.go | 161 ---------------- core/logx/fields.go | 10 +- core/logx/fields_test.go | 8 +- core/logx/logger.go | 6 +- core/logx/logs.go | 136 +++++--------- core/logx/logs_test.go | 29 ++- core/logx/richlogger.go | 172 ++++++++++++++++++ ...ntextlogger_test.go => richlogger_test.go} | 28 ++- core/logx/syslog_test.go | 17 +- core/logx/writer.go | 4 +- 12 files changed, 297 insertions(+), 520 deletions(-) delete mode 100644 core/logx/contextlogger.go delete mode 100644 core/logx/durationlogger.go delete mode 100644 core/logx/durationlogger_test.go create mode 100644 core/logx/richlogger.go rename core/logx/{contextlogger_test.go => richlogger_test.go} (91%) diff --git a/core/logx/contextlogger.go b/core/logx/contextlogger.go deleted file mode 100644 index 2aec407c..00000000 --- a/core/logx/contextlogger.go +++ /dev/null @@ -1,145 +0,0 @@ -package logx - -import ( - "context" - "fmt" - "time" - - "github.com/zeromicro/go-zero/core/timex" - "go.opentelemetry.io/otel/trace" -) - -// WithContext sets ctx to log, for keeping tracing information. -func WithContext(ctx context.Context) Logger { - return &contextLogger{ - ctx: ctx, - } -} - -type contextLogger struct { - logEntry - ctx context.Context -} - -func (l *contextLogger) Error(v ...interface{}) { - l.err(fmt.Sprint(v...)) -} - -func (l *contextLogger) Errorf(format string, v ...interface{}) { - l.err(fmt.Sprintf(format, v...)) -} - -func (l *contextLogger) Errorv(v interface{}) { - l.err(fmt.Sprint(v)) -} - -func (l *contextLogger) Errorw(msg string, fields ...LogField) { - l.err(msg, fields...) -} - -func (l *contextLogger) Info(v ...interface{}) { - l.info(fmt.Sprint(v...)) -} - -func (l *contextLogger) Infof(format string, v ...interface{}) { - l.info(fmt.Sprintf(format, v...)) -} - -func (l *contextLogger) Infov(v interface{}) { - l.info(v) -} - -func (l *contextLogger) Infow(msg string, fields ...LogField) { - l.info(msg, fields...) -} - -func (l *contextLogger) Slow(v ...interface{}) { - l.slow(fmt.Sprint(v...)) -} - -func (l *contextLogger) Slowf(format string, v ...interface{}) { - l.slow(fmt.Sprintf(format, v...)) -} - -func (l *contextLogger) Slowv(v interface{}) { - l.slow(v) -} - -func (l *contextLogger) Sloww(msg string, fields ...LogField) { - l.slow(msg, fields...) -} - -func (l *contextLogger) WithContext(ctx context.Context) Logger { - if ctx == nil { - return l - } - - l.ctx = ctx - return l -} - -func (l *contextLogger) WithDuration(duration time.Duration) Logger { - l.Duration = timex.ReprOfDuration(duration) - return l -} - -func (l *contextLogger) buildFields(fields ...LogField) []LogField { - if len(l.Duration) > 0 { - fields = append(fields, Field(durationKey, l.Duration)) - } - - traceID := traceIdFromContext(l.ctx) - if len(traceID) > 0 { - fields = append(fields, Field(traceKey, traceID)) - } - - spanID := spanIdFromContext(l.ctx) - if len(spanID) > 0 { - fields = append(fields, Field(spanKey, spanID)) - } - - val := l.ctx.Value(fieldsContextKey) - if val != nil { - if arr, ok := val.([]LogField); ok { - fields = append(fields, arr...) - } - } - - return fields -} - -func (l *contextLogger) err(v interface{}, fields ...LogField) { - if shallLog(ErrorLevel) { - getWriter().Error(v, l.buildFields(fields...)...) - } -} - -func (l *contextLogger) info(v interface{}, fields ...LogField) { - if shallLog(InfoLevel) { - getWriter().Info(v, l.buildFields(fields...)...) - } -} - -func (l *contextLogger) slow(v interface{}, fields ...LogField) { - if shallLog(ErrorLevel) { - getWriter().Slow(v, l.buildFields(fields...)...) - } -} - -func spanIdFromContext(ctx context.Context) string { - spanCtx := trace.SpanContextFromContext(ctx) - if spanCtx.HasSpanID() { - return spanCtx.SpanID().String() - } - - return "" -} - -func traceIdFromContext(ctx context.Context) string { - spanCtx := trace.SpanContextFromContext(ctx) - if spanCtx.HasTraceID() { - return spanCtx.TraceID().String() - } - - return "" -} diff --git a/core/logx/durationlogger.go b/core/logx/durationlogger.go deleted file mode 100644 index a9c3e500..00000000 --- a/core/logx/durationlogger.go +++ /dev/null @@ -1,101 +0,0 @@ -package logx - -import ( - "context" - "fmt" - "time" - - "github.com/zeromicro/go-zero/core/timex" -) - -// WithDuration returns a Logger which logs the given duration. -func WithDuration(d time.Duration) Logger { - return &durationLogger{ - Duration: timex.ReprOfDuration(d), - } -} - -type durationLogger logEntry - -func (l *durationLogger) Error(v ...interface{}) { - l.err(fmt.Sprint(v...)) -} - -func (l *durationLogger) Errorf(format string, v ...interface{}) { - l.err(fmt.Sprintf(format, v...)) -} - -func (l *durationLogger) Errorv(v interface{}) { - l.err(v) -} - -func (l *durationLogger) Errorw(msg string, fields ...LogField) { - l.err(msg, fields...) -} - -func (l *durationLogger) Info(v ...interface{}) { - l.info(fmt.Sprint(v...)) -} - -func (l *durationLogger) Infof(format string, v ...interface{}) { - l.info(fmt.Sprintf(format, v...)) -} - -func (l *durationLogger) Infov(v interface{}) { - l.info(v) -} - -func (l *durationLogger) Infow(msg string, fields ...LogField) { - l.info(msg, fields...) -} - -func (l *durationLogger) Slow(v ...interface{}) { - l.slow(fmt.Sprint(v...)) -} - -func (l *durationLogger) Slowf(format string, v ...interface{}) { - l.slow(fmt.Sprintf(format, v...)) -} - -func (l *durationLogger) Slowv(v interface{}) { - l.slow(v) -} - -func (l *durationLogger) Sloww(msg string, fields ...LogField) { - l.slow(msg, fields...) -} - -func (l *durationLogger) WithContext(ctx context.Context) Logger { - return &contextLogger{ - ctx: ctx, - logEntry: logEntry{ - Duration: l.Duration, - }, - } -} - -func (l *durationLogger) WithDuration(duration time.Duration) Logger { - l.Duration = timex.ReprOfDuration(duration) - return l -} - -func (l *durationLogger) err(v interface{}, fields ...LogField) { - if shallLog(ErrorLevel) { - fields = append(fields, Field(durationKey, l.Duration)) - getWriter().Error(v, fields...) - } -} - -func (l *durationLogger) info(v interface{}, fields ...LogField) { - if shallLog(InfoLevel) { - fields = append(fields, Field(durationKey, l.Duration)) - getWriter().Info(v, fields...) - } -} - -func (l *durationLogger) slow(v interface{}, fields ...LogField) { - if shallLog(ErrorLevel) { - fields = append(fields, Field(durationKey, l.Duration)) - getWriter().Slow(v, fields...) - } -} diff --git a/core/logx/durationlogger_test.go b/core/logx/durationlogger_test.go deleted file mode 100644 index b1f1af0d..00000000 --- a/core/logx/durationlogger_test.go +++ /dev/null @@ -1,161 +0,0 @@ -package logx - -import ( - "context" - "strings" - "sync/atomic" - "testing" - "time" - - "github.com/stretchr/testify/assert" - "go.opentelemetry.io/otel" - sdktrace "go.opentelemetry.io/otel/sdk/trace" -) - -func TestWithDurationError(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Error("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationErrorf(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Errorf("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationErrorv(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Errorv("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationErrorw(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Errorw("foo", Field("foo", "bar")) - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) - assert.True(t, strings.Contains(w.String(), "foo"), w.String()) - assert.True(t, strings.Contains(w.String(), "bar"), w.String()) -} - -func TestWithDurationInfo(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Info("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationInfoConsole(t *testing.T) { - old := atomic.LoadUint32(&encoding) - atomic.StoreUint32(&encoding, plainEncodingType) - defer func() { - atomic.StoreUint32(&encoding, old) - }() - - w := new(mockWriter) - o := writer.Swap(w) - defer writer.Store(o) - - WithDuration(time.Second).Info("foo") - assert.True(t, strings.Contains(w.String(), "ms"), w.String()) -} - -func TestWithDurationInfof(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Infof("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationInfov(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Infov("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationInfow(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Infow("foo", Field("foo", "bar")) - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) - assert.True(t, strings.Contains(w.String(), "foo"), w.String()) - assert.True(t, strings.Contains(w.String(), "bar"), w.String()) -} - -func TestWithDurationWithContextInfow(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - otp := otel.GetTracerProvider() - tp := sdktrace.NewTracerProvider(sdktrace.WithSampler(sdktrace.AlwaysSample())) - otel.SetTracerProvider(tp) - defer otel.SetTracerProvider(otp) - - ctx, _ := tp.Tracer("foo").Start(context.Background(), "bar") - WithDuration(time.Second).WithContext(ctx).Infow("foo", Field("foo", "bar")) - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) - assert.True(t, strings.Contains(w.String(), "foo"), w.String()) - assert.True(t, strings.Contains(w.String(), "bar"), w.String()) - assert.True(t, strings.Contains(w.String(), "trace"), w.String()) - assert.True(t, strings.Contains(w.String(), "span"), w.String()) -} - -func TestWithDurationSlow(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).Slow("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationSlowf(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).WithDuration(time.Hour).Slowf("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationSlowv(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).WithDuration(time.Hour).Slowv("foo") - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) -} - -func TestWithDurationSloww(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - - WithDuration(time.Second).WithDuration(time.Hour).Sloww("foo", Field("foo", "bar")) - assert.True(t, strings.Contains(w.String(), "duration"), w.String()) - assert.True(t, strings.Contains(w.String(), "foo"), w.String()) - assert.True(t, strings.Contains(w.String(), "bar"), w.String()) -} diff --git a/core/logx/fields.go b/core/logx/fields.go index 91958720..08bcf636 100644 --- a/core/logx/fields.go +++ b/core/logx/fields.go @@ -6,8 +6,8 @@ var fieldsContextKey contextKey type contextKey struct{} -// WithFields returns a new context with the given fields. -func WithFields(ctx context.Context, fields ...LogField) context.Context { +// ContextWithFields returns a new context with the given fields. +func ContextWithFields(ctx context.Context, fields ...LogField) context.Context { if val := ctx.Value(fieldsContextKey); val != nil { if arr, ok := val.([]LogField); ok { return context.WithValue(ctx, fieldsContextKey, append(arr, fields...)) @@ -16,3 +16,9 @@ func WithFields(ctx context.Context, fields ...LogField) context.Context { return context.WithValue(ctx, fieldsContextKey, fields) } + +// WithFields returns a new logger with the given fields. +// deprecated: use ContextWithFields instead. +func WithFields(ctx context.Context, fields ...LogField) context.Context { + return ContextWithFields(ctx, fields...) +} diff --git a/core/logx/fields_test.go b/core/logx/fields_test.go index c447526f..91f137b9 100644 --- a/core/logx/fields_test.go +++ b/core/logx/fields_test.go @@ -7,8 +7,8 @@ import ( "github.com/stretchr/testify/assert" ) -func TestWithFields(t *testing.T) { - ctx := WithFields(context.Background(), Field("a", 1), Field("b", 2)) +func TestContextWithFields(t *testing.T) { + ctx := ContextWithFields(context.Background(), Field("a", 1), Field("b", 2)) vals := ctx.Value(fieldsContextKey) assert.NotNil(t, vals) fields, ok := vals.([]LogField) @@ -19,8 +19,8 @@ func TestWithFields(t *testing.T) { func TestWithFieldsAppend(t *testing.T) { var dummyKey struct{} ctx := context.WithValue(context.Background(), dummyKey, "dummy") - ctx = WithFields(ctx, Field("a", 1), Field("b", 2)) - ctx = WithFields(ctx, Field("c", 3), Field("d", 4)) + ctx = ContextWithFields(ctx, Field("a", 1), Field("b", 2)) + ctx = ContextWithFields(ctx, Field("c", 3), Field("d", 4)) vals := ctx.Value(fieldsContextKey) assert.NotNil(t, vals) fields, ok := vals.([]LogField) diff --git a/core/logx/logger.go b/core/logx/logger.go index 2d48af47..ca690766 100644 --- a/core/logx/logger.go +++ b/core/logx/logger.go @@ -31,8 +31,10 @@ type Logger interface { Slowv(interface{}) // Sloww logs a message at slow level. Sloww(string, ...LogField) + // WithCallerSkip returns a new logger with the given caller skip. + WithCallerSkip(skip int) Logger // WithContext returns a new logger with the given context. - WithContext(context.Context) Logger + WithContext(ctx context.Context) Logger // WithDuration returns a new logger with the given duration. - WithDuration(time.Duration) Logger + WithDuration(d time.Duration) Logger } diff --git a/core/logx/logs.go b/core/logx/logs.go index 325c9370..28fd5c06 100644 --- a/core/logx/logs.go +++ b/core/logx/logs.go @@ -14,7 +14,7 @@ import ( "github.com/zeromicro/go-zero/core/sysx" ) -const callerDepth = 5 +const callerDepth = 4 var ( timeFormat = "2006-01-02T15:04:05.000Z07:00" @@ -29,15 +29,16 @@ var ( ) type ( - logEntry struct { - Timestamp string `json:"@timestamp"` - Level string `json:"level"` - Duration string `json:"duration,omitempty"` - Caller string `json:"caller,omitempty"` - Content interface{} `json:"content"` + // LogField is a key-value pair that will be added to the log entry. + LogField struct { + Key string + Value interface{} } - logEntryWithFields map[string]interface{} + // LogOption defines the method to customize the logging. + LogOption func(options *logOptions) + + logEntry map[string]interface{} logOptions struct { gzipEnabled bool @@ -47,15 +48,6 @@ type ( maxSize int rotationRule string } - - // LogField is a key-value pair that will be added to the log entry. - LogField struct { - Key string - Value interface{} - } - - // LogOption defines the method to customize the logging. - LogOption func(options *logOptions) ) // Alert alerts v in alert level, and the message is written to error log. @@ -85,35 +77,35 @@ func DisableStat() { // Error writes v into error log. func Error(v ...interface{}) { - errorTextSync(fmt.Sprint(v...)) + writeError(fmt.Sprint(v...)) } // Errorf writes v with format into error log. func Errorf(format string, v ...interface{}) { - errorTextSync(fmt.Errorf(format, v...).Error()) + writeError(fmt.Errorf(format, v...).Error()) } // ErrorStack writes v along with call stack into error log. func ErrorStack(v ...interface{}) { // there is newline in stack string - stackSync(fmt.Sprint(v...)) + writeStack(fmt.Sprint(v...)) } // ErrorStackf writes v along with call stack in format into error log. func ErrorStackf(format string, v ...interface{}) { // there is newline in stack string - stackSync(fmt.Sprintf(format, v...)) + writeStack(fmt.Sprintf(format, v...)) } // Errorv writes v into error log with json content. // No call stack attached, because not elegant to pack the messages. func Errorv(v interface{}) { - errorAnySync(v) + writeError(v) } // Errorw writes msg along with fields into error log. func Errorw(msg string, fields ...LogField) { - errorFieldsSync(msg, fields...) + writeError(msg, fields...) } // Field returns a LogField for the given key and value. @@ -156,22 +148,22 @@ func Field(key string, value interface{}) LogField { // Info writes v into access log. func Info(v ...interface{}) { - infoTextSync(fmt.Sprint(v...)) + writeInfo(fmt.Sprint(v...)) } // Infof writes v with format into access log. func Infof(format string, v ...interface{}) { - infoTextSync(fmt.Sprintf(format, v...)) + writeInfo(fmt.Sprintf(format, v...)) } // Infov writes v into access log with json content. func Infov(v interface{}) { - infoAnySync(v) + writeInfo(v) } // Infow writes msg along with fields into access log. func Infow(msg string, fields ...LogField) { - infoFieldsSync(msg, fields...) + writeInfo(msg, fields...) } // Must checks if err is nil, otherwise logs the error and exits. @@ -244,42 +236,42 @@ func SetUp(c LogConf) (err error) { // Severe writes v into severe log. func Severe(v ...interface{}) { - severeSync(fmt.Sprint(v...)) + writeSevere(fmt.Sprint(v...)) } // Severef writes v with format into severe log. func Severef(format string, v ...interface{}) { - severeSync(fmt.Sprintf(format, v...)) + writeSevere(fmt.Sprintf(format, v...)) } // Slow writes v into slow log. func Slow(v ...interface{}) { - slowTextSync(fmt.Sprint(v...)) + writeSlow(fmt.Sprint(v...)) } // Slowf writes v with format into slow log. func Slowf(format string, v ...interface{}) { - slowTextSync(fmt.Sprintf(format, v...)) + writeSlow(fmt.Sprintf(format, v...)) } // Slowv writes v into slow log with json content. func Slowv(v interface{}) { - slowAnySync(v) + writeSlow(v) } // Sloww writes msg along with fields into slow log. func Sloww(msg string, fields ...LogField) { - slowFieldsSync(msg, fields...) + writeSlow(msg, fields...) } // Stat writes v into stat log. func Stat(v ...interface{}) { - statSync(fmt.Sprint(v...)) + writeStat(fmt.Sprint(v...)) } // Statf writes v with format into stat log. func Statf(format string, v ...interface{}) { - statSync(fmt.Sprintf(format, v...)) + writeStat(fmt.Sprintf(format, v...)) } // WithCooldownMillis customizes logging on writing call stack interval. @@ -324,6 +316,10 @@ func WithRotation(r string) LogOption { } } +func addCaller(fields ...LogField) []LogField { + return append(fields, Field(callerKey, getCaller(callerDepth))) +} + func createOutput(path string) (io.WriteCloser, error) { if len(path) == 0 { return nil, ErrLogPathNotSet @@ -339,24 +335,6 @@ func createOutput(path string) (io.WriteCloser, error) { } } -func errorAnySync(v interface{}) { - if shallLog(ErrorLevel) { - getWriter().Error(v) - } -} - -func errorFieldsSync(content string, fields ...LogField) { - if shallLog(ErrorLevel) { - getWriter().Error(content, fields...) - } -} - -func errorTextSync(msg string) { - if shallLog(ErrorLevel) { - getWriter().Error(msg) - } -} - func getWriter() Writer { w := writer.Load() if w == nil { @@ -372,24 +350,6 @@ func handleOptions(opts []LogOption) { } } -func infoAnySync(val interface{}) { - if shallLog(InfoLevel) { - getWriter().Info(val) - } -} - -func infoFieldsSync(content string, fields ...LogField) { - if shallLog(InfoLevel) { - getWriter().Info(content, fields...) - } -} - -func infoTextSync(msg string) { - if shallLog(InfoLevel) { - getWriter().Info(msg) - } -} - func setupLogLevel(c LogConf) { switch c.Level { case levelInfo: @@ -424,12 +384,6 @@ func setupWithVolume(c LogConf) error { return setupWithFiles(c) } -func severeSync(msg string) { - if shallLog(SevereLevel) { - getWriter().Severe(fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) - } -} - func shallLog(level uint32) bool { return atomic.LoadUint32(&logLevel) <= level } @@ -438,32 +392,38 @@ func shallLogStat() bool { return atomic.LoadUint32(&disableStat) == 0 } -func slowAnySync(v interface{}) { +func writeError(val interface{}, fields ...LogField) { if shallLog(ErrorLevel) { - getWriter().Slow(v) + getWriter().Error(val, addCaller(fields...)...) } } -func slowFieldsSync(content string, fields ...LogField) { - if shallLog(ErrorLevel) { - getWriter().Slow(content, fields...) +func writeInfo(val interface{}, fields ...LogField) { + if shallLog(InfoLevel) { + getWriter().Info(val, addCaller(fields...)...) } } -func slowTextSync(msg string) { - if shallLog(ErrorLevel) { - getWriter().Slow(msg) +func writeSevere(msg string) { + if shallLog(SevereLevel) { + getWriter().Severe(fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) } } -func stackSync(msg string) { +func writeSlow(val interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Slow(val, addCaller(fields...)...) + } +} + +func writeStack(msg string) { if shallLog(ErrorLevel) { getWriter().Stack(fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) } } -func statSync(msg string) { +func writeStat(msg string) { if shallLogStat() && shallLog(InfoLevel) { - getWriter().Stat(msg) + getWriter().Stat(msg, addCaller()...) } } diff --git a/core/logx/logs_test.go b/core/logx/logs_test.go index 718e7438..3be37648 100644 --- a/core/logx/logs_test.go +++ b/core/logx/logs_test.go @@ -461,13 +461,13 @@ func TestStructedLogWithDuration(t *testing.T) { defer writer.Store(old) WithDuration(time.Second).Info(message) - var entry logEntry + var entry map[string]interface{} if err := json.Unmarshal([]byte(w.String()), &entry); err != nil { t.Error(err) } - assert.Equal(t, levelInfo, entry.Level) - assert.Equal(t, message, entry.Content) - assert.Equal(t, "1000.0ms", entry.Duration) + assert.Equal(t, levelInfo, entry[levelKey]) + assert.Equal(t, message, entry[contentKey]) + assert.Equal(t, "1000.0ms", entry[durationKey]) } func TestSetLevel(t *testing.T) { @@ -531,6 +531,7 @@ func TestSetup(t *testing.T) { MustSetup(LogConf{ ServiceName: "any", Mode: "console", + TimeFormat: timeFormat, }) MustSetup(LogConf{ ServiceName: "any", @@ -553,7 +554,15 @@ func TestSetup(t *testing.T) { Encoding: plainEncoding, }) + defer os.RemoveAll("CD01CB7D-2705-4F3F-889E-86219BF56F10") assert.NotNil(t, setupWithVolume(LogConf{})) + assert.Nil(t, setupWithVolume(LogConf{ + ServiceName: "CD01CB7D-2705-4F3F-889E-86219BF56F10", + })) + assert.Nil(t, setupWithVolume(LogConf{ + ServiceName: "CD01CB7D-2705-4F3F-889E-86219BF56F10", + Rotation: sizeRotationRule, + })) assert.NotNil(t, setupWithFiles(LogConf{})) assert.Nil(t, setupWithFiles(LogConf{ ServiceName: "any", @@ -583,6 +592,8 @@ func TestDisable(t *testing.T) { var opt logOptions WithKeepDays(1)(&opt) WithGzip()(&opt) + WithMaxBackups(1)(&opt) + WithMaxSize(1024)(&opt) assert.Nil(t, Close()) assert.Nil(t, Close()) } @@ -711,14 +722,16 @@ func put(b []byte) { func doTestStructedLog(t *testing.T, level string, w *mockWriter, write func(...interface{})) { const message = "hello there" write(message) - var entry logEntry + + var entry map[string]interface{} if err := json.Unmarshal([]byte(w.String()), &entry); err != nil { t.Error(err) } - assert.Equal(t, level, entry.Level) - val, ok := entry.Content.(string) + + assert.Equal(t, level, entry[levelKey]) + val, ok := entry[contentKey] assert.True(t, ok) - assert.True(t, strings.Contains(val, message)) + assert.True(t, strings.Contains(val.(string), message)) } func doTestStructedLogConsole(t *testing.T, w *mockWriter, write func(...interface{})) { diff --git a/core/logx/richlogger.go b/core/logx/richlogger.go new file mode 100644 index 00000000..de52a80e --- /dev/null +++ b/core/logx/richlogger.go @@ -0,0 +1,172 @@ +package logx + +import ( + "context" + "fmt" + "time" + + "github.com/zeromicro/go-zero/core/timex" + "go.opentelemetry.io/otel/trace" +) + +// WithCallerSkip returns a Logger with given caller skip. +func WithCallerSkip(skip int) Logger { + if skip <= 0 { + return new(richLogger) + } + + return &richLogger{ + callerSkip: skip, + } +} + +// WithContext sets ctx to log, for keeping tracing information. +func WithContext(ctx context.Context) Logger { + return &richLogger{ + ctx: ctx, + } +} + +// WithDuration returns a Logger with given duration. +func WithDuration(d time.Duration) Logger { + return &richLogger{ + fields: []LogField{Field(durationKey, timex.ReprOfDuration(d))}, + } +} + +type richLogger struct { + ctx context.Context + callerSkip int + fields []LogField +} + +func (l *richLogger) Error(v ...interface{}) { + l.err(fmt.Sprint(v...)) +} + +func (l *richLogger) Errorf(format string, v ...interface{}) { + l.err(fmt.Sprintf(format, v...)) +} + +func (l *richLogger) Errorv(v interface{}) { + l.err(fmt.Sprint(v)) +} + +func (l *richLogger) Errorw(msg string, fields ...LogField) { + l.err(msg, fields...) +} + +func (l *richLogger) Info(v ...interface{}) { + l.info(fmt.Sprint(v...)) +} + +func (l *richLogger) Infof(format string, v ...interface{}) { + l.info(fmt.Sprintf(format, v...)) +} + +func (l *richLogger) Infov(v interface{}) { + l.info(v) +} + +func (l *richLogger) Infow(msg string, fields ...LogField) { + l.info(msg, fields...) +} + +func (l *richLogger) Slow(v ...interface{}) { + l.slow(fmt.Sprint(v...)) +} + +func (l *richLogger) Slowf(format string, v ...interface{}) { + l.slow(fmt.Sprintf(format, v...)) +} + +func (l *richLogger) Slowv(v interface{}) { + l.slow(v) +} + +func (l *richLogger) Sloww(msg string, fields ...LogField) { + l.slow(msg, fields...) +} + +func (l *richLogger) WithCallerSkip(skip int) Logger { + if skip <= 0 { + return l + } + + l.callerSkip = skip + return l +} + +func (l *richLogger) WithContext(ctx context.Context) Logger { + l.ctx = ctx + return l +} + +func (l *richLogger) WithDuration(duration time.Duration) Logger { + l.fields = append(l.fields, Field(durationKey, timex.ReprOfDuration(duration))) + return l +} + +func (l *richLogger) buildFields(fields ...LogField) []LogField { + fields = append(l.fields, fields...) + fields = append(fields, Field(callerKey, getCaller(callerDepth+l.callerSkip))) + + if l.ctx == nil { + return fields + } + + traceID := traceIdFromContext(l.ctx) + if len(traceID) > 0 { + fields = append(fields, Field(traceKey, traceID)) + } + + spanID := spanIdFromContext(l.ctx) + if len(spanID) > 0 { + fields = append(fields, Field(spanKey, spanID)) + } + + val := l.ctx.Value(fieldsContextKey) + if val != nil { + if arr, ok := val.([]LogField); ok { + fields = append(fields, arr...) + } + } + + return fields +} + +func (l *richLogger) err(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Error(v, l.buildFields(fields...)...) + } +} + +func (l *richLogger) info(v interface{}, fields ...LogField) { + if shallLog(InfoLevel) { + getWriter().Info(v, l.buildFields(fields...)...) + } +} + +func (l *richLogger) slow(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Slow(v, l.buildFields(fields...)...) + } +} + +func spanIdFromContext(ctx context.Context) string { + spanCtx := trace.SpanContextFromContext(ctx) + if spanCtx.HasSpanID() { + return spanCtx.SpanID().String() + } + + return "" +} + +func traceIdFromContext(ctx context.Context) string { + spanCtx := trace.SpanContextFromContext(ctx) + if spanCtx.HasTraceID() { + return spanCtx.TraceID().String() + } + + return "" +} diff --git a/core/logx/contextlogger_test.go b/core/logx/richlogger_test.go similarity index 91% rename from core/logx/contextlogger_test.go rename to core/logx/richlogger_test.go index 8f931481..08777752 100644 --- a/core/logx/contextlogger_test.go +++ b/core/logx/richlogger_test.go @@ -3,6 +3,7 @@ package logx import ( "context" "encoding/json" + "fmt" "io" "strings" "sync/atomic" @@ -201,7 +202,7 @@ func TestLogWithFields(t *testing.T) { writer.Store(old) }() - ctx := WithFields(context.Background(), Field("foo", "bar")) + ctx := ContextWithFields(context.Background(), Field("foo", "bar")) l := WithContext(ctx) SetLevel(InfoLevel) l.Info(testlog) @@ -211,6 +212,31 @@ func TestLogWithFields(t *testing.T) { assert.Equal(t, "bar", val.Foo) } +func TestLogWithCallerSkip(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + writer.lock.RLock() + defer func() { + writer.lock.RUnlock() + writer.Store(old) + }() + + l := WithCallerSkip(1).WithCallerSkip(0) + p := func(v string) { + l.Info(v) + } + + file, line := getFileLine() + p(testlog) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) + + w.Reset() + l = WithCallerSkip(0).WithCallerSkip(1) + file, line = getFileLine() + p(testlog) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) +} + func validate(t *testing.T, body string, expectedTrace, expectedSpan bool) { var val mockValue dec := json.NewDecoder(strings.NewReader(body)) diff --git a/core/logx/syslog_test.go b/core/logx/syslog_test.go index 7e389093..2be0b51a 100644 --- a/core/logx/syslog_test.go +++ b/core/logx/syslog_test.go @@ -42,11 +42,18 @@ func captureOutput(f func()) string { } func getContent(jsonStr string) string { - var entry logEntry + var entry map[string]interface{} json.Unmarshal([]byte(jsonStr), &entry) - val, ok := entry.Content.(string) - if ok { - return val + + val, ok := entry[contentKey] + if !ok { + return "" } - return "" + + str, ok := val.(string) + if !ok { + return "" + } + + return str } diff --git a/core/logx/writer.go b/core/logx/writer.go index 08873c09..5f372566 100644 --- a/core/logx/writer.go +++ b/core/logx/writer.go @@ -256,13 +256,11 @@ func buildFields(fields ...LogField) []string { } func output(writer io.Writer, level string, val interface{}, fields ...LogField) { - fields = append(fields, Field(callerKey, getCaller(callerDepth))) - switch atomic.LoadUint32(&encoding) { case plainEncodingType: writePlainAny(writer, level, val, buildFields(fields...)...) default: - entry := make(logEntryWithFields) + entry := make(logEntry) for _, field := range fields { entry[field.Key] = field.Value }